Plumber Jack

Improved flexibility for log file rotation

2011-12-13T02:27:00.001-08:00

The RotatingFileHandler and TimedRotatingFileHandler classes provide basic log file rotation functionality, but there are times when more functionality is required than is provided in these classes. One requirement is to compress log files when they are rotated. Currently, if you want this kind of functionality, you have to subclass the relevant handler and override the doRollover method. This works, but requires you to copy and paste the entire method, and then adapt it to your needs; clearly, this is not ideal. An example of this can be found in this ActiveState recipe for a TimedCompressedRotatingFileHandler. This uses the .zip format to compress log files.

In order to provide improved flexibility for log file processing (which will generally be compression, but in practice any transformation could be performed), I propose to add two new methods to these handlers (in their common base class, BaseRotatingHandler).

The first method is named rotate. It takes two arguments, source and dest. The source argument is the name of the log file about to be rotated (e.g. test.log), and the dest argument names the target of the rotation (e.g test.log.1). Under normal circumstances, the file named by dest should not exist, having been explicitly removed by the rollover logic. the default behaviour is what happens currently – a call to os.rename(source, dest).

Since we are potentially transforming log files, we might also want to change their extension, so that they are more usable with e.g. file system viewers like Nautilus or Windows Explorer. To facilitate this, a second method is provided, called filename. This takes a single argument – the filename of a destination file in a rotation (for example, test.log.1) – and returns a modified version (for example, adding an extension – test.log.1.gz). The default behaviour is to return the name unchanged.

The definition of the new methods is as follows.

    def filename(self, name):

        """
        Modify the filename of a log file when rotating.

        This is provided so that a custom filename can be provided,
        say by adding an extension.

        The default implementation returns the name unchanged.

        :param name: The default name for the destination log file.
        """

    def rotate(self, source, dest):

        """
        When rotating, rotate the current log in the file named by
        source to the file named by dest.

        On entry, the file named by source should exist and the file
        named by dest should not exist.

        On exit, the file named by source should not exist and the

        file named by dest should exist.

        The default implementation simply renames source to dest.

        :param source: The source filename. This is normally the base
                       filename, e.g. 'test.log'
        :param dest:   The destination filename. This is normally
                       what the source is rotated to, e.g. 'test.log.1'.
        """

This will allow a custom rotation strategy to be implemented relatively easily: for example, if you want to gzip rotated log files, you can ensure that filename returns test.log.1.gz when passed test.log.1, and that rotate gzips test.log to test.log.1.gz.

The ActiveState example I cited earlier used the .zip format, but what if you want to use .gz, .bz2, .7z or some other compression algorithm? You would need to support all of them in a single handler, or write multiple handler classes for each format.

To avoid the need for users to subclass the rotating handlers, I further propose to allow configurability of the rotate and filename methods by providing two new handler attributes (both, by default, set to None in BaseRotatingHandler).

The first handler attribute is named rotator. You can set it to a callable that takes two arguments, source and dest. The meanings of these arguments are the same as for the rotate method. If a callable is provided in the rotator attribute, it is called by the rotate method to perform the rotation.

The second handler attribute is called namer. You can set this to a callable which takes a single argument – the filename of a destination file in a rotation (for example, test.log.1) – and modifies it to, for example, add an extension. If a callable is set, then it is called by the filename method to return the new name.

An example of how you can define a namer and rotator is given in the following snippet, which shows zlib-based compression of the log file.

def namer(name):
    return name + ".gz"

def rotator(source, dest):
    with open(source, "rb") as sf:
        data = sf.read()
        compressed = zlib.compress(data, 9)
        with open(dest, "wb") as df:
            df.write(compressed)
    os.remove(source)

rh = logging.handlers.RotatingFileHandler(...)
rh.rotator = rotator
rh.namer = namer

I’m aware that these are not “true” .gz files, as they are bare compressed data, with no “container” such as you’d find in an actual gzip file. This snippet is just for illustration purposes.

Note: The namer function is called quite a few times during rollover, so it should be as simple and as fast as possible. It should also return the same output every time for a given input, otherwise the rollover behaviour may not work as expected. If either the namer or rotator function raises an exception, this will be handled in the same way as any other exception during an emit() call, i.e. via the handleError method of the handler.

The internal logic for determining which files to delete (when a backupCount is specified on a rotating file handler) uses, in the case of TimedRotatingFileHandler, regular expressions for the date/time-based suffix. The regular expressions used have been updated to allow an optional file extension consisting of a period followed by one or more letters and digits.

These changes will soon appear in Python 3.3’s development repository. Your comments are welcome.

Configurability tweaks for SysLogHandler and Formatter

2011-06-09T14:38:00.001-07:00

There have been some recent changes to SysLogHandler and Formatter which will appear in Python releases.

SysLogHandler currently appends a NUL byte to messages it sends to syslog daemons. This is because earlier versions of these daemons expected the NUL terminator to be present, even though it’s not part of the relevant specification (RFC 5424). More recent releases of these daemons don’t expect the NUL byte to be there, but strip it off if it’s present. And some even more recent daemons follow the specification more strictly, and pass the NUL byte on as part of the message. In order to facilitate dealing with all the various possible destinations for SysLogHandler messages, a new class-level attribute, append_nul, has been added to SysLogHandler. The default value is True, thus preserving current behaviour; however, you can set it to False for specific handler instances where you don’t want the NUL byte to be appended. This change is expected to appear in Python 3.2.1, which should be released soon.
In the same vein, the date formatting logic used by Formatter has been changed to make it more configurable. Previously, the default ISO 8601 format was hard-coded as in this example: 2010-09-06 22:38:15,292 where the part before the comma is handled by a strptime format string ('%Y-%m-%d %H:%M:%S'), and the part after the comma is a millisecond value. Because strptime does not have a format placeholder for milliseconds, the millisecond value is appended using another format string, '%s,%03d' – both of these format strings have been hardcoded into the Formatter.formatTime method. That’s set to change with Python 3.3 – these strings will be defined as class-level attributes which can be overridden at the instance level when desired. The names of the attributes are default_time_format (for the strptime format string) and default_msec_format (for appending the millisecond value).

Added functionality for basicConfig() in Python 3.3

2011-04-11T04:08:00.001-07:00

The logging.basicConfig() function allows users to easily configure either a console handler or file handler for the root logger, and thereby have them usable by all loggers in their application. While this functionality meets the commonest use cases, there are some slightly less common use cases which can be accommodated without too much work. For example:

Configuring a FileHandler with a specific encoding, or with a delay parameter which defers opening the file until the first time it’s actually used.
Configuring a SysLogHandler. This could be useful, say, for cron jobs or other admin scripts.
Configuring multiple handlers with minimal work.

Accordingly, basicConfig() in Python 3.3 will have added functionality in the form of a new handlers keyword argument. This defaults to None, but when specified it is expected to be an iterable of already-created handler instances, which are to be added to the root logger.

Any handler in the iterable which does not have a formatter assigned will be assigned the formatter created by basicConfig(). This allows users to specify formatters if they need to, but defaults to a common formatter for all handlers which have no formatter specified.

This change to basicConfig() also includes improved checking for parameter compatibility: it doesn’t make sense to specify handlers together with stream or filename parameters, or to specify stream and filename parameters together. In Python 3.3, checks have been added so that these invalid combinations will raise a ValueError.

Examples of usage:

logging.basicConfig(handlers=[logging.FileHandler('test.log', 'w', 'utf-8')])

logging.basicConfig(handlers=[logging.SysLogHandler()])

logging.basicConfig(handlers=[logging.StreamHandler(), logging.FileHandler('test.log')])

I’d welcome feedback on this new functionality, which has already been checked into Python’s Mercurial repository.

Logging documentation for Python 2.7 reorganised

2011-04-11T03:35:00.001-07:00

The logging documentation for Python 2.7 has been reorganised into the same structure as that for Python 3.x. The library reference is supposed to be just that – a reference – so the tutorials have been moved to the HOWTO section. The configuration and handler documentation has also been moved into separate pages. The organisation is now as follows:

http://docs.python.org/library/logging – reference documentation for the logging module
http://docs.python.org/library/logging.config - reference documentation for the logging.config module
http://docs.python.org/library/logging.handlers - reference documentation for the logging.handlers module
http://docs.python.org/howto/logging – basic and advanced logging tutorials
http://docs.python.org/howto/logging-cookbook – how to use logging in different scenarios

There’s a prominent sidebar at the start of the reference documentation pages pointing to the HOWTO sections.

I hope the results are easier to navigate and to understand. Please feel free to give your feedback.

Desktop log viewer released

2011-02-11T06:22:00.000-08:00

A Qt-based desktop application for viewing logs received across the network has been released. It incorporates some of the feedback gratefully received following an earlier post with screencast.

The viewer has mandatory dependencies on Qt4 and PyQt4, and optional dependencies on ZeroMQ and pyzmq. Because these packages have non-trivial installation procedures (as they use C extensions) and because there may be an old (conflicting) version of Qt installed, the packaging of the application is in binary forms for Windows, Mac OS X (Intel only) and Linux.

A source distribution is also provided; this assumes that you have PyQt4 and optionally pyzmq already installed.

Downloads are available from the project site, where you can also report issues.

Screenshot:

The Linux binary was smoke-tested on: Fedora 14, Ubuntu (Jaunty, Karmic, Maverick), Linux Mint 10 (Ubuntu and Debian variants), Debian Lenny and OpenSUSE 11.3. It looks better on some than on others, but seems to work on all these platforms.

The Windows binary was smoke-tested on Windows XP and Windows 7.

The Mac OS X binary was smoke-tested on Leopard (Python 2.5).

All feedback gratefully received. Please post issues on the project site (requires a Google account), and also feel free to use the mailing list.

A desktop log viewer

2011-01-17T15:13:00.001-08:00

I’ve created a simple desktop application which is a viewer for viewing logging records sent from applications via the SocketHandler and DatagramHandler. It’s early days and the viewer is fairly simple, so I’ve created a screencast so that I can get some feedback on the user interface before spending too much more time on it. If people think it will be useful, I can release it under a 3-clause BSD license.

I realize that web interfaces are all the rage, but it took me less time to produce this desktop app using PyQt than an equivalent web application would have.

I developed this on Ubuntu Maverick using the bundled versions of Qt and PyQt, and it seems pretty stable. With older versions of Qt/PyQt (e.g. the versions bundled with Ubuntu Karmic and earlier) I have had segfaults with the identical code - I'm not sure where the problem is.

The code also works with a recent version of PyQt on Windows 7.

The screencast is around 3 minutes long.

The video content presented here requires JavaScript to be enabled and the latest version of the Macromedia Flash Player. If you are you using a browser with JavaScript disabled please enable it now. Otherwise, please update your version of the free Flash Player by downloading here.

I’d be grateful for any feedback about the user interface. I know it’s not especially innovative but then it’s doing a fairly simple job :-)

Colourising logging output in terminals

2010-12-29T03:52:00.001-08:00

A nice-to-have feature when logging to terminals is to have the output colourised, typically according to the severity of individual messages. This is fairly straightforward to achieve, but the following points have to be borne in mind:

On Unix, Linux and OS X, terminals support ANSI escape codes for colourisation, and so a single solution should be able to support all of these platforms.
Windows does not support ANSI escape codes (though MS-DOS used to, using the ANSI.SYS driver), but does provide an API which can be used to achieve a similar effect.
When the terminal output is redirected to a file, colourisation should be disabled.

In this post, I’ll present a fairly simple handler which considers each of the above points in its design and implementation. I’ll be adding this handler to the logutils package soon.

We’ll assume that an entire formatted message will be colourised. If you need to colourise only certain parts of the message, you can adapt the solution presented here fairly easily – perhaps by adding a specialised formatter which is aware of ANSI escape codes.

We’ll also assume that we only want to be able to set background colour, foreground colour and foreground intensity, and that we’ll only want to set eight colours – red, green, blue, cyan, magenta, yellow, black and white. That’s more or less the lowest common denominator afforded us by ANSI escape sequences. If you have more specialised needs which are supported by your environment, you should be able to adapt the solution presented here, most likely just by subclassing.

It seems appropriate to base the handler on logging.StreamHandler. In addition to importing logging, we’ll need to import os (so that we can take appropriate action on Windows) and ctypes (so we can access the Windows console API needed to colourise terminal output).

This is how we start the handler implementation:

import ctypes
import logging
import os

class ColorizingStreamHandler(logging.StreamHandler):

    @property
    def is_tty(self):
        isatty = getattr(self.stream, 'isatty', None)
        return isatty and isatty()

    def emit(self, record):
        try:
            message = self.format(record)
            stream = self.stream
            if not self.is_tty:
                stream.write(message)
            else:
                self.output_colorized(message)
            stream.write(getattr(self, 'terminator', '\n'))
            self.flush()
        except (KeyboardInterrupt, SystemExit):
            raise
        except:
            self.handleError(record)

Noting that we need to determine when terminal output is piped to a file, we provide a property called is_tty on the handler which says whether the handler’s stream is a terminal. If it is, we’ll use a method called output_colorized (whose implementation will be platform dependent, and discussed shortly) to do the colourised output; otherwise, we just write the message to the stream.

In order to add colour to the message, we’ll override the format method of the handler:

    def format(self, record):
        message = logging.StreamHandler.format(self, record)
        if self.is_tty:
            # Don't colorize any traceback
            parts = message.split('\n', 1)
            parts[0] = self.colorize(parts[0], record)
            message = '\n'.join(parts)
        return message

We first call the base class format method to do the actual formatting according to whatever formatter is set for the handler. If we are writing to a terminal, we extract the first line of the formatted text (which could contain an exception traceback), colourise that first line and add the traceback without any colouring.

I did consider putting the colourising logic into a specialised Formatter subclass, but decided against it, because:

Colourising is only done when writing to a terminal; a formatter would be unaware of specific output destinations.
Placing the colourising logic in a handler would allow a formatter to be shared with other handlers.
It’s simpler to keep everything in one place.

To do the grunt work, we’ll define the colorize helper method together with some data which drives it. We’ll make it the method’s job to add ANSI escape sequence to colour the message, even though Windows does not support ANSI escape sequences natively - we’ll just have to deal with it in the implementation of output_colorized, which we’ll come to a little later.

