Python logging prints every line of a feature-flag service twice - how do you diagnose it?

seniorshould knowfreq 46%

answer

Copies equal handlers reached
The code did not log twice
Inspect handler lists, not source
One at the module, one at the root
Shared logger, setup ran twice

basics

~20 s

Duplicates mean the record found two handlers on its way up the hierarchy. Print the handler list and propagation flag for that logger and every ancestor, find the second handler, and remove it or the configuration that added it.

solid answer

~50 s

A record is written once per handler it meets while walking its own logger and every ancestor, so seeing a line twice means two handlers were reached — not that the code logged twice. There are two shapes. Either a handler sits on the service's own logger and another sits on the root, typically because a module attached one at import time while startup configuration installed another, an ordering assumption that holds until imports move. Or one setup function ran twice and appended a second handler to the same shared logger, since loggers are process-global singletons. Diagnose it by dumping every logger's handler list and propagation flag rather than by reading the code. Fix by owning configuration in exactly one place, making setup idempotent, and reserving propagation-off for a logger that genuinely has its own destination.

A record is written once per handler it meets while walking its own logger and every ancestor, so seeing a line twice means two handlers were reached — not that the code logged twice. There are two shapes. Either a handler sits on the service's own logger *and* another sits on the root, typically because a module attached one at import time while startup configuration installed another, an ordering assumption that holds until imports move. Or one setup function ran twice and appended a second handler to the same shared logger, since loggers are process-global singletons. Diagnose it by dumping every logger's handler list and propagation flag rather than by reading the code. Fix by owning configuration in exactly one place, making setup idempotent, and reserving propagation-off for a logger that genuinely has its own destination.

code

python · 11 lines

python

import logging
import sys

logging.basicConfig(stream=sys.stdout, format="%(message)s")
logger = logging.getLogger("flags")
logger.addHandler(logging.StreamHandler(sys.stdout))

logger.warning("emitted twice: own handler, then the root handler")

logger.propagate = False
logger.warning("emitted once")

go deeper

for a junior

Recall that one record is written once per handler it meets, and that handlers can live on the logger you used and on any ancestor including the root.

for a middle

Explain both mechanisms — a handler at two levels of the hierarchy, and one shared logger accumulating handlers from repeated setup — and how to print the live handler lists to tell them apart.

for a senior

Show the diagnosis order under pressure: inspect state before code, use the difference between the two lines as a clue, and choose between removing a handler and stopping propagation on the merits.

for a principal

Own the standard that prevents it: one configuration point per service, libraries that never attach handlers, and a startup assertion on the shape of the logging tree so the ordering assumption cannot return.

Read the symptom precisely

When each line of a feature-flag service appears twice, the natural reading — "something calls the logger twice" — is almost always wrong. A record is handed to every handler found while walking its own logger and then each ancestor up to the root, so the count of copies is the count of handlers reached. Two copies, two handlers. A useful first clue is the shape of the two lines: identical text means two handlers sharing a formatter or both using the default, while a bare line next to a timestamped one means two handlers with different formatters, which usually points at two separate pieces of configuration.

Diagnose by inspecting state, not by reading code

Logging configuration is scattered by nature — application startup, a library, a framework, a test helper — so read the live state at runtime. Walk the manager's logger dictionary and print each logger's name, its handler list, and whether it propagates, plus the root's handler list. That dump answers the question in seconds and does not depend on guessing which module ran first.

Two patterns account for nearly all duplicates.

A handler at both levels. The service's own logger carries a handler and so does the root. This is the ordering assumption made visible: a module added a stream handler at import time, and application startup later installed the root handler as well — or the reverse, depending on import order. Nothing errors, because both handlers are perfectly valid; the record simply finds both. The same shape appears when a library rudely configures the root logger and the application also configures it.

The same handler added twice. getLogger returns one shared object per name for the whole process, so a setup helper that calls addHandler and is invoked more than once appends to the same list. The tell is that the number of copies grows with the number of calls. It is most visible in tests: run a 27-minute suite where a fixture calls the setup helper per test, and the first test prints one line, the second two, the twentieth twenty. Under a request handler or a lazily-initialised client the same growth appears in production, just more slowly.

Fix it at the right level

Configure destinations in exactly one place — the application entry point — and let every other module only name a logger. A library or an internal package should attach no handler at all; the records will still reach the application's handlers by propagating up.

Make setup idempotent when it cannot be guaranteed to run once: check whether the logger already has handlers before adding one, or remove existing handlers before installing the new set. Guarding on the existing handler list is cheap and removes the whole class of accumulation bugs.

Switching a logger's propagation off is a real fix, but a narrow one. It means "this logger owns its output and its records must not be seen by ancestors", which is right for a subsystem writing to a dedicated destination and wrong as a general silencer — the records then also vanish from the root's aggregation, so anything shipping the root's output loses that subsystem entirely. Reach for it deliberately, not as a reflex against duplicates.

Guard the regression

Once fixed, keep it fixed by asserting the shape of the configuration rather than the text of the output: after startup, the service's own logger has no handlers of its own and the root has exactly the expected number. That test fails the moment someone adds a convenience handler in a module, which is where the ordering assumption creeps back in. Tests also need their own hygiene, since one process runs every test and the logging tree persists across them: reset the handler list in teardown instead of appending to it in setup.

The mirror symptom

The same model explains the opposite complaint. If a subsystem's lines vanish rather than double, walk the chain the same way: the record may never be created, or it may be created and meet no handler at all because someone switched propagation off on an ancestor while chasing duplicates, or every handler it reaches may reject it. Duplication and silence are two readings of one dump — the handler list and propagation flag along the record's path — which is why that dump, and not a search through the source for logging calls, is the first thing to run in either direction.

### Read the symptom precisely When each line of a feature-flag service appears twice, the natural reading — "something calls the logger twice" — is almost always wrong. A record is handed to every handler found while walking its own logger and then each ancestor up to the root, so the count of copies is the count of handlers reached. Two copies, two handlers. A useful first clue is the shape of the two lines: identical text means two handlers sharing a formatter or both using the default, while a bare line next to a timestamped one means two handlers with different formatters, which usually points at two separate pieces of configuration. ### Diagnose by inspecting state, not by reading code Logging configuration is scattered by nature — application startup, a library, a framework, a test helper — so read the live state at runtime. Walk the manager's logger dictionary and print each logger's name, its handler list, and whether it propagates, plus the root's handler list. That dump answers the question in seconds and does not depend on guessing which module ran first. Two patterns account for nearly all duplicates. **A handler at both levels.** The service's own logger carries a handler and so does the root. This is the ordering assumption made visible: a module added a stream handler at import time, and application startup later installed the root handler as well — or the reverse, depending on import order. Nothing errors, because both handlers are perfectly valid; the record simply finds both. The same shape appears when a library rudely configures the root logger and the application also configures it. **The same handler added twice.** `getLogger` returns one shared object per name for the whole process, so a setup helper that calls `addHandler` and is invoked more than once appends to the same list. The tell is that the number of copies grows with the number of calls. It is most visible in tests: run a 27-minute suite where a fixture calls the setup helper per test, and the first test prints one line, the second two, the twentieth twenty. Under a request handler or a lazily-initialised client the same growth appears in production, just more slowly. ### Fix it at the right level Configure destinations in exactly one place — the application entry point — and let every other module only name a logger. A library or an internal package should attach no handler at all; the records will still reach the application's handlers by propagating up. Make setup idempotent when it cannot be guaranteed to run once: check whether the logger already has handlers before adding one, or remove existing handlers before installing the new set. Guarding on the existing handler list is cheap and removes the whole class of accumulation bugs. Switching a logger's propagation off is a real fix, but a narrow one. It means "this logger owns its output and its records must not be seen by ancestors", which is right for a subsystem writing to a dedicated destination and wrong as a general silencer — the records then also vanish from the root's aggregation, so anything shipping the root's output loses that subsystem entirely. Reach for it deliberately, not as a reflex against duplicates. ### Guard the regression Once fixed, keep it fixed by asserting the shape of the configuration rather than the text of the output: after startup, the service's own logger has no handlers of its own and the root has exactly the expected number. That test fails the moment someone adds a convenience handler in a module, which is where the ordering assumption creeps back in. Tests also need their own hygiene, since one process runs every test and the logging tree persists across them: reset the handler list in teardown instead of appending to it in setup. ### The mirror symptom The same model explains the opposite complaint. If a subsystem's lines vanish rather than double, walk the chain the same way: the record may never be created, or it may be created and meet no handler at all because someone switched propagation off on an ancestor while chasing duplicates, or every handler it reaches may reject it. Duplication and silence are two readings of one dump — the handler list and propagation flag along the record's path — which is why that dump, and not a search through the source for logging calls, is the first thing to run in either direction.

In a 27-minute suite the same line appears once in the first test and twenty times by the twentieth. Why?
A per-test setup helper is calling `addHandler` on a logger that is a process-wide singleton, so the handler list grows with every test while the tree persists across them. The copies track the number of calls, not the number of log statements. Fix it by configuring logging once for the whole session, by guarding on the existing handler list before adding, or by removing the handlers the helper installed in teardown.
When is switching a logger's propagation off the right fix rather than removing a handler?
When that logger genuinely owns a destination — an audit or access log going to its own file that must not be mixed into the general stream. It is the wrong fix for accidental duplication, because it also hides those records from the root's handlers, so anything aggregating the root's output loses the subsystem silently. Prefer removing the extra handler and keeping one configuration point.
The two copies differ - one has a timestamp, one does not. What does that tell you?
Two handlers with different formatters were reached, so two separate pieces of configuration are live: typically one installed by application startup with a full format string, and a bare handler added somewhere with no formatter, which prints only the message. It rules out the double-`addHandler` accumulation pattern, where the copies are identical, and points you at the module that installed the plain handler.

saying these in an interview costs you the question

Assumes the application is logging the same line twice
Removes the root handler and loses everything else's output
Switches propagation off reflexively to silence duplicates
Never inspects the live handler lists before changing code
Adds handlers in a setup function that can run repeatedly
Believes a child logger cannot reach the root's handlers

Python logging prints every line of a feature-flag service twice - how do you diagnose it?

§ answer

basics

solid answer

code

§ go deeper

▾level notes4 levels

▾deep dive~4 min

Read the symptom precisely

Diagnose by inspecting state, not by reading code

Fix it at the right level

Guard the regression

The mirror symptom

▾common follow-ups3 questions

▾red flags6 flags

§ context

▾related questions4 questions

▾related topics4 topics

Read the symptom precisely

Diagnose by inspecting state, not by reading code

Fix it at the right level

Guard the regression

The mirror symptom

answer

go deeper

context