Serilog: Crash when logging quickly from async Tasks

[travis79]

Description
Within a unit test which triggers 100 log messages from async Tasks, an apparently unrelated exception is raised by the TaskScheduler. If I comment out or disable the logging that is triggered by this unit test, then the exception does not occur. The stack trace is below, but it doesn't seem to show any particular reference to Serilog in the trace.

Stack Trace from exception:

System.Threading.Tasks.TaskSchedulerException: "An exception was thrown by a TaskScheduler." ---> System.InvalidOperationException: "System.Threading.Tasks.ConcurrentExclusiveSchedulerPair+ConcurrentExclusiveTaskScheduler"
  at at System.Threading.Tasks.ConcurrentExclusiveSchedulerPair.ConcurrentExclusiveTaskScheduler.QueueTask(Task task)\n   at System.Threading.Tasks.TaskScheduler.InternalQueueTask(Task task)\n   at System.Threading.Tasks.Task.ScheduleAndStart(Boolean needsProtection)
  --- End of inner exception stack trace ---
  at System.Threading.Tasks.Task.ScheduleAndStart(Boolean needsProtection)\n   at System.Threading.Tasks.Task.InternalStartNew(Task creatingTask, Delegate action, Object state, CancellationToken cancellationToken, TaskScheduler scheduler, TaskCreationOptions options, InternalTaskOptions internalOptions)\n   at System.Threading.Tasks.TaskFactory.StartNew(Action action, CancellationToken cancellationToken, TaskCreationOptions creationOptions, TaskScheduler scheduler)\n   at Mozilla.Glean.Dispatchers.LaunchAPI(Action action) in /Users/tlong/Documents/glean/glean-core/csharp/Glean/Dispatchers.cs:line 123\n   at Mozilla.Glean.Tests.DispatchersTests.<>c__DisplayClass4_0.<TestQueuedTasksAreExecutedInOrderAsync>b__1() in /Users/tlong/Documents/glean/glean-core/csharp/GleanTests/DispatchersTests.cs:147

Reproduction
See this PR for implementation details in our project. The particular exception occurs in a unit test that is triggering logging in Dispatchers.cs, specifically the line log.Verbose("Task queued for execution and delayed until flushed");. Please note that it doesn't crash when logged as Verbose, I changed this to be below the minimum logging level as a workaround. The exception only occurs if logged at or above the minimum logging level.

Expected behavior
Logging should occur without causing an exception.

Relevant package, tooling and runtime versions
Using:

• Serilog v2.9.0, Serilog.Sinks.Console v3.1.1, Serilog.Sinks.Trace v2.1.0
• VS for Mac 8.6.3 (build 30)
• dotnet v3.1.300
• MacOS Catalina 10.15.5

Additional context
This is being logged rather quickly in the unit test (100 times with little or no delay) and the logging is occurring from background async Tasks, but the tasks are executed sequentially and not concurrently.

[nblumhardt]

Hi Travis, thanks for dropping by. Very cool to see Serilog pop up in a Mozilla project - big fan, here 😎

My guess, looking at the moving parts, is that the logging involvement may be a red herring. Logging is cheap, but can still take up quite a few cycles. This would make the tasks take longer to execute, and possibly put more stress on the scheduler when logging is enabled.

To test (and hopefully confirm or rule out) this theory, could you try replacing the log statements with Console.WiteLine() and Trace.WriteLine() pairs, to see whether this is enough to trigger the issue? Under the hood, apart from some argument formatting, that should be essentially what Serilog is doing here, with these two sinks enabled.

Let me know if this helps!
Nick

[travis79]

Thanks for the quick response Nick!

So I tried swapping out the logging line with a Console.WriteLine and a Trace.WriteLine as you suggested and I did get different behavior. If I just run the unit test with the change, it now passes, where before when going through Serilog it would crash in this case. It _still_ crashes with the change if I Debug the test though.

After playing around with this it appears there may be some weird interaction between tests, because running the test all by itself without running other tests seems to work whereas running all tests triggers the crash.

Since I did get different behavior but it still crashes with or without Serilog in the mix, I am not sure this is anything directly related to Serilog. I'm open to any other suggestions you might have but I think I need to look at this a little differently.

[skomis-mm]

Hi @travis79,

Could reproduce this on windows. From the stack trace the error about QueueTask:

// If the scheduler has already had completion requested, no new work is allowed to be scheduled

taskSchedulerPair.Complete() happens before all outstanding tasks are queued.

TestCancellingBackgroundTasksClearsQueue test calls this method on shared scheduler via CancelBackgroundTasks(). After that Dispatchers.LaunchAPI(..) for Task.Factory.StartNew(..) path will throw for any subsequent call.
Any delay to AddActionToQueue like Thread.Sleep(1) instead of logging as @nblumhardt pointed will introduce that race error.

[travis79]

Ahh, thanks for the insight. I hadn't used the ConcurrentExclusiveSchedulerPair prior to this, so this is obviously my lack of experience with how it was working. Thanks for the info, feel free to close this issue as I'm pretty sure it's nothing to do with Serilog.