Python Testing & Debugging Beyond unittestAdvanced Python testing playbooks
Debugging & Performance

Structured Logging That Survives pytest Capture

Structured logging is at its most useful when something goes wrong in a test — the fields say which request, which user, which retry — and that is exactly when it tends to be missing. A service configured to write JSON lines to stdout through structlog shows nothing in caplog. A handler created at import time with logging.StreamHandler(sys.stderr) writes to the real stderr, bypassing pytest's capture, so its output interleaves with the progress dots and is never attached to the failing test. Tests that try to assert "a warning was logged with order_id=42" end up grepping rendered strings, which breaks the first time someone changes the renderer.

None of this is a pytest bug. pytest provides a capture handler on the root logger and redirects the standard streams; logs that go through the standard logging tree are captured, shown for failures and available to caplog. Logs that take another route are not. Getting structured logging to cooperate is a matter of making sure, in tests, every event goes through that tree — and then asserting on fields rather than strings.

Prerequisites

Solution

Python
# app/logging_setup.py — one configuration used by the app and by tests.
import logging
import structlog

def configure(json: bool = True) -> None:
    structlog.configure(
        processors=[
            structlog.contextvars.merge_contextvars,
            structlog.processors.add_log_level,
            structlog.processors.TimeStamper(fmt="iso"),
            structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
        ],
        logger_factory=structlog.stdlib.LoggerFactory(),     # → stdlib logging tree
        wrapper_class=structlog.stdlib.BoundLogger,
        cache_logger_on_first_use=False,                     # tests reconfigure
    )
    renderer = structlog.processors.JSONRenderer() if json else structlog.dev.ConsoleRenderer()
    handler = logging.StreamHandler()                        # resolves sys.stderr at emit time
    handler.setFormatter(structlog.stdlib.ProcessorFormatter(processor=renderer))
    root = logging.getLogger()
    root.handlers[:] = [handler]
    root.setLevel(logging.INFO)
Python
# conftest.py
import pytest
from app.logging_setup import configure

@pytest.fixture(autouse=True, scope="session")
def _logging():
    configure(json=False)            # readable output in failure reports
Python
# test_orders.py — asserting on fields, two ways.
import logging
import structlog

def test_rejected_order_logs_reason(caplog):
    caplog.set_level(logging.WARNING, logger="app.orders")
    submit_order(order_id=42, qty=0)
    [rec] = [r for r in caplog.records if r.name == "app.orders"]
    assert rec.msg["event"] == "order_rejected"
    assert rec.msg["order_id"] == 42

def test_rejected_order_logs_reason_capture_logs():
    with structlog.testing.capture_logs() as events:
        submit_order(order_id=42, qty=0)
    assert {"event": "order_rejected", "order_id": 42, "reason": "qty"}.items() <= events[0].items()
Log routes that pytest can and cannot see Three routes for a log event. structlog's default PrintLogger writes straight to stdout and never reaches caplog. A handler bound to sys.stderr at import time bypasses capture. Routing structlog through the stdlib logging tree reaches the root logger, where pytest's capture handler and caplog see every event. Only one route reaches caplog structlog PrintLogger handler(sys.stderr) at import structlog → stdlib logger real stdout/stderr not attached to test root logger pytest capture caplog · failure report
Anything that bypasses the standard logging tree is invisible to caplog and missing from failure reports.

Why this works

pytest's logging plugin adds two handlers to the root logger for each test: one that feeds caplog, and one that collects records for the report section shown on failure. Any record that propagates to the root logger reaches both. structlog.stdlib.LoggerFactory() makes every structlog logger a thin wrapper around a standard logging.Logger, so structlog events become log records, propagate, and are captured like any other.

ProcessorFormatter.wrap_for_formatter keeps the event dictionary intact on the record — as record.msg — until a handler's formatter renders it. That is why the first test can read rec.msg["order_id"] directly: the structure survives until rendering, and caplog's handler does not render. The JSON renderer only runs in the stream handler, so production output is unchanged.

The stream handler is created without an explicit stream, which makes it resolve sys.stderr at emit time rather than at construction. When pytest swaps sys.stderr for its capture buffer, the handler follows. A handler constructed as StreamHandler(sys.stderr) at import captures the original stream object and keeps writing to the terminal regardless.

Seeing logs while debugging

Captured logs appear in the "Captured log call" section of a failing test's report, which is usually enough. When debugging a hang or a slow test, it is more useful to watch logs live:

Bash
pytest -o log_cli=true -o log_cli_level=DEBUG -k test_checkout -s

log_cli streams records to the terminal as they are emitted, with its own format controlled by log_cli_format. Combined with the console renderer in tests, the output is readable key-value lines rather than dense JSON. For CI, where logs are read after the fact, keep the default capture and add -rA to include captured logs for passing tests in the summary when needed.

