Python logging to multiple handlers, at different log levels?

24
votes

Folks,

I'm scratching my head on a python logging config that I can't get right.

Let's say I have the following package installed:

mypackage/
   data/mypackage.logging.conf
   module1.py
   module2.py
   scripts/main.py

As the script can be used interactively or run from a crontab, I have the following requirements:

  1. no print statements, everything goes through logging;

  2. log using a timedRotatingFileHandler, always at DEBUG level;

  3. log using a mailinglogger.SummarisingLogger, always at INFO level;

  4. log to console, with level set by default to INFO or overridden through a command-line option.

Problem is, I can change the log level through the command-line and the console log level is changed accordingly, but the other handlers are also changed, which I don't want... :-/

In a logging config file, I'm not sure I understand the precedence between the root logger's level, other loggers' level and handlers' level settings.

Here is some sample code. Any clues will be appreciated :-)

# mypackage/data/mypackage.logging.conf
[loggers]
root,mypackage

[handlers]
keys=consoleHandler,timedRotatingFileHandler,summarisingHandler

[formatters]
keys=simpleFormatter,consoleFormatter,mypackageFormatter

[logger_root]
#level=INFO
handlers=consoleHandler

[logger_mypackage]
#level=INFO
handlers=timedRotatingFileHandler,summarisingHandler
qualname=mypackage

[handler_consoleHandler]
class=StreamHandler
#level=INFO
formatter=consoleFormatter
args=(sys.stdout,)

[handler_timedRotatingFileHandler]
class=logging.handlers.TimedRotatingFileHandler
level=DEBUG
formatter=mypackageFormatter
args=('mypackage.log', 'M', 1, 5)

[handler_summarisingHandler]
class=mailinglogger.SummarisingLogger
level=INFO
formatter=mypackageFormatter
args=('[email protected]', ('[email protected]',), 'relay.somewhere.com')

#mypackage/scripts/main.py:
import logging
import logging.config
import os
import sys

import mypackage.module1
import mypackage.module2

logging.config.fileConfig('data/mypackage.logging.conf')
log = logging.getLogger(__name__)

if __name__ == '__main__':
    loglevel = 'INFO'
    if len(sys.argv) > 1:
        loglevel = sys.argv[1].upper()

    logging.getLogger('').setLevel(getattr(logging, loglevel))
    # or logging.getLogger('mypackage').setLevel(getattr(logging, loglevel)) ?

    mypackage.module1.do_something()
    mypackage.module2.do_something_else()

#mypackage/module1.py:
import logging

log = logging.getLogger(__name__)
log.addHandler(NullHandler())

def do_something():
    log.debug("some debug message from:" + __name__)
    log.info("some info message from:" + __name__)
    log.error("some error message from:" + __name__)

#mypackage/module2.py:
import logging

log = logging.getLogger(__name__)
log.addHandler(NullHandler())

def do_something_else():
    log.debug("some debug message from:" + __name__)
    log.info("some info message from:" + __name__)
    log.error("some error message from:" + __name__)

UPDATE 1

In the meantime, I discovered this answer and successfully modified my code this way:

#mypackage/scripts/main.py:
import logging
import logging.config
import os
import sys
import mailinglogger

import mypackage.module1
import mypackage.module2

