Merge pull request #269 from nblumhardt/nested-scope-ordering

nblumhardt · web-flow · commit 7713521ec6d3 · 2025-03-14T08:05:33.000+10:00
Correct the order of property additions from external scopes
diff --git a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerProvider.cs b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerProvider.cs
@@ -102,9 +102,12 @@ public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
             }
         }
 
+        scopeItems?.Reverse();
+
         _externalScopeProvider?.ForEachScope((state, accumulatingLogEvent) =>
         {
-            SerilogLoggerScope.EnrichWithStateAndCreateScopeItem(accumulatingLogEvent, propertyFactory, state, out var scopeItem);
+            SerilogLoggerScope.EnrichWithStateAndCreateScopeItem(
+                accumulatingLogEvent, propertyFactory, state, update: true, out var scopeItem);
 
             if (scopeItem != null)
             {
@@ -115,7 +118,6 @@ public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
 
         if (scopeItems != null)
         {
-            scopeItems.Reverse();
             logEvent.AddPropertyIfAbsent(new LogEventProperty(ScopePropertyName, new SequenceValue(scopeItems)));
         }
     }
diff --git a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs
@@ -47,9 +47,9 @@ public void Dispose()
         }
     }
 
-    public void EnrichAndCreateScopeItem(LogEvent logEvent, ILogEventPropertyFactory propertyFactory, out LogEventPropertyValue? scopeItem) => EnrichWithStateAndCreateScopeItem(logEvent, propertyFactory, _state, out scopeItem);
+    public void EnrichAndCreateScopeItem(LogEvent logEvent, ILogEventPropertyFactory propertyFactory, out LogEventPropertyValue? scopeItem) => EnrichWithStateAndCreateScopeItem(logEvent, propertyFactory, _state, update: false, out scopeItem);
 
-    public static void EnrichWithStateAndCreateScopeItem(LogEvent logEvent, ILogEventPropertyFactory propertyFactory, object? state, out LogEventPropertyValue? scopeItem)
+    public static void EnrichWithStateAndCreateScopeItem(LogEvent logEvent, ILogEventPropertyFactory propertyFactory, object? state, bool update, out LogEventPropertyValue? scopeItem)
     {
         if (state == null)
         {
@@ -63,8 +63,8 @@ public static void EnrichWithStateAndCreateScopeItem(LogEvent logEvent, ILogEven
             // Separate handling of this case eliminates boxing of Dictionary<TKey, TValue>.Enumerator.
             scopeItem = null;
             foreach (var stateProperty in dictionary)
-            {                
-                AddProperty(logEvent, propertyFactory, stateProperty.Key, stateProperty.Value);
+            {
+                AddProperty(logEvent, propertyFactory, stateProperty.Key, stateProperty.Value, update);
             }
         }
         else if (state is IEnumerable<KeyValuePair<string, object>> stateProperties)
@@ -79,21 +79,21 @@ public static void EnrichWithStateAndCreateScopeItem(LogEvent logEvent, ILogEven
                 }
                 else
                 {
-                    AddProperty(logEvent, propertyFactory, stateProperty.Key, stateProperty.Value);
+                    AddProperty(logEvent, propertyFactory, stateProperty.Key, stateProperty.Value, update);
                 }
             }
         }
 #if FEATURE_ITUPLE
         else if (state is System.Runtime.CompilerServices.ITuple tuple && tuple.Length == 2 && tuple[0] is string s)
         {
             scopeItem = null; // Unless it's `FormattedLogValues`, these are treated as property bags rather than scope items.
-            AddProperty(logEvent, propertyFactory, s, tuple[1]);
+            AddProperty(logEvent, propertyFactory, s, tuple[1], update);
         }
 #else
         else if (state is ValueTuple<string, object?> tuple)
         {
             scopeItem = null;
-            AddProperty(logEvent, propertyFactory, tuple.Item1, tuple.Item2);
+            AddProperty(logEvent, propertyFactory, tuple.Item1, tuple.Item2, update);
         }
 #endif
         else
@@ -102,22 +102,29 @@ public static void EnrichWithStateAndCreateScopeItem(LogEvent logEvent, ILogEven
         }
     }
 
