Can’t get my head around logging in multiple modules

I’ve been going around in circles with this for the last four hours. I’ve read the docs and this other SO page. This GitHub code recommends importing modules after logging has been setup in the main script, whereas this post suggests each module should have a complete implementation of the logger.

The way logging works has me completely mystified. I’m running Python 3.9.

Here the code at the top of my main script:

import logging


def logger():
    # Adding the following line logs each message twice to the console
    # logging.basicConfig(level=logging.DEBUG)

    # Create the logger
    logger = logging.getLogger(__name__)
    logger.setLevel(logging.DEBUG)

    # Create handlers
    ch = logging.StreamHandler()
    fh = logging.FileHandler('log.log', mode='w')
    ch.setLevel(logging.DEBUG)
    fh.setLevel(logging.DEBUG)

    # Create formatters
    ch.setFormatter(logging.Formatter('[ %(levelname)s ] %(name)s : %(message)s'))
    fh.setFormatter(logging.Formatter('%(asctime)s [ %(levelname)s ] %(name)s : %(message)s'))

    # Add handlers to logger
    logger.addHandler(ch)
    logger.addHandler(fh)

    return logger


logger = logger()

import log_module  # Linter complains but at this point I don't care anymore

logger.debug('Help')

log_module.foo()

In log_module.py, I have the following:

import logging

logger = logging.getLogger(__name__)

def foo():
    logger.setLevel(logging.DEBUG)
    logger.debug('Debugging in module')

If I run the main script, I only get one log message: [ DEBUG ] __main__ : Help.

If I uncomment the line with basicConfig in the logger function, I get three log messages, unformatted:

[ DEBUG ] __main__ : Help
DEBUG:__main__:Help
DEBUG:log_module:Debugging in module

If I copy the whole logger() function over to log_module.py, I get the output I’m expecting, in the correct format, which is:

[ DEBUG ] __main__ : Help
[ DEBUG ] log_module : Debugging in module

However, it seems very silly to copy entire chunks of code across modules.

  • What am I doing wrong?
  • What should I be doing instead?
  • Does this need to be this convoluted just to get logs from multiple modules?

Thanks a lot in advance for your help.

Answer

  • What am I doing wrong?

You’re configuring one logger and using a different logger. When you call logger() in the main script, the returned logger is the __main__ because that is what __name__ evaluates to from the main script. When you call logging.getLogger() from log_module.py, you get a module named log_module.

  • What should I be doing instead?

Either explicitly configure the log_module logger by calling a configure_logger function that accepts a logger instance as an argument, or configure the root logger (get the root logger by calling logging.getLogger() with no arguments). The root logger’s configuration will be inherited by the others.

  • Does this need to be this convoluted just to get logs from multiple modules?

Once you understand that loggers are a hierarchy, it’s a little simpler conceptually. It works nicely when you have nested packages/modules.

  • logging.getLogger() (root logger)
    • logging.getLogger('foo') (inherits configuration from root logger)
      • logging.getLogger('foo.bar') (inherits configuration from foo)
      • logging.getLogger('foo.baz') (inherits configuration from foo)