def main():
    # get the console log level from the command-line
    loglevel = 'INFO'
    if len(sys.argv) > 1:
        loglevel = sys.argv[1].upper()

    # create formatters
    simple_formatter = logging.Formatter("%(name)s:%(levelname)s: %(message)s")
    detailed_formatter = logging.Formatter("%(asctime)s %(name)s[%(process)d]: %(levelname)s - %(message)s")

    # get a top-level "mypackage" logger,
    # set its log level to DEBUG,
    # BUT PREVENT IT from propagating messages to the root logger
    #
    log = logging.getLogger('mypackage')
    log.setLevel(logging.DEBUG)
    log.propagate = 0

    # create a console handler
    # and set its log level to the command-line option 
    # 
    console_handler = logging.StreamHandler(sys.stdout)
    console_handler.setLevel(getattr(logging, loglevel))
    console_handler.setFormatter(simple_formatter)

    # create a file handler
    # and set its log level to DEBUG
    #
    file_handler = logging.handlers.TimedRotatingFileHandler('mypackage.log', 'M', 1, 5)
    file_handler.setLevel(logging.DEBUG)
    file_handler.setFormatter(detailed_formatter)

    # create a mail handler
    # and set its log level to INFO
    #
    mail_handler = mailinglogger.SummarisingLogger(
        '[email protected]', ('[email protected]',), 'relay.somewhere.com')
    mail_handler.setLevel(logging.INFO)
    mail_handler.setFormatter(detailed_formatter)

    # add handlers to the "mypackage" logger
    #
    log.addHandler(console_handler)
    log.addHandler(file_handler)
    log.addHandler(mail_handler)

    # let the modules do their stuff 
    # and log to the "mypackage.module1" and "mypackage.module2" loggers
    #
    mypackage.module1.do_something()
    mypackage.module2.do_something_else()


if __name__ == '__main__':
    main()

Now, I'll try to translate this in a logging.config file...

UPDATE 2

Here is the best logging config and code combination I found.

In the mypackage.logging.conf file, the "mypackage" logger is:

  • set up only with the file and email handlers;
  • its propagate is set to false;
  • its level is set to DEBUG;
  • while the file and email handlers are respectively set to INFO and DEBUG.
#mypackage/data/mypackage.logging.conf
[loggers]
keys=root,mypackage

[handlers]
keys=consoleHandler,timedRotatingFileHandler,summarisingHandler

[formatters]
keys=simpleFormatter,consoleFormatter,mypackageFormatter

[logger_root]
#level=INFO
handlers=consoleHandler

[logger_mypackage]
level=DEBUG
handlers=timedRotatingFileHandler,summarisingHandler
qualname=mypackage
propagate=0

[handler_consoleHandler]
class=StreamHandler
#level=INFO
formatter=consoleFormatter
args=(sys.stdout,)

[handler_timedRotatingFileHandler]
class=logging.handlers.TimedRotatingFileHandler
level=DEBUG
formatter=mypackageFormatter
args=('mypackage.log', 'M', 1, 5)

[handler_summarisingHandler]
class=mailinglogger.SummarisingLogger
level=INFO
formatter=mypackageFormatter
args=('[email protected]', ('[email protected]',), 'relay.somewhere.com')

[formatter_consoleFormatter]
format=%(levelname)s: %(message)s
datefmt=

[formatter_mypackageFormatter]
format=%(asctime)s %(name)s[%(process)d]: %(levelname)s - %(message)s
datefmt=

In the script:

  1. the logging config is read;

  2. a console_formatter is (re-)created;

  3. a console handler is created with the log level from the command-line option, then added to the "mypackage" logger.

import logging
import logging.config
import os
import sys

import mypackage.module1
import mypackage.module2

def setup_logging(loglevel):
    #
    # load logging config from file
    #
    logging.config.fileConfig('data/mypackage.logging.conf')

    # (re-)create formatter
    console_formatter = logging.Formatter("%(name)s:%(levelname)s: %(message)s")

    # create a console handler
    # and set its log level to the command-line option 
    # 
    console_handler = logging.StreamHandler(sys.stdout)
    console_handler.setFormatter(console_formatter)
    console_handler.setLevel(getattr(logging, loglevel))

    # add console handler to the pre-configured "mypackage" logger
    #
    logger = logging.getLogger('mypackage')
    logger.addHandler(console_handler)


