This guide is part of Monitoring & Observability for Spatial Pipelines, within the broader Orchestrating Spatial ETL Pipelines reference.

Structured Logging for Geospatial ETL Jobs

A log line that reads Processing tile... tells a person almost nothing and a query engine nothing at all. The difference between logs that get used during an incident and logs that get skipped is entirely in whether the context travels with the message.

Why Unstructured Logs Fail Spatial Investigations

  • The context is in the wrong place. Which tile, which run, which source — usually in a line printed twenty minutes earlier, if at all.
  • Nothing can be grouped. “How many tiles hit the retry path last night” requires parsing free text with a regular expression that breaks when the message wording changes.
  • Correlation is manual. Joining a warning to the metric it explains means reading timestamps by eye.
  • Volume hides signal. A per-feature log line at scale buries the four lines that mattered under four million that did not.

Version and Environment Compatibility

Component Version Note
Python 3.10+ logging with contextvars-backed filters
structlog >=24.1 Optional; the recipe uses the standard library only
Any log store — Requires one JSON object per line 
pip install "python-json-logger>=2.0"   # optional; a hand-rolled formatter is shown below

The Field Set Every Line Should Carry

Automatic context plus event-specific fields A log record is drawn as two blocks. The left block holds context injected by a filter on every record: run identifier, dataset, stage, partition key and code version. The right block holds fields specific to the event: an event name, counts, durations and identifiers. Because the context is injected rather than typed at the call site, no record can be missing it. injected by the filter run_id dataset stage partition code_version supplied at the call site event · "source_unchanged" rows_in · 12400 duration_ms · 4182 source_uri · https://… whatever this specific event means

The Logging Setup Recipe

from __future__ import annotations

import contextvars
import json
import logging
import sys
from datetime import datetime, timezone

# One context per task; contextvars survive across async boundaries and threads.
_context: contextvars.ContextVar[dict] = contextvars.ContextVar("log_context", default={})


def bind_context(**fields: str) -> None:
    """Attach fields to every subsequent log record in this execution context."""
    _context.set(_context.get() | fields)


