LedgerLine/docs/roadmap/phase-4.md

# Phase 4 — Structured logs, correlated to traces

*Part of `docs/roadmap/` — see [`intro.md`](intro.md) for platform/background context and [`summary.md`](summary.md) for how every phase fits together. Prev: [`phase-3.md`](phase-3.md) · Next: [`phase-5.md`](phase-5.md)*

**Status:** Done

**Message:** Done 2026-10-13. Both directions work in two clicks: a Loki line's
`TraceID` derived field opens the trace, and a Tempo span's logs link returns that
request's lines from every service that logged, the audit/notifier consumers
included (verified live on trace `a4f034b1d66a69b357aef66a647afcef`).

- `common/logging_config.py`: structlog → one JSON object per line on stdout, with
  stdlib and uvicorn records going through the same processor chain. Processors
  add level, logger, ISO-8601 UTC timestamp, `service`, lowercase `trace_id`/`span_id`
  (only inside a valid span) and field-name redaction. `uvicorn.access` is left
  alone on purpose, because re-enabling its propagation undoes `--no-access-log`.
- Every call site is now a past-tense event with shared field names (`account_id`,
  `transaction_id`, `amount_minor`, `risk_score`, `status_code`, `consumer_group`,
  `message_id`, `chaos_flag`). New events: `transaction_failed` (the gateway's 502
  path used to log nothing), `transaction_scored`, `holder_screened`,
  `stream_message_processed`. `holder_name` is no longer logged at all.
- The czy agent sets `service_name` from the Compose service name. Before that
  change, Loki derived it from `container` (`ledgerline-sanctions-1`), so Grafana's
  generated `{service_name="sanctions"}` matched nothing. Streams written before
  2026-10-13 17:52 UTC keep the old value and don't link.
- **Skipped:** Build step 5 (the OTLP-logs silent-drop experiment; Alloy still has no
  `logs` output) and the second Build step 6 (migrating `count_log_lines` to LogQL). The tests run
  against the local stack, whose logs never reach Loki, so the migration first
  needs a local log path into Loki.
- **Carry forward:**
  - The pathology tests still count `docker compose logs` lines matching
    `(?i)lookup` (sanctions) and `(?i)healthz` (downstreams). Those words must stay
    in exactly `lookup_received` and `healthz_probe_received`.
  - `chaos_engaged` lines stay at INFO by choice, so they're visible in Loki during
    Phase 9.
  - httpx's `HTTP Request:` INFO lines are kept; most of gateway's volume is the
    frontend health poll.
  - The deploy hot-reloads bind-mounted code into the old image before
    `--build`, so a commit that adds a dependency crash-loops the services for
    about a minute.
  - `alloy-agent`'s config is a single-file bind mount: after `git pull` it needs
    `docker compose ... restart alloy-agent` to see the new file.

**Time-box:** 1–2 evenings. The easiest phase, and the biggest quality-of-life win.

### Concepts

- **Structured logging.** Replace prose (`f"processing tx for account {id}"`) with
  events: a stable event name plus typed fields (`event="transaction_settled"`,
  `account_id=…`, `amount_minor=…`, `duration_ms=…`). Past-tense event names.
  Consistent field names across all seven services — `account_id` everywhere, never
  `accountId` in one place and `acct` in another. This is what makes LogQL queries
  possible at all.
- **Trace–log correlation.** Every log line emitted inside an active span must carry
  `trace_id` and `span_id`. This is what turns "I have logs and I have traces" into
  "one pane of glass": click a span → see its logs; click a log line → open its
  trace. Both directions are configured, and you'll set both up.
- **Two ways to ship logs, and which one your platform actually does:**
  - **stdout → collector scraping → Loki.** The container-native way. Your app just
    prints JSON; the pipeline handles the rest. Decoupled, survives app crashes,
    standard in Kubernetes. **This is the only path wired in your Alloy config**
    (`loki.source.docker` reading the Docker socket).
  - **OTLP log exporter → collector → Loki.** Logs travel the same path as traces,
    with the same Resource attributes attached automatically. Cleaner correlation,
    but the app owns delivery. **On your platform this currently goes nowhere** —
    Alloy's OTLP receiver has no `logs` output, so OTLP log records are accepted and
    dropped in silence.
  - Do both anyway: use stdout for most services, and *extend Alloy* to wire the
    OTLP logs path for one or two. Then argue the trade-off from experience. That
    comparison — including the fact that a misconfigured pipeline fails silently
    rather than loudly — is precisely what Babak will probe.
- **The field name is not a style choice here.** Your Loki datasource is provisioned
  with `matcherRegex: 'trace[_-]?id["=: ]+([a-fA-F0-9]+)'`, which is case-sensitive.
  A log line must carry lowercase `trace_id`. OpenTelemetry's logging
  auto-instrumentation emits `otelTraceID`, which **will not match** — you'd get
  logs and traces both arriving, no errors anywhere, and no clickable link. Hence
  structlog with an explicit processor rather than the auto-injection shortcut.
- **Log levels in production.** Run INFO. One service left on DEBUG can out-produce
  your entire fleet, and Loki bills/indexes on volume.
- **What never goes in a log:** credentials, tokens, full card numbers, PII. A naive
  `json.dumps(request.__dict__)` will happily dump an `Authorization` header. Build
  redaction into the processor chain, not into each call site.
- **Loki's label model — the thing that surprises everyone.** Loki indexes *labels*,
  not log content. Labels should be few and low-cardinality (`service`, `env`,
  `level`). Everything else lives in the log line body and is filtered at query time.
  Putting `trace_id` in a Loki *label* is a classic cardinality catastrophe; put it
  in the JSON body and use a **derived field** to make it clickable.

### Resources

- *Structured Logging in Python With Structlog: Correlating Logs, Traces, and
  Errors* (dev.to) — free, and the most copy-pasteable structlog + OTel processor
  setup, including the hex formatting for trace/span IDs.
- OpenTelemetry Python Contrib docs → *Logging Instrumentation* — for
  `OTEL_PYTHON_LOG_CORRELATION` and the auto-injected `otelTraceID` / `otelSpanID`
  fields, if you'd rather not hand-roll a processor.
- Udemy backbone: the Loki + LogQL sections.
- Grafana docs → Loki → *Send data via OTLP* and *derived fields*.

### Build

1. Replace `common/logging_config.py` with `structlog`, JSON renderer, plus a
   processor that pulls the current span context and injects `trace_id` / `span_id`.
2. Rewrite every log call as an event with fields. Keep it to ~2–4 log lines per
   handler: request received (or rely on the span), business decision, error.
3. Add a redaction processor with a denylist of field names.
4. Ship all seven services' logs via **stdout**, and confirm they arrive in Loki
   with a `container` label (Alloy's relabel rule sets it from the Docker container
   name, e.g. `ledgerline-gateway-1`). Here that's the Alloy agent on czy
   (`observability/alloy-agent/config.alloy`, already running), not the
   cluster's Alloy. Verify the `trace_id` field is present *and lowercase* in
   the JSON body.
5. **Prove the silent-drop for yourself.** Add an OTLP log exporter to one service,
   send some records, and watch nothing appear in Loki. Then check the Alloy UI:
   the receiver shows traffic, and the pipeline shows no logs output. Now extend
   `k8s/alloy/config.alloy` — add a `logs` output on the receiver plus an
   `otelcol.exporter.loki` → `loki.write` chain — `kubectl apply -k k8s/`, and watch
   them arrive. Write down what you'd have done to debug this if you *hadn't* known.
   That is the most transferable half-hour in the whole project.
6. Confirm the provisioned correlation works in both directions: Loki's
   `derivedFields` on `trace_id` → Tempo, and Tempo's `tracesToLogsV2`
   (`filterByTraceID: true`) → Loki. Both are already in `k8s/grafana/datasources.yml`; you
   are verifying, not writing. If a link doesn't appear, the regex didn't match
   your field name — check that before anything else.
6. **Migrate the test suite's log-counting helpers.** Three pathology tests
   (`retry_storm`, `no_batching`, `chatty_health`) currently count matching lines
   in `docker compose logs` — the only cross-service call counter that existed at
   Phase 0. Rewrite `tests/harness/containers.py::count_log_lines` to query Loki
   with LogQL over structured fields instead. This is a small change and a
   pointed one: notice how much shorter and more precise the assertion gets, and
   that it now works without shelling out to Docker at all. That delta is the
   value of structured logging, measured on your own code.

**Done when:** from a slow trace you can click into that request's logs, and from
any log line you can click into its trace — in both directions, in two clicks.