Logging in Python

There's hardly any docs about this (apart from the way over-detailed
no-wood-for-the-trees library docs), but it turns out Python does have a
good (but broken!) logging system.

Motivated by my experience with Java logging I want:
- An external config that lets me control the level and location of messages
- Logging that is identified with modules, for easy filtering
  (module level is simpler than class level - see below - except that
  it tickles a bug, apparently)

And this is how I do it:

When the app starts, it calls

import logging
import logging.config
import sys
from acooke.util.path import sys_path_find
def init_log(name):
    try:
        path = sys_path_find(name)
        logging.config.fileConfig(path)
        log = logging.getLogger(__name__)
        log.info('Configured logging from %s' % path)
    except:
        logging.exception('Failed to start logging: %s: %s'
                          % sys.exc_info()[:2])
        logging.warning('Will use default logging configuration')
        logging.warning('To fix this, put configuration in %s on $PYTHONPATH'
                        % name)

where sys_path_find runs through the system path looking for the named
file.  This loads the config, which is then accessed within modules as:

from acooke.util.log import Log
log = Log(__name__)

class Foo(object):
    def foo(self):
        log.debug("My debug message")

Which generates a log message associated with the module name.  You would
expect this to look like:

import logging
log = logging.getLoger(__name__)

but that doesn't work.  Instead, the Log class above lazily resolves the
logger instance so that creation happens *after* the configuration
described above has occurred.

class Log(object):
    def __init__(self, name):
        super(Log, self).__init__()
        self._name = name
        self._lazy = None
    def __getattr__(self, key):
        if not self._lazy:
            self._lazy = logging.getLogger(self._name)
        return getattr(self._lazy, key)

And finally, here's a typical config.  I send everything to the same
handler (syserr) with the same format, but i define three different
loggers.  One handles everything from modules in the "dbmac.*" tree (the
application), another handles modules in the "acooke.*" tree (libraries)
and a thrird is a catch all for anything else ("root" is a reserved name).


[loggers]
keys=root,dbmac,acooke

[handlers]
keys=common

[formatters]
keys=common

[logger_root]
# configure level for system logs (if any) here
level=NOTSET
handlers=common

[logger_dbmac]
# configure level for main application here
level=DEBUG
propagate=0
qualname=dbmac
handlers=common

[logger_acooke]
# configure level for acooke libraries here
level=DEBUG
propagate=0
qualname=acooke
handlers=common

[handler_common]
level=NOTSET
class=StreamHandler
args=(sys.stderr,)
formatter=common

[formatter_common]
class=logging.Formatter
datefmt=
format=%(asctime)s [%(levelname)9s %(name)-30s] %(message)s

Typical log output looks like:

2008-04-26 08:54:44,209 [     INFO acooke.util.log               ]
Configured logging from
/home/andrew/projects/personal/src/python/dbmac/dbmac/src/dbmac.ini
2008-04-26 08:54:49,224 [    DEBUG acooke.wx.validators          ] Engine
:= 789
2008-04-26 08:54:49,224 [    DEBUG acooke.wx.validators          ] Name :=
789

Andrew
Comment on this post