class ContextFilter(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        for key, value in _context.get().items():
            setattr(record, key, value)
        return True


class JsonFormatter(logging.Formatter):
    RESERVED = set(logging.LogRecord("", 0, "", 0, "", (), None).__dict__) | {"message", "asctime"}

    def format(self, record: logging.LogRecord) -> str:
        payload = {
            "ts": datetime.fromtimestamp(record.created, timezone.utc).isoformat(),
            "level": record.levelname,
            "logger": record.name,
            "event": record.getMessage(),
        }
        # Anything the caller passed through `extra=` becomes a queryable field.
        payload |= {k: v for k, v in record.__dict__.items() if k not in self.RESERVED}
        if record.exc_info:
            payload["exception"] = self.formatException(record.exc_info)
        return json.dumps(payload, default=str)


def configure_logging(level: int = logging.INFO) -> None:
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(JsonFormatter())
    handler.addFilter(ContextFilter())

    root = logging.getLogger()
    root.handlers.clear()
    root.addHandler(handler)
    root.setLevel(level)
    # GDAL and rasterio are chatty at DEBUG and rarely useful there.
    logging.getLogger("rasterio").setLevel(logging.WARNING)
    logging.getLogger("fiona").setLevel(logging.WARNING)

Usage at a call site stays short, because the context is already bound:

configure_logging()
bind_context(run_id=run_id, dataset="parcels", stage="clean",
             partition=tile_id, code_version="4.2.0")

logger = logging.getLogger(__name__)
logger.info("stage_complete", extra={
    "rows_in": 12_400, "rows_out": 12_180, "quarantined": 220,
    "duration_ms": 4_182,
})

Key Implementation Notes

  • The message is an event name, not a sentence. stage_complete groups; “Finished processing the parcels stage” does not, and it changes wording every time someone edits it.
  • Context is injected, never typed. A filter that adds the run id to every record removes the possibility of a line missing it, which is the failure that breaks correlation exactly when it is needed.
  • contextvars rather than a global. Two tiles processed concurrently in the same process each keep their own partition value, which a module-level dictionary would not.
  • Third-party loggers are quietened explicitly. GDAL and Fiona emit large volumes at debug level, and an unfiltered debug run can produce gigabytes from one task.
  • Exceptions are formatted into a field. A traceback spread across forty lines is unqueryable; as one field it stays attached to its event.
  • default=str on the dump. Geometry objects, Decimal, datetime and Path all appear in spatial code and none serialise natively; failing to log because a value was exotic is the worst possible outcome.
Choosing the logging grain Three logging grains compared for a daily pipeline over four hundred tiles and twelve million features. One line per run is 365 records a year. One line per partition is 146000. One line per feature is over four billion, which is unreadable and expensive, and the detail it would carry belongs in the quarantine table where only failures are stored. records per year · daily pipeline, 400 tiles, 12 M features per run 365 — too coarse to locate a bad tile per partition 146 000 — the right grain per feature 4 380 000 000 — unreadable and expensive Per-feature detail is not lost by choosing the middle option — it lives in the quarantine table, where only the failures are written.

What to Log at Each Level

DEBUG is for the developer and off in production: request URLs, intermediate shapes, the arguments to a warp. Useful when reproducing a problem locally, ruinous at volume.

The volume each log level should produce Line counts per level for a single nightly run over four hundred partitions. Debug, when enabled, produces about four million lines and is off in production. Info produces roughly one per partition. Warning produces a dozen, each a handled anomaly. Error produces none in a healthy run, which is what makes an error line worth reading. lines per nightly run · 400 partitions DEBUG (off in prod) ≈ 4 000 000 INFO ≈ 400 · one per partition WARNING 12 · handled anomalies worth reviewing ERROR 0 · anything here needs a person

INFO records decisions and outcomes: a stage completed with counts, a source was unchanged and skipped, a partition was materialised, a cache was hit. One or a few lines per unit of work.

WARNING records anomalies the job handled: a retry after a 429, a fallback to a mirror, a quarantine rate above the usual band, a geometry repaired. Someone should look at these eventually; nobody should be woken by them.

ERROR records something that failed and needs a human: an exhausted retry budget, a blocking gate, an unwritable sink. If ERROR lines routinely appear in successful runs, the level is wrong and the signal is being eroded.

Troubleshooting Log Pipelines

Symptom Likely cause Fix
Fields missing on some lines Context bound after the first log call Bind at task entry, before any logging
Log store rejects records Same field name with different types across events Fix the field’s type at the source; never reuse a name
Records not JSON in production A library configured the root logger first Clear handlers in configure_logging, as the recipe does
Enormous debug output from GDAL Third-party loggers inherit the root level Set them to WARNING explicitly
Concurrency mixes partitions Context stored in a module global Use contextvars

Integration Note

Call configure_logging and bind_context at the top of each task, using the orchestrator’s own run and partition identifiers so that logs join to run metadata without translation. Emit the same counts that go to the metrics path in emitting metrics for spatial record counts — the log line explains one run, the metric shows the trend, and having both keyed identically is what makes moving between them instant.

Keeping the Field Vocabulary Stable

Structured logs stop being queryable the moment the same concept appears under three names. A pipeline where one task logs tile, another tile_id and a third partition_key forces every query to know all three, and nobody remembers the third.

The fix is a small shared module that defines the field names as constants and a helper for each common event. It costs a few dozen lines and it turns the field vocabulary into something reviewable: adding a name is a diff, and a reviewer can ask whether the concept already has one.

Type stability matters as much as name stability. A field that is an integer in one event and a string in another will be rejected or silently coerced by most log stores, and the coercion is usually discovered during an incident. Fixing the type at the point of definition — rows_in is always an int, duration_ms always a float — avoids a class of problem that is tedious to diagnose after the fact.