Structured Logging for CLI Apps

Every CLI eventually needs to say something other than its result: a warning that a config key is deprecated, a debug trace of which file it opened, an error explaining why it stopped. Reaching for print() for those messages quietly breaks your tool the moment someone pipes its output into another program. This overview shows how to wire Python's logging module into a command-line app so diagnostics go to the right stream, humans get readable output, and machines get parseable records — with verbosity you can dial up or down at runtime.

TL;DR

• Use the logging module for diagnostics, not print(). Reserve print() (or stdout) for the actual result a caller wants to capture.
• Send logs to stderr, results to stdout. That one rule keeps your tool composable in pipes and scripts.
• Learn the four moving parts once: a logger creates records, a handler routes them, a formatter renders them, and a level filters them.
• Give humans a pretty console (a plain formatter or RichHandler) and give machines structured JSON.
• Expose the level with verbose and quiet flags so users choose how much they see.

print() versus logging for CLIs

print() is fine for the one thing your command produces — the converted file path, the JSON payload, the table of results. It is the wrong tool for everything about the run. The moment you print() a status message, you have mixed diagnostics into the data stream, and a user who runs mycli export > data.json finds "Connecting to database..." wedged into their JSON.

logging fixes this by separating three concerns you'd otherwise hand-roll: where a message goes (handler), how it looks (formatter), and whether it shows at all (level). You write one line — log.info("connected") — and configuration elsewhere decides the rest. That indirection is exactly what lets the same call site be silent by default, verbose under -v, and JSON under --log-format=json.

import logging

log = logging.getLogger("mycli")

def export(rows: list[dict]) -> None:
    log.info("exporting %d rows", len(rows))   # diagnostic -> stderr
    for row in rows:
        print(row["id"])                        # result -> stdout

The result goes to stdout; the "exporting N rows" note goes to stderr once you attach a handler there. A caller redirecting stdout still sees the log on their terminal, and a caller redirecting both keeps them in separate files.

The logging model: logger, handler, formatter, level

Four objects do all the work, and understanding them is the whole game:

• Logger — what you call (logging.getLogger("mycli")). Loggers form a dotted namespace (mycli, mycli.db) so you can tune sub-areas independently.
• Handler — where records go: a StreamHandler to stderr, a FileHandler to a log file, a RichHandler for a colorized console. One logger can have several.
• Formatter — how each record is rendered to text: a timestamp-and-level line for humans, a JSON object for machines.
• Level — the threshold. DEBUG < INFO < WARNING < ERROR < CRITICAL. A record below the effective level is dropped before it's ever formatted.

Configure them once at startup, ideally in a single setup_logging() function called from your entry point:

import logging
import sys

def setup_logging(level: int = logging.WARNING) -> None:
    handler = logging.StreamHandler(sys.stderr)          # logs -> stderr
    handler.setFormatter(logging.Formatter(
        "%(levelname)s %(name)s: %(message)s"
    ))
    root = logging.getLogger()
    root.handlers.clear()          # avoid duplicate handlers on re-init
    root.addHandler(handler)
    root.setLevel(level)

Two details matter. Clearing existing handlers makes the function safe to call more than once (tests love this). And configuring the root logger means every module that does logging.getLogger(__name__) inherits the handler for free — you never wire logging per-module.

Logs go to stderr, results go to stdout

This is the rule that makes a CLI behave in a pipeline. stdout is the data channel; stderr is the diagnostics channel. Keep them separate and your tool composes:

$ mycli export --format json > out.json      # only results land in the file
exporting 128 rows                            # log still shows on the terminal
$ mycli export --format json 2>/dev/null | jq '.[0]'   # drop logs, keep data

logging.StreamHandler() defaults to stderr, which is already correct — but be explicit (StreamHandler(sys.stderr)) so no one "fixes" it to stdout later. The payoff is that -v can add as much noise as a user wants without ever corrupting the output another program is parsing. This same discipline underpins choosing exit codes and error handling: errors go to stderr and set a non-zero exit, so scripts can branch on success without scraping text.

Human output versus machine output

The same log record should look different depending on who's reading. A developer at an interactive terminal wants a short, colorized line. A log collector wants a JSON object it can index. Decide by asking one question: is stderr a TTY?

import logging
import sys

def choose_formatter() -> logging.Formatter:
    if sys.stderr.isatty():
        return logging.Formatter("%(levelname)s: %(message)s")   # human
    # non-interactive (piped, CI, systemd): switch to structured output
    from myapp.jsonlog import JsonFormatter
    return JsonFormatter()

