Technical question on BeginScope mechanism

[AroglDarthu]

@nblumhardt Hi Nicholas,

The last couple of hours I have been breaking my head on the scoping mechanism of Serilog.Extensions.Logging. Although the usage pattern is clear to me, I am having a hard time grasping the technical details on it. More precisely I wonder how the scopes do not get intermingled in a multi-threaded scenario.

It seems to me that, because the same provider is being used for every BeginScope, race conditions should occur on setting the CurrentScope property of that provider and on setting the Parent on each SerilogLoggerScope.

However (and luckily so), my attempts to create a sample console app that proves loggers get 'mixed' scopes have failed miserably. Hence I am left with the question: "What keeps these scope stacks from intermingling?"

[bartelink]

See https://gitter.im/serilog/serilog - I suspect your question is exactly the sane as ThomasArdal's over there? (TL;DR ExecutionContext flows and LoggerContext hangs off that, then the logging grabs (serializes/destructures) the state from there when the logging happens)

[AroglDarthu]

Maybe... I did not drill into the code of Serilog itself. The link that I am missing is probably the one where a SerilogLoggerScope gets hooked up to the LogContext.

Just looking at the code of Serilog.Extensions.Logging that link truely escapes me. :-(

[nblumhardt]

Hi @AroglDarthu - the magic is in AsyncLocal<T>:

https://github.com/serilog/serilog-extensions-logging/blob/c5bad0c183ae10d448fcc3532095e298d57906a1/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerProvider.cs#L88

There's a bit of info in: https://docs.microsoft.com/en-us/dotnet/api/system.threading.asynclocal-1?view=netframework-4.8

HTH!

[daiplusplus]

• Are there any cases where AsyncLocal<T> will fail to correctly capture the logging context?

• What if an async task kicks-off a new thread (or uses a thread-pool) that then finishes and that new thread carries its own async execution context and completes on another thread?

• How expensive is AsyncLocal<T> in Serilog?

[bartelink]

There's a decent article out there on the ExecutionContext - this mechanism is a core par of the standard .NET runtime plumbing - lots of stuff would break if it wasn't threaded through correctly. When a Task hops threads etc, the context is explicitly transferred. With regard to efficiency, by definition the specific structure [for a given thread] can only have a single accessor at a time so it's pretty likely to be easy to make efficient. If you peek around the Serilog repo, you'll see lots of emphasis on perf scenarios, so TL;DR it's plenty fast and is not something to worry about using ;)

[sungam3r]

Are there any cases where AsyncLocal will fail to correctly capture the logging context?

There is some special API for "clearing" async context. Sometimes it is useful.