Using multiple DbCommandInterceptor doesn't play nice in AsyncLocal

[ajcvickers]

Moved from discussion #22749

Question

From @srprash

Hi,
I have a sample ASPNetCore webapp which uses EFCore to add or retrieve users to a postgres db. In addition to this, I'm using AWS X-Ray .Net SDK to trace these operations by adding the EFInterceptor along with a custom empty MyDbCommandInterceptor. I'm using the empty interceptor for simplicity. The issue happens with any interceptor used with the EFInterceptor.
The AWS X-Ray SDK uses AsyncLocal to store the trace context of the app. When I use just use one of the interceptors, everything works fine. However, when both the interceptors are used together, the trace context gets messed up and becomes inconsistent across threads for async calls involving ExecuteReaderAsync. The interceptors work fine together for any synchronous operation to the db.

I've opened a related issue on X-Ray SDK's repo with more details pertaining to the error on the SDK but while digging into the cause of the problem, I established that the issue is with AsyncLocal not being consistent for threads invoking ReaderExecutingAsync and ReaderExecutedAsync methods before and after an async call to my postgres db.
I wonder if using multiple DbCommandInterceptors has an impact on separate threads and their thread local storage. Also, ReaderExecutingAsync and ReaderExecutedAsync methods seem to execute on different threads. Is there a way to ensure they run on same thread or to propagate a context between these methods?

I'm hoping to get some direction from this discussion to investigate the problem further and resolve it. Any help is greatly appreciated :)

Replies

From @roji

@srprash can you please submit a minimal console app which demonstrates to inconsistency with? AFAIK the interceptors shouldn't be interfering with AsyncLocal in any way.

(Note that this isn't about thread-local storage, which does not persist across asynchronous operations since those don't necessarily continue on the same thread where they began. This is why AsyncLocal is needed).

[ajcvickers]

EF Team Triage: Closing this issue as the requested additional details have not been provided and we have been unable to reproduce it.

BTW this is a canned response and may have info or details that do not directly apply to this particular issue. While we'd like to spend the time to uniquely address every incoming issue, we get a lot traffic on the EF projects and that is not practical. To ensure we maximize the time we have to work on fixing bugs, implementing new features, etc. we use canned responses for common triage decisions.

[srprash]

Hi @ajcvickers ,
Sorry for the delayed response. Got pulled away into some other stuff. I have uploaded a much simpler repro code here. I couldn't do a console app since this app represents my use case more closely.
This application uses EFCore to make db calls to a postgres db, and illustrates the issue with AsyncLocal on using multiple DbCommandInterceptor in the call chain. You can find more details about the problem and the steps to reproduce in the readme.
As you can see I'm not using any AWS X-Ray related logic here but still running into the issue where AsyncLocal doesn't maintain context (which I expect it to in the async scenarios) when there are more than one DbCommandInterceptor involved.
Please take a look and feel free to ask any questions.

Thanks!

[srprash]

Seems like I cannot reopen this issue. @ajcvickers Would you mind reopening it since its still an ongoing investigation? Thanks.

[ajcvickers]

@AndriySvyryd @roji This repros for me, but I don't know what is happening. I'm guessing the sync context is getting lost here, but I don't know how or why.

[AndriySvyryd]

@srprash AsyncLocal is only guaranteed to be passed down into called methods, not up. Every time the code yields or forks a copy of AsyncLocal is created and passed to the subsequent calls. However in some cases (such as when there's only one interceptor that doesn't perform any async calls) the async method execution is optimized and the same instance of AsyncLocal is used, but this behavior cannot be relied upon. You can see some more examples in this blog post.

[roji]

I just had a race condition with @AndriySvyryd :)

However in some cases (such as when there's only one interceptor that doesn't perform any async calls) the async method execution is optimized and the same instance of AsyncLocal is used, but this behavior cannot be relied upon.

As far as I can tell this is actually simpler: when there's just one interceptor, there's no async state machine anywhere, since there's no async/await keywords; it's simple, synchronous code. Once you have two interceptors, you get a DbCommandInterceptorAggregator which does async/await. And as @AndriySvyryd wrote above, the ExecutionContext (which AsyncLocal relies on) only flows down, not up. You can produce the same effect with a single interceptor by adding the async keyword on the the interceptor's ReaderExecutingAsync method signature.

Here's a minimal code sample that shows what's going on:

class Program
{
    public static async Task Main()
    {
        AsyncLocal.Value = "First value";

        await Async(); // With this, "First value" is printed
        // await NonAsync();  // With this, "Second value" is printed

        Console.WriteLine(AsyncLocal.Value);
    }

    static async Task Async()
    {
        AsyncLocal.Value = "Second value";
    }

    static Task NonAsync()
    {
        AsyncLocal.Value = "Second value";
        return Task.CompletedTask;
    }

    public static AsyncLocal<string> AsyncLocal = new AsyncLocal<string>();
}

[ajcvickers]

TIL something else I didn't know about .NET async. Over the years, async has been a very fruitful source of learning experiences.

[roji]

async has been a very fruitful source of learning experiences

I may have an idea of the original sentence that got euphemized into this 🤣

[srprash]

Hi @roji @AndriySvyryd
Thanks for providing an insight into the root cause of the issue. It's a great learning for me. As far as I understood, the ReaderExecutedAsync method is called after the ReaderExecutingAsync and would therefore have the AsyncLocal storage context from the ReaderExecutingAsync method of the interceptor. But (correct me if I'm wrong), what happens is that the AsyncLocal is already forked for these two methods before invocation and is not passed downstream?

Is there a way to ensure AsyncLocal storage is synced with the context in ReaderExecutingAsync before it enters ReaderExecutedAsync?

[srprash]

Hi @roji @AndriySvyryd
Still looking for some guidance on this. Thanks in advance.

[AndriySvyryd]

@srprash You can add things to AsyncLocal beforehand and have them available in both methods. But there is no reliable way of passing data from ReaderExecutingAsync to ReaderExecutedAsync using AsyncLocal