def main():
    # get the console log level from the command-line
    loglevel = 'INFO'
    if len(sys.argv) > 1:
        loglevel = sys.argv[1].upper()

    # load logging config and setup console handler
    #
    setup_logging(loglevel)

    # log from the script to the "mypackage.scripts.main" logger
    #
    log = logging.getLogger(__name__)
    log.debug("some debug message from:" + __name__)
    log.info("some info message from:" + __name__)
    log.error("some error message from:" + __name__)

    # let the modules do their stuff 
    # and log to the "mypackage.module1" and "mypackage.module2" loggers
    #
    mypackage.module1.do_something()
    mypackage.module2.do_something_else()

if __name__== '__main__':
    main()

Things would be simpler if the handlers were "addressable" by name when loaded from a config file.

Then, we could have the mypackage console handler set up in the config file and its log level changed in the code like this:

def setup_logging(loglevel):
    logging.config.fileConfig('data/mypackage.logging.conf')

    logger = logging.getLogger('mypackage')
    console_handler = logger.getHandler('consoleHandler')
    console_handler.setLevel(getattr(logging, loglevel))

There would no need to re-create a formatter either...

(last update: yes, I'm aware of https://docs.python.org/3/library/logging.config.html#incremental-configuration, but in this case, I'm stuck with Python 2.6... :-)

2
pythonloggingconfig
Are you trying to override log level for some handler, or only filter? In other words, should logging.warn("foo") get dumped as DEBUG to file handler, or not logged by file handlers? – Dima Tisnek
If you want to get an answer, please, spend some time making a small example instead of doing copy/paste with a lot of code. – sorin

2 Answers

3
votes

Use dictConfig. Here is an example of logging to multiple files with separate handles in dictConfig. This isn't exactly what you are looking for, but you could modify this example and simply change the level of each handler that you are looking to use.

import os, logging
from logging.config import dictConfig

FORMAT = "%(asctime)s {app} [%(thread)d] %(levelname)-5s %(name)s - %(message)s. [file=%(filename)s:%(lineno)d]"
DATE_FORMAT = None


def setup_logging(name, level="INFO", fmt=FORMAT):
    formatted = fmt.format(app=name)
    log_dir = r'C:/log_directory'
    if not os.path.exists(log_dir):
        os.makedirs(log_dir)

    logging_config = {
        "version": 1,
        'disable_existing_loggers': False,
        "formatters": {
            'standard': {
                'format': formatted
            }
        },
        "handlers": {
            'default': {
                'class': 'logging.StreamHandler',
                'formatter': 'standard',
                'level': level,
                'stream': 'ext://sys.stdout'
            },
            'file': {
                'class': 'logging.handlers.TimedRotatingFileHandler',
                'when': 'midnight',
                'utc': True,
                'backupCount': 5,
                'level': level,
                'filename': '{}/log1.log'.format(log_dir),
                'formatter': 'standard',
            },
            'file2': {
                'class': 'logging.handlers.TimedRotatingFileHandler',
                'when': 'midnight',
                'utc': True,
                'backupCount': 5,
                'level': level,
                'filename': '{}/log2.log'.format(log_dir),
                'formatter': 'standard',
            }
        },
        "loggers": {
            "": {
                'handlers': ['default', 'file'],
                'level': level
            },
            "second_log": {
                'handlers': ['default', 'file2'],
                'level': level
            }
        }
    }

    dictConfig(logging_config)

log.setup_logging(name="log-name", level=LEVEL
logger = logging.getLogger(__name__)
second_logger = logging.getLogger('second_log')
second_logger.propagate = False
2
votes

An approach to update your handler:

import logging

from rootmodule.mymodule import mylogger

def update_handler_level(logger,  handler_type, level="INFO"):
    # if not root logger user logger.parent
    for handler in logger.handlers or logger.parent.handlers:
        if isinstance(handler, handler_type):
            print(handler.level)
            handler.setLevel(getattr(logging, level, "INFO"))
            print(handler.level)

mylogger.debug('test')
update_handler_level(mylogger, logging.StreamHandler)
mylogger.debug('test')

My logging.cfg is pretty similar than your except the fact that the logger name si set in a constant module (a can do module rename without breaking the logging configuration)

To update from command line, you must have a mapping between your opts value and logging.Handler sub class name.