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.

Sign up for GitHub

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

Jump to bottom

[HTTP/3] Cancellation of response download not reported correctly on server #56129

Closed
JamesNK opened this issue Jul 22, 2021 · 18 comments · Fixed by #57156
Closed

[HTTP/3] Cancellation of response download not reported correctly on server #56129

JamesNK opened this issue Jul 22, 2021 · 18 comments · Fixed by #57156
Assignees
@ManickaP
Labels
area-System.Net.Http blocking-release bug tenet-reliability Reliability/stability related issue (stress, load problems, etc.)
Milestone
6.0.0

Comments

@JamesNK
Copy link
Member

JamesNK commented Jul 22, 2021 •
edited by karelz
Loading

Justification for 6.0: Causes data loss / data corruption on server side.

Reproduction: #56129 (comment)

  1. Client calls server
  2. Client sends data
  3. Client pauses sending.
  4. Server reads data
  5. Server sends data
  6. Server pauses sending.
  7. Client reads data
  8. Client cancels request (HttpResponseMessage.Dispose())
  9. Server QuicStream.ReadAsync doesn't throw QuicStreamAbortedException. Instead QuicStream.ReadAsync returns a read count of 0.
  10. Server never raises its HttpContext.RequestAbort cancellation token because it never saw the abort.

Logs

 Interop.FunctionalTests.Http3.Http3RequestTests.Bidirectional_ClientCancellationAfterResponseReceived_ServerGetsCancellation
   Source: Http3RequestTests.cs line 77
   Duration: 5.4 sec

  Message: 
System.TimeoutException : The operation has timed out.

  Stack Trace: 
TaskExtensions.TimeoutAfter(Task task, TimeSpan timeout, String filePath, Int32 lineNumber) line 125
Http3RequestTests.Bidirectional_ClientCancellationAfterResponseReceived_ServerGetsCancellation() line 145
--- End of stack trace from previous location ---

  Standard Output: 
