Fix Duplicate Python Logs: Repeated Handlers and Logger Propagation

A script calls logger.info() once, but the terminal prints it twice. Calling the initialization function again adds even more copies. This tutorial helps beginner-to-intermediate readers reproduce two causes with the Python standard library, then verify that one business event produces one log record.

If records arrive late, start with Python output buffering troubleshooting. Here we investigate repeated output for the same event. No third-party packages are needed.

1. Choose a method: locate the extra handler path

Two common paths cause duplication:

1. An initialization function creates a new handler each time and attaches it to the same logger.
2. A child logger has its own handler and also propagates the record to a root handler.

The official Python documentation explains that handlers on both a logger and its ancestors can produce duplicate output. Inspect the path, then choose application-level configuration or an independent logger that owns its output.

2. Prepare the environment

Use Python 3.9+ with no third-party dependencies. The examples were tested on Linux with Python 3.11.4. Shell commands work in Bash and zsh.

1. Create a fresh practice directory:

python3 --version
mkdir duplicate-log-demo
cd duplicate-log-demo

2. Save the following code as logging_demo.py. Each command starts a fresh Python process so configuration from an earlier experiment cannot carry over.

3. Complete implementation: reproduce and fix

"""Reproduce and fix duplicate logs in a fresh Python process."""
import argparse
import logging

FORMAT = "%(levelname)s %(name)s %(message)s"


def add_console(logger):
    handler = logging.StreamHandler()
    handler.setFormatter(logging.Formatter(FORMAT))
    logger.addHandler(handler)


def local_logger():
    logger = logging.getLogger("demo.task")
    logger.setLevel(logging.INFO)
    logger.propagate = False
    if not logger.handlers:
        add_console(logger)
    return logger


def inspect_chain(logger):
    while logger is not None:
        levels = [logging.getLevelName(h.level) for h in logger.handlers]
        print(f"{logger.name}: handlers={len(logger.handlers)} "
              f"handler_levels={levels} propagate={logger.propagate} "
              f"effective={logging.getLevelName(logger.getEffectiveLevel())}")
        if not logger.propagate:
            break
        logger = logger.parent


def main():
    parser = argparse.ArgumentParser(description=__doc__)
    parser.add_argument("mode", choices=[
        "repeat", "propagate", "fixed-root", "fixed-local",
    ])
    parser.add_argument("--inspect", action="store_true")
    args = parser.parse_args()
    logger = logging.getLogger("demo.task")
    logger.setLevel(logging.INFO)

    if args.mode == "repeat":
        logger.propagate = False
        for _ in range(2):
            add_console(logging.getLogger("demo.task"))
    elif args.mode == "propagate":
        logging.basicConfig(level=logging.WARNING, format=FORMAT)
        add_console(logger)
    elif args.mode == "fixed-root":
        for _ in range(2):
            logging.basicConfig(level=logging.INFO, format=FORMAT)
    else:
        for _ in range(2):
            logger = local_logger()

    if args.inspect:
        inspect_chain(logger)
    logger.info("job=42 completed")
    return 0


if __name__ == "__main__":
    raise SystemExit(main())

1. Read the help and run both failure modes:

python3 logging_demo.py --help
python3 logging_demo.py repeat
python3 logging_demo.py propagate

Each failure command prints two lines:

INFO demo.task job=42 completed
INFO demo.task job=42 completed

repeat creates a new StreamHandler on each call. The named logger is reused, leaving it with two handlers. In propagate, the record reaches both the local handler and the root handler.

2. Inspect the propagation chain:

python3 logging_demo.py repeat --inspect
python3 logging_demo.py propagate --inspect

The first reports demo.task: handlers=2; the second shows one handler on each of demo.task and root. Diagnostics go to stdout and logs to stderr. Do not rely on the terminal’s relative display order for these two streams.

The propagate mode deliberately sets the root logger to WARNING, yet INFO still appears twice. Propagated records bypass ancestor logger levels. To restrict a destination, set its handler level. Check effective logger and handler levels with the logging level API reference.

4. Two fixes: choose who owns configuration

Method 1: configure logging at the application entry point

python3 logging_demo.py fixed-root --inspect

demo.task has no local handler and root has one, so the record appears once. Configure basicConfig() at the standalone script’s entry point; business modules only obtain loggers and emit records. The demo deliberately calls configuration twice: ordinary basicConfig() does nothing when root already has handlers, as described in the official reference.

When migrating an existing program, remove redundant console-handler initialization from business modules and restart the process. This example does not remove old handlers from a running service.

Method 2: let an independent logger own its output

python3 logging_demo.py fixed-local --inspect

local_logger() adds a handler only when none is directly attached and sets propagate = False. Use this for an independent logging channel owned by your application. For file retention, continue with size-based log rotation using RotatingFileHandler.

Here logger.handlers lists directly attached handlers. hasHandlers() can also find ancestor handlers, so it does not establish whether this logger has its own configuration. See its API lookup rules.

Run this simple check-and-add setup in one thread during startup, outside concurrent work loops. Choose one method. Reusable libraries generally obtain named loggers and leave output configuration to the application; see the library logging guide.

5. Verify actual output and exit codes

Save this as check_logging.py and run python3 check_logging.py in the same directory:

import subprocess
import sys

expected = "INFO demo.task job=42 completed"
for mode, count in [
    ("repeat", 2), ("propagate", 2),
    ("fixed-root", 1), ("fixed-local", 1),
]:
    result = subprocess.run(
        [sys.executable, "logging_demo.py", mode],
        capture_output=True, text=True, timeout=5, check=True,
    )
    assert result.stdout == "", (mode, result.stdout)
    assert result.stderr.splitlines() == [expected] * count, (
        mode, result.stderr,
    )
    print(f"PASS {mode}: {count} record(s)")

invalid = subprocess.run(
    [sys.executable, "logging_demo.py", "unknown"],
    capture_output=True, text=True, timeout=5,
)
assert invalid.returncode == 2
assert "invalid choice" in invalid.stderr
print("PASS invalid mode: exit=2")

Expected output:

PASS repeat: 2 record(s)
PASS propagate: 2 record(s)
PASS fixed-root: 1 record(s)
PASS fixed-local: 1 record(s)
PASS invalid mode: exit=2

The check starts isolated subprocesses and verifies exact content, record counts, and invalid-argument exit status. Merely finishing without an exception is insufficient. A default StreamHandler writes to stderr, which is why the check reads result.stderr.

6. Troubleshooting and direct fixes

force=True removes and closes existing root handlers; it does not remove child handlers. It is not a general deduplication switch. Different process IDs suggest duplicate launches. If the raw log has one copy but a viewer shows two, inspect collection paths. Use the rg log triage workflow to compare raw files before deduplicating message text and hiding real repeated execution.

Summary

Inspect local handler counts and the propagation chain, then decide whether the entry point or an independent channel owns output. Verify exact record counts in fresh processes and check that repeated initialization does not add handlers. Multiple job processes and duplicate collection require tracing the source beyond propagation settings.