Python Observability

Testing structlog Output with pytest

Logging assertions written against rendered text break every time someone changes a formatter. structlog makes a better contract available: the event dictionary, which is stable regardless of how it is eventually rendered. This page covers the two capture mechanisms, when each is correct, and the fixture hygiene that keeps a global configuration from leaking across a test suite. It builds on the structlog processors and pipelines guide, part of the modern Python logging libraries deep dive section.

Two places to intercept, testing two different things The structlog pipeline drawn once with two possible interception points marked. capture_logs intercepts at the very front, replacing the entire configured processor chain with a capturing processor: the test sees the raw event dict exactly as the call site produced it, which is fast and completely isolated, but none of the configured processors run, so a redaction or sampling processor is not exercised. CapturingLoggerFactory intercepts at the very back, replacing only the logger the renderer writes to: every configured processor runs first, so the test sees the fully enriched, redacted, sampled and rendered result. The choice follows from what is under test — application behaviour at the front, pipeline behaviour at the back. log.info("order accepted", order_id=8812, token="sk-live-9f3c") the call site raw event dict the configured chain enrich · redact · sample · render the code you actually deployed the logger stdout, or a stdlib handler capture_logs — intercepts here the chain is replaced entirely fast and isolated — but redaction never ran, so the captured token is still in plain text CapturingLoggerFactory — intercepts here only the final logger is replaced every processor ran, so this is what production would actually have emitted
Test application behaviour on the left, pipeline behaviour on the right. A redaction test written with capture_logs passes whether or not redaction works.

Prerequisites

pip install "structlog>=24.1.0,<26.0.0" \
            "pytest>=8.0.0,<9.0.0"

Implementation

Step 1 — Reset configuration between tests. structlog's configuration is process-global and, with cache_logger_on_first_use, sticks to loggers already created. An autouse fixture removes the whole class of order-dependent failures.

# conftest.py
import pytest
import structlog

@pytest.fixture(autouse=True)
def _reset_structlog():
    structlog.reset_defaults()
    yield
    structlog.reset_defaults()

Step 2 — Capture events for behavioural tests. capture_logs swaps the chain for a capturing one and yields a list of dicts. This is the right tool when the question is "did the code log the right thing", not "did the pipeline format it correctly".

from structlog.testing import capture_logs

def test_rejected_order_is_logged_with_the_reason():
    with capture_logs() as events:
        reject_order(order_id=8812, reason="insufficient_stock")

    assert len(events) == 1
    assert events[0]["event"] == "order rejected"
    assert events[0]["order_id"] == 8812
    assert events[0]["reason"] == "insufficient_stock"
    assert events[0]["log_level"] == "warning"

Note log_level rather than level: capture_logs adds the method name under that key, since your add_log_level processor is one of the ones it bypassed. Asserting on level here is a test that fails for the wrong reason.

Step 3 — Keep the real chain when the pipeline is under test. Swap only the factory. Every configured processor runs, so redaction, sampling and enrichment are genuinely exercised.

import pytest
import structlog
from structlog.testing import CapturingLoggerFactory

@pytest.fixture
def rendered():
    factory = CapturingLoggerFactory()
    configure()                                   # your production configure()
    structlog.configure(logger_factory=factory)   # swap the tail only
    return factory.logger.calls

def test_token_is_redacted_by_the_real_chain(rendered):
    structlog.get_logger("checkout").info("login", token="sk-live-9f3c8a2b")
    payload = rendered[0].args[0]                 # what the renderer produced
    assert "sk-live" not in payload
    assert '"token": "[redacted]"' in payload

factory.logger.calls is a list of CapturedCall objects with args and kwargs, so the assertion runs against the rendered string — which is the correct level of detail here, because the rendering is what is being tested.

Which capture mechanism answers which question Four testing questions matched to mechanisms. Asking whether the application logged the right event with the right fields is answered by capture_logs, because the assertion should not depend on any processor. Asking whether the pipeline redacts, samples or enriches correctly is answered by CapturingLoggerFactory, because the configured chain must actually run. Asking whether a third-party library's records reach the output is answered by pytest's caplog, because those records enter through the standard library and structlog's capture never sees them. Asking whether the final JSON shape matches a downstream contract is answered by rendering to a StringIO handler and parsing the line, because that is the only assertion that covers the serialiser itself. A footer notes that a test using the wrong mechanism usually still passes, which is why the mismatch is worth naming. the question decides the tool did the code log the right event and fields? application behaviour — no processor involved capture_logs assert on event dicts; note the log_level key does the pipeline redact, sample, enrich? the chain itself is the subject CapturingLoggerFactory real processors, captured renderer output do library records reach the output? they enter through logging, not structlog pytest caplog needs stdlib.LoggerFactory configured does the JSON match a downstream contract? the serialiser is the subject render to StringIO, then json.loads the only one that covers the serialiser
A test that uses the wrong mechanism usually still passes. That is exactly why it is worth choosing deliberately — a green redaction test that never ran the redactor is worse than no test.