Let’s discuss ANSI escape sequences briefly now – for more information you can consult this article. Basically, colourising is done by placing a special character sequence in the character stream sent to the terminal. The sequence always starts with an ESC (ASCII 27) followed by a left bracket character ([). The sequence always ends with an ‘m’. In between is one or more integer parameters (as printed characters in decimal format, separated by semicolons). These parameters have the following meanings:

0 – reset background and foreground colours and intensity to the defaults.
1 – set the foreground intensity on.
between 30 and 37 – set the foreground colour to one of the values in this table, after subtracting 30 from the parameter.
between 40 and 47 - set the background colour to one of the values in this table, after subtracting 40 from the parameter.

There are other parameters with other meanings in the ANSI specification, but we won’t concern ourselves with those as they aren’t relevant to our simple colourisation scheme.

So, we use a simple color_map dictionary that allows mapping colour names to integer colour values. We also use a level_map dictionary which maps logging levels to a tuple encoding the background colour, foreground colour (colour names) and intensity (a Boolean). If no background colour is specified (None) , the default is used. Because Windows terminals usually have a dark background and Linux terminals a light background, the level_map is defined slightly differently on Windows. We also define the escape sequence beginning (called the CSI for Control Sequence Introducer/Initiator), and the reset sequence.

    # color names to indices
    color_map = {
        'black': 0,
        'red': 1,
        'green': 2,
        'yellow': 3,
        'blue': 4,
        'magenta': 5,
        'cyan': 6,
        'white': 7,
    }

    #levels to (background, foreground, bold/intense)
    if os.name == 'nt':
        level_map = {
            logging.DEBUG: (None, 'blue', True),
            logging.INFO: (None, 'white', False),
            logging.WARNING: (None, 'yellow', True),
            logging.ERROR: (None, 'red', True),
            logging.CRITICAL: ('red', 'white', True),
        }
    else:
        level_map = {
            logging.DEBUG: (None, 'blue', False),
            logging.INFO: (None, 'black', False),
            logging.WARNING: (None, 'yellow', False),
            logging.ERROR: (None, 'red', False),
            logging.CRITICAL: ('red', 'white', True),
        }
    csi = '\x1b['
    reset = '\x1b[0m'

    def colorize(self, message, record):
        if record.levelno in self.level_map:
            bg, fg, bold = self.level_map[record.levelno]
            params = []
            if bg in self.color_map:
                params.append(str(self.color_map[bg] + 40))
            if fg in self.color_map:
                params.append(str(self.color_map[fg] + 30))
            if bold:
                params.append('1')
            if params:
                message = ''.join((self.csi, ';'.join(params),
                                   'm', message, self.reset))
        return message

Once the mappings and constants have been defined, the colorize method is very simple. If the record’s level is in the level map, we get the tuple for background and foreground colours and intensity, get the appropriate commands and construct the escape sequence. We return the passed in message, bracketed by the initial escape sequence which encodes the appropriate colours and intensity for the record’s level, and the final escape sequence which resets the terminal to default colours and intensity.

The implementation thus far adds ANSI escape sequences to messages to colourise them. These are natively supported on Unix, Linux and OS X, but not so on Windows. We therefore define the output_colorized message, which is called from emit, differently on NT and non-NT platforms. The non-NT implementation is very simple: assuming ANSI support is native, we just write the colourised message to the output stream. For Windows, we need to interpret the ANSI escape sequences and implement them with Win32 API calls. Here are the implementations:

    if os.name != 'nt':
        def output_colorized(self, message):
            self.stream.write(message)
    else:
        import re
        ansi_esc = re.compile(r'\x1b\[((\d+)(;(\d+))*)m')

        nt_color_map = {
            0: 0x00,    # black
            1: 0x04,    # red
            2: 0x02,    # green
            3: 0x06,    # yellow
            4: 0x01,    # blue
            5: 0x05,    # magenta
            6: 0x03,    # cyan
            7: 0x07,    # white
        }

        def output_colorized(self, message):
            parts = self.ansi_esc.split(message)
            write = self.stream.write
            h = None
            fd = getattr(self.stream, 'fileno', None)
            if fd is not None:
                fd = fd()
                if fd in (1, 2): # stdout or stderr
                    h = ctypes.windll.kernel32.GetStdHandle(-10 - fd)
            while parts:
                text = parts.pop(0)
                if text:
                    write(text)
                if len(parts) > 4:
                    params = parts[0]
                    parts = parts[4:]
                    if h is not None:
                        params = [int(p) for p in params.split(';')]
                        color = 0
                        for p in params:
                            if 40 <= p <= 47:
                                color |= self.nt_color_map[p - 40] << 4
                            elif 30 <= p <= 37:
                                color |= self.nt_color_map[p - 30]
                            elif p == 1:
                                color |= 0x08 # foreground intensity on
                            elif p == 0: # reset to default color
                                color = 0x07
                            else:
                                pass # error condition ignored
                        ctypes.windll.kernel32.SetConsoleTextAttribute(h, color)

Because the integer values for ANSI colour codes differ slightly from those for Windows, we use an nt_color_map dictionary to map between the two. We use regular expressions to split the colourised message into escape sequences and literal text to be output. (Note that because there are four groups in the regular expression, the list will contain four entries for each ANSI sequence found.)

In order to colourise the text in the terminal, we need to obtain a Windows console handle for the output stream, using the GetStdHandle Win32 API. If this handle is not obtainable, literal text is output but the ANSI escape sequences are ignored. If the handle is obtained, then the ANSI sequences are converted to the corresponding Win32 attribute values and the SetConsoleTextAttribute API is used to write them to the console.

The whole thing is available a ready-to-run form in this gist, which should run on all Pythons >= 2.5 (and Python 2.4, too, if you have ctypes installed). Here are some screenshots of running the scripts on Ubuntu, Windows 7, Windows 2008, and Mac OS X, showing the expected results for both terminal output and output piped to a file.

Ubuntu Jaunty:

Windows 7:

Windows 2008 (Python 2.4):

Mac OS X:

If you want different colour settings, you can probably achieve this just by changing the level_map contents. If you want to insert colourisation for just part of your messages, you could change the logic in the colorize and/or format methods. Of course, you can also override output_colorized and colorize if you need to support additional ANSI escape sequences.

Your comments are welcome, particularly any suggestions for improvements. Thanks for reading.

Logging documentation for Python 3.2 reorganised

2010-12-19T07:18:00.001-08:00

After comments that the length of logging documentation was making it hard to navigate, and after the addition of a new basic tutorial, the documentation has been reorganised. The library reference is supposed to be just that – a reference – so the tutorials have been moved to the HOWTO section. The configuration and handler documentation has also been moved into separate pages. The organisation of the Python 3.2 logging documentation is now as follows:

http://docs.python.org/dev/library/logging – reference documentation for the logging module
http://docs.python.org/dev/library/logging.config - reference documentation for the logging.config module
http://docs.python.org/dev/library/logging.handlers - reference documentation for the logging.handlers module
http://docs.python.org/dev/howto/logging – basic and advanced logging tutorials
http://docs.python.org/dev/howto/logging-cookbook – how to use logging in different scenarios

There’s a prominent sidebar at the start of the reference documentation pages pointing to the HOWTO sections.

I hope the results are easier to navigate and to understand. Please feel free to give your feedback.

Proposed changes to logging defaults

2010-12-09T15:58:00.001-08:00

Following recent discussion on python-dev, some changes to logging’s default behaviour are likely to be implemented soon, perhaps as soon as in 3.2b2 (3.2b1 was released just a few days ago). By default behaviour is meant behaviour in the absence of any explicit logging configuration.

The current behaviour, which dates from logging’s first appearance in Python, is as follows. When a logging event needs to be output, the logging package looks for handlers which have been configured by the application. If no such handlers are found, the package prints a message “No handlers could be found for logger XXX”, naming the logger that was used to log the event. (The message is only ever printed once, even if subsequent logging calls are made. Furthermore, the message is only printed when logging.raiseExceptions is True, which is the “development” mode of operation for logging. When logging.raiseExceptions is False, the “production” mode of operation for logging, the message isn’t printed, even once.)

This creates some problems when an application (or simple script, or interactive session – I’ll use script to mean any of these) meets the following criteria:

It uses a library which does logging under the covers.
It doesn’t configure any handlers.
The library code invoked logs events of severity WARNING or above.

Because the default verbosity for logging is WARNING, the logging package looks for handlers, and, not finding any, prints the one-off “No handlers could be found …” message. This may be a surprise to the author of the script and also for its users; it can generate support calls to the author from the users. The message was provided as a means of warning developers, who would have been new to logging, about a possible misconfiguration. (Of course, when logging was introduced, everyone was new to it.) The importance of the message is less now than it was before, because many people are familiar with how logging works and provide good support on comp.lang.python to people who are newcomers to logging, or who run into issues that are simple to resolve.

To deal with the problem described above, the approach suggested has been for library developers to add a NullHandler instance to their top-level logger. This prevents messages from library code from causing the misconfiguration message to be printed, because a handler — the NullHandler — is always found when handling events from the library. If a script developer adds logging events in their own code which need to be handled, then the misconfiguration message will still appear, and that’s as it should be.

When the logging package was introduced, this was done with a philosophy that logging is an adjunct to normal application activity — meaning that a script should work in exactly the same way with or without the presence of logging. So logging tries to work as unobtrusively as possible, and is set up so that in production use, exceptions that occur in logging (e.g. mismatched format string and parameters) will not be raised, allowing a script to carry on uninterrupted. Also pertinent is the Unix philosophy that verbosity should be kept to a minimum.

The above describes the current state of play, but things are now set to change. The rationale for changing is:

The present behaviour goes against the Zen of Python, which says “Errors should never pass silently. Unless explicitly silenced.”
Python core developers want to be able to use the logging package not just as an adjunct to doing real work in the standard library, but to actually do the real work when it comes to the output of warning and error messages.
In some cases exceptions can’t be usefully raised, and writing out a message is the only way to provide information about an error condition which has been detected. Providing it via logging provides more flexibility in dealing with it than would a bare write to sys.stderr.

These changes will, in due course, bring benefits such as being able to redirect standard library warning and error messages, which are currently written to sys.stderr, to some destination of a developer’s choosing. However, it may cause some inconvenience to existing users, because the proposed behaviour change is not backwards-compatible.

How will the change be implemented? This is still being thought about, but the current front runner is to implement through the idea of a “handler of last resort”. When no handler is found when processing an event which needs to be output, instead of printing the misconfiguration message, the system will use the “last resort” handler to handle the event. The “last resort” handler will be (by default) a StreamHandler using sys.stderr as its stream, with its level set to WARNING. Details about how to preserve existing behaviour are still being worked on; one thought is that you can get existing behaviour by setting the last resort handler to None.

What’s the impact on users of logging?

If you’re using a version of Python earlier than 3.2, there’s no impact. Things will stay as they are.
Script developers: If you configure logging (i.e. add handlers), there should be no impact – the behaviour you see shouldn’t change, as long as there is no situation where a handler isn’t found. If you don’t configure logging, then in place of a misconfiguration message, you’ll see events of severity WARNING and above printed to sys.stderr without any specific formatting (i.e. as if the format string were "%(message)s").
Library developers: If the script using your library configured logging, you should see no change in behaviour. Otherwise: if you added a NullHandler to your library’s top-level logger, you should see no change in behaviour, but remember — your warning and error messages will not be shown to end-users. If you reverse the NullHandler addition or didn’t add it in the first place, then instead of a misconfiguration message, end-users will see your warning and error messages on sys.stderr.
End users: If the script being run configured logging, you should see no change in behaviour. If it didn’t, then in place of a misconfiguration message, you’ll see events of severity WARNING and above printed to sys.stderr without any specific formatting.

I hope I’ve covered everything, but should any kind reader spot some error or omission, please let me know.

Please feel free to comment giving your views on the proposed change, whether you approve of it or whether you think it affects you adversely. Thanks for reading.

Getting more control over LogRecord creation

2010-12-03T05:02:00.001-08:00

Every logging event is represented by a LogRecord instance. When an event is logged and not filtered out by a logger’s level, a LogRecord is created, populated with information about the event and then passed to the handlers for that logger (and its ancestors, up to and including the logger where further propagation up the hierarchy is disabled). Before Python 3.2, there were only two places where this creation was done:

Logger.makeRecord, which is called in the normal process of logging an event. This invoked LogRecord directly to create an instance.
logging.makeLogRecord, which is called with a dictionary containing attributes to be added to the LogRecord. This is typically invoked when a suitable dictionary has been received over the network (e.g. in pickle form via a SocketHandler, or in JSON form via an HTTPHandler).

This has usually meant that if you need to do anything special with a LogRecord, you’ve had to do one of the following.

Create your own Logger subclass, which overrides makeRecord(), and set it using logging.setLoggerClass before any loggers that you care about are instantiated.
Add a Filter to a logger or handler, which does the necessary special manipulation you need when its filter() method is called.

The first approach would be a little unwieldy in the scenario where (say) several different libraries wanted to do different things. Each would attempt to set its own Logger subclass, and the one which did this last would win. The second approach works reasonably well for many cases, but does not allow you to e.g. use a specialized subclass of LogRecord. Library developers can set a suitable filter on their loggers, but they would have to remember to do this every time they introduced a new logger (which they would do simply by adding new packages or modules and doing logger = logging.getLogger(__name__) at module level). It’s probably one too many things to think about. They could also add the filter to a NullHandler attached to their top-level logger, but this would not be invoked if an application developer attached a handler to a lower-level library logger – so output from that handler would not reflect the intentions of the library developer.

In Python 3.2, LogRecord creation will be done through a factory, which you can specify. The factory is just a callable you can set with logging.setLogRecordFactory(factory), and interrogate with logging.getLogRecordFactory(). The factory is invoked with the same signature as the LogRecord constructor, as LogRecord is the default setting for the factory:

factory(name, lvl, pathname, lineno, msg, args, exc_info, func=None, sinfo=None, **kwargs)

The parameters are as follows:

name – the name of the logger used.
lvl – the numeric value of the event’s level.
pathname, lineno – the location in the source code where the logging call appears.
msg, args – the logging message and arguments.
exc_info – any exception info, or None.
func – the name of the function or method from which the logging call was made.
sinfo – a traceback such as is produced by traceback.print_stack. (This is not the same as the exception traceback.)
kwargs – currently empty, but this could change in future versions of logging.

This approach allows a custom factory to control all aspects of LogRecord creation. For example, you could return a subclass, or just add some additional attributes to the record once created, using a pattern similar to this:

old_factory = logging.getLogRecordFactory()

def record_factory(*args, **kwargs):
    record = old_factory(*args, **kwargs)
    record.custom_attribute = 0xdecafbad 
    return record 
 
logging.setLogRecordFactory(record_factory)

This pattern allows different libraries to chain factories together, and as long as they don’t overwrite each other’s attributes or unintentionally overwrite the attributes provided as standard, there should be no surprises. However, it should be borne in mind that each link in the chain adds run-time overhead to all logging operations, and the technique should only be used when the use of a Filter does not provide the desired result.

These changes have been added to Python 3.2 (i.e. in the py3k branch) and should be in the first beta. Feel free to try them out. Your feedback is, as always, most welcome.

logutils: Using recent logging features with older Python versions

2010-10-31T09:28:00.001-07:00

Python’s development is a process of continuous improvement, and the standard library of course undergoes changes as new versions of Python are released. In the logging package, there have been numerous improvements in recent months:

Dictionary-based configuration (PEP 391)
QueueHandler for working with multiprocessing and in-process queues

In addition, there have been a few bits of utility code which have been posted here:

Classes which facilitate use of logging in particular scenarios, such as unit testing
Classes which facilitate building logging messages using str.format or string.Template

Many of the enhancements have been added as new features which will emerge in Python 3.2, but cannot be added to Python 2.X because there are no Python 2.X branches where new features can be added. Python 2.7, the last 2.X release, is in maintenance mode and will only accept bug-fixes which maintain backwards compatibility.

Although Python 3.2+ is the way forward for Python development, many users will be constrained to use 2.X for some considerable time yet, mostly because libraries they depend on have not yet been ported to 3.X, but sometimes also because their codebase is too large to consider porting to 3.X, when viewed from a cost/benefit viewpoint, or perhaps because their code needs to remain workable under 2.X and they cannot maintain two separate codebases.

For those users who are forced to stick with Python 2.X but who want to use some of the features added recently to logging, the logutils project offers one way in which they can access these features. This is available via PyPI so it can be installed using pip or easy_install. The package is currently at release 0.2 and contains the following:

Dictionary-based configuration (PEP 391) which is broadly compatible with Python 2.7 and 3.2.
The LoggerAdapter class is easier to subclass.
The QueueHandler and QueueListener classes are available for use with in-process, multiprocessing and other types of queue, as described in this post.
The TestHandler and Matcher classes are available for use in unit tests, as described in this post.
An enhanced HTTPHandler allows the use of secure connections and credentials for logging in to websites.

The package needs Python 2.4 or later. Some features are not available in Python 2.4, due to limitations of that Python version. For example, str.format is only available from Python 2.6 onwards; LoggerAdapter relies on a feature added in Python 2.5, namely the extra parameter for adding additional context to logs; and named handlers are not available for Python 2.X versions < 2.7 and Python 3.X versions < 3.2. (As a consequence of this, incremental handler configuration is not available on the versions where named handlers are not available.)

Project downloads are here. You can post issues here (needs a Google account). Documentation is available here.

Supporting alternative formatting styles in logging

2010-10-28T08:09:00.001-07:00

When logging was added to the Python standard library, the only way of formatting messages with variable content was to use the %-formatting method. Since then, Python has gained two new formatting approaches: string.Template (added in Python 2.4) and str.format (added in Python 2.6).

Now, Python’s logging package will provide improved support for these two additional formatting styles. The Formatter class in logging has been enhanced for Python 3.2 to take an additional, optional keyword parameter named style. This defaults to '%', but other possible values are '{' and '$', which correspond to the other two formatting styles. Backwards compatibility is maintained by default (as you would expect), but by explicitly specifying a style parameter , you get the ability to specify format strings which work with str.format or string.Template. Here’s an example console session to show the possibilities:

vinay@eta-jaunty:~$ python3.2
Python 3.2a3+ (py3k:85857, Oct 27 2010, 18:25:50) 
[GCC 4.3.3] on linux2
Type "help", "copyright", "credits" or "license" for more information.

>>> import logging
>>> root = logging.getLogger()
>>> root.setLevel(logging.DEBUG)
>>> handler = logging.StreamHandler()
>>> bf = logging.Formatter('{asctime} {name} {levelname:8s} {message}', style='{')
>>> handler.setFormatter(bf)
>>> root.addHandler(handler)
>>> logger = logging.getLogger('foo.bar')
>>> logger.debug('This is a DEBUG message')
2010-10-28 15:11:55,341 foo.bar DEBUG    This is a DEBUG message
>>> logger.critical('This is a CRITICAL message')
2010-10-28 15:12:11,526 foo.bar CRITICAL This is a CRITICAL message
>>> df = logging.Formatter('$asctime $name ${levelname} $message', style='$')
>>> handler.setFormatter(df)
>>> logger.debug('This is a DEBUG message')
2010-10-28 15:13:06,924 foo.bar DEBUG This is a DEBUG message
>>> logger.critical('This is a CRITICAL message')
2010-10-28 15:13:11,494 foo.bar CRITICAL This is a CRITICAL message
>>>

Note that the formatting of logging messages for final output to logs is completely independent of how an individual logging message is constructed. That can still use %-formatting, as shown here:

>>> logger.error('This is an%s %s %s', 'other,', 'ERROR,', 'message')
2010-10-28 15:19:29,833 foo.bar ERROR This is another, ERROR, message
>>>

Logging calls (logger.debug(), logger.info() etc.) only take positional parameters for the actual logging message itself, with keyword parameters used only for determining options for how to handle the actual logging call (e.g. the exc_info keyword parameter to indicate that traceback information should be logged, or the extra keyword parameter to indicate additional contextual information to be added to the log). So you cannot directly make logging calls using str.format or string.Template syntax, because internally the logging package uses %-formatting to merge the format string and the variable arguments. There would no changing this while preserving backward compatibility, since all logging calls which are out there in existing code will be using %-format strings.

There is, however, a way that you can use {}- and $- formatting to construct your individual log messages. Recall that for a message you can use an arbitrary object as a message format string, and that the logging package will call str() on that object to get the actual format string. Consider the following two classes:

class BraceMessage(object):
    def __init__(self, fmt, *args, **kwargs):
        self.fmt = fmt
        self.args = args
        self.kwargs = kwargs

    def __str__(self):
        return self.fmt.format(*self.args, **self.kwargs)

class DollarMessage(object):
    def __init__(self, fmt, **kwargs):
        self.fmt = fmt
        self.kwargs = kwargs
        
    def __str__(self):
        from string import Template
        return Template(self.fmt).substitute(**self.kwargs)

Either of these can be used in place of a format string, to allow {}- or $-formatting to be used to build the actual “message” part which appears in the formatted log output in place of “%(message)s” or “{message}” or “$message”. It’s a little unwieldy to use the class names whenever you want to log something, but it’s quite palatable if you use an alias such as __ (double underscore – not to be confused with _, the single underscore used as a synonym/alias for gettext.gettext or its brethren).

The above classes, and recent additions to the logging package, will be published in a package called logutils, intended for use with Python 2.4 or later. This is already available for download via PyPI (and will be the subject of a future blog post). They can be used as follows:

>>> from logutils import BraceMessage as __

>>> print(__('Message with {0} {1}', 2, 'placeholders'))
Message with 2 placeholders
>>> class Point: pass
... 
>>> p = Point()
>>> p.x = 0.5
>>> p.y = 0.5
>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})', point=p))
Message with coordinates: (0.50, 0.50)
>>> from logutils import DollarMessage as __
>>> print(__('Message with $num $what', num=2, what='placeholders'))
Message with 2 placeholders
>>>

