Logging in Python

Introduction

Yes, there are official documents for the "logging" module, which are clear and detailed. They helped a lot to get me started with the "logging" module. But, they seem do not address all my questions directly. Only after I had played with the "logging" module for some time did I find all the answers I wanted.

Here comes the note I took. I am wondering if you have time to read (and interested in reading) this notes. I would be very grateful if you could send me your comments.

Disclaimer

Please note that all code shown in this article is for demostration only. For real-world projects, you should add error handling code etc.

Highlights of behaviors of "logging"

logging_flow.png

A word on log level

Recommend to follow this convention in all other tools:

The larger the log level is, the more sever the message is.

Level Numeric value
CRITICAL 50
ERROR 40
WARNING 30
INFO 20
DEBUG 10
NOTSET 0

We need NOT format messages ourselves

logging.warning('hello %s, it is %s now',
                'world',
                datetime.datetime.today())

Exceptions in logging

All one have to do is set "logging.raiseExceptions" to "False" in production environment. The exceptions are just silently ignored (and you may have to bite the bullet of losing log).

Hierarchy of Logger

  • There is a single root logger.

    A caveat, though: root Logger is logging.getLogger() or logging.getLogger(''), NOT logging.getLogger('root')

  • The hierarchy is determined by the name.
    • Logger named "A" is a child of root logger.
    • Logger "A.B" is a child of logger "A".
  • Log propagation

    By default (controlled by Logger.Propagate), logs are passed to the handlers of ancestor loggers. Explained in details later.

Logger and Handler

  • Every logger should have at least one handler.
    • The parent's handlers also count (unless Propagate is false). Hence, need not set handler explicitly for every logger.
    • In fact, adding a handler to both a logger and its ancestors is wrong. That will cause the handler called multiple times for each log record. E.g., messages repeat several times in log.
    • logging.basicConfig() basically create a handler for root logger.
  • A logger controls if a log record should be created while a handler determines how to handle the log record sent to it. Refer to Filtering and Altering.

Filtering and Altering

This task involves log level and filters.

  • The log level of a logger is kind of "global" to all handler of that logger, including the handlers of its ancestors.
  • The log level of a handler only impacts the output of this handler itself.
  • The log level of a parent logger does NOT impact logs from its child loggers. The reason is: those log record are propagated to parent's handlers from the child loggers. Therefore, only the log level of father's handlers matters.
  • "logging.NOTSET" is a special log level. I would say it is NOT a log level but rather a flag. This flag tells the logging system to use a "pre-defined" logging pattern. That is, let the parent logger decide the log level for the child logger.
  • There are more log levels in addition to the named ones ("logging.DEBUG", "logging.INFO" etc.)
  • You can change the log level of loggers/handlers on the fly. I.e. run some code, then change log level, then some other code. The thing is, you are able to do something does not necessarily mean you should do it.
  • Filters works in a similar way in terms of the difference between attaching it to a logger and attaching it to a handler.
  • Filters may be used to alter content of log records. Such as adding new attributes, modifying messages etc.

The Very Basic Logging

This is really the very basic logging set up for simple scripts 

#!/usr/bin/python -t
import logging
import os.path

logging.basicConfig(
    level=logging.INFO,
    filename=os.path.realpath(__file__)+'.log',
    # filemode='w'                # mainly useful during dev
    # format='%(asctime)s %(levelname)s %(name)s: %(message)s',
    # the following format + datefmt matches my emacs log mode definition
    format='%(asctime)s %(levelname)s %(filename)s:%(lineno)d: %(message)s',
    datefmt='%Y-%m-%d %H:%M:%S')
# ...
logging.debug('')
logging.info('')
logging.warning('')

A Practical Logging set up

A more frequently wanted setup is to print necessary prompts and messages on screen (stdout) while put detailed information into a log file. 

#!/bin/env python
# -*- coding: utf-8 -*-

# Print INFO to stdout while debug etc. into log file, STDERR NOT USED.

import logging
import logging.handlers
import sys
import os.path

def init_logging(filename=None):
    formatter = logging.Formatter(
        fmt='%(asctime)s %(levelname)s %(name)s: %(message)s',
        datefmt='%Y-%m-%d %H:%M:%S')
    logfile = logging.handlers.RotatingFileHandler(filename=filename, mode='w')
    logfile.setLevel(logging.NOTSET)

    stdout = logging.StreamHandler(stream=sys.stdout)
    stdout.setLevel(logging.INFO)

    for handler in (logfile, stdout):
        handler.setFormatter(formatter)
        logging.getLogger().addHandler(handler)

    # DO NOT use "basicConfig", which creates an extra stream handler
    logging.getLogger().setLevel(logging.NOTSET)

