Description
Description
Since version 9.0.1 of Serilog.Extensions.Logging, there has been a change in how values in a scope override each other in LogEvents. Previously, the value passed directly to the log method would take precedence over values defined in scopes. Now, the innermost scope value takes precedence instead.
Reproduction Code
[Fact]
public async Task PropertyOverride_Scope()
{
var listener = new LogEventListener();
Log.Logger = new LoggerConfiguration()
.Enrich.FromLogContext()
.WriteTo.Sink(listener)
.CreateLogger();
var provider = new ServiceCollection()
.AddLogging(m => m.AddSerilog(Log.Logger, dispose: true))
.BuildServiceProvider();
var logger = provider.GetRequiredService<ILogger<ScopeTests>>();
using (logger.BeginScope(new Dictionary<string, object?> { { "Value", 1 } }))
using (logger.BeginScope(new Dictionary<string, object?> { { "Value", 2 } }))
{
logger.LogInformation("Value: {Value}", 3);
}
Assert.True(await listener.WaitAsync(1, TimeSpan.FromSeconds(3)));
var logEvent = listener.Events.First();
var value = (logEvent.Properties["Value"] as ScalarValue)?.Value;
// Expected behavior before Serilog.Extensions.Logging 9.0.1
// Assert.Equal(3, value);
// Actual behavior since Serilog.Extensions.Logging 9.0.1
Assert.Equal(2, value);
}
public class LogEventListener : ILogEventSink
{
private readonly SemaphoreSlim _semaphore = new(0);
public List<LogEvent> Events { get; } = [];
public virtual void Emit(LogEvent logEvent)
{
Events.Add(logEvent);
_semaphore.Release();
}
public async Task<bool> WaitAsync(int count, TimeSpan timeout, CancellationToken cancellationToken = default)
{
for (var i = 0; i < count; ++i)
{
var flag = await _semaphore.WaitAsync(timeout, cancellationToken);
if (flag == false)
return false; // timeout
}
return true;
}
}Comparing to LogContext
When using Serilog's native LogContext directly (instead of through Microsoft.Extensions.Logging), the behavior is different and matches the previous behavior:
using (LogContext.PushProperty("Value", 1))
using (LogContext.PushProperty("Value", 2))
{
logger.Information("Value: {Value}", 3);
}
// the "Value" will be 3.Expected Behavior
Before version 9.0.1, when logging with a parameter that shares the same name as a property in a scope, the directly passed value (3 in this case) would take precedence over any scope values, which is consistent with how Serilog's native LogContext API works.
Actual Behavior
Since version 9.0.1, the innermost scope value (2 in this case) takes precedence over the value passed directly to the log method (3), creating inconsistency with Serilog's native behavior.
Questions
- Is this a deliberate change in behavior or an unintended side effect?
- If unintended, can the previous behavior be restored?