When stderr is a terminal, render friendly text. When it's redirected — CI, a pipe, a service manager — emit structured records instead. Let a --log-format=json|console flag override the guess, because autodetection is a default, not a law. The deep recipe for the machine side lives in the child guide below.

The two guides underneath this one

This overview stays at the level of how the pieces fit. Two focused guides carry the implementations:

• Structured JSON logging in Python CLIs — emit machine-readable JSON with a stdlib formatter or structlog, attach context fields like a request ID, and switch renderers based on the terminal.
• Adding verbose and quiet logging flags — map -v, -vv, and --quiet onto log levels, pick sane defaults, and keep verbose and quiet mutually exclusive.

Read the flags guide first if you just want users to be able to say "tell me more"; read the JSON guide when your logs need to land in a pipeline.

A pretty console with RichHandler

For interactive use, Rich gives you colorized levels, aligned columns, and syntax-highlighted tracebacks with almost no configuration. Swap the plain StreamHandler for a RichHandler when stderr is a terminal:

import logging
from rich.logging import RichHandler

def setup_rich_logging(level: int = logging.WARNING) -> None:
    logging.basicConfig(
        level=level,
        format="%(message)s",          # RichHandler adds level + time columns
        datefmt="[%X]",
        handlers=[RichHandler(rich_tracebacks=True, show_path=False)],
    )

rich_tracebacks=True turns an unhandled exception into a readable, source-highlighted panel instead of a wall of monochrome text — a big usability win for the people running your tool. Rich writes to its own console (stderr by default), so the stdout/stderr split still holds. If your CLI already uses Rich for progress bars and other terminal UI, reusing its handler keeps every message visually consistent. Fall back to the plain formatter when output is redirected, so log files stay free of color escape codes.

Production notes

• Set the level, don't gate at the call site. Never wrap log.debug(...) in if verbose:. Set the logger level once and let the framework filter — that's the entire point.
• Don't basicConfig inside a library. If your CLI is also importable, configure logging only in the entry-point/main(), never at import time. Libraries should add a NullHandler and let the application decide.
• Interpolate lazily. Write log.info("got %s rows", n), not log.info(f"got {n} rows"). The %-args are only formatted if the record actually passes the level filter.
• One setup_logging() call. Clear handlers before adding new ones so re-initialization (in tests or plugins) doesn't double every line.
• Capture in tests with caplog. pytest's caplog fixture records emitted logs so you can assert on level and message without parsing terminal text.

One configuration function, called once

Logging configuration belongs in exactly one place, runs before any command, and takes its input from the verbosity flags:

import logging
import sys

LEVELS = {0: logging.WARNING, 1: logging.INFO, 2: logging.DEBUG}
NOISY = ("httpx", "urllib3", "botocore", "asyncio")

def configure_logging(verbosity: int, *, quiet: bool = False, json_format: bool = False) -> None:
    level = logging.ERROR if quiet else LEVELS.get(verbosity, logging.DEBUG)

    handler = logging.StreamHandler(sys.stderr)
    handler.setFormatter(
        JsonFormatter() if json_format else logging.Formatter("%(levelname)s %(name)s: %(message)s")
    )

    root = logging.getLogger()
    root.handlers.clear()          # idempotent: repeated calls do not stack handlers
    root.addHandler(handler)
    root.setLevel(level)

    for name in NOISY:
        logging.getLogger(name).setLevel(max(level, logging.WARNING))

Four decisions are worth calling out. The stream is stderr, always, so logs never contaminate results. handlers.clear() makes the function idempotent, which matters because tests call it repeatedly and duplicated handlers produce duplicated lines. Known-noisy libraries are capped so -vv shows your debug output rather than someone else's retry chatter. And the format is a parameter rather than a second code path.

Wire it into the callback so it happens before dispatch:

@app.callback()
def main(
    ctx: typer.Context,
    verbose: Annotated[int, typer.Option("--verbose", "-v", count=True)] = 0,
    quiet: Annotated[bool, typer.Option("--quiet", "-q")] = False,
) -> None:
    configure_logging(verbose, quiet=quiet)

Nothing else in the program asks how verbose the user wanted things. Modules call log = logging.getLogger(__name__) at import time and log at the level the message deserves; the configuration decides what is shown.

Naming, levels and what to log

