aspnetcore: Logs filled with critical exceptions from Kestrel/Quic

Is there an existing issue for this?

I have searched the existing issues

Describe the bug

I run an app in a linux docker container (tag 7.0) with http/3 enabled. The libmsquic version in 2.1.4 (from ms repo). The server logs are being filled with the following message:

Microsoft.AspNetCore.Server.Kestrel Critical Unexpected exception in HttpConnection.ProcessRequestsAsync. 
An internal error has occurred. StreamShutdown failed: QUIC_STATUS_INVALID_PARAMETER
  at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.Abort(ConnectionAbortedException abortReason)
  at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3.Http3FrameWriter.Abort(ConnectionAbortedException error)
  at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3.Http3ControlStream.Abort(ConnectionAbortedException abortReason, Http3ErrorCode errorCode)
  at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3.Http3Connection.ProcessRequestsAsync[TContext](IHttpApplication`1 application)
  at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.HttpConnection.ProcessRequestsAsync[TContext](IHttpApplication`1 httpApplication)

This doesn’t influence the operations as far as we see. The server responds normally despite the messages.

Expected Behavior

No messages in logs

Steps To Reproduce

No response

Exceptions (if any)

No response

.NET Version

7.0 runtime (no sdk)

Anything else?

No response

About this issue

Original URL
State: open
Created 2 years ago
Comments: 27 (21 by maintainers)

Most upvoted comments

@ManickaP Thanks for that analysis! I can take next steps (which will probably be following up with @JamesNK 😆).

amcasey on May 25, 2023

So I found 2 occurrences of [ api] Exit 2147942487 (e.g. INVALID_PARAMETER) in the logs. Both were for an incoming unidirectional stream (control | QPack) and both were due to the layer above (Kestrel) calling Abort on an already shutdown stream. What happens is that connection idles out and part of that process is also shutdown of all active streams (with the same cause “Connection Idle”). As control streams are not meant to be closed ever, they are alive at this point and they receive this event. What I suspect causes the error to happen here is that processing of this stream event that eventually removes the stream from _streams collection: https://github.com/dotnet/aspnetcore/blob/b441d4e816ef3bc43b72e91ba8793f252ada2c5a/src/Servers/Kestrel/Core/src/Internal/Http3/Http3ControlStream.cs#L244 races with connection closure and in some cases the connection is faster and calls abort: https://github.com/dotnet/aspnetcore/blob/b441d4e816ef3bc43b72e91ba8793f252ada2c5a/src/Servers/Kestrel/Core/src/Internal/Http3/Http3Connection.cs#L499-L506

@JamesNK Could you look into what I found out? If I’m right, this is not a problem of S.N.Quic.

Details from msquic logs:

Error case:
2023-05-20T06:41:35.813851,6155,5,Microsoft-Quic,[strm][0x17783af6e00] Indicating QUIC_STREAM_EVENT_SHUTDOWN_COMPLETE [ConnectionShutdown=1, ConnectionShutdownByApp=0, ConnectionClosedRemotely=0, Co
2023-05-20T06:41:35.815034,11,5,Microsoft-Quic,[ api] Enter STREAM_SHUTDOWN (0x17783af6e00).
2023-05-20T06:41:35.815036,13,5,Microsoft-Quic,[ api] Exit 2147942487

Correct case:
2023-05-20T06:41:49.119196,6155,5,Microsoft-Quic,[strm][0x17783b92870] Indicating QUIC_STREAM_EVENT_SHUTDOWN_COMPLETE [ConnectionShutdown=1, ConnectionShutdownByApp=0, ConnectionClosedRemotely=0, Co

ManickaP on May 25, 2023

Nothing so far, but also something apparent on .net8 preview 2.

ladeak on Mar 29, 2023