Kestrelhttpserver: Improve error message for drain timeout instead of "BadHttpRequestException - Request timed out" With Large Requests

[andrewbull99]

We are encountering a problem with Kestrel timeouts when making large requests to a .NET Core API. The requests are being redirected (for authentication purposes) but redirecting large requests seems to cause Kestrel to choke. It's fine with smaller requests, but anything over a couple of hundred MB seems to trigger the timeout. I think this relates to the message body draining functionality. Apparently it can sometimes abandon draining the request body and send a keep-alive response without an exception and sometimes it throws due to timeout.

The exception looks like this:

2018-02-28 10:12:58.8406 [9][KestrelTrace.ConnectionStart] DEBUG: Connection id "0HLBUQL57F3CA" started. 
2018-02-28 10:12:58.8506 [19][HostingApplicationDiagnostics.LogRequestStarting] INFO: Request starting HTTP/1.1 POST http\://localhost:5000/api/values/upload  873690784 
2018-02-28 10:12:58.8506 [19][TreeRouterLoggerExtensions.MatchedRoute] DEBUG: Request successfully matched the route with name '(null)' and template 'api/Values/upload'. 
2018-02-28 10:12:58.8836 [19][MvcCoreLoggerExtensions.ExecutingAction] DEBUG: Executing action WebApplication1.Controllers.ValuesController.Post (WebApplication1) 
2018-02-28 10:12:58.9036 [19][MvcCoreLoggerExtensions.ActionMethodExecuting] INFO: Executing action method WebApplication1.Controllers.ValuesController.Post (WebApplication1) with arguments ((null)) - ModelState is Valid 
2018-02-28 10:12:58.9346 [19][MvcCoreLoggerExtensions.ActionMethodExecuted] DEBUG: Executed action method WebApplication1.Controllers.ValuesController.Post (WebApplication1), returned result Microsoft.AspNetCore.Mvc.EmptyResult. 
2018-02-28 10:12:58.9656 [19][MvcCoreLoggerExtensions.ExecutedAction] INFO: Executed action WebApplication1.Controllers.ValuesController.Post (WebApplication1) in 62.7726ms 
2018-02-28 10:12:58.9816 [19][KestrelTrace.RequestBodyStart] DEBUG: Connection id "0HLBUQL57F3CA", Request id "0HLBUQL57F3CA:00000001": started reading request body. 
2018-02-28 10:13:05.3562 [17][KestrelTrace.ConnectionBadRequest] INFO: Connection id "0HLBUQL57F3CA" bad request data: "Request timed out." Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException Request timed out.
2018-02-28 10:13:05.3562 [5][KestrelTrace.RequestBodyDone] DEBUG: Connection id "0HLBUQL57F3CA", Request id "0HLBUQL57F3CA:00000001": done reading request body. 
2018-02-28 10:13:05.3562 [20][KestrelTrace.ConnectionBadRequest] INFO: Connection id "0HLBUQL57F3CA" bad request data: "Request timed out." Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException Request timed out. Void ThrowFailed()    at Microsoft.AspNetCore.Server.Kestrel.Internal.System.IO.Pipelines.PipeCompletion.ThrowFailed()
   at Microsoft.AspNetCore.Server.Kestrel.Internal.System.IO.Pipelines.Pipe.GetResult(ReadResult& result)
   at Microsoft.AspNetCore.Server.Kestrel.Internal.System.IO.Pipelines.Pipe.Microsoft.AspNetCore.Server.Kestrel.Internal.System.IO.Pipelines.IReadableBufferAwaiter.GetResult()
   at Microsoft.AspNetCore.Server.Kestrel.Internal.System.IO.Pipelines.ReadableBufferAwaitable.GetResult()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.MessageBody.d__24.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Frame`1.d__2.MoveNext()
2018-02-28 10:13:05.3872 [9][LibuvTrace.ConnectionPause] DEBUG: Connection id "0HLBUQL57F3CA" paused. 
2018-02-28 10:13:05.3872 [20][HostingApplicationDiagnostics.LogRequestFinished] INFO: Request finished in 6539.707ms 408  
2018-02-28 10:13:05.3872 [20][KestrelTrace.ConnectionDisconnect] DEBUG: Connection id "0HLBUQL57F3CA" disconnecting. 
2018-02-28 10:13:05.4092 [17][KestrelTrace.ConnectionStop] DEBUG: Connection id "0HLBUQL57F3CA" stopped. 
2018-02-28 10:13:05.4092 [9][LibuvTrace.ConnectionWriteFin] DEBUG: Connection id "0HLBUQL57F3CA" sending FIN. 

This seems to happen much more often when running behind IIS, though I can also get it to happen when running with Kestrel directly.

Fiddler seems to affect it. Sometimes it prevents the issue occurring, which is perhaps not surprising as Fiddler is buffering the request.

I've created an example solution which seems to trigger the issue quite reliably when running behind IIS. I've been using files of around 800MB.

Our actual code is using a multi-part request which seems to trigger the issue even when running against Kestrel directly. For simplicity I've not implemented multi-part requests in the repro solution. I can do if you think it would be useful.

We're running this on Windows and using Core 2.05. Updating to 2.1.0-preview1-final does not seem to help.

[justinwyer]

@andrewbull99 if you could also provide the multipart example that would be great too. I'll try to reproduce myself on Windows, OS X and Linux.

[andrewbull99]

I've added a multi-part request example solution. I'm using a two files (one 50ish MB, the other 800 MB) and running this I can make it timeout every time when running directly against Kestrel.

You can also achieve the same thing by just using Curl:

curl -F 'file1=@PathToLargeFile1' -F 'file2=@PathToLargeFile2' http://localhost:5000/api/values/upload 

[justinwyer]

Thanks @andrewbull99 I will put together a test for this and then start working on a fix.

[davidfowl]

@justinwyer 👍

[muratg]

@JunTaoLuo Could you also take a look?

[muratg]

@justinwyer Do you have any interesting findings so far? Thanks for looking into it!

[justinwyer]

@muratg I though I had something but my MaxRequestBodySize wasn't taking. With a unit test I've done a 3GB multipart request no problems.

[justinwyer]

@JunTaoLuo take a look at the test here https://github.com/aspnet/KestrelHttpServer/compare/dev...justinwyer:2353-large-requests-timeout

[justinwyer]

@JunTaoLuo so the error is occuring in Http1MessageBody.cs:93

else if (result.IsCompleted)
{                        
    BadHttpRequestException.Throw(RequestRejectionReason.UnexpectedEndOfRequestContent);
}

Any idea why we do this check and throw?
/cc @davidfowl

[JunTaoLuo]

Usually, the error is produced when the request body is being sent too slowly and the MinRequestBodyDataRate of 240 bytes/s is not met. However, in this case, the issue is that the repro does not consume the body of the request and a default timeout of 5 seconds for reading the request was exceeded. This is by design.

I have been able to resolve the exception by changing the method signature to public void PostAsync([FromBody] string content). Note that you may need to configure the MultipartBodyLengthLimit to accommodate the size of the upload.

The only work item here will be to update the error message to be more descriptive, indicating that the RequestBodyDrainTimeout of 5 seconds was exceeded.

[andrewbull99]

I don't think the intent of the 5 second RequestBodyDrainTimeout is for Kestrel to error if the timeout is exceeded, is it? I thought it was intended to limit the latency of requests to Kestrel, while still allowing validation of the request body. @halter73, can you comment here? Some of your previous comments touch on this.

I don't think using the FromBody attribute is a viable work-around for large requests, as it will pull the entire request body into memory, wont it?

[andrewbull99]

I'm not very familiar with the Kestrel code, so this could be way off, but...

I think we're seeing two different issues at work here.

In the dev branch, I'm seeing the same error as @justinwyer, where the code is encountering an unexpected end of request in the PumpAsync method of Http1MessageBody. In my testing, this seems to happen with pretty much any file (even down to 1kb), so long as the request is a multi-part request. From the logs, what seems to be happening is that the server is receiving a FIN and is closing the connection while the PumpAsync method of Http1MessageBody is still trying to read from it.

2018-03-08 14:09:11.5912 [8][HostingApplicationDiagnostics.LogRequestStarting] INFO: Request starting HTTP/1.1 POST http://localhost:5000/api/values/upload multipart/form-data; boundary=------------------------a88ee47a5fd533d3 51663404 
2018-03-08 14:09:11.8142 [8][TreeRouterLoggerExtensions.MatchedRoute] DEBUG: Request successfully matched the route with name '(null)' and template 'api/Values/upload'. 
2018-03-08 14:09:11.9072 [8][ResourceInvoker.InvokeAsync] DEBUG: Executing action WebApplication1.Controllers.ValuesController.Post (WebApplication1) 
..removed MVC stuff for brevity...
2018-03-08 14:09:12.1982 [8][KestrelTrace.ConnectionKeepAlive(KestrelTrace.cs:109)] DEBUG: Connection id "0HLC584SAV4J3" completed keep alive response. 
2018-03-08 14:09:12.1982 [18][LibuvTrace.ConnectionReadFin(LibuvTrace.cs:53)] DEBUG: Connection id "0HLC584SAV4J3" received FIN. 
2018-03-08 14:09:12.2072 [8][KestrelTrace.RequestBodyStart(KestrelTrace.cs:164)] DEBUG: Connection id "0HLC584SAV4J3", Request id "0HLC584SAV4J3:00000001": started reading request body. 
2018-03-08 14:09:12.2072 [12][KestrelTrace.ConnectionDisconnect(KestrelTrace.cs:119)] DEBUG: Connection id "0HLC584SAV4J3" disconnecting. 
2018-03-08 14:09:12.2072 [8][KestrelTrace.RequestBodyDone(KestrelTrace.cs:169)] DEBUG: Connection id "0HLC584SAV4J3", Request id "0HLC584SAV4J3:00000001": done reading request body. 
2018-03-08 14:09:12.2072 [18][LibuvTrace.ConnectionWriteFin(LibuvTrace.cs:58)] DEBUG: Connection id "0HLC584SAV4J3" sending FIN. 
2018-03-08 14:09:12.2072 [8][KestrelTrace.ConnectionBadRequest(KestrelTrace.cs:139)] INFO: Connection id "0HLC584SAV4J3" bad request data: "Unexpected end of request content." Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException Unexpected end of request content. Void Throw(Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.RequestRejectionReason)    at Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException.Throw(RequestRejectionReason reason) in C:\git\KestrelHttpServer\src\Kestrel.Core\BadHttpRequestException.cs:line 38
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1MessageBody.d__4.MoveNext() in C:\git\KestrelHttpServer\src\Kestrel.Core\Internal\Http\Http1MessageBody.cs:line 93
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.IO.Pipelines.PipeCompletion.ThrowLatchedException()
   at System.IO.Pipelines.Pipe.GetResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1MessageBody.d__6.MoveNext() in C:\git\KestrelHttpServer\src\Kestrel.Core\Internal\Http\Http1MessageBody.cs:line 136
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.d__187`1.MoveNext() in C:\git\KestrelHttpServer\src\Kestrel.Core\Internal\Http\HttpProtocol.cs:line 582
2018-03-08 14:09:12.2652 [8][HostingApplicationDiagnostics.LogRequestFinished] INFO: Request finished in 683.3289ms 302  
2018-03-08 14:09:12.2792 [8][KestrelTrace.ConnectionStop(KestrelTrace.cs:94)] DEBUG: Connection id "0HLC584SAV4J3" stopped. 

