Module 6 · 6. Errors, Resources, Diagnostics, and Reliability · Lesson 18 of 24
Structured Logging, Metrics, Traces, and Actionable Diagnostics
Make a failure answerable
“Checkout failed” is not enough to investigate. You need to distinguish a rejected request from a dependency outage, estimate how many attempts are affected, and connect one event to the work that produced it. This lesson instruments four synthetic checkout cases with real .NET logging, metric, and activity APIs, then checks the evidence without sending telemetry anywhere.
- Log question: What happened in this particular attempt, and what approved context helps identify it?
- Metric question: How many attempts had each outcome in the same observation window? What does the duration distribution look like?
- Trace question: Which operation and child operation belong to the same attempt, and where did the failing work occur?
Think of a delivery depot: an incident note describes one parcel, a dashboard counts deliveries, and a route record connects its stops. The analogy only separates questions. It does not mean every event is recorded or that collecting all details is safe or affordable.
Choose a small event contract
ILogger message templates pass named values to the logging pipeline; string interpolation pre-renders them into text. A provider decides how events and supported scopes are recorded. Keep a stable event template and inspect provider behavior rather than assuming a console message proves queryable storage. Microsoft: logging.
For our experiment, each attempted checkout emits one completion event. It has an Outcome field, a synthetic RequestKey scope, and the current trace ID captured by our test provider. Real identifiers require a purpose, access policy, retention policy, and suitable redaction; “put it in logs instead” is not automatic permission to collect it. Do not record credentials, payment details, or raw request/response bodies here.
Counters accumulate increments. Histograms record measurements for a distribution. Tags split measurements by dimensions; large combinations can create substantial collector storage and cost. Use bounded outcome values here rather than per-request IDs. Microsoft: metric instruments and dimensions.
Run one complete in-process experiment
Place the following two files in a CheckoutDiagnostics folder and run dotnet run --project CheckoutDiagnostics.csproj -c Release with a .NET 10 SDK and the ASP.NET Core shared framework. The framework reference supplies ILogger without a NuGet package. This remains a console application; it does not start a web server. No payment, inventory request, exporter, database, or file write occurs.
Read CheckoutTelemetry first, then the capture adapters and Checks. The capture classes intentionally keep events in memory for four sequential calls. They are teaching instruments, not production providers: they are unbounded and not thread-safe. The scenario strings come only from the four-item hardcoded array; arbitrary names currently fall through as success. Unexpected uncaught exceptions do not have a general severity/translation policy here. Do not use this fixture as a real checkout handler or a general instrumentation wrapper.
<Project Sdk="Microsoft.NET.Sdk">
<PropertyGroup>
<OutputType>Exe</OutputType>
<TargetFramework>net10.0</TargetFramework>
<ImplicitUsings>enable</ImplicitUsings>
<Nullable>enable</Nullable>
<TreatWarningsAsErrors>true</TreatWarningsAsErrors>
</PropertyGroup>
<ItemGroup>
<FrameworkReference Include="Microsoft.AspNetCore.App" />
</ItemGroup>
</Project>using System.Diagnostics;
using System.Diagnostics.Metrics;
using Microsoft.Extensions.Logging;
using var capture = new DiagnosticCapture();
using var provider = new CapturingLoggerProvider();
using var factory = LoggerFactory.Create(builder => builder.AddProvider(provider));
using var telemetry = new CheckoutTelemetry(factory.CreateLogger("Checkout"));
string[] scenarios = ["success", "validation", "timeout", "malformed"];
for (int i = 0; i < scenarios.Length; i++)
telemetry.Run(scenarios[i], $"demo-{i + 1:00}");
foreach (CapturedLog log in provider.Logs)
Console.WriteLine($"log: {log.Fields["RequestKey"]} {log.Fields["Outcome"]} {log.Level}");
Console.WriteLine("attempts: " + capture.Counts.Values.Sum());
Console.WriteLine("outcome series: " + capture.Counts.Count);
Console.WriteLine("latency measurements: " + capture.Durations.Count);
Console.WriteLine("spans: " + capture.Spans.Count);
Console.WriteLine("error spans: " + capture.Spans.Count(x => x.Status == ActivityStatusCode.Error));
if (args.Contains("--self-test")) Checks.Run(provider, capture);
public sealed class CheckoutTelemetry : IDisposable
{
public const string Name = "Lesson.Checkout";
private readonly ActivitySource source = new(Name);
private readonly Meter meter = new(Name);
private readonly Counter<long> attempts;
private readonly Histogram<double> duration;
private readonly ILogger logger;
public CheckoutTelemetry(ILogger logger)
{
this.logger = logger;
attempts = meter.CreateCounter<long>("checkout.attempts", "{attempt}");
duration = meter.CreateHistogram<double>("checkout.duration", "ms");
}
public void Run(string scenario, string requestKey)
{
using Activity? checkout = source.StartActivity("checkout");
using IDisposable? scope = logger.BeginScope(new Dictionary<string, object?>
{
["RequestKey"] = requestKey // Synthetic fixture key, not real customer data.
});
long started = Stopwatch.GetTimestamp();
string outcome = "unexpected_error";
Exception? failure = null;
try
{
if (scenario == "validation")
{
outcome = "rejected";
return;
}
LookupInventory(scenario);
outcome = "success";
}
catch (TimeoutException ex)
{
outcome = "dependency_timeout";
failure = ex;
checkout?.SetStatus(ActivityStatusCode.Error, "dependency timeout");
}
catch (InvalidDataException ex)
{
outcome = "invalid_dependency_data";
failure = ex;
checkout?.SetStatus(ActivityStatusCode.Error, "invalid dependency data");
}
finally
{
checkout?.SetTag("checkout.outcome", outcome);
// The only metric dimension is a bounded outcome name, never RequestKey.
var tag = new KeyValuePair<string, object?>("outcome", outcome);
attempts.Add(1, tag);
duration.Record(Stopwatch.GetElapsedTime(started).TotalMilliseconds, tag);
logger.Log(failure is null ? LogLevel.Information : LogLevel.Error,
new EventId(1001, "CheckoutFinished"), failure,
"Checkout finished with {Outcome}", outcome);
}
}
private void LookupInventory(string scenario)
{
using Activity? inventory = source.StartActivity("inventory.lookup");
if (scenario == "timeout")
{
inventory?.SetStatus(ActivityStatusCode.Error, "dependency timeout");
throw new TimeoutException("Synthetic dependency timeout.");
}
if (scenario == "malformed")
{
inventory?.SetStatus(ActivityStatusCode.Error, "invalid dependency data");
throw new InvalidDataException("Synthetic dependency payload failed validation.");
}
}
public void Dispose()
{
source.Dispose();
meter.Dispose();
}
}
// In-process listeners make the emitted instruments visible without an exporter/server.
public sealed class DiagnosticCapture : IDisposable
{
private readonly MeterListener meterListener = new();
private readonly ActivityListener activityListener;
public Dictionary<string, long> Counts { get; } = new(StringComparer.Ordinal);
public List<double> Durations { get; } = [];
public List<CapturedSpan> Spans { get; } = [];
public List<string> MetricTagKeys { get; } = [];
public DiagnosticCapture()
{
meterListener.InstrumentPublished = (instrument, listener) =>
{
if (instrument.Meter.Name == CheckoutTelemetry.Name)
listener.EnableMeasurementEvents(instrument);
};
meterListener.SetMeasurementEventCallback<long>((instrument, value, tags, state) =>
{
string outcome = "";
foreach (var tag in tags)
{
MetricTagKeys.Add(tag.Key);
if (tag.Key == "outcome") outcome = (string)tag.Value!;
}
Counts[outcome] = Counts.GetValueOrDefault(outcome) + value;
});
meterListener.SetMeasurementEventCallback<double>((instrument, value, tags, state) =>
{
foreach (var tag in tags) MetricTagKeys.Add(tag.Key);
Durations.Add(value);
});
meterListener.Start();
activityListener = new ActivityListener
{
ShouldListenTo = source => source.Name == CheckoutTelemetry.Name,
Sample = (ref ActivityCreationOptions<ActivityContext> options) => ActivitySamplingResult.AllDataAndRecorded,
ActivityStopped = activity => Spans.Add(new CapturedSpan(activity.OperationName,
activity.TraceId.ToString(), activity.SpanId.ToString(), activity.ParentSpanId.ToString(),
activity.Status))
};
ActivitySource.AddActivityListener(activityListener);
}
public void Dispose()
{
activityListener.Dispose();
meterListener.Dispose();
}
}
public sealed record CapturedSpan(string Name, string TraceId, string SpanId,
string ParentSpanId, ActivityStatusCode Status);
public sealed record CapturedLog(LogLevel Level, string Message,
Dictionary<string, object?> Fields, string? ExceptionType, string? TraceId);
// Minimal single-threaded test provider: preserve template fields and enabled scopes.
public sealed class CapturingLoggerProvider : ILoggerProvider, ISupportExternalScope
{
private IExternalScopeProvider scopes = new LoggerExternalScopeProvider();
public List<CapturedLog> Logs { get; } = [];
public ILogger CreateLogger(string categoryName) => new CapturingLogger(this);
public void SetScopeProvider(IExternalScopeProvider scopeProvider) => scopes = scopeProvider;
public void Dispose() { }
private sealed class CapturingLogger(CapturingLoggerProvider owner) : ILogger
{
public IDisposable? BeginScope<TState>(TState state) where TState : notnull => owner.scopes.Push(state);
public bool IsEnabled(LogLevel level) => level != LogLevel.None;
public void Log<TState>(LogLevel level, EventId eventId, TState state,
Exception? exception, Func<TState, Exception?, string> formatter)
{
var fields = new Dictionary<string, object?>();
if (state is IEnumerable<KeyValuePair<string, object?>> properties)
foreach (var property in properties) fields[property.Key] = property.Value;
owner.scopes.ForEachScope((scope, target) =>
{
if (scope is IEnumerable<KeyValuePair<string, object?>> values)
foreach (var value in values) target[value.Key] = value.Value;
}, fields);
owner.Logs.Add(new CapturedLog(level, formatter(state, exception), fields,
exception?.GetType().Name, Activity.Current?.TraceId.ToString()));
}
}
}
public static class Checks
{
public static void Run(CapturingLoggerProvider provider, DiagnosticCapture capture)
{
string[] outcomes = ["success", "rejected", "dependency_timeout", "invalid_dependency_data"];
Assert(provider.Logs.Count == 4, "one completion event per attempt");
Assert(capture.Counts.Count == 4 && outcomes.All(x => capture.Counts[x] == 1), "bounded counts");
Assert(capture.MetricTagKeys.All(x => x == "outcome"), "no identifier metric tags");
Assert(capture.Durations.Count == 4 && capture.Durations.All(x => double.IsFinite(x) && x >= 0), "finite latency observations");
for (int i = 0; i < 4; i++)
{
CapturedLog log = provider.Logs[i];
Assert((string)log.Fields["Outcome"]! == outcomes[i], "named outcome property");
Assert((string)log.Fields["{OriginalFormat}"]! == "Checkout finished with {Outcome}", "stable template retained");
Assert((string)log.Fields["RequestKey"]! == $"demo-{i + 1:00}", "scope retained");
Assert(capture.Spans.Any(x => x.Name == "checkout" && x.TraceId == log.TraceId), "log joins checkout trace");
}
Assert(provider.Logs[2].ExceptionType == nameof(TimeoutException), "timeout exception recorded");
Assert(provider.Logs[3].ExceptionType == nameof(InvalidDataException), "malformed exception recorded");
var roots = capture.Spans.Where(x => x.Name == "checkout").ToArray();
var children = capture.Spans.Where(x => x.Name == "inventory.lookup").ToArray();
Assert(roots.Length == 4 && children.Length == 3, "validation skips dependency");
Assert(children.All(child => roots.Any(root => root.TraceId == child.TraceId
&& root.SpanId == child.ParentSpanId)), "parent-child identities correlate");
Assert(capture.Spans.Count(x => x.Status == ActivityStatusCode.Error) == 4, "two failing roots and children");
using var unobserved = new ActivitySource("Lesson.NoListener");
using Activity? absent = unobserved.StartActivity("unobserved");
Assert(absent is null, "no matching listener permits a null activity");
Console.WriteLine("PASS: CheckoutDiagnostics semantic checks");
}
private static void Assert(bool condition, string label)
{
if (!condition) throw new Exception("Assertion failed: " + label);
}
}Expected output
log: demo-01 success Information log: demo-02 rejected Information log: demo-03 dependency_timeout Error log: demo-04 invalid_dependency_data Error attempts: 4 outcome series: 4 latency measurements: 4 spans: 7 error spans: 4
Explain every count before trusting a chart
- Four log events: each hardcoded attempt records exactly one completion. The request keys are fake values demo-01 through demo-04
- Four attempts and four outcome series: each branch contributes one increment to its own outcome value. There is no RequestKey dimension
- Four latency measurements: every attempt records one value, including the early validation return because its finally block still runs. Actual values are deliberately not printed as fixed expectations
- Seven spans: four checkout roots plus three inventory.lookup children. The validation branch returns before a dependency operation begins
- Four error spans: timeout and malformed data each mark both their child operation and root as Error. This is two failed checkout attempts, not four. Success and ordinary validation rejection are left Unset by this chosen policy
Stopwatch measures elapsed time. Microsoft: Stopwatch. The timed region includes fixture work and some instrumentation overhead, not a real dependency round trip. A fast local result is not evidence that a production checkout is fast. The checks require only four finite, nonnegative measurements, not exact timings or a performance threshold.
Why the listeners and null checks matter
MeterListener can collect instrument measurements inside the process. Microsoft: metric collection. DiagnosticCapture enables only instruments from Lesson.Checkout and registers callbacks for our long counter and double histogram. It intentionally summarizes the four measured cases rather than implementing a monitoring backend.
ActivitySource creates activity spans when interested listeners enable them; StartActivity can return null. Disposing an activity ends it. Nested activities describe meaningful work; creating a span for every method would make traces noisy. Microsoft: trace instrumentation. The null-conditional calls let the business branch run even when no span exists. The final check uses a different source name with no matching listener and expects null.
Trace IDs group related work; span and parent-span IDs establish its tree. Across processes, trace context must be propagated, and collection/sampling affect what can later be viewed. Microsoft: tracing concepts. Our code proves only local parent-child links. It does not test HTTP propagation, exporter delivery, backend indexing, or retention. A production integration needs tests for those boundaries, and a trace identifier never replaces authentication or makes an operation idempotent.
Turn the output into assertions
Run dotnet run --project CheckoutDiagnostics.csproj -c Release -- --self-test. After the same nine demo lines, expect PASS: CheckoutDiagnostics semantic checks. The checks inspect the named Outcome and original template, enabled RequestKey scope, recorded exception types, one counter contribution per outcome, absence of identifier metric tags, finite duration values, and exact parent-child ID relationships. Random trace IDs are compared relationally rather than hardcoded.
This is stronger than asserting only a rendered message contains “timeout”: a pre-rendered string could look correct while losing its named field. It is also narrower than claiming a production dashboard works: the in-process capture does not exercise any external telemetry system.
Solved application: one success and three non-success paths
Problem. Plan diagnostics for a checkout that can succeed, reject input, time out talking to inventory, or receive unusable inventory data. Decide what an on-call engineer should inspect.
- Success: completion event with success; one attempt increment; one duration; root plus inventory child. Use it as a baseline to compare the same release and route
- Validation rejection: completion event with rejected; one attempt increment and duration; root only. A sudden increase suggests examining validation changes or callers, rather than assuming inventory is down
- Dependency timeout: error completion event with dependency_timeout and approved cause information; root and child marked Error. Inspect the inventory-related child and compare timeout counts in the same window
- Invalid dependency data: error completion event with invalid_dependency_data; root and child marked Error. Inspect the producer/consumer contract and recent changes without dumping a private payload into logs
Those are the four branches actually modeled. Cancellation, retries, partial side effects, and duplicate payment protection would require extra operation policy and tests; this fixture does not invent their behavior.
Solved calculation: avoid a misleading error percentage
Problem. In a made-up five-minute observation window, checkout has 1,000 attempt increments: 940 success, 40 rejected, 15 dependency_timeout, and 5 invalid_dependency_data. What percentages should be reported?
Solution. Infrastructure/dependency failures are (15 + 5) / 1,000 = 2%. Non-success outcomes are (40 + 15 + 5) / 1,000 = 6%. Both are valid answers to different questions. Label the numerator and denominator explicitly, use the same observation window and route population, and do not count child error spans as extra checkout attempts. These numbers are an exercise dataset, not output measured by the program.
Next ask whether the duration distribution changed for success or timeout separately. An overall average can mix faster rejections with slower dependency work and hide the group you need to investigate. Define an alert from the service’s actual user-impact objective and traffic volume; this lesson does not prescribe a universal percentage threshold.
Solved design review: fix cardinality before adding a dashboard
Problem. A proposal adds RequestKey to every checkout metric. There can be 200,000 distinct request keys in the window. Is that a useful way to drill into one failure?
Solution. Keep the bounded outcome dimension for aggregation. Use an approved diagnostic event to locate one attempt and its trace, as the fixture’s log-to-root check does. Adding a request key turns an aggregate into per-request dimensions and changes its storage shape. With four outcomes and three deployment regions, the theoretical combination count is at most 12 before additional dimensions; adding 200,000 possible keys makes the theoretical product 2,400,000. Only observed combinations appear, so this is an upper-bound design warning, not a claim that all combinations exist.
Solved reliability decision: an optional dependency
Problem. Recommendations are unavailable, but the documented checkout contract permits completion without them. Should checkout retry forever or fabricate recommendations?
Solution. Use the explicitly allowed no-recommendations fallback, record a bounded degraded outcome for that optional feature, and continue the critical checkout operation. Do not relabel the recommendation result as verified data. If recommendations are required by a different product contract, this fallback is not authorized by the scenario. The four-case program does not implement this extension; it is a design exercise.
Interview checks with answers
- Why a stable template? The test provider can retain Outcome and the original template separately; formatting the value into a string first removes that named-value input
- Why four error spans but only two dependency-failed attempts? Each failing attempt has both a failing root and child; the counter records attempts once
- Why might a trace be missing? Check source/listener configuration, sampling, propagation and export. Do not infer that the business operation never happened
- What makes diagnostics actionable? A defined question, bounded schema, truthful outcome, usable correlation and a tested route from emitted evidence to the investigation tool