One thing to note is that you pay no significant performance penalty with this approach: the actual formatting happens not when you make the logging call, but when (and if) the logged message is actually about to be output to a log by a handler. So the only slightly unusual thing which might trip you up is that the parentheses go around the format string and the arguments, not just the format string. That’s because the __ notation is just syntax sugar for a constructor call to one of the XXXMessage classes.

Your comments are, as always, welcome. Thanks for reading.

Shared state in logging: why?

2010-10-26T00:03:00.001-07:00

It’s generally recognised that undisciplined use of global variables is a warning sign about problems with a design. In fact, the paper “Global Variables Considered Harmful” by Wulf and Shaw dates back to 1973. The word “global” and the phrase “global state” have therefore acquired bad connotations in many people’s minds, and that can lead to situations where you “throw the baby out with the bath-water”.

The concept of state shared between multiple software components doesn’t have to be treated in the same way as naïve usage of global variables. There are legitimate situations where state needs to be shared – you will almost certainly be using a computer with a display, a mouse and a keyboard, all of which are essentially shared state (meaning data, and operations on that data, too) for the windowing system your computer is using.

Python’s logging package uses some shared state; Logger objects are shared by all Python code in a single process, in that a call to logging.getLogger('foo.bar') will always return the same object, no matter where it’s called from. The fact that Loggers are singletons is for a specific, considered reason, and not just because I was taking a design short-cut or didn’t know how to do it any other way.

There are alternative logging libraries which make a point of the fact that their loggers are constructed anew each time, so that a call

logger = Logger('foo.bar')

will return a new object every time. These systems perhaps use loggers just as a vehicle for delivering events via their debug(), info() etc. methods; for stdlib logging, Loggers are something more. They play a part in how an application developer, system administrator or support team member controls the logging verbosity of an application. This is done through configuration, which needs to consider the verbosity of all components used in an application - including third-party components whose source you are not free to modify.

Logging verbosity is primarily controlled by configuring level, propagation behaviour and filters for a logger. You can, of course, also control it via configuring levels and filters on handlers; but the best way is to configure loggers where possible, because that avoids the overhead of dispatching events to handlers only to have them be thrown away due to the handler’s configuration.

The logging package relies on loggers being shared across modules, in order to offer this configurability. If my application is using a third-party library which logs some events to a logger named foo.bar, and if I want to configure the verbosity of this logger - by setting its level, say – I can only do this if I can be sure that

logger = logging.getLogger('foo.bar')

will return the same object to the library code, which logs to logger foo.bar, and to my configuration code, which sets that logger’s level to what I want. If the two calls to get that named logger were to return two entirely different objects, then the setLevel() call made by my configuration code would not affect the object used internally by the library. This means that I would essentially lose some level of control over logging verbosity.

When developers are essentially logging just for themselves – i.e. they are the primary, perhaps only, audience for their logging output – then these considerations may not matter too much. If they are not using third-party libraries which use logging, or using libraries whose logging verbosity they don’t care about, that may be another reason for not worrying about this loss of configurability. Since Python logging is intended for the whole Python developer community, some of whom will definitely need and want this level of configurability, the design supports it, using shared state. I know I use this feature myself regularly – say, when examining the SQL output from ORMs such as are provided by Django and SQLAlchemy. I don’t generally log the SQL output (which can be quite voluminous), but might do so as a result of coming across some problem, whether functional or performance-related. When the problem is identified, I can turn the logging of SQL statements off again. In larger application scenarios, this functionality is also available to those who have no means of changing the source code - application support teams or system administrators – assuming that the application developers have provided for this via the mechanisms offered by the logging package.

Another important (but related) design feature of Python logging is the use of hierarchical logger names. In stdlib logging, logger names are not just things which turn up in logging output. When you create a logger named foo.bar, you also conceptually create a logger named foo. This latter logger is not actually created unless and until a getLogger('foo') call is made, but the hierarchical namespace feature (and the way in which handler inheritance works with the logger hierarchy) allows you to turn logging verbosity up and down at multiple levels of a package hierarchy quite easily – for example, turn on all logging in the django logging namespace, or just turn it on just for django.request, or perhaps just for django.db.backends – it puts the application developer/support team/sys admin in control, rather than just the library developer. And while the hierarchical feature might seem overkill for small projects and simple scripts, it doesn’t get in the way, and pays dividends when logging is used in larger systems.

StreamHandler’s newline terminator now configurable

2010-10-20T13:55:00.001-07:00

When StreamHandler writes a formatted log message to its stream, it adds a newline terminator. This behaviour is inherited by FileHandler and the other classes which derive from it (such as the rotating file handlers).

For most people, that’s what they want, since they get log messages on separate lines without having to explicitly code newlines in their log messages. However, some people want the flexibility to not have this newline automatically appended to logged messages.

Starting with Python 3.2, the message terminator will be configurable. This has been done by adding a terminator attribute to StreamHandler, which when emitting an event now writes the formatted message to its stream first, and then writes the terminator. If you don’t want newline termination for a handler, just set the handler instance’s terminator attribute to the empty string.

There’s a small chance that this approach will cause unexpected behaviour – in the unlikely instance that someone is setting a terminator attribute on an a StreamHandler or one of its subclasses for their own, unrelated purposes. Other than that, the new behaviour should be backwards compatible.

If this change is likely to adversely affect you for any reason, please let me know, by replying to this post. The change has already been checked into the py3k branch, and you are welcome to try it out.

Implementing filters using callables

2010-10-20T04:50:00.001-07:00

It’s been pointed out that for implementing logging filters, you shouldn’t have to go to the lengths of creating a Filter class just to define its one filter method. Of course, there are cases where you will need to use Filter classes, but there are also cases where it would be beneficial to just use a function. To cater for this, changes have been made to Python 3.2. Once this enters beta, you will be able to pass a function or other callable to the addFilter and removeFilter methods of Handler and Logger, and this will be called with the LogRecord as its single argument to decide whether the event is to be logged.

The previous functionality did not actually require you to create Filter subclasses – you could pass any instance that had a filter method with the appropriate semantics. The Filter class was an illustration of how to do filtering as well as providing a not uncommon use case – filtering out everything other than a specific sub-tree in the logger namespace.

However, with this change, you’re not forced to call your filtering method filter, so you could e.g. use different filtering methods in a single class, or different functions in a module.

The development documentation has been updated to reflect this change.

Unit testing and logging

2010-09-27T03:36:00.001-07:00

I’ve had questions in the past about using logging and unit testing together – what’s the best way of doing it?

Beyond the choice of unit testing frameworks (e.g. unittest, nose, py.test), unit testing appears to be one of those things (like configuration) where people have strong, and differing, opinions about how they like to do it. This is one reason there is no specific support for unit testing in logging. Besides, logging is one area where functionally, your application should work in exactly the same way no matter how logging is configured, and even if logging is completely switched off (because there are no handlers configured, or the verbosity thresholds are set to be above CRITICAL). I am of course distinguishing here between application logging and request logging as practiced by web servers – the latter is part of the function of the web server, whereas application logging is meant as a operational and diagnostic aid for developers, system administrators and support teams, and orthogonal to the application’s functionality. There are of course scenarios where logging is used to output messages to end users (typically, INFO or WARNING level messages), but it should be borne in mind that the application should keep going even if logging verbosity is turned off.

There are two things that would be useful when using logging and unit testing together:

Some way of capturing all the messages which are logged by the code being unit tested.
Some way of verifying that certain expectations with respect to logged messages are met.

Logging already provides a BufferingHandler class which allows you to capture LogRecords generated by logging activity. You can, for example, subclass this to store the LogRecord.__dict__ values rather than the LogRecords themselves – this will facilitate checking whether expectations are met. You typically don’t want to flush anything until the end of the test, though, so a handler which facilitates testing might look like this:

from logging.handlers import BufferingHandler

class TestHandler(BufferingHandler):
    def __init__(self):
        # BufferingHandler takes a "capacity" argument
        # so as to know when to flush. As we're overriding
        # shouldFlush anyway, we can set a capacity of zero.
        # You can call flush() manually to clear out the
        # buffer.
        BufferingHandler.__init__(self, 0)

    def shouldFlush(self):
        return False

    def emit(self, record):
        self.buffer.append(record.__dict__)

Now let’s consider the checking of expectations about what’s been logged. We could implement this in the TestHandler class directly, but it’s the sort of area where different people may want to do different things. The bare minimum we need in TestHandler would be something that looks for some kind of match between what’s been logged (the buffer of dictionaries) and the expected values. So as an idea, let’s delegate the details of matching to a separate Matcher class, which must have a matches method. Because matching of dictionaries is likely to crop up in tests other than to do with logging, creating a separate Matcher class allows us to deploy the functionality in other scenarios. So, we can develop the TestHandler class a little:

from logging.handlers import BufferingHandler

class TestHandler(BufferingHandler):
    def __init__(self, matcher):
        # BufferingHandler takes a "capacity" argument
        # so as to know when to flush. As we're overriding
        # shouldFlush anyway, we can set a capacity of zero.
        # You can call flush() manually to clear out the
        # buffer.
        BufferingHandler.__init__(self, 0)
        self.matcher = matcher

    def shouldFlush(self):
        return False

    def emit(self, record):
        self.buffer.append(record.__dict__)

    def matches(self, **kwargs):
        """
        Look for a saved dict whose keys/values match the supplied arguments.
        """
        for d in self.buffer:
            if self.matcher.matches(d, **kwargs):
                result = True
                break
        return result

The signature for the matches method allows us to pass just the keys we want to test for in the call. In implementing the Matcher class, we could do whatever we wanted – regular expression matching, for example – but we’ll keep it simple. Let’s assume that we want to either match values exactly, or else do partial matches for string values such as messages. (In order to ensure that a formatted message appears in a LogRecord’s __dict__, we need to call self.format(record) in the emit method.)

To decide which keys to do partial matches on, we can store a set of the relevant keys in a _partial_matches attribute. This is defined in the Matcher class, but you can replace it in a subclass or even an instance of Matcher if you need to. Here’s the Matcher class:

class Matcher(object):

    _partial_matches = ('msg', 'message')

    def matches(self, d, **kwargs):
        """
        Try to match a single dict with the supplied arguments.

        Keys whose values are strings and which are in self._partial_matches
        will be checked for partial (i.e. substring) matches. You can extend
        this scheme to (for example) do regular expression matching, etc.
        """
        result = True
        for k in kwargs:
            v = kwargs[k]
            dv = d.get(k)
            if not self.match_value(k, dv, v):
                result = False
                break
        return result

    def match_value(self, k, dv, v):
        """
        Try to match a single stored value (dv) with a supplied value (v).
        """
        if type(v) != type(dv):
            result = False
        elif type(dv) is not str or k not in self._partial_matches:
            result = (v == dv)
        else:
            result = dv.find(v) >= 0
        return result

Notice that the class is independent of logging and might prove useful elsewhere. Also note the use of str in the match_value method – you may want to replace this with basestring for Python 2.x. (Of course, I could have used isinstance, too.)

Now we can consider what a typical test case using TestHandler and Matcher might look like (some imports omitted):

import unittest

class LoggingTest(unittest.TestCase):
    def setUp(self):
        self.handler = h = TestHandler(Matcher())
        self.logger = l = logging.getLogger()
        l.addHandler(h)
        
    def tearDown(self):
        self.logger.removeHandler(self.handler)
        self.handler.close()
        
    def test_simple(self):
        "Simple test of logging test harness."
        # Just as a demo, let's log some messages.
        # Only one should show up in the log.
        self.logger.debug("This won't show up.")
        self.logger.info("Neither will this.")
        self.logger.warning("But this will.")
        h = self.handler
        self.assertTrue(h.matches(levelno=logging.WARNING))
        self.assertFalse(h.matches(levelno=logging.DEBUG))
        self.assertFalse(h.matches(levelno=logging.INFO))

    def test_partial(self):
        "Test of partial matching in logging test harness."
        # Just as a demo, let's log some messages.
        # Only one should show up in the log.
        self.logger.debug("This won't show up.")
        self.logger.info("Neither will this.")
        self.logger.warning("But this will.")
        h = self.handler
        self.assertTrue(h.matches(msg="ut th")) # from "But this will"
        self.assertTrue(h.matches(message="ut th")) # from "But this will"
        self.assertFalse(h.matches(message="either"))
        self.assertFalse(h.matches(message="won't"))

    def test_multiple(self):
        "Test of matching multiple values in logging test harness."
        # Just as a demo, let's log some messages.
        # Only one should show up in the log.
        self.logger.debug("This won't show up.")
        self.logger.info("Neither will this.")
        self.logger.warning("But this will.")
        self.logger.error("And so will this.")
        h = self.handler
        self.assertTrue(h.matches(levelno=logging.WARNING,
                                  funcName='test_multiple'))
        self.assertTrue(h.matches(levelno=logging.ERROR,
                                  funcName='test_multiple'))
        self.assertFalse(h.matches(levelno=logging.INFO))

if __name__ == '__main__':
    unittest.main()

The whole script is here, and if you run it, you should have no errors:

vinay@eta-jaunty:~/projects/scratch$ python2.7 testhdlr.py
...
----------------------------------------------------------------------
Ran 3 tests in 0.001s

OK
vinay@eta-jaunty:~/projects/scratch$ python3.2 testhdlr.py
...
----------------------------------------------------------------------
Ran 3 tests in 0.001s

OK

Is there anything I’ve missed? Anything you don’t like about these suggestions? Please feel free to comment. Thanks for reading.

"Too long; didn’t read"

2010-09-26T01:47:00.001-07:00

Someone asked: what’s with the tl;dr at the start of every post? My first reaction was surprise that they’d even read any of these posts. After all, logging is a prosaic, even mundane subject – well beneath the radar for many developers. There’s definitely more fun to be had thinking about NoSQL databases, or high availability, or templating systems, or web application frameworks, or (your favourite topic here).

But people do arrive here via search engines, not knowing what they’ll find. Even when people actually come here looking for information about logging, there’s no reason to suppose that every post is of (equal) interest to them.

