Python Logging

notes about logging in python. Put together from reading the logging module source, PEP 282, the official documentation, as well as the blog entries mentioned in References.

Its just intended to collect some notes in one place...so it will (most likely) never comprehensive.

Basic Usage

Basic usage of the module looks like this:

import logging

logging.basicConfig(level=...)

logger = logging.getLogger(...)
logger.info('info message')
logger.error('error message')

This will configure the default log level of the logging module, as well as create a logger for a specific facility and logs some messages.

How would we use this in a normal application? The logging module allows one to create a hierarchy of loggers (simply specify the levels seperated with dots as the logging facility). Lower levels in the hierarchy will inhert settings form the higher levels. This way we can configure logging for specific parts of the application.

One idea is to use the module hierarchy of the application to set up the logging hierarchy. The simplest way to do this is to use the module name as the log facility. An application could look like:

# foo.py

import logging

logger = logging.getLogger(__name__)

def bar():
  logger.info('info message')

def baz():
  logger.error('xy error happened')

# ham.py

import logging

logger = logging.getLogger(__name__)

def eggs():
  logger.info('a warning message')

# main.py

import logging
import foo
import ham

logging.basicConfig(level=logging.ERROR)
logging.getLogger('ham').setLevel(logging.INFO)

foo.bar()
ham.eggs()
foo.baz()

In this example application we use the ERROR log level as the default loglevel for the application. For the ham module we overwrite it to the INFO loglevel.

Why does the basic example not work in IPython?

The logging.basicConfig function does only work if it is the first operation done with the logging module. If we execute the following code in the IPython console:

import logging
root = logging.getLogger()
root.handlers

Out[1]: [<logging.StreamHandler at 0x3875710>]

We can see that there was already a logging handler created by some of the imported modules, which means that basicConfig will not work correctly anymore. There are two possible ways to work around this:

configure the logger manually
manually reset the logger by deleting all handlers, so that basicConfig works again

The first possibility would look like:

import logging

logging.getLogger().setLevel(logging.INFO)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
for h in logger.handlers:
  h.setFormatter(formatter)

The second possibility looks like:

while logging.root.handlers:
  logging.root.removeHandler(logging.root.handlers[-1])
logging.basicConfig(format='%(asctime)s %(message)s', level=logging.DEBUG)

Colorize output in shell/Ipython qtconsole

Since both the shell and the qtconsole support ANSI escape codes, it is simple to provide a formatter the colorized output:

import logging
logger = logging.getLogger()
class ColorFormatter(logging.Formatter):
  def __init__(self, fstring=None, formats=None):
    """ initialize formatter

    The format string used can be specified, as well as the formats used.
    ´fstring´ specifies the format string to use, the syntax is the same as
      for str.format(). The available attributes are:
      - {asctime}     : human readable time of log creation
      - {created}     : time of log creation as returned by time.time()
      - {filename}
      - {funcName}
      - {levelname}   : human readable loglevel name (e.g. INFO)
      - {levelno}     : internal loglevel integer
      - {lineno}
      - {module}
      - {msecs}       : millisecond portion of {created}
      - {message}     : logmessage with arguments
      - {name}        : name of the logger
      - {pathname}    : full path of source (if available)
      - {process}     : PID
      - {processName} : process name (if available)
      - {relativeCreated}
              : logging time in ms after loading of logging module
      - {thread}      : thread ID (if available)
      - {threadName}  : thread name (if available)
      defaults to the standard logging format

    ´formats´ has to be a dict with the logging level as keys, containing
      strings with ANSI escape sequences for the desired formatting
      defaults to custom scheme
    """
    self.formats = formats
    if formats is None:
      self.formats = {
        logging.DEBUG   : '\x1b[32;2m',
        logging.INFO    : '\x1b[30m',
        logging.WARNING : '\x1b[34;1m',
        logging.ERROR   : '\x1b[31;1m',
        logging.CRITICAL: '\x1b[35;1m',
        }
    self._clean = '\x1b[0m'
    
    self.formatstr = fstring
    if fstring is None:
      self.formatstr = '{relativeCreated:.1f}:{levelname}:{name}:{message}'

  def format(self, record):
    return ''.join([
      self.formats[record.levelno],
      self.formatstr.format(message=record.getMessage(), **(record.__dict__)),
      self._clean,
      ])

This formatter can simply be used by setting it as the formatter for the handler of the root logger:

formatter = ColorFormatter()
logger.handlers[0].setFormatter(formatter)

Note that access to ´logger.handlers´ is implementation specific and might cease to work in the future.

Execute this in addition to see the formatting in action:

alog = logging.getLogger('a')
alog.setLevel(logging.DEBUG)

alog.debug('these')
alog.info('are')
alog.warning('the')
alog.error('used')
alog.critical('colors')

andreasWallner/logging.md

Python Logging

Basic Usage

Why does the basic example not work in IPython?

Colorize output in shell/Ipython qtconsole

References