| [0.009s] TestLifetime Information: Starting test Bidirectional_ClientCancellationAfterResponseReceived_ServerGetsCancellation at 2021-07-22T03:15:33
<- Event Private.InternalDiagnostics.System.Net.Http - Info : SocketsHttpHandler#2889227,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpClient#21168530,.ctor,HttpClient#21168530,SocketsHttpHandler#2889227 ->
| [0.069s] Microsoft.Extensions.Hosting.Internal.Host Debug: Hosting starting
| [0.105s] Microsoft.AspNetCore.Server.Kestrel.Core.KestrelServer Debug: Using development certificate: CN=localhost (Thumbprint: 2584996C10BB6B5D974C7FF0A7D513F6E9BD16B8)
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49467480,.ctor,[list][0x22CD09646E0] Listener created ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49467480,.ctor,[list][0x22CD09646E0] Listener started ->
| [0.149s] Microsoft.Hosting.Lifetime Information: Now listening on: https://127.0.0.1:61512
| [0.155s] Microsoft.AspNetCore.Hosting.Diagnostics Debug: Loaded hosting startup assembly Interop.FunctionalTests
| [0.156s] Microsoft.Hosting.Lifetime Information: Application started. Press Ctrl+C to shut down.
| [0.156s] Microsoft.Hosting.Lifetime Information: Hosting environment: Production
| [0.156s] Microsoft.Hosting.Lifetime Information: Content root path: C:\Development\Source\AspNetCore\artifacts\bin\Interop.FunctionalTests\Debug\net6.0\
| [0.156s] Microsoft.Extensions.Hosting.Internal.Host Debug: Hosting started
<- Event Private.InternalDiagnostics.System.Net.Http - Info : StreamingHttpContext#4530763,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpRequestMessage#38803894,Content,HttpRequestMessage#38803894,StreamingHttpContext#4530763 ->
<- Event System.Net.Http - RequestStart : https,127.0.0.1,61512,/,3,0,2 ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#43340473,.ctor,AutoConfigUrl=(null), AutoDetect=True, Proxy=(null), ProxyBypass=(null) ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#43340473,.ctor,_useProxy=True ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#43340473,TryCreate,AutoSettingsUsed, calling WinHttpOpen ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionHandler#15343725,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : DiagnosticsHandler#7911073,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : RedirectHandler#16633715,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - ErrorMessage : WinInetProxyHelper#43340473,GetProxyForUrl,error=12180 ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#43340473,GetProxyForUrl,useProxy=False ->
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 60604200,0,0,.ctor,HttpConnectionPool https://127.0.0.1:61512 ->
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 60604200,0,0,GetHttp3ConnectionAsync,Attempting new HTTP3 connection. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,.ctor,[conn][0x22CD0969FA0] Outbound connection created ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6451435,.ctor,[conn][0x22CD0E62F40] Inbound connection created ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6451435,NativeCallbackHandler,[conn][0x22CD0E62F40] Connection received event IDEAL_PROCESSOR_CHANGED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,NativeCallbackHandler,[conn][0x22CD0969FA0] Connection received event STREAMS_AVAILABLE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,NativeCallbackHandler,[conn][0x22CD0969FA0] Connection received event DATAGRAM_STATE_CHANGED ->
| [0.209s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Connection id "0HMACNRS3J8IG" accepted.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,NativeCallbackHandler,[conn][0x22CD0969FA0] Connection received event PEER_CERTIFICATE_RECEIVED ->
| [0.216s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Connection id "0HMACNRS3J8IG" accepted.
| [0.219s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Connection id "0HMACNRS3J8IG" started.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34717384,HandleEvent,(null) Stream received event START_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34717384,.ctor,[strm][0x22CD096DFA0] Outbound unidirectional stream created in connection [conn][0x22CD0E62F40]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,HandleEventPeerCertificateReceived,[conn][0x22CD0969FA0] Certificate validation for '$CN=localhost' finished with $None ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,NativeCallbackHandler,[conn][0x22CD0969FA0] Connection received event CONNECTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6451435,NativeCallbackHandler,[conn][0x22CD0E62F40] Connection received event CONNECTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22460983,HandleEvent,(null) Stream received event START_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22460983,.ctor,[strm][0x22CD096DB30] Outbound unidirectional stream created in connection [conn][0x22CD0969FA0]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22460983,HandleEvent,[strm][0x22CD096DB30] Stream received event SEND_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6451435,NativeCallbackHandler,[conn][0x22CD0E62F40] Connection received event PEER_STREAM_STARTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#60644701,.ctor,[strm][0x22CD0EAE4D0] Inbound unidirectional stream created in connection [conn][0x22CD0E62F40]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#60644701,HandleEvent,[strm][0x22CD0EAE4D0] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 60604200,0,0,GetHttp3ConnectionAsync,New HTTP3 connection established. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,HandleEvent,(null) Stream received event START_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,.ctor,[strm][0x22CD0EAE790] Outbound bidirectional stream created in connection [conn][0x22CD0969FA0]. ->
| [0.244s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMACNRS3J8IG:3" type Unidirectional connected.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,ReadAsync,[strm][0x22CD0EAE790] Stream reading into Memory of '64' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,HandleEvent,[strm][0x22CD0EAE790] Stream received event SEND_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6451435,NativeCallbackHandler,[conn][0x22CD0E62F40] Connection received event PEER_STREAM_STARTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,.ctor,[strm][0x22CD0EAEAF0] Inbound bidirectional stream created in connection [conn][0x22CD0E62F40]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEvent,[strm][0x22CD0EAEAF0] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34717384,HandleEvent,[strm][0x22CD096DFA0] Stream received event SEND_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,NativeCallbackHandler,[conn][0x22CD0969FA0] Connection received event PEER_STREAM_STARTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,.ctor,[strm][0x22CD0E781B0] Inbound unidirectional stream created in connection [conn][0x22CD0969FA0]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,HandleEvent,[strm][0x22CD0E781B0] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,ReadAsync,[strm][0x22CD0E781B0] Stream reading into Memory of '32' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,ReadAsync,[strm][0x22CD0E781B0] Stream reading into Memory of '32' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34717384,HandleEvent,[strm][0x22CD096DFA0] Stream received event SEND_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,HandleEvent,[strm][0x22CD0E781B0] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34717384,HandleEvent,[strm][0x22CD096DFA0] Stream received event IDEAL_SEND_BUFFER_SIZE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#60644701,ReadAsync,[strm][0x22CD0EAE4D0] Stream reading into Memory of '4096' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,ReadAsync,[strm][0x22CD0E781B0] Stream reading into Memory of '32' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#60644701,ReadAsync,[strm][0x22CD0EAE4D0] Stream reading into Memory of '4096' bytes. ->
| [0.267s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMACNRS3J8IG:2" type Unidirectional accepted.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,ReadAsync,[strm][0x22CD0EAEAF0] Stream reading into Memory of '4096' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,ReadAsync,[strm][0x22CD0EAEAF0] Stream reading into Memory of '4096' bytes. ->
| [0.268s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMACNRS3J8IG:0" type Bidirectional accepted.
| [0.276s] Microsoft.AspNetCore.Server.Kestrel.Http3 Trace: Connection id "0HMACNRS3J8IG:2" received SETTINGS frame for stream ID 2 with length 5.
| [0.279s] Microsoft.AspNetCore.Server.Kestrel.Http3 Trace: Connection id "0HMACNRS3J8IG:0" received HEADERS frame for stream ID 0 with length 48.
| [0.301s] Microsoft.AspNetCore.Server.Kestrel.Http3 Trace: Connection id "0HMACNRS3J8IG:0" received DATA frame for stream ID 0 with length 11.
| [0.324s] Microsoft.AspNetCore.Hosting.Diagnostics Information: Request starting HTTP/3 POST https://127.0.0.1:61512/ - -
| [0.332s] Interop.FunctionalTests.Http3.Http3RequestTests Information: Flush headers on server
| [0.341s] Microsoft.AspNetCore.Server.Kestrel.Http3 Trace: Connection id "0HMACNRS3J8IG:0" sending HEADERS frame for stream ID 0 with length 53.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEvent,[strm][0x22CD0EAEAF0] Stream received event SEND_COMPLETE ->
| [0.342s] Interop.FunctionalTests.Http3.Http3RequestTests Information: Server read body
| [0.346s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HMACNRS3J8IG:0", Request id "0HMACNRS3J8IG:0": started reading request body.
| [0.351s] Microsoft.AspNetCore.Server.Kestrel.Http3 Trace: Connection id "0HMACNRS3J8IG:0" sending DATA frame for stream ID 0 with length 11.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEvent,[strm][0x22CD0EAEAF0] Stream received event SEND_COMPLETE ->
| [0.352s] Interop.FunctionalTests.Http3.Http3RequestTests Information: Server wait for abort
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,HandleEvent,[strm][0x22CD0EAE790] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,HandleEvent,[strm][0x22CD0EAE790] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEvent,[strm][0x22CD0EAEAF0] Stream received event IDEAL_SEND_BUFFER_SIZE ->
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 60604200,36620877,0,ReadFrameEnvelopeAsync,Received frame 1 of length 53. ->
<- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#61858317,RequestMessage,HttpResponseMessage#61858317,HttpRequestMessage#38803894 ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionResponseContent#57265338,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#61858317,Content,HttpResponseMessage#61858317,HttpConnectionResponseContent#57265338 ->
<- Event System.Net.Http - RequestStop :  ->
| [0.370s] Interop.FunctionalTests.Http3.Http3RequestTests Information: Client read body
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 60604200,36620877,0,ReadFrameEnvelopeAsync,Received frame 0 of length 11. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,ReadAsync,[strm][0x22CD0EAE790] Stream reading into Memory of '4' bytes. ->
| [0.371s] Interop.FunctionalTests.Http3.Http3RequestTests Information: Client canceling
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,Dispose,[strm][0x22CD0EAE790] Stream disposing True ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,Dispose,[strm][0x22CD0EAE790] Stream disposed ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEvent,[strm][0x22CD0EAEAF0] Stream received event PEER_RECEIVE_ABORTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEvent,[strm][0x22CD0EAEAF0] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEvent,[strm][0x22CD0EAEAF0] Stream received event PEER_SEND_SHUTDOWN ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEventPeerSendShutdown,[strm][0x22CD0EAEAF0] Stream completing resettable event source. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,HandleEvent,[strm][0x22CD0EAE790] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,HandleEvent,[strm][0x22CD0EAE790] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,HandleEventShutdownComplete,[strm][0x22CD0EAE790] Stream completing resettable event source. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,Cleanup,[strm][0x22CD0EAE790] releasing handles. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEvent,[strm][0x22CD0EAEAF0] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEvent,[strm][0x22CD0EAEAF0] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEventShutdownComplete,[strm][0x22CD0EAEAF0] Stream completing resettable event source. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,NativeCallbackHandler,[conn][0x22CD0969FA0] Connection received event STREAMS_AVAILABLE ->
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 60604200,0,0,Dispose,Disposing pool. ->
| [5.399s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Listener has aborted with exception: Operation aborted.
| [5.401s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Connection id "0HMACNRS3J8IG" aborted by application because: "The connection was aborted by the application via MultiplexedConnectionContext.Abort().".
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#60644701,HandleEvent,[strm][0x22CD0EAE4D0] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#60644701,HandleEventConnectionClose,[strm][0x22CD0EAE4D0] Stream handling connection [conn][0x22CD0E62F40] close ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34717384,HandleEvent,[strm][0x22CD096DFA0] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34717384,HandleEvent,[strm][0x22CD096DFA0] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34717384,HandleEventConnectionClose,[strm][0x22CD096DFA0] Stream handling connection [conn][0x22CD0E62F40] close ->
| [5.405s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Some connections failed to close gracefully during server shutdown.
| [5.410s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Connection id "0HMACNRS3J8IG" aborted by application because: "The connection was aborted because the server is shutting down and request processing didn't complete within the time specified by HostOptions.ShutdownTimeout.".
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,NativeCallbackHandler,[conn][0x22CD0969FA0] Connection received event SHUTDOWN_INITIATED_BY_PEER ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22460983,HandleEvent,[strm][0x22CD096DB30] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22460983,HandleEvent,[strm][0x22CD096DB30] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22460983,HandleEventConnectionClose,[strm][0x22CD096DB30] Stream handling connection [conn][0x22CD0969FA0] close with code 256 ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,HandleEvent,[strm][0x22CD0E781B0] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,HandleEventConnectionClose,[strm][0x22CD0E781B0] Stream handling connection [conn][0x22CD0969FA0] close with code 256 ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22460983,Dispose,[strm][0x22CD096DB30] Stream disposing True ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22460983,Dispose,[strm][0x22CD096DB30] Stream disposed ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,NativeCallbackHandler,[conn][0x22CD0969FA0] Connection received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6451435,NativeCallbackHandler,[conn][0x22CD0E62F40] Connection received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,Dispose,[conn][0x22CD0969FA0] Stream disposing True ->
| [5.423s] Microsoft.AspNetCore.Server.Kestrel.Http3 Debug: Connection id "0HMACNRS3J8IG" is closing.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,Dispose,[strm][0x22CD0E781B0] Stream disposing True ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,Dispose,[strm][0x22CD0E781B0] Stream disposed ->
| [5.425s] Microsoft.AspNetCore.Server.Kestrel.Http3 Trace: Connection id "(null)" sending GO_AWAY frame for stream ID 3 with length 8.
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 60604200,36620877,0,Abort,abortException==System.Net.Quic.QuicConnectionAbortedException: Connection aborted by peer (256).
   at System.Net.Quic.Implementations.MsQuic.MsQuicStream.HandleEventConnectionClose(State state) in System.Net.Quic.dll:token 0x6000159+0x109
   at System.Net.Quic.Implementations.MsQuic.MsQuicStream.HandleEventShutdownComplete(State state, StreamEvent& evt) in System.Net.Quic.dll:token 0x600014e+0x14
   at System.Net.Quic.Implementations.MsQuic.MsQuicStream.HandleEvent(State state, StreamEvent& evt) in System.Net.Quic.dll:token 0x6000149+0xbc
   at System.Net.Quic.Implementations.MsQuic.MsQuicStream.NativeCallbackHandler(IntPtr stream, IntPtr context, StreamEvent& streamEvent) in System.Net.Quic.dll:token 0x6000148+0x14
--- End of stack trace from previous location ---
   at System.Net.Quic.Implementations.MsQuic.Internal.ResettableCompletionSource`1.GetResult(Int16 token) in System.Net.Quic.dll:token 0x600019d+0xf
   at System.Net.Http.Http3Connection.<>c__DisplayClass45_0.<<ProcessServerControlStreamAsync>g__ReadFrameEnvelopeAsync|0>d.MoveNext() in System.Net.Http.dll:token 0x60006aa+0x9d
--- End of stack trace from previous location ---
   at System.Net.Http.Http3Connection.ProcessServerControlStreamAsync(QuicStream stream, ArrayBuffer buffer) in System.Net.Http.dll:token 0x6000699+0x21c
   at System.Net.Http.Http3Connection.ProcessServerStreamAsync(QuicStream stream) in System.Net.Http.dll:token 0x6000698+0x204
   at System.Net.Http.Http3Connection.ProcessServerStreamAsync(QuicStream stream) in System.Net.Http.dll:token 0x6000698+0x4fb ->
| [5.427s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMACNRS3J8IG:3" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
| [5.430s] Microsoft.AspNetCore.Server.Kestrel.Http3 Debug: Connection id "0HMACNRS3J8IG" is closed. The last processed stream ID was 0.
| [5.434s] Microsoft.AspNetCore.Server.Kestrel.Http3 Trace: Connection id "(null)" sending GO_AWAY frame for stream ID 3 with length 1.
| [5.434s] Microsoft.AspNetCore.Server.Kestrel.Http3 Debug: Trace id "0HMACNRS3J8IG:0": HTTP/3 stream error "H3_NO_ERROR". An abort is being sent to the stream.
| Microsoft.AspNetCore.Connections.ConnectionAbortedException: The HTTP/3 connection faulted.
| [5.435s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMACNRS3J8IG:0" aborted by application because: "The HTTP/3 connection faulted.".
| [5.435s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMACNRS3J8IG:0" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
| [5.438s] Microsoft.AspNetCore.Server.Kestrel.Http3 Debug: Trace id "(null)": HTTP/3 stream error "H3_NO_ERROR". An abort is being sent to the stream.
| Microsoft.AspNetCore.Connections.ConnectionAbortedException: The HTTP/3 connection faulted.
| [5.438s] Interop.FunctionalTests.Http3.Http3RequestTests Information: Server RequestAborted token raised.
| [5.438s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMACNRS3J8IG:3" aborted by application because: "The HTTP/3 connection faulted.".
| [5.439s] Microsoft.AspNetCore.Hosting.Diagnostics Information: Request finished HTTP/3 POST https://127.0.0.1:61512/ - - - 200 - - 5116.4570ms
| [5.443s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HMACNRS3J8IG:0", Request id "0HMACNRS3J8IG:0": done reading request body.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,Dispose,[strm][0x22CD0EAEAF0] Stream disposing True ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,Cleanup,[strm][0x22CD0EAEAF0] releasing handles. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,Dispose,[strm][0x22CD0EAEAF0] Stream disposed ->
| [5.446s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Connection id "0HMACNRS3J8IG" stopped.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6451435,Dispose,[conn][0x22CD0E62F40] Stream disposing True ->
| [5.455s] Interop.FunctionalTests.Http3.Http3RequestTests Error: Test threw an exception.
| System.TimeoutException: The operation has timed out.
|    at Microsoft.AspNetCore.Testing.TaskExtensions.TimeoutAfter(Task task, TimeSpan timeout, String filePath, Int32 lineNumber) in C:\Development\Source\AspNetCore\src\Shared\TaskExtensions.cs:line 125
|    at Interop.FunctionalTests.Http3.Http3RequestTests.Bidirectional_ClientCancellationAfterResponseReceived_ServerGetsCancellation() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\test\Interop.FunctionalTests\Http3\Http3RequestTests.cs:line 145
|    at Xunit.Sdk.TestInvoker`1.<>c__DisplayClass48_1.<<InvokeTestMethodAsync>b__1>d.MoveNext() in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\Runners\TestInvoker.cs:line 264
| --- End of stack trace from previous location ---
|    at Xunit.Sdk.ExecutionTimer.AggregateAsync(Func`1 asyncAction) in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\ExecutionTimer.cs:line 48
|    at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in C:\Dev\xunit\xunit\src\xunit.core\Sdk\ExceptionAggregator.cs:line 90
| [5.465s] TestLifetime Information: Finished test Bidirectional_ClientCancellationAfterResponseReceived_ServerGetsCancellation in 5.4616622s

.NET SDK (reflecting any global.json):
 Version:   6.0.100-rc.1.21370.2
 Commit:    64c36e46ff
@ghost
Copy link

ghost commented Jul 22, 2021

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

Issue Details
  1. Client calls server
  2. Client sends data
  3. Server reads data
  4. Server sends data
  5. Client reads data
  6. Client cancels request (HttpResponseMessage.Dispose())
  7. QuicStream.ReadAsync doesn't throw QuicStreamAbortedException. Instead QuicStream.ReadAsync returns a read count of 0.
  8. Server never raises its HttpContext.RequestAbort cancellation token because it never saw the cancellation.

Logs

 Interop.FunctionalTests.Http3.Http3RequestTests.Bidirectional_ClientCancellationAfterResponseReceived_ServerGetsCancellation
   Source: Http3RequestTests.cs line 77
   Duration: 5.4 sec

  Message: 
System.TimeoutException : The operation has timed out.

  Stack Trace: 
TaskExtensions.TimeoutAfter(Task task, TimeSpan timeout, String filePath, Int32 lineNumber) line 125
Http3RequestTests.Bidirectional_ClientCancellationAfterResponseReceived_ServerGetsCancellation() line 145
--- End of stack trace from previous location ---

  Standard Output: 
| [0.009s] TestLifetime Information: Starting test Bidirectional_ClientCancellationAfterResponseReceived_ServerGetsCancellation at 2021-07-22T03:15:33
<- Event Private.InternalDiagnostics.System.Net.Http - Info : SocketsHttpHandler#2889227,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpClient#21168530,.ctor,HttpClient#21168530,SocketsHttpHandler#2889227 ->
| [0.069s] Microsoft.Extensions.Hosting.Internal.Host Debug: Hosting starting
| [0.105s] Microsoft.AspNetCore.Server.Kestrel.Core.KestrelServer Debug: Using development certificate: CN=localhost (Thumbprint: 2584996C10BB6B5D974C7FF0A7D513F6E9BD16B8)
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49467480,.ctor,[list][0x22CD09646E0] Listener created ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49467480,.ctor,[list][0x22CD09646E0] Listener started ->
| [0.149s] Microsoft.Hosting.Lifetime Information: Now listening on: https://127.0.0.1:61512
| [0.155s] Microsoft.AspNetCore.Hosting.Diagnostics Debug: Loaded hosting startup assembly Interop.FunctionalTests
| [0.156s] Microsoft.Hosting.Lifetime Information: Application started. Press Ctrl+C to shut down.
| [0.156s] Microsoft.Hosting.Lifetime Information: Hosting environment: Production
| [0.156s] Microsoft.Hosting.Lifetime Information: Content root path: C:\Development\Source\AspNetCore\artifacts\bin\Interop.FunctionalTests\Debug\net6.0\
| [0.156s] Microsoft.Extensions.Hosting.Internal.Host Debug: Hosting started
<- Event Private.InternalDiagnostics.System.Net.Http - Info : StreamingHttpContext#4530763,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpRequestMessage#38803894,Content,HttpRequestMessage#38803894,StreamingHttpContext#4530763 ->
<- Event System.Net.Http - RequestStart : https,127.0.0.1,61512,/,3,0,2 ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#43340473,.ctor,AutoConfigUrl=(null), AutoDetect=True, Proxy=(null), ProxyBypass=(null) ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#43340473,.ctor,_useProxy=True ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#43340473,TryCreate,AutoSettingsUsed, calling WinHttpOpen ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionHandler#15343725,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : DiagnosticsHandler#7911073,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : RedirectHandler#16633715,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - ErrorMessage : WinInetProxyHelper#43340473,GetProxyForUrl,error=12180 ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#43340473,GetProxyForUrl,useProxy=False ->
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 60604200,0,0,.ctor,HttpConnectionPool https://127.0.0.1:61512 ->
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 60604200,0,0,GetHttp3ConnectionAsync,Attempting new HTTP3 connection. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,.ctor,[conn][0x22CD0969FA0] Outbound connection created ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6451435,.ctor,[conn][0x22CD0E62F40] Inbound connection created ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6451435,NativeCallbackHandler,[conn][0x22CD0E62F40] Connection received event IDEAL_PROCESSOR_CHANGED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,NativeCallbackHandler,[conn][0x22CD0969FA0] Connection received event STREAMS_AVAILABLE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,NativeCallbackHandler,[conn][0x22CD0969FA0] Connection received event DATAGRAM_STATE_CHANGED ->
| [0.209s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Connection id "0HMACNRS3J8IG" accepted.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,NativeCallbackHandler,[conn][0x22CD0969FA0] Connection received event PEER_CERTIFICATE_RECEIVED ->
| [0.216s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Connection id "0HMACNRS3J8IG" accepted.
| [0.219s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Connection id "0HMACNRS3J8IG" started.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34717384,HandleEvent,(null) Stream received event START_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34717384,.ctor,[strm][0x22CD096DFA0] Outbound unidirectional stream created in connection [conn][0x22CD0E62F40]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,HandleEventPeerCertificateReceived,[conn][0x22CD0969FA0] Certificate validation for '$CN=localhost' finished with $None ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,NativeCallbackHandler,[conn][0x22CD0969FA0] Connection received event CONNECTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6451435,NativeCallbackHandler,[conn][0x22CD0E62F40] Connection received event CONNECTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22460983,HandleEvent,(null) Stream received event START_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22460983,.ctor,[strm][0x22CD096DB30] Outbound unidirectional stream created in connection [conn][0x22CD0969FA0]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22460983,HandleEvent,[strm][0x22CD096DB30] Stream received event SEND_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6451435,NativeCallbackHandler,[conn][0x22CD0E62F40] Connection received event PEER_STREAM_STARTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#60644701,.ctor,[strm][0x22CD0EAE4D0] Inbound unidirectional stream created in connection [conn][0x22CD0E62F40]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#60644701,HandleEvent,[strm][0x22CD0EAE4D0] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 60604200,0,0,GetHttp3ConnectionAsync,New HTTP3 connection established. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,HandleEvent,(null) Stream received event START_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,.ctor,[strm][0x22CD0EAE790] Outbound bidirectional stream created in connection [conn][0x22CD0969FA0]. ->
| [0.244s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMACNRS3J8IG:3" type Unidirectional connected.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,ReadAsync,[strm][0x22CD0EAE790] Stream reading into Memory of '64' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,HandleEvent,[strm][0x22CD0EAE790] Stream received event SEND_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6451435,NativeCallbackHandler,[conn][0x22CD0E62F40] Connection received event PEER_STREAM_STARTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,.ctor,[strm][0x22CD0EAEAF0] Inbound bidirectional stream created in connection [conn][0x22CD0E62F40]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEvent,[strm][0x22CD0EAEAF0] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34717384,HandleEvent,[strm][0x22CD096DFA0] Stream received event SEND_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,NativeCallbackHandler,[conn][0x22CD0969FA0] Connection received event PEER_STREAM_STARTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,.ctor,[strm][0x22CD0E781B0] Inbound unidirectional stream created in connection [conn][0x22CD0969FA0]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,HandleEvent,[strm][0x22CD0E781B0] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,ReadAsync,[strm][0x22CD0E781B0] Stream reading into Memory of '32' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,ReadAsync,[strm][0x22CD0E781B0] Stream reading into Memory of '32' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34717384,HandleEvent,[strm][0x22CD096DFA0] Stream received event SEND_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,HandleEvent,[strm][0x22CD0E781B0] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34717384,HandleEvent,[strm][0x22CD096DFA0] Stream received event IDEAL_SEND_BUFFER_SIZE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#60644701,ReadAsync,[strm][0x22CD0EAE4D0] Stream reading into Memory of '4096' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,ReadAsync,[strm][0x22CD0E781B0] Stream reading into Memory of '32' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#60644701,ReadAsync,[strm][0x22CD0EAE4D0] Stream reading into Memory of '4096' bytes. ->
| [0.267s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMACNRS3J8IG:2" type Unidirectional accepted.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,ReadAsync,[strm][0x22CD0EAEAF0] Stream reading into Memory of '4096' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,ReadAsync,[strm][0x22CD0EAEAF0] Stream reading into Memory of '4096' bytes. ->
| [0.268s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMACNRS3J8IG:0" type Bidirectional accepted.
| [0.276s] Microsoft.AspNetCore.Server.Kestrel.Http3 Trace: Connection id "0HMACNRS3J8IG:2" received SETTINGS frame for stream ID 2 with length 5.
| [0.279s] Microsoft.AspNetCore.Server.Kestrel.Http3 Trace: Connection id "0HMACNRS3J8IG:0" received HEADERS frame for stream ID 0 with length 48.
| [0.301s] Microsoft.AspNetCore.Server.Kestrel.Http3 Trace: Connection id "0HMACNRS3J8IG:0" received DATA frame for stream ID 0 with length 11.
| [0.324s] Microsoft.AspNetCore.Hosting.Diagnostics Information: Request starting HTTP/3 POST https://127.0.0.1:61512/ - -
| [0.332s] Interop.FunctionalTests.Http3.Http3RequestTests Information: Flush headers on server
| [0.341s] Microsoft.AspNetCore.Server.Kestrel.Http3 Trace: Connection id "0HMACNRS3J8IG:0" sending HEADERS frame for stream ID 0 with length 53.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEvent,[strm][0x22CD0EAEAF0] Stream received event SEND_COMPLETE ->
| [0.342s] Interop.FunctionalTests.Http3.Http3RequestTests Information: Server read body
| [0.346s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HMACNRS3J8IG:0", Request id "0HMACNRS3J8IG:0": started reading request body.
| [0.351s] Microsoft.AspNetCore.Server.Kestrel.Http3 Trace: Connection id "0HMACNRS3J8IG:0" sending DATA frame for stream ID 0 with length 11.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEvent,[strm][0x22CD0EAEAF0] Stream received event SEND_COMPLETE ->
| [0.352s] Interop.FunctionalTests.Http3.Http3RequestTests Information: Server wait for abort
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,HandleEvent,[strm][0x22CD0EAE790] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,HandleEvent,[strm][0x22CD0EAE790] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEvent,[strm][0x22CD0EAEAF0] Stream received event IDEAL_SEND_BUFFER_SIZE ->
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 60604200,36620877,0,ReadFrameEnvelopeAsync,Received frame 1 of length 53. ->
<- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#61858317,RequestMessage,HttpResponseMessage#61858317,HttpRequestMessage#38803894 ->
<- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionResponseContent#57265338,.ctor, ->
<- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#61858317,Content,HttpResponseMessage#61858317,HttpConnectionResponseContent#57265338 ->
<- Event System.Net.Http - RequestStop :  ->
| [0.370s] Interop.FunctionalTests.Http3.Http3RequestTests Information: Client read body
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 60604200,36620877,0,ReadFrameEnvelopeAsync,Received frame 0 of length 11. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,ReadAsync,[strm][0x22CD0EAE790] Stream reading into Memory of '4' bytes. ->
| [0.371s] Interop.FunctionalTests.Http3.Http3RequestTests Information: Client canceling
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,Dispose,[strm][0x22CD0EAE790] Stream disposing True ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,Dispose,[strm][0x22CD0EAE790] Stream disposed ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEvent,[strm][0x22CD0EAEAF0] Stream received event PEER_RECEIVE_ABORTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEvent,[strm][0x22CD0EAEAF0] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEvent,[strm][0x22CD0EAEAF0] Stream received event PEER_SEND_SHUTDOWN ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEventPeerSendShutdown,[strm][0x22CD0EAEAF0] Stream completing resettable event source. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,HandleEvent,[strm][0x22CD0EAE790] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,HandleEvent,[strm][0x22CD0EAE790] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,HandleEventShutdownComplete,[strm][0x22CD0EAE790] Stream completing resettable event source. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#30135413,Cleanup,[strm][0x22CD0EAE790] releasing handles. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEvent,[strm][0x22CD0EAEAF0] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEvent,[strm][0x22CD0EAEAF0] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,HandleEventShutdownComplete,[strm][0x22CD0EAEAF0] Stream completing resettable event source. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,NativeCallbackHandler,[conn][0x22CD0969FA0] Connection received event STREAMS_AVAILABLE ->
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 60604200,0,0,Dispose,Disposing pool. ->
| [5.399s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Listener has aborted with exception: Operation aborted.
| [5.401s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Connection id "0HMACNRS3J8IG" aborted by application because: "The connection was aborted by the application via MultiplexedConnectionContext.Abort().".
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#60644701,HandleEvent,[strm][0x22CD0EAE4D0] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#60644701,HandleEventConnectionClose,[strm][0x22CD0EAE4D0] Stream handling connection [conn][0x22CD0E62F40] close ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34717384,HandleEvent,[strm][0x22CD096DFA0] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34717384,HandleEvent,[strm][0x22CD096DFA0] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34717384,HandleEventConnectionClose,[strm][0x22CD096DFA0] Stream handling connection [conn][0x22CD0E62F40] close ->
| [5.405s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Some connections failed to close gracefully during server shutdown.
| [5.410s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Connection id "0HMACNRS3J8IG" aborted by application because: "The connection was aborted because the server is shutting down and request processing didn't complete within the time specified by HostOptions.ShutdownTimeout.".
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,NativeCallbackHandler,[conn][0x22CD0969FA0] Connection received event SHUTDOWN_INITIATED_BY_PEER ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22460983,HandleEvent,[strm][0x22CD096DB30] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22460983,HandleEvent,[strm][0x22CD096DB30] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22460983,HandleEventConnectionClose,[strm][0x22CD096DB30] Stream handling connection [conn][0x22CD0969FA0] close with code 256 ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,HandleEvent,[strm][0x22CD0E781B0] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,HandleEventConnectionClose,[strm][0x22CD0E781B0] Stream handling connection [conn][0x22CD0969FA0] close with code 256 ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22460983,Dispose,[strm][0x22CD096DB30] Stream disposing True ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22460983,Dispose,[strm][0x22CD096DB30] Stream disposed ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,NativeCallbackHandler,[conn][0x22CD0969FA0] Connection received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6451435,NativeCallbackHandler,[conn][0x22CD0E62F40] Connection received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57906006,Dispose,[conn][0x22CD0969FA0] Stream disposing True ->
| [5.423s] Microsoft.AspNetCore.Server.Kestrel.Http3 Debug: Connection id "0HMACNRS3J8IG" is closing.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,Dispose,[strm][0x22CD0E781B0] Stream disposing True ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11373314,Dispose,[strm][0x22CD0E781B0] Stream disposed ->
| [5.425s] Microsoft.AspNetCore.Server.Kestrel.Http3 Trace: Connection id "(null)" sending GO_AWAY frame for stream ID 3 with length 8.
<- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 60604200,36620877,0,Abort,abortException==System.Net.Quic.QuicConnectionAbortedException: Connection aborted by peer (256).
   at System.Net.Quic.Implementations.MsQuic.MsQuicStream.HandleEventConnectionClose(State state) in System.Net.Quic.dll:token 0x6000159+0x109
   at System.Net.Quic.Implementations.MsQuic.MsQuicStream.HandleEventShutdownComplete(State state, StreamEvent& evt) in System.Net.Quic.dll:token 0x600014e+0x14
   at System.Net.Quic.Implementations.MsQuic.MsQuicStream.HandleEvent(State state, StreamEvent& evt) in System.Net.Quic.dll:token 0x6000149+0xbc
   at System.Net.Quic.Implementations.MsQuic.MsQuicStream.NativeCallbackHandler(IntPtr stream, IntPtr context, StreamEvent& streamEvent) in System.Net.Quic.dll:token 0x6000148+0x14
--- End of stack trace from previous location ---
   at System.Net.Quic.Implementations.MsQuic.Internal.ResettableCompletionSource`1.GetResult(Int16 token) in System.Net.Quic.dll:token 0x600019d+0xf
   at System.Net.Http.Http3Connection.<>c__DisplayClass45_0.<<ProcessServerControlStreamAsync>g__ReadFrameEnvelopeAsync|0>d.MoveNext() in System.Net.Http.dll:token 0x60006aa+0x9d
--- End of stack trace from previous location ---
   at System.Net.Http.Http3Connection.ProcessServerControlStreamAsync(QuicStream stream, ArrayBuffer buffer) in System.Net.Http.dll:token 0x6000699+0x21c
   at System.Net.Http.Http3Connection.ProcessServerStreamAsync(QuicStream stream) in System.Net.Http.dll:token 0x6000698+0x204
   at System.Net.Http.Http3Connection.ProcessServerStreamAsync(QuicStream stream) in System.Net.Http.dll:token 0x6000698+0x4fb ->
| [5.427s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMACNRS3J8IG:3" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
| [5.430s] Microsoft.AspNetCore.Server.Kestrel.Http3 Debug: Connection id "0HMACNRS3J8IG" is closed. The last processed stream ID was 0.
| [5.434s] Microsoft.AspNetCore.Server.Kestrel.Http3 Trace: Connection id "(null)" sending GO_AWAY frame for stream ID 3 with length 1.
| [5.434s] Microsoft.AspNetCore.Server.Kestrel.Http3 Debug: Trace id "0HMACNRS3J8IG:0": HTTP/3 stream error "H3_NO_ERROR". An abort is being sent to the stream.
| Microsoft.AspNetCore.Connections.ConnectionAbortedException: The HTTP/3 connection faulted.
| [5.435s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMACNRS3J8IG:0" aborted by application because: "The HTTP/3 connection faulted.".
| [5.435s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMACNRS3J8IG:0" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
| [5.438s] Microsoft.AspNetCore.Server.Kestrel.Http3 Debug: Trace id "(null)": HTTP/3 stream error "H3_NO_ERROR". An abort is being sent to the stream.
| Microsoft.AspNetCore.Connections.ConnectionAbortedException: The HTTP/3 connection faulted.
| [5.438s] Interop.FunctionalTests.Http3.Http3RequestTests Information: Server RequestAborted token raised.
| [5.438s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMACNRS3J8IG:3" aborted by application because: "The HTTP/3 connection faulted.".
| [5.439s] Microsoft.AspNetCore.Hosting.Diagnostics Information: Request finished HTTP/3 POST https://127.0.0.1:61512/ - - - 200 - - 5116.4570ms
| [5.443s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HMACNRS3J8IG:0", Request id "0HMACNRS3J8IG:0": done reading request body.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,Dispose,[strm][0x22CD0EAEAF0] Stream disposing True ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,Cleanup,[strm][0x22CD0EAEAF0] releasing handles. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13273752,Dispose,[strm][0x22CD0EAEAF0] Stream disposed ->
| [5.446s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Connection id "0HMACNRS3J8IG" stopped.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6451435,Dispose,[conn][0x22CD0E62F40] Stream disposing True ->
| [5.455s] Interop.FunctionalTests.Http3.Http3RequestTests Error: Test threw an exception.
| System.TimeoutException: The operation has timed out.
|    at Microsoft.AspNetCore.Testing.TaskExtensions.TimeoutAfter(Task task, TimeSpan timeout, String filePath, Int32 lineNumber) in C:\Development\Source\AspNetCore\src\Shared\TaskExtensions.cs:line 125
|    at Interop.FunctionalTests.Http3.Http3RequestTests.Bidirectional_ClientCancellationAfterResponseReceived_ServerGetsCancellation() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\test\Interop.FunctionalTests\Http3\Http3RequestTests.cs:line 145
|    at Xunit.Sdk.TestInvoker`1.<>c__DisplayClass48_1.<<InvokeTestMethodAsync>b__1>d.MoveNext() in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\Runners\TestInvoker.cs:line 264
| --- End of stack trace from previous location ---
|    at Xunit.Sdk.ExecutionTimer.AggregateAsync(Func`1 asyncAction) in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\ExecutionTimer.cs:line 48
|    at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in C:\Dev\xunit\xunit\src\xunit.core\Sdk\ExceptionAggregator.cs:line 90
| [5.465s] TestLifetime Information: Finished test Bidirectional_ClientCancellationAfterResponseReceived_ServerGetsCancellation in 5.4616622s

.NET SDK (reflecting any global.json):
 Version:   6.0.100-rc.1.21370.2
 Commit:    64c36e46ff
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 Jul 22, 2021
@CarnaViire
Copy link
Member

CarnaViire commented Jul 22, 2021 •
edited
Loading

@JamesNK when you saw this, did the code already contain changes from #55724 ? A lot of aborting issues were fixed in that PR

UPD:

Ok, I've re-read the description again. So, as I understand the description, client already has sent the request and now is reading a response. Why would server's ReadAsync throw? Server's reading side was finished already - I understand that from the fact that server is already sending the response. So server's ReadAsync will return 0 on the subsequent calls. Server's WriteAsync should properly throw though, because client has aborted reading in Dispose (fixed in #55724).

Please note that some first WriteAsync's after peer aborting might "succeed" because success would just mean buffering in transport and because of the timings of events arriving, I've mentioned it in that PR:

I've spent a lot of time digging why server didn't get StreamAbortedException on Write even after client clearly called AbortRead and it was synchronized by semaphores. I found out that it is possible that PEER_RECEIVE_ABORTED event will arrive with a significant delay after peer calls AbortRead. In that case even with synchronization via semaphores, first writes after peer aborting may "succeed" (get SEND_COMPLETE event). I ended up asserting that PEER_RECEIVE_ABORTED would arrive eventually.

@JamesNK
Copy link
Member Author

JamesNK commented Jul 22, 2021 •
edited
Loading

Ok, I've re-read the description again. So, as I understand the description, client already has sent the request and now is reading a response. Why would server's ReadAsync throw? Server's reading side was finished already

In a duplex scenario, the client and server sends are still open. The client hasn't finished sending. I'll update the description in the first post to be more explicit. I'm not experienced with reading the logs from HTTP and QUIC event sources but you should be able to see that low-level behavior there.

@karelz karelz added this to the 7.0.0 milestone Jul 22, 2021
@karelz karelz removed the untriaged New issue has not been triaged by the area owner label Jul 22, 2021
@karelz karelz modified the milestones: 7.0.0, 6.0.0 Jul 22, 2021
@karelz
Copy link
Member

karelz commented Jul 22, 2021

Triage: If it is not specific to Duplex, we should try it in 6.0.

@CarnaViire
Copy link
Member

From online discussion: This is not specific to duplex, it will most probably show on disposing not finished request (e.g. upload?) Dispose on Quic stream will send FIN flag on write side - that's why server's Read was returning 0. We need to add HTTP/3 level logic to be sure to differentiate between fully sent and canceled request, and in case of canceled, call AbortWrite on Quic stream before disposing it.

@JamesNK
Copy link
Member Author

JamesNK commented Jul 25, 2021

I've confirmed that it is not specific to duplex. Canceling an in-progress GET request shows the same problem.

https://github.com/dotnet/aspnetcore/tree/jamesnk/http3-httpclientbug-disposeresponse

Test: GET_ClientCancellationAfterResponseHeaders_RequestAbortRaised

@JamesNK JamesNK changed the title [HTTP/3] Duplex streaming and cancellation not reported correctly on server [HTTP/3] Cancellation of response download not reported correctly on server Jul 25, 2021
@karelz
Copy link
Member

karelz commented Jul 25, 2021

Thanks @JamesNK!

@JamesNK
Copy link
Member Author

JamesNK commented Jul 30, 2021 •
edited
Loading

I'm moving this to high priority so it doesn't get missed. Getting notice of a request cancellation is important on the server, and the issue isn't specific to duplex.

@ManickaP @karelz

@ManickaP
Copy link
Member

ManickaP commented Aug 3, 2021

Triage: @geoffkizer could you summarize your thoughts about this and I can take a look at fixing this tomorrow.

@ManickaP ManickaP self-assigned this Aug 3, 2021
@geoffkizer
Copy link
Contributor

There are several ways to cancel an in-flight request. One is to dispose the response body before reading to the end.

When this happens, we need to abort the underlying QUIC stream with the appropriate error code (I think it's H3_REQUEST_CANCELLED or something like that). We should abort both the read and the write side of the QUIC stream -- the write side only matters for duplex, but it should be a no op for non-duplex since the write will have already completed by the time the user gets the HttpResponseMessage.

Other ways for the user to cancel the request include:
(1) Throw while writing request content, i.e. from the request content's SerializeToStreamAsync

  • Again, this should result in aborting both sides of the stream
    (2) Cancel a read on the response stream or a write on the request stream
  • This should as well, but this gets complicated because as implemented currently, it's actually the QUIC stream that will end up aborting, and it's probably not doing it with the correct error code. Not sure how to handle this.

Also note that other failures while processing the request need to result in aborting the underlying QUIC stream as well. For example, if there's an error processing headers, we need to abort with the appropriate H3 error code for invalid headers. If we get the wrong frame type, we need to abort with the appropriate H3 error for that. (Some of these may actually be connection-level errors, meaning they should kill the connection -- not sure). It looks like we handle this today, but we should double check and also ensure we have tests for this.

This was referenced Aug 10, 2021
Closed
Merged
@ghost ghost added the in-pr There is an active PR which will close this issue when it is merged label Aug 10, 2021
@karelz karelz added the bug label Aug 17, 2021
@JamesNK JamesNK mentioned this issue Aug 18, 2021
Merged
@ghost ghost removed the in-pr There is an active PR which will close this issue when it is merged label Aug 19, 2021
@karelz
Copy link
Member

karelz commented Aug 19, 2021

Reopening to track fix in 6.0 for RC2.

@karelz karelz reopened this Aug 19, 2021
@karelz karelz mentioned this issue Aug 20, 2021
Closed
@ghost ghost added the in-pr There is an active PR which will close this issue when it is merged label Aug 20, 2021
@karelz karelz mentioned this issue Aug 24, 2021
Merged
@karelz
Copy link
Member

karelz commented Aug 24, 2021

Fixed in 7.0 in PR #57156.
Fixed in 6.0 RC1 in PR #57999.

@karelz karelz closed this as completed Aug 24, 2021
@JamesNK JamesNK reopened this Aug 25, 2021
@JamesNK
Copy link
Member Author

JamesNK commented Aug 25, 2021

I finally got a chance to test this change and I think the fix isn't complete. I tested my original unit test to see if it was fixed and it still fails. No abort reaches the server.

I believe the issue is the fix only works if the request or response has a length specified. Http3RequestStream.AbortStream checks to see if there is length remaining before aborting, but my test doesn't specify a length, and I'm guessing the underlying QUIC stream is never aborted:

runtime/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs

Lines 1225 to 1237 in a28a614

private void AbortStream()
{
// If the request body isn't completed, cancel it now.
if (_requestContentLengthRemaining != 0) // 0 is used for the end of content writing, -1 is used for unknown Content-Length
{
_stream.AbortWrite((long)Http3ErrorCode.RequestCancelled);
}
// If the response body isn't completed, cancel it now.
if (_responseDataPayloadRemaining != -1) // -1 is used for EOF, 0 for consumed DATA frame payload before the next read
{
_stream.AbortRead((long)Http3ErrorCode.RequestCancelled);
}
}

@JamesNK
Copy link
Member Author

JamesNK commented Aug 25, 2021 •
edited
Loading

Hmm, my guess might be wrong. It looks like _requestContentLengthRemaining is set to -1 if there isn't a content-length specified:

runtime/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3RequestStream.cs

Lines 362 to 363 in a28a614

// If we have a Content-Length, keep track of it so we don't over-send and so we can send in a single DATA frame.
_requestContentLengthRemaining = content.Headers.ContentLength ?? -1;

I'll keep investigating. It might be an issue in Kestrel.

@ManickaP
Copy link
Member

It looks like _requestContentLengthRemaining is set to -1 if there isn't a content-length specified:

Yes, it should work for unknown content lengths. Please let me know if it still doesn't work for you, maybe my tests are covering everything.

@JamesNK
Copy link
Member Author

JamesNK commented Aug 25, 2021

I've looked into this more and I believe the problem is Kestrel doesn't have a way to get notification of the request cancellation from QuicStream in certain situations.

Discussing with some folks offline.

@karelz karelz added the tenet-reliability Reliability/stability related issue (stress, load problems, etc.) label Aug 25, 2021
@ManickaP
Copy link
Member

The follow up problem tracked separately in #58229, closing this one.

@karelz
Copy link
Member

karelz commented Aug 27, 2021

(copying here to make it easier to spot)

Fixed in 7.0 in PR #57156.
Fixed in 6.0 RC1 in PR #57999.

@ghost ghost removed the in-pr There is an active PR which will close this issue when it is merged label Aug 27, 2021
@ghost ghost locked as resolved and limited conversation to collaborators Sep 26, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@ManickaP ManickaP

Labels
area-System.Net.Http blocking-release bug tenet-reliability Reliability/stability related issue (stress, load problems, etc.)
Projects
None yet
Milestone
6.0.0
Development

Successfully merging a pull request may close this issue.

[HTTP/3] Abort response stream on dispose if content not finished ManickaP/runtime
5 participants
@JamesNK @CarnaViire @karelz @ManickaP @geoffkizer