Article

Emitting JSON Logs from a Typer CLI

Configure logging in the Typer root callback — before any subcommand body runs — with a --log-json PATH option that adds a second handler carrying a JSON formatter. The human stream on stderr is untouched, so the same invocation stays readable in a terminal and queryable afterwards. It builds on the Structured Logging for Geospatial CLIs guide, part of the broader CLI Architecture & Design Patterns reference.

Prerequisites

Where Configuration Has to Happen

Logging configuration is global process state, and the moment it is applied determines which records survive. Anything logged before configure_logging runs goes to the default handler — which, if no handler exists, means it is discarded with a no handlers could be found notice or, on modern Python, printed to stderr unformatted.

When the JSON handler starts capturing Module import and option parsing happen before the root callback runs, so any records emitted there are lost. The root callback configures logging, after which every record from the command body onward reaches both handlers. module import records lost option parsing records lost root callback handlers installed here command body everything captured Validation failures raised during parsing never reach the JSON file — they are reported through the parser's own error path instead, which is why exit codes matter as much as records do.

That last point is worth internalising rather than working around. A bad --dst-crs should fail during parsing, which means it will never appear in the log — and that is correct, because it never became work. The exit code carries that information, which is why the two mechanisms complement each other rather than overlapping.

Complete Working Implementation

# gistools/cli.py
from __future__ import annotations

import logging
from pathlib import Path
from typing import Optional

import typer

from gistools.logging_setup import SpatialJsonFormatter, get_logger

app = typer.Typer(no_args_is_help=True, add_completion=True)


def _configure(json_path: Optional[Path], verbose: bool, quiet: bool) -> None:
    level = logging.DEBUG if verbose else logging.INFO
    root = logging.getLogger()
    root.setLevel(logging.DEBUG)           # handlers filter, not the root
    root.handlers.clear()

    if not quiet:
        human = logging.StreamHandler()     # defaults to stderr
        human.setFormatter(logging.Formatter("%(levelname)-7s %(message)s"))
        human.setLevel(level)
        root.addHandler(human)

    if json_path is not None:
        json_path.parent.mkdir(parents=True, exist_ok=True)
        machine = logging.FileHandler(json_path, encoding="utf-8")
        machine.setFormatter(SpatialJsonFormatter())
        machine.setLevel(logging.DEBUG)     # always full detail on the stored stream
        root.addHandler(machine)


@app.callback()
def main(
    ctx: typer.Context,
    log_json: Optional[Path] = typer.Option(
        None, "--log-json", metavar="PATH",
        help="Write one JSON record per event to PATH, in addition to stderr.",
    ),
    verbose: bool = typer.Option(False, "--verbose", "-v",
                                 help="Show debug records on stderr too."),
    quiet: bool = typer.Option(False, "--quiet", "-q",
                               help="Suppress the human stream entirely."),
) -> None:
    """Geospatial batch tooling."""
    if verbose and quiet:
        raise typer.BadParameter("--verbose and --quiet are mutually exclusive")

    _configure(log_json, verbose=verbose, quiet=quiet)

    log = get_logger("gistools").bind(
        command=ctx.invoked_subcommand or "root",
    )
    log.info("run_started", extra={"log_json": str(log_json) if log_json else None})
    ctx.obj = {"log": log}


@app.command()
def warp(
    ctx: typer.Context,
    src: Path = typer.Argument(..., exists=True, dir_okay=False),
    dst: Path = typer.Argument(...),
    dst_crs: str = typer.Option(..., "--dst-crs"),
) -> None:
    """Reproject SRC into DST."""
    log = ctx.obj["log"].bind(src=str(src), dst=str(dst), dst_crs=dst_crs)
    log.info("warp_started")
    # ... the actual work, logging per chunk ...
    log.info("warp_finished", extra={"windows": 42, "duration_ms": 8123})

Step Annotations

  1. The root logger is set to DEBUG and the handlers do the filtering. Setting the root to INFO would drop debug records before any handler saw them, so the stored stream could never be more detailed than the console one — which is the whole point of having two.
  2. root.handlers.clear() before adding. Without it, a second invocation in the same process — which is exactly what a test suite does — accumulates handlers and every record is written twice.
  3. ctx.invoked_subcommand is bound before the subcommand runs. Typer populates it during dispatch, so the root callback can record which command was asked for even though the body has not started.
  4. --quiet removes the handler rather than raising the level. A raised level still formats and discards; removing the handler skips the work entirely, which matters when a batch emits tens of thousands of records.
  5. The mutual-exclusion check raises BadParameter, not ValueError. That gives exit code 2 and a usage message, consistent with every other invalid combination, as described in Argument Parsing with Typer.

The two handlers differ along three axes, and being explicit about each avoids the common mistake of making the stored stream a copy of the console one.

How the two handlers differ The human handler writes plain text to stderr at info level and is suppressed by the quiet flag. The machine handler writes JSON to a file at debug level and is unaffected by verbosity flags, so the stored record is always complete. axis human handler machine handler destination stderr, never stdout a file, or stdout in a container level INFO, or DEBUG with --verbose always DEBUG format one readable line one JSON object

