Logging Convention#

✓
Documentation Verified Last checked: 2026-06-20 Reviewer: Christof Buchbender

Every service in the Data Transfer System emits structured log lines in logfmt format. This document describes the format, the level policy, the runtime level switch, the canonical field dictionary, and the developer API.

How to Log (Developer Quickstart)#

from ccat_data_transfer.logging_utils import get_structured_logger

logger = get_structured_logger(__name__)

# INFO — one line per work-unit stage
logger.info("transfer started", transfer_id=42, location="cologne", size_bytes=1073741824)

# ERROR — failed operation, with automatic traceback capture
try:
    do_archive(archive_id)
except Exception as exc:
    logger.error("archive failed", error=exc, archive_id=7)

# or, equivalently, from inside an except block:
except Exception:
    logger.exception("archive failed", archive_id=7)

get_structured_logger(__name__) returns a StructuredLogger wrapping the standard library logger hierarchy. The handler is installed once on the ccat_data_transfer base logger; module-level loggers propagate to it automatically — no per-module handler needed.

Log Line Format#

Every line is a single valid logfmt record. The LogfmtFormatter handler prepends the three fixed prefix fields exactly once per line:

ts=<utc-iso8601> level=<lowercase> logger=<short-module> msg="<phrase>" <key=value ...>

Field

Source

Notes

ts

emit time

UTC ISO-8601, e.g. 2026-06-20T07:30:33.842106+00:00

level

record level

lowercase: debug, info, warning, error, critical

logger

record.name

ccat_data_transfer. prefix stripped for brevity

msg

first positional arg

always quoted (messages contain spaces)

remaining

kwargs

quoted when the value contains a space, =, ", or is empty

Worked Example — Normal INFO Line#

ts=2026-06-20T07:30:33.842106+00:00 level=info logger=transfer_manager msg="transfer succeeded" transfer_id=42 location=cologne size_bytes=1024

Before / After Contrast#

The superseded style (no longer emitted) mixed a redundant level prefix into the message text and carried additional metadata in an ad-hoc tail:

# BEFORE — superseded, do not write
INFO - msg="transfer succeeded" transfer_id=42 lvl=INFO t=2026-06-20T07:30:33.842106+00:00 logger=ccat_data_transfer.transfer_manager

The leading INFO - prefix made the line invalid logfmt from the first character. The trailing lvl= field printed the logger’s effective threshold (e.g. INFO), not the severity of the individual message — so a DEBUG message emitted while the logger sat at INFO level was still printed with lvl=INFO. The new format is clean logfmt from the first character, with no embedded level prefix and no duplicate lvl=/t=/logger= tail.

Traceback Lines#

Tracebacks are appended on the lines immediately following the summary logfmt line, without a ts= prefix. This intentional absence lets log collectors that key on ^ts= fold them into the same log entry:

ts=2026-06-20T07:35:29.724966+00:00 level=error logger=archive_manager msg="archive failed" archive_id=7 error_type=ValueError error="disk full at /mnt/archive"
Traceback (most recent call last):
  ...
ValueError: disk full at /mnt/archive

The error_type and error fields on the summary line give a machine-readable one-liner for alerting. The full traceback on the following lines is available for deep debugging. Never embed traceback text inside a quoted field value — that breaks logfmt parsing and multiline folding.

Level Policy#

Standing production level is INFO. Levels and their intended meanings:

Level

Meaning

DEBUG

Per-item enumeration, internal state traces, verbose path details. Off in normal production.

INFO

One line per work-unit stage: lifecycle events, state transitions, actionable milestones.

WARNING

Unexpected condition that was handled automatically — the system kept working.

ERROR

A specific operation failed and needs a human to investigate or intervene.

CRITICAL

A manager has hit the consecutive-error threshold; service health is in question.

The Expected-Absence Rule#

A normal or expected absence — “no pending packages found”, “source file not yet arrived”, “nothing to do this cycle” — is not a warning. Log it at DEBUG or INFO. Reserve WARNING for something that was genuinely unexpected but did not require stopping.

Example:

# Correct: absence is expected during normal operation
if not pending:
    logger.debug("no pending transfers", location=location)
    return

# Incorrect: would produce spurious warnings every poll cycle
if not pending:
    logger.warning("no transfers found", location=location)

Runtime LOG_LEVEL Switch#

The active log level is controlled by the LOG_LEVEL operational-config key. The default value is INFO, defined in settings.toml and active in all non-development environments:

LOG_LEVEL = "INFO"   # [default] section
LOG_LEVEL = "DEBUG"  # [development] and [localdev] sections

Allowed values: DEBUG, INFO, WARNING, ERROR.

How the Switch Works#

