On Tue, 7 Dec 2010 22:04:36 +0100 Łukasz Langa wrote:

Wiadomość napisana przez Antoine Pitrou w dniu 2010-12-07, o godz. 21:50:

...

If any library defining a logger must also add a NullHandler just in case, ISTM that complicates a lot the use of logging (and could explain its impopularity). Both for library writers and application writers, apparently (since the former will have to add the NullHandler, and the latter will have to override it so that error messages get printed out rather than lost).

ISTM that the stdlib is a special case here. If you're writing an application then the "No handlers could be found" message is actually useful because there's hardly any reason no to include one.

Why do you say that? Not having to add a handler is certainly useful when you are doing some quick prototyping or simply writing a script (situations in which you still want to get error messages displayed properly by the libraries).

One way or the other, we should really default to the convenience of application developers. This is currently the case.

Why wouldn't there be a default convenience of printing out errors? It's already the case for the root handler, so why would other handler be treated differently?

...

...

import logging logging.debug("foo") logging.error("bar") ERROR:root:bar

Thanks Antoine.

Antoine Pitrou writes:

I thought "error" and "critical" messages were logged to stderr by default? Isn't it the case?

Only if you call basicConfig() or use the logging.debug(), logging.info(), etc. module-level convenience functions (which call basicConfig under the hood).

If any library defining a logger must also add a NullHandler just in case, ISTM that complicates a lot the use of logging (and could explain its impopularity). Both for library writers and application writers, apparently (since the former will have to add the NullHandler, and the latter will have to override it so that error messages get printed out rather than lost).

No - the application developer doesn't have to do anything special. Adding the NullHandler is only needed for the top-level logger of a library package, so it's hardly more onerous than doing an import. It doesn't complicate anything, as far as I can see. It's to be done once per library, and trivial in comparison with all the work needed to develop, test, and package a library. For the stdlib, for example, if we were to standardize and say that all stdlib loggers were to be located below the "py" namespace, then I could put the relevant NullHandler-adding code in the logging package and no other stdlib maintainer would have to do anything other than name their stdlib loggers beginning with "py." (e.g. "py.concurrent.futures") for things to work as expected. If you don't like "py", then pick "std", "stdlib" or whatever. When is the NullHandler needed? Only for cases where an application developer uses a library which does logging under the covers (for those users who might be interested in logging its operations), but where that application developer doesn't use logging themselves for that application. In such a case, a library call which generated a logging event would cause logging to look for handlers, and if one is not found, print that one-off "no handlers could be found for logger XXX" message. This message is there because errors should not pass silently; but in the case of an application developer oblivious of logging who uses a library which uses logging under the hood, you can't argue that that developer has made any error. So the library developer, by adding a NullHandler, can improve things for their users by not forcing them to configure logging handlers (in order to avoid the message). #mylib.py import logging logger = logging.getLogger(__name__) logger.addHandler(logging.NullHandler()) def func(): logger.warning('Something happened!') #myapp.py import mylib mylib.func() If you run myapp.py, no message is printed. If you comment out the "addHandler" line and re-run, then you see No handlers could be found for logger "mylib" which is the misconfiguration message. With the line commented back in, you as an application developer get expected behaviour (no spurious messages about missing handlers). When you decide to use logging in myapp.py, simply insert import logging logging.basicConfig() before calling mylib.func(), and you get WARNING:mylib:Something happened! which is what you would expect. Regards, Vinay Sajip

On Wed, Dec 8, 2010 at 10:09 AM, Antoine Pitrou wrote:

On Tue, 7 Dec 2010 23:45:39 +0000 (UTC) Vinay Sajip wrote:

...

Antoine Pitrou writes:

...

I thought "error" and "critical" messages were logged to stderr by default? Isn't it the case?

Only if you call basicConfig() or use the logging.debug(), logging.info(), etc. module-level convenience functions (which call basicConfig under the hood).

Why wouldn't it be the default for all logging calls ? Such special cases don't really make things easy to remember.

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')". Adding a NullHandler isn't the right thing to do - the behaviour I would want for any standard library logging that hasn't been explicitly configured otherwise is to do what the root logger does under basicConfig(): debug() and info() get suppressed, warn(), error(), critical() and exception() go to stderr. It seems to me like that would be more useful default behaviour in general than emitting a warning about not finding a handler. 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. Cheers, Nick. -- Nick Coghlan   |   ncoghlan@gmail.com   |   Brisbane, Australia

On Wed, Dec 8, 2010 at 11:51 AM, Vinay Sajip wrote:

Nick Coghlan 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@gmail.com   |   Brisbane, Australia

On Wed, Dec 8, 2010 at 6:32 PM, Vinay Sajip wrote:

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

A "handler of last resort" is exactly the kind of concept I had in mind. Just not expressed quite so succinctly :)

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.

Yeah, this is why I can understand Brian's desire to use the logging module rather than a direct write to stderr in the futures implementation.

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

Libraries that write directly to stderr affect program behaviour as well - at least with logging, the application developer will have an easier time of silencing (or redirecting) them. Also, in situations where this default handler will be used, logging currently produces output at least once (the warning that it couldn't find a handler to use). So while it is a behavioural change, it is one that should be acceptable from a compatibility point of view.

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

Agreed. We could also make it easy to replace the handler of last resort so people can easily recover the old behaviour (by inserting NullHandler in place of the default last resort handler). Cheers, Nick. -- Nick Coghlan   |   ncoghlan@gmail.com   |   Brisbane, Australia

On Wed, 8 Dec 2010 01:51:44 +0000 (UTC) Vinay Sajip wrote:

...

Adding a NullHandler isn't the right thing to do - the behaviour I would want for any standard library logging that hasn't been explicitly configured otherwise is to do what the root logger does under basicConfig(): debug() and info() get suppressed, warn(), error(), critical() and exception() go to stderr. It seems to me like that would be more useful default behaviour in general than emitting a warning about not finding a handler.

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

Well, it seems we are asking to remove the special cases, since we are asking for the special case to become the norm. Antoine.

Gregory P. Smith writes:

Hahaha. :)  Well, I won't be suggesting to anyone at work that we throw away our entire bazillion line codebase just because all of it happily relies on logging.{debug,info,warn,error,exception} functions and all log messages go through a single root logger.

That's a perfectly valid way of using logging: if the convenience functions suit your needs, there's no need to use anything else.

I'd argue that anyone using a multi-logger hierarchy has already implemented overkill and that the default for anyone wanting to log something should be to simply call the above functions directly from the logging module.

Some people need the logger hierarchy and it's there for them, but no-one is forced to use it.

This simplistic easy usage somewhat echo's Glenn's comment on this thread

about logging seeming way to daunting as presented today.  It needn't be.

Indeed, and the very first code sample in the logging documentation shows exactly the simplistic easy usage you're talking about. I can't see why anyone would be scared off by that example. Regards, Vinay Sajip

Glenn Linderman wrote:

On 12/10/2010 12:06 AM, Vinay Sajip wrote:

...

...

...

This simplistic easy usage somewhat echo's Glenn's comment on this thread about logging seeming way to daunting as presented today. It needn't be.

Indeed, and the very first code sample in the logging documentation shows exactly the simplistic easy usage you're talking about. I can't see why anyone would be scared off by that example.

It didn't scare me off. But it wasn't _quite_ comprehensive enough to keep me from being put off by the next bit of manual, (about 8%, as mentioned before), which had lots of discussion, but no more examples, so what is lacking up front is a few more examples of using the convenience methods as Greg apparently does, without configuration, but showing use in multiple modules. After it is shown to be simple to get started in a multi-module code base, then all the refinements can be explained and added, but by then people are already using the logger, and learning becomes incremental.

Just a note: after spacing out over this thread for a bit, I thought I'd try out logging, which I'd never tried before, in some code I was writing. I added a couple of lines like logging.info("foo is %s", foo) where I'd usually write sys.stderr.write("foo is %s\n" % foo) Liked it just fine -- easier to write. But nothing came out! Because it's got this odd idea (from Java?) about "severities" of messages, and by default passes nothing less "threatening" than warnings, because logger.root is initialized by default to WARNING. So, still a bit disconcerting for newbies. Bill

On Fri, Dec 10, 2010 at 11:39 AM, Vinay Sajip wrote:

Bill Janssen writes:

...

Liked it just fine -- easier to write.  But nothing came out!  Because it's got this odd idea (from Java?) about "severities" of messages, and by default passes nothing less "threatening" than warnings, because logger.root is initialized by default to WARNING.

The idea about severity of messages is based on the premise that there might be different audiences for logged messages, and that these can change over time. A fairly common developer perspective on logging is that a logger equates to a destination (e.g. console or file) and the only audience for logging is the developer themselves. So, "handlers" and "loggers" seem complicated, perhaps over-complicated.

