Phantom response being issued by custom middleware

[Leonardo-Ferreira]

Describe the bug

My custom timeout middleware is responding with data from another, already "dead", response.

To Reproduce

This custom Middleware:

public class TimeoutMiddleware
{
    private readonly RequestDelegate _next;

    public TimeoutMiddleware(RequestDelegate next)
    {
        _next = next;
    }

    public async Task InvokeAsync(HttpContext httpContext)
    {
        using (var timeoutTS = CancellationTokenSource.CreateLinkedTokenSource(httpContext.RequestAborted))
        {
            var delayTask = Task.Delay(500);

            var res = await Task.WhenAny(delayTask, _next(httpContext));
            if (res == delayTask)
            {
                timeoutTS.Cancel();
                httpContext.Response.StatusCode = 408;
            }
        }
    }
}

And this controller

[HttpGet]
public async Task<string> Get(string timeout)
{
    var result = DateTime.Now.ToString("mm:ss.fff");
    if (timeout != null)
    {
        await Task.Delay(2000);
    }
    var rng = new Random();
    result = result + " - " + DateTime.Now.ToString("mm:ss.fff");
    return result;
}

And just use fiddler to spam a dozen requests and you will see that the first ones will return 408 (as expected) but soon you will start to see a bunch of 200s. When you inspect the time on the body, you will see that the time reported is far BEHIND the request start time

Exceptions (if any)

"Response has already started" but that's not important

Further technical details

• ASP.NET Core version: .Net 5 and 3.1
• Include the output of dotnet --info:

.NET SDK (reflecting any global.json):
Version: 5.0.201
Commit: a09bd5c86c

Runtime Environment:
OS Name: Mac OS X
OS Version: 11.0
OS Platform: Darwin
RID: osx.11.0-x64
Base Path: /usr/local/share/dotnet/sdk/5.0.201/

Host (useful for support):
Version: 5.0.4
Commit: f27d337295

.NET SDKs installed:
2.1.202 [/usr/local/share/dotnet/sdk]
2.1.802 [/usr/local/share/dotnet/sdk]
2.2.207 [/usr/local/share/dotnet/sdk]
3.0.100 [/usr/local/share/dotnet/sdk]
3.1.100-preview2-014569 [/usr/local/share/dotnet/sdk]
3.1.100-preview3-014645 [/usr/local/share/dotnet/sdk]
3.1.100 [/usr/local/share/dotnet/sdk]
3.1.101 [/usr/local/share/dotnet/sdk]
3.1.102 [/usr/local/share/dotnet/sdk]
3.1.200 [/usr/local/share/dotnet/sdk]
3.1.202 [/usr/local/share/dotnet/sdk]
3.1.300 [/usr/local/share/dotnet/sdk]
3.1.301 [/usr/local/share/dotnet/sdk]
3.1.302 [/usr/local/share/dotnet/sdk]
3.1.401 [/usr/local/share/dotnet/sdk]
3.1.402 [/usr/local/share/dotnet/sdk]
3.1.403 [/usr/local/share/dotnet/sdk]
3.1.404 [/usr/local/share/dotnet/sdk]
3.1.405 [/usr/local/share/dotnet/sdk]
3.1.406 [/usr/local/share/dotnet/sdk]
3.1.407 [/usr/local/share/dotnet/sdk]
5.0.100 [/usr/local/share/dotnet/sdk]
5.0.101 [/usr/local/share/dotnet/sdk]
5.0.102 [/usr/local/share/dotnet/sdk]
5.0.103 [/usr/local/share/dotnet/sdk]
5.0.201 [/usr/local/share/dotnet/sdk]

