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

Nick Coghlan ncoghlan at gmail.com
Wed Dec 8 08:28:34 CET 2010

On Wed, Dec 8, 2010 at 11:51 AM, Vinay Sajip <vinay_sajip at yahoo.co.uk> wrote:

Nick Coghlan <ncoghlan 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

More information about the Python-Dev mailing list