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] Hang when reading response data #57888

Closed
JamesNK opened this issue Aug 22, 2021 · 7 comments · Fixed by #58296
Closed

[HTTP/3] Hang when reading response data #57888

JamesNK opened this issue Aug 22, 2021 · 7 comments · Fixed by #58296
Assignees
@CarnaViire
Labels
area-System.Net.Http bug tenet-reliability Reliability/stability related issue (stress, load problems, etc.)
Milestone
6.0.0

Comments

@JamesNK
Copy link
Member

JamesNK commented Aug 22, 2021 •
edited
Loading

Edit: Initially I thought this issue was caused by bidirecitonal streaming, but I've recreated it when just streaming data from the server.

I think the issue is similar to #56115, the read buffer is bigger than the available data. The difference in the new hang is the client calls responseStream.ReadAsync with a large buffer before the data is available.

Scenario:

  1. Client starts request to the server
  2. Client sends headers + data to the server
  3. Server reads incoming data
  4. Server echos request data in response
  5. Client reads response data
  6. Client sends data to the server
  7. Server reads incoming data
  8. Server echos request data in response
  9. Client reads response data <-- HANG
  10. Client completes the request
  11. Server completes the response

Test: https://github.com/grpc/grpc-dotnet/blob/9f72e70c6a47ae823bb3ddcc719f1c63bf721fc7/test/FunctionalTests/Server/DuplexStreamingMethodTests.cs#L37

If the client completes the request before reading the second response then it works.

Failure logs:

 MultipleMessagesFromOneClient_SuccessResponses
   Source: DuplexStreamingMethodTests.cs line 38
   Duration: 5.3 sec

  Message: 
System.TimeoutException : The operation at C:\Development\Source\grpc-dotnet\test\FunctionalTests\Server\DuplexStreamingMethodTests.cs:94 timed out after reaching the limit of 5000ms.

  Stack Trace: 
TaskExtensions.TimeoutAfter[T](Task`1 task, TimeSpan timeout, String filePath, Int32 lineNumber) line 76
DuplexStreamingMethodTests.MultipleMessagesFromOneClient_SuccessResponses() line 94
GenericAdapter`1.BlockUntilCompleted()
NoMessagePumpStrategy.WaitForCompletion(AwaitAdapter awaiter)
AsyncToSyncAdapter.Await(Func`1 invoke)
TestMethodCommand.RunTestMethod(TestExecutionContext context)
TestMethodCommand.Execute(TestExecutionContext context)
<>c__DisplayClass1_0.<Execute>b__0()
BeforeAndAfterTestCommand.RunTestMethodInThreadAbortSafeZone(TestExecutionContext context, Action action)

  Standard Output: 
0.004s GrpcTestContext - Information: Starting DuplexStreamingMethodTests.MultipleMessagesFromOneClient_SuccessResponses
0.037s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : StreamingContent#1850352,.ctor, ->
0.043s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpRequestMessage#33110891,Content,HttpRequestMessage#33110891,StreamingContent#1850352 ->
0.046s HttpEventSourceListener - Debug: <- Event System.Net.Http - RequestStart : https,127.0.0.1,50019,/Chat.Chatter/Chat,2,0,1 ->
0.083s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#4724298,.ctor,AutoConfigUrl=(null), AutoDetect=True, Proxy=(null), ProxyBypass=(null) ->
0.083s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#4724298,.ctor,_useProxy=True ->
0.083s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#4724298,TryCreate,AutoSettingsUsed, calling WinHttpOpen ->
0.086s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionHandler#38643946,.ctor, ->
0.086s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : DiagnosticsHandler#28828555,.ctor, ->
0.086s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : RedirectHandler#61916781,.ctor, ->
0.092s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - ErrorMessage : WinInetProxyHelper#4724298,GetProxyForUrl,error=12180 ->
0.092s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#4724298,GetProxyForUrl,useProxy=False ->
0.095s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 54860159,0,0,.ctor,HttpConnectionPool https://127.0.0.1:50019 ->
0.098s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 54860159,0,0,GetHttp3ConnectionAsync,Attempting new HTTP3 connection. ->
0.100s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#31364791,.ctor,[conn][0x25F6A4F2A40] Outbound connection created ->
0.103s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,.ctor,[conn][0x25F6A559020] Inbound connection created ->
0.106s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,NativeCallbackHandler,[conn][0x25F6A559020] Connection received event IDEAL_PROCESSOR_CHANGED ->
0.113s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#31364791,NativeCallbackHandler,[conn][0x25F6A4F2A40] Connection received event STREAMS_AVAILABLE ->
0.113s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#31364791,NativeCallbackHandler,[conn][0x25F6A4F2A40] Connection received event DATAGRAM_STATE_CHANGED ->
0.115s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#31364791,NativeCallbackHandler,[conn][0x25F6A4F2A40] Connection received event PEER_CERTIFICATE_RECEIVED ->
0.117s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : SafeX509ChainHandle#63449985,Verify,CertVerifyCertificateChainPolicy returned: True. Status: 2148204815 ->
0.117s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#31364791,NativeCallbackHandler,[conn][0x25F6A4F2A40] Connection received event CONNECTED ->
0.118s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,NativeCallbackHandler,[conn][0x25F6A559020] Connection received event CONNECTED ->
0.120s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#47741942,HandleEvent,(null) Stream received event START_COMPLETE ->
0.120s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#47741942,.ctor,[strm][0x25F6A5AFD00] Outbound unidirectional stream created in connection [conn][0x25F6A4F2A40]. ->
0.121s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#47741942,HandleEvent,[strm][0x25F6A5AFD00] Stream received event SEND_COMPLETE ->
0.122s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,NativeCallbackHandler,[conn][0x25F6A559020] Connection received event PEER_STREAM_STARTED ->
0.122s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,.ctor,[strm][0x25F6A4F6DD0] Inbound unidirectional stream created in connection [conn][0x25F6A559020]. ->
0.122s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,HandleEvent,[strm][0x25F6A4F6DD0] Stream received event RECEIVE ->
0.122s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,HandleEventRecv,[strm][0x25F6A4F6DD0] Stream received 8 bytes ->
0.126s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Connection id "0HMB50ULSMP2L" accepted.
0.129s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 54860159,0,0,GetHttp3ConnectionAsync,New HTTP3 connection established. ->
0.130s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,(null) Stream received event START_COMPLETE ->
0.130s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMB50ULSMP2L" accepted.
0.130s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,.ctor,[strm][0x25F6A5F3A50] Outbound bidirectional stream created in connection [conn][0x25F6A4F2A40]. ->
0.131s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMB50ULSMP2L" started.
0.135s GrpcTestContext - Information: Client sending message
0.136s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,HandleEvent,(null) Stream received event START_COMPLETE ->
0.137s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,.ctor,[strm][0x25F6A5F3FF0] Outbound unidirectional stream created in connection [conn][0x25F6A559020]. ->
0.138s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,ReadAsync,[strm][0x25F6A5F3A50] Stream reading into Memory of '64' bytes. ->
0.138s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x25F6A5F3A50] Stream received event SEND_COMPLETE ->
0.140s GrpcTestContext - Information: Client waiting for response
0.144s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB50ULSMP2L:00000003" type Unidirectional connected.
0.148s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,HandleEvent,[strm][0x25F6A5F3FF0] Stream received event SEND_COMPLETE ->
0.152s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,HandleEvent,[strm][0x25F6A5F3FF0] Stream received event SEND_COMPLETE ->
0.153s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,ReadAsync,[strm][0x25F6A4F6DD0] Stream reading into Memory of '4096' bytes. ->
0.153s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,ReadAsync,[strm][0x25F6A4F6DD0] Stream reading into Memory of '4096' bytes. ->
0.154s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB50ULSMP2L:00000002" type Unidirectional accepted.
0.159s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB50ULSMP2L" received SETTINGS frame for stream ID 2 with length 5.
0.161s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,NativeCallbackHandler,[conn][0x25F6A559020] Connection received event PEER_STREAM_STARTED ->
0.161s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#31364791,NativeCallbackHandler,[conn][0x25F6A4F2A40] Connection received event PEER_STREAM_STARTED ->
0.161s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,.ctor,[strm][0x25F6A5F2C40] Inbound unidirectional stream created in connection [conn][0x25F6A4F2A40]. ->
0.161s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,.ctor,[strm][0x25F6A5F3D20] Inbound bidirectional stream created in connection [conn][0x25F6A559020]. ->
0.161s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,HandleEvent,[strm][0x25F6A5F2C40] Stream received event RECEIVE ->
0.161s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x25F6A5F3D20] Stream received event RECEIVE ->
0.161s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,HandleEventRecv,[strm][0x25F6A5F2C40] Stream received 8 bytes ->
0.161s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEventRecv,[strm][0x25F6A5F3D20] Stream received 114 bytes ->
0.162s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,ReadAsync,[strm][0x25F6A5F3D20] Stream reading into Memory of '4096' bytes. ->
0.162s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,ReadAsync,[strm][0x25F6A5F2C40] Stream reading into Memory of '32' bytes. ->
0.162s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,ReadAsync,[strm][0x25F6A5F3D20] Stream reading into Memory of '4096' bytes. ->
0.162s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB50ULSMP2L:00000000" type Bidirectional accepted.
0.163s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,ReadAsync,[strm][0x25F6A5F2C40] Stream reading into Memory of '32' bytes. ->
0.168s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB50ULSMP2L" received HEADERS frame for stream ID 0 with length 86.
0.183s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB50ULSMP2L" received DATA frame for stream ID 0 with length 23.
0.187s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request starting HTTP/3 POST https://127.0.0.1:50019/Chat.Chatter/Chat application/grpc -
0.212s SERVER Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware - Debug: Request matched endpoint 'gRPC - /chat.Chatter/Chat'
0.215s SERVER Microsoft.AspNetCore.Routing.EndpointMiddleware - Information: Executing endpoint 'gRPC - /chat.Chatter/Chat'
0.224s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.225s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB50ULSMP2L", Request id "0HMB50ULSMP2L:00000000": started reading request body.
0.228s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 18 byte message to 'Chat.ChatMessage'.
0.234s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.237s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB50ULSMP2L" sending HEADERS frame for stream ID 0 with length 115.
0.237s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Sending message.
0.240s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Serialized 'Chat.ChatMessage' to 18 byte message.
0.241s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB50ULSMP2L" sending DATA frame for stream ID 0 with length 23.
0.241s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x25F6A5F3D20] Stream received event SEND_COMPLETE ->
0.241s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Message sent.
0.241s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.241s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x25F6A5F3A50] Stream received event RECEIVE ->
0.241s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEventRecv,[strm][0x25F6A5F3A50] Stream received 143 bytes ->
0.242s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x25F6A5F3A50] Stream received event RECEIVE ->
0.242s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEventRecv,[strm][0x25F6A5F3A50] Stream received 79 bytes ->
0.242s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x25F6A5F3D20] Stream received event IDEAL_SEND_BUFFER_SIZE ->
0.242s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 54860159,31311345,0,ReadFrameEnvelopeAsync,Received frame 1 of length 115. ->
0.243s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#48888596,RequestMessage,HttpResponseMessage#48888596,HttpRequestMessage#33110891 ->
0.243s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionResponseContent#40958767,.ctor, ->
0.243s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#48888596,Content,HttpResponseMessage#48888596,HttpConnectionResponseContent#40958767 ->
0.243s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,ReadAsync,[strm][0x25F6A5F3A50] Stream reading into Memory of '64' bytes. ->
0.243s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x25F6A5F3A50] Stream received event RECEIVE ->
0.243s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEventRecv,[strm][0x25F6A5F3A50] Stream received 15 bytes ->
0.251s HttpEventSourceListener - Debug: <- Event System.Net.Http - RequestStop :  ->
0.262s GrpcTestContext - Information: Client reading message
0.265s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 54860159,31311345,0,ReadFrameEnvelopeAsync,Received frame 0 of length 23. ->
0.265s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,ReadAsync,[strm][0x25F6A5F3A50] Stream reading into Memory of '15' bytes. ->
0.267s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,ReadAsync,[strm][0x25F6A5F3A50] Stream reading into Memory of '64' bytes. ->
0.271s GrpcTestContext - Information: Client sending message
0.271s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x25F6A5F3A50] Stream received event SEND_COMPLETE ->
0.271s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x25F6A5F3D20] Stream received event RECEIVE ->
0.271s GrpcTestContext - Information: Client reading message
0.271s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEventRecv,[strm][0x25F6A5F3D20] Stream received 25 bytes ->
0.271s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x25F6A5F3A50] Stream received event IDEAL_SEND_BUFFER_SIZE ->
0.272s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,ReadAsync,[strm][0x25F6A5F3D20] Stream reading into Memory of '4096' bytes. ->
0.272s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB50ULSMP2L" received DATA frame for stream ID 0 with length 23.
0.273s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 18 byte message to 'Chat.ChatMessage'.
0.273s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.273s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Sending message.
0.273s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Serialized 'Chat.ChatMessage' to 18 byte message.
0.273s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB50ULSMP2L" sending DATA frame for stream ID 0 with length 23.
0.273s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Message sent.
0.273s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.273s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x25F6A5F3D20] Stream received event SEND_COMPLETE ->
0.274s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x25F6A5F3A50] Stream received event RECEIVE ->
0.274s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEventRecv,[strm][0x25F6A5F3A50] Stream received 25 bytes ->
0.274s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 54860159,31311345,0,ReadFrameEnvelopeAsync,Received frame 0 of length 23. ->
0.274s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,ReadAsync,[strm][0x25F6A5F3A50] Stream reading into Memory of '64' bytes. ->
5.307s GrpcTestContext - Information: Finishing DuplexStreamingMethodTests.MultipleMessagesFromOneClient_SuccessResponses

The end of the logs show the client receiving the second message's data frame and then hanging:

0.273s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x25F6A5F3D20] Stream received event SEND_COMPLETE ->
0.274s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x25F6A5F3A50] Stream received event RECEIVE ->
0.274s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEventRecv,[strm][0x25F6A5F3A50] Stream received 25 bytes ->
0.274s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 54860159,31311345,0,ReadFrameEnvelopeAsync,Received frame 0 of length 23. ->
0.274s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,ReadAsync,[strm][0x25F6A5F3A50] Stream reading into Memory of '64' bytes. ->
5.307s GrpcTestContext - Information: Finishing DuplexStreamingMethodTests.MultipleMessagesFromOneClient_SuccessResponses

SDK info:

.NET SDK (reflecting any global.json):
 Version:   6.0.100-rc.1.21421.6
 Commit:    77703ed54e
@ghost
Copy link

ghost commented Aug 22, 2021

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

Issue Details

Scenario:

  1. Client starts request to the server
  2. Client sends headers + data to the server
  3. Server reads incoming data
  4. Server echos request data in response
  5. Client reads response data
  6. Client sends data to the server
  7. Server reads incoming data
  8. Server echos request data in response
  9. Client reads response data <-- HANG
  10. Client completes the request

If the client completes the request before reading the second response then it works. (swap the final two steps)

Failure logs:

 MultipleMessagesFromOneClient_SuccessResponses
   Source: DuplexStreamingMethodTests.cs line 38
   Duration: 5.3 sec

  Message: 
System.TimeoutException : The operation at C:\Development\Source\grpc-dotnet\test\FunctionalTests\Server\DuplexStreamingMethodTests.cs:94 timed out after reaching the limit of 5000ms.

  Stack Trace: 
TaskExtensions.TimeoutAfter[T](Task`1 task, TimeSpan timeout, String filePath, Int32 lineNumber) line 76
DuplexStreamingMethodTests.MultipleMessagesFromOneClient_SuccessResponses() line 94
GenericAdapter`1.BlockUntilCompleted()
NoMessagePumpStrategy.WaitForCompletion(AwaitAdapter awaiter)
AsyncToSyncAdapter.Await(Func`1 invoke)
TestMethodCommand.RunTestMethod(TestExecutionContext context)
TestMethodCommand.Execute(TestExecutionContext context)
<>c__DisplayClass1_0.<Execute>b__0()
BeforeAndAfterTestCommand.RunTestMethodInThreadAbortSafeZone(TestExecutionContext context, Action action)

  Standard Output: 
