Use assertLogs without depending on timestamps or handler formatting

By Batu · English technical notes

Use assertLogs without depending on timestamps or handler formatting

Use assertLogs records to assert the logger, level, and resolved message—not a complete rendered line. The controlled fixture below creates two timestamp-bearing renderings of the same event one second apart. assert line_at_zero != line_at_one demonstrates why a snapshot that includes wall-clock text can change even though the event remains the same. It then emits that fixed event inside assertLogs and checks the captured LogRecord instead.

TestCase.assertLogs captures records at or above the selected level and provides records plus formatted output. LogRecord.getMessage() merges a %s message and its arguments, making it appropriate for the application message assertion here. The timestamp examples are deliberately synthetic: their created values are fixed and the formatter uses UTC, so the program’s output is exact and reproducible.

Notice the separate capture output line. captured.output is formatted by the handler installed by assertLogs; it is not proof that an application’s production handler has the same formatter, includes a timestamp, or sends logs to the expected destination. Test a production formatter separately only when that presentation is part of the requirement. Record assertions also do not prove that the event was ultimately persisted or delivered. assertLogs was added in Python 3.4.

AI assistance disclosure: this article was drafted with AI assistance and uses synthetic log records.

import logging
import time
import unittest

logger = logging.getLogger("service.billing")
case = unittest.TestCase()

with case.assertLogs("service.billing", level="INFO") as captured:
    logger.info("invoice %s created", 17)

record = captured.records[0]
assert record.name == "service.billing"
assert record.levelname == "INFO"
assert record.getMessage() == "invoice 17 created"

formatter = logging.Formatter(
    "%(asctime)s %(levelname)s %(name)s %(message)s",
    datefmt="%Y-%m-%dT%H:%M:%S",
)
formatter.converter = time.gmtime

def render_at(created):
    sample = logging.LogRecord(
        record.name, record.levelno, "", 0, record.msg, record.args, None
    )
    sample.created = created
    return formatter.format(sample)

line_at_zero = render_at(0)
line_at_one = render_at(1)
assert line_at_zero != line_at_one

print(f"timestamp change: {line_at_zero != line_at_one}")
print(f"event: {record.levelname} {record.name} {record.getMessage()}")
print(f"capture output: {captured.output[0]}")

timestamp change: True
event: INFO service.billing invoice 17 created
capture output: INFO:service.billing:invoice 17 created

Sources: Python documentation: unittest.TestCase.assertLogs and Python documentation: LogRecord.getMessage.