The middle row is the one to get right. If --verbose also raised the machine handler’s level, there would be no way to get a complete record without also flooding the terminal.

One Named Gotcha: A Library You Import Has Already Configured Logging

Several geospatial packages call logging.basicConfig() at import time. Because basicConfig is a no-op when the root logger already has handlers — and installs a default handler when it does not — the outcome depends on import order, which is not something you control.

The symptom is duplicated console lines: your handler and the library’s both emit, so every message appears twice. The fix is the root.handlers.clear() above, but only if _configure runs after the offending import. Since the root callback runs after all module-level imports have completed, placing configuration there is sufficient — and is another reason not to configure logging at module scope in your own package.

If a library configures logging lazily, on first use rather than at import, clearing in the callback will not help. In that case, silence it by name rather than globally:

logging.getLogger("some_library").propagate = False

Setting propagate = False on that logger keeps its records out of your handlers without disabling the library’s own reporting for anyone who wants it.

Verification

Run a command both ways and confirm each stream carries what it should:

# Human stream only — readable, no JSON on screen.
gis warp in.tif out.tif --dst-crs EPSG:3857

# Both streams — screen unchanged, records on disk.
gis warp in.tif out.tif --dst-crs EPSG:3857 --log-json run.jsonl
jq -r '[.ts, .event, .dst_crs] | @tsv' run.jsonl

The expected record stream begins with the run and narrows into the command:

2026-08-06T09:14:20.114Z	run_started
2026-08-06T09:14:20.119Z	warp_started	EPSG:3857
2026-08-06T09:14:28.242Z	warp_finished	EPSG:3857

Then confirm the quiet path really is silent and the file still fills:

gis --quiet --log-json run.jsonl warp in.tif out.tif --dst-crs EPSG:3857 2>&1 | wc -l   # 0
wc -l run.jsonl                                                                          # > 0

Where the Log Path Itself Should Come From

Hardcoding a log path in a config file is convenient until two runs overlap and the second truncates the first. Three arrangements avoid it, and the right one depends on who is running the tool.

For an operator running commands by hand, a path with a timestamp is the least surprising: the tool computes it from the batch identifier, prints it once at start-up, and never overwrites anything. For a scheduled job, the scheduler usually already provides a run directory, and the correct behaviour is to accept a directory rather than a file and name the file inside it. For a container, neither applies — the platform captures stdout, and the right value for --log-json is -, with the handler writing to stdout instead of opening a file.

Supporting all three is one branch in the handler construction:

Three shapes the log destination can take A dash sends records to stdout for a container platform to capture. An existing directory means the tool generates a filename from the batch identifier inside it. Anything else is treated as an exact file path. --log-json - a single dash records to stdout — the container platform captures them --log-json logs/ an existing directory logs/b-4471.jsonl — named from the batch identifier --log-json run.jsonl anything else that exact file, opened in append mode

Append mode on the third row is deliberate. Truncating is the behaviour people expect from a shell redirect and the wrong one for a log: a re-run that overwrites the evidence of the failure you were investigating is a bad afternoon. Since every record carries a batch identifier, an appended file holding several runs is perfectly queryable.

Testing That the Records Are What You Think

Log output is code, and it breaks in the same ways code does — a field renamed in one place and not another, a level that stops being emitted after a refactor, a formatter that raises on an unusual value and silently drops the record. All three are cheap to test and rarely are.

# tests/test_logging.py
import json

from typer.testing import CliRunner

from gistools.cli import app

runner = CliRunner()


def test_json_log_is_one_object_per_line(tmp_path, raster_path):
    log = tmp_path / "run.jsonl"
    result = runner.invoke(app, ["--log-json", str(log), "raster", "warp",
                                 str(raster_path), str(tmp_path / "out.tif"),
                                 "--dst-crs", "EPSG:3857"])
    assert result.exit_code == 0

    records = [json.loads(line) for line in log.read_text().splitlines()]
    assert records, "no records were written"
    assert {"ts", "level", "event"} <= set(records[0])

    events = [r["event"] for r in records]
    assert "run_started" in events
    assert "warp_finished" in events


def test_numpy_values_do_not_break_the_formatter(tmp_path, caplog):
    import numpy as np
    from gistools.logging_setup import get_logger

    log = get_logger("t")
    log.info("probe", extra={"vertex_count": np.int64(42),
                             "area": np.float32(1.5)})
    # The assertion is simply that no exception escaped the logging call.

The second test is the one that earns its place. A TypeError raised inside a formatter is caught by the logging module and reported as an internal error on stderr, so the record vanishes and the run continues — which means the failure only ever shows up as a gap in the data, weeks later.

Rotating the File

For a long-running worker rather than a one-shot command, a plain FileHandler grows without bound. RotatingFileHandler fixes it, and the sizing needs one thought: a rotation that discards the beginning of a run makes the run unreconstructable.

Sizing the rotation so a whole run fits within one file, with a small number of backups, keeps each run intact and bounds the total. For a batch producing a few thousand records that is a few megabytes per file and perhaps five backups, which is small enough to keep for a quarter without anyone noticing.