Observability Explained: Logs, Metrics and Traces

It is 20:15. Support calls: order 4473 was paid at 19:35, forty minutes ago, and there is still no food and no rider.

You open the dashboard. Every container is green. Orders, payments, kitchen, riders, pricing, notify: all six say UP.

This article follows that one order until we find it, using logs, then metrics, then traces, and ends with the reason the trace could not see the bug on its own. The video tells it as a conversation between two engineers on call, and I voice both of them. This is the written version.

A health check is a fact about a service

Every ten seconds, the platform calls each service's health endpoint and asks whether it is alive. (Ten seconds is the Kubernetes default for a probe.) All six answer yes.

That answer is true. It is also about the wrong thing. A health check is a fact about a service: it is running and it can answer. "Did order 4473 arrive?" is a fact about one request, and no health check answers it. Every service can be healthy while an order is lost between two of them.

So we stop asking about services and start following the order.

Structured logs: search by the order ID

A structured log line is a set of fields, not a sentence. One of the fields is the order ID:

{"ts":"2026-10-23T19:35:02","level":"INFO","service":"payments","order_id":"4473","msg":"message sent to kitchen"}

Because every service writes the same field, one search returns this order's lines from every service:

order_id = 4473
19:35:02  orders    order saved
19:35:03  payments  card charged
19:35:03  payments  message sent to kitchen

And then nothing. The trail stops between payments and the kitchen.

In Java, you do not add the ID to every log call by hand. Put it in SLF4J's MDC once, when the request arrives, and a JSON encoder writes it into every line on that thread:

MDC.put("order_id", order.id());
try {
    handle(order);
} finally {
    MDC.remove("order_id");
}

(The MDC is per thread. Work handed to another thread, or to a reactive pipeline, needs the context copied across.)

The limit of logs: a log shows only what someone chose to write down. You could add more log lines between payments and the kitchen, but that only helps the next order, not this one. And the logs cannot tell you whether this is one order or every order.

Metrics: count instead of reading

So we count. Payments counts the messages it sends to the kitchen, and the kitchen counts the tickets it creates:

kitchen_messages_published_total   (payments)
tickets_created_total              (kitchen)

A number you track over time like that is a metric. All evening, both counters climbed by about fifty a minute, side by side. At 19:31, tickets_created_total went flat, and kitchen_messages_published_total kept climbing.

That answers the question the logs could not. It is not one order. It is every order since 19:31, over two thousand of them by 20:15.

An alert is a rule that watches metrics. One rule on the gap between those two rates, held for five minutes, would have paged the on-call engineer at 19:36, before any customer called. Notice what it watches: a symptom users feel, orders paid with no ticket, not CPU or memory.

The limit of metrics: a counter has no room for one order. (And an order ID never goes into a metric label. Every distinct label value is a new time series, and one series per order grows without end.)

Traces and spans: follow one request

A trace follows one request from start to finish, step by step. Each step is a span: it names the service that did the work and how long it took, and every span of the request shares one trace ID.

Here is the trace for order 4473:

trace 4473
POST /orders                  orders     380 ms
  charge card                 payments   340 ms
  write message for kitchen   payments     4 ms
                              (end)

It goes through orders and payments, and it ends right where payments writes the message. So we open the kitchen's own traces, and there is the surprise: they are separate traces, and none of them is tied to an order. Since 19:31, every one of them ends with the same error:

UnrecognizedPropertyException: Unrecognized field "tip_amount" (class KitchenMessage), not marked as ignorable

What changed just before 19:31? Payments went live at 19:30 with a new field in its message:

{"order_id": "4473", "amount": 540, "tip_amount": 40}

The kitchen still runs the old code, and its reader fails on any field it does not recognize. So every new message fails in the kitchen, while every health check still says yes.

The fix is one line on the kitchen's message class:

@JsonIgnoreProperties(ignoreUnknown = true)
public record KitchenMessage(
        @JsonProperty("order_id") String orderId,
        @JsonProperty("amount") int amount) {}

A note on defaults, because this is the first thing a Java reader will check: a plain Jackson 2 ObjectMapper fails on unknown properties by default. Spring Boot's auto-configured mapper turns that check off, and Jackson 3 turned it off by default. The kitchen in this story builds its own Jackson 2 mapper, which is exactly how this bug happens in real services. And the rule for next time: deploy the reader before the writer.

Why the trace broke

One question is left. Why didn't the kitchen's error show up inside the order's trace?

A trace stays connected only if every service knows which trace it belongs to. When one service calls another over HTTP, the tracing library sends the trace ID in a header for you, the W3C traceparent header:

traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01
             version-trace id-parent span id-flags

But our message does not go straight to the kitchen. Payments writes it into a table first, the outbox, in the same transaction as the payment. A relay sends the row later, in its own loop, after the request and its trace context are gone. A row in a table has no header. So the relay's publish starts a brand new trace, and the trace breaks at the outbox for every order, healthy or stuck.

The fix is one extra column:

ALTER TABLE outbox ADD COLUMN traceparent VARCHAR(55);

Payments stores the current traceparent in the row, in the same transaction that writes the row. The relay reads it back, makes it the parent of its publish span, and puts it on the message's headers. The kitchen continues the same trace. In outline:

// payments, inside the transaction that saves the payment
outbox.insert(new OutboxRow(order.id(), payload, currentTraceparent()));

// the relay, later, in its own loop
for (OutboxRow row : outbox.unsent()) {
    Context parent = contextFrom(row.traceparent());        // the request's trace, restored
    Span publish = tracer.spanBuilder("relay publish").setParent(parent).startSpan();
    try (Scope scope = publish.makeCurrent()) {
        producer.send(row.payload(), headersWithCurrentContext());
    } finally {
        publish.end();
    }
}

(currentTraceparent, contextFrom and headersWithCurrentContext stand for your tracing library's propagator calls: inject into a map, extract from a map.)

Now the kitchen's error shows up inside the order's trace, and the next stuck order is one search away.

The law

A green dashboard tells you the services are alive. It doesn't tell you an order arrived. Follow the request and pass its ID along.

A health check is about a service. A log, a metric and a trace are about requests, and they join up only if the request's ID travels with it at every hop, a table included.

Next time

We deploy something that is not code. We deploy a model.

The delivery app, order 4473, the times, the counters and the tip_amount field are an invented example. What is the strangest bug you have chased while every dashboard was green?