In more complex systems, there are different stakeholders: end users, sys admins, support teams, development teams. You have to consider "what happened" (logging event), "where it happened" (logger name), "how important it is" (severity or level) and "who wants to know" (handler), because not everyone wants to know about everything all the time. That's pretty independent of which language you're developing in; it's more a function of the complexity of the system you're developing. Since Python is used in some fairly large system scenarios - NASA, Google, etc. - it doesn't make sense not to have the whole enchilada of logging functionality, at the risk of making it seem complicated to users with less complex needs. And importance maps reasonably naturally onto an idea of integer levels.

The default setting of WARNING is not from Java either - it's the Unix idea that verbosity should be kept to a minimum unless specifically requested. So, warnings and errors should be shown, but info and debug not. Imagine if the default level was DEBUG - lots of detailed stuff would be displayed, which would be off-putting for most users.

And yet, I have helped many people who were baffled by exactly what Bill observed: logging.info() didn't do anything. Maybe the default should be INFO? -- --Guido van Rossum (python.org/~guido)

On 12/10/2010 12:49 PM, Antoine Pitrou wrote:

...

And yet, I have helped many people who were baffled by exactly what

...

Bill observed: logging.info() didn't do anything. Maybe the default should be INFO? Funny, because displaying only errors and silencing other messages is exactly what I expected logging to do by default.

So we are slowly learning the things that should be on the first couple pages of the logging docs... 1) simple example for one file programs, include an example of specifying output severity threshold. I'm with Antoine here on my expectations. 2) example for multi-module, showing how a single logging destination causes logging to happen in all modules, at the same level (if that is the case, which I hope it is). 3) Maybe a small discussion of log formatting should be next? So the user realizes he shouldn't do the message formatting himself? 4) Then rotating logs for long-running programs. And then the rest of the more feature-filled stuff. I agree logging needs to be full-featured, but many of the features are only necessary in complex environments, and simple stuff should be simple, if it can be, and those cases explained first. Hopefully a useful subset for simple cases can be described in 1-3 pages, and then the complex features after that.

Bill Janssen writes:

stdlib, you don't want that default. I think that logging events (context) have to come into this; you can't do it with just severity alone. I'd expect to have different settings, by default, for __main__ and for http.client, for instance.

Although e.g. http.client may set a default severity, the developer integrating it into an application is free to override that severity for the purposes of their application. Typically, there are different severities set for different parts of an application at different times, depending on where the focus of diagnostic scrutiny is at those times. Severity is not the only filtering mechanism, merely the simplest and most common one, that people can readily grasp. Regards, Vinay Sajip

On 10 December 2010 20:57, Glenn Linderman wrote:

On 12/10/2010 12:49 PM, Antoine Pitrou wrote:

And yet, I have helped many people who were baffled by exactly what

...

Bill observed: logging.info() didn't do anything. Maybe the default should be INFO?

Funny, because displaying only errors and silencing other messages is exactly what I expected logging to do by default.

So we are slowly learning the things that should be on the first couple pages of the logging docs...

1) simple example for one file programs, include an example of specifying output severity threshold.  I'm with Antoine here on my expectations.

2) example for multi-module, showing how a single logging destination causes logging to happen in all modules, at the same level (if that is the case, which I hope it is).

3) Maybe a small discussion of log formatting should be next?  So the user realizes he shouldn't do the message formatting himself?

4) Then rotating logs for long-running programs.

The thing *I* hit very early was wanting to add a command lime option to my script to set the logging level. I'd have liked to be able to add --log=INFO/DEBUG/... but to do that I seem to need to write my own mapping between level names and numbers. A simple example of how to tie command line options to logging config would be a great addition to the documentation. Paul.

On 2010-12-12 18:42 , Glenn Linderman wrote:

On 12/12/2010 2:26 PM, Paul Moore wrote:

...

The thing*I* hit very early was wanting to add a command lime option to my script to set the logging level. I'd have liked to be able to add --log=INFO/DEBUG/... but to do that I seem to need to write my own mapping between level names and numbers. A simple example of how to tie command line options to logging config would be a great addition to the documentation.

Oh?

import * from logger # change some details to avoid this basicConfig( level= eval( opt.loglevel )

level = getattr(logging, opt.logLevel) or level = logging._levelNames[opt.logLevel] -- 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

On 2010-12-12 21:30 , Nick Coghlan wrote:

On Mon, Dec 13, 2010 at 11:22 AM, Robert Kern wrote:

...

level = getattr(logging, opt.logLevel)

While this is the approach I would recommend, it does have a couple of downsides:

1. An upper() call is also needed to allow strings like "info" instead of "INFO": 2. If an integer is available, it would be nice to return it unmodified (or, if we ever get named values in the standard library, convert it to that) 3. The asymmetry with "logging.getLevelName" grates a bit

So it would be far more obvious if there was a "logging.getLevel" counterpart to "logging.getLevelName" that looked something like:

def getLevel(level): try: return operator.index(level) # Integers and equivalents except TypeError: pass try: key = level.upper() except Exception as ex: raise TypeError("Log level must be an integer or string") from ex return globals()[key]

I don't think that the implementation should use globals(). I wouldn't want logging.getLevel('basic_format') to work. Instead, it should look it up in the known set of levels.

...

level = logging._levelNames[opt.logLevel]

That doesn't work (_levelNames maps from integers to strings, we want the mapping from strings to integers and it is only the module globals that provides that).

At least in Python 2.6, it maps both ways. But then again, it is an _implementation _detail that should not be relied upon in your programs. I would suggest that there should be two dictionaries as part of the documented API, one mapping numbers to names and one mapping names to numbers. Or functions/methods returning said dictionaries. Having the entire mappings at hand is more useful than having functions that do the translation. They would allow you to auto-generate UIs (e.g. the help text for a --log-level argument or a radio box widget in a GUI). Having separate mappings makes them easier to work with than the 2.6-style _levelNames mapping. -- 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

Antoine Pitrou writes:

Guido van Rossum wrote:

...

And yet, I have helped many people who were baffled by exactly what Bill observed: logging.info() didn't do anything. Maybe the default should be INFO?

Funny, because displaying only errors and silencing other messages is exactly what I expected logging to do by default.

The one thing I'm sure of is that it's hard to find more than a couple of people with the same view about what the default should be. Anyone for bikesheds? :-) 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 ;-) And whatever it is, it's going to upset *some* group of people because they have to add one line (or so) to get it to do what they want, and they feel really strongly that they shouldn't have to add that one line. In a way, I suppose I'm not unhappy that this is all we're arguing about and not anything more substantive. Some useful feedback about the documentation has emerged, too. I would (naturally) like to see broader adoption of logging in the standard library, and the view from Python core developers who have expressed opinions on this thread seems to be that the present behaviour is an obstacle to that adoption. I have my views but I'm not hidebound by them, hence the proposed change and the posting about it on the logging blog and c.l.py, just to let people know what's coming. It'll be interesting to see, once this change is implemented, whether the suggested obstacle really has been an obstacle, rather than (as I suspect) the low level of logging adoption in the stdlib being largely being a matter of plain inertia. But even if it helps make possible a better resolution of #10626 (as an archetype of unraisable-exception scenarios), that would be a good outcome. Regards, Vinay Sajip

On Sat, Dec 11, 2010 at 12:42 PM, Terry Reedy 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@gmail.com   |   Brisbane, Australia

Nick Coghlan writes:

This could actually make a reasonably good basic for a "task oriented" subsection of the logging documentation. Something like:

Good suggestion, I'll see what I can do. Thanks, Vinay Sajip

On Sun, Dec 12, 2010 at 5:32 AM, Brett Cannon wrote:

On Fri, Dec 10, 2010 at 22:21, Vinay Sajip wrote:

...

Nick Coghlan writes:

...

This could actually make a reasonably good basic for a "task oriented" subsection of the logging documentation. Something like:

Good suggestion, I'll see what I can do.

Just wanted to +1 on some task-oriented (or at least simple intro) docs going into the logging module.

I think Vinay has made some great improvements to the logging module docs in the last day or two. The latest version out of SVN is available on the site at the usual location: http://docs.python.org/dev/library/logging I am putting some minor notes here for Vinay's benefit (I can put them on the tracker instead, if he would prefer): General It may be worth talking to Georg about how best to split the logging docs up into multiple files. The sidebar menu is getting kinda overwhelmed. 14.7.1.1 Parenthetical comment in first row of second table should start with "(e.g. for" not "(e.g. or" 14.7.1.8 Probably best to say "that's it for the basic tutorial" and then point people towards the advanced tutorial in 14.7.2 before setting them loose on the rest of the docs. The advanced tutorial defines the terminology and gives the necessary structure to help keep the detailed docs in perspective without being overwhelmed by the detail. 14.7.2.1 Something appears to have gone wrong with the first bulleted list. It is missing the "These are the configuration methods:" intro text, as well as a bullet for add/removeHandler The "does not address filters" part should cross-reference the detailed section on filter objects This section should state explicitly whether or not the level setting on a child logger affects which messages it passes to its parent logger 14.7.2.5 This section is out of date, and needs to be caveated to make it clear that it applies only to version prior to Python 3.2 (for 3.2, it can describe the new handler of last resort behaviour) And that's the end of the two tutorials... very nice update :) Cheers, Nick. -- Nick Coghlan   |   ncoghlan@gmail.com   |   Brisbane, Australia

