Ugly exception after closing the browser(firefox,chrome) with serverside-blazor, kestrel

[mshobohm]

The following exception was found in Console after closing the browser (running blazor serverside default application and kestrel):

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 POST http://localhost:5000/_blazor/disconnect multipart/form-data; boundary=----WebKitFormBoundaryPApGJ5QsMg4BlrRk 359
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'Blazor disconnect'
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint '/_blazor'
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 25034.602300000002ms 101
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'Blazor disconnect'
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 196.585ms 0
warn: Microsoft.AspNetCore.Server.Kestrel[0]
      Connection processing ended abnormally.
System.InvalidOperationException: Reading is already in progress.
   at System.IO.Pipelines.ThrowHelper.ThrowInvalidOperationException_AlreadyReading()
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.ReadAsync(CancellationToken token)
   at System.IO.Pipelines.Pipe.DefaultPipeReader.ReadAsync(CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1Connection.BeginRead(ValueTask`1& awaitable)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application)
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequestsAsync[TContext](IHttpApplication`1 application) 

It seems to happen with Chrome and Firefox but not with edge.

[Tratcher]

This is with 3.0?

[mshobohm]

Yes. Dotnet Version is 3.0.100.

[Tratcher]

@halter73

[halter73]

This exception is pretty weird. Have you seen it more than once @mshobohm? If so, do you have a reliable way to reproduce this exception?

Normally "System.InvalidOperationException: Reading is already in progress." would indicate the request handler completed while still reading from the request body. However, in that case, I would expect to see the exception to be thrown from MessageBody.ConsumeAsync() rather than by Http1Connection.BeginRead().

I suppose it's possible that the request handler held on to a reference to the request body stream, and then started reading after MessageBody.ConsumeAsync() completed, but in that case I would expect the request body stream to be poisoned since the next request didn't fully arrive yet.

I think we're going to need some more details to get to the bottom of this.

[mshobohm]

After further investigation I found out that I had modified Properties\launchSettings.json:
"applicationUrl": "http://localhost:5000",
and deleted the https://localhost:5001 Part.
So the Server doesn't listen on 5001.

This is needed to reproduce, and try with firefox (closing without additional questions).

[mshobohm]

Real Exception is hidden:
Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException
HResult=0x80131620
Nachricht = Unexpected end of request content.
Quelle = Microsoft.AspNetCore.Server.Kestrel.Core
Stapelüberwachung:
at Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException.Throw(RequestRejectionReason reason) in /_/src/Servers/Kestrel/Core/src/BadHttpRequestException.cs:line 41

[davidfowl]

Looks like it might be a missing call to Advance somewhere

[davidfowl]

@rynowak @pranavk what is /_blazor/disconnect and why is it a multi-part form post?

[halter73]

Thanks for including the first chance exception details @mshobohm. It was really helpful.

@davidfowl and I think we know what happened. Http1ContentLengthMessageBody.ReadAsyncInternal() throws the BadHttpRequestException "Unexpected end of request content" when it calls CheckCompletedReadResult() after the connection-level pipe successfully returned a completed ReadResult.

Since Kestrel's HttpRequestStream sees an exception thrown PipeReader.ReadAsync() and never gets a ReadResult, it never calls PipeReader.AdvanceTo() on the request body pipe which is the correct behavior for HttpRequestStream.

Http1ContentLengthMessageBody.ReadAsyncInternal() should be the one calling PipeReader.AdvanceTo() on the connection-level pipe if it throws an exception after successfully getting a ReadResult from the connection-level pipe.

When we fix this bug, we should audit all the other HTTP/1.x MessageBody implementations to verify their ReadAsync() implementations never throw while leaving the connection-level pipe in an unadvanced state.

To make matters worse, Blazor's CircuitDisconnectMiddleware swallows the BadHttpRequestException without logging it, making it hard to notice the first BadHttpRequestException even happened without looking for first chance exceptions. I think the CircuitDisconnectMiddleware should be logging the exception.

Normally, after middleware exits, Kestrel will try to drain any part of the request body that might not have been read by the application. This should resurface the BadHttpRequestException even though it was initially swallowed. The problem here is that the request body draining logic uses Http1ContentLengthMessageBody.TryReadInternal() instead of Http1ContentLengthMessageBody.ReadAsyncInternal() which as of today, doesn't call CheckCompletedReadResult() which means the draining logic doesn't set bad request state like it should.

If bad request state had been set, the request processing loop would stop preventing Http1Connection.BeginRead() from being called again meaning there would be no "System.InvalidOperationException: Reading is already in progress."

The draining logic doesn't observe the InvalidOperationException that Http1Connection.BeginRead() does because Http1ContentLengthMessageBody.TryReadInternal() elides the call to PipeReader.TryRead() on the connection-level pipe since the MessageBody has already seen the end of the request.

Here's what should be done before we close this issue:

• Change Http1ContentLengthMessageBody.ReadAsyncInternal() to call PipeReader.AdvanceTo() on the connection-level pipe if it throws an exception after successfully getting a ReadResult from the connection-level pipe.
• Audit the other MessageBodies to ensure they don't have a similar bug
• Change Http1ContentLengthMessageBody.TryReadInternal() to call CheckCompletedReadResult() and advance the connection-level PipeReader if it throws.
• Audit the other message bodies to ensure their TryReadInternal() implementations throw BadHttpRequestExceptions internally
• (Maybe) Change CircuitDisconnectMiddleware to log any swallowed exceptions. This might be noisy since the request draining logic might log the same issue once it's fixed.

[mshobohm]

Many thanks in advance for your efforts. Please log the exception(s) only on debug level, if they happen on a regular base. I switched to Loglevel debug and saw that Edge also does have a regular closing exception "System.Net.WebSockets.WebSocketException (0x80004005): The remote party closed the WebSocket connection without completing the close" which is hidden by debug level (thats ok for me). If you can't completely avoid exceptions on closing, hide them from the normal application development protocol(loglevel inf).

[Pilchie]

@anurse - this is sitting in the 3.1.0-Preview2 milestone. Can you get it updated?

[halter73]

I'm the one who tentatively put this into preview2. I know it's getting pretty late to change this, and the only functional impact is the extra first-chance exception and warning log AFAIK, so I'm going to tentatively put this into preview3. @anurse by all means feel free to move the milestone again.