Mysterious Logging Handlers

[Josh English]

I have a Python script that imports a utility script. Both scripts use logging, but the logs don't work as advertised. I'm getting logging output from the utility script but none from the main file. Worse, the format of the utility script's logs don't match anything I define.

The utility script is called xlreader.py. It has the following lines:

-- begin snippet --
import logging
XLOGGER = logging.getLogger('XLREADER')
-- end snippet --

And it calls XLOGGER.debug(), XLOGGER.error() and XLOGGER.info() but it never defines a handler.


The main script imports xlreader but does not reference XLOGGER. It defines its own logger:

-- begin snippet --
import logging
import xlreader

LOG = logging.getLogger('SHIPPING')
FORMAT = '%(asctime)-15s %(name)s %(level)-8s %(message)s'
logging.basicConfig(format=FORMAT,level=logging.DEBUG)
handler = logging.StreamHandler()
formatter = logging.Formatter(FORMAT)
handler.setFormatter(formatter)
LOG.addHandler(handler)
-- end snippet --

I added the logging.basicConfig line but it didn't have any effect. I created the second handler separately.

When I run the scriptI get logging information from only xlreader, not from the main script:

DEBUG:XLREADER:Creating Excel Reader

This format isn't defined anywhere. T

Even more mysterious, after I run the file (in an IDE so I have a REPL afterwards), I have:

>>> XLOGGER
>>> <logging.Logger at 0x981a208>

>>> XLOGGER.handlers
>>> []

>>> XLOGGER.debug('test')
>>> DEBUG:XLREADER:test

>>> LOG.handlers
>>> [<logging.StreamHandler at 0x97e3c88>, <logging.StreamHandler at 0xb2954e0>]

>>> [h.formatter._fmt for h in LOG.handlers]
>>> ['%(asctime)-15s %(name)s %(level)-8s %(message)s',
 '%(asctime)-15s %(name)s %(level)-8s %(message)s']

How can I track where this formatting is coming from?

Josh