[Python-Dev] Using logging in the stdlib and its unit tests (original) (raw)

Nick Coghlan ncoghlan at gmail.com
Sat Dec 11 06:06:20 CET 2010

On Sat, Dec 11, 2010 at 12:42 PM, Terry Reedy <tjreedy at udel.edu> wrote:

On 12/10/2010 5:16 PM, Vinay Sajip wrote:

IMO as long as it's just a small amount of work to get the specific effect that you want, it doesn't really matter too much what the default is - though of course I'd like it to be "right", whatever that means ;-) I think the default should accomodate both internal uses (stdlib and elsewhere) and beginner uses. I suspect the latter would mean outputting most everything, to the convenience functions work (as a beginner might expect).

I think the main point of confusion is going to be what happens to .info() messages by default.

With Vinay's latest changes, the 3.2 default is going to be:

debug() -> /dev/null info() -> /dev/null warning() -> stderr error() -> stderr critical() -> stderr exception() -> stderr

This will apply both to the convenience functions (where this is already the case due to the implicit basicConfig() call and the default level setting on the root logger) and to logger methods (where the new "handler of last resort" will apply instead of emitting the comparatively unhelpful "no handler found" error message).

This is the correct behaviour for library code and even many applications - silent when all goes well, but if anything goes wrong that can't be flagged with an exception, the errors are displayed by default. While Vinay is right that inertia plays a large part in not using the logging module in the standard library, the new behaviour for direct calls to loggers is a direct result of a problem encountered in the concurrent.futures tests due to the fact that Brian previously couldn't rely on an unconfigured logging module doing the right thing.

However, the confusion that this setup will engender is that encountered by Bill: by default, info() messages are silenced rather than displayed on stdout.

Notice that even the recommended "basicConfig" approach to resolving this is subtly flawed, since your choices are to either display info messages on stderr (by specifying just a level argument) or to redirect warning() et al to stdout instead of stderr (by also specifying a stream argument). The "correct" answer (info and below to stdout, warning and above to stderr) is actually quite tricky to set up, since handlers have no innate concept of a "maximum level", so you have to provide a filter function (more on that below [1]).

Basically, as of 3.2, the correct "default" use is likely to be:

print() for information you want to appear on stdout by default (especially in scripts) logging.debug() and .info() for additional debugging information that should be silenced by default

warnings.warn() for actual programmatic warnings that should obey warning filter rules (logging can hook the warnings display mechanism) logging.warn() for warnings that should never raise an exception and should be emitted every time they are encountered

raise an exception for normal error reporting logging.error(), .critical() and .exception() for error reporting that cannot raise an exception for some reason (e.g. long running processes that are simply recording that an exception occurred)

Libraries can now safely use their own getLogger(name) loggers for the latter two uses without worrying about the output being lost by the default logging configuration, so they become a much better option than printing directly to sys.stderr. Most importantly, someone debugging the app will be able to insert additional context information (e.g. stack traces, local variables values) without needing to alter the code emitting the error message.

Regards, Nick.

[1] As an exercise, I decided to actually configure recommended console logging output style via the logging module. It proved to be quite informative as to where some of the flaws in the current documentation lie.

First and foremost, it was genuinely hard for me to figure out that one of my key problems was actually that the root logger is created with a level of WARNING by default so my handlers weren't even being invoked. The only place I found this very important detail was in the documentation of Logger.setLevel()! There really should be a section early on in the logging documentation describing the root logger, how to use it for basic logging, and its default settings (with and without a call to "basicConfig"). Such a section would then include a link to the latter section on the logging heirarchy.

In addition to that, the documentation of the LogRecord class should really include a table of attribute names that are available for use in formatting and filtering. Initially I thought the attribute names corresponded to the parameter names, and subsequently resorted to a dir() call in my filter to figure out what the actual names were after "lvl" caused an AttributeError. Armed with the fact that the attribute I wanted was called "levelno", I was able to discover the list of LogRecord attributes was actually in the Formatter documentation. If a proper list of attributes was added to the LogRecord documentation, then the current table in the formatting section could be removed and replaced with a reference to the table of attributes and some notes on formatting (when the documentation for the new styles feature goes in would probably be an appropriate time to fix this). Similarly, the section on filters could point directly to that table when describing possible filtering criteria.

Anyway, the shortest way I could find of setting this up (debug silenced, info written to stdout, warning and above written to stderr):

import sys, logging root = logging.getLogger()

Turns out the level of the root logger is set to WARNING by default

That should be much easier to find out from the logging docs!

root.setLevel(logging.DEBUG)

Send WARNING and above to stderr

basicConfig() is no help, since it sets the specified level on the

root logger

but NOT on the default handler it installs. To emulate console output

we want to skip the formatting anyway.

err = logging.StreamHandler() err.setLevel(logging.WARNING) root.addHandler(err)

Send INFO to stdout

def is_info(record): return record.levelno == logging.INFO out = logging.StreamHandler(stream=sys.stdout) out.addFilter(is_info) root.addHandler(out)

Cheers, Nick.

-- Nick Coghlan   |   ncoghlan at gmail.com   |   Brisbane, Australia

More information about the Python-Dev mailing list