« Converting Single-Tenant to Multi-Tenant Apps | Main | What is the Difference Between Apprenda and Windows Azure? »

September 03, 2012

Configuring Logging in Python - The Real Life Example

For some time I was playng with Python and few nights ago I finally reached the point that I had to implement configurable logging in order to capture information that would help me troubleshoot some issues. Although I am pretty familiar with Log4J, which is very similar to the Python logging module it took me some time to get my loggers configured properly. Unfortunately the documentation is not very rich on examples hence I thought it will be useful also for other people to publish a good Python logging example tailored to a real life scenario.

I will describe few gotchas that I discovered while playing with the logging module.

Python Logging Scenario

In order to demonstrate the logging functionality I will use a simple Python application that consist of the following packages:

rootpackage
rootpackage.levelonepackage
rootpackage.levelonepackage.leveltwopackage


Each package (except the rootpackage one) contains two modules with exactly the same code in it (I know, I know - it is against all rules of software development to repeat code:)). The code initializes the logger and also defines a function that logs a message with each log level. Here is it:

[1] import logging
[2] import logging.config
[3] from rootmodule.utils import get_logging_config

[4] # set up logging
[5] logging.config.fileConfig(get_logging_config())
[6] logger = logging.getLogger(__name__)

[7] def log_messages():
[8]     """Logs a message with each of the log levels
[9]     """
[10]   print logger.level
[11]     logger.critical("This is a critical message")
[12]     logger.error("This is an error message")
[13]     logger.warn("This is a warning message")
[14]     logger.info("This is an info message")
[15]     logger.debug("This is a debug message")

Line [6] above is important to note because this is the easiest way to get the full name of the module (including the package name). This will allow you to easily change the logging configuration using the package hierarchy structure.

The rootpackage package contains additional module called utils with just one function in it with the sole purpose to retrieve the absolute path to the logging configuration file. Here the code for it:

from os import path

def get_logging_config():
    """Returns the absolute path to the logging config file
    """
    return path.join(path.split(rootpackage.__file__)[0], 'logging.conf')

The logging configuration file logging.conf is also stored in the folder where the rootpackage modules are stored.

Here is the structure of the files on the app.

+ rootpackage
    - __init__.py
    - logging.conf
    - root_logging.py
    - root_logging2.py
    - utils.py
    + levelonepackage
        - __init__.py
        - lovelone_logging.py
        - levelone_logging2.py
        + leveltwopackage
            - __init__.py
            - leveltwo_logging.py
            - leveltwo_logging2.py


Hence there are 3 packages(rootpackage, levelonepackage and leveltwopackage) in the sample app, 7 modules (root_logging,root_logging2, utils, levelone_logging, levelone_logging2
leveltwo_logging and leveltwo_logging2) and 1 logging configuration file (logging.conf). You can download the full source code for the Python logging example from my site.

Sample App Logging Goals

Now that you have looked at the app let's set the following four goals for logging from the app:

  • Limit the messages to a particular log level for a module in particular package
  • Limit the messages to a particular log level for a specific package
  • Log the messages from particular package in a file while the messages from other packages to the console
  • Log the messages from the same package in a file as well as on the console together with the messages from other packages

Those seems to be enough to give you a good idea what is possible as well as how to change the configuration to achieve the desired outcome. Let's start!

Configuring Python Logging

As you may already be aware from Python documentation there are three main objects in Python logging package that you need to configure. Those are the Logger, Handler and Fromatter. In this post I will concentrate on the Logger and the Handler objects and will use a simple Formatter as this one:

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


This formatter will print a message in the following format:

2012-08-23 23:46:03,463 - [rootpackage.root_logging] - DEBUG - This is a debug message


There are other object like Filter for example but I will not discuss those.

Here is the initial code for the logging.conf file that enables DEBUG level for all the the module in my sample app:

[1] [loggers]
[2] keys = root,rootlogging,rootlogging2,levelonelogging,
levelonelogging2,leveltwologging,leveltwologging2


[3] [handlers]
[4] keys = console


[5] [formatters]
[6] keys = generic


[7] [logger_root]
[8] level = DEBUG
[9] handlers = console
 


[10] [logger_rootlogging]
[11] level = DEBUG
[12] handlers = console
[13] qualname = rootpackage.root_logging
[14] propagate = 0


[15] [logger_rootlogging2]
[16] level = DEBUG
[17] handlers = console
[18] qualname = rootpackage.root_logging2
[19] propagate = 0


[20] [logger_levelonelogging]
[21] level = DEBUG
[22] handlers = console
[23] qualname = rootpackage.levelonepackage.levelone_logging
[24] propagate = 0


[25] [logger_levelonelogging2]
[26] level = DEBUG
[27] handlers = console
[28] qualname = rootpackage.levelonepackage.levelone_logging2
[29] propagate = 0


[30] [logger_leveltwologging]
[31] level = DEBUG
[32] handlers = console
[33] qualname = rootpackage.levelonepackage.leveltwopackage.leveltwo_logging
[34] propagate = 0


[35] [logger_leveltwologging2]
[36] level = DEBUG
[37] handlers = console
[38] qualname = rootpackage.levelonepackage.leveltwopackage.leveltwo_logging2
[39] propagate = 0


[40] [handler_console]
[41] class = StreamHandler
[42] level = DEBUG
[43] formatter = generic
[44] args = (sys.stdout,)


