Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

QuicConnection.AcceptStreamAsync throws incorrect exception on browser close #60133

Closed
JamesNK opened this issue Oct 7, 2021 · 12 comments · Fixed by #60181
Closed

QuicConnection.AcceptStreamAsync throws incorrect exception on browser close #60133

JamesNK opened this issue Oct 7, 2021 · 12 comments · Fixed by #60181

Comments

@JamesNK
Copy link
Member

JamesNK commented Oct 7, 2021

Kestrel isn't getting the expected notification that the connection is closed by a browser.

When the browser closes the connection (I'm simulating that by browsing to the website in Chrome, then closing the browser window), System.Net.Quic's QuicConnection.AcceptStreamAsync is throwing QuicOperationAbortedException. This is different from when HttpClient is disposed and closes the connection which is QuicConnectionAbortedException.

From Kestrel's point of view of exceptions from AcceptStreamAsync:

  • QuicOperationAbortedException = the server closed/aborted the connection
  • QuicConnectionAbortedException = the peer closed/aborted the connection

Because Kestrel didn't abort the connection, and it is waiting for QuicConnectionAbortedException to indicate the peer closed the connection, the HTTP/3 connection stays open in a bad state.

I believe the problem is in System.Net.Quic. QuicConnection.AcceptStreamAsync should throw QuicConnectionAbortedException when a connection is closed by the browser.

Logs:

dbug: HttpEventSourceListener[0]
      Starting HttpEventSourceListener.
dbug: Microsoft.Extensions.Hosting.Internal.Host[1]
      Hosting starting
warn: Microsoft.AspNetCore.Server.Kestrel[0]
      Overriding address(es) 'https://localhost:5001/, http://localhost:5000/'. Binding to endpoints defined via IConfiguration and/or UseKestrel() instead.
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#20601768,.ctor,[list][0x1B6113C8160] Listener created ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#20601768,.ctor,[list][0x1B6113C8160] Listener started ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#51198184,.ctor,[list][0x1B612426EC0] Listener created ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#51198184,.ctor,[list][0x1B612426EC0] Listener started ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58130472,.ctor,[list][0x1B6113CEED0] Listener created ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58130472,.ctor,[list][0x1B6113CEED0] Listener started ->
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: http://[::]:5000
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: https://[::]:5001
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: https://[::]:5002
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: https://[::]:5003
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: https://[::]:5004
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: https://[::]:5005
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: https://[::]:5006
dbug: Microsoft.AspNetCore.Hosting.Diagnostics[13]
      Loaded hosting startup assembly Http3SampleApp
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Development
info: Microsoft.Hosting.Lifetime[0]
      Content root path: C:\Development\Source\AspNetCore\artifacts\bin\Http3SampleApp\Debug\net7.0\
dbug: Microsoft.Extensions.Hosting.Internal.Host[2]
      Hosting started
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,.ctor,[conn][0x1B6123E5020] Inbound connection created ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event IDEAL_PROCESSOR_CHANGED ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event CONNECTED ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event PEER_STREAM_STARTED ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,.ctor,[strm][0x1B6123E62E0] Inbound unidirectional stream created in connection [conn][0x1B6123E5020]. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event PEER_STREAM_STARTED ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,.ctor,[strm][0x1B6123E65B0] Inbound bidirectional stream created in connection [conn][0x1B6123E5020]. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,HandleEvent,[strm][0x1B6123E62E0] Stream received event RECEIVE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,HandleEventRecv,[strm][0x1B6123E62E0] Stream received 50 bytes ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,HandleEvent,[strm][0x1B6123E65B0] Stream received event RECEIVE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,HandleEventRecv,[strm][0x1B6123E65B0] Stream received 439 bytes with FIN flag ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event DATAGRAM_STATE_CHANGED ->
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[1]
      Connection id "0HMC9MO6SIKV2" accepted.
dbug: Microsoft.AspNetCore.Server.Kestrel.Connections[39]
      Connection id "0HMC9MO6SIKV2" accepted.
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event DATAGRAM_STATE_CHANGED ->
dbug: Microsoft.AspNetCore.Server.Kestrel.Connections[1]
      Connection id "0HMC9MO6SIKV2" started.
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#51866944,HandleEvent,(null) Stream received event START_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#51866944,.ctor,[strm][0x1B61268F510] Outbound unidirectional stream created in connection [conn][0x1B6123E5020]. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event DATAGRAM_STATE_CHANGED ->
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[3]
      Stream id "0HMC9MO6SIKV2:00000003" type Unidirectional connected.
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event DATAGRAM_STATE_CHANGED ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#51866944,HandleEvent,[strm][0x1B61268F510] Stream received event SEND_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event DATAGRAM_STATE_CHANGED ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#51866944,HandleEvent,[strm][0x1B61268F510] Stream received event SEND_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,ReadAsync,[strm][0x1B6123E62E0] Stream reading into Memory of '4096' bytes. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,ReadAsync,[strm][0x1B6123E62E0] Stream reading into Memory of '4096' bytes. ->
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[2]
      Stream id "0HMC9MO6SIKV2:00000002" type Unidirectional accepted.
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,ReadAsync,[strm][0x1B6123E65B0] Stream reading into Memory of '4096' bytes. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,HandleEvent,[strm][0x1B6123E65B0] Stream received event PEER_SEND_SHUTDOWN ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,HandleEventPeerSendShutdown,[strm][0x1B6123E65B0] Stream completing resettable event source. ->
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[2]
      Stream id "0HMC9MO6SIKV2:00000000" type Bidirectional accepted.
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMC9MO6SIKV2" received SETTINGS frame for stream ID 2 with length 29.
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMC9MO6SIKV2" received 107826396321 frame for stream ID 2 with length 0.
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMC9MO6SIKV2" received 984832 frame for stream ID 2 with length 4.
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMC9MO6SIKV2" received HEADERS frame for stream ID 0 with length 436.
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/3 GET https://www.kestrelhttp3.com/ - -
dbug: Microsoft.AspNetCore.Server.Kestrel[25]
      Connection id "0HMC9MO6SIKV2", Request id "0HMC9MO6SIKV2:00000000": started reading request body.
dbug: Microsoft.AspNetCore.Server.Kestrel[26]
      Connection id "0HMC9MO6SIKV2", Request id "0HMC9MO6SIKV2:00000000": done reading request body.
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
      Connection id "0HMC9MO6SIKV2" sending HEADERS frame for stream ID 0 with length 92.
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
      Connection id "0HMC9MO6SIKV2" sending DATA frame for stream ID 0 with length 20.
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,HandleEvent,[strm][0x1B6123E65B0] Stream received event SEND_COMPLETE ->
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[10]
      Stream id "0HMC9MO6SIKV2:00000000" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,HandleEvent,[strm][0x1B6123E65B0] Stream received event SEND_SHUTDOWN_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,HandleEvent,[strm][0x1B6123E65B0] Stream received event SHUTDOWN_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,HandleEventShutdownComplete,[strm][0x1B6123E65B0] Stream completing resettable event source. ->
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/3 GET https://www.kestrelhttp3.com/ - - - 200 - - 47.9690ms
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,Dispose,[strm][0x1B6123E65B0] Stream disposing True ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,Cleanup,[strm][0x1B6123E65B0] releasing handles. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,Dispose,[strm][0x1B6123E65B0] Stream disposed ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event PEER_STREAM_STARTED ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,.ctor,[strm][0x1B6123E65B0] Inbound bidirectional stream created in connection [conn][0x1B6123E5020]. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,HandleEvent,[strm][0x1B6123E62E0] Stream received event RECEIVE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,HandleEventRecv,[strm][0x1B6123E62E0] Stream received 9 bytes ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,HandleEvent,[strm][0x1B6123E65B0] Stream received event RECEIVE ->
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMC9MO6SIKV2" received 984832 frame for stream ID 2 with length 4.
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[2]
      Stream id "0HMC9MO6SIKV2:00000004" type Bidirectional accepted.
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMC9MO6SIKV2" received HEADERS frame for stream ID 4 with length 402.
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/3 GET https://www.kestrelhttp3.com/favicon.ico - -
dbug: Microsoft.AspNetCore.Server.Kestrel[25]
      Connection id "0HMC9MO6SIKV2", Request id "0HMC9MO6SIKV2:00000004": started reading request body.
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,HandleEventRecv,[strm][0x1B6123E65B0] Stream received 405 bytes with FIN flag ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,ReadAsync,[strm][0x1B6123E62E0] Stream reading into Memory of '4096' bytes. ->
dbug: Microsoft.AspNetCore.Server.Kestrel[26]
      Connection id "0HMC9MO6SIKV2", Request id "0HMC9MO6SIKV2:00000004": done reading request body.
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
      Connection id "0HMC9MO6SIKV2" sending HEADERS frame for stream ID 4 with length 92.
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
      Connection id "0HMC9MO6SIKV2" sending DATA frame for stream ID 4 with length 20.
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,ReadAsync,[strm][0x1B6123E65B0] Stream reading into Memory of '4096' bytes. ->
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[10]
      Stream id "0HMC9MO6SIKV2:00000004" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/3 GET https://www.kestrelhttp3.com/favicon.ico - - - 200 - - 0.8645ms
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,HandleEvent,[strm][0x1B6123E65B0] Stream received event PEER_SEND_SHUTDOWN ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,HandleEventPeerSendShutdown,[strm][0x1B6123E65B0] Stream completing resettable event source. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,HandleEvent,[strm][0x1B6123E65B0] Stream received event SEND_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,HandleEvent,[strm][0x1B6123E65B0] Stream received event SEND_SHUTDOWN_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,HandleEvent,[strm][0x1B6123E65B0] Stream received event SHUTDOWN_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,HandleEventShutdownComplete,[strm][0x1B6123E65B0] Stream completing resettable event source. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,Dispose,[strm][0x1B6123E65B0] Stream disposing True ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,Cleanup,[strm][0x1B6123E65B0] releasing handles. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,Dispose,[strm][0x1B6123E65B0] Stream disposed ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event SHUTDOWN_INITIATED_BY_TRANSPORT ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,HandleEvent,[strm][0x1B6123E62E0] Stream received event SHUTDOWN_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,HandleEventConnectionClose,[strm][0x1B6123E62E0] Stream handling connection [conn][0x1B6123E5020] close ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#51866944,HandleEvent,[strm][0x1B61268F510] Stream received event SEND_SHUTDOWN_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#51866944,HandleEvent,[strm][0x1B61268F510] Stream received event SHUTDOWN_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#51866944,HandleEventConnectionClose,[strm][0x1B61268F510] Stream handling connection [conn][0x1B6123E5020] close ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event SHUTDOWN_COMPLETE ->
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[10]
      Stream id "0HMC9MO6SIKV2:00000003" shutting down writes because: "Operation aborted.".
@ghost
Copy link

ghost commented Oct 7, 2021

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

Issue Details

Kestrel isn't getting the expected notification that the connection is closed by a browser.

When the browser closes the connection (I'm simulating that by browsing to the website in Chrome, then closing the browser window), System.Net.Quic's QuicConnection.AcceptStreamAsync is throwing QuicOperationAbortedException. This is different from when HttpClient is disposed and closes the connection which is QuicConnectionAbortedException.

From Kestrel's point of view of exceptions from AcceptStreamAsync:

  • QuicOperationAbortedException = the server closed/aborted the connection
  • QuicConnectionAbortedException = the peer closed/aborted the connection

Because Kestrel didn't abort the connection, and it is waiting for QuicConnectionAbortedException to indicate the peer closed the connection, the HTTP/3 connection stays open in a bad state.

I believe the problem is in System.Net.Quic. QuicConnection.AcceptStreamAsync should throw QuicConnectionAbortedException when a connection is closed by the browser.

Logs:

dbug: HttpEventSourceListener[0]
      Starting HttpEventSourceListener.
dbug: Microsoft.Extensions.Hosting.Internal.Host[1]
      Hosting starting
warn: Microsoft.AspNetCore.Server.Kestrel[0]
      Overriding address(es) 'https://localhost:5001/, http://localhost:5000/'. Binding to endpoints defined via IConfiguration and/or UseKestrel() instead.
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#20601768,.ctor,[list][0x1B6113C8160] Listener created ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#20601768,.ctor,[list][0x1B6113C8160] Listener started ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#51198184,.ctor,[list][0x1B612426EC0] Listener created ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#51198184,.ctor,[list][0x1B612426EC0] Listener started ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58130472,.ctor,[list][0x1B6113CEED0] Listener created ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58130472,.ctor,[list][0x1B6113CEED0] Listener started ->
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: http://[::]:5000
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: https://[::]:5001
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: https://[::]:5002
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: https://[::]:5003
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: https://[::]:5004
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: https://[::]:5005
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: https://[::]:5006
dbug: Microsoft.AspNetCore.Hosting.Diagnostics[13]
      Loaded hosting startup assembly Http3SampleApp
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Development
info: Microsoft.Hosting.Lifetime[0]
      Content root path: C:\Development\Source\AspNetCore\artifacts\bin\Http3SampleApp\Debug\net7.0\
dbug: Microsoft.Extensions.Hosting.Internal.Host[2]
      Hosting started
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,.ctor,[conn][0x1B6123E5020] Inbound connection created ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event IDEAL_PROCESSOR_CHANGED ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event CONNECTED ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event PEER_STREAM_STARTED ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,.ctor,[strm][0x1B6123E62E0] Inbound unidirectional stream created in connection [conn][0x1B6123E5020]. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event PEER_STREAM_STARTED ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,.ctor,[strm][0x1B6123E65B0] Inbound bidirectional stream created in connection [conn][0x1B6123E5020]. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,HandleEvent,[strm][0x1B6123E62E0] Stream received event RECEIVE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,HandleEventRecv,[strm][0x1B6123E62E0] Stream received 50 bytes ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,HandleEvent,[strm][0x1B6123E65B0] Stream received event RECEIVE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,HandleEventRecv,[strm][0x1B6123E65B0] Stream received 439 bytes with FIN flag ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event DATAGRAM_STATE_CHANGED ->
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[1]
      Connection id "0HMC9MO6SIKV2" accepted.
dbug: Microsoft.AspNetCore.Server.Kestrel.Connections[39]
      Connection id "0HMC9MO6SIKV2" accepted.
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event DATAGRAM_STATE_CHANGED ->
dbug: Microsoft.AspNetCore.Server.Kestrel.Connections[1]
      Connection id "0HMC9MO6SIKV2" started.
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#51866944,HandleEvent,(null) Stream received event START_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#51866944,.ctor,[strm][0x1B61268F510] Outbound unidirectional stream created in connection [conn][0x1B6123E5020]. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event DATAGRAM_STATE_CHANGED ->
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[3]
      Stream id "0HMC9MO6SIKV2:00000003" type Unidirectional connected.
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event DATAGRAM_STATE_CHANGED ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#51866944,HandleEvent,[strm][0x1B61268F510] Stream received event SEND_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event DATAGRAM_STATE_CHANGED ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#51866944,HandleEvent,[strm][0x1B61268F510] Stream received event SEND_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,ReadAsync,[strm][0x1B6123E62E0] Stream reading into Memory of '4096' bytes. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,ReadAsync,[strm][0x1B6123E62E0] Stream reading into Memory of '4096' bytes. ->
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[2]
      Stream id "0HMC9MO6SIKV2:00000002" type Unidirectional accepted.
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,ReadAsync,[strm][0x1B6123E65B0] Stream reading into Memory of '4096' bytes. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,HandleEvent,[strm][0x1B6123E65B0] Stream received event PEER_SEND_SHUTDOWN ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,HandleEventPeerSendShutdown,[strm][0x1B6123E65B0] Stream completing resettable event source. ->
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[2]
      Stream id "0HMC9MO6SIKV2:00000000" type Bidirectional accepted.
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMC9MO6SIKV2" received SETTINGS frame for stream ID 2 with length 29.
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMC9MO6SIKV2" received 107826396321 frame for stream ID 2 with length 0.
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMC9MO6SIKV2" received 984832 frame for stream ID 2 with length 4.
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMC9MO6SIKV2" received HEADERS frame for stream ID 0 with length 436.
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/3 GET https://www.kestrelhttp3.com/ - -
dbug: Microsoft.AspNetCore.Server.Kestrel[25]
      Connection id "0HMC9MO6SIKV2", Request id "0HMC9MO6SIKV2:00000000": started reading request body.
dbug: Microsoft.AspNetCore.Server.Kestrel[26]
      Connection id "0HMC9MO6SIKV2", Request id "0HMC9MO6SIKV2:00000000": done reading request body.
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
      Connection id "0HMC9MO6SIKV2" sending HEADERS frame for stream ID 0 with length 92.
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
      Connection id "0HMC9MO6SIKV2" sending DATA frame for stream ID 0 with length 20.
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,HandleEvent,[strm][0x1B6123E65B0] Stream received event SEND_COMPLETE ->
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[10]
      Stream id "0HMC9MO6SIKV2:00000000" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,HandleEvent,[strm][0x1B6123E65B0] Stream received event SEND_SHUTDOWN_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,HandleEvent,[strm][0x1B6123E65B0] Stream received event SHUTDOWN_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,HandleEventShutdownComplete,[strm][0x1B6123E65B0] Stream completing resettable event source. ->
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/3 GET https://www.kestrelhttp3.com/ - - - 200 - - 47.9690ms
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,Dispose,[strm][0x1B6123E65B0] Stream disposing True ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,Cleanup,[strm][0x1B6123E65B0] releasing handles. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#59107228,Dispose,[strm][0x1B6123E65B0] Stream disposed ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event PEER_STREAM_STARTED ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,.ctor,[strm][0x1B6123E65B0] Inbound bidirectional stream created in connection [conn][0x1B6123E5020]. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,HandleEvent,[strm][0x1B6123E62E0] Stream received event RECEIVE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,HandleEventRecv,[strm][0x1B6123E62E0] Stream received 9 bytes ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,HandleEvent,[strm][0x1B6123E65B0] Stream received event RECEIVE ->
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMC9MO6SIKV2" received 984832 frame for stream ID 2 with length 4.
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[2]
      Stream id "0HMC9MO6SIKV2:00000004" type Bidirectional accepted.
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[46]
      Connection id "0HMC9MO6SIKV2" received HEADERS frame for stream ID 4 with length 402.
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/3 GET https://www.kestrelhttp3.com/favicon.ico - -
dbug: Microsoft.AspNetCore.Server.Kestrel[25]
      Connection id "0HMC9MO6SIKV2", Request id "0HMC9MO6SIKV2:00000004": started reading request body.
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,HandleEventRecv,[strm][0x1B6123E65B0] Stream received 405 bytes with FIN flag ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,ReadAsync,[strm][0x1B6123E62E0] Stream reading into Memory of '4096' bytes. ->
dbug: Microsoft.AspNetCore.Server.Kestrel[26]
      Connection id "0HMC9MO6SIKV2", Request id "0HMC9MO6SIKV2:00000004": done reading request body.
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
      Connection id "0HMC9MO6SIKV2" sending HEADERS frame for stream ID 4 with length 92.
trce: Microsoft.AspNetCore.Server.Kestrel.Http3[47]
      Connection id "0HMC9MO6SIKV2" sending DATA frame for stream ID 4 with length 20.
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,ReadAsync,[strm][0x1B6123E65B0] Stream reading into Memory of '4096' bytes. ->
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[10]
      Stream id "0HMC9MO6SIKV2:00000004" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/3 GET https://www.kestrelhttp3.com/favicon.ico - - - 200 - - 0.8645ms
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,HandleEvent,[strm][0x1B6123E65B0] Stream received event PEER_SEND_SHUTDOWN ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,HandleEventPeerSendShutdown,[strm][0x1B6123E65B0] Stream completing resettable event source. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,HandleEvent,[strm][0x1B6123E65B0] Stream received event SEND_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,HandleEvent,[strm][0x1B6123E65B0] Stream received event SEND_SHUTDOWN_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,HandleEvent,[strm][0x1B6123E65B0] Stream received event SHUTDOWN_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,HandleEventShutdownComplete,[strm][0x1B6123E65B0] Stream completing resettable event source. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,Dispose,[strm][0x1B6123E65B0] Stream disposing True ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,Cleanup,[strm][0x1B6123E65B0] releasing handles. ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22049402,Dispose,[strm][0x1B6123E65B0] Stream disposed ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event SHUTDOWN_INITIATED_BY_TRANSPORT ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,HandleEvent,[strm][0x1B6123E62E0] Stream received event SHUTDOWN_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#14472917,HandleEventConnectionClose,[strm][0x1B6123E62E0] Stream handling connection [conn][0x1B6123E5020] close ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#51866944,HandleEvent,[strm][0x1B61268F510] Stream received event SEND_SHUTDOWN_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#51866944,HandleEvent,[strm][0x1B61268F510] Stream received event SHUTDOWN_COMPLETE ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#51866944,HandleEventConnectionClose,[strm][0x1B61268F510] Stream handling connection [conn][0x1B6123E5020] close ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49428546,NativeCallbackHandler,[conn][0x1B6123E5020] Connection received event SHUTDOWN_COMPLETE ->
dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Quic[10]
      Stream id "0HMC9MO6SIKV2:00000003" shutting down writes because: "Operation aborted.".
Author: JamesNK
Assignees: -
Labels:

area-System.Net.Http

Milestone: -

@dotnet-issue-labeler dotnet-issue-labeler bot added the untriaged New issue has not been triaged by the area owner label Oct 7, 2021
@ManickaP
Copy link
Member

ManickaP commented Oct 7, 2021

We should set up AbortErrorCode in SHUTDOWN_INITIATED_BY_TRANSPORT handler (or add different field for ShutdownInitiatedByTransport.Status) since we use it to distinguish between our and peer initiated connection close.
The fix should be fairly easy.

@CarnaViire
Copy link
Member

CarnaViire commented Oct 7, 2021

Status is a different thing from ErrorCode -- values for QUIC_STATUS are defined in msquic, while ErrorCode values are defined on application level. Same integer will mean different things, so I don't think that assigning Status value to ErrorCode is correct - the user who will receive QuicConnectionAbortedException may misinterpret the value. For 7.0 we should think this through -- add another field to the exception, or add another exception, or something else.

For 6.0 though, when SHUTDOWN_INITIATED_BY_TRANSPORT is received, it should be enough to change connection's AbortErrorCode to something not-clashing with H3 codes and different from default value "-1" -- to trigger required QuicConnectionAbortedException. Potential values are:

  • 0 (used for closing on Dispose, not overlapping with H3 codes),
  • H3_INTERNAL_ERROR (though H3 code will look a bit weird hardcoded into Quic)
  • 0xffffffff
  • something else?

Thoughts?

@JamesNK
Copy link
Member Author

JamesNK commented Oct 7, 2021

Another option could be to throw a new exception, e.g. QuicConnectionClosedException for SHUTDOWN_INITIATED_BY_TRANSPORT.

Updating Kestrel to catch a new error is simple enough (edit: as long as it is just from AcceptStreamAsync. If a new exception could throw from multiple places then I worry about catching them all).

@CarnaViire
Copy link
Member

CarnaViire commented Oct 7, 2021

Does Kestrel also check for QuicOperationAbortedException vs QuicConnectionAbortedException for QuicStream operations?

When a stream operation is aborted due to Connection being closed, one of there exceptions is thrown depending on who closed the connection.

@CarnaViire
Copy link
Member

Then I would say changing AbortErrorCode is way easier since it's a one-liner on Quic side and no changes from Kestrel side.

Different exception is more logical, but more risky, since it requires more changes, in 2-3 places in Quic and 2-3 places in Kestrel + some worries whether we got all the places.

@JamesNK
Copy link
Member Author

JamesNK commented Oct 7, 2021

Sure, I agree.

@ManickaP
Copy link
Member

ManickaP commented Oct 8, 2021

Status is a different thing from ErrorCode

Yes, I know. That's why I wrote 'We should set up AbortErrorCode or add different field for ShutdownInitiatedByTransport.Status'. I never meant setting up status into AbortErrorCode directly, but I probably didn't express myself properly.

Then I would say changing AbortErrorCode is way easier since it's a one-liner on Quic side and no changes from Kestrel side.

That's what I exactly meant, just this field to anything non -1 suffices ATM.

@ManickaP
Copy link
Member

ManickaP commented Oct 8, 2021

Because Kestrel didn't abort the connection, and it is waiting for QuicConnectionAbortedException to indicate the peer closed the connection, the HTTP/3 connection stays open in a bad state.

@JamesNK Do I understand right that if you get QuicOperationAbortedException from AcceptStream you'll just try again to call AcceptStream on the same connection? That doesn't sound right.

@JamesNK
Copy link
Member Author

JamesNK commented Oct 10, 2021

@JamesNK Do I understand right that if you get QuicOperationAbortedException from AcceptStream you'll just try again to call AcceptStream on the same connection? That doesn't sound right.

There is an assumption in Kestrel that this error is only thrown from QuicConnection.AcceptStreamAsync after the server has aborted the connection.

PR to fix that here: dotnet/aspnetcore#37432

@karelz karelz added this to the 6.0.0 milestone Oct 11, 2021
@karelz karelz added bug and removed untriaged New issue has not been triaged by the area owner labels Oct 11, 2021
@ghost ghost added in-pr There is an active PR which will close this issue when it is merged and removed in-pr There is an active PR which will close this issue when it is merged labels Oct 11, 2021
@ManickaP
Copy link
Member

Duplicate of #55157

@ManickaP ManickaP marked this as a duplicate of #55157 Oct 26, 2021
@ManickaP ManickaP removed their assignment Oct 26, 2021
@karelz karelz modified the milestones: 6.0.0, 7.0.0 Nov 4, 2021
@ghost ghost locked as resolved and limited conversation to collaborators Dec 4, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants