skip to content

Why does a logging.Logger set to DEBUG still produce no DEBUG output?

level: middleimportance: must knowfreq 70%

answer

  1. Two gates, not one
  2. The logger checks first, then each handler
  3. NOTSET means ask the ancestors
  4. The root logger defaults to WARNING
  5. getEffectiveLevel() versus handler.level

basics

~20 s

Levels filter twice. The logger's own effective level decides whether a record is created at all, and then every handler applies its own level before emitting. A handler left at WARNING silences DEBUG no matter what the logger says.

solid answer

~40 s

A record has to pass two gates. First the logger compares the call's level against its **effective level** - its own level, or, when that is `logging.NOTSET`, the nearest ancestor's level, ultimately the root logger's, which defaults to WARNING. Only then is a `logging.LogRecord` created and offered to the handlers, and each handler applies **its own** level before emitting. So `logger.setLevel(logging.DEBUG)` with a `logging.StreamHandler` left at WARNING produces nothing, and the reverse - a handler at DEBUG under a logger still on the root's WARNING - is equally silent. `logging.basicConfig(level=logging.DEBUG)` sets the *root logger's* level and leaves the handler at 0, which handles everything. To diagnose, print `logger.getEffectiveLevel()` alongside each `handler.level`.

code

python · 12 lines
python
import logging
import sys

logger = logging.getLogger("ingest")
logger.setLevel(logging.DEBUG)
handler = logging.StreamHandler(sys.stderr)
handler.setLevel(logging.WARNING)
logger.addHandler(handler)

logger.debug("passes the logger, stopped by the handler")
logger.warning("passes both gates")
print(logger.getEffectiveLevel(), handler.level)

go deeper

for a junior

Recall the ordering of DEBUG, INFO, WARNING, ERROR and CRITICAL, and that an unconfigured logger shows only WARNING and above. Know that setting a level on a logger is not always enough for the message to appear.

for a middle

Explain both gates precisely: the logger's effective level resolved through NOTSET up to the root, then each handler's own level applied to the record. Be able to say what basicConfig(level=...) actually sets.

for a senior

Demonstrate the diagnosis on a live service: read getEffectiveLevel() and each handler's level, decide which gate to move, and account for the cost of admitting DEBUG on a hot path rather than turning the root up globally.

for a principal

Own the levelling policy across services: which subsystem loggers exist, who may raise verbosity at runtime and by what mechanism, and how per-destination handler levels keep console noise low while a fuller stream still reaches the retained sink.

### Two gates, not one The single most common logging complaint - "my DEBUG line does not show up" - is almost always the two-stage filter. A message must survive both stages: 1. **The logger gate.** `logger.debug(msg)` first compares `logging.DEBUG` against the logger's *effective* level. If the call is below it, the method returns immediately: no `logging.LogRecord` is ever constructed, no handler is consulted, and the arguments you passed are not formatted. 2. **The handler gate.** If the record is created, it is offered to the handlers attached to that logger and, unless propagation is switched off, to the handlers of its ancestors. Each handler compares `record.levelno` against **its own** level and drops the record if it is lower. Setting one gate open and leaving the other closed is silence, and both directions happen in real code. ### Effective level and NOTSET Every logger has a `level` attribute, which starts at `logging.NOTSET` (0). NOTSET does not mean "log everything" - it means "I have no opinion, ask my ancestors". `Logger.getEffectiveLevel()` walks up the dotted name (`ingest.worker` to `ingest` to the root) and returns the first non-NOTSET level it finds. The root logger is created with WARNING, so an unconfigured logger's effective level is 30 and every DEBUG and INFO call is dropped at the first gate. The numeric constants are `logging.DEBUG` 10, `logging.INFO` 20, `logging.WARNING` 30, `logging.ERROR` 40, `logging.CRITICAL` 50, and `logging.NOTSET` 0. They are plain integers, so comparisons are numeric and a custom level between two of them is legal. Handlers have a `level` too, defaulting to 0 - and on a handler 0 genuinely means "emit everything that reaches me", because a handler has no ancestors to inherit from. That asymmetry is worth stating out loud in an interview: the same constant means "inherit" on a logger and "pass everything" on a handler. ### Why basicConfig(level=...) is not the whole story `logging.basicConfig(level=logging.DEBUG)` attaches a `logging.StreamHandler` to the root logger, gives it a formatter, and sets **the root logger's** level to DEBUG. The handler is left at 0, so it passes everything - which is why the one-liner works and why people conclude that `level=` is "the log level". The moment an application configures handlers explicitly, or a second handler with its own level appears, the two gates diverge and the mental model of a single level breaks. The useful production shape is the opposite of the confusion: keep the logger levels as the coarse control (per subsystem, changed by configuration) and give each handler the level appropriate to its destination - for example a console handler at INFO and a file handler at DEBUG. A handler level can only ever *narrow* what its logger already allowed; it can never widen it, because the record it never received cannot be emitted. ### Diagnosing it in seconds When a message is missing, ask three questions in order. What is `logger.getEffectiveLevel()`? Which handlers will actually see this record, and what is each one's `level`? Is there any handler at all - because with none configured, only WARNING and above escape, through the module's last-resort fallback to stderr. A short interactive check settles it: `logging.getLogger("ingest.worker").getEffectiveLevel()` prints 30 on a fresh interpreter, and drops to 10 as soon as `logging.getLogger("ingest").setLevel(logging.DEBUG)` is called, because the child inherits. If the effective level is right and the message still does not appear, the handler's level (or a filter on the handler) is the remaining suspect. ### The corollary nobody expects Because the first gate happens before the record exists, raising a logger to DEBUG in production has a real cost - every DEBUG call now builds a record and formats a message. Lowering a *handler* to DEBUG has no such effect if the logger still filters the call, and raising a logger while leaving a handler at INFO buys you the cost without the output. Change the gate you actually meant to change.

  • Can a handler set to DEBUG show messages the logger has already filtered out?
    No. The logger gate runs first and, when the call is below the logger's effective level, no record is ever created, so there is nothing for the handler to receive. A handler level can only narrow what its logger already admitted. That is why lowering a handler alone never restores missing DEBUG output, and why the logger level is the control you change first.
  • What is the difference between logging.NOTSET on a logger and on a handler?
    Both are the integer 0, but they mean opposite things. On a logger NOTSET means "I have no level; use my nearest ancestor's", which is why `getEffectiveLevel()` walks up to the root's WARNING. On a handler there is nothing to inherit from, so 0 means "emit every record I am given". A handler created without an explicit level therefore passes everything through.
  • Why is turning a logger up to DEBUG in production not free?
    Because the logger gate is what suppresses the work. Once the logger admits DEBUG, every debug call builds a `LogRecord`, formats the message, and runs the handler chain and filters, and any argument expressions were evaluated at the call site regardless. On a hot path that is measurable, and the resulting volume also costs storage and search time - so raise the level for the narrowest logger you can, not the root.

Two doors between the message and the page: the logger's door decides whether the record is even written, and each handler's door decides whether that destination prints it.

saying these in an interview costs you the question

  • There is only one log level per process
  • Setting the handler to DEBUG re-enables filtered records
  • NOTSET means log everything, everywhere
  • basicConfig's level= sets the handler's level
  • An unconfigured logger defaults to DEBUG
  • Raising a logger to DEBUG costs nothing

context

resolving links…