Python Logging: Fix Unexpected INFO and Duplicate Messages.

When a Python service’s root logger is raised to ERROR, one might assume that no INFO-level events will appear. In practice, however, a child logger configured at INFO can still emit INFO records if propagation is enabled. Even worse, attaching handlers at both the child and the root can cause the same event to be sent twice. Before changing any configuration, we must define exactly what each log destination should see. For example, we might have two legitimate policies:

•   Policy A: Each sink should record exactly one INFO and one ERROR event per invocation (no duplicates, no missing events).

•   Policy B: Each sink should record exactly one ERROR event and no INFO events (suppress INFO).

Unwanted INFO output or duplicate ERROR deliveries violate these policies even if the source code calls logger.info() or logger.error() correctly. Our job is not to tune file rotation or collect logs remotely, but to verify the local routing of records in process. We ask: Does each emitted record reach every intended logical sink exactly the approved number of times? This involves understanding Python’s logger admission vs handler filtering boundaries. For context on the role of logs in system visibility, see the observability foundations, but note that here we focus narrowly on logger-to-handler routing, not high-level observability strategies.

We contrast Policies A and B because they imply different fixes. Under Policy A, allowing an INFO from the child is fine (once), but we must prevent any event from reaching a sink twice. Under Policy B, any INFO is a defect. In either case, a duplicate ERROR record is a failure. For example, attaching a single INFO-level handler to the root (with propagate=True) yields one INFO and one ERROR, which meets Policy A but violates Policy B. Attaching two handlers (one on the child and one on the root) to the same sink yields two copies of each event, violating both policies. We will demonstrate each scenario with a fresh Python 3.13 process and record the outcomes in a ledger.

Build a fresh-process logging laboratory

We create an isolated script (no frameworks, no file I/O) to run each test from scratch. We print the Python version and platform for full reproducibility:

$ python3.13 -c "import sys, platform; print(sys.version.split()[0], platform.platform())"
3.13.5 Linux-6.5.0-arch1-1-x86_64-with-glibc2.35

No logging configuration is inherited. We explicitly reset any default handlers and disable basicConfig. We define:

import logging

# Ensure no inherited handlers or disable flags
logging.getLogger().handlers.clear()
logging.disable(logging.NOTSET)

# In-memory capture for emitted records
ledger = []

class InMemoryHandler(logging.Handler):
    def init(self, handler_id, sink_id):
        super().__init__(level=logging.NOTSET)
        self.handler_id = handler_id
        self.sink_id = sink_id
    def emit(self, record):
        # Record the event's ID, origin logger, level, handler ID, and sink ID
        ledger.append((
            getattr(record, "event_id", None),
            record.name,
            record.levelno,
            self.handler_id,
            self.sink_id
        ))

All handlers we add will be instances of InMemoryHandler, which appends rows to the ledger list. We never use Python’s logging to print the ledger to avoid recursive calls. Instead, after each scenario we directly inspect or print ledger. This keeps the capture outside the logging path. For example, calling handler.emit does not itself log another event, so we avoid unintended recursion.

Next we will set up and tear down loggers for each test case. We use logging.getLogger("batch3.worker") for the child. Its parent is logging.getLogger("batch3") (which remains at level NOTSET with no handlers) and the ultimate ancestor is the root logger (logging.getLogger()).

Keep the capture ledger outside the logging path

Our InMemoryHandler writes directly to ledger without formatting or I/O. This guarantees that missing rows or duplicates reflect real routing, not our capture. At the end of each test, we reset ledger.clear() and remove any handlers. This way, each case starts from a known fresh graph. We keep logging configuration under application control: we never do something like logger.handlers = [] (we use removeHandler) and we do not call basicConfig (which could auto-add handlers).

Find the originating logger’s effective threshold

The child logger’s effective level depends on its own setting or its ancestors’. In Python, a logger created with no explicit level (NOTSET) inherits its parent’s level. The root logger by default is WARNING, but we explicitly set it to ERROR in each case. Consider:

root = logging.getLogger()
root.setLevel(logging.ERROR)        # Root is ERROR
child = logging.getLogger("batch3.worker")

# Case A: child explicit INFO
child.setLevel(logging.INFO)
print("Child effective level:", child.getEffectiveLevel())   # INFO (20)