In these days of ever-shortening attention spans, many people are only interested in tweet-sized chunks, but unfortunately there are some things I can’t cover in 140 chars or less. A reasonable treatment of some topics does require some descent into detail; and, while developers are generally masters of detail, they are often picky about which details they want to be bothered with. You’ll also see that I’m somewhat inexperienced at writing blog posts – though I do hope to get better over time, my writing style might seem more than a little prolix to some.

So it seems like simple courtesy to advertise at the outset what a post-with-detail is about, so as to avoid wasting your time if the topic is of no interest to you. It’s just like the abstract you get at the head of academic papers. While it might seem whimsical to call it a tl; dr, it definitely seems pretentious to call it an abstract. To be fair, I don’t put it at the start of every post :-)

Integrating logging with diverse notification services

2010-09-24T06:58:00.001-07:00

tl;dr: Nowadays, there is a growing number of ways in which people prefer to receive notifications about happenings of interest. While Python logging cannot provide, out-of-the-box, handlers that allow you to send notifications to all of these different systems, the basic functionality provided in the stdlib makes it fairly easy for developers to support the notification mechanisms that are preferred by their audiences. This post will give some examples of how this can be economically achieved.

Logging is basically about getting information about things that happen in your software (whether application or library) out to an interested audience. The diversity of ways in which that audience wants to receive information is growing all the time: from the earliest days of being limited to email and pagers, people have progressed to a using a plethora of social networks, IM and mobile phone platforms, different desktop notification systems - and the list keeps growing. Even if the number of basic types of notification method grows slowly, the number of individual instances of those types can grow faster. For example, if you just look at a subset of desktop notification methods, you have Growl (OS X, Windows), Snarl (Windows), libnotify and mumbles (Linux). The Wikipedia page for Instant messaging lists (at the time of writing) over 20 different IM systems, some of which are only used in particular parts of the world. Likewise, for social networks one might think first of Facebook, Bebo or Twitter, but there are many others which are very popular, but in different parts of the world (for example, Orkut in South and Central America and parts of Asia).

How can you, as a developer who uses logging in your library or application, take account of your users’ preferences when getting information out to them? Of course, the large majority of logging messages will be sent to console or file. However, there will be certain messages in the ERROR or CRITICAL category which need to be sent to people so that urgent action to be taken. These have generally been sent by email, but there are circumstances when you might want to use alternative mechanisms (or even multiple mechanisms) to get information out so that it can be received as soon as possible and (hopefully) acted on in a timely fashion.

Clearly, it’s not practical for the logging package in the stdlib to provide native support for the myriad specialized ways of sending notifications which exist today. Logging currently provides 14 handlers (not including base classes), just about all of which relate to basic infrastructure communication or storage mechanisms:

NullHandler	Used by libraries to avoid misconfiguration messages	StreamHandler	Used to write to streams
FileHandler	Used to write to disk files	RotatingFileHandler	Used to write to size-based rotating log files
TimedRotatingFileHandler	Used to write to time-based rotating log files	WatchedFileHandler	A FileHandler which supports external log file rotation mechanisms
SocketHandler	Used to write to TCP sockets	DatagramHandler	Used to write to UDP sockets
SysLogHandler	Used to write to a syslog daemon via either UDP or Unix domain sockets	SMTPHandler	Used to send emails
NTEventLogHandler	Used to write to Windows NT event logs	HTTPHandler	Used to send to arbitrary web sites
MemoryHandler	Used to buffer up events and process in batches	QueueHandler (3.2)	Used to send to in-process or multiprocessing queues

As you can see, all of these are very generic and relate to storage mechanisms and protocols which are unlikely to go out of fashion any time soon.

However, you don’t need to worry unduly if you want to send notifications using some of the newer facilities available today. Of course you can use something like HTTPHandler (subclassing it if necessary) to send information to any web site, but you may not see any support for e.g. desktop notification systems. How can logging provide this?

It doesn’t make much sense for me to put in “native” support for multiple notification protocols into the stdlib, for a number of reasons:

The methods, protocols and sites which are popular today may not be popular tomorrow. Any support added for them in the stdlib would have to live on for a very long time, even if their popularity waned.
The methods, protocols and sites may keep changing how they work, leading to an increased maintenance burden.
Python is used globally, and people would (understandably) expect to have support for popular systems in their neck of the woods – which may not be easy if, for example, all the documentation about the protocols used is inadequate or in a foreign language I’m not familiar with.
Native support of external protocols may require additional dependencies, which is not an appropriate burden for Python to carry, or use third-party modules which give rise to warnings or errors (for example, some Python libraries for Growl use the deprecated md5 module, which can give rise to deprecation warnings – this requires code in the libraries or applications using them to turn those warnings off).
Even if native support is provided for various systems, there are many options that are available when using such systems.The API for stdlib facilities to support such flexibility in options may be unwieldy, and even if that isn’t the case, it will certainly evolve over time, likely requiring you to subclass and change things, or fork and modify if the original classes weren’t reusable via subclassing. So, any idea of a long-lived “out-of-the-box” solution which requires no work from you is possibly an impossible dream :-(

Of course, developers could write “native” handlers for systems and upload them to PyPI (or post them elsewhere), and indeed people have done this in the past. That may be an approach that works for you; but anyone can upload their offerings to PyPI, which leads to what has been called the selection problem.

Nevertheless, some people might be thinking that some support for these newer notification systems would be nice to have with stdlib logging. What’s a good way of achieving this? We should take inspiration from the Unix philosophy:

Write programs that do one thing and do it well. Write programs to work together.

To apply this philosophy to the problem at hand, we can take advantage of the fact that many of these notification systems have command line interfaces! This is true at least on Unix and Unix-like systems, meaning primarily Linux and OS X. Here are some examples:

Twitter

Before Twitter changed their authentication system to disallow Basic authentication, you could just use curl like this: curl –u username:password -d status="Hello, world!" http://twitter.com/statuses/update.json Now that Twitter has switched to using OAuth, things are not quite so easy, but they can be after a small amount of one-time set-up.

One-time setup

We’ll use Mike Verdone’s Python Twitter Tools. It’s as easy as doing easy_install twitter and waiting for the installation to complete. Then, just type twitter in the shell. You’ll see something like this:

vinay@zeta-lucid:~/tools$ twitter Hi there! We're gonna get you all set up to use the Command-Line Tool.

In the web browser window that opens please choose to Allow access. Copy the PIN number that appears on the next page and paste or type it here:

Please enter the PIN:

A browser window opens on the Twitter website, and you enter your username and password into the presented form and click “Allow” to submit. A numeric PIN code is displayed in the response page, which you type or paste into the shell at the above prompt. You’re then told:

That's it! Your authorization keys have been written to /home/vinay/.twitter_oauth.

and that’s the end of the one-time setup. You can type twitter –-help to find the commands options available via the tool; they’ll fit most people’s needs.

Regular usage

Once you’ve done the above setup, you can just use a command line like twitter set hello to update your status on Twitter:

libnotify

To use libnotify from the command-line, use the notify-send program, which is part of libnotify. (On Ubuntu, you should be able to do sudo apt-get install notify-bin to install it). The man page will tell you all you need to know, but a simple usage would be notify-send title message –I icon_path You can set the urgency, time limit etc. through command-line parameters.

Growl

You can use the growlnotify program which is part of Growl. This has numerous options, but a simple usage would be growlnotify –n appname –m message –I iconpath You can set priority, stickiness etc. using various command-line parameters.

Mumbles

If you use Mumbles, you can use the mumbles-send script which comes with it, for example as follows. mumbles-send title message

Snarl

If you use Snarl, you can use the Snarl_CMD.exe program, for example as follows. Snarl_CMD nShowMessage TIME TITLE BODY [iconPATH]

Other Web-based notification services (for example, ticketing systems)

For Web-based services in general, you may be able to use logging.handlers.HTTPHandler either directly or via subclassing, but if you want to look at a command-line based solution which is similar to the ones above, you can use the excellent curl command-line tool:

curl is a command line tool for transferring data with URL syntax, supporting DICT, FILE, FTP, FTPS, GOPHER, HTTP, HTTPS, IMAP, IMAPS, LDAP, LDAPS, POP3, POP3S, RTMP, RTSP, SCP, SFTP, SMTP, SMTPS, TELNET and TFTP. curl supports SSL certificates, HTTP POST, HTTP PUT, FTP uploading, HTTP form based upload, proxies, cookies, user+password authentication (Basic, Digest, NTLM, Negotiate, kerberos...), file transfer resume, proxy tunnelling and a busload of other useful tricks.

You might be thinking that it seems a bit clunky in this day and age to be using the command-line in this way, and you may be right to think so. But it represents a straightforward, practical approach to integrating logging with many popular notification services in a way which doesn’t load the stdlib with unnecessary baggage. Plus, it may well involve less work for you: for example, you might be able to use a single command-line handler class, configured with various different command lines for different notification methods. Less code is good! And while in the past there was less than an ideal level of support under Windows for command-line tools, perhaps the development of PowerShell shows that the situation is changing for the better.

Perhaps you’re concerned about the overhead of running external command-line programs in subprocesses and the delays this might cause; in that case, you might want to look at this earlier post which explains how you can use QueueHandler and QueueListener classes to delegate the heavy lifting to separate threads or processes, leaving your Web application threads (and other performance-critical threads) as responsive as possible.

One possible realization of a command-line handler might be:

class CommandLineHandler(object):
    """
    A class which executes parametrized command lines in a separate process.
    """
    def __init__(self, cmdline):
        """
        Initialize an instance with a command-line template.
        
        The template consists of a set of strings, some of which may contain
        variable content merged in from a LogRecord.
        
        The LogRecord merge will be done before executing as a command.
        """
        self.cmdline = cmdline
        
    def handle(self, record):
        """
        Handle a record.
        
        This just merges its data into the command-line template and
        executes the resulting command.
        """
        cmdline = [c % record.__dict__ for c in self.cmdline]
        self.execute(cmdline)
        
    def execute(self, cmdline):
        """
        Execute the specified command
        """
        import subprocess
        p = subprocess.Popen(cmdline)
        p.wait()

Recall from the earlier post that QueueListener can be given (as a handler) any object which has a handle method: so a CommandLineHandler instance could be used as a handler.

Of course, you should very careful with any facility which executes potentially arbitrary commands on your server, making sure that command line configuration is covered by security diligence. An example command line as passed to the constructor might be ['notify-send', '%(appname)s - %(name)s', '%(message)s'] where appname is a context value inserted in the LogRecord (e.g. by a Filter, see this documentation).

I’d be grateful to get any feedback about the ideas expressed in this post. If you got this far, thanks for reading :-)

Improved QueueHandler, QueueListener: dealing with handlers that block

2010-09-22T07:06:00.001-07:00

tl; dr: Sometimes you have to get your logging handlers to do their work without blocking the thread you’re logging from. This post discusses one way in which you can do that, and presents a new QueueListener class as well as some improvements in the QueueHandler class discussed in earlier posts. A working script is provided so you can play with these ideas yourself.

Sometimes, you’ll work with code that runs in threads which must do their processing quickly. This is common in Web applications, though of course it also occurs in other scenarios. You may well need to log messages from those threads; however, if you are a library developer, you typically won’t have control over which handlers are configured by the running application. What happens if some of the configured handlers are ones that potentially will block for longish periods of time, causing delays which hold the threads up longer than is acceptable?

The most common culprit which demonstrates sluggish behaviour is the SMTPHandler: sending emails can take a long time, for a number of reasons outside the developer’s control (for example, a poorly performing mail or network infrastructure). But almost any network-based handler can block: Even a SocketHandler operation may do a DNS query under the hood which is too slow (and this query can be deep in the socket library code, below the Python layer, and outside your control).

One answer which pushes itself to the fore is to arrange things so that the time-consuming operation happens on a separate thread. This has been suggested to me once or twice, and suggestions have been made to perhaps provide threaded versions of the existing Handler classes or incorporate threading into some of the existing classes. That didn’t sound like a great idea to me, and for one reason or another I haven’t been able to address it until now.

I recently posted about an addition to Python 3.2 of a QueueHandler class, the addition of which came about as a result of Mike Bayer of SQLAlchemy fame pointing me to a Stack Overflow answer he had given, to a question about using logging with multiprocessing.

Mike’s solution was a specialized handler for use with multiprocessing which delegated to a RotatingFileHandler, which worked for his use case but was not general enough to put in the stdlib. So I came up with QueueHandler, which works not only with multiprocessing queues but also in-process thread-safe queues as implemented in the Queue module (renamed to queue in more recent Pythons). QueueHandler is also easy to subclass, for example to send logging events to a ZeroMQ socket, as described in this post.
QueueHandler also forms the basis of dealing with handlers that block. Before we look at one way to solve that problem, I should mention that the QueueHandler implementation which will be in 3.2 got a slight improvement: a new prepare method was added and the emit method was modified to use it. The docstrings give the reason for this minor refactoring:

    def prepare(self, record):
        """
        Prepares a record for queuing. The object returned by this
        method is enqueued.
        
        The base implementation formats the record to merge the message
        and arguments, and removes unpickleable items from the record
        in-place.
        
        You might want to override this method if you want to convert
        the record to a dict or JSON string, or send a modified copy
        of the record while leaving the original intact.
        """
        # The format operation gets traceback text into record.exc_text
        # (if there's exception data), and also puts the message into
        # record.message. We can then use this to replace the original
        # msg + args, as these might be unpickleable. We also zap the
        # exc_info attribute, as it's no longer needed and, if not None,
        # will typically not be pickleable.
        self.format(record)
        record.msg = record.message
        record.args = None
        record.exc_info = None
        return record

    def emit(self, record):
        """
        Emit a record.

        Writes the LogRecord to the queue, preparing it first.
        """
        try:
            self.enqueue(self.prepare(record))
        except (KeyboardInterrupt, SystemExit):
            raise
        except:
            self.handleError(record)

The whole class is to be found here.

Moving on to how to solve the problem of blocking handlers, the answer is in part to attach only a QueueHandler to those loggers which are accessed from performance-critical threads. They simply write to their queue, which can be sized to a large enough capacity or initialized with no upper bound to their size. The write to the queue will typically be accepted quickly, though you will probably need to catch the queue.Full exception as a precaution in your code. If you are a library developer who has performance-critical threads in their code, be sure to document this (together with a suggestion to attach only QueueHandlers to your loggers) for the benefit of other developers who will use your code.

The second part of the solution is QueueListener, which has been designed as the counterpart to QueueHandler. A QueueListener is very simple: it’s passed a queue and a handler, and it fires up an internal thread which listens to its queue for LogRecords sent from QueueHandlers (or any other source of LogRecords, for that matter). It should be relatively easy to subclass QueueListener to listen using other types of queue – for example, ZeroMQ sockets – though we won’t cover that in this post (it’ll be using a similar approach as was described here for our QueueHandler subclass ZeroMQSocketHandler). Here’s QueueListener:

import threading

class QueueListener(object):

    _sentinel = None
    
    def __init__(self, queue, handler):
        """
        Initialise an instance with the specified queue and
        handler.
        """
        self.queue = queue
        self.handler = handler
        self._stop = threading.Event()
        self._thread = None

    def dequeue(self, block):
        """
        Dequeue a record and return it, optionally blocking.

        The base implementation uses get. You may want to override this method
        if you want to use timeouts or work with custom queue implementations.
        """
        return self.queue.get(block)

    def start(self):
        """
        Start the listener.
        
        This starts up a background thread to monitor the queue for
        LogRecords to process.
        """
        self._thread = t = threading.Thread(target=self._monitor)
        t.setDaemon(True)
        t.start()

    def _monitor(self):
        """
        Monitor the queue for records, and ask the handler
        to deal with them.

        This method runs on a separate, internal thread.
        The thread will terminate if it sees a sentinel object in the queue.
        """
        q = self.queue
        has_task_done = hasattr(q, 'task_done')
        while not self._stop.isSet():
            try:
                record = self.dequeue(True)
                if record is self._sentinel:
                    break
                self.handler.handle(record)
                if has_task_done:
                    q.task_done()
            except queue.Empty:
                pass
        # There might still be records in the queue.
        while True:
            try:
                record = self.dequeue(False)
                if record is self._sentinel:
                    break
                self.handler.handle(record)
                if has_task_done:
                    q.task_done()
            except queue.Empty:
                break

    def stop(self):
        """
        Stop the listener.
        
        This asks the thread to terminate, and then waits for it to do so.
        """
        self._stop.set()
        self.queue.put_nowait(self._sentinel)
        self._thread.join()
        self._thread = None

Since the queue should only ever get LogRecords put into it, it seems reasonable to use None as a sentinel to terminate the thread. Of course, you can set a different sentinel if you wish.

