LedgerLine/docs/roadmap/phase-4.md

Phase 4 — Structured logs, correlated to traces

Part of docs/roadmap/ — see intro.md for platform/background context and summary.md for how every phase fits together. Prev: phase-3.md · Next: 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.
7. 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.