From 54585676b0d1c5c6c1c50092da66d0bd3b8a8f13 Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Tue, 3 Oct 2023 14:48:57 +1000 Subject: [PATCH 1/3] Capture trace and span ids for Serilog 3.1 --- .../Extensions/Logging/SerilogLogger.cs | 7 +++- .../Serilog.Extensions.Logging.csproj | 2 +- .../SerilogLoggerTests.cs | 40 +++++++++++++++---- 3 files changed, 40 insertions(+), 9 deletions(-) diff --git a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs index edcef30..06efe62 100644 --- a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs +++ b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs @@ -8,6 +8,7 @@ using System.Reflection; using Serilog.Debugging; using System.Collections.Concurrent; +using System.Diagnostics; namespace Serilog.Extensions.Logging; @@ -156,8 +157,12 @@ LogEvent PrepareWrite(LogEventLevel level, EventId eventId, TState state if (eventId.Id != 0 || eventId.Name != null) properties.Add(CreateEventIdProperty(eventId)); + var (traceId, spanId) = Activity.Current is { } activity ? + (activity.TraceId, activity.SpanId) : + (default(ActivityTraceId), default(ActivitySpanId)); + var parsedTemplate = MessageTemplateParser.Parse(messageTemplate ?? ""); - return new LogEvent(DateTimeOffset.Now, level, exception, parsedTemplate, properties); + return new LogEvent(DateTimeOffset.Now, level, exception, parsedTemplate, properties, traceId, spanId); } static object? AsLoggableValue(TState state, Func? formatter) diff --git a/src/Serilog.Extensions.Logging/Serilog.Extensions.Logging.csproj b/src/Serilog.Extensions.Logging/Serilog.Extensions.Logging.csproj index 33d764b..7fb4e74 100644 --- a/src/Serilog.Extensions.Logging/Serilog.Extensions.Logging.csproj +++ b/src/Serilog.Extensions.Logging/Serilog.Extensions.Logging.csproj @@ -29,7 +29,7 @@ - + diff --git a/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs b/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs index 94da8bb..597127e 100644 --- a/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs +++ b/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs @@ -2,6 +2,7 @@ // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. using System.Collections; +using System.Diagnostics; using Serilog.Events; using Microsoft.Extensions.Logging; using Serilog.Debugging; @@ -138,7 +139,7 @@ public void LogsCorrectMessage() logger.Log(LogLevel.Information, 0, null!, null!, null!); logger.Log(LogLevel.Information, 0, TestMessage, null!, null!); - logger.Log(LogLevel.Information, 0, null!, null!, (_, __) => TestMessage); + logger.Log(LogLevel.Information, 0, null!, null!, (_, _) => TestMessage); Assert.Equal(3, sink.Writes.Count); @@ -308,7 +309,7 @@ public void WhenDisposeIsTrueProvidedLoggerIsDisposed() } [Fact] - public void BeginScopeDestructuresObjectsWhenDestructurerIsUsedInMessageTemplate() + public void BeginScopeDestructuresObjectsWhenCapturingOperatorIsUsedInMessageTemplate() { var (logger, sink) = SetUp(LogLevel.Trace); @@ -328,7 +329,7 @@ public void BeginScopeDestructuresObjectsWhenDestructurerIsUsedInMessageTemplate } [Fact] - public void BeginScopeDestructuresObjectsWhenDestructurerIsUsedInDictionary() + public void BeginScopeDestructuresObjectsWhenCapturingOperatorIsUsedInDictionary() { var (logger, sink) = SetUp(LogLevel.Trace); @@ -348,7 +349,7 @@ public void BeginScopeDestructuresObjectsWhenDestructurerIsUsedInDictionary() } [Fact] - public void BeginScopeDoesNotModifyKeyWhenDestructurerIsNotUsedInMessageTemplate() + public void BeginScopeDoesNotModifyKeyWhenCapturingOperatorIsNotUsedInMessageTemplate() { var (logger, sink) = SetUp(LogLevel.Trace); @@ -362,7 +363,7 @@ public void BeginScopeDoesNotModifyKeyWhenDestructurerIsNotUsedInMessageTemplate } [Fact] - public void BeginScopeDoesNotModifyKeyWhenDestructurerIsNotUsedInDictionary() + public void BeginScopeDoesNotModifyKeyWhenCapturingOperatorIsNotUsedInDictionary() { var (logger, sink) = SetUp(LogLevel.Trace); @@ -466,7 +467,10 @@ public void MismatchedMessageTemplateParameterCountIsHandled() { var (logger, sink) = SetUp(LogLevel.Trace); +#pragma warning disable CA2017 + // ReSharper disable once StructuredMessageTemplateProblem logger.LogInformation("Some test message with {Two} {Properties}", "OneProperty"); +#pragma warning restore CA2017 Assert.Empty(sink.Writes); } @@ -475,7 +479,7 @@ public void MismatchedMessageTemplateParameterCountIsHandled() public void ExceptionFromAuditSinkIsUnhandled() { var serilogLogger = new LoggerConfiguration() - .AuditTo.Sink(new MySink()) + .AuditTo.Sink(new UnimplementedSink()) .CreateLogger(); var provider = new SerilogLoggerProvider(serilogLogger); @@ -486,11 +490,33 @@ public void ExceptionFromAuditSinkIsUnhandled() Assert.Equal("Oops", ex.InnerException.Message); } - private class MySink : ILogEventSink + class UnimplementedSink : ILogEventSink { public void Emit(LogEvent logEvent) { throw new NotImplementedException("Oops"); } } + + [Fact] + public void TraceAndSpanIdsAreCaptured() + { + using var listener = new ActivityListener(); + listener.ShouldListenTo = _ => true; + listener.Sample = (ref ActivityCreationOptions _) => ActivitySamplingResult.AllData; + + ActivitySource.AddActivityListener(listener); + + var source = new ActivitySource("test.activity", "1.0.0"); + using var activity = source.StartActivity(); + Assert.NotNull(Activity.Current); + + var (logger, sink) = SetUp(LogLevel.Trace); + logger.LogInformation("Hello trace and span!"); + + var evt = Assert.Single(sink.Writes); + + Assert.Equal(Activity.Current.TraceId, evt.TraceId); + Assert.Equal(Activity.Current.SpanId, evt.SpanId); + } } From 6585051952c81b1df07af0c867d112ac0c4b53ba Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Tue, 3 Oct 2023 15:13:56 +1000 Subject: [PATCH 2/3] Force W3C activity ids on .NET 4.x --- .../Serilog.Extensions.Logging.Benchmarks.csproj | 2 +- .../Serilog.Extensions.Logging.Tests.csproj | 6 +++++- .../Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs | 7 ++++++- 3 files changed, 12 insertions(+), 3 deletions(-) diff --git a/test/Serilog.Extensions.Logging.Benchmarks/Serilog.Extensions.Logging.Benchmarks.csproj b/test/Serilog.Extensions.Logging.Benchmarks/Serilog.Extensions.Logging.Benchmarks.csproj index 24fdb78..dcaf754 100644 --- a/test/Serilog.Extensions.Logging.Benchmarks/Serilog.Extensions.Logging.Benchmarks.csproj +++ b/test/Serilog.Extensions.Logging.Benchmarks/Serilog.Extensions.Logging.Benchmarks.csproj @@ -12,7 +12,7 @@ - + diff --git a/test/Serilog.Extensions.Logging.Tests/Serilog.Extensions.Logging.Tests.csproj b/test/Serilog.Extensions.Logging.Tests/Serilog.Extensions.Logging.Tests.csproj index 94c27dc..88d54b2 100644 --- a/test/Serilog.Extensions.Logging.Tests/Serilog.Extensions.Logging.Tests.csproj +++ b/test/Serilog.Extensions.Logging.Tests/Serilog.Extensions.Logging.Tests.csproj @@ -4,6 +4,10 @@ net7.0;net472 enable + + + $(DefineConstants);FORCE_W3C_ACTIVITY_ID + @@ -12,7 +16,7 @@ - + diff --git a/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs b/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs index 597127e..179fd56 100644 --- a/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs +++ b/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs @@ -143,7 +143,7 @@ public void LogsCorrectMessage() Assert.Equal(3, sink.Writes.Count); - Assert.Equal(1, sink.Writes[0].Properties.Count); + Assert.Single(sink.Writes[0].Properties); Assert.Empty(sink.Writes[0].RenderMessage()); Assert.Equal(2, sink.Writes[1].Properties.Count); @@ -501,6 +501,11 @@ public void Emit(LogEvent logEvent) [Fact] public void TraceAndSpanIdsAreCaptured() { +#if FORCE_W3C_ACTIVITY_ID + Activity.DefaultIdFormat = ActivityIdFormat.W3C; + Activity.ForceDefaultIdFormat = true; +#endif + using var listener = new ActivityListener(); listener.ShouldListenTo = _ => true; listener.Sample = (ref ActivityCreationOptions _) => ActivitySamplingResult.AllData; From 3f1ccda34bfb0e833dde82d496f05e1233ab1a04 Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Tue, 3 Oct 2023 15:32:46 +1000 Subject: [PATCH 3/3] Unmatched apostrophe :-) --- .../Serilog.Extensions.Logging.Tests.csproj | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/Serilog.Extensions.Logging.Tests/Serilog.Extensions.Logging.Tests.csproj b/test/Serilog.Extensions.Logging.Tests/Serilog.Extensions.Logging.Tests.csproj index 88d54b2..d7df0d9 100644 --- a/test/Serilog.Extensions.Logging.Tests/Serilog.Extensions.Logging.Tests.csproj +++ b/test/Serilog.Extensions.Logging.Tests/Serilog.Extensions.Logging.Tests.csproj @@ -5,7 +5,7 @@ enable - + $(DefineConstants);FORCE_W3C_ACTIVITY_ID