Kestrel reset error when no reset received

[Tratcher]

RE: dotnet/runtime#55261

The following logs show kestrel throwing a The client reset the request stream. error when no reset frame was received for that stream. These tests started failing between between 6.0 Preview 4 and 6.0 Preview 6, but we don't have server logs from Preview 4 to confirm the prior behavior.

2021-07-27T17:28:48.0481734+02:00  [VRB] Connection id ""0HMAH2CT4I8BM"" received HEADERS frame for stream ID 1831 with length 26 and flags END_HEADERS. (965cec00)

2021-07-27T17:28:48.0482203+02:00  [VRB] Connection id ""0HMAH2CT4I8BM"" received DATA frame for stream ID 1831 with length 4270 and flags NONE. (965cec00)

2021-07-27T17:28:48.0482744+02:00 0HMAH2CT4I8BM:00000727 [INF] Request starting HTTP/2 POST https://localhost:5001/ - 4270 (ca22a1cb)
2021-07-27T17:28:48.0482962+02:00 0HMAH2CT4I8BM:00000727 [VRB] All hosts are allowed. (2e40afda)

2021-07-27T17:28:48.0483186+02:00  [VRB] Connection id ""0HMAH2CT4I8BM"" received DATA frame for stream ID 1831 with length 0 and flags END_STREAM. (965cec00)
2021-07-27T17:28:48.0483201+02:00 0HMAH2CT4I8BM:00000727 [DBG] 1 candidate(s) found for the request path '"/"' (9406aaa8)
2021-07-27T17:28:48.0483411+02:00 0HMAH2CT4I8BM:00000727 [DBG] Request matched endpoint '"/ HTTP: POST"' (cbf60c4b)
2021-07-27T17:28:48.0483583+02:00 0HMAH2CT4I8BM:00000727 [INF] Executing endpoint '"/ HTTP: POST"' (500cc934)

2021-07-27T17:28:48.0485281+02:00 0HMAH2CT4I8BM:00000727 [INF] Executed endpoint '"/ HTTP: POST"' (99874f2b)

2021-07-27T17:28:48.0486058+02:00 0HMAH2CT4I8BM:00000727 [ERR] Connection id ""0HMAH2CT4I8BM"", Request id ""0HMAH2CT4I8BM:00000727"": An unhandled exception was thrown by the application. (560e7d32)
System.IO.IOException: The client reset the request stream.
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpRequestPipeReader.ReadAsync(CancellationToken cancellationToken) in Microsoft.AspNetCore.Server.Kestrel.Core.dll:token 0x6000b2b+0x0
   at System.IO.Pipelines.PipeReader.CopyToAsyncCore[TStream](TStream destination, Func`4 writeAsync, CancellationToken cancellationToken) in System.IO.Pipelines.dll:token 0x60000b8+0x18
   at HttpStress.StressServer.<>c.<<MapRoutes>b__6_6>d.MoveNext() in c:\repos\runtime\src\libraries\System.Net.Http\tests\StressTests\HttpStress\StressServer.cs:line 262
--- End of stack trace from previous location ---
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger) in Microsoft.AspNetCore.Routing.dll:token 0x60000ab+0x5e
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application) in Microsoft.AspNetCore.Server.Kestrel.Core.dll:token 0x6000aa1+0x1b8
2021-07-27T17:28:48.0486522+02:00 0HMAH2CT4I8BM:00000727 [VRB] Connection id ""0HMAH2CT4I8BM"" sending HEADERS frame for stream ID 1831 with length 7 and flags END_STREAM, END_HEADERS. (5439505f)
2021-07-27T17:28:48.0487189+02:00 0HMAH2CT4I8BM:00000727 [INF] Request finished HTTP/2 POST https://localhost:5001/ - 4270 - 500 0 - 0.4368ms (791a596a)
2021-07-27T17:28:48.0487483+02:00  [DBG] Connection id ""0HMAH2CT4I8BM"", Request id ""0HMAH2CT4I8BM:00000727"": started reading request body. (55b8f554)
2021-07-27T17:28:48.0487667+02:00  [DBG] Connection id ""0HMAH2CT4I8BM"", Request id ""0HMAH2CT4I8BM:00000727"": done reading request body. (6feb3b06)

Theory: Kestrel is caching an exception in the HttpRequestPipeReader from a previously reset stream instance, the body control state is never cleared after aborted.

aspnetcore/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.cs

Line 503 in 8b30d86

_bodyControl?.Abort(abortReason);

However, caching this shouldn't be possible if CanReuse correctly guards against caching an aborted stream.

aspnetcore/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Stream.cs

Line 169 in 39912f8

CanReuse = !_connectionAborted && HasResponseCompleted;

There may be race conditions between the RESET_STREAM frame processing and the stream cleanup logic for caching streams.

[adityamandaleeka]

Commented on original issue: dotnet/runtime#55261 (comment)

[adityamandaleeka]

We have more signs pointing to this being a regression: dotnet/runtime#55261 (comment)

@adityamandaleeka I ran these POST tests on .NET Core: 5.0.8, ASP.NET Core: 5.0.8 and they completed successfully. I have not got any errors.

I tested with HttpClient [6.0.0-preview.6.21352.12] and Asp.Net Core [5.0.8]. All runs completed successfully. No failures.

Let's investigate this soon.

[adityamandaleeka]

@sebastienros Can you please take a look at this? The repro is here: dotnet/runtime#55261 (comment)

[sebastienros]

I was able to repro (concurrent canceled POSTs with a body of 1 byte or more) and then used crank to isolate which change introduced the bug.

I isolated it to this commit exactly:

9d2825e...c245920

[alnikola]

@sebastienros @adityamandaleeka Since the root cause has been found, is there any ETA for a fix to be applied? Once it's applied, we'll reenable the test.

[adityamandaleeka]

@alnikola Sorry, missed your question earlier. We are still aiming to get a fix into RC1 if we can.