This does not seem to happen on the release/2.0 branch(the connection is closed but only after the request body is read), but there has been substantial refactoring since then.

2018-03-08 11:49:29.7140 [9][HostingApplicationDiagnostics.LogRequestStarting] INFO: Request starting HTTP/1.1 POST http://localhost:5000/api/values/upload multipart/form-data; boundary=------------------------feff149a03208aa1 51663404 
2018-03-08 11:49:29.9041 [9][TreeRouterLoggerExtensions.MatchedRoute] DEBUG: Request successfully matched the route with name '(null)' and template 'api/Values/upload'. 
2018-03-08 11:49:29.9741 [9][ResourceInvoker.InvokeAsync] DEBUG: Executing action WebApplication1.Controllers.ValuesController.Post (WebApplication1) 
..removed MVC stuff for brevity...
2018-03-08 11:49:30.2111 [9][KestrelTrace.RequestBodyStart(KestrelTrace.cs:153)] DEBUG: Connection id "0HLC55MQBIBHO", Request id "0HLC55MQBIBHO:00000001": started reading request body. 
2018-03-08 11:49:30.2231 [18][LibuvTrace.ConnectionPause(LibuvTrace.cs:90)] DEBUG: Connection id "0HLC55MQBIBHO" paused. 
2018-03-08 11:49:30.2231 [18][LibuvTrace.ConnectionResume(LibuvTrace.cs:95)] DEBUG: Connection id "0HLC55MQBIBHO" resumed. 
2018-03-08 11:49:30.6181 [8][KestrelTrace.RequestBodyDone(KestrelTrace.cs:158)] DEBUG: Connection id "0HLC55MQBIBHO", Request id "0HLC55MQBIBHO:00000001": done reading request body. 
2018-03-08 11:49:30.6401 [18][LibuvTrace.ConnectionReadFin(LibuvTrace.cs:53)] DEBUG: Connection id "0HLC55MQBIBHO" received FIN. 
2018-03-08 11:49:30.6401 [8][KestrelTrace.ConnectionKeepAlive(KestrelTrace.cs:98)] DEBUG: Connection id "0HLC55MQBIBHO" completed keep alive response. 
2018-03-08 11:49:30.6401 [18][KestrelTrace.ConnectionDisconnect(KestrelTrace.cs:108)] DEBUG: Connection id "0HLC55MQBIBHO" disconnecting. 
2018-03-08 11:49:30.6401 [18][LibuvTrace.ConnectionWriteFin(LibuvTrace.cs:58)] DEBUG: Connection id "0HLC55MQBIBHO" sending FIN. 
2018-03-08 11:49:30.6541 [8][HostingApplicationDiagnostics.LogRequestFinished] INFO: Request finished in 950.2941ms 302  
2018-03-08 11:49:30.6671 [8][KestrelTrace.ConnectionStop(KestrelTrace.cs:83)] DEBUG: Connection id "0HLC55MQBIBHO" stopped. 

