Problem with a different number of Activate and Dispose calls in async methods

[Chakrygin]

Hi!

We have encountered the following OpenTracing usage scenario (pseudo code):

async Task PrepareAsync() {
    Start "Prepare + Execute" Span
    Start "Prepare" Span
    Prepare Action
    Finish "Prepare" Span
}

async Task ExecuteAsync() {
    Start "Execute" Span
    Execute Action
    Finish "Execute" Span
    Finish "Prepare + Execute" Span
}

Start "Root" Span
await PrepareAsync();
await ExecuteAsync();
Finish "Root" Span

I expected that after performing the await PrepareAsync method, the Prepare + Execute span would be active as it was not finished.

But the active span is Root

Apparently this is due to the classes AsyncLocalScopeManager and AsyncLocalScope.

This test (for class AsyncLocalScopeManagerTests) shows the problem:

[Fact]
public async Task ActivateAndDisposeInAsyncMethod()
{
    ISpan rootSpan = Substitute.For<ISpan>();
    ISpan prepareSpan = Substitute.For<ISpan>();
    ISpan executeSpan = Substitute.For<ISpan>();
    ISpan prepareAndExecuteSpan = Substitute.For<ISpan>();
    Task completedTask = Task.FromResult(0);

    _source.Activate(rootSpan, finishSpanOnDispose: true);

    async Task PrepareAsync()
    {
        _source.Activate(prepareAndExecuteSpan, finishSpanOnDispose: true);

        _source.Activate(prepareSpan, finishSpanOnDispose: true);
        await completedTask; // some action
        _source.Active.Dispose(); // Disposing "prepare" span.

        Assert.Same(prepareAndExecuteSpan, _source.Active.Span);
    }

    async Task ExecuteAsync()
    {
        Assert.Same(prepareAndExecuteSpan, _source.Active.Span); // FAILED

        _source.Activate(executeSpan, finishSpanOnDispose: true);
        await completedTask; // some action
        _source.Active.Dispose(); // Disposing "execute" span.

        Assert.Same(prepareAndExecuteSpan, _source.Active.Span);

        _source.Active.Dispose(); // Disposing "prepareAndExecute" span.

        Assert.Same(rootSpan, _source.Active.Span);
    }

    await PrepareAsync();
    await ExecuteAsync();

    Assert.Same(rootSpan, _source.Active.Span);
}

I tried to modify the class AsyncLocalScopeManager and change AsyncLocal<IScope> to AsyncLocal<Stack<IScope>> with Push, Pop and Peak calls, but it breaks the tests MultipleCallbacksTest and NestedCallbacksTest in OpenTracing.Examples project.

Tell me, please, is it possible to implement such a scenario (and is it possible)?

[austinlparker]

Hey, thanks for opening the issue. If I'm reading this right, your use case is to start a span in one async method, then finish it in a different async method? I think you'd need to manually pass the span context around in that case rather than using the scope manager. Alternately, the following pseudo-code should work I'd imagine -

async Task Prepare() {
    using (prepareScope = tracer.BuildSpan("prepareAndExecute"))
    {
        DoPrepare()
        await Execute()
    }
}

async Task Execute() {
    using (executeScope = tracer.BuildSpan("execute"))
    {
        DoExecute()
    }
}

using (scope = tracer.BuildSpan("root"))
{
    await PrepareAndExecute();
}

[Chakrygin]

Unfortunately, we use DiagnosticSource similar to this and cannot explicitly create a root span: https://github.com/opentracing-contrib/csharp-netcore/blob/master/src/OpenTracing.Contrib.NetCore/EntityFrameworkCore/EntityFrameworkCoreDiagnostics.cs#L32

We tried to make spans similar to this:

Start "Query" span
    Start "Open Connection" span
        ...
    Finish "Open Connection" span

    Start "Execute Command" span
        ...
    Finish "Execute Command" span

    Start "Execute Command" span
        ...
    Finish "Execute Command" span
Finish "Query" span

[austinlparker]

The last thing you posted should work, but it's hard to say without real code. There's a couple of options as I see it.

1. The default AsyncLocalScopeManager is going to use AsyncLocal Thread Storage to automatically set the scope on each thread (thus each async method will get its own scope and span, that's why your example fails). You could implement a different scope manager (using the IScopeManager interface) that would allow you more control over the active scope at any given time and pass that scope manager in to your tracer.

2. Rather than using scopes, use manual span passing (this is how things work in Golang for example) to your child functions so that you can be more confident about when they're being executed.

Is that helpful?

[Chakrygin]

Thank you, manual span passing does not suit us. Maybe, we will try to use own IScopeManager.