Add project documentation and Claude instructions
Roadmap, phase specs, pathology catalog, and CLAUDE.md establishing Ledgerline as an observability learning project built on a deliberately imperfect seven-service payments backend.
This commit is contained in:
Movses Aslanyan
@@ -0,0 +1,99 @@
|
||||
# Phase 3 — 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-2.md`](phase-2.md) · Next: [`phase-4.md`](phase-4.md)*
|
||||
|
||||
**Status:** Not started
|
||||
|
||||
**Message:** Depends on Phase 2 (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.
|
||||
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.
|
||||
|
||||
Reference in New Issue
Block a user