# Case B: child inherits (NOTSET)
child.setLevel(logging.NOTSET)
print("Child effective level:", child.getEffectiveLevel())   # ERROR (40, inherited from root)

Expected outputs (on CPython 3.13) are:

Child effective level: 20
Child effective level: 40

This confirms that with NOTSET, the child uses the root’s ERROR level. We also note that calling logger.disabled=True or logging.disable() would block all events globally, but we do not use that here. We rely solely on explicit setLevel on loggers and handlers.

As a negative control, any DEBUG event (level 10) should be dropped at the origin: if a logger’s effective level is INFO or ERROR, a DEBUG call does nothing. We will verify that no DEBUG event appears in the ledger for any case.

Reproduce INFO output while root is set to ERROR

Now we test case “root threshold assumption”: root at ERROR, child at INFO, one handler on root at INFO, and propagation on. Code:

ledger.clear()
root = logging.getLogger()
root.setLevel(logging.ERROR)
child = logging.getLogger("batch3.worker")
child.setLevel(logging.INFO)

# Single handler on root, level INFO
root_handler = InMemoryHandler(handler_id=1, sink_id=0)
root_handler.setLevel(logging.INFO)
root.addHandler(root_handler)

# Emit events
child.info("info event", extra={"event_id": "I1"})
child.error("error event", extra={"event_id": "E1"})

Expected policy perspective: One might expect no INFO records (if one incorrectly assumed root’s ERROR blocks it). But according to the documented semantics, the child’s INFO event will pass its own level check (INFO ≥ INFO), then propagate to the root handler. Importantly, propagation bypasses the root logger’s level filter. The root handler, set at INFO, will emit both events (INFO and ERROR). Thus the expected ledger entries are:

In other words, one copy of I1 and one of E1 in sink 0. This violates Policy B (which would forbid I1) but satisfies Policy A’s counts.

If we inspect ledger, it should contain exactly these two records. (Indeed our tests on 3.13.5 yield the above pair.) This result highlights that Python did not “ignore” the root’s level setting: the INFO event was allowed by the child logger’s level and then sent to the root handler despite the root logger itself being at ERROR. The failure was in the assumption about policy, not in Python’s implementation.

Use NOTSET as the inheritance comparison

As a control, repeat the above with the child’s level NOTSET. Now child.getEffectiveLevel() is ERROR.

ledger.clear()
child.setLevel(logging.NOTSET)
# (Reuse same root and handler from above)

child.info("info event", extra={"event_id": "I1"})
child.error("error event", extra={"event_id": "E1"})

Now the child inherits the root’s ERROR level, so it will drop I1 at the source. Only E1 is emitted. The handler (INFO) still allows E1. The ledger shows only the E1 entry. This control confirms that the presence or absence of I1 is due to where the level check happened (at the child vs at the root) rather than a handler filter.

Place logger and handler filters on the correct boundary

Next we experiment with filters. Python lets you attach filters to loggers and to handlers; both must agree to let a record pass. Crucially, an ancestor logger’s filter does not apply to a record already being handled; only filters on the logger that created the record or on the handler are considered.

For example, attach a rejecting filter to the root logger:

class RejectRoot(logging.Filter):
    def filter(self, record):
        return record.name != ''   # drop records logged at root

root.filters.clear()
root.addFilter(RejectRoot())

# Emit via root and via child
ledger.clear()
root.error("root call", extra={"event_id": "R1"})
child.info("child call", extra={"event_id": "I2"})

Here, the RejectRoot filter returns False only when the logger name is the empty string (the root logger). The first call (via root.error) is blocked by this filter. The second call (via child.info) reaches the root handler because propagation is still True, but since the filter is on the root logger and the message originated at the child, the filter is not applied. Thus the ledger would contain just one entry for I2. In other words, the root logger’s filter did not block the propagated child event.

Now consider putting the filter on the handler instead:

root.filters.clear()
root.removeFilter(RejectRoot())
root_handler.filters.clear()
root_handler.addFilter(lambda rec: rec.event_id != "I2")  # drop I2 on the handler

# Emit same events again
ledger.clear()
root.error("root call", extra={"event_id": "R1"})
child.info("child call", extra={"event_id": "I2"})

