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

[Vinay Sajip]

Nick Coghlan <ncoghlan <at> gmail.com> writes:

> 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:
> 

You're right that this is missing from the docstrings; I'll rectify that.

> 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.

I don't have a philosophical problem with this, but there might be differing
opinions about this not just on python-dev but also in the wider community. I'd
definitely want logging to do the right thing and minimize inconvenience as much
as possible. There's also possibly a backwards compatibility dimension to this,
but I'm not sure to what extent a change like this would really affect people in
practice (as nothing will change if logging is configured).

> 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.
> 

Thanks for the detailed explanation. I agree that unraisable warnings and errors
need to be handled somehow. There is a way in which this can be done without
affecting a logging configuration, viz. logging can define a "handler of last
resort" (not attached to any logger) which is invoked when there are no
user-specified handlers. This would by default be a StreamHandler writing to
sys.stderr with a threshold of WARNING (or perhaps ERROR). Thus sounds like a
better option than a direct write to sys.stderr, since you can't change the
latter behaviour easily if you want to do something else instead.

This is of course a backwards-incompatible change to logging semantics: instead
of saying that logging will be silent unless explicitly asked to produce output,
we're saying that logging will always produce output for warnings and errors (or
perhaps just errors), unless explicitly silenced. This is of course in line with
the Zen of Python; the present behaviour, which is not so aligned, is based on
the idea that logging should not affect program behaviour if it's not wanted by
the program developer (as opposed to library developer).

It would also mean changing the documentation about NullHandler to say: "If you
have messages which must get out when you can't raise an exception, then don't
add a NullHandler to your top-level loggers."

Regards,

Vinay Sajip