if __name__ == '__main__':
    init_logging(os.path.join('/tmp', sys.argv[0] + '.log'))
    # To show how it works
    for each in (logging.getLogger('s1'),
                 logging.getLogger('s1.ss'),
                 logging.getLogger('s2')):
        each.debug('')
        each.info('')
        each.warning('')

Log Level per Sub-System

Confronted with a bug, we want to change the log level of suspicious subsystem/subsystems only instead of promote the log level of the whole system.

It seems to me this can be achieved this way:

  1. Each subsystem has its own logger, a non-root logger. Note that it is safe to name all the loggers as "logger" so long as they are in different modules.
  2. All non-root loggers use default log level ("NOTSET").
  3. All non-root loggers bind no handler.
  4. Root logger is configured with log level, formatter, handler etc.

This way,

  • Almost no extra coding. Most configuration is still done on root logger. One just define and use different loggers for different sub-systems.
  • Normally, changing log level of root logger to change the overall log level.
  • If certain sub-system is of special interests, just change the log level of corresponding logger (either promote or demote it). This will NOT impact logs from other loggers.
  • If a sub-system changed its log level, all its sub-sub-system log level changed as well (remember the meaning of "logging.NOTSET"?).
    • The good side is that is usually what we want.
    • If that is not the case, we can only explicitly set sub-system and its sub-sub-system to different log levels some like this: 
      logging.getLogger('s1').setLevel(logging.DEBUG)
logging.getLogger('s1').getChild('ss').setLevel(
    logging.getLogger().getEffectiveLevel())

With all above discussion, here is the sample code. 

#!/usr/bin/python -t

# NO need to configure loggers explicitly in modules/subsystems. Just log with
# loggers got by logging.getLogger. For instance:

# In module/subsystem 1, logger = logging.getLogger('s1') or just
# logger = logging.getLogger(__name__)

# In sub module of module 1, logger = logging.getLogger('s1.ss')

# In module 2, logger = logging.getLogger('s2')

# In main entrance
import logging
logging.basicConfig(
    level=logging.WARNING,
    # filename='test.log',
    format='%(asctime)s %(levelname)s %(name)s: %(message)s',
    # datefmt='%Y-%m-%d %H:%M:%S',
    )

# Change log level per sub-system
logging.getLogger('s1').setLevel(logging.DEBUG)
logging.getLogger('s1').getChild('ss').setLevel(
    logging.getLogger().getEffectiveLevel())

# To show how it works
for each in (logging.getLogger('s1'),
             logging.getLogger('s1.ss'),
             logging.getLogger('s2')):
    each.debug('')
    each.info('')
    each.warning('')

Seperate stdout and stderr: Dispatching Based on Log Level

NOTE: this section demonstrates some capabilities of the logging module. However, we do not really want to use this convoluted solution in real-world project. Log is log, and should go to log file(s). In contrast, stdout and stderr are for use interaction and therefore should NOT be part of log system. Instead, one may want to write wrapper functions to save stdout and stderr messages to log file(s) as well.

This section discusses in detail how to dispatch logs to different destinations/files by log level.

For example, we want information messages goes to the stdout, error messages goes to the stderr, while everything goes to a log file.

  • The "logging.basicConfig" may not applicable any more.

    This function creates an anonymous handler, which we have little control over. Since we are talking about an "advanced" topic now, maybe we prefer define more than one handlers explicitly, and define their log levels, formatters, filters etc. explicitly as well.

  • In this case, the logger's log level is NOTSET while handlers' log levels are set respectively.
    • I do it this way since every handler deals with log messages of different log level. Therefore, we have to delegate the determination of logging or not to handlers.
    • If we do want to raise the "global log level", we are still free to do that by setting the logger's log level.
  • In this case, I combined log levels and filters to get logs within a range of log level.

    There is an interesting fact of stdout: we want stdout accept messages log levels of which are between logging.INFO and logging.WARNING. But, there is no way to set a log level range for certain logger (or handler). 

#!/bin/env python
# -*- coding: utf-8 -*-

# NO need to configure loggers explicitly in modules/subsystems. Just log with
# loggers got by logging.getLogger. For instance:

# In module/subsystem 1, logger = logging.getLogger('s1') or just
# logger = logging.getLogger(__name__)

# In sub module of module 1, logger = logging.getLogger('s1.ss')

# In module 2, logger = logging.getLogger('s2')

# In main entrance