The advantage of having a separate QueueListener class is that you can use the same instance to service multiple QueueHandlers. This is more resource-friendly than, say, having threaded versions of the existing handler classes, which would eat up one thread per handler for no particular benefit.

Here’s a simple snippet showing how to use QueueHandler and QueueListener together:

def main():
    q = queue.Queue(-1)
    qh = QueueHandler(q)
    h = logging.StreamHandler()
    ql = QueueListener(q, h)
    root = logging.getLogger()
    root.addHandler(qh)
    ql.start()
    f = logging.Formatter('%(threadName)s: %(message)s')
    h.setFormatter(f)
    # The log output will display the thread which generated
    # the event (the main thread) rather than the internal
    # thread which monitors the internal queue. This is what
    # you want to happen.
    root.warning('Look out!')
    ql.stop()

if __name__ == '__main__':
    main()

This should be self-explanatory, but of course please feel free to post a comment if you need clarification of anything.

The whole script is here, and if you run it you should see something like the following:

MainThread: Look out!

Notice that QueueListener is not even especially logging-specific: You can pass it as a handler any object that has a handle method which takes a single argument, and that method will be passed any non-sentinel object which appears on the queue.

You should be able to paste QueueHandler and QueueListener into your own code, as you may well be using Python versions earlier than 3.2 :-)

The plan is to add QueueListener to logging.handlers, so before 3.2 enters beta, I’d be grateful for any comments or suggestions you have about any of this stuff.

Python Logging Functionality - Facts vs. Myths

2010-09-19T04:25:00.000-07:00

tl; dr: Some inaccuracies and misunderstandings about how stdlib logging works have been expressed in the documentation and marketing presentations of a suggested alternative. On closer examination, certain statements which imply a lack of functionality or other shortcomings in stdlib logging have been shown to be inaccurate. You should feel confident that in using the stdlib logging package you are very unlikely to find it wanting, and that, if it seems too hard or not possible to achieve some result that you want to achieve, you should raise the issue on comp.lang.python or bugs.python.org and be assured of prompt responses and resolutions. Now, you can read on if you want more details :-).

Recently Armin Ronacher, developer of Werkzeug and Jinja among other things, released a library for logging which, in his opinion, is preferable to the logging package provided as part of Python since the 2.3 release. Now preferences are a very personal thing, and since Armin has made worthy software contributions to the Python community, there will no doubt be many people who trust his judgement and follow where he leads. In general, choice in software is good, and people should be free to make up their own minds about the software they want to use. However, in order to make an informed decision, people need accurate information on which to base that decision. For example, I chose to use argparse over the stdlib's optparse even before argparse landed in the stdlib; in making that choice, I looked at Steven Bethard's rationale as described here and was fortunate to have the time to be able to examine and evaluate each of his points for myself.

In the case of choosing whether to use Python logging or something else, people may or may not have the time to investigate in any depth the relative merits of the alternatives on offer. Armin has seemingly made it easier for busy people by including, in his library's documentation, reasons why you should use his offering in preference to the stdlib's logging package, and what he perceives to be problems with the code in the stdlib. This is what Steven did for argparse, but in the case of logging Armin has made a number of statements which are inaccurate or misleading. No doubt he has not meant to deliberately mislead anyone, but some of the things he has said have led me to conclude that perhaps Armin doesn't really understand some of the aspects of how stdlib logging works, and how you can use it in Web applications, desktop applications, casual utility scripts, and of course libraries which support all of these application development constituencies. And if Armin - a clearly talented developer - is making some egregious mistakes in his thinking about how stdlib logging works and what you can or can't do with it, then it's possible that the lack of understanding which he demonstrates is more widespread; as maintainer of the stdlib logging package, I feel there's a need to do something to rectify this. Hence, this post.

Isn't that what the stdlib documentation is for? Of course, at least partly, and while the stdlib logging documentation undergoes continual additions and revisions (which hopefully can be viewed as continuous improvement), it is a difficult medium in which to address certain points. Of necessity, the stdlib documentation for most modules is presented largely in a reference style, with only limited examples which might serve as tutorials. And even for sections where much effort has been expended in presenting using a tutorial style, there is always room for expositions which do not fit easily in the stdlib documentation: for example, a "cookbook" style presentation which tries to show how to solve common and less common problems which arise in considering how best to use a package. And then, who reads documentation, anyway? ;-)

Of course no software is perfect, nor can any design or implementation hope to please all of its users all of the time. I have always viewed stdlib logging as capable of being improved, not because there was anything especially wrong with it to start with, but rather that through the philosophy of continuous improvement you have the best chance of providing something which remains relevant and useful to as many users as possible. That, it seems to me, is a core Python philosophy, enshrined in the procedures, standards and practices of the PEP process.

You might be thinking that this post is a bit of an over-reaction on my part. Perhaps, but as well as the concern I expressed about there being a lack of understanding out there about how logging works, I have another concern. This is based on a strong view that for certain types of functionality, too much choice is not a good thing. For example, imagine if there were several competing implementations of regular expressions in Python, or implementations of pickling functionality, in common use. Some library developers would use one particular version, others a different one. So an application developer using several such libraries would not only have to pull in additional dependencies but also spend some time and thought on how to get the different libraries to work together. And so it is with logging, in my view; it's an infrastructure function and a lot of libraries out there already use it. Of course if it fell short of meeting developer requirements, then it should not be immune from being supplanted by a better alternative (as with optparse and argparse). However, I believe that stdlib logging still remains fit for purpose, and am willing to stand up and say so when the criticisms made of it are without merit or overstated.

So, let's review some of the statements in Armin's documentation and presentations which merit closer examination. It's a long list, hence the tl;dr at the top of this post, but there are even more points that I could have made if not for the lack of time :-(

Statements	What they imply ("Myths")	How it really is ("Facts")	Conclusions
In the opening paragraph in the "Why you should use Logbook" section
Despite the existence of stdlib logging, you should use Logbook.	Logbook is better than stdlib logging now, and is ready to be used.	As stated in the same paragraph, Logbook is in the alpha stage of development and should be treated as a developer preview, and only supports Python 2.6 and 2.7.	Logbook is at present suitable for evaluation use only.
In the "Advantages over Logging" section
If properly configured, Logbook’s logging calls will be very cheap and provide a great performance improvement over the standard library’s logging module. While we are not there yet, there will be some performance improvements in the upcoming versions when we implement certain critical code paths in C.	stdlib logging is slow.	You can evaluate these test scripts yourself: time_logging.py and time_logbook.py. In the output of these scripts, you need to look at the "log_simple" line on each for a meaningful comparison. It's not a scientific benchmark, but on my machine, with these scripts, the Logbook code runs around 30% slower than the stdlib code.	Logbook is at present a fair bit slower than stdlib logging, so it is somewhat premature to boast about "great performance improvements". While it's possible for Logbook to improve performance by writing performance-critical code in C, it's also possible for stdlib code to improve using the same approach. (Note, however, that building C extensions of third-party libraries from source under Windows can be a pain). Anyway, according to the numbers shown by these test scripts, logging calls take of the order of tens of microseconds - not a real concern in most scenarios. If you are having performance problems which you think are due to logging overhead, the recommendation is to profile and see where the bottlenecks really are. If they are found to be in logging, please post your findings on comp.lang.python or bugs.python.org if you think that's appropriate.
Logbook also supports the ability to inject additional information for all logging calls happening in a specific thread. For example, this makes it possible for a web application to add request-specific information to each log record such as remote address, request URL, HTTP method and more.	stdlib logging can't do this.	I have already explained to Armin how to do this - see this post.	stdlib logging CAN do this fairly easily.
The Logbook system is (besides the stack) stateless and unit testing it is very simple. If context managers are used, it is impossible to corrupt the stack, so each test can easily hook in custom log handlers.	There's something inherently good about a shared stack, but having a shared dict is somehow worse. Unit testing with stdlib logging is not simple. Unit tests with stdlib logging can't hook in custom handlers.	There's no convincing argument that the type of shared state (execution context) offered by Logbook is better than how stdlib works. You just have to take it on trust. Unit testing with stdlib logging is not hard, since you can add/remove handlers to/from loggers, close handlers in tearDown which you opened in setUp, and disable loggers you don't need. Unit tests with stdlib logging CAN hook in any handlers you want; in fact, Python's own regression tests use unittest to do testing of the logging package itself.	From the evidence presented, there's no proof of any actual functional advantage of Logbook over logging. You just have to take it on trust.
In the "Design Principles" section
Logbook [...] supports paradigms we think are more suitable for modern applications than the traditional Java inspired logging system that can also be found in the Python standard library and many more programming languages.	Having a design that was inspired by a Java library is somehow bad, just because of Java. Tha fact that it appears in many more programming languages damns it even further.	Although the Java log4j system was an influence on stdlib logging, this is because it had some good abstract ideas, well worth using. Though we have a lot of very clever people in the Python community, not every clever person is a Pythonista; it's very parochial to think that good ideas can only come from the Python community. The ideas that emerged in log4j and other packages are the ideas of "what happened? where did it happen? how important is it? who wants to know?" and if you think about it, these ideas are hardly Java-specific. In fact, they are pretty central to the problem domain addressed by logging. So - "what happened?" is the details of the logging call, "where did it happen?" is the logger name, "how important is it?" is the level, and "who wants to know?" is the handler. Hardly that complicated, and pretty much a minimum requirement for any logging package that aspires to the name. Also, anyone who bothers to look at log4j in detail will see that Python logging is not a mindless translation - it's very Pythonic. Beyond the basic abstractions of "What? Where? How Important? Who Needs To Know?", there's no real correspondence between the Java artefacts and the Python ones. Using David A. Wheeler's SLOCCount, log4j 1.2.15 = 168 source files, around 16K SLOC; Python 2.6 logging = 3 source files, < 1.5K SLOC. Almost every class in stdlib logging maps to a core concept of logging, other than the handler classes, which are geared towards specific types of audience for logging messages.	There's no indication that a Java influence has been detrimental to stdlib logging. All of the core concepts from stdlib logging are also present in Logbook: loggers ("where?"), levels ("how important?"), handlers ("who wants to know?") and the details passed to logging calls ("what happened?"). So if stdlib logging "suffers" from Java influences, so equally does Logbook. It's also worth bearing in mind that Python logging works in Python 2.3 -> 2.7 and 3.0 -> 3.2, without the need to depend on specific features present only in the more recent versions of Python. And while a case can be made for certain programming styles like the with statement to have better support in stdlib logging, these are by no means essential to the basic business of logging; in any case support for new features can always be added as and when it's needed.
Logbook is unique in that it has the concept of logging channels but that it does not keep a global registry of them. In the standard library’s logging module a logger is attached to a tree of loggers that are stored in the logging module itself as global state.	The shared state embodied in Logbook's process or thread context is somehow good, but the shared tree of loggers stored as "global" state in stdlib logging is somehow bad.	One reason for the shared state in stdlib logging is that application developers often need explicit access to loggers used by libraries, in order to control the level of verbosity of logging from those libraries, in the context of the application being developed. This verbosity varies over the life of an application - for example, when a bug is discovered in an application in production, it's common to selectively turn the verbosity of different library loggers up and down, while diagnosing the problem. You can't do that when the logger used by a library is hidden completely from a user of that library. This is a fundamental point which may not bite developers working in limited scenarios, but I've had reason to rely on this functionality time and again. For example: I sometimes need to turn the verbosity of SQLAlchemy's logging so that I can examine SQL statements being generated from the ORM. If I couldn't access SQLAlchemy's top-level logger, using the name "sqlalchemy" and the fact that because of the "global" registry, the SQLAlchemy code and my code are both referring to the same object when they say logging.getLogger('sqlalchemy')), I couldn't turn this verbosity up and down, as and when needed. Strictly speaking, the tree of loggers in stdlib logging does not need to be global. As a look at logging's source code will show, the tree of loggers is held as an instance variable of an instance of a Manager class. A binding to this Manager instance is currently stored in the Logger class, and through this binding you can say that the tree of loggers is global. This state of affairs has been the situation since the first release of logging in the stdlib. It would be well within the bounds of possibility to either expand the Manager class to be a context manager, or derive a context manager class from it. If this was done, then the tree of loggers need not be global: it would just be an attribute of the Manager instance, and there could be more than one Manager (or derived context manager) instance in a Python process. This improved context manager may well appear in the future, but at present there has not been a strong enough case made for the need for doing this. If such a case is made (for example, by someone generating a PEP or proto-PEP making the justification) then providing such a feature can be considerered, and it would not be a major undertaking (but not a trivial one, either).	There is nothing wrong with logging's design just because it uses a shared registry of loggers. In fact, the shared registry confers some positive, practical benefits in real-life use cases.
In logbook a logger is just an opaque object [...] the lifetime and availability of that object is controlled by the person creating that logger. The registry is necessary for the logging library to give the user the ability to configure these loggers.	It's better for a library developer to keep their loggers completely encapsulated in the library, so application developers using that library have no access to it.	The need to access the loggers in libraries comes up again and again in practice, particularly in production environments and long-running service processes where you can't just fire up a debugger, when a problem arises, to see what's causing it. With stdlib logging, features exist to turn the verbosity of library logging up and down, for different libraries at different times, without needing to stop the long-running processes.	The stated advantage of Logbook over stdlib logging seems illusory. The logger registry actually solves practical problems in real-world environments where multiple libraries from multiple vendors are integrated into an application. It's not clear, from Logbook's documentation, whether you can tune the verbosity of logging in a library component which utilised Logbook for its logging functionality.
Logbook has a completely different concept of dispatching from loggers to the actual handlers which removes the requirement and usefulness of such a registry. The advantage of the logbook system is that it’s a cheap operation to create a logger and that a logger can easily be garbage collected to remove all traces of it.	There's no utility in a shared registry between different components of an application. Creating a logger in stdlib logging is expensive. It's important to be able to remove all traces of a logger that you created.	The preceding discussions try to show why a shared registry is useful. There's no example given in the Logbook documentation of how you might (as an application developer) tune the logging verbosity of a component you use. It's not clear that this is even possible in Logbook. Creating loggers in the stdlib is not particularly expensive, and is a one-off operation; so amortized over many uses, the creation should actually be cheaper in the stdlib. It's true that loggers can't be garbage collected to remove all traces of it, but not clear why that is really important, as the memory used by loggers is not significant in normal usage.	stdlib logging is designed the way it is for good reasons, not because its designer lacks imagination. The stated disadvantages of stdlib logging over Logbook are not proven, just stated as if they were.
Logbook moves the burden of delivering a log record from the log channel’s attached log to an independent entity that looks at the context of the execution to figure out where to deliver it.	The loggers in stdlib logging are suffering from some kind of burden when delivering log records.	In both stdlib logging and Logbook, records are delivered using handlers. Loggers become a way for an application developer to finely control the logging verbosity of their application, so that they are in control rather than library developers who, of necessity, cannot anticipate every circumstance about how their libraries are used and deployed.	The context of execution is insufficient to determine how records generated in libraries should be delivered. In practice, you need a combination of the execution context and the wishes of the application developer regarding how library logging is to be configured.
In the "Context sensitive handler stack" section
Let’s take a GUI application [which] might fail or log messages. The typical default behaviour here would be to log into a logfile. Fair enough, that’s how these applications work. But what’s the point in logging if not even a single warning happened? The traditional solution with the logging library from Python is to set the level high (like ERROR or WARNING) and log into a file. When things break, you have a look at the file and hope it contains enough information. When you are in full control [...] with a stack based system like Logbook has, there is a lot more you can do. For example you could immediately after your application boots up instanciate a FingersCrossedHandler. This handler buffers all log records in memory and does not emit them at all. What’s the point? That handler activates when a certain threshold is reached. For example, when the first warning occurs you can write the buffered messages as well as the warning that just happened into a logfile and continue logging from that point. Because there is no point in logging when you will never look at that file anyways.	This kind of functionality is only possible with a context sensitive handler stack, which only Logbook has. You can't do this with stdlib logging.	You can do exactly this with stdlib logging, where from the earliest release there's been a MemoryHandler class which buffers up records in memory until a message with a specified threshold level is seen, when all the messages buffered so far are then forwarded to a target handler for processing.	The supposed advantage of a context-sensitive handler stack in this scenario isn't any particular advantage at all.
But that alone is not the killer feature of a stack. In a GUI application there is the point where we are still initializing the windowing system. So a file is the best place to log messages. But once we have the GUI initialized, it would be very helpful to show error messages to a user in a console window or a dialog. So what we can do is to initialize at that point a new handler that logs into a dialog. When then a long running tasks in the GUI starts we can move that into a separate thread and intercept all the log calls for that thread into a separate window until the task succeeded.	This is somehow a killer feature of a stack, which you can't do any other way.	You can do this kind of processing perfectly easily with stdlib logging. There are examples of dialog- or window-based handlers (for Qt, say) in answers to questions on Stack Overflow. You can combine the provided stdlib logging handlers such as MemoryHandler and FileHandler together with your own window-specific handlers (dependent on which windowing system you are using) to achieve the sort of effect described.	Another supposed advantage of a context sensitive handler stack, which isn't.
In Armin's Logbook presentation
In the "Why not logging?" slide
stdlib logging is not really suited for Web applications.	Don't even bother trying to use stdlib logging with Web applications, it's not worth it.	It's perfectly possible to use stdlib logging with Web application, as I showed Armin how to meet his requirements, in this post.	This statement is just plain wrong and illustrates a lack of understanding of how to use the functionality of stdlib logging, rather than any lack of functionality in stdlib logging.
Logging's central registry of loggers makes unittesting a pain.	It's too much trouble to use stdlib logging in your unittests.	It doesn't need to be a pain. A future post on this blog will describe scenarios showing how to use logging in your unit tests. It's probably possible to provide additional utility functions in stdlib logging to make some aspects of unit testing easier, but there are no real showstoppers; if Armin describes his problem scenario in as much detail as he described his Web application configuration problem, I will (hopefully) be able to suggest some ways of easing his pain.	Unless specific details are given as to why unit testing with stdlib logging is considered to be a pain (i.e. what you'd like to do but what you can't do) then this statement must be taken with a pinch of salt.
The same registry also causes issues when libraries want to start logging	The registry is central to the issues caused by libraries doing logging	There are documented things that library authors need to do when setting up logging for libraries. If library developers do not follow the recommendations then this might in fact cause problems, but that has nothing to do with the existence of a central registry (or at least, the connection has not been demonstrated).	There's no evidence that the existence of a central registry is somehow responsible for how third-party libraries misuse logging.
You can't delete loggers once created.	It's important that you be able to delete loggers once created.	The reason why loggers are not deleted once created is that multiple threads (other than the one that wants to delete the logger) can have references to the logger. This is facilitated by having a central registry, but even in a system without a central registry, loggers could be passed between threads. In that scenario, you can't actually guarantee to delete the logger since there could be references to it in another thread. It's not demonstrated that it's important to expunge all loggers completely from memory. The number of logger instances is related to the number of logical "areas" in an application - the idea of "where" in a component a particular event occurred. This is not so large that the amount of memory used by loggers becomes significant. And stdlib logging allows loggers to be disabled, which means that they cease to perform any logging (until re-enabled) and are as good as gone.	It's true that you can't delete loggers, but they can be easily disabled; they do not, under normal usage patterns, occupy large amounts of memory.
In the "Why does nobody like logging?" slide
Why does nobody like logging?	Nobody likes logging.	This is an opinion, not a fact. There are many people who have expressed their thanks to me for the existence of the logging package and feedback saying that it has been very useful to them. Even Armin has told me that he liked logging "a lot", which is hard to reconcile with what he's now saying - since logging's basic design has been the same from the outset, and it seems to meet his functional needs even if it doesn't press his aesthetic hot buttons.	There's no basis in fact for this statement. It's marketing FUD.
The default configuration of stdlib logging for applications is bad.	The statement speaks for itself.	On the contrary, the default configuration for applications is consistent with the principle of least surprise and the Zen of Python's "explicit is better than implicit". In common with the Unix philosophy, software should not be excessively verbose except when it needs to be, or is asked to be. By default, stdlib logging will only output messages of severity WARNING or higher. (It's easy to change this default.) In fact, in the default configuration of logbook 0.2, every DEBUG logging call in every library which uses Logbook in your application will print debug messages to stderr when your application runs, even if you specify that you want to see only messages of severity WARNING or greater. Perhaps you won't care if your application is a GUI application or a Web application, since you won't have a console, and perhaps logbook is expressly designed only for these types of application. For a console application, it's very likely you will get Too Much Information. Here is an example.	The default configuration of stdlib logging is quite sane; there's nothing wrong with it.
Useless default configuration for libraries	The statement speaks for itself.	Library developers are supposed to add a NullHandler to their top-level logger and to the level and propagation flag as needed, but to not add any other handlers to their logging configuration because that configuration is the prerogative of the application developer. However, it's not possible to prevent library authors from breaking these rules.	By default, libraries aren't supposed to handle messages - only to log them - and the application developer is expected to configure any logging (though they don't have to; if they don't, no logging output should be generated). This is consistent with the principle of least surprise and Zen of Python point mentioned earlier.
Who sets up the logging config? Libraries sometimes call basicConfig.	If library developers don't follow the guidelines set down for logging from libraries, that's somehow the fault of stdlib logging.	There is documentation about how to configure logging in libraries, and while this may be lacking in some way, it's not immediately clear what that lack is.	Perhaps more or better documentation is needed, but that won't eliminate completely the possibility that a library developer will misguidedly add handlers to the logging configuration, say by calling basicConfig().
logging.warn() and friends are not thread-safe.	Stay away from stdlib logging if you want to use threads.	If logging is correctly configured in an application, there should be no untoward behaviour by stdlib logging. In versions of Python earlier than 2.7.1 and 3.2, the code in basicConfig() omitted acquiring and releasing an internal lock, and you could demonstrate incorrect behaviour in stdlib logging by calling basicConfig() directly or indirectly from multiple threads; this has been fixed in 2.7.1 and 3.2, but nevertheless, it is wrong to do any logging from multiple threads before configuring handlers (if you want any logging output, that is) - because if no handlers have been configured before threads start running, any messages they log could be lost (because there are no handlers to deliver them). So, good practice would mean that this problem shouldn't occur in practice, and even if it does, the worst consequence is that handlers are added multiple times, resulting in multiple messages output for the same event.	It's disingenuous to say that these functions are not thread-safe. Although the statement is technically correct, the unexpected behaviour only occurs if logging is not configured before multiple threads are started, and more than one of these threads calls basicConfig() either directly or via logging.warn() and friends. Even then, the behaviour occurs only rarely, due to thread timing uncertainties. In any case, the incorrect behaviour will not occur in Python versions >= 2.7.1 or >= 3.2, because the requisite lock acquisition/release code has now been added.

