The previous lesson left Jordan Hall holding an alert: OrdersFastBurnRate, 8% of orders are failing. Metrics tell him how much and since when; they don't tell him which orders, in which service, or why. In the Kilometre Zero monolith the answer was one grep away in a single log file. Today an order passes through Kong, three replicas of orders, two of inventory, payments, a Kafka topic and analytics, each writing inside its own container; the log for order P-2026-000125 is scattered across seven places and goes by a different name in each. This lesson builds the other two pillars of observability: structured, centralised logs, so that one identifier brings together everything that happened to a request, and distributed traces, to see the path and the timing of that request across every service. By the end, the three signals are tied together in Grafana: from the metric that alerts, to the trace that pinpoints, to the log that explains.

1. Why tail -f no longer cuts it
2. Structured logs: standard fields, levels and what not to log
3. Collection pipeline: agent, store and query
4. services/common/logs.py: JSON with an injected trace_id
5. Distributed tracing: traces, spans and context
6. Instrumenting with OpenTelemetry: services/common/traces.py
7. Collector, backends and sampling
8. A "create order" trace, annotated
9. Bringing the three signals together
10. Common mistakes and tips
11. Exercises and solutions
12. Conclusion

On a single machine, a log is a file and an incident is investigated with tail -f, grep and less. In a distributed system that stops working for reasons that have nothing to do with convenience; they are structural:

• The information about a request is scattered. Creating order P-2026-000125 produces lines in Kong, orders, inventory, payments and analytics. To piece the story together you have to open five terminals and guess which line in each one belongs to that order.
• The clocks don't agree. As we saw in 01-05, sorting lines from different machines by timestamp can swap cause and effect. You need a correlation identifier, not just the time.
• Containers are ephemeral. When Kubernetes (07-05) replaces an orders pod, its log disappears with it. If the failure happened just before it died, the evidence is gone.
• Free-form text can't be queried. Order 125 rejected for stock (pink-tomato) is readable for a person; to ask "how many stock rejections of pink-tomato in Lleida in the last hour" you have to parse it with brittle regular expressions.
• Volume. 140 couriers sending a position every 5 s, 100 requests/s on orders: that is millions of lines a day. Nobody reads them; you need to be able to filter them.

The solution has two parts: every service writes structured logs with common fields, and a pipeline collects them from every node into a central, queryable store.

A structured log is a record with named fields, normally one JSON line per event:

The fields that every service in km0/ always includes:

Specific fields (order_id, product, replica) are added as extra keys, not inside the message. And yes: order_id is welcome here. What was a cardinality problem in metrics (07-01) is exactly what you want in logs, because a log is indexed by text or by a handful of labels; it doesn't create a series per value.

Logs travel over the network, are stored for months and are read by a lot of people. Everything Module 6 protected with encryption and access control can end up in the clear in a log if nobody is watching:

• Secrets: JWT tokens (not even "for debugging"), passwords, Vault credentials, API keys for the payment gateway, full Authorization headers. An HTTP trace at debug that dumps headers is a leak.
• Personal data in the clear: Anna's name, email, phone number and address. You record user: "u:9f1c3a" (the pseudonym from 06-02) and order_id; anyone who needs the phone number gets it from the database with their own permission and their own audit trail.
• Card data: never, in any form (06-02).
• Full request bodies: besides personal data, they are huge. Log the relevant fields, picked one by one.

The audit logs from 06-05 (who did what, hash chain, object lock in MinIO) are a separate channel with different guarantees: immutability and long retention. The operational logs in this lesson are for diagnosis, are kept for weeks and can be deleted; the two must not be mixed.