import logging
import logging.handlers
import sys

class IgnoreHigherLog(logging.Filter):

    def __init__(self, high_level):
        logging.Filter.__init__(self)
        self.level_to_discard = high_level

    def filter(self, record):
        if record.levelno < self.level_to_discard:
            return True

    def set_high_level(self, high_level):
        self.level_to_discard = high_level

def init_logging():
    formatter = logging.Formatter(
        fmt='%(asctime)s %(levelname)s %(name)s: %(message)s',
        datefmt='%Y-%m-%d %H:%M:%S')

    logfile = logging.handlers.RotatingFileHandler(
        filename='/tmp/test.log', mode='w')

    logfile.setLevel(logging.NOTSET)

    stderr = logging.StreamHandler(stream=sys.stderr)
    stderr.setLevel(logging.WARNING)

    stdout = logging.StreamHandler(stream=sys.stdout)
    stdout.setLevel(logging.INFO)
    stdout.addFilter(IgnoreHigherLog(logging.WARNING))

    for handler in (logfile, stdout, stderr):
        handler.setFormatter(formatter)
        logging.getLogger().addHandler(handler)

    # DO NOT use "basicConfig", which creates an extra stream handler
    logging.getLogger().setLevel(logging.NOTSET)

    # Change log level per sub-system
    logging.getLogger('s1').setLevel(logging.DEBUG)
    logging.getLogger('s1').getChild('ss').setLevel(
        logging.getLogger().getEffectiveLevel())

if __name__ == '__main__':
    init_logging()
    # To show how it works
    for each in (logging.getLogger('s1'), logging.getLogger('s1.ss'),
                 logging.getLogger('s2')):
        each.debug('')
        each.info('')
        each.warning('')

Sub-System Based Logging

A more common case than dispatching based on log level is to dispatch logs based on their sources (sub-system/module).

Code for such need is similar to that for dispatching based on log level. But, in this case, we

  • Bind handlers to different loggers instead of bind all handlers to root logger.
  • All handers leave log level as default ("NOTSET") so that what discussed in Log Level per Sub-System still holds true.

For code, refer to Logging for Tracking.

Logging for Tracking

With sub-system based logging ready, one may still want more. For me works in telecom industry, it is natural to want the ability to trace a partical phone call by printing logs related to that call ID without impacting the over all log level.

This, as far as I can think of, can be achieved this way:

  1. Unset (or lower) log level of every logger involved to ensure all related log records (along with other log records) are send to handlers.
    • If all non-root loggers are of level "NOTSET", it is good for us: changing log level of the root logger will do the job.
  2. Explicitly set the log level of every handler so that the "actual" log level keeps the same.
    • If all handlers are bound to the root logger, iterate the "logging.getLogger().handlers".
  3. Create a dedicated handler with log level NOTSET (or low enough) so that it pass all logs it received to its filters.
  4. Add a filter to that handler to filter out records we do not need.

Note that

  • This solution also works in sub-system level. Just regard the sub-system's logger as if it is the root logger.
  • If loggers generate logs in an uniform format, it would be very easy to impliment a filter. As shown in the sample code.

An Example

#!/usr/bin/python -t

# NO need to configure loggers explicitly in modules/subsystems. Just log with
# loggers got by logging.getLogger. For instance:

# In module/subsystem 1, logger = logging.getLogger('s1') or just
# logger = logging.getLogger(__name__)

# In sub module of module 1, logger = logging.getLogger('s1.ss')

# In module 2, logger = logging.getLogger('s2')

# In main entrance
import logging
import logging.handlers
import sys


class MyFilter(logging.Filter):
    '''This class assumes all non-root loggers has level NOTSET'''

    def __init__(self):
        logging.Filter.__init__(self)
        self.key = None
        self.subsys = None
        self.is_active = False

    def filter(self, record):
        if not self.is_active:
            # let everything pass
            return True
        # suppose all logs created by logger.xxx('%s ...', key, ...)
        if self.key != None and record.args[0] != self.key:
            return False
        elif self.subsys != None and record.name != self.subsys:
            return False
        else:
            return True

    def activate(self):
        self.is_active = True

    def deactivate(self):
        self.is_active = False

    def set_target_key(self, key):
        self.key = key

    def set_target_subsys(self, subsys):
        self.subsys = subsys