It also doesn't seem to happen with a request body that is not multi-part. Using the non-multi-part repro solution console app, the connection is only closed when the app is closed.

2018-03-08 14:17:23.6489 [12][HostingApplicationDiagnostics.LogRequestStarting] INFO: Request starting HTTP/1.1 POST http://localhost:5000/api/values/upload  51663176 
2018-03-08 14:17:23.8118 [18][LibuvTrace.ConnectionPause(LibuvTrace.cs:90)] DEBUG: Connection id "0HLC589F04KVK" paused. 
2018-03-08 14:17:23.9158 [12][TreeRouterLoggerExtensions.MatchedRoute] DEBUG: Request successfully matched the route with name '(null)' and template 'api/Values/upload'. 
2018-03-08 14:17:24.0098 [12][ResourceInvoker.InvokeAsync] DEBUG: Executing action WebApplication1.Controllers.ValuesController.Post (WebApplication1) 
..removed MVC stuff for brevity...
2018-03-08 14:17:24.4076 [12][KestrelTrace.ConnectionKeepAlive(KestrelTrace.cs:109)] DEBUG: Connection id "0HLC589F04KVK" completed keep alive response. 
2018-03-08 14:17:24.4076 [12][KestrelTrace.RequestBodyStart(KestrelTrace.cs:164)] DEBUG: Connection id "0HLC589F04KVK", Request id "0HLC589F04KVK:00000001": started reading request body. 
2018-03-08 14:17:24.4356 [18][LibuvTrace.ConnectionResume(LibuvTrace.cs:95)] DEBUG: Connection id "0HLC589F04KVK" resumed. 
2018-03-08 14:17:24.4496 [18][LibuvTrace.ConnectionPause(LibuvTrace.cs:90)] DEBUG: Connection id "0HLC589F04KVK" paused. 
2018-03-08 14:17:24.4496 [18][LibuvTrace.ConnectionResume(LibuvTrace.cs:95)] DEBUG: Connection id "0HLC589F04KVK" resumed. 
2018-03-08 14:17:24.9575 [7][KestrelTrace.RequestBodyDone(KestrelTrace.cs:169)] DEBUG: Connection id "0HLC589F04KVK", Request id "0HLC589F04KVK:00000001": done reading request body. 
2018-03-08 14:17:24.9725 [7][HostingApplicationDiagnostics.LogRequestFinished] INFO: Request finished in 1334.8391ms 302  
...Console app closed...
2018-03-08 14:19:02.8037 [18][LibuvTrace.ConnectionReset(LibuvTrace.cs:85)] DEBUG: Connection id "0HLC589F04KVK" reset. 
2018-03-08 14:19:02.8037 [8][KestrelTrace.ConnectionDisconnect(KestrelTrace.cs:119)] DEBUG: Connection id "0HLC589F04KVK" disconnecting. 
2018-03-08 14:19:02.8167 [18][LibuvTrace.ConnectionWriteFin(LibuvTrace.cs:58)] DEBUG: Connection id "0HLC589F04KVK" sending FIN. 
2018-03-08 14:19:02.8167 [12][KestrelTrace.ConnectionStop(KestrelTrace.cs:94)] DEBUG: Connection id "0HLC589F04KVK" stopped. 

