Pin Log Records and Handler Order Before One Extract

Log setup extracts fail without a frozen record contract. Green assertion counts hide handler order and extra-field drift.

Pin the record contract first, then extract one factory. Skip every other cleanup until that test stays green.

The failure this workflow targets

Messy repos often configure logging inside business functions. A later extract moves basicConfig into a helper module. Tests still pass on message substrings after that move.

Handlers attached in a new sequence rewrite formatter output. Extra keys vanish when a filter moves with the helper.

Child loggers stop propagating after a propagate cleanup. Substring checks do not catch those silent breaks.

Record-level characterization tests catch that class of drift. They compare structure instead of a single haystack string.

What you freeze before any extract

Freeze five observables and leave the rest unconstrained. Unfrozen fields must be ones the extract will change.

1. Capture every logger name that emits during one command.
2. Assert level numbers, not only the level names.
3. Store getMessage text after argument interpolation finishes.
4. Record handler class order on each named logger.
5. Keep the extra keys your shipper actually consumes.

Do not freeze line numbers or created timestamps at all. Those values move when you extract a function body.

Do not freeze thread ids on a single-thread CLI. Those ids add noise without protecting the extract.

Do not freeze pathname or funcName across a helper move. The extract changes those attributes by definition.

Labeled messy module under test

The module below is a labeled synthetic example. It is not production telemetry and has no live credentials.

# messy.py — labeled example, not a live service
from __future__ import annotations

import logging
import sys


def ingest(path: str, verbose: bool) -> int:
    level = logging.DEBUG if verbose else logging.INFO
    logging.basicConfig(level=level)
    log = logging.getLogger("ingest")
    log.info("start path=%s", path)
    log.debug("verbose=%s", verbose)
    log.info("done rows=%s", 3)
    return 0


def main(argv: list[str] | None = None) -> int:
    argv = list(sys.argv[1:] if argv is None else argv)
    verbose = "--verbose" in argv
    path = "input.csv"
    if "--path" in argv:
        path = argv[argv.index("--path") + 1]
    return ingest(path, verbose)

One command path is enough for the first freeze. Ignore serve, migrate, and doctor until ingest is pinned.

Artifact: a record snapshot harness

The harness is a labeled, unexecuted camera. Copy it beside the messy module. Point the runner at one entry function.

# characterization_logging.py
from __future__ import annotations

import json
import logging
from dataclasses import asdict, dataclass
from typing import Any


@dataclass(frozen=True)
class RecordShot:
    name: str
    levelno: int
    message: str
    extra_keys: tuple[str, ...]


@dataclass(frozen=True)
class HandlerShot:
    logger_name: str
    handler_type: str
    formatter: str | None


class ListHandler(logging.Handler):
    def __init__(self) -> None:
        super().__init__()
        self.records: list[logging.LogRecord] = []

    def emit(self, record: logging.LogRecord) -> None:
        self.records.append(record)


def handler_shots() -> list[HandlerShot]:
    shots: list[HandlerShot] = []
    items: list[logging.Logger] = [logging.getLogger()]
    for value in logging.root.manager.loggerDict.values():
        if isinstance(value, logging.Logger):
            items.append(value)
    for item in items:
        for handler in item.handlers:
            fmt = None
            if handler.formatter is not None:
                fmt = getattr(handler.formatter, "_fmt", None)
            shots.append(
                HandlerShot(
                    logger_name=item.name or "root",
                    handler_type=type(handler).__name__,
                    formatter=fmt,
                )
            )
    return shots


def record_shots(records: list[logging.LogRecord]) -> list[RecordShot]:
    sample = logging.LogRecord("", 0, "", 0, "", (), None)
    reserved = set(sample.__dict__)
    out: list[RecordShot] = []
    for rec in records:
        extras = tuple(sorted(k for k in rec.__dict__ if k not in reserved))
        out.append(
            RecordShot(
                name=rec.name,
                levelno=rec.levelno,
                message=rec.getMessage(),
                extra_keys=extras,
            )
        )
    return out


def snapshot(run) -> dict[str, Any]:
    root = logging.getLogger()
    old_handlers = list(root.handlers)
    probe = ListHandler()
    probe.setLevel(logging.DEBUG)
    root.addHandler(probe)
    try:
        run()
        return {
            "records": [asdict(s) for s in record_shots(probe.records)],
            "handlers": [asdict(s) for s in handler_shots()],
        }
    finally:
        root.removeHandler(probe)
        root.handlers = old_handlers


def dump(path: str, data: dict[str, Any]) -> None:
    with open(path, "w", encoding="utf-8") as fh:
        json.dump(data, fh, indent=2, sort_keys=True)
        fh.write("\n")

That file is the contract camera only. It does not refactor the messy module.

Numbered workflow

1. Isolate one command path

Pick one argv vector and ignore sibling commands. Example vector: ingest, fixture path, and verbose. Mixing ingest with serve pollutes the gold file.

2. Capture a golden JSON fixture

Run the camera once against current main. Commit the JSON after a secret scan.

python -c "from characterization_logging import dump, snapshot; from messy import main; dump('gold_ingest_verbose.json', snapshot(lambda: main(['ingest', '--path', 'fixture.csv', '--verbose'])))"

Treat that file as a characterization oracle. Do not pretty-print it by hand later.

A trimmed gold file looks like this shape.

{
  "handlers": [
    {"formatter": null, "handler_type": "ListHandler", "logger_name": "root"}
  ],
  "records": [
    {"extra_keys": [], "levelno": 20, "message": "start path=fixture.csv", "name": "ingest"},
    {"extra_keys": [], "levelno": 10, "message": "verbose=True", "name": "ingest"},
    {"extra_keys": [], "levelno": 20, "message": "done rows=3", "name": "ingest"}
  ]
}

Level 20 is INFO in the standard library. Level 10 is DEBUG in the same table. See LogRecord attributes for the field list.

3. Assert the freeze in pytest

# test_ingest_logging_contract.py
import json
from pathlib import Path

from characterization_logging import snapshot
from messy import main

GOLD = Path(__file__).with_name("gold_ingest_verbose.json")


def test_ingest_verbose_log_contract() -> None:
    observed = snapshot(
        lambda: main(["ingest", "--path", "fixture.csv", "--verbose"])
    )
    expected = json.loads(GOLD.read_text(encoding="utf-8"))
    assert observed["records"] == expected["records"]
    assert observed["handlers"] == expected["handlers"]

Run one file, not the whole suite, on the first pass.

python -m pytest test_ingest_logging_contract.py -q

The test fails on reorder, drop, or extra-key loss. It stays silent on line number churn.

4. Draft assertions from the fixture

A free coding model can read the JSON fixture. It should not invent logger names you never captured.

Disclosure: This article was prepared as part of MonkeyCode's product outreach.

MonkeyCode's free model access and free server option can sit beside that fixture file. Paste the JSON and ask for pytest assertions only. Reject any suggestion that rewrites messy.py first.

Keep the model off the extract until the unrefactored module is green. That order is the method.

5. Make the smallest logger extract

Move one function and nothing else. Leave filters, propagate flags, and formatters in place.

# logging_setup.py — smallest extract after the contract is green
import logging


def configure_ingest_logging(verbose: bool) -> None:
    level = logging.DEBUG if verbose else logging.INFO
    logging.basicConfig(level=level)

Call that helper from the same ingest path. Run the contract test and stop on red. Do not clean filters in the same patch.

6. Re-record only after a deliberate contract change

If you intend a new log line, update gold alone. Do not mix gold updates with the extract commit. Bisect stays cheap when those diffs stay split.

Decision table

Symptom after extract	Frozen field that should catch it	Safe next step
Message text moved to another logger	name plus message	Restore the logger name, rerun gold
Debug lines vanished	levelno	Pin the verbose flag before the factory
JSON formatter lost request_id	extra_keys	Keep the filter on the original logger
Duplicate lines in CI	handlers order and types	Do not add a second basicConfig
Timestamps shifted by one second	none; created stays unfrozen	Ignore created; do not gold it

Substring checks accept each of those failures. Record shots reject them with a precise diff.

Why substring tests lie

assert "ingested" in caplog.text still counts as green. It accepts a WARNING that used to be INFO.

It accepts two handlers printing the same message. It accepts a missing extra key used by a shipper.

Record shots compare name, level, message, and extras. That is the data an extract needs.

Isolating process-global logging

logging.basicConfig is process-global by design. Tests must restore handlers after each case.

The snapshot function restores root.handlers in finally. Forked workers still need a fresh interpreter per case.

python -m pytest test_ingest_logging_contract.py --count=3 -q

Repeat local runs until the gold file is stable. Instability usually means an unfrozen timestamp or a second basicConfig.

If handler shots differ only by ListHandler, filter test-only types. Document that filter in the test module, not in production code.

loggerDict does not include the root logger. The harness adds root explicitly for that reason. PlaceHolder entries in loggerDict must be skipped.

Redaction before git add

Characterization will commit secrets if you skip review. Scan the gold file before the first commit.

1. Strip tokens, passwords, and session cookies.
2. Replace absolute home paths with a fixture token.
3. Drop hostnames, emails, and ticket identifiers.
4. Reject records that contain customer payload samples.

Split gold files by command, not by calendar day. Large oracles hide the one field you needed.

Limitations

This workflow does not prove log correctness. It only pins current behavior for one argv path.

Multi-thread emission order remains underspecified here. Do not gold interleaved worker records without a sort key.

The ListHandler probe can itself change handler order. Restore handlers, then compare against a filtered shot list.

MonkeyCode does not replace the freeze. A model that rewrites logging first will hide the drift the contract was meant to catch.

Python logging behavior is defined by the standard library, not by this harness. Confirm field names against the current docs before you freeze extras.

Who should not use this approach

Do not use this during an active production incident. Pinning records is slower than silencing a pager.

Do not use this to hide secrets in logs. Characterization will snapshot those secrets on disk.

Do not use this on libraries that must not configure logging. Library code should not call basicConfig at import time.

Do not use this if you cannot run the messy command locally. A fixture you cannot regenerate is not a contract.

Skip this when the goal is a new logging taxonomy. Characterization preserves the old taxonomy on purpose.

Practical bounds

One command path, one extract, one gold file. That batch size stays reviewable in a single diff.

Caplog remains useful for new behavior you intend. Characterization is for behavior you refuse to change yet.

After the factory extract stays green, stop. Do not rename loggers in the same change set.

Freeze records and handler order first. Extract one factory after the contract is green.

When the gold file is committed, the free server is enough to draft assertion stubs from that JSON. Leave timestamps and line numbers out of gold.