Step 4 — Cover the standard-library half. Records from dependencies never pass through structlog's capture. Assert on them with caplog, which requires the pipeline to be configured with stdlib.LoggerFactory.

import logging

def test_library_records_are_enriched(caplog):
    configure()                                   # stdlib.LoggerFactory + ProcessorFormatter
    with caplog.at_level(logging.WARNING):
        logging.getLogger("urllib3").warning("retrying connection")

    assert caplog.records[0].name == "urllib3"
    assert caplog.records[0].levelname == "WARNING"

Step 5 — Assert on fields, never on substrings. A test that greps a rendered line couples itself to the renderer and to key ordering, and it can match text you did not intend.

# brittle: passes or fails on formatting decisions
assert "order rejected" in capsys.readouterr().out

# stable: survives any renderer change
assert any(e["event"] == "order rejected" and e["order_id"] == 8812 for e in events)
Why an autouse reset fixture is not optional The same two tests run in two orders, with and without a reset fixture. Without the fixture, the first test calls structlog.configure with a JSON renderer and logs, which caches that chain onto the logger; the second test configures a console renderer but the already-cached logger keeps the JSON chain, so the second test's assertion fails for a reason that has nothing to do with the code under test. Reversing the test order makes the failure move to the other test, which is the signature of this class of bug: it is order-dependent and disappears when the failing test is run alone. With an autouse fixture calling structlog.reset_defaults before and after every test, each test starts from an unconfigured state and both pass in either order. the same two tests, two orders no reset fixture test A · configure(json) · logs · PASSED test B · configure(console) · still JSON · FAILED the logger cached test A's chain and ignored B's configure run B alone and it passes — the classic symptom autouse reset_defaults reset · test A · configure(json) · PASSED · reset reset · test B · configure(console) · PASSED · reset every test starts from an unconfigured state and passes in any order, including in parallel shards cache_logger_on_first_use is what makes this happen — it is the right production setting and the reason tests need isolation reset before as well as after, so a test that fails mid-way cannot poison the next one
The failure moves when you reorder the suite, which is the tell. cache_logger_on_first_use is correct in production and precisely what makes test isolation mandatory.

Configuration options

Concern Tool Notes
Event assertions capture_logs bypasses the chain; level is log_level
Pipeline assertions CapturingLoggerFactory full chain runs; assert on rendered output
Library records caplog needs stdlib.LoggerFactory
Serialiser contract StringIO handler + json.loads the only one covering json.dumps
Isolation structlog.reset_defaults autouse fixture, before and after
Ordering cache_logger_on_first_use the reason isolation is needed at all

Verification

Run the suite and confirm the two capture styles disagree in the way they should — the raw capture sees the secret, the full-chain capture does not.

pytest tests/test_logging.py -v

Expected Output:

tests/test_logging.py::test_rejected_order_is_logged_with_the_reason PASSED
tests/test_logging.py::test_token_is_redacted_by_the_real_chain PASSED
tests/test_logging.py::test_library_records_are_enriched PASSED

A useful sanity check while writing these: temporarily remove the redaction processor from the configuration. test_token_is_redacted_by_the_real_chain must fail. If it still passes, the test is capturing at the wrong point and is not testing what its name claims.

Common mistakes

The redaction test passes with redaction removed

Error signature: deleting a processor breaks nothing in the suite. Root cause: the test used capture_logs, which replaces the whole chain. Remediation: use CapturingLoggerFactory for anything that asserts on processor behaviour, and verify by deleting the processor once.

KeyError: 'level' inside a captured event

Error signature: the assertion fails on a key that definitely exists in production output. Root cause: capture_logs bypasses add_log_level and records the method name as log_level. Remediation: assert on log_level under capture_logs, or switch to the full-chain fixture if the field name itself matters.

Tests pass alone and fail in the suite

Error signature: order-dependent failures that disappear with -k. Root cause: a test called structlog.configure and the cached loggers carried into later tests. Remediation: add the autouse reset_defaults fixture, and configure inside a fixture rather than at module import.

