Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Behavior Change: Property Value Overriding in LogEvents Since Serilog.Extensions.Logging 9.0.1 #271

Open
huoshan12345 opened this issue Mar 30, 2025 · 2 comments · May be fixed by #272
Open

Comments

@huoshan12345
Copy link

huoshan12345 commented Mar 30, 2025

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?
@nblumhardt
Copy link
Member

Thanks for the note! I think this is an unintended consequence of the external scope provider support added in v9, which would have been masked by another issue in the 9.0.0 build, but revealed by the 9.0.1 fix.

I am not sure whether Microsoft.Extensions.Logging sets any expectations around how conflicts between event and scope properties should be resolved, and thus whether this is a bug or just unspecified behavior. A proposal/PR that reverts to the earlier behavior would be welcome, but I'm not sure it's possible without significant performance costs - needs some investigation.

@huoshan12345
Copy link
Author

Hi @nblumhardt, thanks for the reply!

After reviewing the behavior, I believe it makes sense to maintain consistency with Serilog's LogContext behavior, specifically:

  1. Inner scopes should add or update properties from outer scopes
  2. Scopes should add properties to LogEvents but not override existing properties

I've created PR (#272) implementing this approach. Looking forward to your review!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants