Skip to content

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

New issue
New issue
Closed
#58296
Closed
[HTTP/3] Hang when reading response data#57888
#58296
Assignees
CarnaViire
Labels
area-System.Net.Httpbugtenet-reliabilityReliability/stability related issue (stress, load problems, etc.)
Milestone
6.0.0
@JamesNK

Description

@JamesNK
JamesNK
opened on Aug 22, 2021

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

Metadata

Metadata

Assignees

Labels

area-System.Net.Httpbugtenet-reliabilityReliability/stability related issue (stress, load problems, etc.)

Type

No type

Projects

No projects

Milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions