# Logging Convention

```{eval-rst}
.. verified:: 2026-06-20
   :reviewer: Christof Buchbender
```

Every service in the Data Transfer System emits structured log lines in
[logfmt](https://brandur.org/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)

```python
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:

```python
# 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:

```toml
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.

```python
# 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.

```python
# 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:

```toml
[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:

```python
# 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")
```