I think the above error is blocking access to the original error I was seeing, which is the request body draining timeout. I think I can fix the timeout issue on the 2.0 release branch by changing the kind of timeout action used during the request body draining so that a draining timeout is not considered a fatal error and breaking out of PumpAsync instead of throwing. While this seems to work, I'm not sure if that goes against the design of the timeout.

[halter73]

Kestrel is behaving as intended here.

One thing you have to consider is how application middleware is invoked before the request body has been processed/consumed. There is no request body buffering by default. It's entirely possible by the time your app is invoked the client hasn't even started sending the request body.

It's up to middleware like the form reader to consume the entire request body when it's ready. It used to be that Kestrel would abort the underlying TCP connection anytime the app didn't fully consume the request body. The idea is we didn't want to waste any time consuming a request body only to ignore the contents.

What we learned from the old behavior is that it's actually fairly common for app developers not to consume the request body in their apps. Usually it's just an oversight, not some malicious client trying to keep unwanted connections open.

The problem is that there is no way with HTTP/1.1 for the server to tell the client not to send the rest of the request body short of aborting the underlying TCP connection. The only way to keep the connection usable and avoid the cost of forcing the client to reestablish the connection for future requests is to receive and ACK the entire unconsumed body.

After some feedback, we decided we'd consume the request body automatically and ignore it's contents when the app doesn't fully consume the request body. Obviously we didn't want to allow this to happen indefinitely, so we decided to abort this automatic request body consumption and the underlying TCP connection after a non-configurable 5 second timeout. If consuming the request body takes that long, it's probably more efficient for the client to reestablish a connection anyway.

