Record Logger Identity Before You Touch basicConfig

Record logger identity before moving any setup function. Return-value tests miss duplicate handlers after extracts.

Named loggers, handler counts, and propagate flags are the contract. Treat that tree as frozen input, not style.

The failure mode

Messy repos call basicConfig at import time. They also call getLogger with inconsistent names. A cleanup extract often wraps setup in a function.

The new function runs on every import path. Root then gains a second StreamHandler instance.

Files receive every line twice after the move. Stdout tests still pass if they join streams loosely.

A later package split can change import order too. The second import repeats setup without any traceback.

Pin the tree, not the log text

Do not pin log text alone for this refactor. Text can match while the tree still changed.

Capture each logger name present after import. Capture the effective level for every named logger.

Count handlers on root and on each named logger. Record each handler class, not its repr memory address.

Record formatter fmt and datefmt when a formatter exists. Record the propagate flag on every named logger.

Record the disabled flag on those same loggers. Record attached filter classes by class name only.

Why class names beat object reprs

Handler reprs include ids that change every process. Characterization must ignore identity and keep type.

Formatter strings are data, unlike memory addresses. Drop stream object ids from the snapshot as well.

Root is named "root" in the logging module. Do not rewrite that name in the fixture.

Example messy module

The module below is illustrative. Copy it before you run any test.

# messy_report.py — example only, not production history
import logging

LOG = logging.getLogger("report.core")


def _setup() -> None:
    logging.basicConfig(
        level=logging.INFO,
        format="%(levelname)s %(name)s %(message)s",
    )
    LOG.setLevel(logging.DEBUG)
    LOG.propagate = True


_setup()


def build_summary(rows: list) -> dict:
    LOG.debug("row_count=%s", len(rows))
    if not rows:
        LOG.warning("empty input")
        return {"count": 0, "ok": False}
    LOG.info("ok count=%s", len(rows))
    return {"count": len(rows), "ok": True}


if __name__ == "__main__":
    print(build_summary([1, 2, 3]))

Import of this module configures logging immediately. That is the behavior under characterization.

build_summary return values are the wrong contract here. The logging tree is the contract.

Characterization harness

Snapshot the tree in a subprocess, not the test process. Import-time basicConfig would otherwise leak across tests.

The script below is a proposal. Run it with a current CPython interpreter.

# snap_logging_tree.py — example characterization harness
from __future__ import annotations

import json
import logging
import runpy
import sys
from pathlib import Path


def snapshot() -> dict:
    loggers = [logging.getLogger()]
    manager = logging.Logger.manager
    for name in sorted(manager.loggerDict):
        obj = manager.loggerDict[name]
        if isinstance(obj, logging.Logger):
            loggers.append(obj)
    rows = []
    for lg in loggers:
        handlers = []
        for handler in lg.handlers:
            fmt = handler.formatter
            handlers.append(
                {
                    "class": type(handler).__name__,
                    "level": int(handler.level),
                    "fmt": None if fmt is None else getattr(fmt, "_fmt", None),
                    "datefmt": None if fmt is None else fmt.datefmt,
                }
            )
        rows.append(
            {
                "name": lg.name,
                "level": int(lg.level),
                "effective": int(lg.getEffectiveLevel()),
                "propagate": bool(lg.propagate),
                "disabled": bool(lg.disabled),
                "handler_count": len(lg.handlers),
                "handlers": handlers,
                "filter_classes": [type(f).__name__ for f in lg.filters],
            }
        )
    return {"loggers": rows}


def main() -> None:
    root = Path(sys.argv[1]).resolve()
    sys.path.insert(0, str(root))
    runpy.run_module("messy_report", run_name="not_main")
    json.dump(snapshot(), sys.stdout, indent=2, sort_keys=True)
    sys.stdout.write("\n")


if __name__ == "__main__":
    main()

Pass the directory that contains messy_report.py. Keep stdout as pure JSON.

python snap_logging_tree.py . > logging_tree.json
python snap_logging_tree.py . > logging_tree_2.json
python -c "from pathlib import Path; a=Path('logging_tree.json').read_bytes(); b=Path('logging_tree_2.json').read_bytes(); raise SystemExit(a!=b)"

Exit status zero means two clean processes agreed. Nonzero means the snapshot still contains noise.

Workflow

1. Inventory every setup call

Search for basicConfig, dictConfig, and fileConfig. Search also for addHandler and setLevel.

python -c "import pathlib,re; p=pathlib.Path('.'); keys=('basicConfig','dictConfig','fileConfig','addHandler','setLevel','getLogger');
[print(f'{k}:{sum(1 for _ in path.read_text(errors=\"ignore\").splitlines() if k in _)}') for k in keys for path in p.rglob('*.py') if path.is_file()]"

Record each getLogger name as a literal string. Do not normalize names during this inventory.

2. Freeze one snapshot on a clean process

Run the snapshot script twice on the same commit. The JSON documents must match byte for byte.

If they differ, you still have process-global noise. Remove time, pids, and stream ids first.

Do not pretty-print with unsorted keys in fixtures. sort_keys=True keeps diffs readable and stable.

3. Store the snapshot as a committed fixture

Keep the JSON next to the test, not in /tmp. Reviewers then see tree drift as a diff.

A pytest check can load that fixture. Keep the assertion on the parsed object, not on log text.

# test_logging_tree.py — example, unexecuted until copied
import json
import subprocess
import sys
from pathlib import Path

FIXTURE = Path(__file__).with_name("logging_tree.json")


def test_import_logging_tree_matches_fixture(tmp_path):
    proc = subprocess.run(
        [sys.executable, "snap_logging_tree.py", "."],
        check=True,
        capture_output=True,
        text=True,
    )
    got = json.loads(proc.stdout)
    expected = json.loads(FIXTURE.read_text())
    assert got == expected

Failing equality is the refactor signal. Do not weaken it with subset checks.

4. Add the one-shot guard before any extract

The smallest safe change is a one-shot guard. It prevents a second basicConfig during later moves.

# example seam, still inside messy_report.py
_configured = False


def _setup() -> None:
    global _configured
    if _configured:
        return
    logging.basicConfig(
        level=logging.INFO,
        format="%(levelname)s %(name)s %(message)s",
    )
    LOG.setLevel(logging.DEBUG)
    LOG.propagate = True
    _configured = True

Re-run the snapshot after the guard lands. The tree must match the committed fixture exactly.

If handler_count rises, the guard did not run first. Fix the guard before any file move.

5. Move one function only after the guard holds

Extract configure_logging into a sibling module next. Keep the import-time call in the original file.

Do not change logger names in the same patch. Do not alter format strings in that patch.

Re-run the snapshot. Handler classes and counts must stay identical.

A return-value test on build_summary is extra, not sufficient. Keep it after the tree assertion.

6. Ask a model for the extract only after pins exist

A model can draft the extract patch later. Do that only after the pin tests exist.

Disclosure: This article was prepared as part of MonkeyCode's product outreach. MonkeyCode offers free model access and a free server option.

Use that server to rerun this same harness. Treat model output as a diff, never as truth.

7. Compare trees across two environments

Run the same snapshot on a second machine. Path separators must not leak into logger names.

If they do, your format string is encoding filesystem data. Split that concern before the extract.

Locale can change formatted exceptions inside handlers. Keep exceptions out of this tree fixture.

Decision table

Use the table as the merge checklist. One "yes" column is the allowed surface.

Observation	Change in the extract PR?	Reason
logger name	No	Call sites bind to the name
handler_count	No	Duplicates mean double I/O
handler class	No	Stream versus File is visible
formatter fmt	No	Downstream parsers depend on it
propagate	No	Parents would double-emit
disabled	No	Silent loggers are behavior
one-shot guard	Yes	Prevents re-entry, same tree
function location	Yes	Allowed after the tree is pinned

If a patch needs two "No" rows, split the patch. Tree drift plus a move is two changes.

What this does not prove

This harness does not prove log text is useful. It only proves the tree stayed stable.

It does not prove thread safety under concurrent emits. It does not prove dictConfig YAML equivalence.

It does not pin QueueHandler listener processes. It does not pin syslog facility numbers.

Pytest caplog replaces handlers and will hide duplication. Run this snapshot outside caplog fixtures.

Custom logging.Filter instances may carry closures. Class names will not catch those closures.

Who should skip this approach

Skip this if the repo has no logging yet. Skip this if stdout is the only sink by contract.

Skip this if you plan to adopt structlog in the same PR. That mixes two behavior changes.

Skip this if configuration lives only in dictConfig files. Pin those files as data instead.

Do not use a model to invent logger names. Names are an external contract with operators.

Greenfield services with one JSON handler can wait. This workflow pays off on god scripts.

Close

Handler duplication is a behavior change, not style. Freeze the tree, then move one function.

Commit the pin fixture before you accept a generated patch.