Batu Lab NotesPractical developer guides

Format a deterministic logging record

By Batu ยท English technical notes

Also published in our Blogger archive.

Logging output is difficult to compare exactly when its format includes a timestamp, process identifier, thread name, or source location. This example deliberately selects only stable record fields: levelname, name, and the rendered message. A StreamHandler writes to an in-memory StringIO, while a Formatter defines the exact layout LEVEL|LOGGER|MESSAGE.

The named logger is new in this standalone process. The example attaches its one local handler with addHandler() and sets propagate to False, so the record is not also offered to root handlers. Calling logger.info("job=%s", "A17") lets logging render the message from its format string and argument. The program asserts the entire captured record, including its newline, then prints it without adding a second newline.

The result is deterministic for this fixed input and selected formatter fields; it is not a guarantee that every logging configuration is deterministic. Adding %(asctime)s, %(process)d, exception information, or variable input changes what can be asserted. Also, applications that initialize a logger more than once should manage their own handler lifecycle through addHandler() and removeHandler() rather than modifying the handlers list directly.

logging.Formatter documents percent-style record formatting, and Logger.info() documents deferred message formatting. Both APIs are available in supported Python 3 versions.

AI assistance disclosure: This article was drafted with AI assistance and should be adapted to the application's logging policy.

import io
import logging


stream = io.StringIO()
handler = logging.StreamHandler(stream)
handler.setFormatter(logging.Formatter("%(levelname)s|%(name)s|%(message)s"))

logger = logging.getLogger("build.record")
logger.propagate = False
logger.setLevel(logging.INFO)
logger.addHandler(handler)
logger.info("job=%s", "A17")

record = stream.getvalue()
assert record == "INFO|build.record|job=A17\n"
print(record, end="")
INFO|build.record|job=A17