0.004s GrpcTestContext - Information: Starting DuplexStreamingMethodTests.MultipleMessagesFromOneClient_SuccessResponses
0.037s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : StreamingContent#1850352,.ctor, ->
0.043s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpRequestMessage#33110891,Content,HttpRequestMessage#33110891,StreamingContent#1850352 ->
0.046s HttpEventSourceListener - Debug: <- Event System.Net.Http - RequestStart : https,127.0.0.1,50019,/Chat.Chatter/Chat,2,0,1 ->
0.083s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#4724298,.ctor,AutoConfigUrl=(null), AutoDetect=True, Proxy=(null), ProxyBypass=(null) ->
0.083s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#4724298,.ctor,_useProxy=True ->
0.083s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#4724298,TryCreate,AutoSettingsUsed, calling WinHttpOpen ->
0.086s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionHandler#38643946,.ctor, ->
0.086s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : DiagnosticsHandler#28828555,.ctor, ->
0.086s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : RedirectHandler#61916781,.ctor, ->
0.092s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - ErrorMessage : WinInetProxyHelper#4724298,GetProxyForUrl,error=12180 ->
0.092s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#4724298,GetProxyForUrl,useProxy=False ->
0.095s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 54860159,0,0,.ctor,HttpConnectionPool https://127.0.0.1:50019 ->
0.098s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 54860159,0,0,GetHttp3ConnectionAsync,Attempting new HTTP3 connection. ->
0.100s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#31364791,.ctor,[conn][0x25F6A4F2A40] Outbound connection created ->
0.103s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,.ctor,[conn][0x25F6A559020] Inbound connection created ->
0.106s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,NativeCallbackHandler,[conn][0x25F6A559020] Connection received event IDEAL_PROCESSOR_CHANGED ->
0.113s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#31364791,NativeCallbackHandler,[conn][0x25F6A4F2A40] Connection received event STREAMS_AVAILABLE ->
0.113s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#31364791,NativeCallbackHandler,[conn][0x25F6A4F2A40] Connection received event DATAGRAM_STATE_CHANGED ->
0.115s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#31364791,NativeCallbackHandler,[conn][0x25F6A4F2A40] Connection received event PEER_CERTIFICATE_RECEIVED ->
0.117s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : SafeX509ChainHandle#63449985,Verify,CertVerifyCertificateChainPolicy returned: True. Status: 2148204815 ->
0.117s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#31364791,NativeCallbackHandler,[conn][0x25F6A4F2A40] Connection received event CONNECTED ->
0.118s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,NativeCallbackHandler,[conn][0x25F6A559020] Connection received event CONNECTED ->
0.120s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#47741942,HandleEvent,(null) Stream received event START_COMPLETE ->
0.120s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#47741942,.ctor,[strm][0x25F6A5AFD00] Outbound unidirectional stream created in connection [conn][0x25F6A4F2A40]. ->
0.121s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#47741942,HandleEvent,[strm][0x25F6A5AFD00] Stream received event SEND_COMPLETE ->
0.122s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,NativeCallbackHandler,[conn][0x25F6A559020] Connection received event PEER_STREAM_STARTED ->
0.122s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,.ctor,[strm][0x25F6A4F6DD0] Inbound unidirectional stream created in connection [conn][0x25F6A559020]. ->
0.122s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,HandleEvent,[strm][0x25F6A4F6DD0] Stream received event RECEIVE ->
0.122s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,HandleEventRecv,[strm][0x25F6A4F6DD0] Stream received 8 bytes ->
0.126s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Connection id "0HMB50ULSMP2L" accepted.
0.129s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 54860159,0,0,GetHttp3ConnectionAsync,New HTTP3 connection established. ->
0.130s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,(null) Stream received event START_COMPLETE ->
0.130s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMB50ULSMP2L" accepted.
0.130s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,.ctor,[strm][0x25F6A5F3A50] Outbound bidirectional stream created in connection [conn][0x25F6A4F2A40]. ->
0.131s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMB50ULSMP2L" started.
0.135s GrpcTestContext - Information: Client sending message
0.136s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,HandleEvent,(null) Stream received event START_COMPLETE ->
0.137s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,.ctor,[strm][0x25F6A5F3FF0] Outbound unidirectional stream created in connection [conn][0x25F6A559020]. ->
0.138s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,ReadAsync,[strm][0x25F6A5F3A50] Stream reading into Memory of '64' bytes. ->
0.138s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x25F6A5F3A50] Stream received event SEND_COMPLETE ->
0.140s GrpcTestContext - Information: Client waiting for response
0.144s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB50ULSMP2L:00000003" type Unidirectional connected.
0.148s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,HandleEvent,[strm][0x25F6A5F3FF0] Stream received event SEND_COMPLETE ->
0.152s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,HandleEvent,[strm][0x25F6A5F3FF0] Stream received event SEND_COMPLETE ->
0.153s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,ReadAsync,[strm][0x25F6A4F6DD0] Stream reading into Memory of '4096' bytes. ->
0.153s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,ReadAsync,[strm][0x25F6A4F6DD0] Stream reading into Memory of '4096' bytes. ->
0.154s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB50ULSMP2L:00000002" type Unidirectional accepted.
0.159s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB50ULSMP2L" received SETTINGS frame for stream ID 2 with length 5.
0.161s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,NativeCallbackHandler,[conn][0x25F6A559020] Connection received event PEER_STREAM_STARTED ->
0.161s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#31364791,NativeCallbackHandler,[conn][0x25F6A4F2A40] Connection received event PEER_STREAM_STARTED ->
0.161s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,.ctor,[strm][0x25F6A5F2C40] Inbound unidirectional stream created in connection [conn][0x25F6A4F2A40]. ->
0.161s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,.ctor,[strm][0x25F6A5F3D20] Inbound bidirectional stream created in connection [conn][0x25F6A559020]. ->
0.161s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,HandleEvent,[strm][0x25F6A5F2C40] Stream received event RECEIVE ->
0.161s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x25F6A5F3D20] Stream received event RECEIVE ->
0.161s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,HandleEventRecv,[strm][0x25F6A5F2C40] Stream received 8 bytes ->
0.161s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEventRecv,[strm][0x25F6A5F3D20] Stream received 114 bytes ->
0.162s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,ReadAsync,[strm][0x25F6A5F3D20] Stream reading into Memory of '4096' bytes. ->
0.162s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,ReadAsync,[strm][0x25F6A5F2C40] Stream reading into Memory of '32' bytes. ->
0.162s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,ReadAsync,[strm][0x25F6A5F3D20] Stream reading into Memory of '4096' bytes. ->
0.162s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB50ULSMP2L:00000000" type Bidirectional accepted.
0.163s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,ReadAsync,[strm][0x25F6A5F2C40] Stream reading into Memory of '32' bytes. ->
0.168s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB50ULSMP2L" received HEADERS frame for stream ID 0 with length 86.
0.183s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB50ULSMP2L" received DATA frame for stream ID 0 with length 23.
0.187s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request starting HTTP/3 POST https://127.0.0.1:50019/Chat.Chatter/Chat application/grpc -
0.212s SERVER Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware - Debug: Request matched endpoint 'gRPC - /chat.Chatter/Chat'
0.215s SERVER Microsoft.AspNetCore.Routing.EndpointMiddleware - Information: Executing endpoint 'gRPC - /chat.Chatter/Chat'
0.224s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.225s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB50ULSMP2L", Request id "0HMB50ULSMP2L:00000000": started reading request body.
0.228s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 18 byte message to 'Chat.ChatMessage'.
0.234s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.237s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB50ULSMP2L" sending HEADERS frame for stream ID 0 with length 115.
0.237s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Sending message.
0.240s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Serialized 'Chat.ChatMessage' to 18 byte message.
0.241s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB50ULSMP2L" sending DATA frame for stream ID 0 with length 23.
0.241s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x25F6A5F3D20] Stream received event SEND_COMPLETE ->
0.241s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Message sent.
0.241s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.241s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x25F6A5F3A50] Stream received event RECEIVE ->
0.241s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEventRecv,[strm][0x25F6A5F3A50] Stream received 143 bytes ->
0.242s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x25F6A5F3A50] Stream received event RECEIVE ->
0.242s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEventRecv,[strm][0x25F6A5F3A50] Stream received 79 bytes ->
0.242s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x25F6A5F3D20] Stream received event IDEAL_SEND_BUFFER_SIZE ->
0.242s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 54860159,31311345,0,ReadFrameEnvelopeAsync,Received frame 1 of length 115. ->
0.243s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#48888596,RequestMessage,HttpResponseMessage#48888596,HttpRequestMessage#33110891 ->
0.243s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionResponseContent#40958767,.ctor, ->
0.243s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#48888596,Content,HttpResponseMessage#48888596,HttpConnectionResponseContent#40958767 ->
0.243s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,ReadAsync,[strm][0x25F6A5F3A50] Stream reading into Memory of '64' bytes. ->
0.243s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x25F6A5F3A50] Stream received event RECEIVE ->
0.243s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEventRecv,[strm][0x25F6A5F3A50] Stream received 15 bytes ->
0.251s HttpEventSourceListener - Debug: <- Event System.Net.Http - RequestStop :  ->
0.262s GrpcTestContext - Information: Client reading message
0.265s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 54860159,31311345,0,ReadFrameEnvelopeAsync,Received frame 0 of length 23. ->
0.265s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,ReadAsync,[strm][0x25F6A5F3A50] Stream reading into Memory of '15' bytes. ->
0.267s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,ReadAsync,[strm][0x25F6A5F3A50] Stream reading into Memory of '64' bytes. ->
0.271s GrpcTestContext - Information: Client sending message
0.271s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x25F6A5F3A50] Stream received event SEND_COMPLETE ->
0.271s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x25F6A5F3D20] Stream received event RECEIVE ->
0.271s GrpcTestContext - Information: Client reading message
0.271s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEventRecv,[strm][0x25F6A5F3D20] Stream received 25 bytes ->
0.271s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x25F6A5F3A50] Stream received event IDEAL_SEND_BUFFER_SIZE ->
0.272s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,ReadAsync,[strm][0x25F6A5F3D20] Stream reading into Memory of '4096' bytes. ->
0.272s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB50ULSMP2L" received DATA frame for stream ID 0 with length 23.
0.273s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 18 byte message to 'Chat.ChatMessage'.
0.273s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.273s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Sending message.
0.273s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Serialized 'Chat.ChatMessage' to 18 byte message.
0.273s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB50ULSMP2L" sending DATA frame for stream ID 0 with length 23.
0.273s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Message sent.
0.273s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.273s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x25F6A5F3D20] Stream received event SEND_COMPLETE ->
0.274s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x25F6A5F3A50] Stream received event RECEIVE ->
0.274s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEventRecv,[strm][0x25F6A5F3A50] Stream received 25 bytes ->
0.274s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 54860159,31311345,0,ReadFrameEnvelopeAsync,Received frame 0 of length 23. ->
0.274s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,ReadAsync,[strm][0x25F6A5F3A50] Stream reading into Memory of '64' bytes. ->
5.307s GrpcTestContext - Information: Finishing DuplexStreamingMethodTests.MultipleMessagesFromOneClient_SuccessResponses

