Distributed Tracing and Structured Logging in .NET

The hardest bugs aren't the ones that crash the application. They're the ones that produce subtly wrong results, fail intermittently under specific conditions, or emerge only when multiple services interact under load. These bugs resist ad-hoc investigation. They demand a systematic approach.

This post covers the methodology and tooling I rely on for debugging .NET applications in production: a structured process for narrowing down root causes, correlation IDs for tracing requests across service boundaries, structured logging that remains searchable at scale, and Activity-based distributed tracing.

The Scientific Method

Before reaching for any tool, apply a deliberate process. The most common debugging mistake is skipping straight from "it's broken" to modifying code. A structured approach prevents that:

1. Observe. What is the actual behavior? What was the expected behavior? When did the problem first appear?
2. Hypothesize. What could account for the difference? List at least three candidate causes.
3. Test. Design the smallest possible experiment that eliminates one hypothesis.
4. Analyze. Did the experiment confirm or reject the hypothesis?
5. Iterate. Continue narrowing until the root cause is reached.

Listing multiple hypotheses at step two is what makes the method work. It guards against fixating on the first plausible explanation and missing the actual cause entirely. Step three is where most of the time goes, and the two sections after this one are about doing it well: checking the assumption a hypothesis rests on, and building a reproduction small enough to be trusted.

Reproduction Before Investigation

A bug that can't be reproduced is a bug that can't be fixed with confidence. Before spending time on investigation:

• Document exact reproduction steps so others can trigger the failure independently.
• Isolate variables. Does the problem occur in all environments? With all inputs? At all times of day?
• Use git bisect for regressions. When the behavior was known to be correct at some prior point, bisecting the commit history is the fastest path to the offending change.

git bisect start
git bisect bad                    # Current commit exhibits the bug
git bisect good v1.2.0            # This release was known-good
# Git checks out a midpoint -- test it and mark as good or bad
# Repeat until the offending commit is isolated

Verifying the Assumption, Not the Code

Most hypotheses at step two are not really about the code under investigation. They rest on an assumption about what something else does: a library, the runtime, a build tool, an API being called. Test the assumption at its source before designing an experiment around it, because an experiment built on a wrong assumption produces a confident wrong answer.

Three tiers, in descending order of authority.

1. The vendor's source, where it is available. It describes what actually happens.
2. The vendor's documentation. It describes what is promised, which is a different thing and is sometimes silent exactly where the question lands.
3. Everything else, including search results, forum answers, and memory of how the thing worked last time.

That third tier is not merely weaker. It is actively misleading on hard problems, because the questions with easy answers are the ones that get answered often, and the residue is confident folk knowledge about the cases nobody checked. I have lost a full day to this: the advice returned by every search pointed at my non-standard SDK and package configuration, which was working correctly in dozens of other repositories at the same time, while the actual cause was project identity collisions in build server memory.

Reading the source answers questions that no amount of experimenting will. When I wanted to know whether Except delegates membership to the collection it was handed, benchmarks could only ever show me timings. ExceptIterator constructing a fresh HashSet from its second argument, with no type check anywhere, is the answer itself. The same applies to the formatting rule that would not fire: TokenBasedFormattingRule.AdjustNewLinesAfterSemicolonToken contains both the sorting check and a comment explaining that the check is deliberate. Nothing in the documentation mentioned it, and nothing could have been inferred from the outside.

Documentation is worth most when it contradicts the hypothesis. Searching the official docs for evidence that NuGet cached anything against project GUIDs returned the opposite, and being wrong in a checkable way is what pushed the investigation somewhere better instead of confirming a comfortable theory. A source that only ever agrees is not being consulted.

Clean-Room Reproduction

Once an assumption is in question, reproduce it in a project that contains nothing else. A new solution, the smallest possible file, and none of the code that was failing.

This buys two things. It removes every variable that was not deliberately put back, which is what makes the result mean something. And it converts a bug report into something the maintainer can act on, which is the difference between an issue that gets a fix and one that gets closed.

The clean room for the formatting rule is two files of four using directives each, identical except that one pair is in alphabetical order. That is the entire reproduction. It fits in an issue body, it needs no project of mine, and it makes the behavior undeniable in a way that a description of my codebase never would.

The negative result is as useful as the positive one. When the minimal case does not reproduce, the difference between it and the failing system is the bug, and adding things back one at a time converges on it quickly. Testing restore at the project level and then at the solution level, rather than only at the level that was failing, is the same move at a smaller scale.