Configuring logging for Web applications

2010-09-17T09:10:00.000-07:00

tl;dr: You can easily configure your web applications with Python logging, so that logged messages can go into web-application-specific log files (or other destinations) even for multiple web applications in the same Python process, and have those logs contain request-specific information such as remote user IP address, request method and others. Demonstration scripts are here and here, copy them to the same initially empty folder and run webapptest.py in that folder, and then look at app*.log. Look at the InjectingFilter class - that's the core of the solution. Read on for more information.

In a recent post on Reddit, Armin Ronacher, developer of Werkzeug and Jinja among other things, had this to say:

I don't know a setup of logging that would work out for me. But maybe you do and could share. Say I am a library called by anyone and use three or five loggers without any handlers. Now in the same Python process are two different web applications, each independently but using the same library. How can each of these applications have their own log where all logging messages from that library are redirected to the correct one of these application's log files (the correct one is the one where all calls were issued by the same handling thread) including additional information such as current IP and HTTP request method. I tried, I failed.

Now, Armin has recently been working on his own logging library, and saying at conferences and in other public fora that he's done this mainly because he thinks Python logging is not really suited to Web applications. This, despite the fact that it's used in Google App Engine, Pylons, Tornado and other Web application platforms, by the many developers that use them. Now Armin can make a little arm-waving FUD go a long way, and I was very glad to have an actual problem statement from him that I could try to nail with a solution. I'm pleased to say it only took around ten minutes or so of work to come up with something which seems to solve his problem for him. His response? "This is actually quite neat ..." ;-)

To illustrate the solution, I first wrote a simple module which represents the library. This demonstration example only uses one logger, but it could use three or five loggers and the solution would be the same. Here is the library module, christened webapplib.py:

import logging
import time

logger = logging.getLogger(__name__)

def useful():
    logger.debug('Hello from webapplib!')
    time.sleep(0.01)

The useful() function represents a call into the library from a Web application; this call will be made during request processing. The time.sleep() call is there to simulate real activity, so that multiple threads will definitely be running at the same time processing requests, for a more realistic scenario.

The next step was to construct a test harness which simulates requests and web applications. First, the request:

class Request:
    def __init__(self, method, ip):
        self.method = method
        self.ip = ip

REQUESTS = [
    Request('GET', '192.168.2.20'),
    Request('POST', '192.168.2.20'),
    Request('GET', '192.168.2.21'),
    Request('POST', '192.168.2.21'),
    Request('GET', '192.168.2.22'),
    Request('POST', '192.168.2.22'),
]

The dummy Request class just has HTTP method and IP, as example attributes which need to be put into the logs. The REQUESTS array is just a list of dummy requests which will be sent, during the test run, to the dummy web applications.

Next, we need to consider how to simulate the Web applications. Let's start with the following skeleton snippet:

import logging

root = logging.getLogger()
root.setLevel(logging.DEBUG)

formatter = logging.Formatter('%(asctime)s %(threadName)-11s %(appName)s %(name)-9s %(ip)s %(method)-4s %(message)s')

class WebApp:
    def __init__(self, name):
        self.name = name
        handler = logging.FileHandler(name + '.log', 'w')
        handler.setFormatter(formatter)
        root.addHandler(handler)
        self.num_requests = 0

    def process_request(self, request):
        self.num_requests += 1
        logger.debug('Request processing started')
        webapplib.useful()
        logger.debug('Request processing finished')

Now the appName, method and ip in the format string are not part of the normal set of attributes which are part of logging: they are extra request-specific attributes which we want to inject into all log messages. In order for the format string to have the desired effect, attributes with those names will need to be added to the LogRecord for the event being logged, before formatting takes place; we'll come to that in a bit.

The WebApp class, representing a dummy web application, is fairly straightforward: we initialize a FileHandler for that application in the constructor, based on its name, set its formatter, and add it to the root logger.

We maintain a counter of requests processed by each WebApp instance. This counter is incremented in process_request, which we will call from our top-level test harness to simulate processing a request. This method logs two DEBUG messages, and calls into the common webapplib library's useful() method, which will also log a DEBUG message. So in total, each processed request should result in 3 lines in the log.

Before looking at the specifics of the solution to the problem, let's see what the top-level test harness looks like:

def main():
    app1 = WebApp('app1')
    app2 = WebApp('app2')
    apps = [app1, app2]
    threads = []
    #Add a common handler which will capture all events
    handler = logging.FileHandler('app.log', 'w')
    handler.setFormatter(formatter)
    root.addHandler(handler)
    #while True:
    for i in xrange(1000):
        try:
            app = choice(apps)
            request = choice(REQUESTS)
            t = threading.Thread(target=app.process_request, args=(request,))
            threads.append(t)
            t.start()
        except KeyboardInterrupt:
            break    
    for t in threads:
        t.join()
    for app in apps:
        print '%s processed %s requests' % (app.name, app.num_requests)
    
if __name__ == '__main__':
    main()

So the test harness creates two dummy Web applications called app1 and app2, and sends a thousand requests (chosen at random from our array of pre-constructed requests) to an app which is also chosen at random. A FileHandler for 'app.log' is created and added to the root logger, which will capture all logging (i.e. across all Web applications). Each request is processed on a separate thread.

So far, we've described the simulation artefacts and the overall structure of the test harness. Now let's look at the core of the solution. Let's review the problems we have to solve:

Each LogRecord needs the relevant thread-specific information injected into it before formatting.
The handler for each of the application-specific logs needs to filter out any record which is not intended for that log.

We can solve both of these by using an appropriate Filter subclass. We'll call it InjectingFilter, because it injects data into the LogRecord as well as acting as a filter. But how will it work? We'll use a threading.local object to hold thread-specific state which is needed by the filter. Here's the first cut of what InjectingFilter looks like:

import threading

tlocal = threading.local()

class InjectingFilter(logging.Filter):
    def filter(self, record):
        record.method = tlocal.request.method
        record.ip = tlocal.request.ip
        return True

This shows just the injection logic of the filter, and not any filtering logic. The thread-local object tlocal will hold a reference to the request currently being processed, which the filter uses to inject HTTP method and IP address into the LogRecord. This request needs to be set into the thread-local in WebApp.process_request, which now looks like this:

    def process_request(self, request):
        tlocal.request = request
        self.num_requests += 1
        logger.debug('Request processing started')
        webapplib.useful()
        logger.debug('Request processing finished')

So far, so good. Next, we need to implement the filtering part: this is done by attaching, to each app-specific handler, an app-specific filter. In order to operate effectively, the filter needs to know whether the current thread belongs to its Web application (in which case, the record is accepted for processing) or not (in which case, the record is rejected). One easy way of doing this is to ensure that the WebApp maintains a set of names of the threads it's currently using, and the filter can just check if the current thread belongs to its app's set. So we need to keep a reference to the app in the filter, and this also allows the injection of the appName attribute into the LogRecord. So the WebApp class will now look like this (simple implementation):

class WebApp:
    def __init__(self, name):
        self.name = name
        self.threads = set()
        handler = logging.FileHandler(name + '.log', 'w')
        f = InjectingFilter(self)
        handler.setFormatter(formatter)
        handler.addFilter(f)
        root.addHandler(handler)
        self.num_requests = 0

    def process_request(self, request):
        tlocal.request = request
        tlocal.appName = self.name
        tname = threading.currentThread().getName()
        self.threads.add(tname)
        self.num_requests += 1
        try:
            logger.debug('Request processing started')
            webapplib.useful()
            logger.debug('Request processing finished')
        finally:
            self.threads.remove(tname)

and the InjectingFilter class will look like this (simple implementation):

class InjectingFilter(logging.Filter):
    def __init__(self, app):
        self.app = app

    def filter(self, record):
        record.method = tlocal.request.method
        record.ip = tlocal.request.ip
        record.appName = tlocal.appName
        tname = threading.currentThread().getName()
        return tname in self.app.threads

You can pick up the whole script as webapptest.py from here, and use it with the webapplib.py script shown as the first code in this post. What happens if we run it?

vinay@zeta-lucid:~/projects/scratch$ python webapptest.py
app1 processed 506 requests
app2 processed 494 requests
vinay@zeta-lucid:~/projects/scratch$ wc -l app*.log
  1518 app1.log
  1482 app2.log
  3000 app.log
  6000 total

So the app.log file contains all the log messages - 3 per request, for a total of 3000 - and the lines in app1.log and app2.log add up to 3000 too, which looks promising. Plus the individual line counts for these files are 3 x the number of requests processed, so that's also consistent. Let's look at the first few lines of each file:

vinay@zeta-lucid:~/projects/scratch$ head app.log app1.log app2.log
==> app.log <==
2010-09-17 16:11:48,226 Thread-1    app1 __main__  192.168.2.20 GET  Request processing started
2010-09-17 16:11:48,227 Thread-1    app1 webapplib 192.168.2.20 GET  Hello from webapplib!
2010-09-17 16:11:48,228 Thread-2    app1 __main__  192.168.2.21 POST Request processing started
2010-09-17 16:11:48,229 Thread-2    app1 webapplib 192.168.2.21 POST Hello from webapplib!
2010-09-17 16:11:48,230 Thread-3    app2 __main__  192.168.2.21 POST Request processing started
2010-09-17 16:11:48,230 Thread-3    app2 webapplib 192.168.2.21 POST Hello from webapplib!
2010-09-17 16:11:48,231 Thread-4    app1 __main__  192.168.2.22 POST Request processing started
2010-09-17 16:11:48,232 Thread-4    app1 webapplib 192.168.2.22 POST Hello from webapplib!
2010-09-17 16:11:48,233 Thread-5    app2 __main__  192.168.2.21 GET  Request processing started
2010-09-17 16:11:48,233 Thread-5    app2 webapplib 192.168.2.21 GET  Hello from webapplib!

==> app1.log <==
2010-09-17 16:11:48,226 Thread-1    app1 __main__  192.168.2.20 GET  Request processing started
2010-09-17 16:11:48,227 Thread-1    app1 webapplib 192.168.2.20 GET  Hello from webapplib!
2010-09-17 16:11:48,228 Thread-2    app1 __main__  192.168.2.21 POST Request processing started
2010-09-17 16:11:48,229 Thread-2    app1 webapplib 192.168.2.21 POST Hello from webapplib!
2010-09-17 16:11:48,231 Thread-4    app1 __main__  192.168.2.22 POST Request processing started
2010-09-17 16:11:48,232 Thread-4    app1 webapplib 192.168.2.22 POST Hello from webapplib!
2010-09-17 16:11:48,236 Thread-7    app1 __main__  192.168.2.21 POST Request processing started
2010-09-17 16:11:48,236 Thread-7    app1 webapplib 192.168.2.21 POST Hello from webapplib!
2010-09-17 16:11:48,237 Thread-8    app1 __main__  192.168.2.22 POST Request processing started
2010-09-17 16:11:48,238 Thread-8    app1 webapplib 192.168.2.22 POST Hello from webapplib!

