Collect and propagate current trace and span ids through LogEvent (#…

…1955)

Serilog.sln

@@ -8,7 +8,6 @@ Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "assets", "assets", "{E9D1B5
 		appveyor.yml = appveyor.yml
 		Build.ps1 = Build.ps1
 		build.sh = build.sh
-		CHANGES.md = CHANGES.md
 		Directory.Build.props = Directory.Build.props
 		Directory.Build.targets = Directory.Build.targets
 		global.json = global.json

Serilog.sln.DotSettings

@@ -218,6 +218,7 @@
 	<s:Boolean x:Key="/Default/UserDictionary/Words/=destructure/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/UserDictionary/Words/=Enricher/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/UserDictionary/Words/=Enrichers/@EntryIndexedValue">True</s:Boolean>
+	<s:Boolean x:Key="/Default/UserDictionary/Words/=formattable/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/UserDictionary/Words/=Obsoletion/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/UserDictionary/Words/=stringified/@EntryIndexedValue">True</s:Boolean></wpf:ResourceDictionary>
 

src/Serilog/Core/Logger.cs

@@ -12,6 +12,8 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
+using System.Diagnostics;
+
 #pragma warning disable Serilog004 // Constant MessageTemplate verifier
 
 namespace Serilog.Core;
@@ -79,7 +81,7 @@ public sealed class Logger : ILogger, ILogEventSink, IDisposable
     /// <returns>A logger that will enrich log events as specified.</returns>
     public ILogger ForContext(ILogEventEnricher enricher)
     {
-        if (enricher == null)
+        if (enricher == null!)
             return this; // No context here, so little point writing to SelfLog.
 
         return new Logger(
@@ -102,7 +104,7 @@ public ILogger ForContext(ILogEventEnricher enricher)
     /// <returns>A logger that will enrich log events as specified.</returns>
     public ILogger ForContext(IEnumerable<ILogEventEnricher> enrichers)
     {
-        if (enrichers == null)
+        if (enrichers == null!)
             return this; // No context here, so little point writing to SelfLog.
 
         return ForContext(new SafeAggregateEnricher(enrichers));
@@ -164,7 +166,7 @@ public ILogger ForContext(string propertyName, object? value, bool destructureOb
     /// <returns>A logger that will enrich log events as specified.</returns>
     public ILogger ForContext(Type source)
     {
-        if (source == null)
+        if (source == null!)
             return this; // Little point in writing to SelfLog here because we don't have any contextual information
 
         return ForContext(Constants.SourceContextPropertyName, source.FullName);
@@ -352,7 +354,7 @@ public void Write<T>(LogEventLevel level, Exception? exception, string messageTe
     public void Write(LogEventLevel level, Exception? exception, string messageTemplate, params object?[]? propertyValues)
     {
         if (!IsEnabled(level)) return;
-        if (messageTemplate == null) return;
+        if (messageTemplate == null!) return;
 
         // Catch a common pitfall when a single non-object array is cast to object[]
         if (propertyValues != null &&
@@ -362,7 +364,8 @@ public void Write(LogEventLevel level, Exception? exception, string messageTempl
         var logTimestamp = DateTimeOffset.Now;
         _messageTemplateProcessor.Process(messageTemplate, propertyValues, out var parsedTemplate, out var boundProperties);
 
-        var logEvent = new LogEvent(logTimestamp, level, exception, parsedTemplate, boundProperties);
+        var currentActivity = Activity.Current;
+        var logEvent = new LogEvent(logTimestamp, level, exception, parsedTemplate, boundProperties, currentActivity?.TraceId ?? default, currentActivity?.SpanId ?? default);
         Dispatch(logEvent);
     }
 
@@ -372,7 +375,7 @@ public void Write(LogEventLevel level, Exception? exception, string messageTempl
     /// <param name="logEvent">The event to write.</param>
     public void Write(LogEvent logEvent)
     {
-        if (logEvent == null) return;
+        if (logEvent == null!) return;
         if (!IsEnabled(logEvent.Level)) return;
         Dispatch(logEvent);
     }

src/Serilog/Events/LogEvent.cs

@@ -12,6 +12,9 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
+using System.Diagnostics;
+// ReSharper disable IntroduceOptionalParameters.Global
+
 namespace Serilog.Events;
 
 /// <summary>
@@ -20,12 +23,23 @@ namespace Serilog.Events;
 public class LogEvent
 {
     readonly Dictionary<string, LogEventPropertyValue> _properties;
-
-    LogEvent(DateTimeOffset timestamp, LogEventLevel level, Exception? exception, MessageTemplate messageTemplate, Dictionary<string, LogEventPropertyValue> properties)
+    ActivityTraceId _traceId;
+    ActivitySpanId _spanId;
+
+    LogEvent(
+        DateTimeOffset timestamp,
+        LogEventLevel level,
+        Exception? exception,
+        MessageTemplate messageTemplate,
+        Dictionary<string, LogEventPropertyValue> properties,
+        ActivityTraceId traceId,
+        ActivitySpanId spanId)
     {
         Timestamp = timestamp;
         Level = level;
         Exception = exception;
+        _traceId = traceId;
+        _spanId = spanId;
         MessageTemplate = Guard.AgainstNull(messageTemplate);
         _properties = Guard.AgainstNull(properties);
     }
@@ -41,12 +55,8 @@ public class LogEvent
     /// <exception cref="ArgumentNullException">When <paramref name="messageTemplate"/> is <code>null</code></exception>
     /// <exception cref="ArgumentNullException">When <paramref name="properties"/> is <code>null</code></exception>
     public LogEvent(DateTimeOffset timestamp, LogEventLevel level, Exception? exception, MessageTemplate messageTemplate, IEnumerable<LogEventProperty> properties)
-        : this(timestamp, level, exception, messageTemplate, new Dictionary<string, LogEventPropertyValue>())
+        : this(timestamp, level, exception, messageTemplate, properties, default, default)
     {
-        Guard.AgainstNull(properties);
-
-        foreach (var property in properties)
-            AddOrUpdateProperty(property);
     }
 
     /// <summary>
@@ -57,10 +67,22 @@ public LogEvent(DateTimeOffset timestamp, LogEventLevel level, Exception? except
     /// <param name="exception">An exception associated with the event, or null.</param>
     /// <param name="messageTemplate">The message template describing the event.</param>
     /// <param name="properties">Properties associated with the event, including those presented in <paramref name="messageTemplate"/>.</param>
+    /// <param name="traceId">The id of the trace that was active when the event was created, if any.</param>
+    /// <param name="spanId">The id of the span that was active when the event was created, if any.</param>
     /// <exception cref="ArgumentNullException">When <paramref name="messageTemplate"/> is <code>null</code></exception>
     /// <exception cref="ArgumentNullException">When <paramref name="properties"/> is <code>null</code></exception>
-    internal LogEvent(DateTimeOffset timestamp, LogEventLevel level, Exception? exception, MessageTemplate messageTemplate, EventProperty[] properties)
-        : this(timestamp, level, exception, messageTemplate, new Dictionary<string, LogEventPropertyValue>(Guard.AgainstNull(properties).Length))
+    [CLSCompliant(false)]
+    public LogEvent(DateTimeOffset timestamp, LogEventLevel level, Exception? exception, MessageTemplate messageTemplate, IEnumerable<LogEventProperty> properties, ActivityTraceId traceId, ActivitySpanId spanId)
+        : this(timestamp, level, exception, messageTemplate, new Dictionary<string, LogEventPropertyValue>(), traceId, spanId)
+    {
+        Guard.AgainstNull(properties);
+
+        foreach (var property in properties)
+            AddOrUpdateProperty(property);
+    }
+
+    internal LogEvent(DateTimeOffset timestamp, LogEventLevel level, Exception? exception, MessageTemplate messageTemplate, EventProperty[] properties, ActivityTraceId traceId, ActivitySpanId spanId)
+        : this(timestamp, level, exception, messageTemplate, new Dictionary<string, LogEventPropertyValue>(Guard.AgainstNull(properties).Length), traceId, spanId)
     {
         for (var i = 0; i < properties.Length; ++i)
             _properties[properties[i].Name] = properties[i].Value;
@@ -76,6 +98,18 @@ internal LogEvent(DateTimeOffset timestamp, LogEventLevel level, Exception? exce
     /// </summary>
     public LogEventLevel Level { get; }
 
+    /// <summary>
+    /// The id of the trace that was active when the event was created, if any.
+    /// </summary>
+    [CLSCompliant(false)]
+    public ActivityTraceId? TraceId => _traceId == default ? null : _traceId;
+
+    /// <summary>
+    /// The id of the span that was active when the event was created, if any.
+    /// </summary>
+    [CLSCompliant(false)]
+    public ActivitySpanId? SpanId => _spanId == default ? null : _spanId;
+
     /// <summary>
     /// The message template describing the event.
     /// </summary>
@@ -201,6 +235,8 @@ internal LogEvent Copy()
             Level,
             Exception,
             MessageTemplate,
-            properties);
+            properties,
+            TraceId ?? default,
+            SpanId ?? default);
     }
 }

src/Serilog/Formatting/Display/MessageTemplateTextFormatter.cs

@@ -24,6 +24,7 @@ namespace Serilog.Formatting.Display;
 /// to them. Second, tokens without matching properties are skipped
 /// rather than being written as raw text.
 /// </summary>
+/// <remarks>New code should prefer <c>ExpressionTemplate</c> from <c>Serilog.Expressions</c>.</remarks>
 public class MessageTemplateTextFormatter : ITextFormatter
 {
     readonly IFormatProvider? _formatProvider;
@@ -70,6 +71,14 @@ public void Format(LogEvent logEvent, TextWriter output)
                 var moniker = LevelOutputFormat.GetLevelMoniker(logEvent.Level, pt.Format);
                 Padding.Apply(output, moniker, pt.Alignment);
             }
+            else if (pt.PropertyName == OutputProperties.TraceIdPropertyName)
+            {
+                Padding.Apply(output, logEvent.TraceId?.ToString() ?? "", pt.Alignment);
+            }
+            else if (pt.PropertyName == OutputProperties.SpanIdPropertyName)
+            {
+                Padding.Apply(output, logEvent.SpanId?.ToString() ?? "", pt.Alignment);
+            }
             else if (pt.PropertyName == OutputProperties.NewLinePropertyName)
             {
                 Padding.Apply(output, Environment.NewLine, pt.Alignment);

src/Serilog/Formatting/Display/OutputProperties.cs

@@ -35,6 +35,16 @@ public static class OutputProperties
     /// </summary>
     public const string LevelPropertyName = "Level";
 
+    /// <summary>
+    /// The id of the trace that was active at the log event's time of creation, if any.
+    /// </summary>
+    public const string TraceIdPropertyName = "TraceId";
+
+    /// <summary>
+    /// The id of the span that was active at the log event's time of creation, if any.
+    /// </summary>
+    public const string SpanIdPropertyName = "SpanId";
+
     /// <summary>
     /// A new line.
     /// </summary>

src/Serilog/Formatting/Json/JsonFormatter.cs

@@ -71,6 +71,18 @@ public void Format(LogEvent logEvent, TextWriter output)
             JsonValueFormatter.WriteQuotedJsonString(message, output);
         }
 
+        if (logEvent.TraceId != null)
+        {
+            output.Write(",\"TraceId\":");
+            JsonValueFormatter.WriteQuotedJsonString(logEvent.TraceId.ToString()!, output);
+        }
+
+        if (logEvent.SpanId != null)
+        {
+            output.Write(",\"SpanId\":");
+            JsonValueFormatter.WriteQuotedJsonString(logEvent.SpanId.ToString()!, output);
+        }
+
         if (logEvent.Exception != null)
         {
             output.Write(",\"Exception\":");

src/Serilog/ILogger.cs

@@ -12,6 +12,8 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
+using System.Diagnostics;
+
 namespace Serilog;
 
 /// <summary>
@@ -62,7 +64,7 @@ ILogger ForContext(ILogEventEnricher enricher)
     ILogger ForContext(IEnumerable<ILogEventEnricher> enrichers)
 #if FEATURE_DEFAULT_INTERFACE
     {
-        if (enrichers == null)
+        if (enrichers == null!)
             return this; // No context here, so little point writing to SelfLog.
 
         return ForContext(new SafeAggregateEnricher(enrichers));
@@ -113,7 +115,7 @@ ILogger ForContext<TSource>()
     ILogger ForContext(Type source)
 #if FEATURE_DEFAULT_INTERFACE
     {
-        if (source == null)
+        if (source == null!)
             return this; // Little point in writing to SelfLog here because we don't have any contextual information
 
         return ForContext(Constants.SourceContextPropertyName, source.FullName);
@@ -324,16 +326,19 @@ void Write(LogEventLevel level, Exception? exception, string messageTemplate, pa
 #if FEATURE_DEFAULT_INTERFACE
     {
         if (!IsEnabled(level)) return;
-        if (messageTemplate == null) return;
+        if (messageTemplate == null!) return;
 
         // Catch a common pitfall when a single non-object array is cast to object[]
         if (propertyValues != null &&
             propertyValues.GetType() != typeof(object[]))
             propertyValues = new object[] { propertyValues };
 
+        var logTimestamp = DateTimeOffset.Now;
         if (BindMessageTemplate(messageTemplate, propertyValues, out var parsedTemplate, out var boundProperties))
         {
-            Write(new LogEvent(DateTimeOffset.Now, level, exception, parsedTemplate, boundProperties));
+            var currentActivity = Activity.Current;
+            var logEvent = new LogEvent(logTimestamp, level, exception, parsedTemplate, boundProperties, currentActivity?.TraceId ?? default, currentActivity?.SpanId ?? default);
+            Write(logEvent);
         }
     }
 #else

src/Serilog/Serilog.csproj

@@ -1,7 +1,7 @@
 <Project Sdk="Microsoft.NET.Sdk">
   <PropertyGroup>
     <Description>Simple .NET logging with fully-structured events</Description>
-    <VersionPrefix>3.0.2</VersionPrefix>
+    <VersionPrefix>3.1.0</VersionPrefix>
     <Authors>Serilog Contributors</Authors>
     <TargetFrameworks Condition=" '$(OS)' == 'Windows_NT'">net462;net471</TargetFrameworks>
     <TargetFrameworks>$(TargetFrameworks);netstandard2.1;netstandard2.0;net5.0;net6.0;net7.0</TargetFrameworks>
@@ -66,6 +66,19 @@
 
   <ItemGroup Condition=" '$(TargetFramework)' == 'net462' ">
     <PackageReference Include="System.ValueTuple" Version="4.5.0" />
+    <PackageReference Include="System.Diagnostics.DiagnosticSource" Version="7.0.2" />
+  </ItemGroup>
+
+  <ItemGroup Condition=" '$(TargetFramework)' == 'net471' ">
+    <PackageReference Include="System.Diagnostics.DiagnosticSource" Version="7.0.2" />
+  </ItemGroup>
+
+  <ItemGroup Condition=" '$(TargetFramework)' == 'netstandard2.0' ">
+    <PackageReference Include="System.Diagnostics.DiagnosticSource" Version="7.0.2" />
+  </ItemGroup>
+
+  <ItemGroup Condition=" '$(TargetFramework)' == 'netstandard2.1' ">
+    <PackageReference Include="System.Diagnostics.DiagnosticSource" Version="7.0.2" />
   </ItemGroup>
 
 </Project>

test/Serilog.ApprovalTests/Serilog.approved.txt

@@ -358,11 +358,17 @@ namespace Serilog.Events
     public class LogEvent
     {
         public LogEvent(System.DateTimeOffset timestamp, Serilog.Events.LogEventLevel level, System.Exception? exception, Serilog.Events.MessageTemplate messageTemplate, System.Collections.Generic.IEnumerable<Serilog.Events.LogEventProperty> properties) { }
+        [System.CLSCompliant(false)]
+        public LogEvent(System.DateTimeOffset timestamp, Serilog.Events.LogEventLevel level, System.Exception? exception, Serilog.Events.MessageTemplate messageTemplate, System.Collections.Generic.IEnumerable<Serilog.Events.LogEventProperty> properties, System.Diagnostics.ActivityTraceId traceId, System.Diagnostics.ActivitySpanId spanId) { }
         public System.Exception? Exception { get; }
         public Serilog.Events.LogEventLevel Level { get; }
         public Serilog.Events.MessageTemplate MessageTemplate { get; }
         public System.Collections.Generic.IReadOnlyDictionary<string, Serilog.Events.LogEventPropertyValue> Properties { get; }
+        [System.CLSCompliant(false)]
+        public System.Diagnostics.ActivitySpanId? SpanId { get; }
         public System.DateTimeOffset Timestamp { get; }
+        [System.CLSCompliant(false)]
+        public System.Diagnostics.ActivityTraceId? TraceId { get; }
         public void AddOrUpdateProperty(Serilog.Events.LogEventProperty property) { }
         public void AddPropertyIfAbsent(Serilog.Events.LogEventProperty property) { }
         public void RemovePropertyIfPresent(string propertyName) { }
@@ -452,7 +458,9 @@ namespace Serilog.Formatting.Display
         public const string MessagePropertyName = "Message";
         public const string NewLinePropertyName = "NewLine";
         public const string PropertiesPropertyName = "Properties";
+        public const string SpanIdPropertyName = "SpanId";
         public const string TimestampPropertyName = "Timestamp";
+        public const string TraceIdPropertyName = "TraceId";
     }
 }
 namespace Serilog.Formatting

test/Serilog.PerformanceTests/PipelineBenchmark.cs

@@ -30,9 +30,6 @@ public void Setup()
         _log = new LoggerConfiguration()
             .WriteTo.Sink(new NullSink())
             .CreateLogger();
-
-        // Ensure template is cached
-        _log.Information(_exception, "Hello, {Name}!", "World");
     }
 
     [Benchmark]