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.

python

log.debug(f"comparing {photo.name} against {len(candidates)} candidates")

Good — handing over the pieces.

python

log.debug("comparing %s against %d candidates", photo.name, len(candidates))

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:

python

except OSError as error:
    log.error("could not read %s: %s", path, error)     # loses the trace

python

except OSError:
    log.exception("could not read %s", path)            # keeps it

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

python

log.error("could not write report", exc_info=True)

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:

python

def main() -> None:
    logging.basicConfig(
        level=logging.INFO,
        format="%(asctime)s %(levelname)-8s %(name)s: %(message)s",
        datefmt="%Y-%m-%dT%H:%M:%S%z",
    )
    ...

text

2026-07-29T14:30:11+0000 INFO     photo_tools.main: captioned 58 files
2026-07-29T14:30:11+0000 WARNING  photo_tools.scan: skipping notes.txt

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.

Make the level configurable

Reading it from the environment costs one line and means you can turn on debug logging in a running system without a code change:

python

level = os.environ.get("LOG_LEVEL", "INFO").upper()
logging.basicConfig(level=level, ...)

The first time you need debug output from production, this line is the difference between a restart and a deployment.

Structured logs

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

python

log.info("photo captioned", extra={
    "photo": photo.name,
    "album_id": album.id,
    "duration_ms": elapsed * 1000,
})

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.

text

never    passwords, API keys, tokens, session cookies
never    full card numbers, government identifiers
never    an entire request body from an untrusted source
care     personal data - names, emails, addresses, locations

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

python

log.debug("request: %r", request)      # what is in the headers?

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

text

SETUP
  log = logging.getLogger(__name__)      once per module, at the top
  never logging.info(...) on the root

LEVELS - who needs to see this?
  debug     for you, diagnosing. off in production
  info      milestones; it is working
  warning   wrong, but continuing
  error     an operation failed; someone should look
  critical  cannot continue

  test: would this wake you up?  -> error or above
  inflation destroys the signal

FORMATTING
  log.info("captioned %s in %d ms", name, ms)      <- yes
  log.info(f"captioned {name}")                    <- no

  the f-string is built even when the level discards it
  and %s keeps a stable template for structured tools

EXCEPTIONS
  except X:
      log.exception("could not read %s", path)     keeps the traceback
  elsewhere: log.error(..., exc_info=True)
  never log just str(error)

CONFIGURING
  library      getLogger + log calls ONLY, never handlers
  application  basicConfig once in main(), or dictConfig
  format with asctime, levelname, name, message
  level from LOG_LEVEL in the environment

STRUCTURED
  extra={"photo": name, "album_id": id, "duration_ms": ms}
  put identifiers in every line

NEVER LOG
  passwords, keys, tokens, cookies, card numbers, ids
  whole request objects - the headers carry credentials
  care with personal data; sanitise newlines from user input

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.