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: Not started

Message: Depends on Phase 3 (trace IDs must exist before log correlation means anything).

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). 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 config.alloy.j2 — add a logs output on the receiver plus an otelcol.exporter.loki → loki.write chain — re-run the playbook, 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 datasources.yml.j2; 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.