If you really want to avoid aborting the TCP connection. You can consume the request body and ignore the contents yourself pretty easily. You can do so in one line with await context.Request.Body.CopyToAsync(Stream.Null);. At that point, you'd probably want to add a timeout so the client doesn't keep the connection open forever, so why not just let Kestrel handle it for you?

The error message could be clearer though. It won't be able to go into the detail I have in this essay of a comment, but it should make it clear that it was a drain timeout that occurred. I think @JunTaoLuo will be improving this.

[andrewbull99]

@halter73, thank you for your detailed response. I really appreciate it.

we decided to abort this automatic request body consumption and the underlying TCP connection after a non-configurable 5 second timeout

The problem with the connection being aborted is that IIS then returns the client HTTP 502 'Bad Gateway'. Is that expected behaviour also?

It's not that I want to avoid the cost of setting up a new connection, I just want to avoid killing the integration with IIS so that the client actually receives the HTTP 302.

I will try explicitly draining the request body as you suggest, thanks!

[halter73]

Interesting about the 502. IMHO, IIS should return a response as soon as it receives it, but if it doesn't you'll have to deal with consuming the request body in app code/middleware.

[Tratcher]

Most clients aren't bidirectional, and that goes for WinHttp which ANCM uses. They don't return the response until the request is finished.

[andrewbull99]

Thanks for your help everyone. I am able to work around the draining timeout / IIS 502 issue by explicitly draining the request body as halter73 suggested, though interestingly not if I use async. That seems to cause other issues.

I agree that what Kestrel is doing makes sense and is preferable, but it's not great that IIS returns HTTP 502 in this scenario. Does that warrant creating an issue on the ANCM repo? Or is this just a limitation of running behind a reverse proxy?

[halter73]

I'm interested in what the problem was with consuming the body asynchronously. @andrewbull99 Do you have any more details about this?

