proper logging implementation for Python modules

Question

Does anyone know of any good examples of modules with nice logging implementations?

I have been doing logging a couple of different ways, but I'm not sure which is most Pythonic.

For scripts, this is what I've been doing:

import logging

LOGGER = logging.getLogger(__program__)
STREAM = logging.StreamHandler()
FORMATTER = logging.Formatter('(%(name)s) %(levelname)s: %(message)s')
STREAM.setFormatter(FORMATTER)
LOGGER.addHandler(STREAM)

def main():
    LOGGER.warning('This is a warning message.')

That is executed in the global namespace and I can call LOGGER from anywhere.

The aforementioned solution is not such a good idea for modules because the code is executed upon import. So for modules, I have been calling this _logging() function early on to set up the logging.

def _logging():
    import logging

    global logger
    logger = logging.getLogger(__program__)
    stream = logging.StreamHandler()
    formatter = logging.Formatter('(%(name)s) %(levelname)s: %(message)s')
    stream.setFormatter(formatter)
    logger.addHandler(stream)

def main():
    _logging()
    logger.warning('This is a warning message.')

Since logger is global, I can just call it anywhere it is needed. However pylint barks out a global-variable-undefined warning. It is defined as Global variable logger undefined at the module level Used when a variable is defined through the “global” statement but the variable is not defined in the module scope but I'm not really sure why that is an issue here.

Or should I call the _logger() function early on (minus the global) and then create the logger everywhere that it is needed?

def _logging():
    import logging

    logger = logging.getLogger(__program__)
    stream = logging.StreamHandler()
    formatter = logging.Formatter('(%(name)s) %(levelname)s: %(message)s')
    stream.setFormatter(formatter)
    logger.addHandler(stream)

def main():
    _logging()
    logger = logging.getLogger(__program__)
    logger.warning('This is a warning message.')

The last technique seems to be the cleanest, albeit the most tedious, especially since I am often logging from within dozens of small classes, functions, methods, et cetera. Are there any examples from people/modules who have already blazed a path through this territory?

Community · Accepted Answer · 2017-05-23 12:07:11Z

If I understood correctly, you are configuring logging in each module separately. That would be unnecessary and against the design of logging module.

I think that the key to logging is understanding that logging module is a stateful object in you Python process. At least for me after that insight there was only one obvious way to do logging in most situations.

You should configure logging at the beginning of your program. Define handlers, formatters, etc., and the configuration will remain throughout the program, as long as it isn't explicitly overridden.

All modules that do logging can define a global logger right after logging is imported. There is no need to put this into a function. As is also recommended by the documentation, it is good practice to name each logger according to module name (including package path):

import logging
logger = logging.getLogger(__name__)

It is also important to understand that loggers in your program form a hierarchy. By default, loggers propagate records to their parents. This means that at the bottom there is one logger (root) which gets all the records unless you configure some loggers to prevent this. Often it may be enough to configure only the root logger.

To be a little more concrete, let's make a program with two modules, one.py and two.py. one.py contains a function main which will be the entry point to the program. We'll configure logging using dictConfig, which lets us separate the logging configuration nicely from the rest of the code. We'll put the configuration dict in a separate YAML file, like this:

# logging_config.yaml

version: 1

formatters:
    brief:
        format: '%(message)s'
    default:
        format: '%(asctime)s %(levelname)-8s %(name)-15s %(message)s'
        datefmt: '%Y-%m-%d %H:%M:%S'

handlers:
    console:
        class: logging.StreamHandler
        formatter: brief
        stream: ext://sys.stdout
    file:
        class: logging.handlers.RotatingFileHandler
        formatter: default
        filename: example.log
        maxBytes: 1024
        backupCount: 3

loggers:
    two:
        level: INFO
        handlers: [file]
        propagate: False

root:
    level: INFO
    handlers: [console]

These snippets are mostly adapted from the documentation. In this configuration we define that everything above level INFO from logger two is logged into a file. Records from two are also not propagated further. Everything that comes to the root logger is fed to console if it is above level INFO.

The definition of module one could then be like this:

# one.py

import logging
import logging.config
import yaml

def configure_logging(filename):
    with open(filename) as f:
        config = yaml.load(f)
    logging.config.dictConfig(config)

def main():
    configure_logging('logging_config.yaml')

    from two import func
    logger = logging.getLogger(__name__)

    logger.info('Starting the program')
    func()
    logger.info('Finished')

One tricky detail here is that we import module two and define the logger only after the configuration is set. This is done because by default dictConfig disables all existing loggers.

And finally, here is the definition for module two:

# two.py
import logging

logger = logging.getLogger(__name__)

def func():
    logger.info('Doing stuff')

Now if we run the program, we get the following output:

>>> import one
>>> one.main()
Starting the program
Finished

And the log file example.log contains the following line:

2015-06-07 15:04:15 INFO     two             Doing stuff

Excellent examples of logging can be found in Python documentation:

I'm not able to test your code ATM but I think I have done similar. One issue is that if you call main() multiple times, it will configure logger multiple times, resulting in multiple handlers and therefore duplicate messages. So I must either do a check to ensure handler is not already configured or shutdown then reload logger. I have read through the logger docs, I just find it very complicated because it is so powerful. There are so many different ways to use it and each has its own issues.
Sorry, I was perhaps a bit sloppy in the answer. To prevent multiple handlers and configure the root logger you should use basicConfig
Forgive me for being a little rusty but will basicConfig be useful even with different loggers possessing their own StreamHandler/Formatter?
I've now made the example better. I ended up using dictConfig, which is more flexible than fileConfig.
I think that the key to logging is understanding that logging module is a stateful object in you Python process. +1

Collectives™ on Stack Overflow

proper logging implementation for Python modules

1 Answer 1

5 Comments

Linked

Hot Network Questions

Collectives™ on Stack Overflow

1 Answer 1

5 Comments

Linked

Related