Hi, I suggest to replace “error” with “event” in the module doc synopsis. Regards

Nick, Thanks for the detailed exposition.

Notice that even the recommended "basicConfig" approach to resolving this is subtly flawed, since your choices are to either display info

Right. basicConfig() is pretty basic.

Basically, as of 3.2, the correct "default" use is likely to be:

The suggestions make sense.

[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. [snip] documentation of Logger.setLevel()! There really should be a section early on in the logging documentation describing the root logger, how

Agreed.

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

Yes.

formatting (when the documentation for the new styles feature goes in would probably be an appropriate time to fix this). Similarly, the

Sorry, what do you mean by "new styles feature"?

Anyway, the shortest way I could find of setting this up (debug

Yes, except that you could have set the root logger level to INFO rather than DEBUG. This raises some more questions. Obviously, we don't want users to have to go through these steps themselves. Once these steps have been finalised, the last resort handler could be modified to do all this. Should this handler be part of the public API, so that it can be inherited from etc? I realise we're in beta and hence feature freeze ... just sayin'. We're all consenting adults here, after all :-) Regards, Vinay Sajip

Nick Coghlan writes:

The switching between percent, str.format and string.Template formatting. It turns out that has been documented, but the table in question is still written from a percent-style formatting point of view.

Oh, right - yes. I presume you mean the table in the formatter documentation which shows %(message)s etc.

The "lazy" stream handler might be useful to make public in some way. For example, rather than hardcoding sys.stderr, it could take a callable that it uses to retrieve the stream. That kind of change can wait until 3.3 though - what is there now should be fine to let us get concurrent.futures and the logging tests to play nicely together.

Actually if we're to change things to print INFO to stdout and WARNING+ to stderr, I'd change the last resort handler class to be more than just defining a lazy stream property: perhaps something like [untested] class _DefaultHandler(StreamHandler): def __init__(self, level=NOTSET): """ Initialize the handler. """ Handler.__init__(self, level) def emit(self, record): if record.levelno == INFO: self.stream = sys.stdout else: self.stream = sys.stderr super(_DefaultHandler, self).emit(record)

As far as whether anything else in the logging defaults needs to change, I don't think so. I'm now happy that if an application needs

I agree it can be refined later, but if we agreed that INFO goes to stdout, then something like the above could be put in place for 3.2 (perhaps 3.2b2).

output defaults to sys.stderr" philosophy). The change to the default behaviour was just to make logging.warning() etc a suitable replacement for writing directly to sys.stderr when exceptions can't be raised, which is in keeping with the existing spirit of the logging module.

Agreed.

I don't think we should be adding more *code* at this stage. But documentation fixes and adjustments may be a good idea. I've learned quite a bit myself about the logging module in the course of this discussion, so it would be nice if some of that could be captured and used to improve the documentation.

Yes, you (and Glenn, and others) have given me quite a bit to work on, on that score!

That said, something that might be interesting is to see what my addHandler() recipe [1] would do for the examples in the logging documentation. If it makes a big enough difference, then it may be worth talking to Georg about adding it, even for 3.2. Alternatively, if you like the idea, but we don't want to break the feature freeze for it, then it may make a nice "see-also" link from the docs. I find it useful from a "here are all the things I can configure on a handler in one easy bundle" point of view, even aside from any benefits in reduced typing.

Actually I've been thinking about a handlers= optional argument for basicConfig for some time (which, if provided, would override file and stream arguments). But it seemed a little unwieldy and came across plainly as the afterthought it admittedly was :-) Regards, Vinay Sajip

On Sat, Dec 11, 2010 at 7:28 PM, Vinay Sajip wrote:

Nick Coghlan writes: Actually if we're to change things to print INFO to stdout and WARNING+ to stderr,

I suspect our messages crossed paths in mid-stream, but I actually realised I was wrong on that front - the behaviour already provided by logging.basicConfig is the better way to go. The missing piece in the story of "how do I create X kind of output" is plain old vanilla print statements and similar direct writes to sys.stdout. The logging module is a tool to track what is happening in a program, not a tool for providing a console based UI. Cheers, Nick. -- Nick Coghlan   |   ncoghlan@gmail.com   |   Brisbane, Australia

On Sat, Dec 11, 2010 at 10:06 PM, Vinay Sajip wrote:

Nick Coghlan writes:

...

the logging module is a tool to track what is happening in a program, not a tool for providing a console based UI.

That was certainly the thinking behind how it worked before my recent changes, but I completely accept that it wasn't helpful in the concurrent.futures scenario, and agree with the comments you made around this in your earlier posts. However, what Antoine has said on this thread (and others have concurred) leads me to believe that he wants to use it not purely as a tracking tool (as I've termed it, "an adjunct to doing real work") but also as a tool to provide program output (e.g. doing some of the program's real work, say by calling error() to print an error message).

I think that's actually just a case where the lines get a little blurry. From logging's point of view, it is still being used to say "Hey, this particular event happened during program execution". We're just adjusting our display policy to say that there are certain kinds of events that should be made visible to the user by default, but piping them into the logging machinery is preferable to writing them directly to sys,stderr. By contrast, most information that is written to sys.stdout isn't really reporting events that happened in the program - it is actual meaningful data that is related to the task the program accomplishes. Cheers, Nick. -- Nick Coghlan   |   ncoghlan@gmail.com   |   Brisbane, Australia

On Sun, Dec 12, 2010 at 3:24 AM, Tres Seaver wrote:

-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1

On 12/11/2010 04:28 AM, Vinay Sajip wrote:

...

Actually if we're to change things to print INFO to stdout and WARNING+ to stderr,

ACK!  That would be an awful default -- stdout belongs to the application, not to "meta" stuff like logging, which should only go to stderr.  Much better to document the "how-to" for setting up something like that than to make it a default.

Don't worry, that isn't going to happen. Vinay was just responding to something he thought I was suggesting. I wasn't really, but I can understand someone getting that impression (as I was using that behaviour as my running example of "so just what *is* involved if an applications wants to configure logging like that?"). Cheers, Nick. -- Nick Coghlan   |   ncoghlan@gmail.com   |   Brisbane, Australia

On Sat, Dec 11, 2010 at 4:25 PM, Glenn Linderman wrote:

On 12/10/2010 9:24 PM, Nick Coghlan wrote: This could actually make a reasonably good basic for a "task oriented" subsection of the logging documentation. Something like:

Yep, agree.  But sadly, for each point, there may be multiple options (your StreamHandler, but I'd want a FileHandler; your separation of messages by level, my wanting them combined; etc.)

No, no, no, that's the *whole point* of using logging. The library writer doesn't really *care* about where the messages end up - that is entirely in the hands of the application developer when they choose which handlers to install. The only situation that the library writer cares about is the one that tripped up concurrent.futures and that has already been changed for 3.2b2: that warnings and errors written to a logger were silenced by default if the application never even called basicConfig(). That has now been fixed so they will be emitted on sys.stderr instead (including obeying any redirections of stderr over the lifetime of the program). Notice that my task list is *entirely* from the point of view of the person emitting the messages. How those messages are later displayed is then up to the application writer (or the logging module default settings, if the application writer doesn't do anything specific).

Your comment about basicConfig setting the level on the root logger, but not on the default handler making it useless is opaque to me,

An early version of my code used basicConfig to create the stderr StreamHandler, but that turned out to be pointless since I wanted different levels on the logger and the handler.

but is there perhaps room for another basic setup API that could get the setup code down to a line or two in simple cases?

For 3.2? No. For 3.3? Maybe.

Would that be a useful set of functionality to bundle?  And could it be extended, when the user wants more power, or would it have to be replaced, because it gets in the way of the user that wants more power?

Logging already has powerful configuration mechanisms, especially following the addition of dictConfig (http://docs.python.org/dev/library/logging#logging-config-dictschema), so it really doesn't need anything else along those lines. At the simpler end, basicConfig already covers sending all messages to a single stream with a single format - it's only split-stream handling (such as stderr/stdout potentially being different endpoints) that it can't cope with. What may make more sense than yet another global config mechanism, is a module level "addHandler" helper function along the following lines: from logging import Formatter, FileHandler, StreamHandler, getLogger def addHandler(*, handler=None, stream=None, filename=None, filemode='a', format=None, datefmt=None, style='{', level=None, max_level=None, filters=(), logger=None): """stream, filename, level, format, datefmt, style: as per logging.basicConfig handler: use a precreated handler instead of creating a new one logger: logger to add the handler to (uses root logger if none specified) filters: an iterable of filters to add to the handler max_level: can optionally limit the handler to messages of a certain level and below """ # Create the handler if one hasn't been passed in if handler is None: if filename is not None: handler = FileHandler(filename, filemode) else: handler = StreamHandler(stream) # Set up the formatting of the log messages # New API, so it can default to str.format instead of %-formatting formatter = Formatter(format, datefmt, style) handler.setFormatter(formatter) # Set up filtering of which messages to handle if level is not None: handler.setLevel(level) if max_level is not None: def level_ok(record): return record.levelno <= max_level handler.addFilter(level_ok) for filter in filters: handler.addFilter(filter) # Add the fully configured handler to the specified logger if logger is None: logger = getLogger() logger.addHandler(handler) return handler # Previous set up example is now only three lines long import sys, logging # Let root logger handlers see all messages logging.getLogger().setLevel(logging.NOTSET) # Send WARNING and above to stderr addHandler(stream=sys.stderr, level=logging.WARNING) # Send INFO to stdout addHandler(stream=sys.stdout, level=logging.INFO, max_level=logging.INFO) logging.info("Hello world!") logging.warn("Hello world!") Cheers, Nick. -- Nick Coghlan   |   ncoghlan@gmail.com   |   Brisbane, Australia

On 12/11/2010 12:00 AM, Nick Coghlan wrote:

...

On 12/10/2010 9:24 PM, Nick Coghlan wrote: This could actually make a reasonably good basic for a "task oriented" subsection of the logging documentation. Something like:

Yep, agree. But sadly, for each point, there may be multiple options (your StreamHandler, but I'd want a FileHandler; your separation of messages by level, my wanting them combined; etc.) No, no, no, that's the *whole point* of using logging. The library writer doesn't really *care* about where the messages end up - that is entirely in the hands of the application developer when they choose which handlers to install. The only situation that the library writer cares about is the one that tripped up concurrent.futures and that has already been changed for 3.2b2: that warnings and errors written to a logger were silenced by default if the application never even called basicConfig(). That has now been fixed so they will be emitted on sys.stderr instead (including obeying any redirections of stderr over

On Sat, Dec 11, 2010 at 4:25 PM, Glenn Linderman wrote: the lifetime of the program).

Notice that my task list is *entirely* from the point of view of the person emitting the messages. How those messages are later displayed is then up to the application writer (or the logging module default settings, if the application writer doesn't do anything specific).

Yes, yes, yes... that's what your list was! I see that now! But it is interesting that in missing that point, and reading your logging setup code, I saw that the same list of tasks is also exactly the sorts of things that you would want to control, for simple uses of the logger. Does basicConfig give that control? I don't know, the first 8% of the logger documentation don't tell me that, they only give me a canned example (actually 3) without explanation of its full function. Someday I'll read more. Until then, basicConfig is opaque: I know only three incantations for using it, and not even any surety that they can be mixed, or that it can be called more than once in the same program.

...

Your comment about basicConfig setting the level on the root logger, but not on the default handler making it useless is opaque to me, An early version of my code used basicConfig to create the stderr StreamHandler, but that turned out to be pointless since I wanted different levels on the logger and the handler.

...

but is there perhaps room for another basic setup API that could get the setup code down to a line or two in simple cases? For 3.2? No.

For 3.3? Maybe.

...

Would that be a useful set of functionality to bundle? And could it be extended, when the user wants more power, or would it have to be replaced, because it gets in the way of the user that wants more power? Logging already has powerful configuration mechanisms, especially following the addition of dictConfig (http://docs.python.org/dev/library/logging#logging-config-dictschema), so it really doesn't need anything else along those lines.

Sure; that is the replacement technique. And maybe that is OK, if there are no useful intermediates between basicConfig (whatever it might be capable of) and dictConfig (or the other various config techniques that preceded it and still exist, if I understand correctly from has been said here on python-dev).

At the simpler end, basicConfig already covers sending all messages to a single stream with a single format - it's only split-stream handling (such as stderr/stdout potentially being different endpoints) that it can't cope with.

OK, so I'd probably be fine with basicConfig, even though you weren't, once I understand it a little better.

What may make more sense than yet another global config mechanism, is a module level "addHandler" helper function along the following lines:

And once I learn enough to understand the addHandler code, I will have read a lot of the logger documentation than I have to date, or it will have been restructured enough that re-reading the first 8%, or maybe 12% if the easy-to-understand part grows! But I like what you said here:

# Previous set up example is now only three lines long import sys, logging # Let root logger handlers see all messages logging.getLogger().setLevel(logging.NOTSET) # Send WARNING and above to stderr addHandler(stream=sys.stderr, level=logging.WARNING) # Send INFO to stdout addHandler(stream=sys.stdout, level=logging.INFO, max_level=logging.INFO)

logging.info("Hello world!") logging.warn("Hello world!")

And this subset usage of addHandler is reasonably understandable for beginners, although clearly the complexity of all the parameters must add power that is not needed in the simple case, that you feel could be useful in the complex case. And I would change the third line from level=logging.INFO to level=logging.DEBUG to see lots more on stdout, correct? Looking back at the logger's simple examples section, I see that getLogger is used before being defined, is not explained, nor is its parameter explained. So it is not clear how to go from the first simple example to the second simple example. I wonder if that is where I started getting a bit of uncertainty about the ability to quickly learn what was going on... the rotating log example uses several APIs that haven't been used before, without explaining them at all. Can that example actually be added to the previous example? What is the magic 'MyLogger'? Where has basicConfig() gone in the second example? I'm not expecting answers to the above questions here, but I'd love to see the documentation improved to the point that I don't have them any more :) Glenn

On 12/11/2010 3:52 AM, Vinay Sajip wrote:

I will try to incorporate more basic examples at the top of the documentation, but surely you don't want me to add more verbiage about basicConfig when your overall feeling is that there's too much documentation?

I try not to post unless I feel there is a new detail; yes the 8% is probably repetitive, but at present, going further, at least sequentially, does feel like a large mountain to climb... suddenly becoming significantly steeper there. I really can't say much about the 92% of the documentation, because of the mountain. Whether the existing documentation can be reordered to avoid the steep part, but rather provide a gentle upward path, I cannot say. If it is properly organized reference material, then probably adding more about something at the beginning is appropriate, to give the foundation, justification, and assistance for climbing the slope. My overall feeling is not necessarily that there is too much documentation (there is a lot, but maybe that is a good thing, I should read it some week) but that it suffers in not providing useful information for the beginner at the front. I've listed what I've gleaned here and tried to point out the things that I still don't know, and tried to point out where things became less than obvious along the way. I do think it was primarily because the intro material is too brief and too disconnected, that I quit reading at the 8% mark (or so). If the rest of the large document were to be similarly disconnected, it wouldn't be worth my time to read it... and if I had to read it all, just to understand enough to get started with simple logging, then it would be faster to write my own, which is the path I took. I suffer with my own being primitive, but I can tweak it when I need to. I still don't fully understand the nuances between handlers and filters, and likely won't until I read more of the documentation. Jumping directly to the documentation (at the 28% mark, I'd have had to read a long way to find it) for basicConfig per your links helps, but sadly, because the first paragraph is full of the terms "logger", "handler", and "formatter", which I have only rudimentary ideas about what they do, being a beginner, I almost gave up again. But the description of the valid keywords for **kwargs was actually understandable, at the end of that documentation. I also learned that calling basicConfig more than once in a program is probably useless, and it should be nearly the first logger API called, if it is used. The first paragraph should be split, perhaps: "Does basic configuration for the logging system." is almost redundant with the name, but is OK if first. The rest of that paragraph, and the next three, should probably be moved after the list of kwargs keys and descriptions. Yes, the word handler is used a bit, but it is associated there with concepts like file names and stream handles, and that eases the uncertainty; together with the simple example at the front, and the verbage there, I can see that I specify a file name, and it makes the logger log to that file :) And the level parameter is fine. I'm less sure about format and datefmt and why I would want to specify them or how, and am surprised to find that format is to be used by a "handler" not a "formatter", but the simple example shows me I can leave those out for starters. Personally, I suffer in writing documentation; when I attempt to do so, and people read it, they usually tell me that after about the third read, they finally understand it, but sadly it takes them three reads. It is interesting to be looking at the logger from the other side... maybe I'll be able to improve the documentation I write, after analyzing why the logger documentation was hard for me to approach.

On Sat, Dec 11, 2010 at 3:06 PM, Nick Coghlan wrote:

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

I need to correct this comment, since it's wrong and basicConfig(level=logging.INFO) actually does the right thing. As Glenn mentioned later in the thread, the output of logging.info and logging.debug messages is *distinct* from an application's normal operational output that is emitted on stdout. So making it easy to emit such messages on stderr is the right thing to do - it's OK that it requires a bit of additional set up to get them onto stdout instead (since they really don't belong there most of the time). I know my own rule of thumb is going to be updated along the lines of "Am I writing to sys.stderr, or guarding output with a verbosity flag? Then perhaps I should be using the logging module rather than print statements". Cheers, Nick. -- Nick Coghlan   |   ncoghlan@gmail.com   |   Brisbane, Australia

Guido van Rossum wrote:

And yet, I have helped many people who were baffled by exactly what Bill observed: logging.info() didn't do anything. Maybe the default should be INFO?

Yeah, I was curious enough to read the code and find out why. But many won't. By the way, I tried reading the 2.7 docs first, and didn't figure it out from them. So I looked at the code. Bill

On 12/10/2010 10:47 AM, Stephen J. Turnbull wrote:

Vinay Sajip writes:

...

Indeed, and the very first code sample in the logging documentation shows exactly the simplistic easy usage you're talking about. I can't see why anyone would be scared off by that example.

They're not scared by that example. What you need is a paragraph below it that says

""" Do you think the above is all you should need? If so, you're right. You can stop reading now. If you think you need more, we've got that, too. Read on (you may need more coffee). """

+1

Oleg Broytman writes:

Better yet (IMHO) would be to split the huge page into "Logging: Simple start" and "Logging: Advanced usage (for the brave of of heart)".

Splitting is OK, but I disagree about the gloss "for the brave of heart". In my experience, if it is a YAGNI, the complexity is nearly impenetrable. If you *do* need it, it's not at all difficult to understand what the complexity is for, and it doesn't even look all that complex because it matches up with the problem you need to solve. If the documentation is still a deterrent, that's a problem with the documentation and it should be improved. AFAICT, making it clear that exporting all the internal flexibility is for those who need it, while most users will rarely need it, should be enough. But I'm not a good test case, since I already am familiar with XEmacs's similar system.

Antoine Pitrou writes:

Why wouldn't it be the default for all logging calls ? Such special cases don't really make things easy to remember.

One size doesn't fit all. Everything's documented reasonably well. If you use it often, you remember it. If you use it seldom, you might need to look things up.

You seem pretty tied up to the "application developer" situation. There are cases (scripts, prototyping, etc.) where you certainly want to see error messages (errors should not pass silently) but don't want to configure logging for each of the libraries you use.

You don't have to configure each of the libraries you use. The "application developer" = "The developer who is not writing a library" = "The person writing a script, prototyping, etc." I don't mean Application with a capital A. I'm just using it as a convenient label to mean a library user who is not writing a library themselves.

Having convenient and understandable defaults would go a long way towards making logging more usable, IMO.

The defaults are I believe reasonably convenient, or at least not inconvenient: 1. If writing a library, add a NullHandler to the top-level logger of your library, don't add any other handlers by default (i.e. on import), document the names of the loggers you use. Otherwise, see the following. 2. If writing a simple script, prototyping etc. i.e. for casual use, use logging.debug(), logging.info() etc. That's easy enough and convenient enough for casual users to remember, I hope. All WARNING, ERROR and CRITICAL events in your code and in that of any libraries you use will be printed to sys.stderr. 3. If slightly less than very casual use (e.g. you want to log to file, or want a specific message format), call basicConfig(). Just the one extra line to remember to do, hopefully not too inconvenient. All WARNING, ERROR and CRITICAL events in your code and in that of any libraries you use will be printed to sys.stderr, unless you specify a file to log to and/or a different logging level, in which case what you specified will be used as destination/threshold for logging messages. 4. For more advanced use, use programmatic configuration, fileConfig or dictConfig to specify a configuration. Convenience is inversely proportional to how involved the configuration is. If you can specify what you think is inconvenient in the above, that would be helpful. Regards, Vinay Sajip

Antoine Pitrou writes:

My point is that the default behaviour should be helpful.

I can't disagree with that. Now if only we could agree what we mean by "default" and "helpful" ;-)

I would point out that logging is really the kind of thing people don't want to spend time with. I know it's not very gratifying for the module author (you!), but nobody expects (*) to have to first configure a

Logging's just a tool - I completely understand that it's just an adjunct to the interesting stuff. Doesn't bother me a bit :-)

logging library when they want to use a third-party library. They expect it to work *and* give useful error report by default.

(*) (not in the Python land anyway; Java might be different)

The Java thing is a red herring, I believe. It's more akin to the Unix idea of minimum verbosity as a default. In general, you don't need to "configure a library" except when you want specific behaviour from that library's loggers.

First, you cannot call it a "default", since the library writer has to make it explicit. Second, I don't find that convenient at all. When I use a third-party lib I want the errors to be displayed, not silenced. I'm willing to bet that most people have the same expectation. *Especially* when prototyping, since you're not sure you've got everything right.

So, that's two problems: - the library author has to explicit activate what you argue is a "default" behaviour (otherwise the library user gets an unhelpful message that handlers are not configured) - the library user still has to override that "default" since it's not satisfying for most uses

See my comments to Nick Coghlan's post about getting messages out when you can't raise an exception. I think the case is not as common as you suggest (because in many instances, you would raise an exception to signal an error). I'm not opposed to changing the way things work, but I think we need more of a consensus because some backwards incompatibility will result, albeit not likely to affect too many users of logging.

There's a third problem with it: - all this is not easily discoverable. You cannot expect each user of a third-party lib to *also* read the logging docs in addition to the third-party lib docs. On my Web browser, http://docs.python.org/dev/library/logging.html seems to be at least 50 pages long.

You're complaining about too much documentation?! Don't measure it by weight! Seriously, I don't see what's wrong with a library developer reading the documentation for any module they're using, logging included. "Configuring logging for a library" is easily visible in the sidebar on that page. So I wouldn't agree that "it's not easily discoverable". It's not exactly buried. And it's the library developer who has to read it, not the user of the library. The user of the library only needs to know what logger names are used by that library, and that too only if they want to configure those loggers.

For a comparison, the warnings module logs all warnings by default on stderr without requiring any a priori configuration. And that's what stderr is for (reporting errors).

But that behaviour is *not* always wanted. That's why I was asked to add warnings integration to logging - to redirect warning messages to logging. Things are seldom as black and white as you're making them out to be here.

Indeed, this is convenient. And that's what I'm arguing should be the default for *all* loggers, not just the top-level one. There's no reason that what is convenient for the root logger isn't for other loggers.

Loggers work in a hierarchy, and the package is specifically designed so that you can attach handlers just to the root logger, and get messages from all code in your application + its libraries to destinations that you configure there. This is not special case behaviour for root logger versus other loggers - it's just that the root logger is a convenient, logical place to attach handlers.

I know that one line sounds "not too inconvenient" since you are the library author and you are so used to it (and certainly like using it and spend a lot of time improving its features, which is good). I think most people, however, have different expectations (see beginning of this message).

Hey, that's not why I think "not too inconvenient"! It's because (a) It's no less inconvenient than "import foo", and it's hard to argue that one line is really inconvenient for this case - remember, for the simplest uses you can omit the basicConfig() call, since you can use logging.info() etc. (b) For this case, since there's no telepathy in this world, you need some way for the programmer to communicate their intent about the logging level, or format string, or log file that they want to use. I stand by the statement that one line (or more precisely, one function call) is not too much to ask here, so yes - "not too inconvenient". That's emphatically not because I'm the module's author and "used to it". Regards, Vinay Sajip

Paul Moore writes:

And yet Unix invented the concept of stderr, precisely to ensure that there's a route for things the program wants to inform the user about to get out.

The NullHandler approach could be seen as the equivalent of adding 2>/dev/null to every command by default.

Not quite true. The program can (as of right now) ensure that all warnings and messages get directed to stderr, simply by calling basicConfig(). That'll work even if every library has added a NullHandler. Although you can argue that the call to basicConfig() shouldn't be necessary, you tone comes across as a bit of an overreaction.

The "specific behaviour" I want is for errors and warnings to go to stderr. Every time. (Unless I'm writing a service that wants to redirect all output to a log file, or something like that - and that's where I'm really glad to have the logging module! And the fact that the defaults tend to encourage library authors not to use it really frustrate me as an applicatioo developer.)

I don't see where your assertion that "the defaults tend to encourage library developers not to use it" comes from. If it's Antoine's post in this thread, then I believe he was referring to the stdlib rather than libraries in general, and I would also say that I don't believe it's a major factor; I would say that inertia was a more pertinent factor. Of course I understand I could be wrong about this, but I don't recall when a stdlib maintainer has said to me, "I want to start using logging in stdlib module XXX, but can't justify it because ..." I doubt whether making this change will result in a flurry of stdlib modules which suddenly adopt logging, but stdlib maintainers can certainly prove me wrong easily enough by stating otherwise in response to this. It's not as if I'm not approachable - you will see that many improvements to the logging package exist because of user feedback, both from python-dev and elsewhere.

Hmm. As far as I can tell from reading the thread, everyone but you is in favour of errors and warnings going to stderr by default. I may have missed some dissenting views, but it certainly feels like a consensus to me!

"Everyone but you" - I think you mean "everyone on this thread but you", and "everyone else on this thread" is not remotely close to "everyone else, period".

If you feel that the proposal needs to be presented to a wider group than just python-dev then that's fair. But personally, I think that python-dev will be a reasonably good indicator in this case.

I don't dispute that, but there's not really been enough time for more than a few people on python-dev to respond.

...

But that behaviour is *not* always wanted. That's why I was asked to add warnings integration to logging - to redirect warning messages to logging. Things are seldom as black and white as you're making them out to be here.

Exactly!!!! Logging should be a BETTER option than direct writes to stderr. At the moment, though, it's a CHOICE - writes to stderr, which are visible by default but (very) inflexible, or logging which is flexible but suppressed by default (OK, "if you follow the recommended practice to avoid a user-hostile warning"). The problem is that some people are voting with their feet that visibility matters more than flexibility.

I don't think it's unreasonable to ask which people are voting with their feet, that you know of. This discussion was initiated by me after I got added to the nosy list of an issue. It's not as if there has been a host of voters who have asked for change and are walking away because of some intransigence on my part. As you can see in my response to Nick's post, I am making concrete suggestions on how the situation could be improved. It's not helping to talk about people voting with their feet, especially as no serious attempt to engage with me on this issue has been made in the past. Because of backward-compatibility considerations, I would consider it premature to make this kind of change just based on a request by one or two python-dev members. I have the highest level of respect for people who have responded on this thread, but how can I be sure that they're representing everyone else on this list? It's a great community, with a lot of cohesion, but people do have divergent opinions. (I'm not talking about me here. If there's a consensus about this, I've no problem implementing a "handler of last resort".)

But you don't because the library developer added a NullHandler which you have to switch off!!!

Where are you getting this "switch off" from? There's no switching off that happens. The NullHandler remains in place. What you are doing is "switching on" output to some specific place you want - console, file etc. - with a level of verbosity and format that you choose.

FWIW, basicConfig has *never* been what I want. Except in the sense that I have to use it to switch on logging to stderr (if only it worked, but see the comment above about NullHandler) because that's not the default. In all other cases, I've wanted a little bit more (which may not be hard to achieve, but that's not the point here).

Well, "may not be hard to achieve" is in line with "not too inconvenient", if you ask me. And as for "if only it worked", that makes it sound like there's some effect you can't achieve at very modest cost in terms of any code you have to write.

Saying that's convenient is like saying that adding sys.stderr=open("/dev/tty", "w") is a convenient way of getting errors displayed when you don't like the default destination of /dev/null.

I don't think I'm saying that at all. I see where you're coming from, but apart from stating your point of view, IMO you're not adding to the discussion in the same way that Nick, say, has. Regards, Vinay Sajip

On Wed, 8 Dec 2010 12:15:53 +0000 (UTC) Vinay Sajip wrote:

...

First, you cannot call it a "default", since the library writer has to make it explicit. Second, I don't find that convenient at all. When I use a third-party lib I want the errors to be displayed, not silenced. I'm willing to bet that most people have the same expectation. *Especially* when prototyping, since you're not sure you've got everything right.

So, that's two problems: - the library author has to explicit activate what you argue is a "default" behaviour (otherwise the library user gets an unhelpful message that handlers are not configured) - the library user still has to override that "default" since it's not satisfying for most uses

See my comments to Nick Coghlan's post about getting messages out when you can't raise an exception. I think the case is not as common as you suggest (because in many instances, you would raise an exception to signal an error).

I'm not talking specifically about exceptions, but about errors in general. If the case wasn't common, I'm not sure why the error() and critical() methods would exist at all. (of course I'm assuming error() is meant to output error messages. If that's a wrong interpretation then I'm a bit puzzled :-))

...

There's a third problem with it: - all this is not easily discoverable. You cannot expect each user of a third-party lib to *also* read the logging docs in addition to the third-party lib docs. On my Web browser, http://docs.python.org/dev/library/logging.html seems to be at least 50 pages long.

You're complaining about too much documentation?! Don't measure it by weight! Seriously, I don't see what's wrong with a library developer reading the documentation for any module they're using, logging included.

I was talking about the user of a library, not its developer (see the snippet quoted above).

The user of the library only needs to know what logger names are used by that library, and that too only if they want to configure those loggers.

The thing is, they don't *want* to configure them, but you force them to do some configuration if they don't want error messages to be silenced.

...

For a comparison, the warnings module logs all warnings by default on stderr without requiring any a priori configuration. And that's what stderr is for (reporting errors).

But that behaviour is *not* always wanted.

Sure. What I'm arguing is that the warnings module's default behaviour is much more useful than the logging module's default behaviour.

That's why I was asked to add warnings integration to logging - to redirect warning messages to logging.

That's a separate topic :)

(b) For this case, since there's no telepathy in this world, you need some way for the programmer to communicate their intent about the logging level, or format string, or log file that they want to use.

Well, the programmer doesn't have to communicate their intent about what and how warnings get displayed by default, and I'm not sure the warnings module has a telepathy routine inside (although you never know, since IIRC Brett did some philosophy studies). Regards Antoine.

On Thu, Dec 9, 2010 at 12:43 AM, Fred Drake wrote:

On Wed, Dec 8, 2010 at 9:27 AM, Antoine Pitrou wrote:

...

The thing is, they don't *want* to configure them, but you force them to do some configuration if they don't want error messages to be silenced.

As I tried to explain earlier, a NullHandler doesn't silence anything except the message about logging not being configured. Propagation is not controlled by the handlers, but by the loggers.

If the only handler is NullHandler though, (or if there are no handlers configured at all) then output does get silenced by default, even errors and warning messages. The application has to (directly or indirectly) configure logging with additional handlers in order for the output to appear somewhere. That's the behaviour that is inappropriate for use cases like the concurrent.futures handling of unraisable errors that started this discussion over on the bug tracker. Cheers, Nick. -- Nick Coghlan   |   ncoghlan@gmail.com   |   Brisbane, Australia

On Wed, Dec 8, 2010 at 9:52 AM, Nick Coghlan wrote: ..

P.S. On a completely unrelated note, has anyone thought about creating a write-only TextIO stream that outputs received writes via the logging module?

I've done something similar for C++ iostreams many moons ago. The idea was to prepend all lines written to std::log with timestamp and other information. It worked reasonably well, but involved a lot of C++ hackery at the time. I think this is a great idea and would allow existing libraries that use sys.stderr for messages start using say the root logger instead when user redefines sys.stderr.

On Thu, Dec 9, 2010 at 2:46 AM, Vinay Sajip wrote:

Nick Coghlan writes:

...

That said, while I think Vinay's suggested "handler of last resort" solution is a good one and something we should be doing for 3.2, I'm also happy to let the idea bake for at least a few weeks.

I agree on the baking part, since it will allow time for any drawbacks to be spotted or better solutions found. There are also the questions of what level and format to use for the handler of last resort, before it can actually be implemented.

As a starting point, I'd say warnings and above, no formatting (i.e. just the message). To minimise bikeshedding, I'd like to be guided by the idea that this is a more configurable alternative to printing directly to stderr, but in the absence of application level configuration, you wouldn't be able to tell which approach the library was using just by looking at the program output. Cheers, Nick. -- Nick Coghlan   |   ncoghlan@gmail.com   |   Brisbane, Australia

On 8 December 2010 14:52, Nick Coghlan wrote:

As I see it, there aren't many cases at the *library* level where logging errors is more appropriate than raising exceptions:

On a slightly tangential note, what do you think of the idea of library code including info or debug level logging? In effect, tracing and diagnostic code built in and available simply by changing the logging level? Paul.

>> On a slightly tangential note, what do you think of the idea of >> library code including info or debug level logging? In effect, >> tracing and diagnostic code built in and available simply by changing >> the logging level? Vinay> That's how it works right now. You get info() and debug() Vinay> messages sent via calls in library code, just by changing the Vinay> level of (say) the root logger. There can be performance implications if you log heavily. I don't know how the code is organized, but functionally these two calls are equivalent: >>> logging.error("error 1 2 3 %s" % "yup") ERROR:root:error 1 2 3 yup >>> logging.error("error 1 2 3 %s", "yup") ERROR:root:error 1 2 3 yup The second form should be preferred in library code as long as the format string expansion is deferred until after the test is made to emit the message. Skip

On 8 December 2010 19:04, Vinay Sajip wrote:

Paul Moore writes:

...

On 8 December 2010 14:52, Nick Coghlan wrote:

...

As I see it, there aren't many cases at the *library* level where logging errors is more appropriate than raising exceptions:

On a slightly tangential note, what do you think of the idea of library code including info or debug level logging? In effect, tracing and diagnostic code built in and available simply by changing the logging level?

That's how it works right now. You get info() and debug() messages sent via calls in library code, just by changing the level of (say) the root logger.

You misunderstand me. I know that's how those levels work. What I'm not sure about (and I think would be interesting and potentially useful information) is whether the individuals participating in this thread feel that liberal use of info and debug level logging in library code is useful. All the discussion thus far has been about warning and error levels (mainly because people seem less comfortable with the "suppress by default" approach for those levels, whereas it's natural for debug and info levels). I guess I'm wondering what best practices for logging might be. (Actually, that might make the subject of an interesting blog posting, if you're looking for suggestions :-)). Paul.

On Thu, Dec 9, 2010 at 4:49 AM, Paul Moore wrote:

On 8 December 2010 14:52, Nick Coghlan wrote:

...

As I see it, there aren't many cases at the *library* level where logging errors is more appropriate than raising exceptions:

On a slightly tangential note, what do you think of the idea of library code including info or debug level logging? In effect, tracing and diagnostic code built in and available simply by changing the logging level?

It's a trade-off between performance and the ability to diagnose faults and what you want to do will vary by application and problem domain. My background is in working on distributed projects where we need enough diagnostic information to debug one-off failures of the live system, so I'm in favour of the idea in general, but doing it *can* carry a fairly hefty speed cost (you can ameliorate that to some degree by handing off the actual I/O to a separate thread, but the system would still be faster if the log messages weren't there). As Skip says, you definitely want to take advantage of the lazy string formatting when doing this with the Python logging module. Cheers, Nick. -- Nick Coghlan   |   ncoghlan@gmail.com   |   Brisbane, Australia

On Wed, 8 Dec 2010 14:54:09 +0000 (UTC) Vinay Sajip wrote:

Antoine Pitrou writes:

...

I'm not talking specifically about exceptions, but about errors in general. If the case wasn't common, I'm not sure why the error() and critical() methods would exist at all.

(of course I'm assuming error() is meant to output error messages. If that's a wrong interpretation then I'm a bit puzzled )

Then again, it's not always helpful when *library* code prints out messages to stderr. A user of the library might prefer that an error code be returned or an exception raised, so they can deal with the condition most appropriately.

Sorry, what are you arguing about and what kind of answer are you expecting? Obviously error() is preferrable in some cases and other means of communicating the error are preferrable in other cases. That's kind of stating the obvious to me. But since you are the one you wrote the library and added error() in the first place, why are you trying to convince me that error() is not useful? Perhaps you should explain how error() is supposed to be used for if it's not supposed to log errors.

...

I was talking about the user of a library, not its developer (see the snippet quoted above).

Yes, but see my response to that. A user of a library doesn't need to know the specifics of what loggers that library uses, they just need to make a positive statement of where they want warning and error messages go, and how they want them formatted.

And my point, again, is that they want it to work by default *without* making such a positive statement. I'm not sure if I'm supposed to explain this using different words since you're not appearing to get it.

BTW we haven't discussed this yet - but these enabled-by-default messages, what format should they have? (e.g. just message, logger name + message, logger name + severity + message etc.) It might sound like a trivial point, but it also seems like whatever you pick, some bikeshed discussions would ensue.

I'm sorry but your way of argumenting is really puzzling to me. You are trying to find counter-arguments against something which you *already* implemented yourself in logging.error(). If you're interested in having a theoretical argument about what a beautiful design should be (and if you want to argue about your own design decisions), I'll leave the discussion here. I'm only interested in the *practical* matter of logging having an useful behaviour by default, which apparently you don't really care about. Fair enough, but this whole thread is quite telling, IMO, about the general impedance mismatch between the logging design and the expectations of casual users (which is 99% of them, certainly). Regards Antoine.

On Wed, 8 Dec 2010 19:00:31 +0000 (UTC) Vinay Sajip wrote:

...

If you're interested in having a theoretical argument about what a beautiful design should be (and if you want to argue about your own design decisions), I'll leave the discussion here. I'm only interested

No, I'm not interested in that. Like you I'm interested in practical matters, but unlike you I have to make some implementation choices, going forward - so it shouldn't be surprising that I want to talk around the issue to make sure that no wrong decision gets made. Sorry if that offends you because it sometimes seems to be stating the (to you) obvious.

Ok, I'm sorry for the harsh words. I really hope this discussions leads to somewhere. Regards Antoine.

Vinay Sajip writes:

No offence taken, and do do I

s/do do/so do/ Perhaps it was a Freudian slip admitting that I *am* a dodo! Regards, Vinay

Terry Reedy writes:

Your proposal struck me as probably the best way forward. Can you code it up and put a patch on the tracker that people can test before the next beta?

Coded up (including unit test) and checked into py3k branch, r87157. Regressions pass OK. Old behaviour can be obtained by setting logging.lastResort = None. Regards, Vinay Sajip

Antoine Pitrou writes: Hi Antoine,

When you make significant changes outside of logging, it would be nice if you first opened an issue and posted the patch for review. There's nothing obviously wrong with what you committed, but I think it's principally better to ask first for advice.

Sorry, which significant changes outside of logging do you mean? If you're referring to my addition of TestHandler and Matcher to test.support, I did mention this earlier in the thread, with a link to the code (though it wasn't on a patch added to the tracker, I agree). I can revert this change, if you want. The changes in r87157 are to Lib/logging/__init__.py, Lib/test/test_logging.py and Misc/NEWS - so IMO not outside of logging. Perhaps wrongly, I expected that these straightforward-seeming changes wouldn't adversely affect anyone else's workflow, except perhaps making it easier for Brian Quinlan to make changes to test_concurrent_futures to resolve #10626. I did run regressions and everything passed OK.

(then there's nothing wrong with committing if you didn't get an opinion past a week or two)

Sorry if my eagerness has stepped on any toes - it's not intentional. The diff of the changes is here: https://gist.github.com/736120 Comments are of course welcome. Regards, Vinay Sajip

Antoine Pitrou writes:

Yes, I am talking about this one. I am not asking that you revert it; I am just saying that it is generally appreciated if substantial patches get proposed on the tracker before being committed.

OK, sorry - point taken.

In this case since it's in test.support we can probably improve it on the fly, of course.

For sure. Regards, Vinay

On Wed, Dec 8, 2010 at 9:51 AM, Glenn Linderman

wrote:

On 12/8/2010 4:15 AM, Vinay Sajip wrote:

You're complaining about too much documentation?! Don't measure it by weight!

On 12/8/2010 5:57 AM, Vinay Sajip wrote:

Of course I understand I could be wrong about this, but I don't recall when a stdlib maintainer has said to me, "I want to start using logging in stdlib module XXX, but can't justify it because ..."

So I'm a fairly new Python user, but 30 years programming experience.

When I first looked at the Python logging facility (and again today, when I looked again), I found a simple example of debugging logging. Then a bunch of stuff about how to configure rotating logs. Then something about logging levels. And then a dissertation on the theory of loggers "The logging library takes a modular approach and offers the several categories of components: loggers, handlers, filters, and formatters." And I hadn't gotten through 10% of the documentation yet, per the scrollbar.

My reaction the first time was "Sounds sophisticated and complex. I think I'll do something simpler for now, and maybe someday, when I have a spare week, I'll read the documentation and see if the benefits are worth the effort."

OK, so now you've discovered that too much documentation can be a turn off... at least, if it is presented from the top to describe the sophistication of the facility, rather than how easy it is to use (if it is, I still haven't gotten to 10%, and I still don't know that).

Exactly. All I ever recommend people do is: import logging ... logging.warn('doing something a bit odd.') ... for x in thing: logging.debug('working on %r', x) ... And be done with it. If they are controlling their __main__ they'll probably want to call a common function to setup the log message formatting and where it gets written to from there. Otherwise ignore that and leave that up to the person using your library (directly, indirectly or otherwise) to do that in their __main__ code. For logging to be useful it needs to be dirt simple. The above is. -gps

Am 08.12.2010 01:09, schrieb Antoine Pitrou:

On Tue, 7 Dec 2010 23:45:39 +0000 (UTC) Vinay Sajip wrote:

...

Antoine Pitrou writes:

...

I thought "error" and "critical" messages were logged to stderr by default? Isn't it the case?

Only if you call basicConfig() or use the logging.debug(), logging.info(), etc. module-level convenience functions (which call basicConfig under the hood).

Why wouldn't it be the default for all logging calls ? Such special cases don't really make things easy to remember.

...

When is the NullHandler needed? Only for cases where an application developer uses a library which does logging under the covers (for those users who might be interested in logging its operations), but where that application developer doesn't use logging themselves for that application.

You seem pretty tied up to the "application developer" situation. There are cases (scripts, prototyping, etc.) where you certainly want to see error messages (errors should not pass silently) but don't want to configure logging for each of the libraries you use.

But errors don't pass silently, do they? The usual way to present errors is still by raising exceptions. Georg

Am 08.12.2010 10:42, schrieb Antoine Pitrou:

...

But errors don't pass silently, do they? The usual way to present errors is still by raising exceptions.

Or logging them. http://docs.python.org/dev/library/logging.html#logging.Logger.exception

Yes, thank you I'm aware of the exception() method. But hopefully standard library modules don't use it to report exceptions to code that uses them? Georg

Antoine Pitrou writes:

On Wed, 08 Dec 2010 11:48:16 +0100 Georg Brandl wrote:

But hopefully standard

...

library modules don't use it to report exceptions to code that uses them?

I'm not aware of that, but there are certainly third-party libs using it (think an HTTP server that wants to log an error in one of its request handlers without the error taking the whole server down).

That's not the same thing as Georg is talking about, IIUC. The exception() method is used in exception *handler* code to record that the exception occurred, but the correct thing for any code to do when an error condition is detected (in most situations at least) is to raise an exception. It would be quite wrong for code to e.g. call logger.error(...) instead of raise ... Regards, Vinay Sajip

Eric Smith writes:

Wouldn't it make more sense to add these to test.support? I don't think we make any guarantees about its API being stable, although I have a faint recollection of that being debated in the past.

That's what I mean when I said "unit test infrastructure" - adding to test.support. Sorry, I should have been more explicit. Regards, Vinay Sajip

On Dec 07, 2010, at 04:59 PM, Robert Kern wrote:

As a library author, I would dearly love to just add logging liberally without placing any additional burden to the users of my library. If my users wants to read those logs, he will configure logging. If he doesn't, he won't. With the current behavior, I can't do that. If I add logging, he has to add code just to silence a message that is meaningless to him (after I get the support emails asking if things are broken and explain how to silence it). If I add a NullHandler, I remove the ability for him to use logging.basicConfig(), the easiest and most straightforward way for him to add logging to his application.

+1 -Barry

On Dec 08, 2010, at 12:01 AM, Vinay Sajip wrote:

Barry, if you mean +1 as in "I agree this is how it should work", then we're all agreed.

Yep, that's what I meant! -Barry

On 2010-12-07 17:58 , Vinay Sajip wrote:

Robert Kern writes:

...

If I had my druthers, I would simply remove the "No handlers could be found for logger XXX" message. If we always wrote entire applications from the ground up, it makes a lot of sense. The person that writes the code that issues logs is the same person that writes the code to configure logging for reading. If you add logging in one place, you almost certainly want to use it somewhere else and not setting up logging is probably an error. But when you want to write reusable libraries, those roles become separated.

Exactly - we do use third-party libraries. When logging was added there was some debate about whether this one-off message should be printed, and in balance it was thought better to print this, not least because people would be unfamiliar with logging (as it was then new) and so be not unlikely to misconfigure it. No indication of this at all would be double-plus-ungood.

I really don't understand how this view can be consistent with the practice of adding NullHandler to loggers. If this message is so important to prevent misconfiguration, then why should a library author decide to silence it for his users? I think that the chances of a misconfiguration that the warning would catch. are small in practice. I don't have any solid survey data on how people configure their loggers, but I strongly suspect that almost all configurations include a catch-all root logger and that most of those *only* consist of that root logger.

...

As a library author, I would dearly love to just add logging liberally without placing any additional burden to the users of my library. If my users wants to read those logs, he will configure logging. If he doesn't, he won't. With the current behavior, I can't do that. If I add logging, he has to add code just to silence a message that is meaningless to him (after I get the support emails asking if things are broken and explain how to silence it). If I add a NullHandler, I remove the ability for him to use logging.basicConfig(), the easiest and most straightforward way for him to add logging to his application.

You don't remove the ability for him to use basicConfig() - that's another mistake in your post (you already corrected the other mistake in your self-response). See my example with mylib.py/myapp.py in another post on this thread, in response to Antoine.

Same mistake. I intended the correction to apply to all such statements in my post.

...

This is only my personal anecdotal experience, but the current behavior has always wasted my time and never saved any of my time.

That's because I think you're doing it wrong, or else I've misunderstood your use case.

I will try to state it more plainly: the message has always been a false positive in my experience. It has never helped me fix a real problem and has otherwise wasted my time.

NullHandler is the way to go, and doesn't preclude the use of basicConfig() UNLESS you choose to add the NullHandler to the root logger (not what you're supposed to do - you're supposed to add it to the top-level logger *of your library*, not the top-level logger of the logging hierarchy.)

See the mylib/myapp example and tell me which it is - your mistake or mine?

I think that boilerplate should be minimized. If using getLogger() should almost always be followed by adding a NullHandler, then it should be the default behavior. The easiest way to achieve this effect is to simply not issue the warning message. -- 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

On 12/8/10 2:51 AM, Vinay Sajip wrote:

Robert Kern writes:

...

I really don't understand how this view can be consistent with the practice of adding NullHandler to loggers. If this message is so important to prevent misconfiguration, then why should a library author decide to silence it for his users?

Because the application developer knows more about the end-user audience for their application, they are better placed to know how logging should work for their application. It's not an error for a particular application developer to decide that nothing should be produced by logging for a particular application; they (particularly when casual users) would be confused by the misconfiguration message due to logging by a library they're using.

The library author's users are the application developers who use the library, not the end users who use their applications. Sometimes they're the same people, I know, but I just think of them as wearing different hats :-)

I'm sorry, but it's not at all clear that you have understood my point. There is no way for me to parse your words as a sensible reply to what I said. Let's say I write a library called Foo. I want to add logging to my functions. You want to write an application called Bar that uses Foo and you want to configure logging for your application (at the very least to provide a default if not production). The warning is supposed to help you not make mistakes when configuring logging in your application. If I, library author, attach NullHandlers to all of Foo's loggers, then you will not get that warning if you forget to add handlers the Foo loggers. My adding the NullHandler to Foo prevented that warning that you consider to be so important. I don't think the warning helps much, if at all.

...

[...] I strongly suspect that almost all configurations include a catch-all root logger and that most of those *only* consist of that root logger.

That doesn't seem right: your comment might be conflating loggers with handlers. The common pattern would be (or should be) to name loggers according to __name__ in the modules which use logging, but only configure *handlers* for the root logger. That way, logging messages indicate their origin (because of the __name__ convention) but you only need to add handlers at the root logger to capture all the logging information.

Yes. That's what I meant.

...

I think that boilerplate should be minimized. If using getLogger() should almost always be followed by adding a NullHandler, then it should be the default behavior. The easiest way to achieve this effect is to simply not issue the warning message.

getLogger() should NOT "almost always be followed by adding a NullHandler". For example, in Django, only the logger named "django" would have that handler added; no other Django logger (e.g. "django.db.models") would need to have that handler added.

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. 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? Personally, I would back the proposals being made elsewhere in this thread, that in the absence of configuration, warnings and errors should be printed to stderr no matter where they come from. This gives useful behavior out-of-the-box 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. -- 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

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

Glenn Linderman writes:

Or what am I missing?

That threads are not necessarily dedicated to apps, in a real world setting. Depending on the server implementation, a single thread could be asked to handle requests for different apps over its lifetime. So the only way of knowing which threads are currently servicing a particular app is to maintain a set of them. Regards, Vinay Sajip

On 12/9/2010 12:26 AM, Vinay Sajip wrote:

...

...

Or what am I missing? That threads are not necessarily dedicated to apps, in a real world setting. Depending on the server implementation, a single thread could be asked to handle requests for different apps over its lifetime. So the only way of knowing which

Glenn Linderman writes: threads are currently servicing a particular app is to maintain a set of them.

Agreed, they are not necessarily dedicated to apps. But while they are running the app, they have the appname in their thread local storage, no? So if a thread has the appname in its thread local storage, is it not servicing that app, at that moment? And if it is, why is that insufficient? That is my question, and you've sidestepped it.

And one more thing: the filters for*both* apps are called for a given request. One will return True, the other will return False.

Bear in mind that the intention of the post is to be didactic, so it's possible there are some improvements that could be made when implementing for production.

OK, I just learned what "didactic" meant, so you've taught me something. I understood that both filters would be called. I understood, that in production, it would probably not be necessary to log messages to both the app log and the global log, that the global log would be there just for things that are not app-specific. But I still don't see a need to maintain a set of threads running the app in the app object, if the app keeps track of what app it is running, in a spot that is accessible to the filter (which it seems to be). I don't see how it is beneficial to keep track of two separate data structures that could serve the same purpose. I realize you designed this in 10 minutes, and probably took twice that long to write it up, so didn't necessarily analyze it for efficiency. But I'm asking for that analysis now, if there is any real need for the app to track the set of threads, _for the purpose of the problem being solved_? I understand there might be other reasons for which that might be useful, but for the logging it simply seems to be inefficient redundancy... and if it isn't, then I don't understand the example, yet, and I'm trying to. So since you hand-waved, instead of giving a straight answer, and then maybe your second message was an attempt to back-pedal a bit, not sure, I went ahead and downloaded your code, made changes to remove the set of threads as outlined (see modified functions below), and it seems to run just as correctly. I thought it was an obvious question, while trying to understand the code, and maybe learn about the logger, and I guess I have, a little. And maybe some other things too. Please further explain if I am still missing something. Under what conditions of the problem you were solving does the code below fail? class InjectingFilter(logging.Filter): def __init__(self, app): self.app = app def filter(self, record): record.method = tlocal.request.method record.ip = tlocal.request.ip record.appName = tlocal.appName return record.appName == self.app.name # tname = threading.currentThread().getName() # return tname in self.app.threads class WebApp: def __init__(self, name): self.name = name self.threads = set() handler = logging.FileHandler(name + '.log', 'w') f = InjectingFilter(self) handler.setFormatter(formatter) handler.addFilter(f) root.addHandler(handler) self.num_requests = 0 def process_request(self, request): tlocal.request = request tlocal.appName = self.name # tname = threading.currentThread().getName() # self.threads.add(tname) self.num_requests += 1 try: logger.debug('Request processing started') webapplib.useful() logger.debug('Request processing finished') finally: pass # self.threads.remove(tname)