.NET runtimes installed:
Microsoft.AspNetCore.All 2.1.13 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.All]
Microsoft.AspNetCore.All 2.2.8 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.All]
Microsoft.AspNetCore.App 2.1.13 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 2.2.8 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 3.0.0 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 3.1.0-preview2.19528.8 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 3.1.0-preview3.19555.2 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 3.1.0 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 3.1.1 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 3.1.2 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 3.1.4 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 3.1.5 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 3.1.6 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 3.1.7 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 3.1.8 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 3.1.9 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 3.1.10 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 3.1.11 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 3.1.12 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 3.1.13 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 5.0.0 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 5.0.1 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 5.0.2 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 5.0.3 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 5.0.4 [/usr/local/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.NETCore.App 2.0.9 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 2.1.13 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 2.1.14 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 2.1.15 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 2.1.16 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 2.1.17 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 2.1.18 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 2.1.19 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 2.1.20 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 2.1.21 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 2.1.22 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 2.1.23 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 2.2.8 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 3.0.0 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 3.1.0-preview2.19525.6 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 3.1.0-preview3.19553.2 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 3.1.0 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 3.1.1 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 3.1.2 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 3.1.4 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 3.1.5 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 3.1.6 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 3.1.7 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 3.1.8 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 3.1.9 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 3.1.10 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 3.1.11 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 3.1.12 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 3.1.13 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 5.0.0 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 5.0.1 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 5.0.2 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 5.0.3 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 5.0.4 [/usr/local/share/dotnet/shared/Microsoft.NETCore.App]

• The IDE (VS / VS Code/ VS4Mac) you're running on, and its version
  Visual Studio for Mac, version 8.9.2 (build 0) (yeah the build number is ZERO, really weird)

[Tratcher]

This is an extremely unsafe pattern. If your timeout fires then _next is still running when InvokeAsync ends, which can cause the MVC controller to write to a stale HttpContext that might get recycled for the next request. Also, HttpContext is not thread safe, you must not access it from multiple threads concurrently.

If you call _next then you must wait for it to finish. I don't think it's possible to correctly write a middleware that does early termination like this.

[Leonardo-Ferreira]

HttpContext that might get recycled for the next request

yeah, that seems to be whats going on over here... this is really unfortunate... I mean, I was OK with the idea of the _next possibly running forever, after all, it already does, I was just hoping to be able to get a response back to my users on more reliable fashion...

the real implementation of this middleware is much more complex and performs quite beautifully... it allows for you to choose which kind of timeout you want: cooperative or strict (strict being the one I'm demonstrating here)

is there a way to check if im getting a new instance or a recycled one? perhaps I can work something out of that...

[davidfowl]

Strict mode is broken, cooperative is the only mode that is reliable.

[davidfowl]

BTW the above code has a mini-timer leak, you can see the bad and good pattern here https://github.com/davidfowl/AspNetCoreDiagnosticScenarios/blob/a87d6b804d8924e8487f3bf79f37fe9973049649/Scenarios/Infrastructure/TaskExtensions.cs#L48-L89

[Leonardo-Ferreira]

Cooperative mode works as well as your developers skills... a have a bunch here that has no idea what a CancellationToken is...

Ps: tks for the timer leak tip!

[davidfowl]

Thinking outside of the box here a minute, I can think of one way to implement this safely but it's expensive and not pay for play. You'd need to stub out the HttpContext and either:

• Synchronize access to the properties
• Copy the state into a new HttpContext

That would let you implement strict mode safely.

[Leonardo-Ferreira]

@davidfowl If I were able to spawn a HttpContext per request, I wouldn't need to worry about thread safety. This would hamper giga escale applications due to memory consumption and garbage collection, but that is not my reality here...

[davidfowl]

If that were a concern then you could pool them 😄.

[Leonardo-Ferreira]

@davidfowl for the first time now im getting acquainted with the Asp Net Core code, and its 1:20am here... ill try to cook something up on the lines of copying the state of the original... and by the way, what do you mean "it's not pay for play"?

[davidfowl]

ill try to cook something up on the lines of copying the state of the original... and by the way, what do you mean "it's not pay for play"?

You'd be paying the cost of wrapping the HttpContext for every request even if no timeout occurred. It's something you end up doing ahead of time just in case it times out and every request ends up being penalized as a result.

[Leonardo-Ferreira]

what if I could mark the instance which timed-out?

check this out: httpContext.Abort() does the job in a very messy way.

If I could register this "corrupted" instance for Abort() as soon as the request at hand concludes, its all good!
I could spawn a helper Task and simply use a ConcurrentQueue<HttpContext>... the task would pool on the queue, and whenever it found something there, check if there's a active (httpContext.RequestAborted) request for that context, if not, Abort and Dispose

[davidfowl]

I don't think that works but I'd be fine reviewing the implementation. Also Abort will abort the entire connection, I'm not sure if you want to do that in this case?

[Leonardo-Ferreira]

by using

timeoutTS.Cancel();
httpContext.Response.StatusCode = 408;
httpContext.Response.OnCompleted(() => { return Task.Factory.StartNew(()=> { httpContext.Abort(); }); });

I managed to replace the phantom responses with 504s... not ideal but an evolution

and yes, Abort does closes the connection (which is not terrible) but it does not kill the actual httpContext

[davidfowl]

You can't set the response. That's already a race condition. You can abort though.