Your Logs Are an API: Testing Python Logging with pytest's caplog

At 3 a.m., during an incident, your logs are the only interface you have to production. Dashboards, alerts, and log queries all depend on them: an alert fires on level=ERROR, a saved search filters on order_id, a compliance check makes sure no password ever reaches the log pipeline.

That makes your log output an API. Other systems depend on its shape, yet most codebases never test it. Someone downgrades an error to a warning, renames order_id to orderId, or adds a debug line that dumps a whole request body, and no test fails.

pytest has a built-in fixture for this, caplog. In this post we'll use it to test four things:

1. The right level is used for the right situation
2. Structured fields passed through extra= are present
3. Unexpected errors carry a traceback
4. A JSON formatter and a redaction filter behave correctly, together

All code runs on Python 3.13 with pytest 9 and needs nothing beyond the standard library and pytest.

The code under test

Here is a small checkout function. It tells three different stories: a captured payment (INFO), a declined card (WARNING, because it's a normal business outcome and shouldn't page anyone), and a gateway failure (ERROR with a traceback, because it should).

# checkout.py
import logging

logger = logging.getLogger("shop.checkout")


class PaymentDeclined(Exception):
    pass


def charge(order_id, amount_cents, gateway):
    logger.debug("charging order", extra={"order_id": order_id})
    try:
        gateway(amount_cents)
    except PaymentDeclined:
        logger.warning(
            "payment declined",
            extra={"order_id": order_id, "amount_cents": amount_cents},
        )
        return False
    except Exception:
        logger.exception("gateway error", extra={"order_id": order_id})
        raise
    logger.info("payment captured", extra={"order_id": order_id,
                                            "amount_cents": amount_cents})
    return True

The extra= dictionary is the standard library's way of attaching structured fields. Each key becomes an attribute on the LogRecord, which is exactly what we'll assert on.

Test 1: levels and fields

caplog.records is a list of the actual LogRecord objects that were emitted. Asserting on records instead of formatted strings makes the tests resilient to formatting changes:

import logging

from checkout import PaymentDeclined, charge


def ok_gateway(amount):
    return None


def declining_gateway(amount):
    raise PaymentDeclined()


def test_success_logs_info_with_order_id(caplog):
    caplog.set_level(logging.INFO, logger="shop.checkout")

    assert charge("ord-42", 1999, ok_gateway) is True

    [record] = caplog.records
    assert record.levelname == "INFO"
    assert record.getMessage() == "payment captured"
    assert record.order_id == "ord-42"
    assert record.amount_cents == 1999


def test_decline_is_a_warning_not_an_error(caplog):
    caplog.set_level(logging.INFO, logger="shop.checkout")

    assert charge("ord-7", 500, declining_gateway) is False

    assert [r.levelname for r in caplog.records] == ["WARNING"]
    assert caplog.records[0].order_id == "ord-7"

Two details matter here:

• caplog.set_level(..., logger=...) scopes the level change to one logger and restores it after the test, so tests don't leak configuration into each other.
• [record] = caplog.records is a small trick: the unpacking fails if there isn't exactly one record. That catches accidental duplicate logging, which is a common bug when a handler gets attached twice.

The second test protects a decision that is easy to undo by accident. If someone "fixes" the decline path to use logger.error, your on-call rotation starts getting paged for expired credit cards. Now a test fails first.

Test 2: debug output stays at debug

Use the caplog.at_level context manager when a test needs different levels in different phases. caplog.messages gives you just the formatted message strings:

def test_debug_line_only_appears_at_debug(caplog):
    with caplog.at_level(logging.INFO, logger="shop.checkout"):
        charge("ord-1", 100, ok_gateway)
    assert "charging order" not in caplog.messages

    caplog.clear()
    with caplog.at_level(logging.DEBUG, logger="shop.checkout"):
        charge("ord-1", 100, ok_gateway)
    assert caplog.messages[0] == "charging order"

caplog.clear() resets the captured records between phases.

Test 3: errors carry a traceback

A log line that says gateway error without a stack trace is almost useless. logger.exception() attaches exc_info to the record, so assert that it's there and has the right type:

import pytest


def broken_gateway(amount):
    raise TimeoutError("gateway timed out")


