[CS] CARLOS SEIDL PT
Articles

Logs, metrics and traces in .NET: three views of the same incident

A deploy makes checkout slow: how a metric by version, a log with the trace id and a distributed trace in .NET 10 lead from the alert to the cause.

By 9 min read
  • Observability
  • Logs
  • Metrics
  • Traces
  • .NET 10
Capa do artigo: Logs, metrics and traces in .NET: three views of the same incident

Logs, metrics and traces show the same problem from different angles. A metric answers "how is the system behaving?", and it is the one that fires the alert. A log answers "what happened?" with the detail of each event. A trace answers "what path did the request take?" and shows which service the time was spent in. On its own, each signal leaves the investigation half done; linked by the deploy version and the trace id, they lead from the alert to the cause. In this article, in .NET 10, a deploy makes checkout slow, and I follow the incident through the three signals: the payments service p95 goes from 43 ms to 807 ms in the new version, the error log carries the trace id, and the trace shows that 812 of the 825 ms were spent in a single step.

Three questions about the same problem

The three signals do not compete with each other. Each one keeps a different kind of information, at a different cost:

  • Logs = "what happened?" A timestamped record of each event: errors, warnings, requests, state changes. It is the most detailed signal and the most expensive to keep, because it grows with traffic.
  • Metrics = "how is the system behaving?" Numbers aggregated over time: request rate, error rate, latency, CPU, memory. They are cheap, keep months of history and are the basis of alerts and trends.
  • Traces = "what path did the request take?" A request that goes through several services becomes a tree of spans, each with a start, a duration and a status. The trace shows where the time went and where the error appeared.

During an incident, seeing the signals is only part of the job. The hard part is linking them to each other and to what changed: the deploy, the commit, the dependency. That is what the example in this article shows.

The scenario: a deploy that makes checkout slow

I wrote three ASP.NET Core services, each on its own port: gateway, which receives the checkout; orders, which saves the order; and payments, which runs a fraud check before approving the payment. The gateway calls orders, which calls payments, over HTTP.

Halfway through the run, payments moves from version 1.4.0 to 1.5.0. The new version has a bug in the fraud check: for 10% of the orders it takes 800 ms instead of 20 ms, and for half of those (5% of the total) it times out and returns 502. A client sends 200 checkouts before the deploy and 200 after it, 20 at a time.

The conditions: everything runs on one machine, in one process, with .NET 10 (SDK 10.0.402). The delays are simulated with Task.Delay, so the numbers are there to follow the reasoning, not as a benchmark. The signals are collected in memory and printed to the console; in production, OpenTelemetry would play that role and send everything to a backend.

What .NET already gives you, with no packages

The three signals already exist in the platform. ASP.NET Core creates an Activity (the .NET span) for each incoming request and publishes the http.server.request.duration metric. HttpClient creates a span for each call and propagates the W3C traceparent header, so the next service continues the same trace. And ILogger is everywhere.

To read these signals in the example, an ActivityListener and a MeterListener are enough. It is the same mechanism OpenTelemetry uses under the hood:

C#
_traces = new ActivityListener
{
    ShouldListenTo = s => s.Name is
        "Microsoft.AspNetCore" or
        "System.Net.Http" or
        "Payments",
    Sample = (ref ActivityCreationOptions<
        ActivityContext> _) =>
        ActivitySamplingResult.AllDataAndRecorded,
    ActivityStopped = Spans.Add,
};
ActivitySource.AddActivityListener(_traces);

_meters.InstrumentPublished = (i, l) =>
{
    if (i.Name == "http.server.request.duration")
        l.EnableMeasurementEvents(i);
};

ShouldListenTo picks the span sources: the ASP.NET Core one, the HttpClient one and Payments, which is mine and shows up later. Sample decides how much to keep; here, everything. In production, with a lot of traffic, you keep a sample.

Metrics: how is the system behaving?

A metric only helps find the cause if it carries the right dimensions. A middleware in each service puts the service name and version on the request span and metric. The built-in metric accepts extra tags through IHttpMetricsTagsFeature:

C#
app.Use(async (ctx, next) =>
{
    // Same name and version on the span and the metric.
    var v = version();
    var span = Activity.Current;
    span?.SetTag("service", name);
    span?.SetTag("service.version", v);
    var tags = ctx.Features
        .Get<IHttpMetricsTagsFeature>()?.Tags;
    tags?.Add(new("service", name));
    tags?.Add(new("service.version", v));

    var route = (ctx.GetEndpoint() as RouteEndpoint)
        ?.RoutePattern.RawText;
    if (span is not null)
        span.DisplayName =
            $"{ctx.Request.Method} {route}";

    await next();
    if (ctx.Response.StatusCode >= 500)
        span?.SetStatus(ActivityStatusCode.Error);
});

The middleware also gives the span the route name (POST /payments/{id:int}) and marks the span as an error when the response is 5xx. With the 400 requests, the metric grouped by service and version looks like this:

Text
metrics: http.server.request.duration
service   version  requests  5xx    p50     p95
gateway   2.1.0         400   10     46 ms  208 ms
orders    3.0.2         400   10     45 ms  108 ms
payments  1.4.0         200    0     30 ms   43 ms
payments  1.5.0         200   10     31 ms  807 ms

