Movses AslanyanandClaude Opus 5.5
7719ef5fcf
k8s/ is now a faithful port of the mentor's Ansible Grafana stack (Prometheus, Alertmanager, Loki, Tempo, Alloy, Grafana, node-exporter) for the ledgerline-observability namespace on falken: same versions and configs, one *.vione.cloud ingress per tool behind Traefik basic auth, secrets generated by create-secrets.sh into gitignored files. Two fixes over the Ansible role, both verified live: Tempo's metrics-generator needs traces_storage or it runs no processors, and Prometheus needs exemplar-storage to keep exemplars. Ledgerline stays on czy; an Alloy agent in the Traefik override ships its container logs to Loki. Roadmap and CLAUDE.md now point at k8s/. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
103 lines
6.5 KiB
Markdown
103 lines
6.5 KiB
Markdown
# 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:** 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, 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.
|
||
|