Two cautions. A reproduction that only runs on one machine is not clean, so state the SDK version, the tool versions, and the operating system alongside it. And some defects are invisible to a single-project clean room by their nature, because they live in state shared between things. When a minimal case has to contain two solutions before the failure appears, that requirement is not an obstacle to the reproduction. It is the finding.

Correlation IDs: Tracing Requests Across Service Boundaries

In a distributed system, a single user action may traverse five or more services. Without a shared identifier threading through all of them, correlating log entries across service boundaries becomes an exercise in archaeology.

A correlation ID is a unique string, typically a GUID, that accompanies a request through every service it touches:

public class CorrelationMiddleware
{
    private readonly RequestDelegate _next;

    public CorrelationMiddleware(RequestDelegate next) => _next = next;

    public async Task InvokeAsync(HttpContext context)
    {
        // Honor the caller's correlation ID, or generate a new one
        var correlationId = context.Request.Headers["X-Correlation-ID"]
            .FirstOrDefault() ?? Guid.NewGuid().ToString();

        // Make it available throughout the request pipeline
        context.Items["CorrelationId"] = correlationId;

        // Attach it to every log entry emitted during this request
        using (LogContext.PushProperty("CorrelationId", correlationId))
        {
            // Echo it back so the caller can reference it in their own logs
            context.Response.Headers.Append("X-Correlation-ID", correlationId);
            await _next(context);
        }
    }
}

When service A calls service B, it passes the correlation ID in the request header. Service B's middleware picks it up and attaches it to its own log context. The result is that a single query retrieves the complete request path across every service involved:

// Application Insights (KQL)
traces
| where timestamp > ago(30m)
| where customDimensions.CorrelationId == "abc-123-def-456"
| order by timestamp asc

Adding this costs almost nothing, a few lines of middleware per service. It pays for itself the first time an incident crosses a service boundary and the investigation collapses from grepping several log stores into one query.

Structured Logging: Named Properties, Not String Interpolation

The difference between logs that can be searched and logs that can't is structure. String interpolation produces human-readable text that's effectively opaque to query engines:

// Unstructured -- human-readable but unsearchable
_logger.LogInformation($"User {userId} processed {count} records in {elapsed}ms");

// Structured -- every field is independently queryable
_logger.LogInformation(
    "User {UserId} processed {RecordCount} records in {ElapsedMs}ms",
    userId, count, elapsed);

The structured version supports queries for all requests by a specific user, all requests that processed more than 1,000 records, or all requests slower than 500ms, without resorting to regex pattern matching against free text.

Context, Not Just Events

When an exception occurs, the stack trace shows where the failure happened. The surrounding context shows why:

try
{
    await ProcessDataAsync(data);
}
catch (Exception ex)
{
    _logger.LogError(ex,
        "Failed to process data. Context: {@Context}",
        new
        {
            DataId = data?.Id,
            DataType = data?.GetType().Name,
            RecordCount = data?.Records?.Count,
            Timestamp = DateTime.UtcNow
        });
    throw;
}

The @ prefix instructs Serilog (and compatible logging frameworks) to serialize the entire object rather than calling .ToString(). This captures the full state at the point of failure, which is often the difference between a quick diagnosis and hours of guesswork.

Activity-Based Distributed Tracing

.NET's System.Diagnostics.Activity API provides built-in distributed tracing that integrates directly with OpenTelemetry. Each activity represents a unit of work and automatically records its parent, forming a tree of spans that visualization tools like Jaeger or Azure Monitor can render as a timeline:

private static readonly ActivitySource _activitySource = new("DataPipeline");

public async Task<ProcessingResult> ProcessAsync(DataInput input)
{
    using var activity = _activitySource.StartActivity("ProcessData");
    activity?.SetTag("input.type", input.GetType().Name);
    activity?.SetTag("input.size", input.Data?.Length.ToString());

    var stages = new (string Name, Func<Task> Action)[]
    {
        ("Validate", () => ValidateInput(input)),
        ("Transform", () => TransformData(input)),
        ("Persist", () => PersistData(input))
    };

    foreach (var (name, action) in stages)
    {
        using var stageActivity = _activitySource.StartActivity($"Stage.{name}");
        try
        {
            _logger.LogDebug("Starting stage: {Stage}", name);
            await action();
            _logger.LogDebug("Completed stage: {Stage}", name);
        }
        catch (Exception ex)
        {
            stageActivity?.SetStatus(ActivityStatusCode.Error, ex.Message);
            _logger.LogError(ex, "Failed at stage: {Stage}", name);
            throw;
        }
    }

    return new ProcessingResult { Success = true };
}

