How to extend the logging.Logger Class?

Question

I would like to start with a basic logging class that inherits from Python's logging.Logger class. However, I am not sure about how I should be constructing my class so that I can establish the basics needed for customising the inherited logger.

This is what I have so far in my logger.py file:

import sys
import logging
from logging import DEBUG, INFO, ERROR

class MyLogger(object):
    def __init__(self, name, format="%(asctime)s | %(levelname)s | %(message)s", level=INFO):
        # Initial construct.
        self.format = format
        self.level = level
        self.name = name

        # Logger configuration.
        self.console_formatter = logging.Formatter(self.format)
        self.console_logger = logging.StreamHandler(sys.stdout)
        self.console_logger.setFormatter(self.console_formatter)

        # Complete logging config.
        self.logger = logging.getLogger("myApp")
        self.logger.setLevel(self.level)
        self.logger.addHandler(self.console_logger)

    def info(self, msg, extra=None):
        self.logger.info(msg, extra=extra)

    def error(self, msg, extra=None):
        self.logger.error(msg, extra=extra)

    def debug(self, msg, extra=None):
        self.logger.debug(msg, extra=extra)

    def warn(self, msg, extra=None):
        self.logger.warn(msg, extra=extra)

This is the main myApp.py:

import entity
from core import MyLogger

my_logger = MyLogger("myApp")

def cmd():
    my_logger.info("Hello from %s!" % ("__CMD"))

entity.third_party()
entity.another_function()
cmd()

And this is the entity.py module:

# Local modules
from core import MyLogger

# Global modules
import logging
from logging import DEBUG, INFO, ERROR, CRITICAL

my_logger = MyLogger("myApp.entity", level=DEBUG)

def third_party():
    my_logger.info("Initial message from: %s!" % ("__THIRD_PARTY"))

def another_function():
    my_logger.warn("Message from: %s" % ("__ANOTHER_FUNCTION"))

When I run the main app, I get this:

2016-09-14 12:40:50,445 | INFO | Initial message from: __THIRD_PARTY!
2016-09-14 12:40:50,445 | INFO | Initial message from: __THIRD_PARTY!
2016-09-14 12:40:50,445 | WARNING | Message from: __ANOTHER_FUNCTION
2016-09-14 12:40:50,445 | WARNING | Message from: __ANOTHER_FUNCTION
2016-09-14 12:40:50,445 | INFO | Hello from __CMD!
2016-09-14 12:40:50,445 | INFO | Hello from __CMD!

Everything is printed twice, as probably I have failed to set the logger class properly.

Update 1

Let me clarify my goals.

(1) I would like to encapsulate the main logging functionality in one single location so I can do this:

 from mylogger import MyLogger
 my_logger = MyLogger("myApp")
 my_logger.info("Hello from %s!" % ("__CMD"))

(2) I am planning to use CustomFormatter and CustomAdapter classes. This bit does not require a custom logging class, those can be plugged in straight away.

(3) I probably do not need to go very deep in terms of customisation of the underlying logger class (records etc.), intercepting logger.info, loggin.debug etc. should be enough.

So referring back to this python receipt that has been circulated many times on these forums:

I am trying to the find the sweet point between having a Logger Class, yet still be able to use the built in functions like assigning Formatters and Adapters etc. So everything stays compatible with the logging module.

class OurLogger(logging.getLoggerClass()):
    def makeRecord(self, name, level, fn, lno, msg, args, exc_info, func=None, extra=None):
        # Don't pass all makeRecord args to OurLogRecord bc it doesn't expect "extra"
        rv = OurLogRecord(name, level, fn, lno, msg, args, exc_info, func)
        # Handle the new extra parameter.
        # This if block was copied from Logger.makeRecord
        if extra:
            for key in extra:
                if (key in ["message", "asctime"]) or (key in rv.__dict__):
                    raise KeyError("Attempt to overwrite %r in LogRecord" % key)
                rv.__dict__[key] = extra[key]
        return rv

