Merge pull request #227 from nblumhardt/sp-tr

Capture trace and span ids for Serilog 3.1

Author: nblumhardt

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<TState>(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>(TState state, Func<TState, Exception?, string>? formatter)

src/Serilog.Extensions.Logging/Serilog.Extensions.Logging.csproj

@@ -29,7 +29,7 @@
     <None Include="..\..\assets\serilog-extension-nuget.png" Pack="true" PackagePath="" Visible="false" />
     <None Include="..\..\README.md" Pack="true" PackagePath="\" Visible="false" />
     <PackageReference Include="Microsoft.SourceLink.GitHub" Version="1.1.1" PrivateAssets="All" />
-    <PackageReference Include="Serilog" Version="2.12.0" />
+    <PackageReference Include="Serilog" Version="3.1.0-*" />
     <!-- The version of this reference must match the major and minor components of the package version prefix. -->
     <PackageReference Include="Microsoft.Extensions.Logging" Version="7.0.0" />
     <PackageReference Include="Nullable" Version="1.3.1" PrivateAssets="All" />

test/Serilog.Extensions.Logging.Benchmarks/Serilog.Extensions.Logging.Benchmarks.csproj

@@ -12,7 +12,7 @@
   <ItemGroup>
     <PackageReference Include="Microsoft.NET.Test.Sdk" Version="17.5.0" />
     <PackageReference Include="xunit.runner.visualstudio" Version="2.4.5" PrivateAssets="All" />
-    <PackageReference Include="xunit" Version="2.4.2" />
+    <PackageReference Include="xunit" Version="2.5.1" />
     <PackageReference Include="BenchmarkDotNet" Version="0.13.5" />
   </ItemGroup>
 

test/Serilog.Extensions.Logging.Tests/Serilog.Extensions.Logging.Tests.csproj

@@ -4,6 +4,10 @@
     <TargetFrameworks>net7.0;net472</TargetFrameworks>
     <ImplicitUsings>enable</ImplicitUsings>
   </PropertyGroup>
+  
+  <PropertyGroup Condition=" '$(TargetFramework)' == 'net472' ">
+    <DefineConstants>$(DefineConstants);FORCE_W3C_ACTIVITY_ID</DefineConstants>
+  </PropertyGroup>
 
   <ItemGroup>
     <ProjectReference Include="..\..\src\Serilog.Extensions.Logging\Serilog.Extensions.Logging.csproj" />
@@ -12,7 +16,7 @@
   <ItemGroup>
     <PackageReference Include="Microsoft.NET.Test.Sdk" Version="17.5.0" />
     <PackageReference Include="xunit.runner.visualstudio" Version="2.4.5" PrivateAssets="all" />
-    <PackageReference Include="xunit" Version="2.4.2" />
+    <PackageReference Include="xunit" Version="2.5.1" />
     <PackageReference Include="Shouldly" Version="4.1.0" />
     <PackageReference Include="PublicApiGenerator" Version="11.0.0" />
   </ItemGroup>

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,11 +139,11 @@ public void LogsCorrectMessage()
 
         logger.Log<object>(LogLevel.Information, 0, null!, null!, null!);
         logger.Log(LogLevel.Information, 0, TestMessage, null!, null!);
-        logger.Log<object>(LogLevel.Information, 0, null!, null!, (_, __) => TestMessage);
+        logger.Log<object>(LogLevel.Information, 0, null!, null!, (_, _) => TestMessage);
 
         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);
@@ -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,38 @@ 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()
+    {
+#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<ActivityContext> _) => 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);
+    }
 }