Activities propagate automatically through async/await, HttpClient calls, and message queues. Each child activity records a reference to its parent, so the complete chain of operations is reconstructable from the trace data without any manual plumbing.

Timing Without Noise

For performance debugging, wrap suspect operations with Stopwatch and log the results structurally. Placing the logging in a finally block ensures that timing is captured even when the operation fails, which is often precisely when the timing matters most:

public class DiagnosticMiddleware
{
    public async Task InvokeAsync(HttpContext context)
    {
        using var scope = _logger.BeginScope(
            "Request {RequestId}", context.TraceIdentifier);

        var stopwatch = Stopwatch.StartNew();
        try
        {
            await _next(context);
        }
        finally
        {
            stopwatch.Stop();
            _logger.LogInformation(
                "Request {Method} {Path} completed in {Duration}ms with {StatusCode}",
                context.Request.Method,
                context.Request.Path,
                stopwatch.ElapsedMilliseconds,
                context.Response.StatusCode);
        }
    }
}

This middleware produces a structured log entry for every request, including its method, path, duration, and status code. Over time, these entries form a dataset that can be queried to identify performance trends, outliers, and regressions.

Debugging Concurrent Operations

Concurrency bugs require additional instrumentation because their behavior depends on timing and ordering that may not be captured by standard logging. Using SemaphoreSlim for controlled parallelism combined with per-item tracing shows what each concurrent operation is doing:

public async Task ProcessConcurrentlyAsync(IEnumerable<DataItem> items)
{
    var semaphore = new SemaphoreSlim(Environment.ProcessorCount);
    var tasks = items.Select(async item =>
    {
        await semaphore.WaitAsync();
        try
        {
            using var activity = _activitySource.StartActivity("ProcessItem");
            activity?.SetTag("item.id", item.Id);

            var sw = Stopwatch.StartNew();
            await ProcessItemAsync(item);

            _logger.LogDebug(
                "Processed item {ItemId} in {Duration}ms",
                item.Id, sw.ElapsedMilliseconds);
        }
        finally
        {
            semaphore.Release();
        }
    });

    await Task.WhenAll(tasks);
}

Bounding parallelism to Environment.ProcessorCount prevents thread pool starvation. The per-item Activity creates individual spans that correlate with any later service calls each item triggers, making it possible to trace a single item's journey through the entire system.

Querying the Instrumentation

Structured logging and distributed tracing are only valuable if the data they produce can be queried. Here are the query patterns I use most frequently.

Errors in the Last Hour

{
    "query": {
        "bool": {
            "must": [
                { "term": { "level": "ERROR" } },
                { "range": { "@timestamp": { "gte": "now-1h" } } }
            ]
        }
    }
}

A Single Request Across Services

traces
| where customDimensions.CorrelationId == "abc-123"
| project timestamp, message, ServiceName = tostring(customDimensions.ServiceName)
| order by timestamp asc

Slow Operations over Time

traces
| extend Stage = tostring(customDimensions.Stage),
         ElapsedMs = todouble(customDimensions.ElapsedMs)
| where ElapsedMs > 500
| summarize count() by bin(timestamp, 5m), Stage
| render timechart

The casts are not decoration. Application Insights stores every customDimensions value as a string, so comparing one to a number matches nothing: where customDimensions.ElapsedMs > 500 silently returns an empty result rather than the slow operations it looks like it asks for. Grouping is stricter still and fails loudly, with "Summarize group key is of a 'dynamic' type" and a demand for an explicit cast. Equality against a string literal is the one case that works untouched, which is why the correlation ID filters above need nothing.

These queries become second nature during incident response, and having them documented in a runbook saves valuable time when every minute matters.

The Debugging Toolkit at a Glance

If only two things from this post are worth adopting, make them correlation IDs and structured logging. They cost almost nothing to add, they require no changes to the application's business logic, and they make every future debugging session materially faster.

References

• System.Diagnostics.Activity
• OpenTelemetry .NET
• Serilog Structured Logging
• Application Insights
• git bisect