Python Observability

Asserting on Log Output with pytest caplog

pytest's caplog fixture is the natural tool for testing that code logs what it should, and it is frequently used in ways that make tests brittle or blind. This page covers what it captures and when, how to assert on the fields downstream systems depend on rather than on wording, the propagation setting that silently hides records from it, and the formatting stage it deliberately does not see. It is a task article under log testing and verification, part of the Python logging fundamentals and structured data section.

Where caplog listens A logger hierarchy is drawn with the root logger at the top, an application logger named billing beneath it, and a logger named audit that has its propagation disabled because it has its own file handler. caplog attaches a capturing handler to the root logger. A record logged to billing propagates up to root and is captured. A record logged to audit stops at audit's own handler and never reaches root, so caplog never sees it and a test asserting on it fails with an empty capture. A third path shows a record below the effective level being discarded at the logger before any handler is consulted. The note records that caplog captures LogRecord objects before any formatter runs, so it sees the fields the code supplied and never the bytes production emits. caplog listens at the root, and only there root logger caplog's handler billing propagate = True captured audit propagate = False stops at its own handler — never reaches root captured before any formatter runs — caplog sees the fields the code supplied, never the bytes you ship
Propagation decides whether caplog sees a record at all. The formatter never runs before capture, so caplog cannot tell you whether it works.

Prerequisites

pip install "pytest>=8.0.0,<9.0.0"

Implementation

Step 1 — Set the capture level on the logger under test. By default caplog captures at the root logger's effective level, which is usually WARNING. Info and debug records from the code under test are discarded before caplog sees them. Setting the level for the specific logger, rather than globally, captures what the test needs without filling the capture with every library's debug output.

import logging

def test_order_accepted_is_logged(caplog, order_service):
    caplog.set_level(logging.INFO, logger="orders")
    order_service.accept(order_id="ord_7")

Step 2 — Filter captured records by logger and level. During any non-trivial test, other code logs too — the framework, the database driver, an HTTP client. Asserting on the total number of captured records couples the test to all of them. Selecting the records from the logger under test, at the level of interest, keeps it about the behaviour being tested.

    accepted = [
        r for r in caplog.records
        if r.name == "orders" and r.levelno == logging.INFO
        and getattr(r, "event", None) == "order_accepted"
    ]
    assert len(accepted) == 1

Step 3 — Assert on attributes, not on the rendered message. Fields passed through extra become attributes of the LogRecord. Asserting on them directly is both simpler than parsing the message and far more stable, because they are the contract that dashboards and alert rules use. The message text is free to change.

    record = accepted[0]
    assert record.order_id == "ord_7"
    assert record.event == "order_accepted"
    assert isinstance(record.amount_cents, int)       # type matters to the index

Step 4 — Check exception information when the call should carry a traceback. A call that should use log.exception but uses log.error produces a record with no traceback, and the difference only matters during an incident. Asserting on exc_info catches it.

def test_gateway_timeout_logs_the_exception(caplog, payment_service, gateway):
    caplog.set_level(logging.ERROR, logger="billing")
    gateway.fail_with(TimeoutError("read timed out"))

    payment_service.charge(order_id="ord_9", amount=100)

    (record,) = [r for r in caplog.records if r.name == "billing"]
    assert record.exc_info is not None, "use log.exception so the traceback is kept"
    assert record.exc_info[0] is TimeoutError

Expected Output: a failure that names the fix when someone replaces exception with error.

FAILED test_billing_logging.py::test_gateway_timeout_logs_the_exception
AssertionError: use log.exception so the traceback is kept

Step 5 — Make sure the logger propagates. If a logger is configured with its own handlers and propagate: False, records stop there and caplog — attached at the root — never sees them. The test fails with an empty capture and the logging looks broken when it is working exactly as configured. Either assert on that logger's own handler in the test, or temporarily enable propagation for the duration of the test.

@pytest.fixture
def propagate(monkeypatch):
    def _enable(name: str):
        monkeypatch.setattr(logging.getLogger(name), "propagate", True)
    return _enable

def test_audit_event(caplog, propagate, admin_service):
    propagate("audit")
    caplog.set_level(logging.INFO, logger="audit")
    admin_service.delete_user("u_42")
    assert any(getattr(r, "action", None) == "user_deleted" for r in caplog.records)

Step 6 — Clear between phases of a longer test. A test that performs several operations and asserts on each should clear the capture between them, so each assertion sees only the records from its own phase. Without it, an assertion that an event did not happen can be satisfied or violated by records left over from an earlier step, which produces exactly the kind of flaky failure that erodes trust in a suite.

    caplog.clear()
    order_service.cancel(order_id="ord_7")
    assert any(getattr(r, "event", None) == "order_cancelled" for r in caplog.records)
Assert on the contract, not the prose One log record is shown with its message text and three structured attributes. A test that asserts on the message text — an exact string match against the words used — breaks when a developer rewords the message for clarity, which happens frequently and for good reasons, and passes when a field an alert rule depends on is removed, because the message still reads the same. A test that asserts on the level, the logger name and the event and order identifier attributes survives any rewording and fails exactly when the field the alert rule uses disappears. The annotation records that the first kind of test is eventually deleted as noise and the second kind is the only one that protects anything downstream. one record, two ways to test it level=INFO name=orders msg="Order ord_7 accepted" event=order_accepted order_id=ord_7 amount_cents=4200 assert msg == "Order ord_7 accepted" breaks when the wording improves passes when event= is removed eventually deleted as noise assert r.event == "order_accepted" survives any rewording fails when the alert's field goes protects what depends on it
A message-text assertion fails for the wrong reasons and passes for the wrong reasons. A field assertion does neither.

What caplog does not tell you

It is worth being clear about the limits, because a green caplog suite is easy to mistake for evidence that logging works end to end.

It does not run your formatter. caplog's handler formats with its own simple format for its text property; your production formatter — JSON, field renaming, timestamp handling — never runs. A formatter that raises on every record, or that silently drops a field, passes every caplog test. Testing the formatter needs the real handler chain and a captured output stream, as described in snapshot testing structured log output.

It does not run your filters. Filters attached to your handlers — redaction, rate limiting, sampling — are skipped, because caplog attaches its own handler. A test asserting that a secret is absent from a caplog record proves nothing about whether it reaches the output. Redaction filters attached to loggers rather than handlers do run, which is one argument for attaching them there.

It does not see non-propagating loggers. As in step 5. This is the most common reason for a caplog test that "cannot see" a log statement that obviously executes.

It sees records from every thread. Background threads that log during the test contribute records. That is usually harmless when records are filtered by logger name and troublesome when a test asserts on counts.

Within those limits, it is exactly the right tool for the question it answers: did this code path produce this event, at this level, with these fields.

Testing structlog through caplog

Services using structlog can use caplog as well, provided structlog is configured to hand its events to the standard library rather than rendering and printing them itself. The pattern is to route structlog through a standard library logger with a formatter that renders at the handler, which is the same arrangement recommended for production in migrating from standard logging to structlog.

With that arrangement, a structlog call produces a standard LogRecord whose message is the event dictionary. caplog captures it like any other record, and the structured fields are available on the record — either as the message dictionary itself or, with the appropriate processor, as record attributes. Assertions then look the same as for standard library logging, and the tests do not care which library produced the event.

Where structlog is configured to print directly, bypassing the standard library, caplog sees nothing at all. structlog provides its own capture helper for that case, which records the event dictionaries directly and supports the same style of field assertions. The choice between the two follows the production configuration: test through the path production actually uses, so the test exercises the same routing that will run in the service.

A small shared helper that extracts the event dictionary from a captured record, regardless of which library produced it, keeps assertions uniform across a codebase that uses both — which is common during a migration and worth making painless.

Which fixture for which question A table of pytest's output-capturing fixtures and the question each answers. caplog captures LogRecord objects from the logging module before formatting, answering what was logged, at which level, with which extra fields. capsys captures text written to stdout and stderr, answering what the configured handler actually printed, formatting included. capfd captures at the file-descriptor level, including output from subprocesses and C extensions. A custom in-memory handler attached in a fixture captures records for a specific logger with a specific formatter. The note says caplog tests what the code logs; capsys tests what the configuration emits, and both are worth having. fixture captures answers caplog LogRecords, before formatting what the code logged capsys stdout and stderr text what the handler printed capfd file descriptors includes subprocesses custom handler records for one logger with a chosen formatter caplog tests what the code logs; capsys tests what the configuration emits
caplog sees records before formatting, capsys sees what reached the terminal. Each catches mistakes the other cannot.

Configuration options

caplog feature Use Note
set_level(level, logger=…) capture below the root's level scoped to one logger; reset after the test
records the LogRecord objects assert on attributes
record_tuples (name, level, message) quick checks; message is fragile
text caplog's own formatting not your production format
clear() reset between phases isolates assertions
at_level(...) a context manager temporary level for a block

Verification

Confirm the test would actually fail if the event were removed — the check most logging tests never get.

# temporarily comment out the log call in the code under test, then:
pytest tests/test_order_logging.py -q

Expected Output: a failure, which proves the test is testing something.

F
FAILED tests/test_order_logging.py::test_order_accepted_is_logged
assert 0 == 1

A test that still passes with the log call removed is asserting on records from somewhere else — usually another logger emitting a similar event.

Common mistakes

Capturing at the default level. Error signature: an empty capture for an info-level event. Root cause: the root logger's effective level is warning. Remediation: set_level on the logger under test.

Asserting on total record count. Error signature: tests that break when a library adds a debug statement. Root cause: counting records from every logger. Remediation: filter by logger name and event.

Asserting on message text. Error signature: tests updated with every wording change. Root cause: coupling to prose. Remediation: assert on attributes.

A non-propagating logger. Error signature: caplog never sees a statement that clearly executes. Root cause: propagate: False in the configuration. Remediation: enable propagation for the test, or assert on that logger's own handler.

Setting the level globally. Error signature: captures full of framework and driver debug output, and slow tests. Root cause: set_level with no logger argument lowers the root. Remediation: scope the level to the logger under test.

Treating caplog as a formatter test. Error signature: a green suite and broken production output. Root cause: caplog captures before formatting. Remediation: add an output-level test for the formatter and filters.

Frequently Asked Questions

What does caplog capture?

LogRecord objects, via a handler attached to the root logger, before any of your application's handlers format them. It also offers the text rendered with its own simple format, which is not your production format.

Why does caplog see nothing from my logger?

Usually propagation. caplog's handler is on the root logger, so a logger with propagate set to False — common in dictConfig setups that give a logger its own handlers — never passes records up to it. The level is the second most common cause.

How do I assert on extra fields?

Fields passed via extra become attributes on the LogRecord, so assert on them as attributes: record.order_id rather than parsing them out of the message. For structlog, configure it to render through the standard library and the fields arrive the same way.

Does caplog test my formatter?

No. It captures records before your formatter runs. A test that passes with caplog says nothing about whether your JSON formatter works, which needs a test that captures the formatter's actual output.

Related Guides