Update 2

I have created a repo with a simple python app demonstrating a possible solution. However, I am keen to improve this.

xlog_example

This example effectively demonstrates the technique of overriding the logging.Logger class and the logging.LogRecord class through inheritance.

Two external items are mixed into the log stream: funcname and username without using any Formatters or Adapters.

Answer 1

At this stage, I believe that the research I have made so far and the example provided with the intention to wrap up the solution is sufficient to serve as an answer to my question. In general, there are many approaches that may be utilised to wrap a logging solution. This particular question aimed to focus on a solution that utilises logging.Logger class inheritance so that the internal mechanics can be altered, yet the rest of the functionality kept as it is since it is going to be provided by the original logging.Logger class.

Having said that, class inheritance techniques should be used with great care. Many of the facilities provided by the logging module are already sufficient to maintain and run a stable logging workflow. Inheriting from the logging.Logger class is probably good when the goal is some kind of a fundamental change to the way the log data is processed and exported.

To summarise this, I see that there are two approaches for wrapping logging functionality:

1) The Traditional Logging:

This is simply working with the provided logging methods and functions, but wrap them in a module so that some of the generic repetitive tasks are organised in one place. In this way, things like log files, log levels, managing custom Filters, Adapters etc. will be easy.

I am not sure if a class approach can be utilised in this scenario (and I am not talking about a super class approach which is the topic of the second item) as it seems that things are getting complicated when the logging calls are wrapped inside a class. I would like to hear about this issue and I will definitely prepare a question that explores this aspect.

2) The Logger Inheritance:

This approach is based on inheriting from the original logging.Logger class and adding to the existing methods or entirely hijacking them by modifying the internal behaviour. The mechanics are based on the following bit of code:

# Register our logger.
logging.setLoggerClass(OurLogger)
my_logger = logging.getLogger("main")

From here on, we are relying on our own Logger, yet we are still able to benefit from all of the other logging facilities:

# We still need a loggin handler.
ch = logging.StreamHandler()
my_logger.addHandler(ch)

# Confgure a formatter.
formatter = logging.Formatter('LOGGER:%(name)12s - %(levelname)7s - <%(filename)s:%(username)s:%(funcname)s> %(message)s')
ch.setFormatter(formatter)

# Example main message.
my_logger.setLevel(DEBUG)
my_logger.warn("Hi mom!")

This example is crucial as it demonstrates the injection of two data bits username and funcname without using custom Adapters or Formatters.

Please see the xlog.py repo for more information regarding this solution. This is an example that I have prepared based on other questions and bits of code from other sources.

Answer 2

This line

self.logger = logging.getLogger("myApp")

always retrieves a reference to the same logger, so you are adding an additional handler to it every time you instantiate MyLogger. The following would fix your current instance, since you call MyLogger with a different argument both times.

self.logger = logging.getLogger(name)

but note that you will still have the same problem if you pass the same name argument more than once.

What your class needs to do is keep track of which loggers it has already configured.

class MyLogger(object):
    loggers = set()
    def __init__(self, name, format="%(asctime)s | %(levelname)s | %(message)s", level=INFO):
        # Initial construct.
        self.format = format
        self.level = level
        self.name = name

        # Logger configuration.
        self.console_formatter = logging.Formatter(self.format)
        self.console_logger = logging.StreamHandler(sys.stdout)
        self.console_logger.setFormatter(self.console_formatter)

        # Complete logging config.
        self.logger = logging.getLogger(name)
        if name not in self.loggers:
            self.loggers.add(name)
            self.logger.setLevel(self.level)
            self.logger.addHandler(self.console_logger)

This doesn't allow you to re-configure a logger at all, but I leave it as an exercise to figure out how to do that properly.

The key thing to note, though, is that you can't have two separately configured loggers with the same name.

---

Of course, the fact that logging.getLogger always returns a reference to the same object for a given name means that your class is working at odds with the logging module. Just configure your loggers once at program start-up, then get references as necessary with getLogger.