TopolearnPropagation explains most 'why is this logged twice' and 'why is this not logged' puzzles.
Loggers form a tree by name: app.db.pool is a child of app.db, which is a child of app, which is a child of the root logger. When a logger accepts a record, the record is handed to the logger's own handlers and then, because propagate is True by default, to the handlers of each ancestor in turn, up to the root.
Two details trip people up:
- Ancestor logger levels are not checked during propagation; only the originating logger's effective level and each handler's level are. A record from
app.dbat DEBUG reaches the root's handlers even if the root logger is set to WARNING. - If both
appand the root have handlers, a record fromapp.xis printed by both: duplicate lines.
The standard design avoids both: put handlers only on the root logger (or one top-level application logger), leave module loggers handler-less, and control verbosity with levels. Set logger.propagate = False only when a subtree must go somewhere else exclusively, such as an audit log.
If no handler is found anywhere, logging falls back to logging.lastResort, which prints WARNING and above to stderr. That's the bare message you see before configuring anything.
Example
import logging, sys
def show(msg):
h = logging.StreamHandler(sys.stdout)
h.setFormatter(logging.Formatter(msg + " %(name)s: %(message)s"))
return h
root = logging.getLogger()
root.addHandler(show("[root]"))
root.setLevel(logging.WARNING)
app = logging.getLogger("app")
app.setLevel(logging.INFO)
app.addHandler(show("[app]"))
logging.getLogger("app.db").info("connected") # handled twice
# [app] app.db: connected
# [root] app.db: connected (root's WARNING level isn't checked)
app.propagate = False
logging.getLogger("app.db").info("pooled")
# [app] app.db: pooledRemember
- Records go to their logger's handlers, then every ancestor's handlers
- Ancestor logger levels are skipped; only handler levels apply on the way up
- Configure handlers once at the root to avoid duplicates
Watch out for
- Adding a handler to a module logger and to the root, then seeing every line twice.