Python: custom logging across all modules

Question

Task

I have a collection of scripts and I'd like them to produce unified logging messages with minimum alterations to modules doing logging the actual messages.

I've written a small module 'custom_logger' which I plan to call from the main application once, have it return a logger, which I'd then continue using.

The submodules I'd be importing into the app should only (or rather I wish them to)

• should only "import logging as log" - so that nothing specific to my site is required to make them just run if someone else finds them useful.
• should just log messages with log.info/error('message') without adding anything site-specific to them
• should use the already configured 'root' logger with all its formatting and handers and not affect the root logger's configuration

*custom_logger.py*

import logging
import logging.handlers
import os
import sys


def getLogger(name='root', loglevel='INFO'):
  logger = logging.getLogger(name)

  # if logger 'name' already exists, return it to avoid logging duplicate
  # messages by attaching multiple handlers of the same type
  if logger.handlers:
    return logger
  # if logger 'name' does not already exist, create it and attach handlers
  else:
    # set logLevel to loglevel or to INFO if requested level is incorrect
    loglevel = getattr(logging, loglevel.upper(), logging.INFO)
    logger.setLevel(loglevel)
    fmt = '%(asctime)s %(filename)-18s %(levelname)-8s: %(message)s'
    fmt_date = '%Y-%m-%dT%T%Z'
    formatter = logging.Formatter(fmt, fmt_date)
    handler = logging.StreamHandler()
    handler.setFormatter(formatter)
    logger.addHandler(handler)

    if logger.name == 'root':
      logger.warning('Running: %s %s',
                     os.path.basename(sys.argv[0]),
                     ' '.join(sys.argv[1:]))
    return logger

Then comes the submodule which has a few test messages with examples of what works and what doesn't.

submodule.py

import sys
import custom_logger
import logging


class SubClass(object):

  def __init__(self):
    # NOK (no idea why since by default (no name parameter), it should return the root logger)
    #log = logging.getLogger()
    #log.info('message from SubClass / __init__')

    # OK (works as expected)
    #log = logging.getLogger('root')
    #log.info('message from SubClass / __init__')

    # OK (works as expected)
    log = custom_logger.getLogger('root')
    log.info('message from SubClass / __init__')


  def SomeMethod(self):
    # OK but I'd have to define `log` for every method, which is unacceptable
    # Please see question below all code snippets
    log = custom_logger.getLogger('root')
    log.info('message from SubClass / SomeMethod')

And the main app: app.py Nothing special here:

#!/usr/bin/python

import custom_logger
import submodule

log = custom_logger.getLogger('root', loglevel='DEBUG')

log.debug('debug message')
log.info('info message')
log.warning('warning message')
log.error('error message')

a = submodule.SubClass() # this should produce a log message
a.SomeMethod()           # so should this

Output that I'm after and that I'm getting, just in an exteremely ugly way:

% ./app.py 
2013-04-08T03:07:46BST custom_logger.py   WARNING : Running: app.py 
2013-04-08T03:07:46BST app.py             DEBUG   : debug message
2013-04-08T03:07:46BST app.py             INFO    : info message
2013-04-08T03:07:46BST app.py             WARNING : warning message
2013-04-08T03:07:46BST app.py             ERROR   : error message
2013-04-08T03:07:46BST submodule.py       INFO    : message from SubClass / __init__
2013-04-08T03:07:46BST submodule.py       INFO    : message from SubClass / SomeMethod

I want to be able to define a logger in the app.py and then in the submodules only use the standard Python logging library to make use of an already configured logger in the app.py.

Also, an ugly workaround: if I place the below code after the imports in submodule.py:

log = custom_logger.getLogger('root')

it will be executed before my logger is configured in app.py, effectively making the submodule, not my app configure logging.

Another workaround I considered: within the constuctor of the SubClass class, I could define

self.log = custom_logger.getLogger('root')

and then use self.log.error('some error'). There must be a nicer way - if you can suggest something useful or point out where I misunderstood the documentation, I'd be very grateful!

PS. I've spent quite a bit reading the Python logging howto (basic and advanced) and the cookbook so if I've missed something useful there, please point it out.

Thank you!

Answer 1

If you want to change root logger you could just use getLogger() everywhere, with no arguments.

Regarding the instance setup only in the main module, you can instantiate your logger, add your own Handler, and use it in all the other submodules (as I did bellow).

I created a class that inherits the StreamHandler in custom_logger.py:

class MyHandler(logging.StreamHandler):

    def __init__(self):
        logging.StreamHandler.__init__(self)
        fmt = '%(asctime)s %(filename)-18s %(levelname)-8s: %(message)s'
        fmt_date = '%Y-%m-%dT%T%Z'
        formatter = logging.Formatter(fmt, fmt_date)
        self.setFormatter(formatter)

Then, in submodule.py, I put the getLogger after the imports and commented it in the methods:

import sys
import logging

log = logging.getLogger('root')

class SubClass(object):

    def __init__(self):
         log.info('message from SubClass / __init__')

    def SomeMethod(self):
        log.info('message from SubClass / SomeMethod')

Then, in app.py I created a Logger instance (that will be the same in all modules) and added my handler, which formats the output:

#!/usr/bin/python

import logging
import custom_logger
import submodule

log = logging.getLogger('root')
log.setLevel('DEBUG')
log.addHandler(custom_logger.MyHandler())

log.debug('debug message') 
log.info('info message')
log.warning('warning message')
log.error('error message')

a = submodule.SubClass() # this should produce a log message
a.SomeMethod()           # so should this

Output:

./app.py 
2013-04-08T15:20:05EEST app.py             DEBUG   : debug message
2013-04-08T15:20:05EEST app.py             INFO    : info message
2013-04-08T15:20:05EEST app.py             WARNING : warning message
2013-04-08T15:20:05EEST app.py             ERROR   : error message
2013-04-08T15:20:05EEST submodule.py       INFO    : message from SubClass / __init__
2013-04-08T15:20:05EEST submodule.py       INFO    : message from SubClass / SomeMethod