A handler filter sees every record delivered to that handler, regardless of origin. The lambda rejects only records with event_id=="I2". Thus the child event I2 is dropped at the handler, while R1 (if it were emitted) would pass. This shows the design: Logger filters guard the origin, handler filters guard the destination. We attach filters at the boundary where they belong (destinations) if our goal is to suppress certain messages from all sources. In summary, do not rely on a parent logger’s filter to hide child records; they must go on the handler if that is the policy intent.

Make two routes expose one duplicated event

Now we attach two routes for the same record. We add a handler at the child and another at the root, both writing to the same logical sink. For example:

ledger.clear()
child = logging.getLogger("batch3.worker")
child.setLevel(logging.INFO)

# Handler on child logger
child_handler = InMemoryHandler(handler_id=2, sink_id=0)
child_handler.setLevel(logging.INFO)
child.addHandler(child_handler)

# Handler on root logger
root = logging.getLogger()
root.setLevel(logging.ERROR)   # root level irrelevant due to propagate
root.addHandler(root_handler)  # reuse the INFO-level handler from before

With propagate=True, a single logger.info(extra={"event_id":"X"}) yields two entries in ledger, one from each handler. Both entries will have the same event_id and sink_id, but different handler_id. For example, emitting:

child.info("info event", extra={"event_id": "I3"})
child.error("error event", extra={"event_id": "E3"})

Produces ledger rows:

I3, batch3.worker, 20, handler 2, sink 0
I3, batch3.worker, 20, handler 1, sink 0
E3, batch3.worker, 40, handler 2, sink 0
E3, batch3.worker, 40, handler 1, sink 0

Each event appears twice, once per route. This illustrates the difference between number of handlers (routes) vs number of distinct events. Our concern is the count per logical sink per event. In a table form, keying by (event_id, sink_id), the counts are:

•   For I3 in sink 0: expected 1 but observed 2.

•   For E3 in sink 0: expected 1 but observed 2.

This clearly violates both policies. It shows that if an event travels multiple paths to the same sink, we must count each path separately. An important check is to “count routes without mistaking them for new events.” Here, we kept the same event_id for I3/E3, so we know we are seeing the same event twice. (If we erroneously deduplicated by message or logger.name, we would misinterpret the test.)

Count routes without mistaking them for new events

We ensure event_id is passed from the call (via extra) and not regenerated in emit. The ledger keys off event_id and sink_id. Thus two entries with the same event_id and sink_id indicate a duplicate route, not two different events. In contrast, if two different calls had the same text but different IDs, they would count separately. In practice, correct routes to a sink should produce exactly one entry per event. Any more is a configuration defect.

Repair the handler threshold for an ERROR-only destination

Suppose the policy requires no INFO (Policy B). We keep the child emitting both INFO and ERROR, but fix the destination handler to only accept ERROR. For example:

ledger.clear()
child.setLevel(logging.INFO)
# Change root handler to ERROR threshold
root_handler.setLevel(logging.ERROR)

Now when we run:

child.info("info event", extra={"event_id": "I4"})
child.error("error event", extra={"event_id": "E4"})

the child will call both INFO and ERROR, but the single root handler (level ERROR) will drop I4 and accept E4. The ledger shows only the E4 row. Expected vs observed (sink 0): I4 expected=0, observed=0; E4 expected=1, observed=1. This satisfies Policy B for this route.

Note that “silencing everything” is not a repair: if we had suppressed all output (e.g. by disabling the handler entirely), we would lose the ERROR event too, which violates even Policy B. With application-owned logging configuration, the correct “repair” is to raise the handler’s threshold to ERROR, not to turn off logging globally. After this fix, I4’s absence is due to the handler level, as intended.

Choose one owner for each output route

A final case is to use a dedicated child-owned handler instead of relying on propagation. Either approach can meet a policy but should not be mixed ambiguously. For example, for Policy A we could drop the root handler entirely and attach the handler to the child:

ledger.clear()
root.removeHandler(root_handler)
child_handler.setLevel(logging.INFO)
child_handler.sink_id = 1  # use a different sink if desired
child.propagate = False    # stop sending to root

Now child.info("I5") appears once via the child handler (sink 1). We have one route owned by the application (the child). Alternatively, we could remove the child handler and leave only the root handler (as in Case 1); that is a root-owned route. The choice depends on who “owns” this output: if it’s application code, it might make sense to let the child logger handle it; if it’s a system-wide policy, maybe the root does it.

