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: 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
    

