Enrich.FromLogContext() + BeginScope() = double calls to SerilogLoggerProvider.Enrich()

[wjrogers]

While developing a custom scope object, I noticed my code was called twice per log event, so I started experimenting with the debugger. I captured the two stack traces below at a breakpoint inside the scope state enumeration in EnrichAndCreateScopeItem. When used with Enrich.FromLogContext(), a logger created by SerilogLoggerProvider applies the scope stack twice. Is this intended?

First, the provider adds itself to its logger as an enricher: https://github.com/serilog/serilog-extensions-logging/blob/b7c975d986984f8bf8e74cd295681bcc171ebb5a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerProvider.cs#L43

Serilog.Extensions.Logging.dll!Serilog.Extensions.Logging.SerilogLoggerScope.EnrichAndCreateScopeItem(Serilog.Events.LogEvent logEvent, Serilog.Core.ILogEventPropertyFactory propertyFactory, out Serilog.Events.LogEventPropertyValue scopeItem)
Serilog.Extensions.Logging.dll!Serilog.Extensions.Logging.SerilogLoggerProvider.Enrich(Serilog.Events.LogEvent logEvent, Serilog.Core.ILogEventPropertyFactory propertyFactory)
Serilog.dll!Serilog.Core.Enrichers.SafeAggregateEnricher.Enrich(Serilog.Events.LogEvent logEvent, Serilog.Core.ILogEventPropertyFactory propertyFactory)
Serilog.dll!Serilog.Core.Logger.Dispatch(Serilog.Events.LogEvent logEvent)
Serilog.Extensions.Logging.dll!Serilog.Extensions.Logging.SerilogLogger.Log<object>(Microsoft.Extensions.Logging.LogLevel logLevel, Microsoft.Extensions.Logging.EventId eventId, object state, System.Exception exception, System.Func<object, System.Exception, string> formatter)

Second, on the outermost call to BeginScope(), the provider pushes itself onto the LogContext, so enriching from the LogContext results in a second call to Enrich(): https://github.com/serilog/serilog-extensions-logging/blob/b7c975d986984f8bf8e74cd295681bcc171ebb5a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerProvider.cs#L69

Serilog.Extensions.Logging.dll!Serilog.Extensions.Logging.SerilogLoggerScope.EnrichAndCreateScopeItem(Serilog.Events.LogEvent logEvent, Serilog.Core.ILogEventPropertyFactory propertyFactory, out Serilog.Events.LogEventPropertyValue scopeItem)
Serilog.Extensions.Logging.dll!Serilog.Extensions.Logging.SerilogLoggerProvider.Enrich(Serilog.Events.LogEvent logEvent, Serilog.Core.ILogEventPropertyFactory propertyFactory)
Serilog.dll!Serilog.Context.LogContext.Enrich(Serilog.Events.LogEvent logEvent, Serilog.Core.ILogEventPropertyFactory propertyFactory)
Serilog.dll!Serilog.Core.Enrichers.SafeAggregateEnricher.Enrich(Serilog.Events.LogEvent logEvent, Serilog.Core.ILogEventPropertyFactory propertyFactory)
Serilog.dll!Serilog.Core.Logger.Dispatch(Serilog.Events.LogEvent logEvent)
Serilog.Extensions.Logging.dll!Serilog.Extensions.Logging.SerilogLogger.Log<object>(Microsoft.Extensions.Logging.LogLevel logLevel, Microsoft.Extensions.Logging.EventId eventId, object state, System.Exception exception, System.Func<object, System.Exception, string> formatter)

I'm guessing the provider pushes itself onto the LogContext so that logging via other Serilog loggers (e.g. via the static Log class) -- which might not use the same underlying logger as the SerilogLoggerProvider -- still propagates the scope properties? Is there a recommended way to initialize Serilog + Microsoft.Extensions.Logging that prevents the double-enrichment?

[nblumhardt]

Thanks for raising this, and sorry about the lack of response - this library was a little tricky to keep up with, for a time :-)

Your assessment is correct, this is to support Log; I don't know if there's a simple alternative implementation we could use, although I'd guess something is possible.

I'll leave this open as a reminder to look out for an opportunity to tackle it, but in the meantime I think this is essentially by-design.

[nblumhardt]

Closing this to keep the tracker tidy; no plans to make these changes at present, but still mindful that something might emerge down the line.