-    static void AddProperty(LogEvent logEvent, ILogEventPropertyFactory propertyFactory, string key, object? value)
+    static void AddProperty(LogEvent logEvent, ILogEventPropertyFactory propertyFactory, string key, object? value, bool update)
     {
-        var destructureObject = false;
+        var destructureObjects = false;
 
         if (key.StartsWith('@'))
         {
             key = SerilogLogger.GetKeyWithoutFirstSymbol(SerilogLogger.DestructureDictionary, key);
-            destructureObject = true;
+            destructureObjects = true;
         }
         else if (key.StartsWith('$'))
         {
             key = SerilogLogger.GetKeyWithoutFirstSymbol(SerilogLogger.StringifyDictionary, key);
             value = value?.ToString();
         }
 
-        var property = propertyFactory.CreateProperty(key, value, destructureObject);
-        logEvent.AddPropertyIfAbsent(property);
+        var property = propertyFactory.CreateProperty(key, value, destructureObjects);
+        if (update)
+        {
+            logEvent.AddOrUpdateProperty(property);
+        }
+        else
+        {
+            logEvent.AddPropertyIfAbsent(property);
+        }
     }
 }
diff --git a/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs b/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs
@@ -3,12 +3,14 @@
 
 using System.Collections;
 using System.Diagnostics;
+using Microsoft.Extensions.DependencyInjection;
 using Serilog.Events;
 using Microsoft.Extensions.Logging;
 using Serilog.Debugging;
 using Serilog.Extensions.Logging.Tests.Support;
 using Xunit;
 using Serilog.Core;
+// ReSharper disable AccessToDisposedClosure
 
 namespace Serilog.Extensions.Logging.Tests;
 
@@ -17,9 +19,9 @@ public class SerilogLoggerTest
     const string Name = "test";
     const string TestMessage = "This is a test";
 
-    static Tuple<SerilogLogger, SerilogSink> SetUp(LogLevel logLevel, IExternalScopeProvider? externalScopeProvider = null)
+    static Tuple<SerilogLogger, CollectingSink> SetUp(LogLevel logLevel, IExternalScopeProvider? externalScopeProvider = null)
     {
-        var sink = new SerilogSink();
+        var sink = new CollectingSink();
 
         var serilogLogger = new LoggerConfiguration()
             .WriteTo.Sink(sink)
@@ -34,7 +36,7 @@ static Tuple<SerilogLogger, SerilogSink> SetUp(LogLevel logLevel, IExternalScope
             provider.SetScopeProvider(externalScopeProvider);
         }
 
-        return new Tuple<SerilogLogger, SerilogSink>(logger, sink);
+        return new Tuple<SerilogLogger, CollectingSink>(logger, sink);
     }
 
     [Fact]
@@ -516,7 +518,7 @@ public void Dispose()
             }
         }
     }
-    
+
     [Fact]
     public void MismatchedMessageTemplateParameterCountIsHandled()
     {
@@ -579,4 +581,41 @@ public void TraceAndSpanIdsAreCaptured()
         Assert.Equal(Activity.Current.TraceId, evt.TraceId);
         Assert.Equal(Activity.Current.SpanId, evt.SpanId);
     }
+
+    [Fact]
+    public void LoggingScopeReplacesPropertyInNestedScope()
+    {
+        var sink = new CollectingSink();
+        using var logger = new LoggerConfiguration().WriteTo.Sink(sink).CreateLogger();
+
+        var services = new ServiceCollection();
+        services.AddLogging(l => l.AddSerilog(logger));
+
+        using var serviceProvider = services.BuildServiceProvider();
+        var msLogger = serviceProvider.GetRequiredService<ILogger<SerilogLoggerTest>>();
+
+        using (msLogger.BeginScope(new Dictionary<string, object> { { "EXECUTION_TAGS", "[TAG1]" } }))
+        {
+            msLogger.LogInformation("Message1");
+            using (msLogger.BeginScope(new Dictionary<string, object> { { "EXECUTION_TAGS", "[TAG2]" } }))
+            {
+                msLogger.LogInformation("Message2");
+            }
+        }
+
+        var logEvent = sink.Writes.FirstOrDefault(e => e.MessageTemplate.Text == "Message1");
+        Assert.NotNull(logEvent);
+        AssertHasScalarProperty(logEvent, "EXECUTION_TAGS", "[TAG1]");
+
+        logEvent = sink.Writes.FirstOrDefault(e => e.MessageTemplate.Text == "Message2");
+        Assert.NotNull(logEvent);
+        AssertHasScalarProperty(logEvent, "EXECUTION_TAGS", "[TAG2]");
+    }
+
+    static void AssertHasScalarProperty(LogEvent logEvent, string name, object? expectedValue)
+    {
+        Assert.True(logEvent.Properties.TryGetValue(name, out var result));
+        var scalar = Assert.IsType<ScalarValue>(result);
+        Assert.Equal(expectedValue, scalar.Value);
+    }
 }
diff --git a/test/Serilog.Extensions.Logging.Tests/SerilogLoggingBuilderExtensionsTests.cs b/test/Serilog.Extensions.Logging.Tests/SerilogLoggingBuilderExtensionsTests.cs
@@ -21,7 +21,7 @@ public void AddSerilogMustRegisterAnILoggerProvider()
     [Fact]
     public void AddSerilogMustRegisterAnILoggerProviderThatForwardsLogsToStaticSerilogLogger()
     {
-        var sink = new SerilogSink();
+        var sink = new CollectingSink();
         Log.Logger = new LoggerConfiguration()
             .WriteTo.Sink(sink)
             .CreateLogger();
@@ -39,7 +39,7 @@ public void AddSerilogMustRegisterAnILoggerProviderThatForwardsLogsToStaticSeril
     [Fact]
     public void AddSerilogMustRegisterAnILoggerProviderThatForwardsLogsToProvidedLogger()
     {
-        var sink = new SerilogSink();
+        var sink = new CollectingSink();
         var serilogLogger = new LoggerConfiguration()
             .WriteTo.Sink(sink)
             .CreateLogger();
diff --git a/test/Serilog.Extensions.Logging.Tests/Support/CollectingSink.cs b/test/Serilog.Extensions.Logging.Tests/Support/CollectingSink.cs
@@ -6,7 +6,7 @@
 
 namespace Serilog.Extensions.Logging.Tests.Support;
 
-public class SerilogSink : ILogEventSink
+public class CollectingSink : ILogEventSink
 {
     public List<LogEvent> Writes { get; set; } = new();
 

Original file line number	Diff line number	Diff line change
`@@ -102,9 +102,12 @@ public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)`
`102`	`102`	`}`
`103`	`103`	`}`
`104`	`104`
	`105`	`+ scopeItems?.Reverse();`
	`106`	`+`
`105`	`107`	`_externalScopeProvider?.ForEachScope((state, accumulatingLogEvent) =>`
`106`	`108`	`{`
`107`		`- SerilogLoggerScope.EnrichWithStateAndCreateScopeItem(accumulatingLogEvent, propertyFactory, state, out var scopeItem);`
	`109`	`+ SerilogLoggerScope.EnrichWithStateAndCreateScopeItem(`
	`110`	`+ accumulatingLogEvent, propertyFactory, state, update: true, out var scopeItem);`
`108`	`111`
`109`	`112`	`if (scopeItem != null)`
`110`	`113`	`{`
`@@ -115,7 +118,6 @@ public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)`
`115`	`118`
`116`	`119`	`if (scopeItems != null)`
`117`	`120`	`{`
`118`		`- scopeItems.Reverse();`
`119`	`121`	`logEvent.AddPropertyIfAbsent(new LogEventProperty(ScopePropertyName, new SequenceValue(scopeItems)));`
`120`	`122`	`}`
`121`	`123`	`}`
Original file line number	Diff line number	Diff line change
`@@ -47,9 +47,9 @@ public void Dispose()`
`47`	`47`	`}`
`48`	`48`	`}`
`49`	`49`
`50`		`- public void EnrichAndCreateScopeItem(LogEvent logEvent, ILogEventPropertyFactory propertyFactory, out LogEventPropertyValue? scopeItem) => EnrichWithStateAndCreateScopeItem(logEvent, propertyFactory, _state, out scopeItem);`
	`50`	`+ public void EnrichAndCreateScopeItem(LogEvent logEvent, ILogEventPropertyFactory propertyFactory, out LogEventPropertyValue? scopeItem) => EnrichWithStateAndCreateScopeItem(logEvent, propertyFactory, _state, update: false, out scopeItem);`
`51`	`51`
`52`		`- public static void EnrichWithStateAndCreateScopeItem(LogEvent logEvent, ILogEventPropertyFactory propertyFactory, object? state, out LogEventPropertyValue? scopeItem)`
	`52`	`+ public static void EnrichWithStateAndCreateScopeItem(LogEvent logEvent, ILogEventPropertyFactory propertyFactory, object? state, bool update, out LogEventPropertyValue? scopeItem)`
`53`	`53`	`{`
`54`	`54`	`if (state == null)`
`55`	`55`	`{`
`@@ -63,8 +63,8 @@ public static void EnrichWithStateAndCreateScopeItem(LogEvent logEvent, ILogEven`
`63`	`63`	`// Separate handling of this case eliminates boxing of Dictionary<TKey, TValue>.Enumerator.`
`64`	`64`	`scopeItem = null;`
`65`	`65`	`foreach (var stateProperty in dictionary)`
`66`		`- {`
`67`		`- AddProperty(logEvent, propertyFactory, stateProperty.Key, stateProperty.Value);`
	`66`	`+ {`
	`67`	`+ AddProperty(logEvent, propertyFactory, stateProperty.Key, stateProperty.Value, update);`
`68`	`68`	`}`
`69`	`69`	`}`
`70`	`70`	`else if (state is IEnumerable<KeyValuePair<string, object>> stateProperties)`
`@@ -79,21 +79,21 @@ public static void EnrichWithStateAndCreateScopeItem(LogEvent logEvent, ILogEven`
`79`	`79`	`}`
`80`	`80`	`else`
`81`	`81`	`{`
`82`		`- AddProperty(logEvent, propertyFactory, stateProperty.Key, stateProperty.Value);`
	`82`	`+ AddProperty(logEvent, propertyFactory, stateProperty.Key, stateProperty.Value, update);`
`83`	`83`	`}`
`84`	`84`	`}`
`85`	`85`	`}`
`86`	`86`	`#if FEATURE_ITUPLE`
`87`	`87`	`else if (state is System.Runtime.CompilerServices.ITuple tuple && tuple.Length == 2 && tuple[0] is string s)`
`88`	`88`	`{`
`89`	`89`	scopeItem = null; // Unless it's `FormattedLogValues`, these are treated as property bags rather than scope items.
`90`		`- AddProperty(logEvent, propertyFactory, s, tuple[1]);`
	`90`	`+ AddProperty(logEvent, propertyFactory, s, tuple[1], update);`
`91`	`91`	`}`
`92`	`92`	`#else`
`93`	`93`	`else if (state is ValueTuple<string, object?> tuple)`
`94`	`94`	`{`
`95`	`95`	`scopeItem = null;`
`96`		`- AddProperty(logEvent, propertyFactory, tuple.Item1, tuple.Item2);`
	`96`	`+ AddProperty(logEvent, propertyFactory, tuple.Item1, tuple.Item2, update);`
`97`	`97`	`}`
`98`	`98`	`#endif`
`99`	`99`	`else`
`@@ -102,22 +102,29 @@ public static void EnrichWithStateAndCreateScopeItem(LogEvent logEvent, ILogEven`
`102`	`102`	`}`
`103`	`103`	`}`
`104`	`104`
`105`		`- static void AddProperty(LogEvent logEvent, ILogEventPropertyFactory propertyFactory, string key, object? value)`
	`105`	`+ static void AddProperty(LogEvent logEvent, ILogEventPropertyFactory propertyFactory, string key, object? value, bool update)`
`106`	`106`	`{`
`107`		`- var destructureObject = false;`
	`107`	`+ var destructureObjects = false;`
`108`	`108`
`109`	`109`	`if (key.StartsWith('@'))`
`110`	`110`	`{`
`111`	`111`	`key = SerilogLogger.GetKeyWithoutFirstSymbol(SerilogLogger.DestructureDictionary, key);`
`112`		`- destructureObject = true;`
	`112`	`+ destructureObjects = true;`
`113`	`113`	`}`
`114`	`114`	`else if (key.StartsWith('$'))`
`115`	`115`	`{`
`116`	`116`	`key = SerilogLogger.GetKeyWithoutFirstSymbol(SerilogLogger.StringifyDictionary, key);`
`117`	`117`	`value = value?.ToString();`
`118`	`118`	`}`
`119`	`119`
`120`		`- var property = propertyFactory.CreateProperty(key, value, destructureObject);`
`121`		`- logEvent.AddPropertyIfAbsent(property);`
	`120`	`+ var property = propertyFactory.CreateProperty(key, value, destructureObjects);`
	`121`	`+ if (update)`
	`122`	`+ {`
	`123`	`+ logEvent.AddOrUpdateProperty(property);`
	`124`	`+ }`
	`125`	`+ else`
	`126`	`+ {`
	`127`	`+ logEvent.AddPropertyIfAbsent(property);`
	`128`	`+ }`
`122`	`129`	`}`
`123`	`130`	`}`
Original file line number	Diff line number	Diff line change
`@@ -6,7 +6,7 @@`
`6`	`6`
`7`	`7`	`namespace Serilog.Extensions.Logging.Tests.Support;`
`8`	`8`
`9`		`-public class SerilogSink : ILogEventSink`
	`9`	`+public class CollectingSink : ILogEventSink`
`10`	`10`	`{`
`11`	`11`	`public List<LogEvent> Writes { get; set; } = new();`
`12`	`12`