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

[Nick Coghlan]

On Wed, Dec 8, 2010 at 11:51 AM, Vinay Sajip <vinay_sajip at yahoo.co.uk> wrote:
> Nick Coghlan <ncoghlan <at> gmail.com> writes:
>
>> Indeed - I was very surprised to find just now that calling
>> "logging.warn('Whatever')" is not the same as doing "log =
>> logging.getLogger(); log.warn('Whatever')".
>
> Don't know why you'd be surprised: it's been that way since logging was added to
> Python, and the logging.debug() etc. are documented as convenience methods for
> casual use in throwaway scripts, interactive sessions etc. The convenience is in
> that you don't need to specify a logger (the root logger is used) and that
> basicConfig() is called for you.

I've previously only used logging as an application author, hence I
hadn't noticed some of the subtleties that come up when using logging
in library code where you don't control which handlers are going to be
installed at runtime.

The surprise came from not realising there was a basicConfig() call
hidden inside the convenience APIs, a fact which is *not* mentioned in
the docstrings. It may be mentioned in the main documentation, but I
didn't look at that at the time - there was nothing to suggest the
docstrings were lacking pertinent information:

>>> print(logging.warn.__doc__)

    Log a message with severity 'WARNING' on the root logger.

>>> print(logging.getLogger().warn.__doc__)

        Log 'msg % args' with severity 'WARNING'.

        To pass exception information, use the keyword argument exc_info with
        a true value, e.g.

        logger.warning("Houston, we have a %s", "bit of a problem", exc_info=1)

>> So my suggestion would be:
>> 1. In the absence of a "config" call, make the "no handler" path in
>> loggers emit messages *as if* basicConfig() has been called (without
>> actually calling it)
>> 2. Remove the implicit calls to basicConfig() from the module level
>> convenience function
>>
>> How *feasible* that idea is to implement, I don't know.
>>
>
> What about "Special cases aren't special enough to break the rules."? Why should
> logging from stdlib modules be treated differently from the case of logging from
> library modules in general? It could be argued that the behaviour you're
> proposing is confusing/inconsistent to some people.

I'm not proposing that the standard library be special-cased, I'm
proposing that the default behaviour of an unconfigured logging module
in general be changed to something more useful (i.e. warnings and
errors printed to stderr, everything else suppressed), rather than
unhelpfully suppressing *all* output except for an "Oh, I'm throwing
output away" message the first time it happens.

The specific use case that triggered my interest in this default
behaviour is one where concurrent.futures *can't* raise an exception
because it knows nothing is going to be in a position to handle that
exception (due to the way callbacks are handled, c.f knows it provides
the outermost exception handler in the affected call stack). Instead
it has to catch the error and display it *somewhere* (i.e. it's very
similar to the use cases for PyErr_WriteUnraisable at the C level).

The options for handling this are:

1. Write the error detail directly to stderr. (Unless the default
behaviour of logging changes, that is what I am going to suggest Brian
do, as it exactly mimics the behaviour of the PyErr_WriteUnraisable
API).
2. Write it to the root logger with the convenience APIs (Possible
option, but I don't like the global state impact of implicitly calling
basicConfig() from library code)
3. Add a StdErr handler for the logger (this is what is currently
implemented, and again, I don't like it because of the global state
impact on something that should be completely under an application's
control)

Basically, the current behaviour of logging is such that libraries
*cannot* use it for unraisable warnings and error messages, as the
messages will be suppressed unless the application takes steps to see
them. That is OK for debug and info messages, but unacceptable for
warnings and errors. A throwaway script using concurrent.futures needs
to know if callbacks are failing, and that needs to happen without any
logging related boilerplate in the script itself.

If, however, an application completely lacking even a call to
logging.basicConfig() would still see warnings and errors, then
libraries could safely use the module without needing to worry about
applications needing an particular boilerplate in order to see the
unraisable errors and warnings that are emitted.

Regards,
Nick.

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