Each service writes JSON to stdout (not to files of its own: the container shouldn't know where its logs end up). One agent per node reads the output of every container on the node, adds labels (service, instance, node) and ships it to the central store. Queries are run from an interface that understands the format.

Loki versus Elasticsearch, which is the real architectural decision:

Kilometre Zero chooses Loki because its query pattern is almost always "service + range + trace_id", storage goes to MinIO and it already uses Grafana and Prometheus. Cardinality matters again, this time in Loki's labels: service, instance and level are labels; trace_id, order_id and user are not (they would create a stream per value); you search for them inside the content with | json | trace_id="...".

Logs grow without limit unless someone decides otherwise. A typical policy: debug is not shipped in production; info is kept for 14 days; warning/error for 90 days; Kong logs (one line per request) for 30 days; audit logs are a different system with years of retention. In Loki retention is configured per stream and old chunks are deleted from the bucket. Reducing volume at the source (not logging every delivery position, but a per-minute summary plus the rejections) is usually the most effective measure.

A minimal Promtail and Loki configuration in docker-compose.yml:

With structlog, each service configures the logger once and then uses log.info("event", key=value). A processor looks up the OpenTelemetry context (section 6) and adds trace_id and span_id if there is an active span:

How it is used in orders, with the middleware that captures the X-Request-Id propagated by Kong:

Details worth noticing:

• structlog doesn't format strings: log.warning("stock_reservation_rejected", product=...) produces separate keys. Writing log.warning(f"Rejected {product}") works, but loses the structure. The discipline is "stable event name + fields".
• The redact processor is a safety net, not the policy: the policy is not to pass that data in. But it costs little and stops a log.debug("request", headers=dict(request.headers)) written late on a Tuesday night from dumping tokens.
• The trace_id is read from the active OpenTelemetry span. Without tracing configured, the context is invalid and it simply doesn't appear; with it, every log line from any service taking part in the same request carries the same trace_id, even though the services have done nothing explicit to pass it along.

LogQL queries in Grafana:

The second query shows a valuable use: metrics from logs for questions that don't deserve a metric of their own (07-01, exercise 1) but that you do want to graph now and then.

Logs with a trace_id answer "what happened"; traces answer "where it went and how long each step took". The model, inherited from Dapper (Google) and standardised by OpenTelemetry:

• A trace is the whole tree of work caused by one external request. It is identified by a 128-bit trace_id.
• A span is a unit of work with a name, start, end, attributes (order_id, rpc.method, db.statement), status (OK/ERROR) and events. It has a span_id and a parent_span_id, except for the root.
• The propagation context is what travels from one service to the next so that the receiver's span hangs off the sender's. The standard is W3C Trace Context: a traceparent header:

(Plus an optional tracestate for vendor data.) In HTTP and gRPC it is a header; in Kafka, a message header; in the saga, it is stored alongside the state in the sagas table so that a compensation hours later still hangs off the original trace.

OpenTelemetry (OTel) brings three things: an SDK that creates spans and manages context, automatic instrumentations for well-known libraries (gRPC, FastAPI, psycopg, redis, requests, kafka-python/confluent-kafka), and an export protocol (OTLP) towards a Collector or a backend. The km0/ services share the configuration:

How orders uses it when publishing the event after the saga, and analytics when consuming it:

Two clarifications:

• gRPC, HTTP and PostgreSQL need no code: the instrumentors intercept the calls, create spans and write/read traceparent in the metadata. In inventory, AuthInterceptor and the MetricsInterceptor from 07-01 live alongside the OTel interceptor; the order does not affect the context.
• Kafka does need manual propagation (or the confluent-kafka instrumentor, which does the same under the hood): the message is an inert piece of data consumed later, in another process; nobody "calls" it. The same goes for the saga: order_saga.py stores traceparent in the row of the sagas table, and when the outbox relay or a compensation picks the work back up, they rebuild the context with propagate.extract on that value. Without this, the compensation for P-2026-000125 would show up as an orphan trace with no relation to the order.

Services don't send traces to the backend directly but to the OpenTelemetry Collector: an intermediate process that receives OTLP, processes it (adds attributes, filters, batches, samples) and exports to one or more destinations. Advantages: services only know one endpoint; switching from Jaeger to Tempo means changing the Collector; tail sampling happens there.

Kilometre Zero uses Tempo, with the blocks in the km0-traces bucket in MinIO, for consistency with Loki and Grafana.

Keeping every trace of 100 requests/s with 8-12 spans each is expensive and almost pointless: most are identical and successful. Two strategies:

The usual approach, and what km0/ does, is to combine them: a ParentBased sampler in the SDK so that the decision is consistent across the whole trace, a high ratio at the source (or 100% on low-traffic services) and tail sampling in the Collector to keep what is interesting.

This is how trace 4bf92f35... for Anna's order P-2026-000125, which took 482 ms and ended well, appears in Grafana (Tempo). Indentation shows the parent-child relationship:

What the trace tells us that the metrics couldn't:

• Of the 482 ms, 318 are the external payment gateway. Nothing in km0/ can speed them up; what you can do is run the reservation and the charge in parallel, or accept the order as "pending confirmation" (07-04).
• The UPDATE in inventory took 98 ms on an operation that normally takes 2: there is lock contention on crianza-wine (Grape Harvest Week, lots of orders for the same product). The p99 metric for ReserveStock showed it climbing; the trace says which statement.
• The analytics span belongs to the same trace even though it happens after the response: that is the effect of propagating traceparent in the Kafka headers.
• Every span carries the trace_id, so one click takes you to the log lines of all five services with that identifier, in order.

Observability isn't three tools but a journey: the metric says something is wrong, the trace says where, the log says why. Grafana lets that journey be three clicks:

• Exemplars: Prometheus can store, next to each histogram bucket, the trace_id of a recent observation. In prometheus_client you pass exemplar={"trace_id": ...} to observe(); on the p99 graph, each point has a diamond that opens that trace. This is the metric → trace link.
• Log ↔ trace link: the Loki datasource in Grafana is configured with a derived field that recognises trace_id in the JSON and shows a "view trace in Tempo" button; and Tempo, the other way round, with "logs for this trace", which runs {service=~".+"} | json | trace_id="..." in Loki.
• Trace → metric: Tempo can generate RED metrics from spans (span metrics), useful for services that aren't instrumented with Prometheus.

An example of an exemplar in metrics.py (07-01), now that the trace context exists:

With this in place, at 10:13 on Saturday Jordan's journey is: OrdersFastBurnRate alert → dashboard with the error rate → exemplar diamond over the spike → trace of a failed order with the ReserveStock span in red and rpc.grpc.status_code=UNAVAILABLE → "logs for this trace" → {"event": "circuit_open", "dependency": "inventory"}... which is where the rest of the module comes in.

• Free-text logs "because they read better". They read better one at a time; they can't be queried. Stable event name + fields; for reading locally, structlog has a colourised console renderer.
• Promoting trace_id or order_id to a Loki label. Every value creates a stream and Loki degrades just as Prometheus does with high cardinality. Labels: service, instance, level, environment. Everything else, in the JSON.
• Logging full headers or bodies at debug and leaving it switched on. This is the most common leak of tokens and personal data. A redaction processor as a net, and debug off by default.
• Losing the context across asynchronous hops. A ThreadPoolExecutor, an asyncio.create_task or a Kafka message without propagate.inject breaks the trace. When a trace "ends abruptly", look for the hop with no propagation.
• Head sampling only. It discards 90% of errors. Tail sampling in the Collector to keep errors and slow traces.
• Traces without business attributes. A POST /orders span without km0.order_id forces you to search by time. Add the domain identifier as an attribute (there is no cardinality problem in traces and logs).
• Confusing operational logs with auditing. Retention, immutability and access are different (06-05). The audit trail doesn't go to Loki with 14 days, and debug logs don't go to the bucket with object lock.
• Sending traces straight to the backend from each service. It couples every service to the backend and makes tail sampling impossible. Put a Collector in between.

Exercise 1. Mark tells support that his Artisan Cheese Week order "gave an error" and provides the X-Request-Id the website showed him: 7a1b.... Martha opens Grafana. (a) Write the LogQL query that gathers everything that happened to that request across all services. (b) The query returns lines from Kong and orders with trace_id 9c4d..., but none from inventory; instead, there are inventory lines with a different trace_id in the same second. What has broken and where would you look for it? (c) On the orders line Martha finds the field "user": "u:2b77e1". How does she confirm that it is Mark without anyone else being able to do so on their own, and why doesn't the log contain his email?

Exercise 2. The team decides that delivery should publish one log line for every position received (140 couriers, one every 5 s) at the info level, and that debug should include the message body. (a) Work out how many lines a day delivery alone generates and estimate the volume if each line takes up 350 bytes. (b) Propose an alternative that preserves the ability to investigate "why the dashboard showed van-3-017 in Girona when it was in Lleida" without that volume. (c) What privacy problem does debug with the body add, and which mechanism from this lesson would you use to mitigate it as a last resort?

Exercise 3. The trace in section 8 shows 318 ms in the payment gateway and 98 ms of lock wait in inventory. A colleague suggests "setting TraceIdRatioBased(1.0) on every service so we never lose a trace like this one". (a) Work out how many spans per second the Collector would receive with 100 requests/s to orders and 12 spans per trace, plus the catalog traffic (400 requests/s, 4 spans). (b) Explain why the otel-collector.yaml configuration in section 7 would already have kept this trace even if the ratio were 0.1, and what would have happened if the 0.1 ratio had been configured without ParentBased. (c) A span from the saga's compensation, executed two hours after the order failed, shows up as a new trace rather than inside the order's trace. What is missing, and where?

Exercise 1.

(a) {service=~".+"} | json | request_id="7a1b...", with the time range narrowed down to the moment of the order (Loki scans the content, so the range matters). (b) Kong and orders share a trace_id, so HTTP propagation works; inventory has a different trace_id at the same instant, so inventory is creating new traces instead of continuing the one from orders: the traceparent isn't arriving in the gRPC metadata or isn't being read. Suspects in order: GrpcInstrumentorClient not instrumented in orders (the client doesn't inject), a custom interceptor in inventory that rebuilds the metadata and drops traceparent (check AuthInterceptor/ServiceInterceptor from 06-04), or a gRPC stub created before configure_traces was called. You check it with a log.debug of the metadata received in inventory (redacting authorization) or by looking in Tempo at whether the inventory server span is a root. (c) The pseudonymisation from 06-02 is a keyed function (HMAC) over the user identifier: Martha asks the identity service, with her operator role and her support ticket (it is audited, 06-05), to resolve u:2b77e1; or she computes the pseudonym of Mark's sub and compares. The log doesn't contain the email because it is personal data that would travel to Loki, to MinIO and to the screen of anyone with access to Grafana: what gets recorded is the pseudonym, which identifies nobody without the key, and the order_id, which is what support needs.

Exercise 2.

(a) 140 × (86,400 / 5) = 2,419,200 lines a day; at 350 bytes, about 847 MB a day uncompressed from positions alone, about 25 GB a month. (b) Log at info only what is anomalous (positions rejected by validation, impossible jumps between two positions, out-of-order messages) plus a summary per courier per minute (positions_received, last_ts); to reconstruct the route of van-3-017, the data is already in delivery.positions with hours of retention and in the HDFS lake (04-02): investigate by querying that data, not the log. In addition, one sampled trace per courier every N messages gives the internal path without logging each one. (c) The body contains the exact position of an employee along with their identifier, which is personal data (06-05, exercise 3); if someone switches on debug in production, it gets copied to Loki without the access guarantees of delivery.positions. As a last resort, the redact processor with position/lat/lon in FORBIDDEN_KEYS (and with the body logged as fields, never as an opaque string, so that the redactor can do its job); but the right policy is not to log the body.

Exercise 3.

(a) orders: 100 × 12 = 1,200 spans/s; catalog: 400 × 4 = 1,600 spans/s; about 2,800 spans/s in total, 242 million a day, which the Collector must receive and hold for 10 s each in order to decide (about 28,000 spans permanently in memory, feasible), and of which Tempo would write whatever the policies let through. With TraceIdRatioBased(1.0) the cost is in the network and in the Collector, not in storage, as long as there is tail sampling. (b) The trace lasts 482 ms and the slow policy keeps everything over 500 ms... so it would not keep it on duration; but that doesn't matter either: if it had a span with an error, the errors policy stores it; if not, it falls into the probabilistic 10%. With the 0.1 head ratio, the decision was taken by Kong (or orders) when the trace was created, and ParentBased makes every service honour it: either the whole trace is sampled or nobody generates it. Without ParentBased, each service would roll its own dice: orders would keep it and inventory wouldn't, and the trace would be left with holes (the server ReserveStock span missing, precisely the one with the 98 ms). (c) What is missing is storing the order's traceparent in the row of the sagas table when the saga is created, and, when running the compensation, rebuilding the context with propagate.extract on that value and creating the compensation span with context=ctx (or as a link to the original trace if you prefer a new, linked trace). It belongs in order_saga.py, at the point where the relay or the scheduler picks up a pending saga.

With this lesson, Kilometre Zero's observability has its three signals. Logs stop being text in the files of ephemeral containers and become JSON events with common fields (ts in UTC, level, service, instance, trace_id, request_id, pseudonymised user, event), free of secrets and personal data, collected by Promtail on each node and stored in Loki with low-cardinality labels, queryable with LogQL by the X-Request-Id that Kong assigns or by the trace_id that OpenTelemetry injects. Traces give the path: nested spans with the W3C traceparent propagated through HTTP and gRPC with no code, and by hand through Kafka headers and the sagas table, sent to a Collector that tail-samples to keep errors and slowness, and stored in Tempo. And all three come together in Grafana with exemplars and log↔trace links, so that an alert turns, in three clicks, into a trace with the guilty span and the log lines that explain it.

We now know that it fails, where and why. Jordan's journey ended at an orders log saying circuit_open towards inventory, and in Tempo a ReserveStock span in red with UNAVAILABLE: inventory-1 isn't responding. The next question isn't about observability but about survival: how does the platform detect that a node has gone down and isn't merely slow? Who decides that inv-vlc becomes the primary, and how do you stop inv-bcn from coming back believing it still is? And what if what has been lost is not a process but the last two hours of km0_inventory data? The next lesson covers failure management and recovery: detection, failover with fencing, backups and PITR, and what to do during the minutes in which all of the above is happening.