def init_logging():
    formatter = logging.Formatter(
        fmt='%(asctime)s %(levelname)s %(name)s: %(message)s',
        datefmt='%Y-%m-%d %H:%M:%S')

    handler1 = logging.handlers.RotatingFileHandler(filename='/tmp/1.log')
    logging.getLogger('s1').addHandler(handler1)

    handler2 = logging.handlers.RotatingFileHandler(filename='/tmp/2.log')
    logging.getLogger('s2').addHandler(handler2)

    # To trace a particular phone call
    tracker = logging.StreamHandler(stream=sys.stdout)
    the_filter = MyFilter()
    tracker.addFilter(the_filter)
    logging.getLogger().addHandler(tracker)

    for one in (handler1, handler2, tracker):
        one.setFormatter(formatter)

    return the_filter


# Usage
##########################
def test_logging():
    for each in (logging.getLogger('s1'),
                 logging.getLogger('s1.ss'),
                 logging.getLogger('s2')):
        for i in range(1, 3):
            each.debug('%s', i)
            each.info('%s', i)
            each.warning('%s', i)


def main():
    the_filter = init_logging()

    print '# By default, no trace, root logger controls the "global log level"'
    logging.getLogger().setLevel(logging.WARNING)
    test_logging()

    print '# Trace a particular call flow'
    the_filter.set_target_key(1)
    the_filter.activate()
    test_logging()

    print '# Limit the trace within s1 only (no sub-system either)'
    the_filter.set_target_subsys('s1')
    test_logging()

    print '# Deactivate'
    the_filter.deactivate()
    test_logging()

if __name__ == '__main__':
    main()

An Example Simpler by Suits Many Cases

The previous example might be a little bit overwhelming. But in fact, many projects are much simpler:

  • All non-root loggers are of level "NOTSET".
  • All handlers are with "NOTSET" and are bound to root logger.
  • When trace turned on, want every log for the target while other logs printed based on log level as it is before the trace turned on.

The code can then be much simpler as well. 

import logging


class MyFilter(logging.Filter):

    def __init__(self, string):
        logging.Filter.__init__(self)
        self.str = string
        self.old_level = None

    def filter(self, record):
        if self.str in record.msg or record.levelno >= self.old_level:
            return True
        else:
            return False

    def activate(self):
        logger = logging.getLogger()
        self.old_level = logger.level
        logger.setLevel(logging.NOTSET)
        # filter on non-logger not impact logs from other loggers
        for handler in logger.handlers:
            handler.addFilter(self)

    def deactivate(self):
        logger = logging.getLogger()
        logger.setLevel(self.old_level)
        for handler in logger.handlers:
            handler.removeFilter(self)

Logging in Libraries

This should be much the same as that for sub-systems.

  • Every library logger should bind an instance of "logging.NullHandler" (i.e. "logging.NullHandler()") in case the library's users Add no handler to the root logger or the library handler.
  • Do not add any other handler, set log level, or add filter for loggers in libraries. Those things should be determined by the libraries' users.

Advices

Always Use Per-Sub-System Loggers

After discussing several logging scenarios at length, you may find that

  • To use sub-system loggers solely need no extra effort. It is as simple 'getLogger(subsys_name)' to get the logger and use it. You only pay extra effort (configuring the non-root loggers) when you need extra features.
  • Using a logger per sub-system does not necessarily complicate the control of log. Without extra configuration, we can still control logging (log level, destination, filter etc.) as if only root logger used.
  • But, using sub-system loggers enables us to achieve finer granularity of log control when we have to, with almost trivia effort.
    • Log settings such as log levels, filters, handlers can be easily changed in a "central" place.
  • It is hard to switch to this strategy (one logger per sub-system) if you had not do that in the very beginning. The reason is obvious: logging function calls are scattered all around in source code.

Therefore, I would like to suggest:

Always "define" loggers for every sub-system/module and use them instead of the root logger even if using root logger fulfill all your needs for the time being.

"import"-able log settings

  • All non-root logger are get at the beginning of each source file. No handler, no log level set. This way configuration of the root logger (and that of its handlers) determin the logging behavior of the whole system.
  • Even the "main" module has a non-root logger and logging use that instead of using root logger directly.
  • Put root logger configuration into a function. And in every module: 
    if __name__ == '__main__':
    util.initlogger()
    # ...

With this strategy, the logging settings takes effect for every module if it is run as the main module. But if it is imported, the logging settings is ignored silently instead of changing "global" logging settings brutally.

Control Logging via Configuration File

So far so good! But, wait, isn't it a convention to put configurations into configuration files?

The logging system does provide such ability. In this section, I dsicuss two ways to achieve that.

Use dictConfig

The "logging.config.dictConfig" itself is actually not a method dealing with configuration files directly. Instead, it requires a python dict object as the first argument.

