nblumhardt / serilog-timings

Extends Serilog with support for timed operations
Apache License 2.0
218 stars 21 forks source link

Operations that change non-concurrent collections must have exclusive access #57

Closed tereshechkin closed 1 year ago

tereshechkin commented 1 year ago

Error "Operations that change non-concurrent collections must have exclusive access" occures if logging is disabled:

System.InvalidOperationException: Operations that change non-concurrent collections must have exclusive access. A concurrent update was performed on this collection and corrupted its state. The collection's state is no longer correct. at System.Collections.Generic.Dictionary2.TryInsert(TKey key, TValue value, InsertionBehavior behavior) at System.Collections.Generic.Dictionary2.set_Item(TKey key, TValue value) at Operation.EnrichWith(String propertyName, Object value, Boolean destructureObjects)\r\n at

This is due to the fact that the extension method "OperationAt" returns a static object "LeveledOperation.None". Accordingly, several threads work with a single object of the "Operation" type. This leads to an error accessing the Dictionary "Operation._contextParams" in the "EnrichWith" method.

Below is the code to reproduce the error.

    static readonly Microsoft.Extensions.Logging.ILogger _logger = LoggerFactory.Create(builder =>
    {
        builder.AddDebug();
    }).CreateLogger<MicrosoftILoggerExamples>();

    public static void TestСollections()
    {
        var tasksCount = 10;
        var cyclesCount = 1000;
        var taskList = new List<Task>();
        for (int i = 0; i < tasksCount; i++)
        {
            var task = Task.Run(() =>
            {
                int cycle = 0;
                while (cycle < cyclesCount)
                {
                    TestLog();
                    Thread.Sleep(10);
                    cycle++;
                }
            });
            taskList.Add(task);
        }
    }

    public static void TestLog()
    {
        const string testValue = "testValue";
        using (_logger.BeginScope(PlatformLoggerConstants.PlatformMethodKey, testValue))
        using (var op = _logger.OperationAt(LogLevel.Trace).Begin("TestLog - ", testValue))
        {
            try
            {
                op.EnrichWith("TestProperty", testValue);
                op.Complete();
            }
            catch (Exception ex)
            {
                Console.WriteLine(ex);
                _logger.LogError(ex, ex.Message, testValue);
            }
        }
    }
nblumhardt commented 1 year ago

Ah drat. Nice catch!

nblumhardt commented 1 year ago

Hi again! After scratching my head for a little while - I think you're using a port of Serilog.Extensions.Logging for the Microsoft.Extensions.Logging logger. There's no Operation._contextParams in this library.

If you need a hand tracking down the correct codebase/repo, posting some dependency information from your CSPROJ file would help identify the source of the code. HTH!

tereshechkin commented 1 year ago

Oops. The error does not occur in the original implementation of Serilog-Timings, but in a separate branch that was made for Microsoft.Extensions.Logging.ILogger, since there is a project where this interface is used exclusively.

There is no such problem in the original Serilog-Timings implementation.

Sorry for disturbing:)

nblumhardt commented 1 year ago

No problem at all, thanks for dropping by all the same :-)