Python logging to multiple handlers, at different log levels?

Question

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... :-)

Answer 1

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.