Python’s standard logging package is a really wonderful thing, but unfortunately some of its key ideas aren’t clearly documented in a large enough point font.
Luckily most library authors seem to understand these ideas by default, however quite a few (particularly commercial) libraries seem to ignore them. If you’re writing and distributing reusable libraries that use the logging package, please try to avoid:
Logging to the root logger
Ideally package-level convenience functions like logging.debug() wouldn’t exist, since they’re hard-wired to use the root logger. When library code emits messages via the convenience functions, no useful component name is included in the message, and so the user is forced to grep her site-packages directory to try and find the culprit of a strange looking message.
Library code should *always* log to a private logger instance, which will percolate up the root anyway, except the message will be nicely tagged and organized so the application author can selectively disable (or enable!) logging for your code.
If everything logs to the root logger, then one of the primary benefits of the logging package is lost: selectively controllable hierarchical logging contexts.
A better approach is something like “LOG = logging.getLogger(‘mypkg.mymod’)” module-level or class-level attribute, then always logging as “LOG.debug(foo)” or “self.LOG.debug(bar)”, etc.
Logging during module initialization
Ever seen “No handlers could be found for logger “foo”“? That’s most probably because some library decided to log something before the application that imported it had time to setup the logging package.
Prefer to delay any actual logging calls (except getLogger()) until classes or functions of your library have been explicitly invoked.
Explicitly configuring handlers
This one is super annoying.. it totally defeats the purpose of the logging package! You should never, ever, EVER be explicitly calling Logging.addHandler() or Logging.setLevel() from inside library code, unless your library is specifically designed (and documented) as managing log output.
When you call addHandler() from inside library code, what you’re effectively saying is “I don’t care what the application developer (or system administrator (or end user)) thinks, I have better ideas about where my logs should be sent, and there is no possible situation where this will break stuff!”, and also “I have no bigger problems to think about right now except log management!”
Often your ideas will be wrong. For example, consuming your library from within a GUI running as non-root, where log output might be redirected to some kind of text edit control, or similar, except you’ve hard-wired your output to be written to /var/log/mypkg.log.
Except in very rare cases, the majority of logging configuration should be deferred to the consuming application’s top level, where tools like logging.config.fileConfig() can be used to configure the entire system’s logging using a standard convention, rather than package-specific or app-specific hard-wired values or environment variables or whatever else.
Defaulting to INFO
This one isn’t so bad, but preferably you should avoid it. Your default “LOG.foo()” call should most probably be “LOG.debug()”, no matter how important a problem seems to you at the time! To the application developer consuming your library, he really doesn’t care what 1600-byte URL you’re making a HTTP POST to 10 times a minute, so long as your package functions correctly.
Another side of this is use of “.exception()”, although I have no ideal rule for its use. Roughly: if your library catches and swallows an exception in a graceful, designed-for manner, then it almost certainly shouldn’t be logging the event as an exception. Since exceptions are logged at the highest priority, there is no way to turn off these useless, highly verbose, gracefully handled exception messages without disabling logging for your entire package, which might result in some important messages getting hidden that really should have been logged.
Logging too much
Sometimes on investigating a slow piece of code one might find LOG.debug() type calls embedded in tight loops. The logging package isn’t exactly slow, but it’s no speed demon either! Prefer tracking a few integer stats variables in your loops, and dumping them as a single logging event once the loop ends.
Anonymous replies: the official logging cookbook actually provides an alternative to your section about “Logging during module initialisation” under “configuring logging for a library” in its howto. It suggests and recommends simply adding a NullHandler (provided standard from 2.7 onwards) to the root logger for the library, thereby silencing the error message without interfering with a user’s configuration of logging.
Thanks for the improvement!