python: logging module

Basic concepts

Loggers

expose the interface that application code directly uses.

Handlers

send the log records (created by loggers) to the appropriate destination.

StreamHandler
sends logging output to streams such as sys.stdout, sys.stderr or any file-like object (or, more precisely, any object which supports write() and flush() methods).
FileHandler
sends logging output to a disk file.

Filters

provide a finer grained facility for determining which log records to output.

Formatters

specify the layout of log records in the final output.

class logging.Formatter(fmt=None, datefmt=None, style='%')
If no fmt is specified, '%(message)s' is used. If no datefmt is specified, the ISO8601 date format is used;
The style parameter can be one of %, { or $ and determines how the format string will be merged with its data: using one of %-formatting, str.format() or string.Template.
the default date format is:

%Y-%m-%d %H:%M:%S

Logging Levels

logging-level

LogRecord attributes¶

attribute      format
=============================
levelname   |   %(levelname)s    : Text logging level for the message ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL').
message     |   %(message)s
name        |   %(name)s         : Name of the logger used to log the call.

When to logging

level                    When it’s used
====================================================
print()    |        Display console output for ordinary usage of a command line script or program
DEBUG      |        Detailed information, typically of interest only when diagnosing problems.
INFO       |        Confirmation that things are working as expected.
WARNING    |        An indication that something unexpected happened, or indicative of some problem in the near future (e.g. ‘disk space low’). The software is still working as expected.
ERROR      |        Due to a more serious problem, the software has not been able to perform some function.
CRITICAL   |        A serious error, indicating that the program itself may be unable to continue running.

The logging tree

The Logger instances are configured in a tree structure, based on their names, as illustrated in the figure. Typically each application or library defines a base name, with loggers for individual modules set as children. The root logger has no name.

logging-tree.png

The tree structure is useful for configuring logging because it means each logger does not need its own set of handlers. If a logger does not have any handlers, the message is handed to its parent for processing. This means that for most applications it is only necessary to configure handlers on the root logger, and all log information will be collected and sent to the same place.

Logging Flow

logging_flow.png

Logging Configuration

Programmers can configure logging in three ways:

Creating loggers, handlers, and formatters explicitly using Python code that calls the configuration methods listed above.
Creating a logging config file and reading it using the fileConfig() function.
Creating a dictionary of configuration information and passing it to the dictConfig() function.

logging.basicConfig(**kwargs)

Does basic configuration for the logging system by creating a StreamHandler with a default Formatter and adding it to the root logger.

import logging

# create logger
logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)

# create console handler and set level to debug
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

# create formatter
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# add formatter to ch
ch.setFormatter(formatter)

# add ch to logger
logger.addHandler(ch)

# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warn('warn message')
logger.error('error message')
logger.critical('critical message')

run it,

$ python simple_logging_module.py
2005-03-19 15:10:26,618 - simple_example - DEBUG - debug message
2005-03-19 15:10:26,620 - simple_example - INFO - info message
2005-03-19 15:10:26,695 - simple_example - WARNING - warn message
2005-03-19 15:10:26,697 - simple_example - ERROR - error message
2005-03-19 15:10:26,773 - simple_example - CRITICAL - critical message

File configuration

The fileConfig() API is older than the dictConfig() API and does not provide functionality to cover certain aspects of logging. For example, you cannot configure Filter objects
read more about: Configuration file format¶

import logging
import logging.config

logging.config.fileConfig('logging.conf')

# create logger
logger = logging.getLogger('simpleExample')

# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warn('warn message')
logger.error('error message')
logger.critical('critical message')

Here is the logging.conf file:

[loggers]
keys=root,simpleExample

[handlers]
keys=consoleHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

[logger_simpleExample]
level=DEBUG
handlers=consoleHandler
qualname=simpleExample
propagate=0

[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=simpleFormatter
args=(sys.stdout,)

[formatter_simpleFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
datefmt=

Configuration dictionary schema¶

import logging
from logging.config import dictConfig

logging_config = dict(
    version = 1,
    formatters = {
        'f': {'format':
              '%(asctime)s %(name)-12s %(levelname)-8s %(message)s'}
        },
    handlers = {
        'h': {'class': 'logging.StreamHandler',
              'formatter': 'f',
              'level': logging.DEBUG}
        },
    root = {
        'handlers': ['h'],
        'level': logging.DEBUG,
        },
)

dictConfig(logging_config)

logger = logging.getLogger()
logger.debug('often makes a very good meal of %s', 'visiting tourists')

Examples

Logging from multiple modules

# myapp.py
import logging
import mylib

def main():
    logging.basicConfig(filename='myapp.log', level=logging.INFO)
    logging.info('Started')
    mylib.do_something()
    logging.info('Finished')

if __name__ == '__main__':
    main()

# mylib.py
import logging

def do_something():
    logging.info('Doing something')

If you run myapp.py, you should see this in myapp.log:

INFO:root:Started
INFO:root:Doing something
INFO:root:Finished

Reference

pyDoc: Loging Cookbook