From c89e100766b7b7ac79bd270cd644b56b2766ad82 Mon Sep 17 00:00:00 2001 From: Brent Date: Mon, 20 Jul 2026 18:15:14 -0400 Subject: [PATCH] Correlate .NET logger trace id with active span (th-de3805) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The .NET logger seeded traceId with a fabricated uuid (== correlationId) at construction. When a log is emitted inside an active distributed trace, stamp the real W3C trace/span id from System.Diagnostics.Activity.Current instead, so CloudWatch JSON logs correlate to the trace. Captured at emit time — the span is live at the log call, not necessarily when the logger was created. Falls back to the prior traceId (fabricated uuid, no spanId) when no W3C activity is in scope. - SmooLogger.Emit: override traceId + add spanId from Activity.Current (W3C only). - New ContextKey.SpanId ("spanId"). - Depends only on the BCL diagnostics API (Activity) — no @smooai/observability dependency (would be circular). Logger lines already flow through the ForwardTo ILogger the obs provider hooks, so an active obs provider turns them into OTLP log records with matching ids. Tests prove a log inside an active Activity carries the span's trace/span id, and that it falls back to the correlation uuid with no activity. Co-Authored-By: Claude Opus 4.8 Claude-Session: https://claude.ai/code/session_01S2bM94GAnVjYSSv1x7HKRB --- dotnet/src/SmooAI.Logger/LogContext.cs | 1 + dotnet/src/SmooAI.Logger/SmooLogger.cs | 12 ++++ .../TraceCorrelationTests.cs | 64 +++++++++++++++++++ 3 files changed, 77 insertions(+) create mode 100644 dotnet/tests/SmooAI.Logger.Tests/TraceCorrelationTests.cs diff --git a/dotnet/src/SmooAI.Logger/LogContext.cs b/dotnet/src/SmooAI.Logger/LogContext.cs index 69761a5e..69d31726 100644 --- a/dotnet/src/SmooAI.Logger/LogContext.cs +++ b/dotnet/src/SmooAI.Logger/LogContext.cs @@ -23,6 +23,7 @@ public static class ContextKey public const string RequestId = "requestId"; public const string Duration = "duration"; public const string TraceId = "traceId"; + public const string SpanId = "spanId"; public const string Error = "error"; public const string Namespace = "namespace"; public const string Service = "service"; diff --git a/dotnet/src/SmooAI.Logger/SmooLogger.cs b/dotnet/src/SmooAI.Logger/SmooLogger.cs index 7431d92a..052cef67 100644 --- a/dotnet/src/SmooAI.Logger/SmooLogger.cs +++ b/dotnet/src/SmooAI.Logger/SmooLogger.cs @@ -428,6 +428,18 @@ private void Emit(Level level, string message, object? data, Exception? error) } } + // Correlate with the active distributed trace when one is in scope: stamp the + // real W3C trace/span id from Activity.Current instead of the fabricated uuid + // seeded at construction. Falls back to the prior traceId (no spanId) when no + // W3C activity is active. This is captured at emit time — the span is live at + // the log call, not necessarily when the logger was created. + var activity = System.Diagnostics.Activity.Current; + if (activity is not null && activity.IdFormat == System.Diagnostics.ActivityIdFormat.W3C) + { + entry[ContextKey.TraceId] = activity.TraceId.ToHexString(); + entry[ContextKey.SpanId] = activity.SpanId.ToHexString(); + } + entry[ContextKey.Level] = (int)level; entry[ContextKey.LogLevel] = level.ToWireString(); entry[ContextKey.Time] = DateTimeOffset.UtcNow.ToString("O"); diff --git a/dotnet/tests/SmooAI.Logger.Tests/TraceCorrelationTests.cs b/dotnet/tests/SmooAI.Logger.Tests/TraceCorrelationTests.cs new file mode 100644 index 00000000..601ad81f --- /dev/null +++ b/dotnet/tests/SmooAI.Logger.Tests/TraceCorrelationTests.cs @@ -0,0 +1,64 @@ +using System.Diagnostics; +using System.Text.Json; +using SmooAI.Logger; + +namespace SmooAI.Logger.Tests; + +/// +/// Verifies the emit-time trace correlation (th-de3805): a log emitted inside an +/// active W3C carries that span's real trace/span id, and +/// falls back to the fabricated correlation uuid when no activity is in scope. +/// +public class TraceCorrelationTests +{ + private static (SmooLogger Logger, StringWriter Out) Build() + { + var writer = new StringWriter(); + return (new SmooLogger(new SmooLoggerOptions { Output = writer, PrettyPrint = false }), writer); + } + + private static JsonElement ParseSingle(string captured) + { + var line = captured.Split('\n', StringSplitOptions.RemoveEmptyEntries)[0]; + return JsonDocument.Parse(line).RootElement; + } + + [Fact] + public void Log_Within_Active_Activity_Carries_Real_TraceAndSpanId() + { + // ActivitySource only starts activities when a listener samples them. + using var source = new ActivitySource("smooai.logger.tests"); + using var listener = new ActivityListener + { + ShouldListenTo = s => s.Name == "smooai.logger.tests", + Sample = (ref ActivityCreationOptions _) => ActivitySamplingResult.AllData, + }; + ActivitySource.AddActivityListener(listener); + + var (logger, writer) = Build(); + using var activity = source.StartActivity("op"); + Assert.NotNull(activity); + Assert.Equal(ActivityIdFormat.W3C, activity!.IdFormat); + + logger.LogInfo("inside span"); + var entry = ParseSingle(writer.ToString()); + + Assert.Equal(activity.TraceId.ToHexString(), entry.GetProperty("traceId").GetString()); + Assert.Equal(activity.SpanId.ToHexString(), entry.GetProperty("spanId").GetString()); + } + + [Fact] + public void Log_Without_Activity_Falls_Back_To_Correlation_Uuid() + { + // No listener registered here, and any ambient activity cleared. + Activity.Current = null; + + var (logger, writer) = Build(); + logger.LogInfo("no span"); + var entry = ParseSingle(writer.ToString()); + + // Prior behavior: traceId == the fabricated correlation id, no spanId emitted. + Assert.Equal(entry.GetProperty("correlationId").GetString(), entry.GetProperty("traceId").GetString()); + Assert.False(entry.TryGetProperty("spanId", out _)); + } +}