Finding the Cause in Logs: Correlation IDs, Trace IDs and Building a Timeline

Version note: The code in this post was built and run with .NET 10; the log queries were run with jq 1.7.1.

Guess First

Payment errors have started at Bookstore. You have the logs of two services (orders and payments) and a change log. The change log shows a configuration change in the payment service at 09:25:47 and a deploy of the payment service from 2.4.0 to 2.4.1 at 09:26:17. The most repeated error line in the logs is "An unhandled exception has occurred while executing the request.", written 245 times. Three questions: did the deploy start the errors, or the configuration change? Does the most repeated message point to the root cause? And is the deploy completely innocent? The answers are in logs I produced by actually running both services.

Narrow the Question Before Opening the Logs

Searching logs in production is like looking for a book in a library: if you don't know what you're after, you get lost between the shelves. Before typing anything into a search box, pin down three answers. What is broken: which endpoint, which error, what does the user see? Since when: the time of the first complaint, the time of the first error? Who is affected: everyone, a group of customers, a single pod?

In this post's case the answers are: the checkout endpoint returns 500, it started around 09:25, it hits random orders. Our evidence is structured logs and a change log. How we produce the logs (ILogger, Serilog, structured logging) is covered in the Web API (Application Programming Interface) series post "Logging in ASP.NET Core: ILogger, Log Levels, Structured Logging and Serilog" and in the upcoming .NET Logging series; log infrastructure (collection, storage) belongs to the upcoming Observability series. Here we read logs.

Anatomy of a Structured Log

Both services write with the JSON (JavaScript Object Notation) console formatter, with scopes enabled:

WebApplicationBuilder builder = WebApplication.CreateBuilder(args);
builder.Logging.ClearProviders();
builder.Logging.AddJsonConsole(options =>
{
    options.IncludeScopes = true;
    options.UseUtcTimestamp = true;
    options.TimestampFormat = "yyyy-MM-ddTHH:mm:ss.fffZ";
});
builder.Services.AddProblemDetails();
builder.Services.AddHttpClient("payments", client =>
    client.BaseAddress = new Uri(builder.Configuration["Payments:BaseUrl"]!));

WebApplication app = builder.Build();
app.UseExceptionHandler();

app.MapPost("/orders/{id:int}/checkout", async (int id, IHttpClientFactory factory, ILogger<Program> logger) =>
{
    // OrderId is added as a scope to every log line in this request
    using IDisposable? scope = logger.BeginScope(new Dictionary<string, object> { ["OrderId"] = id });
    string customerEmail = $"customer{id}@example.com";
    logger.LogInformation("Checkout started for order {OrderId} by {CustomerEmail}", id, customerEmail);

    HttpClient payments = factory.CreateClient("payments");
    using HttpResponseMessage response = await payments.PostAsync($"/payments/{id}", null);
    if (!response.IsSuccessStatusCode)
    {
        logger.LogError("Payment failed for order {OrderId} with status {StatusCode}", id, (int)response.StatusCode);
        throw new InvalidOperationException($"Payment failed for order {id}");
    }

    logger.LogInformation("Checkout completed for order {OrderId}", id);
    return Results.Ok(new { id, status = "Paid" });
});

app.Run();

The payment service imitates a card provider: each call takes between 80 and 260 ms and returns 504 if it exceeds Provider:TimeoutMs from configuration. The value is read on every request through IOptionsMonitor<ProviderOptions>.CurrentValue, so when the file changes the new value applies without a restart. Keep that in mind.

An error line written by the order service:

{
  "Timestamp": "2026-11-08T09:25:48.418Z",
  "EventId": 0,
  "LogLevel": "Error",
  "Category": "Program",
  "Message": "Payment failed for order 1211 with status 504",
  "State": {
    "OrderId": 1211,
    "StatusCode": 504,
    "{OriginalFormat}": "Payment failed for order {OrderId} with status {StatusCode}"
  },
  "Scopes": [
    {
      "Message": "SpanId:dfe81cce851872b8, TraceId:7d861d9c26dcdd37d55db88d26e3e1d7, ParentId:0000000000000000",
      "SpanId": "dfe81cce851872b8",
      "TraceId": "7d861d9c26dcdd37d55db88d26e3e1d7",
      "ParentId": "0000000000000000"
    },
    {
      "Message": "ConnectionId:0HNPTF8OHRA7J",
      "ConnectionId": "0HNPTF8OHRA7J"
    },
    {
      "Message": "RequestPath:/orders/1211/checkout RequestId:0HNPTF8OHRA7J:00000001",
      "RequestId": "0HNPTF8OHRA7J:00000001",
      "RequestPath": "/orders/1211/checkout"
    },
    {
      "Message": "System.Collections.Generic.Dictionary`2[System.String,System.Object]",
      "OrderId": 1211
    }
  ]
}