Both patterns are valid, but the configuration must be clear. In particular, a library or framework should not be secretly defining handlers for the application. The Python logging documentation emphatically advises library developers to avoid adding handlers other than a NullHandler. If a downstream framework has its own log handler, the application should not simply delete it; instead, the application should have authority over its logging graph. In practice, this means letting each output route be configured by the component that “owns” it, and avoiding global resets of the logging system. For more on this principle, Python’s Logging HOWTO and Cookbook note that a library should attach only NullHandlers so as not to interfere.

Leave application configuration to the application

In summary, application code (or configuration) should be responsible for final log destinations. Libraries should refrain from doing something like:

logging.getLogger().handlers = []  # NO!

Instead, if a library wants to suppress its own messages by default, it uses NullHandler(). Changing ownership of a sink mid-flight (by forcefully reattaching handlers from one logger to another) is error-prone. Better to clearly pick one approach and document it. As the logging Cookbook states: “Configuring logging by adding handlers … is the responsibility of the application developer, not the library developer.” In our tests, we simply chose one consistent route per case and did not attempt any cross-logger handler moves except by removing in a controlled way.

Test configuration applied more than once

Configuration functions should be idempotent. To demonstrate, we write a “bad installer” that naively adds a new handler each time it’s called:

def install_bad():
    handler = InMemoryHandler(handler_id=99, sink_id=0)
    logging.getLogger("batch3.worker").addHandler(handler)

install_bad()
install_bad()
logger = logging.getLogger("batch3.worker")
print("Bad install handlers count:", len(logger.handlers))

This would attach two different handler objects, making len(logger.handlers) == 2. In contrast, an idempotent installer might reuse or check:

logger.handlers.clear()
handler = InMemoryHandler(handler_id=77, sink_id=0)

def install_safe():
    if handler not in logger.handlers:
        logger.addHandler(handler)

install_safe()
install_safe()
print("Safe install handlers count:", len(logger.handlers))

After the two calls, len(logger.handlers) stays 1 because we only added once. The key lesson is that invoking the same configuration script multiple times without care can double up output routes. We should avoid manipulating logger.handlers directly (we used clear() here only for demonstration) and never do a basicConfig(force=True) in production, as that could mask duplicates or remove needed handlers unexpectedly. Always use addHandler/removeHandler, and ensure your script checks whether it needs to attach a handler or not. In practice, test the handler list before and after reconfiguration.

We haven’t introduced any library-owned handlers, so we didn’t need to clean those out. In a real application, we’d identify each handler by name or ID before adding or removing.

Build the complete event-to-sink evidence ledger

Finally, we compile all data to make a pass/fail determination. We recorded the Python build (3.13.5 on Arch Linux x86_64) and each test’s configuration. Below is a summary table of expected vs observed counts of I1 (INFO) and E1 (ERROR) for sink 0 in each case:

(Pass means meets policy.)

All observed counts were exactly as expected from our separate runs. We ensured every intended event was either present or explicitly absent: for example, in cases 3–4 the INFO count is explicitly zero (and is indeed observed as zero). We did not see any extraneous handlers or routes. Each test reset the logging graph so that no hidden state (like a leftover handler from a prior test) affected the results. In this controlled lab environment there were no unknown or asynchronous routes (we did not invoke any network or file handlers), so we had full confidence in the ledger.

Do not deduplicate by message text

Notice that we used numeric event_id values. This is important: if we had relied on comparing message text or logger name, we might miscount duplicates or separate events. For instance, one event ID “I1” appearing twice (as in Case 2) is a duplicate route, not two events. Conversely, two separate events could have the same message template but different IDs; we treat them distinctly. Our final check keys off the tuple (event_id, sink_id). Only when the count in the ledger matches the expected count for each tuple do we consider the policy satisfied.

Add positive controls and unexplained-route failures

Besides the child-originated INFO/ERROR events, we also tested negative controls. No DEBUG-level event ever appears in any ledger, confirming that source-level filtering worked (DEBUG was always below the origin logger’s level and thus blocked). We also sent one direct root ERROR (e.g. logger = logging.getLogger(); logger.error("X", extra={"event_id":"R2"})) as a positive control. In a correct configuration with a handler on the root or a propagating child, that R2 should appear once. It did, verifying that our test harness sees expected root events.