The client appears to receive the second message's data frame and then hang.

.NET SDK (reflecting any global.json):
 Version:   6.0.100-rc.1.21421.6
 Commit:    77703ed54e
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 Aug 22, 2021
@JamesNK JamesNK changed the title [HTTP/3] Bidirectional streaming not returning response data [HTTP/3] Hang when reading response data Aug 22, 2021
@JamesNK
Copy link
Member Author

JamesNK commented Aug 22, 2021

Server streaming repo logs:

 NoBuffering_SuccessResponsesStreamed
   Source: ServerStreamingMethodTests.cs line 37
   Duration: 5.3 sec

  Message: 
System.TimeoutException : The operation at C:\Development\Source\grpc-dotnet\test\Shared\MessageHelpers.cs:102 timed out after reaching the limit of 5000ms.

  Stack Trace: 
TaskExtensions.TimeoutAfter[T](Task`1 task, TimeSpan timeout, String filePath, Int32 lineNumber) line 76
MessageHelpers.AssertReadStreamMessageAsync[T](PipeReader pipeReader, String compressionEncoding, List`1 compressionProviders) line 102
TaskExtensions.TimeoutAfter[T](Task`1 task, TimeSpan timeout, String filePath, Int32 lineNumber) line 72
ServerStreamingMethodTests.NoBuffering_SuccessResponsesStreamed() line 98
GenericAdapter`1.BlockUntilCompleted()
NoMessagePumpStrategy.WaitForCompletion(AwaitAdapter awaiter)
AsyncToSyncAdapter.Await(Func`1 invoke)
TestMethodCommand.RunTestMethod(TestExecutionContext context)
TestMethodCommand.Execute(TestExecutionContext context)
<>c__DisplayClass1_0.<Execute>b__0()
BeforeAndAfterTestCommand.RunTestMethodInThreadAbortSafeZone(TestExecutionContext context, Action action)

  Standard Output: 
0.003s GrpcTestContext - Information: Starting ServerStreamingMethodTests.NoBuffering_SuccessResponsesStreamed
0.016s SERVER Grpc.AspNetCore.Server.Model.Internal.ServiceRouteBuilder - Trace: Discovering gRPC methods for FunctionalTestsWebsite.Infrastructure.DynamicService.
0.018s SERVER Grpc.AspNetCore.Server.Model.Internal.BinderServiceMethodProvider - Debug: Could not find bind method for FunctionalTestsWebsite.Infrastructure.DynamicService.
0.019s SERVER Grpc.AspNetCore.Server.Model.Internal.ServiceRouteBuilder - Trace: Added gRPC method '40a587f8-a9cd-4d63-9fd4-fbdcd7f06532' to service 'DynamicService'. Method type: 'ServerStreaming', route pattern: '/DynamicService/40a587f8-a9cd-4d63-9fd4-fbdcd7f06532'.
0.040s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : GrpcStreamContent#54860159,.ctor, ->
0.043s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpRequestMessage#57266958,Content,HttpRequestMessage#57266958,GrpcStreamContent#54860159 ->
0.045s HttpEventSourceListener - Debug: <- Event System.Net.Http - RequestStart : https,127.0.0.1,50019,/DynamicService/40a587f8-a9cd-4d63-9fd4-fbdcd7f06532,2,0,1 ->
0.079s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#31364791,.ctor,AutoConfigUrl=(null), AutoDetect=True, Proxy=(null), ProxyBypass=(null) ->
0.079s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#31364791,.ctor,_useProxy=True ->
0.079s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#31364791,TryCreate,AutoSettingsUsed, calling WinHttpOpen ->
0.082s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionHandler#25445537,.ctor, ->
0.082s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : DiagnosticsHandler#43347212,.ctor, ->
0.082s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : RedirectHandler#66105400,.ctor, ->
0.088s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - ErrorMessage : WinInetProxyHelper#31364791,GetProxyForUrl,error=12180 ->
0.088s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#31364791,GetProxyForUrl,useProxy=False ->
0.091s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 49642866,0,0,.ctor,HttpConnectionPool https://127.0.0.1:50019 ->
0.094s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 49642866,0,0,GetHttp3ConnectionAsync,Attempting new HTTP3 connection. ->
0.096s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6563976,.ctor,[conn][0x1E226C92A40] Outbound connection created ->
0.099s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,.ctor,[conn][0x1E226CF9020] Inbound connection created ->
0.102s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,NativeCallbackHandler,[conn][0x1E226CF9020] Connection received event IDEAL_PROCESSOR_CHANGED ->
0.109s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6563976,NativeCallbackHandler,[conn][0x1E226C92A40] Connection received event STREAMS_AVAILABLE ->
0.109s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6563976,NativeCallbackHandler,[conn][0x1E226C92A40] Connection received event DATAGRAM_STATE_CHANGED ->
0.110s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6563976,NativeCallbackHandler,[conn][0x1E226C92A40] Connection received event PEER_CERTIFICATE_RECEIVED ->
0.113s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : SafeX509ChainHandle#63449985,Verify,CertVerifyCertificateChainPolicy returned: True. Status: 2148204815 ->
0.113s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6563976,NativeCallbackHandler,[conn][0x1E226C92A40] Connection received event CONNECTED ->
0.114s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6563976,NativeCallbackHandler,[conn][0x1E226C92A40] Connection received event IDEAL_PROCESSOR_CHANGED ->
0.116s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57600139,HandleEvent,(null) Stream received event START_COMPLETE ->
0.117s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57600139,.ctor,[strm][0x1E226C99A80] Outbound unidirectional stream created in connection [conn][0x1E226C92A40]. ->
0.117s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,NativeCallbackHandler,[conn][0x1E226CF9020] Connection received event CONNECTED ->
0.117s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57600139,HandleEvent,[strm][0x1E226C99A80] Stream received event SEND_COMPLETE ->
0.119s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,NativeCallbackHandler,[conn][0x1E226CF9020] Connection received event PEER_STREAM_STARTED ->
0.119s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,.ctor,[strm][0x1E226C963F0] Inbound unidirectional stream created in connection [conn][0x1E226CF9020]. ->
0.119s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,HandleEvent,[strm][0x1E226C963F0] Stream received event RECEIVE ->
0.119s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,HandleEventRecv,[strm][0x1E226C963F0] Stream received 8 bytes ->
0.121s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Connection id "0HMB51UJJ4FOE" accepted.
0.122s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 49642866,0,0,GetHttp3ConnectionAsync,New HTTP3 connection established. ->
0.123s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,HandleEvent,(null) Stream received event START_COMPLETE ->
0.123s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,.ctor,[strm][0x1E226C98310] Outbound bidirectional stream created in connection [conn][0x1E226C92A40]. ->
0.124s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMB51UJJ4FOE" accepted.
0.125s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMB51UJJ4FOE" started.
0.129s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,HandleEvent,[strm][0x1E226C98310] Stream received event SEND_COMPLETE ->
0.129s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,NativeCallbackHandler,[conn][0x1E226CF9020] Connection received event PEER_STREAM_STARTED ->
0.129s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,.ctor,[strm][0x1E226D83160] Inbound bidirectional stream created in connection [conn][0x1E226CF9020]. ->
0.129s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,HandleEvent,[strm][0x1E226D83160] Stream received event RECEIVE ->
0.129s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,HandleEventRecv,[strm][0x1E226D83160] Stream received 137 bytes ->
0.129s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,(null) Stream received event START_COMPLETE ->
0.129s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,.ctor,[strm][0x1E226D844E0] Outbound unidirectional stream created in connection [conn][0x1E226CF9020]. ->
0.132s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,HandleEvent,[strm][0x1E226C98310] Stream received event SEND_SHUTDOWN_COMPLETE ->
0.132s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,ReadAsync,[strm][0x1E226C98310] Stream reading into Memory of '64' bytes. ->
0.137s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB51UJJ4FOE:00000003" type Unidirectional connected.
0.142s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x1E226D844E0] Stream received event SEND_COMPLETE ->
0.142s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6563976,NativeCallbackHandler,[conn][0x1E226C92A40] Connection received event PEER_STREAM_STARTED ->
0.142s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#40923024,.ctor,[strm][0x1E226D857C0] Inbound unidirectional stream created in connection [conn][0x1E226C92A40]. ->
0.142s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#40923024,HandleEvent,[strm][0x1E226D857C0] Stream received event RECEIVE ->
0.142s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#40923024,HandleEventRecv,[strm][0x1E226D857C0] Stream received 1 bytes ->
0.144s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#40923024,ReadAsync,[strm][0x1E226D857C0] Stream reading into Memory of '32' bytes. ->
0.145s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#40923024,ReadAsync,[strm][0x1E226D857C0] Stream reading into Memory of '32' bytes. ->
0.145s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x1E226D844E0] Stream received event SEND_COMPLETE ->
0.145s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#40923024,HandleEvent,[strm][0x1E226D857C0] Stream received event RECEIVE ->
0.145s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#40923024,HandleEventRecv,[strm][0x1E226D857C0] Stream received 7 bytes ->
0.146s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,ReadAsync,[strm][0x1E226C963F0] Stream reading into Memory of '4096' bytes. ->
0.146s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x1E226D844E0] Stream received event IDEAL_SEND_BUFFER_SIZE ->
0.146s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,ReadAsync,[strm][0x1E226C963F0] Stream reading into Memory of '4096' bytes. ->
0.147s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB51UJJ4FOE:00000002" type Unidirectional accepted.
0.147s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#40923024,ReadAsync,[strm][0x1E226D857C0] Stream reading into Memory of '32' bytes. ->
0.148s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,ReadAsync,[strm][0x1E226D83160] Stream reading into Memory of '4096' bytes. ->
0.148s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,ReadAsync,[strm][0x1E226D83160] Stream reading into Memory of '4096' bytes. ->
0.148s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,HandleEvent,[strm][0x1E226D83160] Stream received event PEER_SEND_SHUTDOWN ->
0.148s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,HandleEventPeerSendShutdown,[strm][0x1E226D83160] Stream completing resettable event source. ->
0.148s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB51UJJ4FOE:00000000" type Bidirectional accepted.
0.152s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB51UJJ4FOE" received SETTINGS frame for stream ID 2 with length 5.
0.153s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB51UJJ4FOE" received HEADERS frame for stream ID 0 with length 120.
0.168s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB51UJJ4FOE" received DATA frame for stream ID 0 with length 12.
0.172s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request starting HTTP/3 POST https://127.0.0.1:50019/DynamicService/40a587f8-a9cd-4d63-9fd4-fbdcd7f06532 application/grpc -
0.197s SERVER Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware - Debug: Request matched endpoint 'gRPC - /DynamicService/40a587f8-a9cd-4d63-9fd4-fbdcd7f06532'
0.200s SERVER Microsoft.AspNetCore.Routing.EndpointMiddleware - Information: Executing endpoint 'gRPC - /DynamicService/40a587f8-a9cd-4d63-9fd4-fbdcd7f06532'
0.205s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.205s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB51UJJ4FOE", Request id "0HMB51UJJ4FOE:00000000": started reading request body.
0.205s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB51UJJ4FOE", Request id "0HMB51UJJ4FOE:00000000": done reading request body.
0.208s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 7 byte message to 'Greet.HelloRequest'.
0.212s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.220s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB51UJJ4FOE" sending HEADERS frame for stream ID 0 with length 143.
0.220s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,HandleEvent,[strm][0x1E226D83160] Stream received event SEND_COMPLETE ->
0.220s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,HandleEvent,[strm][0x1E226C98310] Stream received event RECEIVE ->
0.220s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,HandleEventRecv,[strm][0x1E226C98310] Stream received 146 bytes ->
0.221s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,HandleEvent,[strm][0x1E226C98310] Stream received event RECEIVE ->
0.221s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,HandleEventRecv,[strm][0x1E226C98310] Stream received 82 bytes ->
0.221s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 49642866,19208783,0,ReadFrameEnvelopeAsync,Received frame 1 of length 143. ->
0.222s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#2681320,RequestMessage,HttpResponseMessage#2681320,HttpRequestMessage#57266958 ->
0.222s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionResponseContent#5135072,.ctor, ->
0.222s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#2681320,Content,HttpResponseMessage#2681320,HttpConnectionResponseContent#5135072 ->
0.222s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,ReadAsync,[strm][0x1E226C98310] Stream reading into Memory of '64' bytes. ->
0.222s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,HandleEvent,[strm][0x1E226C98310] Stream received event RECEIVE ->
0.222s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,HandleEventRecv,[strm][0x1E226C98310] Stream received 18 bytes ->
0.223s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,ReadAsync,[strm][0x1E226C98310] Stream reading into Memory of '64' bytes. ->
0.231s HttpEventSourceListener - Debug: <- Event System.Net.Http - RequestStop :  ->
0.246s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,ReadAsync,[strm][0x1E226C98310] Stream reading into Memory of '64' bytes. ->
0.253s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Sending message.
0.256s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Serialized 'Greet.HelloReply' to 22 byte message.
0.256s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB51UJJ4FOE" sending DATA frame for stream ID 0 with length 27.
0.257s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Message sent.
0.257s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,HandleEvent,[strm][0x1E226D83160] Stream received event SEND_COMPLETE ->
0.257s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,HandleEvent,[strm][0x1E226C98310] Stream received event RECEIVE ->
0.257s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,HandleEventRecv,[strm][0x1E226C98310] Stream received 29 bytes ->
0.257s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 49642866,19208783,0,ReadFrameEnvelopeAsync,Received frame 0 of length 27. ->
0.258s HttpEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#46251828,ReadAsync,[strm][0x1E226C98310] Stream reading into Memory of '64' bytes. ->
5.280s GrpcTestContext - Information: Finishing ServerStreamingMethodTests.NoBuffering_SuccessResponsesStreamed

@karelz karelz added this to the 7.0.0 milestone Aug 24, 2021
@karelz karelz added bug tenet-reliability Reliability/stability related issue (stress, load problems, etc.) and removed untriaged New issue has not been triaged by the area owner labels Aug 24, 2021
@karelz
Copy link
Member

karelz commented Aug 24, 2021

Triage: We should look at it and understand. This may be needed for 6.0.

@karelz karelz modified the milestones: 7.0.0, 6.0.0 Aug 24, 2021
@CarnaViire CarnaViire mentioned this issue Aug 27, 2021
Merged
@ghost ghost added the in-pr There is an active PR which will close this issue when it is merged label Aug 27, 2021
@ghost ghost removed the in-pr There is an active PR which will close this issue when it is merged label Aug 31, 2021
@karelz
Copy link
Member

karelz commented Aug 31, 2021

Reopening to track 6.0 backport. This breaks gRPC streaming - it hangs.

@karelz karelz reopened this Aug 31, 2021
@JamesNK
Copy link
Member Author

JamesNK commented Aug 31, 2021 •
edited
Loading

@karelz FYI, gRPC isn't impacted by this bug because gRPC knows exactly how much to read from the response.

However, I think this bug could be common for non-gRPC usage:

  • Reading to the end of the response data stream is common.
  • Specifying a bigger buffer than is required is common.
  • Internet latency means calling Stream.ReadAsync before the data is available is common.

All the requirements to get this bug are common activities. I think that a lot of people will run into this issue.

@karelz
Copy link
Member

karelz commented Aug 31, 2021

Thanks @JamesNK. Based on team discussion, we think we should take it to 6.0 as the conditions for hitting the hang are fairly common in real-world usage.

@karelz karelz mentioned this issue Sep 1, 2021
Merged
@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 Sep 1, 2021
@karelz
Copy link
Member

karelz commented Sep 3, 2021

Fixed in 6.0 RC2 in PR #58460.
Fixed in 7.0 in PR #58296.

@karelz karelz closed this as completed Sep 3, 2021
@ghost ghost locked as resolved and limited conversation to collaborators Oct 3, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@CarnaViire CarnaViire

Labels
area-System.Net.Http 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] Fix content stream read hang CarnaViire/runtime
3 participants
@JamesNK @CarnaViire @karelz