This line has three different identities, each with its own job. TraceId is this request's distributed trace identity; it crosses service boundaries. RequestId and ConnectionId are Kestrel's local identities, meaningful only inside this process. OrderId is the business-side correlation ID: what you search for when support comes to you with "order 1211". TraceId, SpanId and ParentId are in the scope without any code of mine thanks to the ASP.NET Core host's default activity tracking setting; I only turned on IncludeScopes. The fields under State aren't part of the message text either, they're separate fields, so you can query StatusCode = 504.

Following a Request Across Services with W3C traceparent

To see how TraceId crosses a service boundary, I sent a traceparent header to the order service by hand. Per the W3C (World Wide Web Consortium) Trace Context standard the header's format is version-traceid-parentid-flags: a 2-hex version, a 32-hex trace ID, a 16-hex parent span ID and 2 hex of flags.

curl -s -X POST -H "traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01" \
  http://localhost:5485/orders/3001/checkout

jq -c 'select(.Scopes[0].TraceId? == "4bf92f3577b34da6a3ce929d0e0e4736")
  | {svc: (input_filename|sub(".log";"")), msg: .Message, span: .Scopes[0].SpanId, parent: .Scopes[0].ParentId}' \
  orders.log payments.log

{"svc":"orders","msg":"Checkout started for order 3001 by customer3001@example.com","span":"eff40b740adb25bb","parent":"00f067aa0ba902b7"}
{"svc":"orders","msg":"Checkout completed for order 3001","span":"eff40b740adb25bb","parent":"00f067aa0ba902b7"}
{"svc":"payments","msg":"Payment authorized for order 3001 in 247 ms","span":"8af86f601507cbe2","parent":"920d797f4233866b"}

Three details are worth reading. The order service adopted the incoming trace ID as is, created a new ID for its own span and recorded the span from the header as the parent. In the payment service the trace ID is the same, but the parent is 920d797f4233866b: neither the order service's server span nor my header. It's the client span HttpClient opened for the outgoing call. That span doesn't show up in the order service's log because I raised the System.Net.Http.HttpClient category to Warning. I wrote no code to make the link: HttpClient added the header and ASP.NET Core read it on the other side.

From the Customer's traceId to the Logs

The error response the user sees is the shortest path to the logs. With AddProblemDetails, the 500 response carries a traceId (the mechanics are in the Web API series post "Global Error Handling in ASP.NET Core: Exception Middleware and ProblemDetails"; I cut some of the headers):

HTTP/1.1 500 Internal Server Error
Content-Type: application/problem+json

{"type":"https://tools.ietf.org/html/rfc9110#section-15.6.1","title":"An error occurred while processing your request.","status":500,"traceId":"00-9f370a6bb2a4cecf88a0a618ff4163e3-08b74be4487177d3-00"}

Careful: this traceId isn't the same string as the TraceId field in the logs. It's a full traceparent value; the part to search for is the middle 32 characters. The trailing 00 flag means "not sampled"; the trace ID is still written to the logs. Querying both services with the middle part:

{"svc":"orders","t":"09:39:29.583","lvl":"Information","msg":"Checkout started for order 2001 by customer2001@example.com"}
{"svc":"orders","t":"09:39:29.796","lvl":"Error","msg":"Payment failed for order 2001 with status 504"}
{"svc":"orders","t":"09:39:29.812","lvl":"Error","msg":"An unhandled exception has occurred while executing the request."}
{"svc":"payments","t":"09:39:29.779","lvl":"Warning","msg":"Card provider timed out after 150 ms for order 2001"}

