Threading Five Services with One Id

One-line summary

In a system with five services, the way to answer "an order disappeared" is not to guess by time but to link lines by an id that travels with each request, and the problem you actually run into in the field is not a missing id but the chain breaking at some point in the middle.

Why this is needed

Grouping by time works only when requests come sparsely. If dozens come in per second, dozens of lines around 02:01:08 come out per service, and there is no basis to choose which of them belongs to this order. On top of that, if each service's clock differs a little, even the order looks reversed.

So when a request starts, you create an id and pass it along to every downstream call. The problem was that each called that id by a different name — X-Request-Id, X-B3-TraceId, X-Correlation-Id. With different vendors, the chain broke. W3C Trace Context is the standard that settled its name and format into one, and nearly all the tracing libraries that come out now use this header.

How it works

traceparent is a single fixed-length value.

00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01

The four hyphen-separated fields are version · trace-id · parent-id · trace-flags, respectively. The current version is 00. The trace-id is 16 bytes (32 lowercase hex characters) and points to the whole trace, and the parent-id is 8 bytes (16 characters) and points to this one request. Other tracing systems call the parent-id a span-id. The specification writes that both values are invalid if all zeros, and that a vendor must ignore an invalid traceparent (MUST). The same goes for a parent-id with uppercase hex mixed in.

The names get confusing here. The parent-id of the header I received is the span id of the party that called me, and the parent-id of the header I send is my own span id. So if you keep both the incoming and the outgoing headers in the log, the parent-child relationship is restored exactly from those two values. That is the span tree.

trace-flags is an 8-bit field. Today only one sampled flag is used, but the specification pins down that you should mask, not interpret the hex as a number and compare with that value — not only 01 is sampled; 09 is sampled too (the value with 00000001 and 00001000 turned on together). Trace Context Level 2 added a random-trace-id flag in the second bit, so in practice 03 and 02 have started circulating. A count made with flags == "01" is already wrong.

tracestate is a list of name=value entries per vendor, and each system that participated in the trace adds a new entry on the left. The leftmost is the system that wrote the current traceparent.

The logging conventions mesh with this too. The OpenTelemetry log data model places TraceId, SpanId, and TraceFlags fields in the log record and writes that if a SpanId is present, a TraceId should be present too (SHOULD). This is where logs and traces meet on the same id.

What you see in the field

It breaks. The specification writes that intermediary components must at least pass traceparent and tracestate through unchanged so that the trace does not break (MUST), but old uninstrumented services, proxies, and message queues simply drop the header. The services after them have no header received, so they start the trace anew. The screen shows two short traces, and the relationship between them is nowhere.

What you use then is the business key. If you join the before and after with a value the system carries anyway, such as an order number or a payment number, you can line up even the part where the trace broke on one line. It is not a complete solution — a business key is the same value even across retries, so it cannot point to a single request. Even so, it is enough to prove "where it broke," and that proof becomes the basis for making the next deployment pass the header through.

Its own time looks like a lie. If you subtract the time of the child spans from a span's duration, you get the time that service spent itself. But if a child is not instrumented and cannot be seen, that time is loaded as is onto the parent's own time. The conclusion "the order service spent 800 ms" is really "something invisible that the order service calls spent 800 ms." A span whose own time is unusually large is not the culprit but the next place to instrument.

Only samples remain. With heavy traffic, not every trace is stored. A trace with sampled turned off is either entirely absent from the screen or only partly there. If the order the customer mentioned was left out of the sample, it is normal for the tracing tool to have nothing, and then you have to go down to the logs.

What you will do in the next lab

You build the logs of five services, split every traceparent into four fields, and quarantine invalid values with reasons. You find the trace-id of the order the customer mentioned, line up the lines of that trace in time order, build the span tree with parent-id, and work out each span's duration and own time. Then you find the service where the header broke, join the before and after with the order number, read the sampled flag as a mask to separate traces that were recorded from those that were not, and leave the investigation results as a report. The grader re-parses the originals itself and compares them with your results.