The alert starts at the gateway: 10 5xx responses and a p95 of 208 ms. But look at how misleading the gateway number is. It mixes the 200 good requests from before the deploy with the 200 from after it, and the problem, which hits 5% of the total, sits right at the p95 boundary and shows up diluted. This value also moves between runs; in mine, it stayed between 170 and 273 ms. When the same metric is split by the service.version tag, the cause is obvious: payments 1.4.0 had a p95 of 43 ms, 1.5.0 has 807 ms and all the errors. The metric already said when and where. It does not say why.

Logs: what happened?

Payments logs every approved payment and every failure. The log uses a message template, so the order number becomes a field, not just text:

C#
using (var span = Source.StartActivity("fraud-check"))
{
    await Task.Delay(bug ? 800 : 20);
    if (bug && id % 20 == 0)
    {
        span?.SetStatus(ActivityStatusCode.Error);
        log.LogError(
            "Fraud check timed out for order {OrderId}",
            id);
        return Results.StatusCode(502);
    }
}

log.LogInformation(
    "Payment approved for order {OrderId}", id);
return Results.Ok();

The detail that turns the log into a lead is in the logger. Each line keeps the trace id of the request in progress, read from Activity.Current:

C#
var traceId =
    Activity.Current?.TraceId.ToString() ?? "-";
t.Logs.Add(new(
    level, service, format(state, error), traceId));

The result:

Text
logs: 400 lines, 10 errors
  error payments "Fraud check timed out for order 220"
        trace=b6cc653596e1ddbc4eebb2f2e6493937
  error payments "Fraud check timed out for order 240"
        trace=849a183c274cb8a0178a811f6f1f718b

That is 400 lines for 400 requests, and only 10 matter. The log says exactly what happened: the fraud check timed out on order 220. But it only sees one service. Without the trace id, you would have to guess which gateway request matches that line, based on the time. With it, the next step is direct.

Traces: what path did the request take?

The ASP.NET Core and HttpClient spans show the calls between services. What happens inside a service needs a span of its own. That is why the fraud check, in the snippet from the previous section, runs inside Source.StartActivity("fraud-check"), created from an ActivitySource:

C#
static readonly ActivitySource Source = new("Payments");

With the trace id from the log, I build the span tree of that request:

Text
trace b6cc653596e1ddbc4eebb2f2e6493937
  load: call /checkout/220                    825 ms  ERROR
    gateway: POST /checkout/{id:int}          824 ms  ERROR
      gateway: call /orders/220               824 ms  ERROR
        orders: POST /orders/{id:int}         824 ms  ERROR
          orders: call /payments/220          813 ms  ERROR
            payments: POST /payments/{id:int}  813 ms  ERROR
              payments: fraud-check           812 ms  ERROR

The trace shows the whole path, from the client to the fraud check, with the same trace id in the three services, thanks to the traceparent propagated by HttpClient. Of the 825 ms of the request, 812 ms were spent in fraud-check. The gateway and orders are marked as errors, but they only passed on the 502 that came from below. Without the trace, each team would see its own service in red and start investigating in the wrong place.

From alert to cause: linking the three signals

The full path of the incident was this:

  1. Metric: the gateway starts returning 5xx and its p95 goes up. Split by service.version, the problem is in payments 1.5.0.
  2. Log: filtering the payments errors, the message says what failed (the fraud check) and carries the trace id.
  3. Trace: with the trace id, the span tree shows that almost all the time was spent in fraud-check.

What made this path possible was not a tool, it was two conventions. The first is using the same service name and version in the three signals; the version is what links the signal to the deploy and, from there, to the commit. The second is writing the trace id in every log. In OpenTelemetry, this information has standard names, such as service.name and service.version; in the example, I used service to keep it short.

There are tools that go further and cross these signals with deploys, commits and past incidents to suggest a hypothesis for the cause, some of them already with AI agents. But all of them depend on the same starting point: signals with a consistent name, version and trace id. Without that, not even an agent can link the alert to the change that caused it.

Things that matter in production

  • Metric cardinality. Version, service, route and status are good tags, because they have few values. Order number, user or full URL are not: each new value creates a new series, and the cost explodes. That kind of detail goes to the log and the trace.
  • Log with a template, not with built text. LogError("... {OrderId}", id) keeps the order as a searchable field; string interpolation keeps only text and prevents filtering.
  • Trace sampling. Keeping 100% of the traces only makes sense with little traffic. In production, use sampling and, if the backend allows it, always keep the traces with errors.
  • Your own span on the steps that matter. ASP.NET Core and HttpClient show the boundaries between services. A database call, an external check or heavy computation needs an ActivitySource of your own to show up in the trace.
  • OpenTelemetry instead of the listeners. The listeners in the example are there to show the mechanism. In production, use the OpenTelemetry packages for .NET, which read the same sources and send the three signals over OTLP to the backend you choose.

Summary

  • Metrics say how the system is doing and fire the alert; logs say what happened; traces say where the request went and where the time was spent.
  • .NET already emits the three signals: an Activity per request, http.server.request.duration and ILogger, with traceparent propagation through HttpClient.
  • The version tag on the metrics links the problem to the deploy: the payments p95 went from 43 ms to 807 ms only in 1.5.0, while the aggregated gateway number diluted the effect.
  • The trace id in each log leads from the error to the trace, and the trace showed that 812 of the 825 ms were in the fraud check.
  • The same name and version in the three signals and the trace id in every log are worth more than any tool you pick later.

To go further, also read Resilience in .NET, which covers the deadline and the degradation that payments 1.5.0 lacked, and Kubernetes with .NET, where these services usually run. If you need observability in your API, see the .NET backend service.

References

← all articles