LOG_LEVEL is stored in the SystemSettings table and is editable through the AdminSettings UI or the operational-config API — both maintain an audit trail of every change.

  • Manager poll loops call apply_runtime_log_level(op_config, session) at the end of every poll cycle (after work(), before the inter-cycle sleep). The OperationalConfig cache refreshes every 60 seconds, so a level change takes effect within one cache window plus one poll cycle — no redeploy or restart required.

  • Celery workers call apply_runtime_log_level at the start of every task execution, using the same 60-second-cached OperationalConfig. A level change reaches workers within one cache window.

The practical result: an incident responder can set LOG_LEVEL=DEBUG, watch verbose output stream from a live service, then set it back to INFO — all without touching the process.

configure_logging() is idempotent: if a LogfmtFormatter handler is already attached to the base logger, only the level is updated. Multiple calls are safe.

Message Phrasing Rules#

  • Lowercase stable phrases — the message text must not change between invocations for the same event. It is the primary grouping key in log aggregators.

  • No interpolation in the message — data belongs in keyword arguments, never in the message string.

  • Past tense for terminal events — "transfer succeeded", "transfer failed", "package created".

  • Acronyms and identifiers keep their casing — BBCP, S3, LTA, DB, Redis.

# Correct
logger.info("transfer succeeded", transfer_id=42, duration_s=12.4)
logger.error("S3 upload failed", error=exc, archive_id=7)

# Incorrect — data in message text; fails ruff G004
logger.info(f"transfer {transfer_id} succeeded in {duration:.1f}s")

Error and Traceback Handling#

Use .error("phrase", error=exc) when you have the exception object at hand. Use .exception("phrase") from inside an except block when the current exception is implicit.

Both methods:

  1. Extract error_type=<ExceptionClass> and error="<single-line message>" onto the summary logfmt line.

  2. Carry the full traceback via exc_info so LogfmtFormatter appends it on the following lines — not embedded inside a quoted value.

For CCATDataOperationError subclasses, transfer_id is also extracted automatically.

# Preferred: pass the exception object
try:
    run_transfer(transfer_id)
except Exception as exc:
    logger.error("transfer failed", error=exc, transfer_id=transfer_id)

# Also correct: inside an except block, exception is implicit
try:
    run_transfer(transfer_id)
except Exception:
    logger.exception("transfer failed", transfer_id=transfer_id)

# Banned: f-string interpolation of exception text
except Exception as e:
    logger.error(f"transfer failed: {str(e)}")   # fails ruff G004

Field Dictionary#

Use these canonical snake_case keys whenever logging the corresponding concept. Keys align with ops-db entity names so log lines are directly correlatable with database records.

Concept

Key

Site

site_id / site

Data location

location_id / location / location_type

Raw data package

raw_package_id

Transfer package

transfer_package_id

Data transfer

transfer_id

LTA transfer

lta_transfer_id

File

file_id / path / rel_path

Physical copy

physical_copy_id

Staging job

staging_job_id

Archive

archive_id

Operation type

op_type

Celery

queue / task_id

Size

size_bytes

Counts

file_count / package_count

Duration

duration_s

Retries

retry_count

Status

status / from_status + to_status

Error

error + error_type

Log Collection: Loki and Grafana#

Promtail (the log collector, configured in the system-integration repo) reads the logfmt output and:

  • Promotes level to a low-cardinality Loki label — enabling label-based filtering such as {job="transfer-manager"} | level="error".

  • Adopts ts as the Loki entry timestamp, so the stored timestamp reflects when the event occurred, not when the collector saw the line.

  • Folds tracebacks using a multiline rule keyed on ^ts=: continuation lines (no ts= prefix) are merged into the preceding entry so the complete traceback appears as one Loki log event.

Do not promote high-cardinality fields such as transfer_id, archive_id, or task_id to Loki labels — they create unbounded label cardinalities and degrade query performance. Query them instead with the logfmt filter:

{job="transfer-manager"} | logfmt | transfer_id="42"

The Promtail pipeline configuration and Grafana dashboard definitions live in the system-integration repository.

Ruff G + LOG Guardrail#

pyproject.toml enforces the structured logging convention across the entire package:

[tool.ruff.lint]
extend-select = ["G", "LOG"]

The G ruleset catches f-string log calls (G004), %-format log calls, and string concatenation in log arguments. The LOG ruleset catches misuse of the logging module itself (e.g. calling logger.warn instead of logger.warning).

ruff check . will fail on any new logger.info(f"...") in the package source. The tests/ and examples/ directories are excluded — they are out of scope for the production log-format convention.

When writing a new log call, always use the keyword-argument form:

# This passes ruff
logger.info("package created", raw_package_id=pkg.id, file_count=n)

# This fails ruff G004
logger.info(f"package {pkg.id} created with {n} files")