Choosing how to view test logs Three viewing modes are compared. Default capture shows logs only for failing tests in the report. log_cli streams logs live to the terminal, useful for hangs. The -rA flag adds captured logs for passing tests to the end-of-run summary, useful in CI archives. Three ways to read the same records default capture shown for failures only everyday runs log_cli=true streamed live hangs and slow tests -rA passing tests too CI archives
All three read the same captured records; only the moment and place they are shown differ.

Asserting on logs without making tests brittle

Once logs are capturable, there is a temptation to assert on all of them, and suites that do end up breaking every time someone rewords a message. Log assertions are worth writing only where the log is the behaviour: an audit event that compliance depends on, a warning that operators alert on, a security event that must include the actor's identity. Everywhere else, logs are diagnostics, and tests should not pin them.

When a log is part of the contract, assert on the fields that carry meaning and ignore the rest. The subset comparison in the second test above — the expected dictionary's items are a subset of the event's items — does exactly that: it checks event, order_id and reason, and stays green when someone adds a request_id or changes the timestamp format. Assert on the event name rather than a human-readable message; event names are identifiers and change rarely, messages are prose and change often.

For negative assertions — "no error was logged during this operation" — filter by level rather than by content: assert not [r for r in caplog.records if r.levelno >= logging.ERROR]. That catches unexpected errors from any logger, including libraries, which is often the most valuable log assertion a test can make. An integration test that passes while the HTTP client logged three connection-reset errors is hiding a problem, and a level-based check surfaces it without knowing anything about the client's messages.

A shared helper keeps these patterns consistent across a suite. A fixture that yields structlog.testing.capture_logs() events, plus a function assert_logged(events, event=..., **fields) that performs the subset match and prints all captured events on failure, makes the intent of each assertion obvious and the failure output useful.

What to assert about logs Two columns contrast log assertions. Worth asserting: event names and meaningful fields for audit, alerting and security events, and the absence of error-level records. Not worth asserting: full rendered message strings, timestamps, field order and incidental diagnostic logs. Pin the contract, not the prose assert event name: "order_rejected" meaningful fields as a subset audit, alert and security events no records at ERROR or above leave alone full rendered message strings timestamps and field order incidental debug logs exact count of info records
Assertions on the left survive renderer changes and rewording; those on the right break on both.

Correlating log lines with the test that produced them

In a large suite, especially under pytest-xdist, logs from many tests end up in the same CI output, and matching a log line to the test that emitted it is tedious. Binding the test's node id into the logging context fixes that with a few lines:

Python
@pytest.fixture(autouse=True)
def _bind_test_id(request):
    structlog.contextvars.bind_contextvars(test=request.node.nodeid)
    yield
    structlog.contextvars.clear_contextvars()

Every event emitted during the test now carries a test field, rendered in both the console and JSON formats. When logs are shipped from CI to a log store, filtering by that field reconstructs the exact sequence of events for one failing test, even when it ran interleaved with dozens of others on the same worker. The clear_contextvars call at teardown also fixes the leak described in the edge cases below, so the fixture pays for itself twice.

The same idea extends to request-scoped identifiers. If the code under test binds a request_id at the start of each request, a failing integration test's captured logs show every event for that request together, and the id links those logs to the matching spans when tracing is also enabled. Together, the test id and the request id give two levels of grouping — which test, and which request within that test — which is usually all that is needed to turn a wall of interleaved CI output into a readable story of what happened before the failure.

Edge cases and failure modes

  • cache_logger_on_first_use=True in tests. Loggers bound before capture_logs or reconfiguration keep the old processors. Disable caching in tests.
  • Libraries that call logging.basicConfig. A stray basicConfig adds a handler bound to stderr. Reset root handlers in your configuration function, as above.
  • Propagation disabled. A logger with propagate = False never reaches the root, so caplog misses it. Enable propagation or attach caplog.handler to that logger in the test.
  • Level filtering. caplog records only what passes both the logger level and the handler level. Use caplog.set_level(..., logger=...) for the specific logger under test.
  • Contextvars leaking between tests. structlog.contextvars.bind_contextvars state persists across tests in the same thread. Call clear_contextvars() in a fixture.

Frequently Asked Questions

Why is caplog empty when my code uses structlog? structlog's default configuration prints directly to stdout instead of going through the standard logging module, so pytest's caplog handler never sees the events. Configure structlog to render through stdlib logging in tests, or use structlog.testing.capture_logs.

Why do my logs disappear when a test passes? pytest captures log records and only shows them in the report for failing tests. Use -o log_cli=true to stream logs live, or -rA to show captured output for passing tests too.

How do I assert on structured log fields? With stdlib logging, read record attributes from caplog.records, where fields passed via extra appear as attributes. With structlog, capture_logs returns a list of event dictionaries you can assert on directly.

← Back to Logging and Observability for Debugging