[Python-Dev] Using logging in the stdlib and its unit tests

[Nick Coghlan]

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