A logger per module, named __name__, is the whole naming convention. It gives you free hierarchy — mytool.core.sync inherits from mytool.core inherits from mytool — so a user can be told to run with a specific subsystem at debug level, and it makes the source of a line obvious without adding it to the message.

Choosing a level is easier with a rule than with taste:

• ERROR — the operation failed. Something the user must know about, and usually the last thing before a non-zero exit.
• WARNING — it worked, but not the way it should. A deprecated key, a retry, a fallback.
• INFO — a step completed. What a user asking "what is it doing" wants: one line per meaningful unit of work, not one per file.
• DEBUG — everything you would want in a bug report: arguments, resolved configuration, URLs, timings.

Two mistakes account for most bad logging. Logging and raising the same problem produces two reports of one failure — either log it and handle it, or raise it and let the boundary report it, never both. And using f-strings for the message:

log.debug("uploading %s to %s", path, bucket)      # formatted only if DEBUG is enabled
log.debug(f"uploading {path} to {bucket}")         # formatted always, even when discarded

The first also keeps the arguments as structured fields for any handler that wants them, which is what makes the JSON format useful rather than a wrapper around a sentence.

Exceptions, and the one place they belong

log.exception attaches the current traceback and is only correct inside an except block. In a CLI it should appear approximately once, at the boundary, not scattered wherever an error is caught:

def main() -> None:
    try:
        app()
    except MytoolError as exc:
        log.error("%s", exc)                       # expected: one line, no traceback
        sys.exit(EXIT[type(exc)])
    except Exception:
        log.exception("internal error")            # unexpected: full traceback at ERROR
        sys.exit(70)

The distinction is the whole point. An expected failure — a missing file, an unreachable service — gets a sentence, because a traceback tells the user nothing they can act on. An unexpected exception is a bug in your code, and the traceback is the bug report.

For development, --debug should turn the boundary off entirely and let Python print the traceback itself, which keeps the interactive experience honest without changing what users see.

Testing what the tool logged

Logging is easy to leave untested and then break silently. Two small tests cover the cases that matter.

import logging

def test_verbosity_maps_to_levels(caplog):
    configure_logging(verbosity=1)
    with caplog.at_level(logging.INFO):
        logging.getLogger("mytool.core").info("started")
        logging.getLogger("mytool.core").debug("noisy detail")

    messages = [record.message for record in caplog.records]
    assert "started" in messages
    assert "noisy detail" not in messages       # -v must not enable DEBUG

def test_configure_is_idempotent():
    configure_logging(0)
    configure_logging(0)
    assert len(logging.getLogger().handlers) == 1

The second one looks trivial and catches a real regression: a configuration function that appends rather than replaces produces duplicated output the moment anything calls it twice, and the tests are usually where that first happens.

For the stream itself, assert through the CLI runner that errors land on stderr rather than stdout — that is the property scripts depend on, and it is the one most easily broken by a stray print:

def test_errors_go_to_stderr():
    result = CliRunner(mix_stderr=False).invoke(app, ["sync", "/does/not/exist"])
    assert result.exit_code != 0
    assert result.stdout == ""
    assert "does not exist" in result.stderr

Logging to a file as well as the terminal

Some tools benefit from keeping a rolling record of their own runs — a deployment tool, a long-running sync, anything whose failures get investigated hours later. Two handlers on the same root logger cover it:

from logging.handlers import RotatingFileHandler

def add_file_log(path: Path, *, level: int = logging.DEBUG) -> None:
    path.parent.mkdir(parents=True, exist_ok=True)
    handler = RotatingFileHandler(path, maxBytes=2_000_000, backupCount=3, encoding="utf-8")
    handler.setLevel(level)
    handler.setFormatter(JsonFormatter())
    logging.getLogger().addHandler(handler)

The terminal handler stays at whatever the verbosity flags asked for; the file handler records everything at DEBUG in JSON. That combination means the user sees a clean run and you get the full detail when they report a problem — mytool doctor --log can then print the path rather than asking them to reproduce with -vv.

Put the file under the user's state or cache directory rather than the working directory, cap its size with rotation, and never write it unless the user opted in or the path is somewhere clearly theirs. A tool that silently fills a home directory with logs is a tool people uninstall, so make the location visible in the help text.

Frequently asked questions

Related

• Up: Advanced Input Parsing for Python CLIs
• Down: Structured JSON logging in Python CLIs
• Down: Adding verbose and quiet logging flags
• Sideways: Error handling and exit codes
• Sideways: Interactive terminal UI with Rich