We did not encounter any unexpected handlers or filters in the baseline. If, hypothetically, an unknown handler had been present (for example, if a framework had installed one), we would mark the configuration invalid (HOLD) and require an explicit decision on what to do (we did not test that scenario here). Throughout, we kept collection synchronous and in-process: we did not involve any asynchronous queues, external transports or file rotation. Those out-of-scope factors could affect real durability, but they do not change our acceptance of the local logging policy.

Decide whether the configured policy passes

We now evaluate each scenario against the declared policies. A policy passes only if every (event_id, sink) pair has exactly the approved multiplicity. Otherwise we must either REPAIR or HOLD. Here are the outcomes:

•   Case 1 (root-only INFO handler): Under Policy A this is acceptable (INFO & ERROR each appeared once). Under Policy B it fails (an INFO appeared, which Policy B forbids).

•   Action: If Policy A is intended, ACCEPT. If Policy B is intended, REPAIR by suppressing INFO (for example, by raising handler level or removing this route).

•   Case 2 (duplicate child+root handlers): Both policies fail (each event appeared twice). This is a routing defect, not a simple threshold issue.

•   Action: REPAIR by removing one of the duplicate routes (either drop the child handler or the root handler) so that only a single path to the sink remains. This is a clear configuration bug.

•   Case 3 (root ERROR-only handler): Passes Policy B (ERROR only, count 1). Fails Policy A (INFO missing).

•   Action: For Policy B, ACCEPT (no change needed). For Policy A, REPAIR by allowing an INFO route (e.g. add a child handler or lower the handler level back to INFO).

•   Case 4 (child NOTSET, root INFO handler): Same outcome as Case 3: it effectively allowed only ERROR.

•   Action: As in Case 3.

•   Case 5 (child-only INFO handler, no propagation): Passes Policy A, fails B (INFO appears).

•   Action: If A is intended, ACCEPT. If B is intended, REPAIR by raising the child handler’s level to ERROR.

No unapproved paths were found in our lab: all ledger entries were for explicitly added handlers. If any record had turned up via an untracked handler, we would mark HOLD (unknown ownership) and investigate rather than automatically deleting it.

Separate routing acceptance from historical reconciliation

In our terminology, ACCEPT means the current configuration meets the chosen policy going forward. REPAIR means code or config changes are needed to fix mismatches (e.g. remove or reconfigure a handler). HOLD means we lack clarity on who owns an output route. RECONCILE refers to any needed historical fix (e.g. if logs were missing or duplicated before this fix). Importantly, a successful ACCEPT does not retroactively fix past logs. If, say, INFO messages were missing before, that’s a reconciliation issue outside this local check. Our decision criteria focus solely on new events in the live system after deployment.

Roll out and roll back without losing ownership

Before applying changes in production, maintain a versioned snapshot of the logging graph and the intended policy. For each release, re-run a quick sanity test: configure the handlers as deployed, emit a test INFO and ERROR for each relevant logger, and verify the ledger matches expected counts. If an essential sink stops receiving events (for example, if a handler is inadvertently removed), halt the rollout. In practice, one can automate this test in a staging environment.

Moreover, assign clear ownership of each logging endpoint: e.g., the backend team owns the service’s log config, while the observability team might own the log-collector-side configuration. Avoid letting unrelated libraries silently configure your logs. The logs must be treated as a controlled output, and any change to logging config should require review, much like a database schema change. The operational logging and recovery practice reminds us that system logging is a crucial admin function. Just as one would not update a database schema without backward compatibility checks, do not roll out log config changes without ensuring all destinations still get their intended records.

In a rollback scenario, revert both code and logging graph to the previous known-good state. Retain the prior configuration file or handler code so you can restore it. Then re-test the policy with the old graph before letting traffic resume, ensuring you truly recovered the original behavior.

Strengthen the backend debugging foundations

Local traceability like this is part of robust backend debugging practice. Understanding exactly how log records flow (or don’t) into each sink can prevent costly gaps in observability. For those looking to build these skills formally, Refonte Learning’s Backend Developer Program offers three months of practical training (10–12 hours/week) in backend systems, testing, and debugging. It covers core backend technologies (APIs, databases, logging, testing and deployment) under expert mentorship, culminating in a completion certificate. Interested readers might consider Backend Developer Program to deepen their skills in testing and system observability.