What is worth asserting on

Logging assertions have a bad reputation because most of them test the wrong thing: they pin a message string, break when someone rewords it, and get deleted. A useful test asserts on behaviour that a consumer depends on, and there are exactly three kinds.

The event happened. A record with a specific event name was emitted, at a specific level, when a specific thing occurred. This is a behavioural assertion about the code, and it is worth writing for records that something downstream acts on — an alert, an audit trail, a support workflow. It is not worth writing for a debug line.

The fields are present and correctly typed. A record carries order_id as an integer, duration_ms as a float, trace_id as a 32-character hex string. This is a contract test: a dashboard or an alert depends on those fields existing with those types, and nothing else in the build will notice if a refactor drops one.

The policy applied. Secrets are masked, probe traffic is dropped, the sampler kept the first N. These test the pipeline rather than the application, and they need the full-chain fixture rather than capture_logs.

def test_order_rejection_is_auditable():
    with capture_logs() as events:
        reject_order(order_id=8812, reason="insufficient_stock")

    audit = [e for e in events if e["event"] == "order rejected"]
    assert len(audit) == 1
    assert audit[0]["log_level"] == "warning"
    assert isinstance(audit[0]["order_id"], int)          # the type is the contract
    assert audit[0]["reason"] == "insufficient_stock"
Assertion Tests Fixture Worth writing for
The event happened application behaviour capture_logs records something acts on
Fields and types the record contract capture_logs anything a dashboard reads
The policy applied the pipeline CapturingLoggerFactory redaction, sampling, filtering
The exact message text nothing useful — never

Testing what is not logged

The negative assertion is the one that catches security regressions, and it needs care to be meaningful. Asserting that a specific string is absent from the output passes trivially — most strings are absent from most output — so the test has to first establish that the record exists and then assert on its contents.

def test_login_records_never_carry_the_password(rendered):
    submit_login(username="ada", password="hunter2")

    assert rendered, "no record was emitted — the test is not testing anything"
    payload = "".join(str(call.args) for call in rendered)
    assert "ada" in payload                    # the record is genuinely about this login
    assert "hunter2" not in payload            # and the secret is not in it

The first assertion is what makes the third meaningful. Without it, a refactor that removes the log call entirely leaves the test green, and the next person to add a log call there has no protection at all.

Keeping the suite fast

Logging tests are cheap individually and can become slow in aggregate if each one reconfigures a full pipeline. Two habits keep that in check. Configure at the fixture level with scope="module" where the configuration does not vary, so a hundred tests share one setup. And prefer capture_logs for the majority of assertions — it replaces the chain rather than running it, which makes it both faster and immune to changes in the configuration under test.

One more habit is worth adopting early: assert on the number of records, not only on their contents. A test that finds the expected event among five records passes equally well when a refactor starts emitting the same event three times, which is a real regression — duplicated records inflate volume, distort counts and confuse anyone reading a timeline. assert len(matching) == 1 costs nothing and catches the class of change that adds a handler, adds a second call site, or turns propagation back on.

Reserve the full-chain fixture for the handful of tests that genuinely exercise the pipeline. In a typical service that is a redaction test, a sampling test and a format-contract test: three tests that run the real chain, and everything else running against captured event dictionaries.

Frequently Asked Questions

What is the difference between capture_logs and CapturingLoggerFactory?

capture_logs replaces the whole processor chain with a capturing one, so it is fast and isolated but your real processors never run — a redaction processor under test would not be exercised. CapturingLoggerFactory replaces only the logger factory, so the entire configured chain runs and you assert on what the renderer produced. Use the first for testing application behaviour, the second for testing the pipeline itself.

Why does caplog not see my structlog output?

Because caplog hooks the standard library's handler machinery, and structlog only reaches it when configured with stdlib.LoggerFactory. With PrintLoggerFactory or a capturing factory the records never become LogRecords, so caplog stays empty. Either configure the stdlib factory in tests or use structlog's own capture.

Do I need to reset structlog between tests?

Yes, if any test calls structlog.configure. Configuration is global, and with cache_logger_on_first_use enabled, loggers created in an earlier test keep their frozen chain. An autouse fixture calling structlog.reset_defaults, ordered before your own configuration fixture, removes a whole class of ordering-dependent failures.

How do I assert that something was NOT logged?

Capture, then assert on the absence of a matching event: assert not any(e['event'] == 'order rejected' for e in caplog_events). Do it with an explicit predicate rather than a substring check on the rendered output, because a substring can match a longer message you did not intend to cover.

Related Guides