1

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.

Cirrocumulus
  • 520
  • 3
  • 15

1 Answers1

3
  • 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)
jisrael18
  • 719
  • 3
  • 10
  • 1
    Typo, I think: `foo.bar` and `foo.baz` *both* inherit configuration from `foo`. – chepner Aug 13 '21 at 14:24
  • Thank you. It took a while for me to realise that, to make it short, the logger instance in the main script should simply not have a name... It works when I'm using the above barebones scripts, so thanks a lot for clearing that out. However, as soon as I import a module such as PySide into those scripts, every log message is doubled with a non-formatted one. I have not changed anything else otherwise, and still don't understand what logger instance is producing that (since I'm only calling *my* loggers). – Cirrocumulus Aug 13 '21 at 15:47
  • I managed to make this work when PySide is imported by adding the following line immediately after I instantiate my logger in the main script, before I do anything else: `for h in logger.handlers: logger.removeHandler(h)`. This removes all the handlers which might be there (PySide adds only one). I don't know if this is the way this should be done, but if so maybe it should be added to the answer. – Cirrocumulus Aug 13 '21 at 16:37
  • It sounds like you're calling `logging.basicConfig()`, which adds a stream handler to the root logger, and also adding handlers your module loggers. If you add a handler to the root logger and to a module logger, that would cause multiple log messages. When writing an **application**, in most cases, you only want to configure the root logger. Sometimes you'll want to configure a separate file handler each module of your application so each module logs to a separate path. A well-behaved **library** will not configure the root logger (i.e. importing a file should never modify the root logger). – jisrael18 Aug 13 '21 at 16:57
  • @Cirrocumulus If you reply with a link to current code, I can take a look at your specific situation later tonight. – jisrael18 Aug 13 '21 at 16:59
  • @jisrael18 Like I wrote I've been on this for the most part of the day, so I'm absolutely positive I have no call to `basicConfig()` anywhere (this has been part of the problem). I've just double-checked with a project-wide search. Maybe it's a PySide6/Qt issue or bug? My code works as expected with my `removeHandler`hack, but if you want to have a look the project is here: https://github.com/Merkwurdichliebe/beacon2map — Thanks a lot. – Cirrocumulus Aug 13 '21 at 17:40