Distributed Tracing with OpenTelemetry

The problem: one order, four services, thousands of log lines

In our shop, an order takes this path:

1. The order service. It gets the HTTP request, saves the order, and puts a message in Kafka.
2. The Worker service. It reads the message and calls the payment service.
3. The payment service. It calls the bank.

A customer calls: “My payment took too long.” Each service has several copies (Pods), and each one writes its own log. These are the questions:

• Which Pods did this request pass through?
• Of the three seconds of total time, how much was in the database, how much in the queue, and how much at the bank?
• Which logs belong to this request?

With logs alone, we must match the log times with each other and guess. This takes hours.

The idea: Trace and Span

Distributed Tracing has two simple ideas:

1. The full path (Trace). The whole journey of one request through all services. It has a unique ID that we call the Trace Id.
2. One part of the work (Span). One specific job inside this journey. For example, a database query, an HTTP call, or processing a message. Each Span has a start time, a duration, a name, a few tags (Tag), and a parent Span.

All Spans of one request have the same Trace Id. Each Span knows its parent. So a tool can show them as a tree and as a waterfall chart:

This chart answers the questions above with one look. Notice one more point: the main request finished after 60 milliseconds, but the Worker’s job happened later and separately. A Trace also shows asynchronous work.

Passing the ID between services

For Spans from different services to join one Trace, each service must give the Trace Id and the parent Span ID to the next service. We call this Context Propagation.

The W3C Trace Context standard defines a header named traceparent. This header has four parts:

1. In HTTP it is automatic. In .NET, ASP.NET Core itself reads the traceparent header from the request. The HttpClient class also adds it to the next request.
2. In a message queue it is not automatic. Kafka does not do this by itself. The producer must put the ID in the message header. The consumer must read it and make its own Span a child of it. Or use a ready Instrumentation library that does the same thing.

If we forget this step, the Trace breaks right at Kafka. See what happens:

Code: setting up OpenTelemetry in .NET

In .NET, the Activity class is the Span, and the ActivitySource class is what creates Spans. These classes are part of .NET itself. OpenTelemetry collects them and sends them to the viewing tool.

builder.Services.AddOpenTelemetry()
    .ConfigureResource(r => r.AddService("orders-api"))
    .WithTracing(tracing => tracing
        .AddAspNetCoreInstrumentation()   // incoming HTTP requests
        .AddHttpClientInstrumentation()   // outgoing HTTP calls
        .AddSource(Telemetry.SourceName)  // our own spans
        .AddOtlpExporter());              // send to the collector

For our own important jobs, we create a manual Span and put the order ID on it. Support does not know the Trace Id, but they know the order number. With this tag, we get from the order number to the Trace:

public static class Telemetry
{
    public const string SourceName = "Shop.Orders";
    public static readonly ActivitySource Source = new(SourceName);
}

public async Task ReserveStockAsync(Order order, CancellationToken ct)
{
    using var activity = Telemetry.Source.StartActivity("ReserveStock");
    activity?.SetTag("order.id", order.Id);

    try
    {
        await warehouse.ReserveAsync(order.Id, order.Items, ct);
    }
    catch (Exception ex)
    {
        activity?.SetStatus(ActivityStatusCode.Error, ex.Message);
        throw;
    }
}

The question mark after activity is important. If nobody listens to this source, or this request was not chosen to be saved, the StartActivity method returns null. This is on purpose, so that when a Trace is not needed, it also has no cost.

Passing the ID through Kafka

This code is written with the Confluent.Kafka library and the OpenTelemetry context propagation API. The producer side puts the ID in the header:

private static readonly TextMapPropagator Propagator = Propagators.DefaultTextMapPropagator;

public async Task PublishAsync(OrderPlaced message, CancellationToken ct)
{
    using var activity = Telemetry.Source.StartActivity("PublishOrderPlaced", ActivityKind.Producer);

    var headers = new Headers();
    Propagator.Inject(
        new PropagationContext(activity?.Context ?? default, Baggage.Current),
        headers,
        (h, key, value) => h.Add(key, Encoding.UTF8.GetBytes(value)));

    await producer.ProduceAsync("orders",
        new Message<string, string> { Key = message.OrderId.ToString(), Value = Serialize(message), Headers = headers }, ct);
}

The consumer side reads the ID and makes its own Span a child of it:

var parent = Propagator.Extract(default, result.Message.Headers,
    (h, key) => h.TryGetLastBytes(key, out var bytes)
        ? new[] { Encoding.UTF8.GetString(bytes) }
        : Enumerable.Empty<string>());

Baggage.Current = parent.Baggage;

using var activity = Telemetry.Source.StartActivity(
    "ProcessOrderPlaced", ActivityKind.Consumer, parent.ActivityContext);

Where does the data go?

The app sends Trace data with the standard OTLP protocol. Usually it first goes to an OpenTelemetry Collector. The Collector gathers the data, filters it, and sends it to the viewing tool. Tools like Jaeger, Grafana Tempo or Zipkin. Because the protocol is standard, changing the viewing tool does not need a change in the app code.

Sampling

Saving the Trace of every request in a high-traffic system is very expensive. So we keep only a part. We have two ways:

Head-based sampling in .NET looks like this. ParentBased means: if the previous service has decided, follow the same decision:

tracing.SetSampler(new ParentBasedSampler(new TraceIdRatioBasedSampler(0.1)));

Important rules

1. Check context propagation at every boundary. HTTP, message queues, background jobs. Wherever the ID is lost, the Trace breaks.
2. A business ID on the Span. The order number, not sensitive data.
3. Put the Trace ID in the logs too. So you get from an error log straight to the Trace, and the other way around.
4. Create manual Spans for important jobs, but not for every method. Too many Spans cost money and also clutter the chart.
5. A Span name should be short and fixed. Do not put IDs in the name. Make them tags. A fixed name lets us compare similar Spans.
6. Mark errors on the Span. Otherwise, in the viewing tool, a failed Span looks green.

Common mistakes