==> app2.log <==
2010-09-17 16:11:48,230 Thread-3    app2 __main__  192.168.2.21 POST Request processing started
2010-09-17 16:11:48,230 Thread-3    app2 webapplib 192.168.2.21 POST Hello from webapplib!
2010-09-17 16:11:48,233 Thread-5    app2 __main__  192.168.2.21 GET  Request processing started
2010-09-17 16:11:48,233 Thread-5    app2 webapplib 192.168.2.21 GET  Hello from webapplib!
2010-09-17 16:11:48,234 Thread-6    app2 __main__  192.168.2.22 GET  Request processing started
2010-09-17 16:11:48,235 Thread-6    app2 webapplib 192.168.2.22 GET  Hello from webapplib!
2010-09-17 16:11:48,239 Thread-9    app2 __main__  192.168.2.20 POST Request processing started
2010-09-17 16:11:48,239 Thread-9    app2 webapplib 192.168.2.20 POST Hello from webapplib!
2010-09-17 16:11:48,241 Thread-3    app2 __main__  192.168.2.21 POST Request processing finished
2010-09-17 16:11:48,244 Thread-5    app2 __main__  192.168.2.21 GET  Request processing finished

So app.log contains interspersed messages from app1 and app2, but app1.log seems to contain just app1 messages, and app2.log seems to contain just app2 messages. This is encouraging, and we can confirm with:

vinay@zeta-lucid:~/projects/scratch$ grep app1 app1.log | wc -l
1518
vinay@zeta-lucid:~/projects/scratch$ grep app2 app1.log | wc -l
0
vinay@zeta-lucid:~/projects/scratch$ grep app2 app2.log | wc -l
1482
vinay@zeta-lucid:~/projects/scratch$ grep app1 app2.log | wc -l
0

The log lines all contain appName, request method and IP address, as required, Job done, it seems.

Of course, this is a test scenario with dummy requests and web applications implemented simplistically, but the principle of the solution will apply equally to real web application server environments.

QueueHandler and ZeroMQ support

2010-09-13T23:45:00.000-07:00

A new handler has been added to logging for Python 3.2: QueueHandler . This allows you to send logging events to a queue of some description. For users of earlier versions of Python, here is the latest code from the Py3K branch:

class QueueHandler(logging.Handler): 
    """ 
    This handler sends events to a queue. Typically, it would be used together 
    with a multiprocessing Queue to centralise logging to file in one process 
    (in a multi-process application), so as to avoid file write contention 
    between processes. 
 
    This code is new in Python 3.2, but this class can be copy pasted into 
    user code for use with earlier Python versions. 
    """ 
 
    def __init__(self, queue): 
        """ 
        Initialise an instance, using the passed queue. 
        """ 
        logging.Handler.__init__(self) 
        self.queue = queue 
 
    def enqueue(self, record): 
        """ 
        Enqueue a record. 
 
        The base implementation uses put_nowait. You may want to override 
        this method if you want to use blocking, timeouts or custom queue 
        implementations. 
        """ 
        self.queue.put_nowait(record) 
 
    def emit(self, record): 
        """ 
        Emit a record. 
 
        Writes the LogRecord to the queue, preparing it for pickling first. 
        """ 
        try: 
            # The format operation gets traceback text into record.exc_text 
            # (if there's exception data), and also puts the message into 
            # record.message. We can then use this to replace the original 
            # msg + args, as these might be unpickleable. We also zap the 
            # exc_info attribute, as it's no longer needed and, if not None, 
            # will typically not be pickleable. 
            self.format(record) 
            record.msg = record.message 
            record.args = None 
            record.exc_info = None 
            self.enqueue(record) 
        except (KeyboardInterrupt, SystemExit): 
            raise 
        except: 
            self.handleError(record)

This code is perfectly usable in earlier Python versions, including 2.x - just copy and paste it into your own code. In addition to usage with queues from the queue and multiprocessing modules (as described in this earlier post), the QueueHandler makes it easy to support other queue-like objects, such as ZeroMQ sockets.

In the example below, a PUBLISH socket is created separately and passed to the handler (as its ‘queue’):

import zmq # using pyzmq, the Python binding for ZeroMQ 
import json # for serializing records portably 
 
ctx = zmq.Context() 
sock = zmq.Socket(ctx, zmq.PUB) # or zmq.PUSH, or other suitable value 
sock.bind('tcp://*:5556') # or wherever 
 
class ZeroMQSocketHandler(QueueHandler): 
    def enqueue(self, record): 
        data = json.dumps(record.__dict__) 
        self.queue.send(data) 

handler = ZeroMQSocketHandler(sock)

Of course there are other ways of organizing this, for example passing in the data needed by the handler to create the socket:

class ZeroMQSocketHandler(QueueHandler): 
    def __init__(self, uri, socktype=zmq.PUB, ctx=None): 
        self.ctx = ctx or zmq.Context() 
        socket = zmq.Socket(self.ctx, socktype) 
        socket.bind(uri) 
        QueueHandler.__init__(self, socket) 
 
    def enqueue(self, record): 
        data = json.dumps(record.__dict__) 
        self.queue.send(data) 
 
    def close(self): 
        self.queue.close()

To test this out, put this together into a little test script (imports not shown, but you can get the working script here):

def main(): 
    print('Enter messages to send:') 
    h = ZeroMQSocketHandler('tcp://*:5556') 
    logger = logging.getLogger() 
    logger.addHandler(h) 
    try: 
        while True: 
            s = raw_input('> ') 
            logger.warning(s) 
    finally: 
        logger.removeHandler(h) 
        h.close()

For the receiving end, you can use a simple script like this:

import json 
import pprint 
import zmq 
 
URI = 'tcp://localhost:5556' 
 
def main(): 
    print('Receiving on a SUB socket: %s' % URI) 
    ctx = zmq.Context() 
    sock = zmq.Socket(ctx, zmq.SUB) 
    sock.setsockopt(zmq.SUBSCRIBE, '') 
    sock.connect(URI) 
    try: 
        while True: 
            msg = sock.recv() 
            data = json.loads(msg) 
            pprint.pprint(data) 
            print('-'*40) 
    finally: 
        sock.close() 
 
if __name__ == '__main__': 
    main()

And the output would be something like:

Receiving on a SUB socket: tcp://localhost:5556
{u'args': None,
 u'created': 1284446528.9099669,
 u'exc_info': None,
 u'exc_text': None,
 u'filename': u'zmqlog.py',
 u'funcName': u'main',
 u'levelname': u'WARNING',
 u'levelno': 30,
 u'lineno': 78,
 u'message': u"It's easy to log to ZeroMQ!",
 u'module': u'zmqlog',
 u'msecs': 909.96694564819336,
 u'msg': u"It's easy to log to ZeroMQ!",
 u'name': u'root',
 u'pathname': u'zmqlog.py',
 u'process': 13647,
 u'processName': u'MainProcess',
 u'relativeCreated': 521204.14185523987,
 u'thread': -1215568192,
 u'threadName': u'MainThread'}
----------------------------------------

Using filters to add contextual information to logs

2010-09-13T04:46:00.000-07:00

As an alternative to using LoggerAdapters to add contextual information to logs, you can also use Filters to achieve the same result. This approach has been documented with an example in the in-development Python documentation, here. This functionality has been available since the earliest version of Python logging (i.e. since 2.3) but since the advent of thread-locals in 2.4 it can be used to log thread-local information. This can be used, for example, in an HTTP request handler, to record request-specific information such as client IP address, HTTP method, path, query string etc. in your logs.

Using logging with multiprocessing

2010-09-07T03:07:00.000-07:00

There can be a few gotchas when using logging with the multiprocessing module. For example, if you want to write rotated log files from your multi-process application, a naïve implementation might just configure a RotatingFileHandler directly. This could lead to multiple processes trying to write to the file concurrently, which will almost certainly lead to the log getting corrupted because of interleaved writes by different processes.

Note that logging to the same rotated files from multiple threads in a single-process application would be fine; the logging package uses threading locks to ensure that no log corruption occurs. There's no equivalent cross-platform synhronisation for processes in the stdlib, however; that's why you can get corruption with multi-process applications.

To circumvent the problem scenario, you can use a multiprocessing Queue and a listener process which listens for logging events sent to the queue. When it sees these events, it pops them off the queue and processes them; as it's the only process which will write to files directly, there are no contention issues which lead to corruption. The other processes just need to configure a QueueHandler, which will send logging events via the queue to the listener process.

The plan is to add QueueHandler to Python 3.2, but the implementation here is simple enough and should be copy-pastable into your own code for use with earlier Python versions.

The script is fairly well annotated so I'll say no more.

#!/usr/bin/env python
# Copyright (C) 2010 Vinay Sajip. All Rights Reserved.
#
# Permission to use, copy, modify, and distribute this software and its
# documentation for any purpose and without fee is hereby granted,
# provided that the above copyright notice appear in all copies and that
# both that copyright notice and this permission notice appear in
# supporting documentation, and that the name of Vinay Sajip
# not be used in advertising or publicity pertaining to distribution
# of the software without specific, written prior permission.
# VINAY SAJIP DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS SOFTWARE, INCLUDING
# ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL
# VINAY SAJIP BE LIABLE FOR ANY SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR
# ANY DAMAGES WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER
# IN AN ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT
# OF OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
#
"""
An example script showing how to use logging with multiprocessing.

The basic strategy is to set up a listener process which can have any logging
configuration you want - in this example, writing to rotated log files. Because
only the listener process writes to the log files, you don't have file
corruption caused by multiple processes trying to write to the file.

The listener process is initialised with a queue, and waits for logging events
(LogRecords) to appear in the queue. When they do, they are processed according
to whatever logging configuration is in effect for the listener process.

Other processes can delegate all logging to the listener process. They can have
a much simpler logging configuration: just one handler, a QueueHandler, needs
to be added to the root logger. Other loggers in the configuration can be set
up with levels and filters to achieve the logging verbosity you need.

A QueueHandler processes events by sending them to the multiprocessing queue
that it's initialised with.

In this demo, there are some worker processes which just log some test messages
and then exit.

This script was tested on Ubuntu Jaunty and Windows 7.

Copyright (C) 2010 Vinay Sajip. All Rights Reserved.
"""
# You'll need these imports in your own code
import logging
import logging.handlers
import multiprocessing

# Next two import lines for this demo only
from random import choice, random
import time

class QueueHandler(logging.Handler):
    """
    This is a logging handler which sends events to a multiprocessing queue.
    
    The plan is to add it to Python 3.2, but this can be copy pasted into
    user code for use with earlier Python versions.
    """

    def __init__(self, queue):
        """
        Initialise an instance, using the passed queue.
        """
        logging.Handler.__init__(self)
        self.queue = queue
        
    def emit(self, record):
        """
        Emit a record.

        Writes the LogRecord to the queue.
        """
        try:
            ei = record.exc_info
            if ei:
                dummy = self.format(record) # just to get traceback text into record.exc_text
                record.exc_info = None  # not needed any more
            self.queue.put_nowait(record)
        except (KeyboardInterrupt, SystemExit):
            raise
        except:
            self.handleError(record)
#
# Because you'll want to define the logging configurations for listener and workers, the
# listener and worker process functions take a configurer parameter which is a callable
# for configuring logging for that process. These functions are also passed the queue,
# which they use for communication.
#
# In practice, you can configure the listener however you want, but note that in this
# simple example, the listener does not apply level or filter logic to received records.
# In practice, you would probably want to do ths logic in the worker processes, to avoid
# sending events which would be filtered out between processes.
#
# The size of the rotated files is made small so you can see the results easily.
def listener_configurer():
    root = logging.getLogger()
    h = logging.handlers.RotatingFileHandler('/tmp/mptest.log', 'a', 300, 10)
    f = logging.Formatter('%(asctime)s %(processName)-10s %(name)s %(levelname)-8s %(message)s')
    h.setFormatter(f)
    root.addHandler(h)

# This is the listener process top-level loop: wait for logging events
# (LogRecords)on the queue and handle them, quit when you get a None for a 
# LogRecord.
def listener_process(queue, configurer):
    configurer()
    while True:
        try:
            record = queue.get()
            if record is None: # We send this as a sentinel to tell the listener to quit.
                break
            logger = logging.getLogger(record.name)
            logger.handle(record) # No level or filter logic applied - just do it!
        except (KeyboardInterrupt, SystemExit):
            raise
        except:
            import sys, traceback
            print >> sys.stderr, 'Whoops! Problem:'
            traceback.print_exc(file=sys.stderr)

# Arrays used for random selections in this demo

LEVELS = [logging.DEBUG, logging.INFO, logging.WARNING,
          logging.ERROR, logging.CRITICAL]

LOGGERS = ['a.b.c', 'd.e.f']

MESSAGES = [
    'Random message #1',
    'Random message #2',
    'Random message #3',
]

# The worker configuration is done at the start of the worker process run.
# Note that on Windows you can't rely on fork semantics, so each process
# will run the logging configuration code when it starts.
def worker_configurer(queue):
    h = QueueHandler(queue) # Just the one handler needed
    root = logging.getLogger()
    root.addHandler(h)
    root.setLevel(logging.DEBUG) # send all messages, for demo; no other level or filter logic applied.

# This is the worker process top-level loop, which just logs ten events with
# random intervening delays before terminating.
# The print messages are just so you know it's doing something!
def worker_process(queue, configurer):
    configurer(queue)
    name = multiprocessing.current_process().name
    print('Worker started: %s' % name)
    for i in range(10):
        time.sleep(random())
        logger = logging.getLogger(choice(LOGGERS))
        level = choice(LEVELS)
        message = choice(MESSAGES)
        logger.log(level, message)
    print('Worker finished: %s' % name)

# Here's where the demo gets orchestrated. Create the queue, create and start
# the listener, create ten workers and start them, wait for them to finish,
# then send a None to the queue to tell the listener to finish.
def main():
    queue = multiprocessing.Queue(-1)
    listener = multiprocessing.Process(target=listener_process,
                                       args=(queue, listener_configurer))
    listener.start()
    workers = []
    for i in range(10):
        worker = multiprocessing.Process(target=worker_process,
                                       args=(queue, worker_configurer))
        workers.append(worker)
        worker.start()
    for w in workers:
        w.join()
    queue.put_nowait(None)
    listener.join()

if __name__ == '__main__':
    main()

Using a custom file naming scheme for rotated log files

2010-09-03T02:46:00.000-07:00

When you use rotated log files with Python logging's built-in functionality, the rotated files are named by appending a number to the base log file name: thus, app.log would give rise to log files app.log, app.log.1, app.log.2 etc.

Sometimes, you may not want this: for example, you may want to preserve the file extension so that you can take advantage of file associations (typically on Windows). You can implement a scheme where log file names take the form app.log, app.1.log, app.2.log etc. by subclassing RotatingFileHandler and overriding the doRollover() method. The exact code for this method varies slightly across different versions of Python, so I won't reproduce the whole method, but there's always an if statement in the method which does the rotation. In your overridden method, you can use the following logic (in place of the default logic) to implement an extension-preserving rotation scheme, for example as follows:

if self.backupCount > 0:
    name, ext = os.path.splitext(self.baseFilename)
    for i in range(self.backupCount - 1, 0, -1):
        sfn = "%s.%d%s" % (name, i, ext)
        dfn = "%s.%d%s" % (name, i + 1, ext)
        if os.path.exists(sfn):
            if os.path.exists(dfn):
                os.remove(dfn)
            os.rename(sfn, dfn)
    dfn = "%s.1%s" % (name, ext)
    if os.path.exists(dfn):
        os.remove(dfn)
    os.rename(self.baseFilename, dfn)

Using a custom Formatter to deal with Unicode messages

2010-07-06T10:21:00.000-07:00

Sometimes, you want to use Unicode in messages, and different logging handlers deal with Unicode in different ways. For example, FileHandler allows you to specify an encoding, which is then used to encode Unicode messages to bytes. In Python 2.x, SMTPHandler doesn't do any encoding, which can lead to UnicodeEncodeErrors being raised when smtplib writes the message to a socket.

To avoid this, you can use a Formatter which encodes the message for you, as in the following example:

import logging, logging.handlers

class EncodingFormatter(logging.Formatter):

    def __init__(self, fmt, datefmt=None, encoding=None):
        logging.Formatter.__init__(self, fmt, datefmt)
        self.encoding = encoding

    def format(self, record):
        result = logging.Formatter.format(self, record)
        if isinstance(result, unicode):
            result = result.encode(self.encoding or 'utf-8')
        return result

