{"action":"created","issue":{"url":"https://api.github.com/repos/serilog/serilog/issues/1154","repository_url":"https://api.github.com/repos/serilog/serilog","labels_url":"https://api.github.com/repos/serilog/serilog/issues/1154/labels{/name}","comments_url":"https://api.github.com/repos/serilog/serilog/issues/1154/comments","events_url":"https://api.github.com/repos/serilog/serilog/issues/1154/events","html_url":"https://github.com/serilog/serilog/issues/1154","id":318722357,"number":1154,"title":"\"Collection was modified; enumeration operation may not execute\" with complex enricher chain","user":{"login":"bartelink","id":206668,"avatar_url":"https://avatars3.githubusercontent.com/u/206668?v=4","gravatar_id":"","url":"https://api.github.com/users/bartelink","html_url":"https://github.com/bartelink","followers_url":"https://api.github.com/users/bartelink/followers","following_url":"https://api.github.com/users/bartelink/following{/other_user}","gists_url":"https://api.github.com/users/bartelink/gists{/gist_id}","starred_url":"https://api.github.com/users/bartelink/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/bartelink/subscriptions","organizations_url":"https://api.github.com/users/bartelink/orgs","repos_url":"https://api.github.com/users/bartelink/repos","events_url":"https://api.github.com/users/bartelink/events{/privacy}","received_events_url":"https://api.github.com/users/bartelink/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":4,"created_at":"2018-04-29T14:41:13Z","updated_at":"2018-05-02T11:35:52Z","closed_at":null,"author_association":"NONE","body":"I'm using the dev version of Async and latest of File, Console and Core and got the following exception:\r\n\r\n```\r\n2018-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.\r\n   at System.ThrowHelper.ThrowInvalidOperationException(ExceptionResource resource)\r\n   at System.Collections.Generic.Dictionary`2.Enumerator.MoveNext()\r\n   at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()\r\n   at Serilog.Events.LogEvent..ctor(DateTimeOffset timestamp, LogEventLevel level, Exception exception, MessageTemplate messageTemplate, IEnumerable`1 properties)\r\n   at Serilog.Core.Sinks.SecondaryLoggerSink.Emit(LogEvent logEvent)\r\n   at Serilog.Sinks.Async.BackgroundWorkerSink.Pump() {}\r\n```\r\n\r\nHere is an outline of the logger pipeline that triggers it:\r\n\r\n```\r\n new Serilog.LoggerConfiguration()\r\n                .Enrich.WithThreadId()\r\n                .Enrich.FromLogContext()\r\n                .WriteTo.Async(\r\n                    bufferSize: 16384,\r\n                    configure: (Serilog.Configuration.LoggerSinkConfiguration a) =>\r\n                    {\r\n                        if (consoleMinLevel != null)\r\n                            a.Sink(AppHostHealthMonitor.LogSink, restrictedToMinimumLevel: consoleMinLevel.Value);\r\n                        foreach (var filePath in textLogs ?? Enumerable.Empty<string>())\r\n                            a.Logger(l => l\r\n                                .Filter.ByExcluding(x => x.Level >= Serilog.Events.LogEventLevel.Fatal && consoleMinLevel == null)\r\n                                .Enrich.With<UtcTimestampEnricher>()\r\n                                .WriteTo.File(path: filePath, buffered: true, flushToDiskInterval: TimeSpan.FromSeconds(1),\r\n                                    outputTemplate: \"{UtcTimestamp:yyyy-MM-dd HH:mm:ss.ffff}|{NLogLevel}|{SourceContext}|{Message:l}|{Properties}{NewLine}{Exception}\",\r\n                                    rollOnFileSizeLimit: true, fileSizeLimitBytes: 1024L * 1024 * 20, retainedFileCountLimit: 10));\r\n                    });\r\n```\r\n\r\nThe problem seems rooted in the following not doing a full deep copy:\r\n\r\n```\r\npublic void Emit(LogEvent logEvent)\r\n        {\r\n            if (logEvent == null) throw new ArgumentNullException(nameof(logEvent));\r\n\r\n            var copy = new LogEvent(\r\n                logEvent.Timestamp,\r\n                logEvent.Level,\r\n                logEvent.Exception,\r\n                logEvent.MessageTemplate,\r\n                logEvent.Properties.Select(p => new LogEventProperty(p.Key, p.Value)));\r\n\r\n            _logger.Write(copy);\r\n        }\r\n```\r\n\r\nObviously '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)\r\n\r\nIf anyone can give me some guidance as to what the intended semantics are, I'm happy to fix it appropriately."},"comment":{"url":"https://api.github.com/repos/serilog/serilog/issues/comments/385948100","html_url":"https://github.com/serilog/serilog/issues/1154#issuecomment-385948100","issue_url":"https://api.github.com/repos/serilog/serilog/issues/1154","id":385948100,"user":{"login":"bartelink","id":206668,"avatar_url":"https://avatars3.githubusercontent.com/u/206668?v=4","gravatar_id":"","url":"https://api.github.com/users/bartelink","html_url":"https://github.com/bartelink","followers_url":"https://api.github.com/users/bartelink/followers","following_url":"https://api.github.com/users/bartelink/following{/other_user}","gists_url":"https://api.github.com/users/bartelink/gists{/gist_id}","starred_url":"https://api.github.com/users/bartelink/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/bartelink/subscriptions","organizations_url":"https://api.github.com/users/bartelink/orgs","repos_url":"https://api.github.com/users/bartelink/repos","events_url":"https://api.github.com/users/bartelink/events{/privacy}","received_events_url":"https://api.github.com/users/bartelink/received_events","type":"User","site_admin":false},"created_at":"2018-05-02T11:35:52Z","updated_at":"2018-05-02T11:35:52Z","author_association":"NONE","body":"Determined that this was a PEBKAC issue relating to what I was doing inside the `.Async`'s `configure` - see the gitter. Will document as I close when we reach root cause. For now, the issue was that I was doing a `.WriteTo` a `.Sink` that did enrichment as well as a `a.Logger`. i.e. the `a.Sink` seems to be be triggering enrichment overlapping with enrichment in the `.Logger`. The mitigation is to wrap the logging in a `.Logger`, which ensures the two loggers within the `.Async` never touch the original (I `.WriteTo.Seq` after the `.WriteTo.Async` and that works fine too - the conflict is confined to inside the `.Async` above):\r\n\r\nMitigated version:\r\n\r\n```\r\n                        // NB don't assume that these logger chains are processed sequentially\r\n                        if (consoleMinLevel != null)\r\n                            // NB need to ensure messages get cloned to an independent copy by the `.Logger` or the main `a.Logger` can throw an\r\n                            // InvalidOperationException due to the mutations that AppHostHealthMonitor.LogSink's Enrichers trigger\r\n                            a.Logger(\r\n                                l => l.WriteTo.Sink(AppHostHealthMonitor.LogSink),\r\n                                restrictedToMinimumLevel: consoleMinLevel.Value);\r\n```"}}
{"actor":{"display_login":"bartelink"}}