Introspect Python logging with logging_tree

The problem

We wanted to add some logging to our CherryPy application, so — as a simple first step — we grabbed the root logger '' and tried writing a message:

import cherrypy
import logging

log = logging.getLogger('')

class HelloWorld:
    def index(self):
        log.error('Test message')
        return 'Hello world!'
    index.exposed = True

if __name__ == '__main__':
    cherrypy.quickstart(HelloWorld())

The result was disappointing. The site displayed Hello world! in the browser and produced a standard Apache log message, but our own log message was nowhere to be seen. I knew enough about logging to know that a root handler was necessary if I wanted output, so I tried adding one:

...
if __name__ == '__main__':
    log.addHandler(logging.StreamHandler())
    cherrypy.quickstart(HelloWorld())

The result was rather bizarre. While our Test message appeared in the output, the server now produced two copies of every CherryPy log message.

It was at this point that, tired of trying to guess how the logging tree looked by searching our entire code base for calls to the logging package — and searching the code of our third-party libraries, like CherryPy — I instead wrote the first version of logging_tree() so that I could really see what was going on. You can install it quite simply, and it supports any version of Python from 2.3 through 3.2:

pip install logging_tree

Invoking it from your application can be as simple as:

import logging_tree
logging_tree.printout()

These two lines, added to my index() method, printed the entire logger configuration to my terminal the next time I reloaded the page.

Interpreting a tree

This CherryPy application actually produces a more complicated logging situation than in the simplified tree used for illustration at the top of this post. Here is what logging_tree really prints out — in a few places I have used ellipses to keep lines within the margins of my blog, but this time no lines are omitted:

<--""
   Level WARNING
   Handler Stream <open file '<stderr>', mode 'w' at ...>
   |
   o<--[cherrypy]
       |
       o<--"cherrypy.access"
       |   Level INFO
       |   Handler <cherrypy._cplogging.NullHandler object at 0x...>
       |   Handler Stream <open file '<stdout>', mode 'w' at ...>
       |   |
       |   o<--"cherrypy.access.166457196"
       |       Level INFO
       |       Handler <cherrypy._cplogging.NullHandler object at 0x...>
       |
       o<--"cherrypy.error"
           Level INFO
           Handler <cherrypy._cplogging.NullHandler object at 0x...>
           Handler Stream <open file '<stdout>', mode 'w' at ...>
           |
           o<--"cherrypy.error.166457196"
               Level INFO
               Handler <cherrypy._cplogging.NullHandler object at 0x...>

Loggers that have been created through actual calls to getLogger() are displayed with their names in double quotes. When a logger only exists by implication, but has never actually been named in a getLogger() call — like the [cherrypy] node — then its name is shown in square brackets.

Each logger displays its own Level that, as discussed above, is only consulted when a message is submitted directly to that logger using one of its methods like log() or error().

Propagation is turned on for all of these loggers, as shown by the <-- arrows that connect each logger to its parent.

You can see that this tree includes both built-in handlers and also some custom ones defined in the CherryPy framework. The logging_tree package tries to introspect the built-in handlers to give you more information about them — here, it displays the particular output files to which the stream handlers will be printing — but for the CherryPy loggers it has no choice but to simply print their repr() and hope that you can make sense of them.

Solving the problem

Thanks to this diagram, the problem is now clear: because propagation is turned on, CherryPy logging messages get printed by their own handlers and also by the new handler we have installed at the root. You can see this by imagining a new cherrypy.access error message and following the propagation arrows that will take it from its logger-of-origin up to the root, where our own handler is installed.

We can see, in fact, that CherryPy creates several loggers to receive its Apache-style logging messages, and goes ahead and suits those loggers up with handlers that write the messages to the correct files. Since I ran this application in debug mode from the command line, these handlers are directed at <stdout> instead of actual log files.

The solution to my problem was to simply turn off propagation, since CherryPy's handlers were already taking care of its messages:

logging.getLogger('cherrypy').propagate = False

The logging_tree package makes it very clear when propagation has been turned off, both by removing the <-- arrow from next to the logger's name, and also with a Propagate OFF message. So this is how the tree looked following the fix:

<--""
   Level WARNING
   Handler Stream <open file '<stderr>', mode 'w' at ...>
   |
   o   "cherrypy"
       Propagate OFF
       |
       ...

I hope that logging_tree proves useful for many more Python programmers as we all wrestle with logging misbehavior! The package is available both on the Python Package Index and is also available as a project on GitHub if you want to contribute.