intermediate30 minby DevFox

Logging Instead of Print

Levels, loggers and handlers; structured logs you can search; and what must never reach a log line. Configuring logging once, at the edge, instead of everywhere.

Python
DevOps

The nightly job failed. You open the output and find four thousand lines of Processing photo..., three lines that say ok, and nothing about what went wrong, when it went wrong, or which of the four thousand photos was involved. Someone added those prints while debugging eighteen months ago and never took them out.

Print is a fine tool for working something out at your desk. It is the wrong tool for a program that runs unattended, because it cannot be filtered, redirected, timestamped or switched off without editing code. By the end of this lesson your programs will produce output you can actually search when something breaks at three in the morning.

What print cannot do

A print writes text to standard output. That is all it does, and the things it does not do are the entire subject:

text

no level        you cannot ask for only the problems
no timestamp    "it failed" - when?
no source       which module, which function, which line
no routing      everything goes one place
no off switch   removing it means editing and redeploying

Logging gives you all five, for roughly the same typing.

A logger per module

python

import logging

log = logging.getLogger(__name__)


def process(photo):
    log.debug("processing %s", photo.name)
    ...
    log.info("captioned %s", photo.name)

getLogger(__name__) is the whole convention. __name__ is the module's dotted path, so the logger is named photo_tools.captions — which means output says where it came from, and you can turn logging up for one module without touching the rest:

python

logging.getLogger("photo_tools.captions").setLevel(logging.DEBUG)

Never call logging.info(...) on the root logger directly. It works, and it gives up the per-module control that is most of the point.

Levels, and choosing between them

Five levels, and the choice is about who needs to see this:

python

log.debug("chunk %d of %d, %d bytes", i, total, len(chunk))
log.info("captioned 58 of 63 files in %s", folder)
log.warning("skipping %s: unsupported format", path)
log.error("could not write report to %s", path, exc_info=True)
log.critical("output volume is full, stopping")

CRITICAL — the program cannot continue
Rare enough that seeing one is itself information.
ERROR — an operation failed
Someone should look. The test: would you want to be woken up for this?
WARNING — wrong, but continuing
If routine events land here, the level stops meaning anything and the real warning arrives among two thousand others.
INFO — milestones
The program doing what it should. Would you want it in a daily summary?
DEBUG — for you, while diagnosing
Off in production. Only when hunting a specific bug.

The width is roughly how many lines each level should produce. Inflation is the common mistake.

Let the logger do the formatting

Bad — building the message before the level is checked.

Good — handing over the pieces.

The f-string is evaluated before debug is called, so the string is built on every single call — including the millions of times in production where the level is INFO and the message is immediately discarded. In a tight loop that is real time spent formatting text nobody will read. The %s form passes the pieces and formats only if something is actually going to emit it.

It also gives structured logging tools the raw values and a stable message template, so "comparing %s against %d" groups as one kind of event rather than as a million unique strings.

Logging an exception

Never log an exception by turning it into a string:

log.exception logs at ERROR and attaches the full traceback. It only works inside an except block. Elsewhere, exc_info=True does the same:

The traceback is the difference between "something failed" and knowing which line, in which call, with what cause. Losing it turns a five-minute fix into an afternoon.

Configuring it once, at the edge

Libraries log. Applications decide where it goes. That split matters:

In a library, only ever getLogger(__name__) and log calls. Never configure handlers or levels — you do not own the program's output, and a library that adds a handler produces duplicate lines in someone else's application.

In an application, configure once, at startup, in main:

Every line now carries a timestamp, a level and a source. That is what makes output greppable, and grep is what you will actually use.

For anything larger, dictConfig sets it all out declaratively — several handlers, different levels per module, a file and the console at once. Reach for it when basicConfig stops being enough.

Structured logs

Once logs are read by a machine rather than a person, text formatting becomes the obstacle. Structured logging emits key-value data:

With a JSON formatter, that becomes a record you can query — "every failure for album 7", "the slowest one percent" — without parsing prose. Libraries like structlog make it the default rather than an extra dictionary.

The habit that pays even without such a library: put the identifiers in every log line. A message saying "processing failed" is nearly useless; one carrying the photo name, the album and the request id can be traced through a whole system.

What must never be logged

Logs are stored, copied to a search system, kept for months and seen by more people than you expect.

The one that catches people is logging a whole object for convenience:

That prints the authorization header into a file. Log the fields you need by name, and if you must log a structure, redact it first.

A cheat sheet to keep

Where to go next

Your programs can now say what they are doing at a level someone can filter, with timestamps and sources that make output searchable, and with tracebacks preserved where they matter. The two habits worth forming immediately: log.exception inside every except you care about, and identifiers in every message.

Next is Working with JSON and External Data, which deals with everything arriving from outside your program. Logging is how you find out what happened; validation at the boundary is how you stop the worst of it happening at all.

Before you move on, take a script with prints in it and convert them. Give each one a level honestly — most print calls turn out to be debug — then run it with the level set to WARNING and see how much of that output you never needed.