Trace.CorrelationManager.LogicalOperationStack
enables having nested logical operation identifiers where the most common case is logging (NDC). Should it still work with async-await
?
Here's a simple example using LogicalFlow
which is my simple wrapper over the LogicalOperationStack
:
private static void Main() => OuterOperationAsync().GetAwaiter().GetResult();
private static async Task OuterOperationAsync()
{
Console.WriteLine(LogicalFlow.CurrentOperationId);
using (LogicalFlow.StartScope())
{
Console.WriteLine("\t" + LogicalFlow.CurrentOperationId);
await InnerOperationAsync();
Console.WriteLine("\t" + LogicalFlow.CurrentOperationId);
await InnerOperationAsync();
Console.WriteLine("\t" + LogicalFlow.CurrentOperationId);
}
Console.WriteLine(LogicalFlow.CurrentOperationId);
}
private static async Task InnerOperationAsync()
{
using (LogicalFlow.StartScope())
{
await Task.Delay(100);
}
}
LogicalFlow
:
public static class LogicalFlow
{
public static Guid CurrentOperationId =>
Trace.CorrelationManager.LogicalOperationStack.Count > 0
? (Guid) Trace.CorrelationManager.LogicalOperationStack.Peek()
: Guid.Empty;
public static IDisposable StartScope()
{
Trace.CorrelationManager.StartLogicalOperation();
return new Stopper();
}
private static void StopScope() =>
Trace.CorrelationManager.StopLogicalOperation();
private class Stopper : IDisposable
{
private bool _isDisposed;
public void Dispose()
{
if (!_isDisposed)
{
StopScope();
_isDisposed = true;
}
}
}
}
Output:
00000000-0000-0000-0000-000000000000
49985135-1e39-404c-834a-9f12026d9b65
54674452-e1c5-4b1b-91ed-6bd6ea725b98
c6ec00fd-bff8-4bde-bf70-e073b6714ae5
54674452-e1c5-4b1b-91ed-6bd6ea725b98
The specific values don't really matter, but as I understand it both the outer lines should show Guid.Empty
(i.e. 00000000-0000-0000-0000-000000000000
) and the inner lines should show the same Guid
value.
You might say that LogicalOperationStack
is using a Stack
which is not thread-safe and that's why the output is wrong. But while that's true in general, in this case there's never more than a single thread accessing the LogicalOperationStack
at the same time (every async
operation is awaited when called and no use of combinators such as Task.WhenAll
)
The issue is that LogicalOperationStack
is stored in the CallContext
which has a copy-on-write behavior. That means that as long as you don't explicitly set something in the CallContext
(and you don't when you add to an existing stack with StartLogicalOperation
) you're using the parent context and not your own.
This can be shown by simply setting anything into the CallContext
before adding to the existing stack. For example if we changed StartScope
to this:
public static IDisposable StartScope()
{
CallContext.LogicalSetData("Bar", "Arnon");
Trace.CorrelationManager.StartLogicalOperation();
return new Stopper();
}
The output is:
00000000-0000-0000-0000-000000000000
fdc22318-53ef-4ae5-83ff-6c3e3864e37a
fdc22318-53ef-4ae5-83ff-6c3e3864e37a
fdc22318-53ef-4ae5-83ff-6c3e3864e37a
00000000-0000-0000-0000-000000000000
Note: I'm not suggesting anyone actually do this. The real practical solution would be to use an ImmutableStack
instead of the LogicalOperationStack
as it's both thread-safe and since it's immutable when you call Pop
you get back a new ImmutableStack
that you then need to set back into the CallContext
. A full implementation is available as an answer to this question: Tracking c#/.NET tasks flow
So, should LogicalOperationStack
work with async
and it's just a bug? Is LogicalOperationStack
just not meant for the async
world? Or am I missing something?
Update: Using Task.Delay
is apparently confusing as it uses System.Threading.Timer
which captures the ExecutionContext
internally. Using await Task.Yield();
instead of await Task.Delay(100);
makes the example easier to understand.
async-await
but about a bug that was already fixed.await Task.Delay(100)
withTask.Delay(100).Wait()
?