[andrewbull99]

So if I do this:

[HttpPost("upload")]
public async void Post()
{
    await Request.Body.CopyToAsync(Stream.Null);
    Response.Redirect("http://www.wikipedia.org");
}

Kestrel throws an unhandled exception like this:

2018-03-09 16:46:55.1625 [9][KestrelTrace.ConnectionStart] DEBUG: Connection id "0HLC641LVOIMM" started.
2018-03-09 16:46:55.2225 [5][HostingApplicationDiagnostics.LogRequestStarting] INFO: Request starting HTTP/1.1 POST http://andytest.dev-globalrelay.net:5000/api/values/upload multipart/form-data; boundary="8c65ad2b-eac4-4c86-a62f-31ab8d67c772" 925354178
2018-03-09 16:46:55.2835 [5][TreeRouterLoggerExtensions.MatchedRoute] DEBUG: Request successfully matched the route with name '(null)' and template 'api/Values/upload'.
2018-03-09 16:46:55.3165 [5][MvcCoreLoggerExtensions.ExecutingAction] DEBUG: Executing action WebApplication1.Controllers.ValuesController.Post (WebApplication1)
2018-03-09 16:46:55.3385 [5][MvcCoreLoggerExtensions.ActionMethodExecuting] INFO: Executing action method WebApplication1.Controllers.ValuesController.Post (WebApplication1) with arguments ((null)) - ModelState is Valid
2018-03-09 16:46:55.3625 [5][KestrelTrace.RequestBodyStart] DEBUG: Connection id "0HLC641LVOIMM", Request id "0HLC641LVOIMM:00000001": started reading request body.
2018-03-09 16:46:55.3865 [9][LibuvTrace.ConnectionPause] DEBUG: Connection id "0HLC641LVOIMM" paused.
2018-03-09 16:46:55.3975 [9][LibuvTrace.ConnectionResume] DEBUG: Connection id "0HLC641LVOIMM" resumed.
2018-03-09 16:46:55.3975 [5][MvcCoreLoggerExtensions.ActionMethodExecuted] DEBUG: Executed action method WebApplication1.Controllers.ValuesController.Post (WebA
pplication1), returned result Microsoft.AspNetCore.Mvc.EmptyResult.2018-03-09 16:46:55.4285 [5][MvcCoreLoggerExtensions.ExecutedAction] INFO: Executed action WebApplication1.Controllers.ValuesController.Post (WebApplication1) in 99.8803ms

Unhandled Exception: System.InvalidOperationException: Concurrent reads or writes are not supported.
   at Microsoft.AspNetCore.Server.Kestrel.Internal.System.IO.Pipelines.PipeCompletion.ThrowFailed()
   at Microsoft.AspNetCore.Server.Kestrel.Internal.System.IO.Pipelines.Pipe.GetResult(ReadResult& result)
   at Microsoft.AspNetCore.Server.Kestrel.Internal.System.IO.Pipelines.Pipe.Microsoft.AspNetCore.Server.Kestrel.Internal.System.IO.Pipelines.IReadableBufferAwaiter.GetResult()
   at Microsoft.AspNetCore.Server.Kestrel.Internal.System.IO.Pipelines.ReadableBufferAwaitable.GetResult()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.MessageBody.d__23.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.FrameRequestStream.d__23.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at WebApplication1.Controllers.ValuesController.d__1.MoveNext() in C:\git\RequestTimeOutReproMultiPart\WebApplication1\Controllers\ValuesController.cs:line 20
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()

But the synchronous version works fine.

EDIT: This is because I was not returning a Task from the Controller method. Please ignore.

[halter73]

Never use async void in ASP.NET Core code (or most anything... maybe WPF callbacks but even then...).

Change it to async Task and you should be fine. I always recommend async code over sync code if possible. I think it's particularly important to use async code for things like consuming a large request body.

[muratg]

cc @Tratcher

[Tratcher]

@JunTaoLuo I've already modified the timeout exception messages in https://github.com/aspnet/KestrelHttpServer/pull/2356. See if they cover this scenario too.

[JunTaoLuo]

@Tratcher No they do not, I was testing with your changes and while your updates differentiate between timeouts from reading the request header vs the request body, it does not differentiate between reading timeouts in general and the hard drain timeout.