Skip to content

← The Edge of the System step 6 of 12

Medium Framework

Logging in libraries: the hierarchy, the effective level, and whose configuration it is

A library that calls logging.basicConfig(), or attaches a StreamHandler to its own logger, has hijacked the logging of every application that imports it. The symptom in someone else’s production system is duplicated lines, or missing lines, or a stream nobody configured writing to stderr inside a JSON log pipeline. The HOWTO is unusually blunt about it:

It is strongly advised that you do not log to the root logger in your library… do not add any handlers other than NullHandler to your library’s loggers… the configuration of handlers is the prerogative of the application developer.

The division of responsibility is the whole item:

library application
creates loggers logging.getLogger(__name__) —
adds handlers only NullHandler, on the top-level package logger yes, all of them
sets levels never yes
calls basicConfig / dictConfig never exactly once, in main()

getLogger(__name__) is what makes this work. Your logger names mirror your package hierarchy, so an application can silence acme.db without silencing acme, and can turn on acme.http.client at DEBUG in production for ten minutes without touching your code. That is only possible because you named things after your modules and then kept your hands off the configuration.

On the application side: dictConfig() rather than code, and configured once, at the top of main(). basicConfig() called after anything has already logged is silently a no-op — it installs a handler on root only if root has none, and the first log call installs one. That is the source of the perennial “my logging config does nothing” bug.

What you implement

The logger tree is global mutable state, so instead of poking at it you model the configured levels as data and reimplement the two walks the stdlib does. This is not a toy: reading someone’s dictConfig and predicting what a given logger will emit is exactly this computation, done in your head.

def logger_ancestry(name: str, propagate: Mapping[str, bool]) -> list[str]: ...
def effective_level(configured: Mapping[str, int], name: str) -> int: ...

logger_ancestry returns the loggers a record reaches, root last: "acme.db.pool" reaches acme.db.pool, acme.db, acme, root. A logger with propagate=False is the last one reached — the record stops there and never sees root’s handlers. Missing from the mapping means True, the default.

effective_level implements Logger.getEffectiveLevel:

  1. Walk the logger and its ancestors, nearest first.
  2. The first level that is not NOTSET wins.
  3. If the walk falls off the end, the answer is WARNING.

Two details that catch people:

  • NOTSET is 0, and it means “not set”, not “level zero”. A logger explicitly set to NOTSET does not stop the walk. If you implement this as “first name present in the mapping”, you get the wrong answer.
  • propagate has nothing to do with the level walk. It governs handler delivery only. getEffectiveLevel walks straight through a logger with propagate=False. These are two independent traversals of the same tree, and conflating them is why people set propagate=False and are surprised that the level did not change.

Root is spelled "root", and the empty string names it too — logging.getLogger("") is logging.getLogger().