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!

score 20 · Answer 1 · edited Nov 13 '15 at 23:35

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

Thank you Mihai. I thought I was going to have more time to look into it but I'll need to wait for the weekend. So far I've been able to make my class that does it all (attaching formatters, handlers and setting loglevel) work by defining log as a getLogger object in the submodule.py. I was hoping this could be done without putting things outside of the class definition. My question was more of "why certain approaches I've made did not work as expected as I'd like to understand the reason behind it, as opposed to getting a code handed over to me, but I do appreciate your help :) — Marcin Kaminski, Apr 10 '13 at 01:27
I updated my answer. Other then that you can look in the module's code. You can see that root logger is instantiated during the import. I also don't really understand why getLogger("root") doesn't work the same in all situations (you can do getLogger() in app.py and getLogger("root") in submodule.py and you get what you need, but not vice-versa). — Mihai, Apr 10 '13 at 14:15
How to make it work with stdout redirect to file e.g. python ./app.py >> file.log ? — Edijs Petersons, Apr 14 '16 at 11:37
This does not work on windows.I can get it to write to file, but it is not really redirecting. It will write to both file and stdout: logging.getLogger('root').addHandler(logging.StreamHandler(sys.stdout)) — Edijs Petersons, Apr 15 '16 at 06:46

Python: custom logging across all modules

1 Answers1

Linked