The cause of the two Error lines in the order service is a Warning written 17 ms earlier in the payment service: the card provider timed out at 150 ms. For a single request, the answer is that clear.

Timeline: First Error and Most Frequent Error

A single request's story tells you "why" but not "why now". For that you need to put events on the same axis. I started both services, drove traffic of about 6 checkouts per second and played the scenario: after 35 seconds I changed Provider:TimeoutMs in the payment service's appsettings.json from 2000 to 150, after 30 more seconds I restarted the service as 2.4.1 (the deploy), and 15 seconds later I raised the log level to Debug. The change log:

2026-11-08T09:25:47 config-change payments Provider:TimeoutMs 2000->150 (by ops-portal)
2026-11-08T09:26:17 deploy payments 2.4.0->2.4.1 (pipeline #812)
2026-11-08T09:26:33 log-level payments Default Information->Debug (diagnosis)

First, the most repeated errors. I replace the numbers in messages with N before grouping, otherwise every order number counts as a separate message:

jq -r 'select(.LogLevel=="Error" or .LogLevel=="Warning")
  | (input_filename|sub(".log";"")) + "  " + (.Message|gsub("[0-9]+";"N"))' orders.log payments.log \
  | sort | uniq -c | sort -rn

 245 orders  An unhandled exception has occurred while executing the request.
 244 payments  Card provider timed out after N ms for order N
 244 orders  Payment failed for order N with status N

At the top of the list sits a generic message that says nothing: the line the exception handler middleware writes for every unhandled exception. The most frequent error is usually the last, noisiest link of the chain. Now the first line for each service and level:

jq -r 'select(.LogLevel=="Error" or .LogLevel=="Warning")
  | [.Timestamp, (input_filename|sub(".log";"")), .LogLevel, .Message] | @tsv' orders.log payments.log \
  | sort | awk -F'\t' '!seen[$2 FS $3]++'

2026-11-08T09:25:48.407Z	payments	Warning	Card provider timed out after 150 ms for order 1211
2026-11-08T09:25:48.418Z	orders	Error	Payment failed for order 1211 with status 504

The first signal comes from the payment service, one second after the configuration change. The error count in 10-second buckets says the same:

jq -r 'select(.LogLevel=="Error" and .Category=="Program") | .Timestamp[11:18] + "0"' orders.log | sort | uniq -c

   1 09:25:40
  37 09:25:50
  40 09:26:00
  38 09:26:10
  34 09:26:20
  39 09:26:30
  43 09:26:40
  12 09:26:50

The number of checkouts started in the same buckets is steady between 59 and 67; there's no traffic spike. Putting it all in one table; times are UTC (Coordinated Universal Time):

Because both services write UTC, the lines sort directly. The answers to the opening questions are in the table. The errors started 30 seconds before the deploy; rolling back the deploy would have fixed nothing. The cause is the configuration change. But the deploy left its own mark: the difference between 245 and 244 is a single Connection refused at 09:26:18.193, while the service was restarting. Two separate problems produce the same symptom (500); one is continuous, the other momentary.

One more detail: the configuration change doesn't appear in the logs at all. IOptionsMonitor picked up the new value silently. Without the change log, the most important line of the timeline would be missing. That's why it matters to keep changes (deploys, config, feature flags) in the same place as the logs.

Raising the Log Level at Runtime

WebApplication.CreateBuilder loads appsettings.json while watching the file for changes, and logging filters are bound to configuration. So when you change Logging:LogLevel in the file, the new level applies without restarting the process. In the scenario I set Default to Debug in the payment service at 09:26:33; the first Debug line arrived within the same second:

{"t":"09:26:33.991","msg":"Calling card provider for order 1507, timeout 150 ms"}

This line turns the diagnosis into evidence: the service runs with a 150 ms timeout. In production I set three rules for this. Raise the level only for the relevant category (not Default, but something like Bookstore.Payments); this tiny service wrote 127 Debug lines here, and under real traffic it would write thousands per second. Revert the level after a while and record it in the change log. And if on Kubernetes you mount configuration from a ConfigMap as a file, per the Kubernetes docs a ConfigMap mounted with subPath doesn't receive updates; then the file never changes and no reload happens.

What if there are no logs at all, or they go quiet exactly where you need them? Metrics first: error rate, latency, thread pool. Then the process itself: the dump in post 09 and dotnet-stack and dotnet-trace in post 10 show what the logs don't write. The last resort is to add the missing log and deploy; but that deploy also goes on the timeline as a line.

The Same Queries in Seq, Kibana and KQL

I worked with jq on plain files; in production these logs live in a log platform. I took the query syntax below from each product's documentation and did not run it for this post:

Seq:
@TraceId = '7d861d9c26dcdd37d55db88d26e3e1d7'

Kibana (KQL, ECS):
trace.id : "7d861d9c26dcdd37d55db88d26e3e1d7"

Application Insights (KQL):
union requests, dependencies, traces, exceptions
| where operation_Id == "7d861d9c26dcdd37d55db88d26e3e1d7"
| order by timestamp asc

The KQL (Kibana Query Language) query in Kibana assumes the logs are indexed with ECS (Elastic Common Schema) field names; KQL (Kusto Query Language) in Application Insights keeps the W3C trace ID in the operation_Id field. So there are two different "KQL"s and they look nothing alike; when your team says "we'll search in KQL", make sure you know which one. Whatever platform you use, the method is the same: find the first signal, not the noisiest message; read a single request's story by trace ID; finally put the events on the same axis as the change log.

Production Notes

Logs carry personal data, and during debugging logs are the thing that gets copied and pasted most. In this case the checkout line contains the customer's email:

grep -cE '[A-Za-z0-9._%+-]+@example\.com' orders.log

635

Mask logs before pasting them into a ticket, a chat or an AI (Artificial Intelligence) tool. Replacing emails in every string field with jq is one line:

jq -c 'select(.Message|startswith("Checkout started"))
  | walk(if type == "string" then gsub("[A-Za-z0-9._%+-]+@[A-Za-z0-9.-]+"; "[redacted-email]") else . end)
  | {Message, State}' orders.log | head -1

{"Message":"Checkout started for order 1001 by [redacted-email]","State":{"OrderId":1001,"CustomerEmail":"[redacted-email]","{OriginalFormat}":"Checkout started for order {OrderId} by {CustomerEmail}"}}

walk matters: the email sits both in the rendered Message and in a separate field under State; masking only one isn't enough. The real fix is never writing PII (Personally Identifiable Information) to logs at all; a customer ID is enough instead of an email. How to do that is the subject of the .NET Logging series. The debugging-side rule: if you go looking for secrets or personal data in logs (say, "did a token leak?"), don't share what you find, report that it exists and rotate the secret. And grant access on the log platform by need, not "everyone sees everything".

Common Pitfalls

Starting with the most repeated error. In this case the most frequent message was the generic exception handler line that explains nothing. The first signal was a Warning in another service; someone filtering out Warnings and looking only at Errors would never have seen it.

Saying "it started after the deploy" without checking the times. The errors started 30 seconds before the deploy. A rollback without a timeline would have changed nothing and sent the team down the wrong path.

Searching for the traceId from ProblemDetails as is. That value is a full traceparent in the form 00-...-...-00; the TraceId field in the logs is just the middle 32 characters.

Putting services that log in different time zones side by side. If one service writes local time and another UTC, the timeline shifts by 3 hours and cause and effect swap places. Write everything in UTC and convert on screen.

Not recording configuration changes. A setting that changes live through IOptionsMonitor leaves no trace in the logs; without a change log, the root cause stays invisible.

A Small Experiment

★☆☆ Run this post's "first error" query with Warnings left out, Errors only. Which service does the first line lead you to?

★★☆ Add a log line to the payment service that writes the old and new TimeoutMs values when configuration changes, using IOptionsMonitor<ProviderOptions>.OnChange. Replay the scenario and build the timeline from logs alone, without looking at the change log.

★★★ Add an inventory service call to the order service to form a three-service chain. Write a jq or C# script that prints all spans of a single trace ID as a tree using their parent relationships.

The logs answered "when, and in which request". But if the process crashed, the last log line says nothing, or memory grows quietly, you need to look at the process's internal state at that moment. In the next post we move on to crash and memory dump analysis with dotnet-dump.