serilog: "Collection was modified; enumeration operation may not execute" with complex enricher chain

I’m using the dev version of Async and latest of File, Console and Core and got the following exception:

2018-04-27 14:21:57.3356+1 FTL HealthLogger Serilog SelfLog warning 2018-04-27T13:21:57.3301713Z Serilog.Sinks.Async.BackgroundWorkerSink fatal error in worker thread: System.InvalidOperationException: Collection was modified; enumeration operation may not execute.
   at System.ThrowHelper.ThrowInvalidOperationException(ExceptionResource resource)
   at System.Collections.Generic.Dictionary`2.Enumerator.MoveNext()
   at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
   at Serilog.Events.LogEvent..ctor(DateTimeOffset timestamp, LogEventLevel level, Exception exception, MessageTemplate messageTemplate, IEnumerable`1 properties)
   at Serilog.Core.Sinks.SecondaryLoggerSink.Emit(LogEvent logEvent)
   at Serilog.Sinks.Async.BackgroundWorkerSink.Pump() {}

Here is an outline of the logger pipeline that triggers it:

 new Serilog.LoggerConfiguration()
                .Enrich.WithThreadId()
                .Enrich.FromLogContext()
                .WriteTo.Async(
                    bufferSize: 16384,
                    configure: (Serilog.Configuration.LoggerSinkConfiguration a) =>
                    {
                        if (consoleMinLevel != null)
                            a.Sink(AppHostHealthMonitor.LogSink, restrictedToMinimumLevel: consoleMinLevel.Value);
                        foreach (var filePath in textLogs ?? Enumerable.Empty<string>())
                            a.Logger(l => l
                                .Filter.ByExcluding(x => x.Level >= Serilog.Events.LogEventLevel.Fatal && consoleMinLevel == null)
                                .Enrich.With<UtcTimestampEnricher>()
                                .WriteTo.File(path: filePath, buffered: true, flushToDiskInterval: TimeSpan.FromSeconds(1),
                                    outputTemplate: "{UtcTimestamp:yyyy-MM-dd HH:mm:ss.ffff}|{NLogLevel}|{SourceContext}|{Message:l}|{Properties}{NewLine}{Exception}",
                                    rollOnFileSizeLimit: true, fileSizeLimitBytes: 1024L * 1024 * 20, retainedFileCountLimit: 10));
                    });

The problem seems rooted in the following not doing a full deep copy:

public void Emit(LogEvent logEvent)
        {
            if (logEvent == null) throw new ArgumentNullException(nameof(logEvent));

            var copy = new LogEvent(
                logEvent.Timestamp,
                logEvent.Level,
                logEvent.Exception,
                logEvent.MessageTemplate,
                logEvent.Properties.Select(p => new LogEventProperty(p.Key, p.Value)));

            _logger.Write(copy);
        }

Obviously ‘just’ materializing is going to cost perf… (there is no major perf win to splitting the enrich into the async pipeline - its more that logically those enrichers are only useful there and I have other sinks that do not require the same enrichment which are paying the price for something that I was trying to offload)

If anyone can give me some guidance as to what the intended semantics are, I’m happy to fix it appropriately.

About this issue

Original URL
State: closed
Created 6 years ago
Comments: 18 (18 by maintainers)

Commits related to this issue

reverting 67cfc0ee, fixes https://github.com/serilog/serilog/issues/1154 — committed to skomis-mm/serilog-sinks-async by deleted user 6 years ago
Fixes a number of issues with `LoggerSinkConfiguration.Wrap()` identified in #1154 - Ensures that `wt.X(); wt.Y()` and `wt.X().WriteTo.Y()` are equivalent - Ensures a failing sink doesn't block eve... — committed to nblumhardt/serilog by nblumhardt 6 years ago

Most upvoted comments

@nblumhardt thanks for explaining, I didn’t take an account a PBS which can have the same potential problem with the Logger.Write(..) like Async does. Seems reasonable to leave things as is, leaving full fix optional to the client code (.WriteTo.Logger(lc => lc.Async(..))) if needed.

Without full copying of LogEvent I played a bit with ThreadLocal properties inside LogEvent where enriching is local to the current thread (with copying parent properties when needed), but this is too major change that best to be leaved for research for the future version along with the full immutable LogEvent and other solutions that can fix Logger.Write related problem.

I’ll close the #32 in favor of fixed Wrap method which gives less hops for the LogEvent to reach target sink.

skomis-mm on May 14, 2018

Thanks for digging into it, @skomis-mm - I think I’m on the same page. I’m splitting time between a few too many projects at the moment, and context-switching back into this five minutes at a time is getting tough 😃 I’ll put aside some time to properly think through the solutions and get a proper reply back onto this thread ASAP.

nblumhardt on May 12, 2018

@bartelink I checked this and found the regression I made in this pr. The underlying reason is described by @nblumhardt that loggers can mutate the events passed into them via Write(event) in different threads. But another issue is that the current .Wrap is not working (at least for the Async package) as expected for pipelines built with the Action<LoggerSinkConfiguration> configure action. It doesn’t create an aggregating sink and adds wrapped inner sinks to the flat list of the parent logger. Another thing is that the way of how inner pipeline is configured makes difference on the result pipeline:

a.Sink(..);
a.Logger(..);

and

a.Sink(..).WriteTo.Logger(..);

will create different results.

For the current Async implementation the first block will result in two BackgroundWorkerSinks. So the threading issue is become apparent. That’s why reverting to 1.1 will hide the problem away. It still exists and the following setup won’t work for the exact underlying reason

Log.Logger = new LoggerConfiguration()
   .WriteTo.Async(c => c.Sink(new LoggerConfiguration().Enrich.WithProperty(...).WriteTo.Sink(...).CreateLogger())
   .WriteTo.Async(c => c.Sink(new LoggerConfiguration().Enrich.WithProperty(...).WriteTo.Sink(...).CreateLogger()))
         .CreateLogger();

Summarizing this I believe aforementioned pr should be reverted asap (since 1.2 is on the master already).

.Async extension method could be modified as well and based on the SecondaryLoggerSink(.Logger(...)) so each inner pipeline will work with their own copy of the event. It will solve the threading issue but inner sinks could observe enriched events of each other as side effects because of LogEvent’s mutability + increased allocations so I’m not sure if this needed (since there were no complaints for the 1.0-1.1)

Thoughts?

skomis-mm on May 10, 2018

Seems key diff between dev and master is thatmaster is using Logger.Write whereas dev is using ILogSink.Emit This is reproable independent of the health monitoring (I removed it at the same time as I consolidated the enrichers outside the pipe)

bartelink on Apr 29, 2018