def test_unexpected_error_logs_traceback(caplog):
    caplog.set_level(logging.ERROR, logger="shop.checkout")

    with pytest.raises(TimeoutError):
        charge("ord-9", 100, broken_gateway)

    [record] = caplog.records
    assert record.exc_info is not None
    assert record.exc_info[0] is TimeoutError

This test fails if someone replaces logger.exception(...) with logger.error(...), which silently drops the traceback.

Test 4: the formatter and the redaction filter

Most production setups ship JSON logs. Here is a minimal formatter that copies every extra= field into the JSON, plus a filter that masks sensitive keys before anything is written:

# app_logging.py
import json
import logging

_RESERVED = set(vars(logging.makeLogRecord({}))) | {"message", "asctime"}
SENSITIVE_KEYS = {"password", "token", "card_number"}


class JsonFormatter(logging.Formatter):
    def format(self, record):
        payload = {
            "level": record.levelname,
            "logger": record.name,
            "message": record.getMessage(),
        }
        # Anything passed via extra=... becomes an attribute on the record.
        for key, value in vars(record).items():
            if key not in _RESERVED:
                payload[key] = value
        if record.exc_info:
            payload["exception"] = self.formatException(record.exc_info)
        return json.dumps(payload, default=str)


class RedactFilter(logging.Filter):
    def filter(self, record):
        for key in SENSITIVE_KEYS:
            if hasattr(record, key):
                setattr(record, key, "[REDACTED]")
        return True

The _RESERVED trick builds the set of attribute names every LogRecord has by default, so anything else on the record must have come from extra=.

You can unit-test both classes without any logger at all, because logging.makeLogRecord() builds a record from a dict:

import json

from app_logging import JsonFormatter, RedactFilter


def make_record(**extra):
    return logging.makeLogRecord(
        {"name": "shop.checkout", "levelname": "INFO", "levelno": 20,
         "msg": "user %s logged in", "args": ("alice",), **extra}
    )


def test_formatter_emits_valid_json_with_extras():
    line = JsonFormatter().format(make_record(order_id="ord-42"))
    data = json.loads(line)
    assert data == {
        "level": "INFO",
        "logger": "shop.checkout",
        "message": "user alice logged in",
        "order_id": "ord-42",
    }


@pytest.mark.parametrize("field", ["password", "token", "card_number"])
def test_redact_filter_masks_sensitive_fields(field):
    record = make_record(**{field: "s3cret"})
    assert RedactFilter().filter(record) is True
    data = json.loads(JsonFormatter().format(record))
    assert data[field] == "[REDACTED]"
    assert "s3cret" not in json.dumps(data)

Comparing the whole dict with == is deliberate. It catches extra fields leaking into the output, not just missing ones.

Test 5: the whole pipeline

Unit tests on the formatter are good, but the real bug is often in the wiring. caplog.handler is a real logging.Handler, so you can give it your production formatter and filter and assert on the final text with caplog.text:

def test_full_pipeline_through_a_real_handler(caplog):
    logger = logging.getLogger("shop.checkout")
    caplog.handler.setFormatter(JsonFormatter())
    caplog.handler.addFilter(RedactFilter())
    caplog.set_level(logging.INFO, logger="shop.checkout")

    logger.info("login", extra={"user": "alice", "password": "hunter2"})

    data = json.loads(caplog.text.strip())
    assert data["user"] == "alice"
    assert data["password"] == "[REDACTED]"

A fresh handler is created for every test, so this configuration doesn't leak into other tests.

Running it

$ python -m pytest -q
.........                                                                [100%]
9 passed in 0.01s

Takeaways

• Assert on caplog.records, not strings. Records give you the level, the logger name, exc_info, and every extra= field as attributes.
• Use the [record] = caplog.records unpacking to catch duplicate log lines for free.
• Scope levels with set_level(..., logger=...) or at_level. Both restore the previous state automatically.
• Test redaction explicitly. A parametrized test over your sensitive keys is cheap insurance against a compliance incident.
• Test the wiring once by attaching your real formatter and filters to caplog.handler.

If a dashboard, alert, or audit depends on a log line, that log line deserves a test.

---

Note: An AI assistant helped draft this post; all code was run and tested (Python 3.13, pytest 9.1).