In Python 3, best Pythonic way to set base class method to run once only

Question

I'm currently trying to log the full class name and method that is currently running.

In the following rough code, I have a class attribute in Base that tracks whether or not the logging handler has been added. Without it, I get one message for each time the Base class is inherited, which makes perfect sense. e.g. without it I get this output:

1688489421.224986 DEBUG Base.TestClassA.testmethod1 |debug message from test class A|
1688489421.225088  INFO Base.TestClassB.testmethod2 |info message from test class B|
1688489421.225088  INFO Base.TestClassB.testmethod2 |info message from test class B|
1688489421.225162 ERROR Base.TestClassC.another_method |error message from test class C|
1688489421.225162 ERROR Base.TestClassC.another_method |error message from test class C|
1688489421.225162 ERROR Base.TestClassC.another_method |error message from test class C|

A test at the end of the __init__ method then only calls self.__logger.addHandler(console_handler) once. With the check, the correct output is seen:

1688490430.369992 DEBUG Base.TestClassA.testmethod1 |debug message from test class A|
1688490430.370093  INFO Base.TestClassB.testmethod2 |info message from test class B|
1688490430.370155 ERROR Base.TestClassC.another_method |error message from test class C|

But is that the right way to do it? It feels a little fragile, but I'm still very much a beginner so I don't have the experience to really tell.

What's the correct Pythonic way to only call self.__logger.addHandler(console_handler) once?

#!/usr/bin/env python3

import logging


# Cargo culted from https://stackoverflow.com/a/50731615/2988388
class MetaBase(type):
    def __init__(cls, *args):
        super().__init__(*args)

        # Explicit name mangling
        logger_attribute_name = "_" + cls.__name__ + "__logger"

        # Logger name derived accounting for inheritance for the bonus marks
        logger_name = ".".join([c.__name__ for c in cls.mro()[-2::-1]])

        setattr(cls, logger_attribute_name, logging.getLogger(logger_name))


class Base(metaclass=MetaBase):
    log_handler_added = False

    def __init__(self):
        log_formatter = logging.Formatter(
            "{created:<f} {levelname:>5s} {name}.{funcName:>8s} |{message}|",
            style="{",
        )
        loglevel = "DEBUG"

        # turn the "info", "debug" etc env var value into a number
        # that sets the logging level of detail
        numeric_level = getattr(logging, loglevel.upper(), None)
        if not isinstance(numeric_level, int):
            raise ValueError("Invalid log level: %s" % loglevel)

        # Just log to stdout/stderr
        console_handler = logging.StreamHandler()
        console_handler.setFormatter(log_formatter)
        self.__logger.setLevel(numeric_level)

        # use the class attribute to only add the handler once,
        # otherwise you get a log message for each time Base
        # has been inherited
        # https://stackoverflow.com/q/36320514/2988388
        if not Base.log_handler_added:
            self.__logger.addHandler(console_handler)
            Base.log_handler_added = True


class TestClassA(Base):
    def testmethod1(self):
        self.__logger.debug("debug message from test class A")


class TestClassB(Base):
    def testmethod2(self):
        self.__logger.info("info message from test class B")


class TestClassC(Base):
    def another_method(self):
        self.__logger.error("error message from test class C")


a = TestClassA()
a.testmethod1()

b = TestClassB()
b.testmethod2()

p = TestClassC()
p.another_method()

And as a bonus question, is it possible to use this metaclass+inheritance to log messages in __main__?

score 1 · Accepted Answer · answered Jul 04 '23 at 18:22

This seems over-complex. I would use a simple mixin and a formatter set on the root logger of the application. It can be the responsibility of main to initialize the root logger.

Mixin:

class LoggingMixin:
    @classmethod
    @property
    def log(cls):
        return logging.getLogger(cls.__name__)

Classes:

class TestClassA(LoggingMixin):
    def testmethod1(self):
        self.log.debug("debug message from test class A")


class TestClassB(LoggingMixin):
    def testmethod2(self):
        self.log.info("info message from test class B")


class TestClassC(LoggingMixin):
    def another_method(self):
        self.log.error("error message from test class C")

Setup:

if __name__ == "__main__":
    logging.basicConfig(
        format="{created:<f} {levelname:>5s} {name}.{funcName:>8s} |{message}|",
        level=logging.DEBUG,
        style="{",
    )

    a = TestClassA()
    a.testmethod1()

    b = TestClassB()
    b.testmethod2()

    p = TestClassC()
    p.another_method()

Output:

1688494741.449282 DEBUG TestClassA.testmethod1 |debug message from test class A|
1688494741.449282  INFO TestClassB.testmethod2 |info message from test class B|
1688494741.450281 ERROR TestClassC.another_method |error message from test class C|

Astonishing! That's so much simpler than the other solutions I've seen. I will give this a try and mark you as the correct answer as soon as I can. Huge thank you, I can see that I have a lot, a whole enormous amount, more to learn about Python. — acjca2, Jul 04 '23 at 18:31
@acjca2 Glad to have helped! Doing it this way also has the advantage of sharing a single log format for the entire application. It will even make the formatting consistent from dependencies you pip install if they also output to the logging module. — flakes, Jul 04 '23 at 18:36

In Python 3, best Pythonic way to set base class method to run once only

1 Answers1