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

[Robert Kern]

If we're all converging on adding a "handler of last resort" and dropping the 
warning message, we can just let this branch of the thread drop. But if you want 
to continue, I already had most of the following already written. I hope it 
clears some things up more than it muddies them further. :-)

On 12/8/10 11:43 AM, Vinay Sajip wrote:
> Robert Kern<robert.kern<at>  gmail.com>  writes:

>> I don't think the warning helps much, if at all.
>
> Perhaps not. I'm not so hung up on the importance of the message now, but it
> certainly *was* important when logging was first introduced, and users couldn't
> expect to get the same level of help on comp.lang.python that they now can.
> Today there are quite a few people who can help people with finger-trouble
> logging issues.

I am not commenting on the reasonableness of the behavior when it was 
introduced, just what I think is the best behavior now.

> Consider the scenarios when not having the current behaviour would bite you:
>
> 1. You're new to Python/new to logging. You write some code, perhaps across
> several modules, which code makes logging calls, but you omit to configure any
> handlers, whether through forgetting or not understanding what needs to be done.
> Without the message, you've no idea why no logging messages appear, no matter
> how much you fiddle with levels.
> 2. You write some code and decide you don't want to use logging, but use some
> third party libraries which do. You don't care about that, so it's annoying to
> have "no handlers could be found for logger XXX" messages printed to console.
> You berate the library developer for their lack of consideration.
>
> Perhaps you don't find yourself in these situations, but surely you sympathize
> with people who do? How would you propose to address both those scenarios?

I am quite familiar with the latter in the third-party library author role. 
However, the messages I get aren't about lack of consideration but "What is 
wrong with my code? Are things broken?" They think the warning comes from my code.

As for the former, I'm not sure how that would cause much confusion. If I'm 
interested in getting the logged information, wouldn't I first find out how to 
configure logging? It's just about the very first thing you see reading the 
docs. It's one of the fundamental operations using the logging package. I can't 
imagine that this is a common failure mode. I think that the documentation 
ameliorates it better than the warning message.

>> In a large package (particularly a namespace package), I can't guarantee
>> that any particular module will get imported. I will want to be able to
>> import just foo.bar.baz without needing to worry about whether
>> foo.setup_logging got imported and ran the logging configuration as a
>> side-effect. I want to be able to loosen the coupling between modules
>> across my package, not add more coupling.
>
> I'm not sure what coupling you're talking about - perhaps you can illustrate
> with an example. If I develop a package "foo.bar" which is part of namespace
> package "foo", and use loggers named __name__ in my code, and add a NullHandler
> to logger "foo.bar", that's all I have to do. Likewise, if another person
> develops "foo.baz" and they add a NullHandler to "foo.baz", then where's the
> coupling between the two packages? They needn't even know about each other.

You were saying (in the part of the conversation that you snipped) that one 
would just add a NullHandler to the "django" logger to take care of messages 
sent to "django.db.models" and all of the other child loggers. *That* introduces 
a tighter coupling than I am comfortable with. All modules that use logging must 
make sure that the code that adds the NullHandler to the "django" logger gets 
executed. It's certainly reasonable to make that effort sometimes, but there are 
good reasons to avoid it, too. Just using logging should not force my hand.

If I do keep things decoupled, then I am adding a NullHandler to nearly every 
logger anyways, and I return to my original point that this is repetitive 
boilerplate and should be eliminated by appropriate defaults.

>> But in any case, while adding a NullHandler to just the package's root logger
>> helps you to avoid needing a NullHandler on every logger, the effect is the
>> same. Almost all loggers effectively terminate in a NullHandler either
>> directly or through a chain of parent loggers. So why not just make it the
>> default?
>
> There's no "termination" when a NullHandler is encountered.

All I meant is that it eventually reaches a NullHandler so no warning message is 
issued. Whether it actually stops there or not is irrelevant to my point. My 
point is that it is rarely the case that you deliberately want to have a logger 
which will cause the “No handlers could be found" message. Whether you add the 
NullHandler to each logger or to one parent logger, you almost always want that 
behavior. That's why I think it should be the default behavior.

> Django has dozens of
> modules, many of which could use logging, but only one NullHandler needs to be
> added for the whole of Django. The effect you say is the same is not: when
> adding new modules to Django, for example, no additional NullHandler adding
> needs to be done.

The "effect" that I am talking about is that the log messages eventually get 
handled by a NullHandler and no warning message about missing handlers is sent. 
I'm not talking about the effect on developer effort.

The only thing adding a NullHandler accomplishes is to silence the warning. I 
think that accomplishing that effect in this manner is bad design. It's not 
obvious, particularly pre-2.7 where you had to roll your own NullHandler. It 
introduces a special case ("library authors should never add Handlers except 
they *should* add a NullHandler").

> I don't want to appear rude, but this seems to be another mistake (or perhaps a
> variant of the same mistake as before) you are making about how logging works.

It seems that I am being particularly unclear in stating my points. You also 
seem to be addressing small errors or misunderstandings in my statements at 
length and ignoring the substantive points. I understand that it is not 
intentional, but it is frustrating.

> You obviously feel strongly about it, and if you have a specific use case which
> is causing/has caused you pain, please spell it out for me (on comp.lang.python,
> say) and I will try to help sort out the problem.

I want to write library code that liberally uses logging. I want to avoid doing 
any configuration of logging in my library code. I do not want users of my 
library code to need to configure logging until they actually want to change the 
(sensible) defaults. Is that clear enough?

>> without configuration but remains completely configurable. Library errors
>> don't pass silently, but logging allows people to silence them explicitly.
>> It separates the concerns of library authors (who should never touch logging
>> configuration and shouldn't be required to think about it) from those of the
>> application authors and application users.
>
> You surprise me with "library authors (who should never touch logging
> configuration and shouldn't be required to think about it)". If you use logging,
> you should think about it at least a little, just as with any other software you
> use. For example, about default levels, propagation, etc. etc. The Django team,
> for example, have expended a reasonable amount of thought on how best to add
> logging support to their library; I don't believe their time has been wasted.

Fair enough. I don't disagree. Please drop "and shouldn't be required to think 
about it" from my statements.

-- 
Robert Kern

"I have come to believe that the whole world is an enigma, a harmless enigma
  that is made terrible by our own mad attempt to interpret it as though it had
  an underlying truth."
   -- Umberto Eco