def main():
    root = logging.getLogger()
    sh = logging.handlers.SMTPHandler(mailhost=('localhost', 25),
                                      fromaddr='vms@test.com',
                                      toaddrs='test@test.com',
                                      subject='Logged Event')
    root.addHandler(sh)
    sh.setFormatter(EncodingFormatter('%(message)s', encoding='iso8859-1'))
    root.error(u'accentu\u00e9')
    
if __name__ == '__main__':
    main()

PEP for logging configuration using dictionaries

2009-10-17T00:33:00.000-07:00

I recently created a PEP to propose a new way of configuring logging, using dictionaries: PEP 391.

How to treat a logger like an output stream

2009-09-24T04:34:00.000-07:00

Sometimes, you need to interface to a third-party API which expects a file-like object to write to, but you want to direct the API's output to a logger. You can do this using a LoggerWriter, which wraps a logger with a file-like API. Here's a short script illustrating the class:

import logging

class LoggerWriter:
    def __init__(self, logger, level):
        self.logger = logger
        self.level = level

    def write(self, message):
        if message != '\n':
            self.logger.log(self.level, message)

def main():
    logging.basicConfig(level=logging.DEBUG)
    logger = logging.getLogger("demo")
    info_fp = LoggerWriter(logger, logging.INFO)
    debug_fp = LoggerWriter(logger, logging.DEBUG)
    print >> info_fp, "An INFO message"
    print >> debug_fp, "A DEBUG message"

if __name__ == "__main__":
    main()

When run, the script prints:

INFO:demo:An INFO message
DEBUG:demo:An DEBUG message

Many thanks to Barry Warsaw for the suggestion.

Python Logging 101

2009-09-14T04:27:00.000-07:00

Introduction

The Merriam-Webster dictionary definition of the verb to log is:

To make a note or record of : enter details of or about in a log

At its most basic, a log is a list of events which may be of interest to someone in the future. In the context of software development, a log is a list of events of interest which occur during execution of an application program. (I use the word events as a synonym for happenings, rather than in the sense of mouse movements or keystrokes.) You can define an event quite simply, by asking the questions

What happened?
When did it happen?
Where did it happen (in which area of the application)?
How important is it?

The first three of these are objective, but the last is subjective. Lots of things happen during program execution, but only some of these are worth recording in a log. Generally, the developers of an application are best placed to decide which events are worth logging, and of their relative importance in the scheme of things.

Typically, logs are read by developers (when tracking down bugs), system administrators (as part of routine monitoring of systems), support desk staff (when dealing with particular support issues), and even end users (when they see an error message). Events that are of interest to one audience may not be interesting to another. The audience might even be dispersed across different geographical locations. A good logging system caters for all of these audiences by allowing:

Developers to easily record events - what happened, when, where and how important it is.
Flexible dissemination of event information to wherever an interested reader (whether human or another program) can read it.
Flexibility of configuration, so that recording of events can be made conditional on where they occurred and how important they are, without changing the application code.

Basic logging of errors to text files and system logs is an old technique, but not very flexible. In this post, I introduce a logging system for the Python programming language. This system, while it borrows ideas from other systems, is not a port of anything but an independent implementation for use by Python developers.The logging package has been part of Python since Python 2.3 (released in 2002).

I'll cover each of the above points - recording events, disseminating events and configuring the system.

Recording events

Recalling that an event was defined above in terms of four dimensions, the following table shows how these dimensions are provided to the logging API.

What happened	This is passed in using a formatting string with optional arguments
When it happened	This is not passed in explicitly. The module assumes that the time you called the logging API was the time of the event.
Where it happened	This is specified in terms of a logging channel or logger name (defined below).
How important it is	This is specified in terms of an integer level (defined below).

Loggers

A logging channel indicates an area of an application. How an area is defined is up to the developer. Since an application can have any number of areas, logging channels are identified by a unique string. Application areas can be nested (e.g. an area of input processing might include sub-areas read CSV files, read XLS files and read Gnumeric files). To cater for this nesting, channel names are organized into a namespace hierarchy where levels are separated by periods, much like Java or Python package namespaces. In the above instance, channel names might be "input" for the upper level, and "input.csv", "input.xls" and "input.gnu" for the sub-levels. Having determined the relevant application area, an application obtains a reference to a logger object, which is specific to a particular channel name:

logger = logging.getLogger("input.xls")

You can call the above code from any module or function, and it will always return a reference to the same logger. This avoids the need to pass logger references between functions. If this is the first call specifying a particular channel name, then a new logger is created and returned to you; the same logger is returned on subsequent calls with that channel name. The namespace hierarchy maps onto an equivalent hierarchy of loggers. The logger named "input.csv" would have a parent logger named "input". There is no requirement to instantiate all the loggers implied by a particular namespace - the system does that as and when needed. At the top of the hierarchy is a root logger which is created automatically, and used like any other logger. Once you have obtained a reference to a logger, you are almost ready to start logging.

Levels

By default, there are five levels of importance associated with logging events. Experience has shown that having more levels is unhelpful, since the choice of which level to assign to an event becomes subjective. The five levels are DEBUG, INFO, WARNING, ERROR and CRITICAL. Their significance is described in the following table.

DEBUG	Detailed information, of no interest when everything is working well but invaluable when diagnosing problems.
INFO	Affirmations that things are working as expected, e.g. "service has started" or "indexing run complete". Often ignored.
WARNING	There may be a problem in the near future, and this gives advance warning of it. But the application is able to proceed normally.
ERROR	The application has been unable to proceed as expected, due to the problem being logged.
CRITICAL	This is a serious error, and some kind of application meltdown might be imminent.

The above categories will cater for most scenarios, though the module allows an application developer to define their own custom levels if they really need to. Using the logging module couldn't be simpler. In any module which uses logging, you simply include the statement

import logging

and you can then log away:

inputLogger = logging.getLogger("input")
csvLogger = logging.getLogger("input.csv")
csvLogger.debug("Trying to read file '%s'" % filename)
csvLogger.warning("File '%s' contains no data", filename)
csvLogger.error("File '%s': unexpected end of file at line %d, offset %d", filename, lineno, offset)
csvLogger.critical("File '%s': too large, not enough memory, amount used = %d", filename, memused)

If you are handling an exception, you can provide for a stack trace to be inserted into the log, as indicated by the three equivalent statements in the following listing. When the logger sees the exc_info argument, it treats it as an indication that traceback information is desirable.

logger.exception("Error reading file '%s' at offset %d", filename, offset)
logger.error("Error reading file '%s' at offset %d", filename, offset, exc_info=1)
logger.log(logging.ERROR, "Error reading file '%s' at offset %d", filename, offset, exc_info=1)

Disseminating events

So far, so good. We've got hold of some loggers, and told them about various events at various levels of importance. What happens to those logged events? That's where handlers come in. Recall that a key component of a good logging system is getting the events to somewhere where interested parties can read them. In today's heterogeneous computing environments, where NT rubs shoulders with UNIX and multiple applications need to work together to deliver complex requirements, there are often requirements for event log information to be available on machines other than where the events were generated.

Handlers allow flexible dissemination of logging events. To see how flexible, the following shows a list of the handlers currently provided with Python logging.

Handler	How it's used
StreamHandler	Used to write to an output stream, typically sys.stdout or sys.stderr
FileHandler	Inherits from StreamHandler to allow writing to a disk file.
RotatingFileHandler	Used for logging to a set of files, switching from one file to the next when the current file reaches a certain size.
TimedRotatingFileHandler	Used for logging to a set of files, switching from one file to the next at specified times.
SocketHandler	Used to send the events, via a socket, to a remote server listening on a TCP port.
DatagramHandler	Similar to SocketHandler, except that UDP sockets are used. There's less overhead but less reliability.
SMTPHandler	Used to send the events to designated e-mail addresses.
SysLogHandler	Used to send the events to a UNIX/Linux syslog.
NTEventLogHandler	Used to send the events to an NT event log.
HTTPHandler	Used to post the events to a Web server.
MemoryHandler	Used to buffer events in memory until a trigger is received, at which point the events are sent to another handler to deal with.
NullHandler	Used in library code which uses logging to avoid misconfiguration messages when used in an application which doesn't configure logging.

These classes inherit from the base classes Handler and BufferingHandler, depending on whether they need to deal with events one at a time or whether they process events in batches.

Handlers are associated with loggers in a flexible way. A logger can have handlers associated with it directly by means of the addHandler method (with a corresponding removeHandler method for dissociation, if required). But not every logger needs to be associated with a handler. This is because whenever a logging event is passed to a logger, the logger and all of its parents are searched for handlers, and ALL these handlers are asked to handle the event. In order to get output from the logging system, all that is needed is that one or more handlers be associated with the root logger, and all loggers will automatically use those handlers.

If no logger has any handlers, the system will indicate this to sys.stderr (as it's assumed to be a misconfiguration) and then keep quiet.

If it is desired for a particular logger that handler search does not propagate to its parents, then the propagate attribute of the logger can be set to 0. If this is done, the search for handlers will stop at that logger and not continue upwards through the hierarchy.

A Handler usage scenario

Suppose you want some events to be brought to the attention of developers, others operations staff, and yet others to the user. Then one way you could go about this is:

Configure an SMTPHandler with a developer email address, configured to pass ERROR events or worse.
Configure an SMTPHandler with a support desk email address, configured to pass CRITICAL events or worse.
Configure a FileHandler to pass all DEBUG events.
Configure your loggers however you want. For example, in production, you can set the topmost logger's level to WARNING, and you'll never see DEBUG messages anywhere. If you find there's a problem with a specific area of the application, you can set the logger for that area to send DEBUG events. Then you will see all events with levels >= DEBUG from that area, but only events with levels >= WARNING from the other areas.

SMTPHandlers are generally used to notify people about problems which need urgent handling. If there's no urgency, then it's appropriate just to configure FileHandlers. It's not uncommon to have one log file for errors only and another log file which also includes DEBUG and INFO events.

Configuring the level of output

Handlers and loggers are all very well, but we need to control the verbosity of output generated by the logging system. When a developer writes an application, they should add logging calls for every conceivable event an audience may be interested in. After all, if they don't do this, those events would never be captured. During application testing, most of these events will probably be logged at some point. However, when the application is shipped, suppose that a bug is reported. No one wants to wade through reams of detail looking for the key pointers to the problem - so the verbosity has to be turned right down across the application. As developers home in on the problem, they would like to be able to turn the verbosity up and down selectively in particular areas, to see what is happening. They should be able to do this without changing the application code in any way.

The most basic form of verbosity control is provided by setting a threshold level on loggers, handlers or both. Both Logger and Handler have a setLevel method which takes a level and associates it with the logger or handler. When a logging call is made, if the logger's threshold is above the level of the call, no event is actually generated. For example, if a logger's threshold is set to ERROR, then debug(), info() and warning() calls on that logger do not generate any events, but error() and critical() do. Similarly, if a handler's threshold is set above the level of an event which is passed to it for handling, the handler ignores the event.

From a performance point of view, it is better to apply thresholds at the logger level than the handler level. However, there may be times when levels must be applied at the handler level to get the desired effect.

There is also an overall, high-level filter which can be applied to all loggers at one stroke. The module contains a function disable() which takes a level argument and acts as a threshold for all loggers. This setting is checked before the logger's own level setting.

Filters

If simple level-based filtering of the kind described above is not enough, then you can instantiate Filter objects and associate them with both loggers and handlers. A filter object has a filter() method which is passed an event and which returns a value indicating whether the event is to be processed. Multiple filters can be associated with loggers and handlers, which both inherit from a base class Filterer having addFilter(), removeFilter() and filter() methods. The Filterer.filter() method calls the filter() method on all attached filters until all have seen the event, or until one of the filters rejects the event. If the event comes through unscathed, it is processed.

LogRecords

In the discussion so far, we have talked in general terms about events. But how is an event represented? In this system, events are described by LogRecord instances. The LogRecord class has minimal functionality, acting as a repository for all the information of interest in an event; its single method getMessage() is intended to provide a hook for converting the message and arguments (passed to it at creation time) into a string representation of the event.

The main information passed in a logging call is the level, a message and arguments for use with that message. All of this information is held in the LogRecord. There is also additional information which the system generates automatically, and all of the information in a LogRecord can appear in the final output from the system. Here's a list of the information currently held in a LogRecord:

Logger name (logging channel - e.g. "input.csv")
Event level (e.g. DEBUG)
Event level text (e.g. "DEBUG")
Pathname of source file from where the logging call was issued
Filename of source file from where the logging call was issued
Line number in source file where the logging call was issued
Name of function from which logging call was issued
Time when the event (LogRecord) was created (as seconds after the epoch)
Millisecond portion of the creation time
Creation time relative to when the logging module was loaded (typically, application startup time)
Thread id (available if threading is available on your platform)
Process id

Message Objects

In the preceding discussion and examples, it has been assumed that the message passed when logging the event is a string. However, this is not the only possibility. You can pass an arbitrary object as a message, and its __str__() method will be called when needed to convert it to a string representation. In fact, if you want to, you can avoid computing a string representation altogether - for example, the SocketHandler emits an event by pickling it and sending it over the wire.

Event Processing

Let's assume that an event has been generated, and needs to be processed. What do I mean by processing? All that's left to do is to format the event appropriately for the target audience, and then output it to the relevant sink.

In almost all cases, this means formatting the event into some form of text string. The actual formatting is done at the last moment, to avoid unnecessary processing. Formatting is controlled through the use of Formatter objects, which are associated with handlers using the setFormatter() method.

Controlling Output Formats

Formatters control the formatting of an event into text. There are two base classes - Formatter (which works on single events) and BufferingFormatter (which works on a set of events, and includes the ability to add header and trailer text). Formatters use Python's powerful % operator (similar to C's sprintf) to format the output flexibly.

Formatters know how a LogRecord is laid out - they know the field names. If you specify a format string such as "%(asctime)s %(level)-5s %(message)s", this would output the time, level of the logging event and the user's message (itself obtained by evaluating msg % args where msg and args were specified by the user).

Formatters are initialized with a format string and an optional date/time format string. The latter is used as an argument to the standard library strftime function. Formatters try to avoid needless processing - for example, the creation time is formatted into text using the date format string only if the main format string contains "%(asctime)s". If exception information is required and available, it is formatted using the standard traceback module and appended to the formatted string. It's also cached for subsequent format operations.

Optimization

Formatting of message arguments is deferred until it cannot be avoided. However, computing the arguments passed to the logging method can also be expensive, and you may want to avoid doing it if the logger will just throw away your event. To decide what to do, you can call the isEnabledFor method which takes a level argument and returns true if the event would be created by the Logger for that level of call. You can write code like this:

if logger.isEnabledFor(logging.DEBUG):
logger.debug("Message with %s, %s", expensive_func1(), expensive_func2())

so that if the logger's threshold is set above DEBUG, the calls to expensive_func1 and expensive_func2 are never made.

There are other optimizations which can be made for specific applications which need more precise control over what logging information is collected. Here's a list of things you can do to avoid processing during logging which you don't need:

You don't want information about where calls were made from.	Set logging._srcfile to None.
You don't want threading information in the log.	Set logging.logThreads to 0.
You don't want process information in the log.	Set logging.logProcesses to 0.

Also note that the core logging module only includes the basic handlers. If you don't import logging.handlers and logging.config, they stay out of your way.

Threading

The logging module doesn't use threads itself, but it ensures that it is thread-safe by using a reentrant lock (threading.RLock) to serialize access to internal data structures, as well as to I/O handlers. Each handler instance gets a reentrant lock, and each operation to emit an event is bracketed with a lock acquisition and release.

Convenience Functions

For casual users of the logging system, or Python novices, it may be too much trouble to create loggers in a namespace hierarchy. For such modes of use, the module defines module level functions debug(), info(), warning(), error() and critical() which delegate to the root logger. If no handler has been configured for this logger, then basicConfig() is called to attach a handler to the root logger. This means that the very simplest use of the logging module is as indicated:

import logging
logging.debug("Here's some %s information about %s", "debugging", "something")
logging.info("Here's some %s", "information")
logging.warn("This is your first %s", "warning")
logging.error("To %s is human", "err")
logging.critical("The situation is getting %s", "critical")
logging.exception("Please add a %s to this message", "stack traceback")

What's with the config stuff?

The configuration system in the logging.config is a very basic implementation of a one-shot configuration, not likely to be of much help in sophisticated usage but providing some value for novice and/or casual users. If you don't want to use it, don't - the entire logging system can be programmatically configured, and if you want you can have your own configuration file format and load that using your own code, making logging API calls to actually do the configing of loggers, handlers etc. The implementation uses ConfigParser (in order to avoid having yet another configuration meta-format) and so the format is more verbose than it could be.