Add deployment phase and Traefik compose override
Insert a new Phase 1 (deployment: Compose + Traefik on a server, marked Done) between the base project and the OTel concepts phase, and shift the old phases 1-10 to 2-11. Update summary, intro, README and CLAUDE.md references (spoiler rules now target Phase 9, the bottleneck hunt). Add docker-compose.traefik.yml: an override that fronts the gateway with Traefik and Let's Encrypt and removes all other published host ports. Co-Authored-By: Claude Sonnet 5.5 <noreply@anthropic.com>
This commit is contained in:
Movses Aslanyan
co-authored by
Claude Sonnet 5.5
Claude Sonnet 5.5
parent
b2112e55e1
commit
5e514ecf25
+99
-82
@@ -1,99 +1,116 @@
|
||||
# Phase 3 — Structured logs, correlated to traces
|
||||
# Phase 3 — Distributed tracing
|
||||
|
||||
*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).
|
||||
**Message:** Depends on Phase 2's `common/telemetry.py` bootstrap existing first.
|
||||
|
||||
**Time-box:** 1–2 evenings. The easiest phase, and the biggest quality-of-life win.
|
||||
**Time-box:** 2–3 evenings. This is the biggest phase and the heart of the task.
|
||||
|
||||
**Why traces before logs and metrics?** Two reasons. First, the SDK bootstrap
|
||||
(Resource, providers, exporters, Collector wiring) is shared across all three
|
||||
signals — do it once here and logs and metrics become incremental. Second, tracing
|
||||
is what Babak actually asked for ("trace a single request, see where it stuck"),
|
||||
and once trace IDs exist, log correlation in Phase 4 works on the first try instead
|
||||
of needing rework.
|
||||
|
||||
### 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.
|
||||
- **Trace / span / span context.** A trace is one request's journey; a span is one
|
||||
timed operation within it. Each span carries a trace ID, its own span ID, and its
|
||||
parent's span ID. That parent pointer is the entire data structure.
|
||||
- **Span kinds:** `SERVER` (you handled an inbound request), `CLIENT` (you made an
|
||||
outbound call), `PRODUCER` / `CONSUMER` (async messaging), `INTERNAL`. Getting
|
||||
these right is what makes the service graph render correctly.
|
||||
- **Context propagation.**
|
||||
- *In-process*: OTel uses Python `contextvars`. This works across `await` — but
|
||||
**not** across a bare `threading.Thread` or a `ProcessPoolExecutor` unless you
|
||||
carry the context explicitly.
|
||||
- *Cross-process*: the **W3C Trace Context** headers, `traceparent` and
|
||||
`tracestate`. (B3 is the legacy Zipkin format; you'll see it in older systems.)
|
||||
- The classic bug: any boundary that doesn't carry those headers **starts a brand
|
||||
new trace**. Your Redis Stream hop is exactly this. You'll fix it by hand with
|
||||
`TraceContextTextMapPropagator().inject(...)` into the message payload on the
|
||||
producer and `.extract(...)` on the consumer, then starting the consumer span
|
||||
with that context as parent. This is the single most valuable exercise in the
|
||||
phase — most people never do it manually and never really understand it.
|
||||
- Related: `links` (for a consumer span that batches messages from many traces)
|
||||
and **Baggage** (arbitrary key/values propagated alongside trace context —
|
||||
useful, and a foot-gun, because it's sent on every hop and is visible to
|
||||
downstream systems; never put secrets in it).
|
||||
- **Auto- vs manual instrumentation.** Auto gets you the server span, the HTTP
|
||||
client spans, the DB query spans — 80% of the value for 20 lines of setup. Manual
|
||||
gets you the business semantics: `score_transaction`, `check_sanctions_list`,
|
||||
`settle_ledger_entry`. You need both. Auto-instrumentation alone produces traces
|
||||
that show *which service* was slow but not *why*.
|
||||
- **Span attributes vs metric labels.** Spans are the right home for
|
||||
high-cardinality data (account IDs, transaction IDs, merchant names). Costs scale
|
||||
with volume, not with distinct values. This is why "put it on the span, not the
|
||||
metric" is the standing rule.
|
||||
- **Errors on spans:** set span status to `ERROR` and call `record_exception(e)`.
|
||||
That's how the exception ends up attached to the trace and how the `spanmetrics`
|
||||
connector in Phase 5 will count your error rate.
|
||||
- **Sampling — the concept now, the config later.**
|
||||
- *Head-based*: decide at trace start. Cheap and predictable, but blind — it drops
|
||||
errors at the same rate as successes.
|
||||
- *Tail-based*: decide after the trace finishes. Can keep 100% of errors and slow
|
||||
traces, but must run in the Collector and buffer spans in memory.
|
||||
- For a local demo: sample 100% (`ParentBased(AlwaysOn)`). Understand the trade-off
|
||||
now; you'll configure tail sampling in the Collector in Phase 6.
|
||||
- Whatever you choose, the sampling decision must **propagate** — the sampled flag
|
||||
rides in `traceparent`. Use `ParentBased` samplers so a service doesn't
|
||||
unilaterally drop half of a trace its caller decided to keep.
|
||||
|
||||
### 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*.
|
||||
- Jessica Garson — *Introduction to OpenTelemetry with Python* (PyTexas 2025, ~30
|
||||
min, free) and *…with Django* (DjangoCon US 2024, ~30 min, free). Watch both.
|
||||
- Your chosen Udemy backbone: the instrumentation + context-propagation sections.
|
||||
- SigNoz — *OpenTelemetry FastAPI Instrumentation* (free article) — the most
|
||||
practical FastAPI-specific setup, including batch/queue env vars.
|
||||
- OpenTelemetry docs → Python → *Instrumentation* and *Propagation*. Reference, not
|
||||
reading.
|
||||
- **OpenTelemetry Demo**: open `src/recommendation` (Python) and the Go/TS services
|
||||
side by side. Look specifically at how they mix auto-instrumentation with
|
||||
hand-rolled business spans, and how the Kafka producer/consumer propagate context.
|
||||
This is the "professional implementation" you asked to study.
|
||||
|
||||
### 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.
|
||||
1. **Shared bootstrap.** Create `common/telemetry.py` with a single
|
||||
`setup_telemetry(service_name)` that builds the `Resource`, `TracerProvider`,
|
||||
`BatchSpanProcessor` and OTLP exporter, and installs the propagator. Every
|
||||
service calls it once at startup. Keep it under 60 lines.
|
||||
2. **Auto-instrument all seven services**: `FastAPIInstrumentor`,
|
||||
`HTTPXClientInstrumentor`, `SQLAlchemyInstrumentor`, `RedisInstrumentor`. Verify
|
||||
you now get a connected trace across `gateway → ledger → fraud → sanctions`.
|
||||
3. **Manual spans for business logic.** At minimum: `fraud.score_transaction`,
|
||||
`sanctions.lookup_watchlist`, `insights.aggregate_120d`,
|
||||
`ledger.settle`. Add semantic attributes (`db.system`, `http.route`) and
|
||||
namespaced business ones (`ledgerline.account.id`, `ledgerline.risk.score`,
|
||||
`ledgerline.tx.amount_minor`).
|
||||
4. **Propagate across the Redis Stream by hand.** Producer: create a `PRODUCER` span,
|
||||
inject trace context into the message fields. Consumers (`notifier`, `audit`):
|
||||
extract, and start a `CONSUMER` span with the extracted context as parent.
|
||||
5. **Record exceptions** everywhere you currently `logger.exception(...)`.
|
||||
6. Delete the manual `X-Request-Id` plumbing. Trace ID replaces it and does strictly
|
||||
more.
|
||||
7. **Delete `tests/test_no_observability.py`.** It has done its job — it guarded
|
||||
the "before" state so you could measure against it, and from here it's
|
||||
actively wrong. Everything else in `tests/` must still pass: instrumenting
|
||||
the system is not allowed to change its behaviour, and if `make test` goes red
|
||||
after adding spans, you've broken something real. That is exactly the safety
|
||||
net you built it for.
|
||||
|
||||
**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.
|
||||
### Done when
|
||||
|
||||
- One request produces **one connected trace** covering all seven services,
|
||||
including both async consumers.
|
||||
- With `chaos-nightmare` on, you can open a slow trace and *point at the span* that
|
||||
ate the time.
|
||||
- You can explain why `blocking_event_loop` looks different in a trace than
|
||||
`slow_sanctions` does. (Hint: one shows a long span, the other shows a *gap*
|
||||
before spans start, plus every concurrent request in that process degrading
|
||||
together.)
|
||||
|
||||
|
||||
Reference in New Issue
Block a user