Issues with AsyncLocal<T> and ASP.NET on .NET 4.6.2

[jdaigle]

Framework version 4.6.2

For certain HTTP requests anything set to an AsyncLocal<T> variable in Application_BeginRequest() is null by the time any part of the MVC5 pipeline invokes (action filters, controllers, etc). Further, the value is still null at Application_EndRequest(). On my computer, this is easily reproducible from an empty ASP.NET project using an HTTP POST with a relatively large content body, 14KB or so).

I know this isn't exactly an issue with MiniProfiler, but maybe it is now that MiniProfiler uses AsyncLocal<T>.

For example, IDbProfiler.ExecuteFinish() may throw a null reference exception the timing object added to the dictionary in IDbProfiler.ExecuteStart() is null (because it tries to access Head via AsyncLocal<> which is sometimes null).

Side note: how would you even go about reporting this type of .NET bug (if it is a bug)? Maybe we can't rely on AsyncLocal in ASP.NET (not Core)?.

[jdaigle]

An update: https://stackoverflow.com/questions/43391498/asynclocal-value-is-null-after-being-set

The same behavior is observed using CallContext.LogicalGetData/CallContext.LogicalSetData.

Looking through the commit history, I'm not fully clear as to why MiniProfiler.Head needs to be implemented using AsyncLocal versus just a regular instance variable? It seems that the "current" MiniProfiler instance already flows correctly (using AsyncLocal for DefaultProfilerProvider, and HttpContext.Current.Items for WebRequestProfilerProvider).

Maybe we need a way to override the behavior of MiniProfiler.Head when it's running in the context of ASP.NET (not Core)?

[NickCraver]

The head must be async flow aware because the position of the head is relative to where in the code flow it is. For example, if you start a timing in an async flow, the head for that flow differs from the parent position it should be in outside the flow (or any other flows). Without this awareness, you'll see all threads fighting for the same head, and none will be correct.

I haven't had time to dig in here yet, lots happening...I'll try to analyze further soon.

[jdaigle]

@NickCraver thanks - at this point I know it's not a bug in MiniProfiler (although perhaps there are a few places we could better check for null references like in ExecuteStart).

[jdaigle]

So far, some of my research as lead me to believe that setting something via AsyncLocal or logical CallContext is not safe from Application_BeginRequest() or any of the ASP.NET pipeline events because the ExecutionContext doesn't flow between the worker threads executing these events. Small/short requests may execute the handler from the same thread that executed Application_BeginRequest(), but larger/long requests may not.

Is it possibly correct to say that MiniProfiler.Head should never be null for the current/active profiler (outside of deserialization)? As a workaround, could it be as simple as having .Head null-coalesce to .Root?

[jdaigle]

Another possible solution: modify MiniProfiler WebRequestProfilerProvider.Current { get; } so that before returning it checks if .Head is null, and if so sets it to the value of .Root.

But I guess technically .Head could be null once the .Root timing is stopped (since Stop() sets .Head to the timing's ParentTiming which for the root is null) - but I think practically that should only happen when the MiniProfiler.Stop() is called.

[NickCraver]

Can you post the web.config for the app which has the issue? I'm just getting into this, and it seems like the synchronization context is off here, like it's not targeting 4.5+. A web.config would help out here.

[jdaigle]

@NickCraver Here's an entire minimal reproduction: https://github.com/jdaigle/AsyncLocalBug (there's a simple IHttpHandler inside of Global.asax.cs).

From what I can tell, it's actually the ExecutionContext at fault here. Specifically the fact that it does not automatically flow between ASP.NET pipeline events (e.g. BeginRequest, the handler, EndRequest, etc.). And so if those events don't execute synchronously, then all of the data on the ExecutionContext is lost.

I've semi-confirmed this based on reading @davidfowl's comments towards the end of https://github.com/aspnet/AspNetKatana/issues/31. He even explicitly says "Don't use async locals when you're in System.Web...".

The easiest way I've been able to reproduce this is by POSTing a large-ish request (e.g. many 10s of KB).

[NickCraver]

Sorry @jdaigle it's hard to split time between this many projects - I'm not absolutely sure how to cleanly support both this scenario and async at the same time. Currently, if one were to step on landmine introduced by a null coalesce, I think the results would be even worse. For example, if a user used .ConfigureAwait(false) or .ContinueWith() or any other context-losing item, I think null is a much better result rather than a misprofiling. Knowing it broken is better than having a bad tree.

I don't think we need the null checks...I think we want to tackle this upsteam and ensure Head isn't null. I really appreciate the digging here, it's tremendously helpful. What do you think about tracking the last set head for restoration in this situation? I think this would cover the vast majority of cases hitting it, idea:

// Allows async to properly track the attachment point
private readonly FlowData<Timing> _head = new FlowData<Timing>();

// When async context flows aren't preserved, fallback to enable correct profiling in most cases
private Timing _lastSetHead;

/// <summary>
/// Gets or sets points to the currently executing Timing. 
/// </summary>
public Timing Head
{
    get => _head.Value ?? _lastSetHead;
    set => _head.Value = _lastSetHead = value;
}

Thoughts?

[NickCraver]

I pushed the proposed fix in a PR above ^

[jdaigle]

Hey @NickCraver, no worries. I know you do a lot more than many of us mortal software developers ;)

I like your idea. And I was already considering it before settling on what I submitted in my PR - my thinking was to try and isolate the messy behavior of ASP.NET away from the shared code. But you think this is cleaner, I'm on board.

[NickCraver]

New packages on NuGet for easier testing: 4.0.0-alpha6-79 across the board.

[jdaigle]

Tested and working.