A shortcoming that might seem. But, in fact, it enables us chosing configuration file format freely. For example, one may read configurations from an XML configuration file, convert them into a dict and pass it to the "dictConfig".

At the time of this writing, I found YAML is rather easy to handle. With all logging related configurations goes into file "logging.yml", the source code remains only one line to load that file besides my classes, functions etc.

The YAML file: 

# To load, logging.config.dictConfig(yaml.load(open('./conf.yml', 'r')))

version: 1

root:
    # NOTE: root logger is NOT under "loggers"
    handlers: [trace]
    level: NOTSET

loggers:
    s1:
        handlers: [log1]
    s2:
        handlers: [log2]

handlers:
    log1:
        class: logging.handlers.RotatingFileHandler
        formatter: mine
        filename: 1.log
        level: WARNING
    log2:
        class: logging.handlers.RotatingFileHandler
        formatter: mine
        filename: 2.log
        level: INFO
    trace:
        class: logging.StreamHandler
        formatter: mine
        level: DEBUG
        filters: [mine]

formatters:
    mine:
        format: '%(asctime)s %(levelname)-8s %(name)-6s: %(message)s'

filters:
    mine:
        (): test.MyFilter
        key: 1
        subsys: s1

One issue of using YAML, though, is that module "yaml" is not a standard module. We have to install it ourselves.

Use INI file

If you can neither install "yaml" etc. nor handcraft xxx_to_dict on production hosts to load configuration files (in YAML, or JSON etc.), you can try "logging.config.fileConfig".

A major issue of this measure is: it does not support configuration for filters (and no plan to support it).

Hence, this is not recommended, feel free to skip this section. If you can bear with the limitation, read on.

The code becomes very succinct as well since all information goes into the configuration file.

The configuration is a bit lengthy, in my opinion. 

# To load, logging.config.fileConfig('./conf.ini')

[loggers]
keys = root, subsys1, subsys2, subsubsys

[handlers]
keys = log1, log2, trace

[formatters]
keys = mine

[filters]
# this section makes NO sense
keys = mine

[logger_root]
level = NOTSET
handlers = trace

[logger_subsys1]
qualname = s1
handlers = log1

[logger_subsubsys]
qualname = s1.ss
handlers =

[logger_subsys2]
qualname = s2
handlers = log2

[handler_log1]
class = logging.handlers.RotatingFileHandler
args = ('./1.log', 'a')
formatter = mine
level = WARNING

[handler_log2]
class = logging.handlers.RotatingFileHandler
args = ('./2.log', 'a')
formatter = mine
level = WARNING

[handler_trace]
class = logging.StreamHandler
args = (sys.stderr,)              # the comma is mandatory
formatter = mine
filters = mine # does NOT work

[filter_mine]
# filters does NOT work at all
class = logging.Filter
args = ('s1')

[formatter_mine]
class = logging.Formatter
format = %(asctime)s %(levelname)-8s %(name)-6s: %(message)s
formatter = mine

Logging from Multiple Threads

TODO: but not in a foreseeable future.

Misc

Formatter for High-Resolution Time-Stamp

#!/bin/env python
# -*- coding: utf-8 -*-

'''High-resolution time based on
http://stackoverflow.com/questions/6290739/python-logging-use-milliseconds-in-time-format'''

import logging
import datetime


class MyFormatter(logging.Formatter):

    converter = datetime.datetime.fromtimestamp

    def formatTime(self, record, datefmt=None):
        create_time = self.converter(record.created)
        if datefmt:
            stamp = create_time.strftime(datefmt)
        else:
            stamp = '%s.%03d' % (create_time.strftime('%Y-%m-%d %H:%M:%S'),
                                 record.msecs)
        return stamp

def demo():
    formatter = MyFormatter(
        fmt='%(asctime)s %(levelname)s %(name)s: %(message)s',
        datefmt='%Y-%m-%d %H:%M:%S.%f')

    logging.basicConfig(level=logging.INFO)
    for handler in logging.getLogger().handlers:
        handler.setFormatter(formatter)

    logging.info('datefmt:%s', formatter.datefmt)

    formatter.datefmt = None
    logging.info('datefmt:%s', formatter.datefmt)


if __name__ == '__main__':
    demo()

Change Log Configure on the Fly

Suppose the application runs 7x24. It would be nice if we type some commands and then the logging configuration changes without restarting the application.

TODO: but maybe never


Created: 2015-12-11 Fri 11:38 by Emacs 24.5.1 (Org mode 8.2.10)

comments powered by Disqus