[45] [formatter_generic]
[46] format=%(asctime)s - [%(name)s] - %(levelname)s - %(message)s

Except the Formatter that I explained earlier I have defined 7 Loggers (one for each of the modules in the app except for the utils one and one for the root Logger) and one Handler for handling console logs.

Lines 2, 4 and 6 from the logging.conf file define the dictionary keys for the configuration of the different logging objects (Loggers, Handlers and Formatters). If you define a configuration key for one of the objects you MUST have section in logging.conf that corresponds to this key. For example I have defined Logger configuration key levelonelogging. The corresponding section for this key is [logger_levelonelogging] and the information from that section will be used to configure the corresponding logger. Also, as Gevin Baker mentions in his blog post A real Python logging example, you SHOULD NOT add any spaces in the keys list.

If you try to call the log_messages() function from any of the modules you will see similar output on the console:

10
2012-08-26 20:32:40,302 - [rootpackage.root_logging] - CRITICAL - This is a critical message
2012-08-26 20:32:40,302 - [rootpackage.root_logging] - ERROR - This is an error message
2012-08-26 20:32:40,302 - [rootpackage.root_logging] - WARNING - This is a warning message
2012-08-26 20:32:40,302 - [rootpackage.root_logging] - INFO - This is an info message
2012-08-26 20:32:40,302 - [rootpackage.root_logging] - DEBUG - This is a debug message


The only difference you will see is that for different modules you will get the module names in the square brackets. The first row of the output is the numeric equivalent of the log level, and in the case of DEBUG this is 10.

Changing the Log Level for Python Module

Now, let's see what changes we need to make in order to limit the messages from one of the modules to only ERROR messages. Let's for example choose module rootpackage.levelonepackage.levelone_logging2 for our test. The configuration for that module is done in section [logger_levelonelogging2] starting at line 25. The only change you need to do is to change line 26 to the following:

[26] level = ERROR

and you will get the following output if you call log_messages() from the module rootpackage.levelonepackage.levelone_logging2:

40
2012-08-26 21:55:29,654 - [rootpackage.levelonepackage.levelone_logging2] - CRITICAL - This is a critical message
2012-08-26 21:55:29,654 - [rootpackage.levelonepackage.levelone_logging2] - ERROR - This is an error message


All other modules (including rootpackage.levelonepackage.levelone_logging) will continue to log with level DEBUG. As you can see this was pretty simple.

Changing the Log Level for Python Package

Next we wanted to have all the modules from particular package to use the same log level. Because we started with a module rootpackage.levelonepackage.levelone_logging2 in package rootpackage.levelonepackage let's configure the logging in a way that all modules in this package (both levelone_logging and levelone_logging2) log with level ERROR. We will need to do few more modifications to our configuration file. Here are the modifications that we need to make:

  • Line 2: Remove the levelonelogging2 key from the list. Here is how the line should look like:
    keys = root,rootlogging,rootlogging2,levelonelogging,
    leveltwologging,leveltwologging2
  • Lines 20-24: Change those as follows
    [20] [logger_levelonelogging]
    [21] level = ERROR
    [22] handlers = console
    [23] qualname = rootpackage.levelonepackage
    [24] propagate = 0


    Note that in line 23 we removed the module name and left just the name of the package
  • Lines 25-29: Remove those as we won't need them anymore

Now, if you call log_messages() from the modules rootpackage.levelonepackage.levelone_logging or rootpackage.levelonepackage.levelone_logging2 you will get the following result:

0
2012-08-26 21:55:29,654 - [rootpackage.levelonepackage.levelone_logging] - CRITICAL - This is a critical message
2012-08-26 21:55:29,654 - [rootpackage.levelonepackage.levelone_logging] - ERROR - This is an error message

0
2012-08-26 21:55:32,254 - [rootpackage.levelonepackage.levelone_logging2] - CRITICAL - This is a critical message
2012-08-26 21:55:32,254 - [rootpackage.levelonepackage.levelone_logging2] - ERROR - This is an error message

Note that the log levels for the loggers (in this particular case rootpackage.levelonepackage.levelone_logging and rootpackage.levelonepackage.levelone_logging2) are not set (value is 0) but it is set for the package logger and all the modules in the package will log with the same level if they don't have separate logger configured.

Changing the Log Handler for Python Package

Last two goals we had were to log the messages from particular package to a file or to a file and to the console at the same time. In order to achieve the former let's define new handler in our configuration file. Here are the steps for that:
  • Line 4: Add additional key file
  • Line 22: Change the handler from console to file for the rootpackage.levelonepackage package
    [22] handlers = file
  • At the bottom of the config file add the following section that defines the file handler
    [handler_file]
    class = FileHandler
    level = ERROR
    formatter = generic
    args = ('sample.log', 'a')

Now, if you call log_messages() from the modules rootpackage.levelonepackage.levelone_logging or rootpackage.levelonepackage.levelone_logging2 the only thing you will see on the console is the number 0 because the function prints the log level. If you exit Python and look in the folder where you started it you will find a file sample.log that contains the log messages. If you want to see the log messages on the cosole and also log them to a file the only change you will need to do is to add the handler to the list of handlers for the package as follows:

[22] handlers = console,file


And rememer - NO SPACES in the list!

Hope this will kick start your logging with Python and make your life easier.

Comments

Feed You can follow this conversation by subscribing to the comment feed for this post.

The comments to this entry are closed.