[HTTP/3] Server sometimes doesn't receive notification of the end of request stream #57608
Description
The test scenario for this is quite complex. The client is attempting to POST request data to the server. It is sending it in chunks, and the server is failing a number of times, causing the client to retry the request.
When the client eventually sends all data, and the server successfully reads it, the client completes the request stream. The problem is the server doesn't seem to get that notification, so it never sends a response (just a simple response at the end, no bidirectional steaming involved), so the test times out.
Note that this is flakey. Sometimes it passes, sometimes it fails.
Test class: RetryTests
Test method: ClientStreaming_MultipleWritesAndRetries_Failure
https://github.com/grpc/grpc-dotnet/blob/f552a4982f76f7b1db7d9fcc33c7d44fe31be985/test/FunctionalTests/Client/RetryTests.cs#L40
Failure logs:
ClientStreaming_MultipleWritesAndRetries_Failure
Source: RetryTests.cs line 40
Duration: 5.6 sec
Message:
System.TimeoutException : The operation at C:\Development\Source\grpc-dotnet\test\FunctionalTests\Client\RetryTests.cs:96 timed out after reaching the limit of 5000ms.
Stack Trace:
TaskExtensions.TimeoutAfter[T](Task`1 task, TimeSpan timeout, String filePath, Int32 lineNumber) line 76
RetryTests.ClientStreaming_MultipleWritesAndRetries_Failure() line 96
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 RetryTests.ClientStreaming_MultipleWritesAndRetries_Failure
0.017s 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 'd74b4053-eb67-4e47-8f28-512d6f1a8ae6' to service 'DynamicService'. Method type: 'ClientStreaming', route pattern: '/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'.
0.061s Grpc.Net.Client.Internal.RetryCall - Trace: Starting retry worker.
0.063s Grpc.Net.Client.Internal.RetryCall - Debug: Starting attempt 1.
0.068s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : PushStreamContent`2#54860159,.ctor, ->
0.079s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpRequestMessage#43347212,Content,HttpRequestMessage#43347212,PushStreamContent`2#54860159 ->
0.094s Grpc.Net.Client.Internal.GrpcCall - Debug: Starting gRPC call. Method type: 'ClientStreaming', URI: 'https://127.0.0.1:50019/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'.
0.099s SystemNetEventSourceListener - Debug: <- Event System.Net.Http - RequestStart : https,127.0.0.1,50019,/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6,2,0,1 ->
0.132s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#66105400,.ctor,AutoConfigUrl=(null), AutoDetect=True, Proxy=(null), ProxyBypass=(null) ->
0.132s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#66105400,.ctor,_useProxy=True ->
0.132s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#66105400,TryCreate,AutoSettingsUsed, calling WinHttpOpen ->
0.137s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionHandler#1883749,.ctor, ->
0.137s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : DiagnosticsHandler#55334867,.ctor, ->
0.138s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : RedirectHandler#39996610,.ctor, ->
0.144s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - ErrorMessage : WinInetProxyHelper#66105400,GetProxyForUrl,error=12180 ->
0.144s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : WinInetProxyHelper#66105400,GetProxyForUrl,useProxy=False ->
0.147s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 6563976,0,0,.ctor,HttpConnectionPool https://127.0.0.1:50019 ->
0.151s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 6563976,0,0,GetHttp3ConnectionAsync,Attempting new HTTP3 connection. ->
0.153s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#20936295,.ctor,[conn][0x1E782D32A40] Outbound connection created ->
0.155s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,.ctor,[conn][0x1E782D99020] Inbound connection created ->
0.158s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,NativeCallbackHandler,[conn][0x1E782D99020] Connection received event IDEAL_PROCESSOR_CHANGED ->
0.163s GrpcTestContext - Information: Client writing message 0.
0.164s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#20936295,NativeCallbackHandler,[conn][0x1E782D32A40] Connection received event STREAMS_AVAILABLE ->
0.164s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#20936295,NativeCallbackHandler,[conn][0x1E782D32A40] Connection received event DATAGRAM_STATE_CHANGED ->
0.165s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#20936295,NativeCallbackHandler,[conn][0x1E782D32A40] Connection received event PEER_CERTIFICATE_RECEIVED ->
0.168s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : SafeX509ChainHandle#63449985,Verify,CertVerifyCertificateChainPolicy returned: True. Status: 2148204815 ->
0.168s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#20936295,NativeCallbackHandler,[conn][0x1E782D32A40] Connection received event CONNECTED ->
0.169s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,NativeCallbackHandler,[conn][0x1E782D99020] Connection received event CONNECTED ->
0.171s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#47741942,HandleEvent,(null) Stream received event START_COMPLETE ->
0.171s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#47741942,.ctor,[strm][0x1E782DEFD40] Outbound unidirectional stream created in connection [conn][0x1E782D32A40]. ->
0.172s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#47741942,HandleEvent,[strm][0x1E782DEFD40] Stream received event SEND_COMPLETE ->
0.172s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,NativeCallbackHandler,[conn][0x1E782D99020] Connection received event PEER_STREAM_STARTED ->
0.172s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,.ctor,[strm][0x1E782E02200] Inbound unidirectional stream created in connection [conn][0x1E782D99020]. ->
0.172s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,HandleEvent,[strm][0x1E782E02200] Stream received event RECEIVE ->
0.174s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Connection id "0HMB1Q46LVNPH" accepted.
0.177s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMB1Q46LVNPH" accepted.
0.177s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 6563976,0,0,GetHttp3ConnectionAsync,New HTTP3 connection established. ->
0.177s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMB1Q46LVNPH" started.
0.178s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,(null) Stream received event START_COMPLETE ->
0.178s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,.ctor,[strm][0x1E782E24C20] Outbound bidirectional stream created in connection [conn][0x1E782D32A40]. ->
0.182s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,HandleEvent,(null) Stream received event START_COMPLETE ->
0.182s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,.ctor,[strm][0x1E782E25F00] Outbound unidirectional stream created in connection [conn][0x1E782D99020]. ->
0.184s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x1E782E24C20] Stream received event SEND_COMPLETE ->
0.186s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,ReadAsync,[strm][0x1E782E24C20] Stream reading into Memory of '64' bytes. ->
0.187s Grpc.Net.Client.Internal.RetryCall - Trace: Sending 0 buffered messages from previous failed gRPC calls.
0.187s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,NativeCallbackHandler,[conn][0x1E782D99020] Connection received event PEER_STREAM_STARTED ->
0.187s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,.ctor,[strm][0x1E782E36390] Inbound bidirectional stream created in connection [conn][0x1E782D99020]. ->
0.187s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x1E782E36390] Stream received event RECEIVE ->
0.190s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPH:00000003" type Unidirectional connected.
0.194s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,HandleEvent,[strm][0x1E782E25F00] Stream received event SEND_COMPLETE ->
0.195s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#20936295,NativeCallbackHandler,[conn][0x1E782D32A40] Connection received event PEER_STREAM_STARTED ->
0.195s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,.ctor,[strm][0x1E782E57DA0] Inbound unidirectional stream created in connection [conn][0x1E782D32A40]. ->
0.195s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,HandleEvent,[strm][0x1E782E57DA0] Stream received event RECEIVE ->
0.197s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,ReadAsync,[strm][0x1E782E57DA0] Stream reading into Memory of '32' bytes. ->
0.197s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.197s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,HandleEvent,[strm][0x1E782E25F00] Stream received event SEND_COMPLETE ->
0.198s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,HandleEvent,[strm][0x1E782E57DA0] Stream received event RECEIVE ->
0.198s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,ReadAsync,[strm][0x1E782E57DA0] Stream reading into Memory of '32' bytes. ->
0.198s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,ReadAsync,[strm][0x1E782E02200] Stream reading into Memory of '4096' bytes. ->
0.199s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,ReadAsync,[strm][0x1E782E57DA0] Stream reading into Memory of '32' bytes. ->
0.199s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,ReadAsync,[strm][0x1E782E02200] Stream reading into Memory of '4096' bytes. ->
0.200s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPH:00000002" type Unidirectional accepted.
0.201s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,ReadAsync,[strm][0x1E782E36390] Stream reading into Memory of '4096' bytes. ->
0.201s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,ReadAsync,[strm][0x1E782E36390] Stream reading into Memory of '4096' bytes. ->
0.201s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPH:00000000" type Bidirectional accepted.
0.203s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 8 bytes buffered for this call.
0.205s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPH" received SETTINGS frame for stream ID 2 with length 5.
0.205s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.206s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPH" received HEADERS frame for stream ID 0 with length 260.
0.207s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x1E782E24C20] Stream received event SEND_COMPLETE ->
0.207s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x1E782E36390] Stream received event RECEIVE ->
0.208s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,ReadAsync,[strm][0x1E782E36390] Stream reading into Memory of '4096' bytes. ->
0.208s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.220s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPH" received DATA frame for stream ID 0 with length 8.
0.225s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request starting HTTP/3 POST https://127.0.0.1:50019/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6 application/grpc -
0.231s GrpcTestContext - Information: Client writing message 1.
0.231s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.231s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 16 bytes buffered for this call.
0.231s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.231s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x1E782E24C20] Stream received event SEND_COMPLETE ->
0.231s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.231s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x1E782E36390] Stream received event RECEIVE ->
0.231s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,ReadAsync,[strm][0x1E782E36390] Stream reading into Memory of '4096' bytes. ->
0.231s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x1E782E24C20] Stream received event IDEAL_SEND_BUFFER_SIZE ->
0.232s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPH" received DATA frame for stream ID 0 with length 8.
0.245s GrpcTestContext - Information: Client writing message 2.
0.245s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.245s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 24 bytes buffered for this call.
0.246s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.246s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x1E782E24C20] Stream received event SEND_COMPLETE ->
0.246s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.246s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x1E782E36390] Stream received event RECEIVE ->
0.246s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,ReadAsync,[strm][0x1E782E36390] Stream reading into Memory of '4096' bytes. ->
0.246s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPH" received DATA frame for stream ID 0 with length 8.
0.249s SERVER Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware - Debug: Request matched endpoint 'gRPC - /DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'
0.255s SERVER Microsoft.AspNetCore.Routing.EndpointMiddleware - Information: Executing endpoint 'gRPC - /DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'
0.261s GrpcTestContext - Information: Client writing message 3.
0.261s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.262s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 32 bytes buffered for this call.
0.262s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.262s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x1E782E24C20] Stream received event SEND_COMPLETE ->
0.262s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.262s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x1E782E36390] Stream received event RECEIVE ->
0.262s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,ReadAsync,[strm][0x1E782E36390] Stream reading into Memory of '4096' bytes. ->
0.262s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPH" received DATA frame for stream ID 0 with length 8.
0.270s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.271s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB1Q46LVNPH", Request id "0HMB1Q46LVNPH:00000000": started reading request body.
0.273s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.277s GrpcTestContext - Information: Client writing message 4.
0.278s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.278s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 40 bytes buffered for this call.
0.278s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.278s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x1E782E24C20] Stream received event SEND_COMPLETE ->
0.278s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.278s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x1E782E36390] Stream received event RECEIVE ->
0.278s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,ReadAsync,[strm][0x1E782E36390] Stream reading into Memory of '4096' bytes. ->
0.278s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.278s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPH" received DATA frame for stream ID 0 with length 8.
0.278s GrpcTestContext - Information: Server received 0.
0.279s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.279s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.279s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.279s GrpcTestContext - Information: Server failing at 1.
0.283s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Information: Error status code 'Unavailable' raised.
Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="")
at Grpc.AspNetCore.FunctionalTests.Client.RetryTests.<>c__DisplayClass0_0.<<ClientStreaming_MultipleWritesAndRetries_Failure>g__ClientStreamingWithReadFailures|0>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\FunctionalTests\Client\RetryTests.cs:line 53
--- End of stack trace from previous location ---
at Grpc.AspNetCore.FunctionalTests.Client.RetryTests.<>c__DisplayClass0_0.<<ClientStreaming_MultipleWritesAndRetries_Failure>g__ClientStreamingWithReadFailures|0>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\FunctionalTests\Client\RetryTests.cs:line 47
--- End of stack trace from previous location ---
at Grpc.Shared.Server.ClientStreamingServerMethodInvoker`3.Invoke(HttpContext httpContext, ServerCallContext serverCallContext, IAsyncStreamReader`1 requestStream) in C:\Development\Source\grpc-dotnet\src\Shared\Server\ClientStreamingServerMethodInvoker.cs:line 100
at Grpc.Shared.Server.ClientStreamingServerMethodInvoker`3.Invoke(HttpContext httpContext, ServerCallContext serverCallContext, IAsyncStreamReader`1 requestStream) in C:\Development\Source\grpc-dotnet\src\Shared\Server\ClientStreamingServerMethodInvoker.cs:line 111
at Grpc.AspNetCore.Server.Internal.CallHandlers.ClientStreamingServerCallHandler`3.HandleCallAsyncCore(HttpContext httpContext, HttpContextServerCallContext serverCallContext) in C:\Development\Source\grpc-dotnet\src\Grpc.AspNetCore.Server\Internal\CallHandlers\ClientStreamingServerCallHandler.cs:line 52
at Grpc.AspNetCore.Server.Internal.CallHandlers.ServerCallHandlerBase`3.<HandleCallAsync>g__AwaitHandleCall|8_0(HttpContextServerCallContext serverCallContext, Method`2 method, Task handleCall) in C:\Development\Source\grpc-dotnet\src\Grpc.AspNetCore.Server\Internal\CallHandlers\ServerCallHandlerBase.cs:line 95
0.293s GrpcTestContext - Information: Client writing message 5.
0.304s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.304s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 48 bytes buffered for this call.
0.304s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.304s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x1E782E24C20] Stream received event SEND_COMPLETE ->
0.304s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.305s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x1E782E36390] Stream received event RECEIVE ->
0.305s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,ReadAsync,[strm][0x1E782E36390] Stream reading into Memory of '4096' bytes. ->
0.305s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPH" received DATA frame for stream ID 0 with length 8.
0.307s SERVER Microsoft.AspNetCore.Routing.EndpointMiddleware - Information: Executed endpoint 'gRPC - /DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'
0.309s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPH" sending HEADERS frame for stream ID 0 with length 149.
0.309s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x1E782E36390] Stream received event SEND_COMPLETE ->
0.309s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPH:00000000" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
0.309s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x1E782E24C20] Stream received event RECEIVE ->
0.310s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x1E782E24C20] Stream received event RECEIVE ->
0.310s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x1E782E36390] Stream received event SEND_SHUTDOWN_COMPLETE ->
0.310s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x1E782E36390] Stream received event IDEAL_SEND_BUFFER_SIZE ->
0.310s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 6563976,19208783,0,ReadFrameEnvelopeAsync,Received frame 1 of length 149. ->
0.311s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request finished HTTP/3 POST https://127.0.0.1:50019/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6 application/grpc - - 200 0 application/grpc 85.8864ms
0.311s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#2681320,RequestMessage,HttpResponseMessage#2681320,HttpRequestMessage#43347212 ->
0.311s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionResponseContent#5135072,.ctor, ->
0.311s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#2681320,Content,HttpResponseMessage#2681320,HttpConnectionResponseContent#5135072 ->
0.311s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,ReadAsync,[strm][0x1E782E24C20] Stream reading into Memory of '64' bytes. ->
0.311s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x1E782E24C20] Stream received event RECEIVE ->
0.312s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,ReadAsync,[strm][0x1E782E24C20] Stream reading into Memory of '64' bytes. ->
0.312s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x1E782E24C20] Stream received event PEER_SEND_SHUTDOWN ->
0.312s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEventPeerSendShutdown,[strm][0x1E782E24C20] Stream completing resettable event source. ->
0.312s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB1Q46LVNPH", Request id "0HMB1Q46LVNPH:00000000": done reading request body.
0.312s SERVER Microsoft.AspNetCore.Server.Kestrel - Information: Connection id "0HMB1Q46LVNPH", Request id "0HMB1Q46LVNPH:00000000": the application completed without reading the entire request body.
0.315s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPH:00000000" read side aborted by application with error code 256 because: "The application completed without reading the entire request body.".
0.319s SystemNetEventSourceListener - Debug: <- Event System.Net.Http - RequestStop : ->
0.319s Grpc.Net.Client.Internal.GrpcCall - Trace: Response headers received.
0.320s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x1E782E24C20] Stream received event PEER_RECEIVE_ABORTED ->
0.321s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,Dispose,[strm][0x1E782E36390] Stream disposing True ->
0.321s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,Dispose,[strm][0x1E782E36390] Stream disposed ->
0.321s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEvent,[strm][0x1E782E36390] Stream received event SHUTDOWN_COMPLETE ->
0.321s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,HandleEventShutdownComplete,[strm][0x1E782E36390] Stream completing resettable event source. ->
0.321s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58801125,Cleanup,[strm][0x1E782E36390] releasing handles. ->
0.321s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x1E782E24C20] Stream received event SEND_SHUTDOWN_COMPLETE ->
0.321s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEvent,[strm][0x1E782E24C20] Stream received event SHUTDOWN_COMPLETE ->
0.321s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,HandleEventShutdownComplete,[strm][0x1E782E24C20] Stream completing resettable event source. ->
0.321s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#20936295,NativeCallbackHandler,[conn][0x1E782D32A40] Connection received event STREAMS_AVAILABLE ->
0.324s Grpc.Net.Client.Internal.GrpcCall - Information: Call failed with gRPC error status. Status code: 'Unavailable', Message: '(null)'.
0.324s Grpc.Net.Client.Internal.RetryCall - Debug: Evaluated retry for failed gRPC call. Status code: 'Unavailable', Attempt: 1, Retry: True
0.325s Grpc.Net.Client.Internal.GrpcCall - Debug: Finished gRPC call.
0.325s GrpcTestContext - Information: Client writing message 6.
0.326s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,Dispose,[strm][0x1E782E24C20] Stream disposing True ->
0.326s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,Cleanup,[strm][0x1E782E24C20] releasing handles. ->
0.326s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#456780,Dispose,[strm][0x1E782E24C20] Stream disposed ->
0.327s Grpc.Net.Client.Internal.RetryCall - Trace: Starting retry delay of 00:00:00.
0.328s Grpc.Net.Client.Internal.RetryCall - Debug: Starting attempt 2.
0.328s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : PushStreamContent`2#23694519,.ctor, ->
0.328s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpRequestMessage#31951190,Content,HttpRequestMessage#31951190,PushStreamContent`2#23694519 ->
0.328s Grpc.Net.Client.Internal.GrpcCall - Debug: Starting gRPC call. Method type: 'ClientStreaming', URI: 'https://127.0.0.1:50019/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'.
0.328s SystemNetEventSourceListener - Debug: <- Event System.Net.Http - RequestStart : https,127.0.0.1,50019,/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6,2,0,1 ->
0.329s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 6563976,19208783,0,GetHttp3ConnectionAsync,Found expired HTTP3 connection. ->
0.329s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#47741942,Dispose,[strm][0x1E782DEFD40] Stream disposing True ->
0.329s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#47741942,Dispose,[strm][0x1E782DEFD40] Stream disposed ->
0.329s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 6563976,0,0,GetHttp3ConnectionAsync,Attempting new HTTP3 connection. ->
0.329s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#47741942,HandleEvent,[strm][0x1E782DEFD40] Stream received event SEND_SHUTDOWN_COMPLETE ->
0.329s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#47741942,HandleEvent,[strm][0x1E782DEFD40] Stream received event SHUTDOWN_COMPLETE ->
0.329s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#47741942,HandleEventConnectionClose,[strm][0x1E782DEFD40] Stream handling connection [conn][0x1E782D32A40] close ->
0.329s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,HandleEvent,[strm][0x1E782E02200] Stream received event RECEIVE ->
0.329s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,HandleEvent,[strm][0x1E782E02200] Stream received event PEER_SEND_SHUTDOWN ->
0.329s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,HandleEventPeerSendShutdown,[strm][0x1E782E02200] Stream completing resettable event source. ->
0.329s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,HandleEvent,[strm][0x1E782E02200] Stream received event SHUTDOWN_COMPLETE ->
0.329s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,HandleEventShutdownComplete,[strm][0x1E782E02200] Stream completing resettable event source. ->
0.329s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#47741942,Cleanup,[strm][0x1E782DEFD40] releasing handles. ->
0.329s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,HandleEvent,[strm][0x1E782E57DA0] Stream received event SHUTDOWN_COMPLETE ->
0.329s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,HandleEventConnectionClose,[strm][0x1E782E57DA0] Stream handling connection [conn][0x1E782D32A40] close ->
0.329s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34930376,.ctor,[conn][0x1E782D36F10] Outbound connection created ->
0.329s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,NativeCallbackHandler,[conn][0x1E782D99020] Connection received event SHUTDOWN_INITIATED_BY_PEER ->
0.330s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,HandleEvent,[strm][0x1E782E25F00] Stream received event SEND_SHUTDOWN_COMPLETE ->
0.330s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,HandleEvent,[strm][0x1E782E25F00] Stream received event SHUTDOWN_COMPLETE ->
0.330s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,HandleEventConnectionClose,[strm][0x1E782E25F00] Stream handling connection [conn][0x1E782D99020] close with code 256 ->
0.330s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#20936295,NativeCallbackHandler,[conn][0x1E782D32A40] Connection received event SHUTDOWN_COMPLETE ->
0.331s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#20936295,Dispose,[conn][0x1E782D32A40] Connection disposing True ->
0.331s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2256335,.ctor,[conn][0x1E782E9D0A0] Inbound connection created ->
0.331s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,Dispose,[strm][0x1E782E57DA0] Stream disposing True ->
0.331s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,Cleanup,[strm][0x1E782E57DA0] releasing handles. ->
0.331s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#20936295,RemoveStream,[conn][0x1E782D32A40] releasing handle after last stream. ->
0.331s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2256335,NativeCallbackHandler,[conn][0x1E782E9D0A0] Connection received event IDEAL_PROCESSOR_CHANGED ->
0.331s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#44307732,Dispose,[strm][0x1E782E57DA0] Stream disposed ->
0.334s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Connection id "0HMB1Q46LVNPH" aborted by peer with error code 256.
System.Net.Quic.QuicConnectionAbortedException: Connection aborted by peer (256).
at System.Net.Quic.Implementations.MsQuic.MsQuicConnection.AcceptStreamAsync(CancellationToken cancellationToken)
at System.Net.Quic.QuicConnection.AcceptStreamAsync(CancellationToken cancellationToken)
at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicConnectionContext.AcceptAsync(CancellationToken cancellationToken)
0.335s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Connection id "0HMB1Q46LVNPH" aborted by application with error code 256 because: "The client closed the connection.".
0.335s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,NativeCallbackHandler,[conn][0x1E782D99020] Connection received event SHUTDOWN_COMPLETE ->
0.338s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Debug: Connection id "0HMB1Q46LVNPH" is closed. The last processed stream ID was 0.
0.339s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34930376,NativeCallbackHandler,[conn][0x1E782D36F10] Connection received event STREAMS_AVAILABLE ->
0.339s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34930376,NativeCallbackHandler,[conn][0x1E782D36F10] Connection received event DATAGRAM_STATE_CHANGED ->
0.339s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMB1Q46LVNPH" stopped.
0.339s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,Dispose,[conn][0x1E782D99020] Connection disposing True ->
0.339s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34930376,NativeCallbackHandler,[conn][0x1E782D36F10] Connection received event PEER_CERTIFICATE_RECEIVED ->
0.341s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : SafeX509ChainHandle#52435881,Verify,CertVerifyCertificateChainPolicy returned: True. Status: 2148204815 ->
0.341s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34930376,NativeCallbackHandler,[conn][0x1E782D36F10] Connection received event CONNECTED ->
0.341s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#19674623,HandleEvent,(null) Stream received event START_COMPLETE ->
0.341s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#19674623,.ctor,[strm][0x1E782D88C40] Outbound unidirectional stream created in connection [conn][0x1E782D36F10]. ->
0.341s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#19674623,HandleEvent,[strm][0x1E782D88C40] Stream received event SEND_COMPLETE ->
0.341s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 6563976,0,0,GetHttp3ConnectionAsync,New HTTP3 connection established. ->
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,HandleEvent,(null) Stream received event START_COMPLETE ->
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,.ctor,[strm][0x1E782EE5F90] Outbound bidirectional stream created in connection [conn][0x1E782D36F10]. ->
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2256335,NativeCallbackHandler,[conn][0x1E782E9D0A0] Connection received event CONNECTED ->
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2256335,NativeCallbackHandler,[conn][0x1E782E9D0A0] Connection received event PEER_STREAM_STARTED ->
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,ReadAsync,[strm][0x1E782EE5F90] Stream reading into Memory of '64' bytes. ->
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#48191601,.ctor,[strm][0x1E782EB03F0] Inbound unidirectional stream created in connection [conn][0x1E782E9D0A0]. ->
0.342s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Connection id "0HMB1Q46LVNPI" accepted.
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#48191601,HandleEvent,[strm][0x1E782EB03F0] Stream received event RECEIVE ->
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2256335,NativeCallbackHandler,[conn][0x1E782E9D0A0] Connection received event PEER_STREAM_STARTED ->
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,.ctor,[strm][0x1E782EB0750] Inbound bidirectional stream created in connection [conn][0x1E782E9D0A0]. ->
0.342s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMB1Q46LVNPI" accepted.
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.342s Grpc.Net.Client.Internal.RetryCall - Trace: Sending 6 buffered messages from previous failed gRPC calls.
0.342s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMB1Q46LVNPI" started.
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58698824,HandleEvent,(null) Stream received event START_COMPLETE ->
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58698824,.ctor,[strm][0x1E782D350E0] Outbound unidirectional stream created in connection [conn][0x1E782E9D0A0]. ->
0.342s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPI:00000003" type Unidirectional connected.
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58698824,HandleEvent,[strm][0x1E782D350E0] Stream received event SEND_COMPLETE ->
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#58698824,HandleEvent,[strm][0x1E782D350E0] Stream received event SEND_COMPLETE ->
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#48191601,ReadAsync,[strm][0x1E782EB03F0] Stream reading into Memory of '4096' bytes. ->
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#48191601,ReadAsync,[strm][0x1E782EB03F0] Stream reading into Memory of '4096' bytes. ->
0.342s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPI:00000002" type Unidirectional accepted.
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34930376,NativeCallbackHandler,[conn][0x1E782D36F10] Connection received event PEER_STREAM_STARTED ->
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#36788523,.ctor,[strm][0x1E782F18F50] Inbound unidirectional stream created in connection [conn][0x1E782D36F10]. ->
0.342s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.343s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.343s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPI:00000000" type Bidirectional accepted.
0.343s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#36788523,HandleEvent,[strm][0x1E782F18F50] Stream received event RECEIVE ->
0.343s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#36788523,ReadAsync,[strm][0x1E782F18F50] Stream reading into Memory of '32' bytes. ->
0.343s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received SETTINGS frame for stream ID 2 with length 5.
0.343s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#36788523,ReadAsync,[strm][0x1E782F18F50] Stream reading into Memory of '32' bytes. ->
0.343s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received HEADERS frame for stream ID 0 with length 290.
0.343s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request starting HTTP/3 POST https://127.0.0.1:50019/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6 application/grpc -
0.344s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.344s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.344s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.344s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 0 with length 8.
0.344s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.344s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.344s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.344s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.344s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 0 with length 8.
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.344s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.344s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.344s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 0 with length 8.
0.344s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.344s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.344s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 0 with length 8.
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.344s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,HandleEvent,[strm][0x1E782EE5F90] Stream received event IDEAL_SEND_BUFFER_SIZE ->
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.344s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 0 with length 8.
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.344s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.344s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 0 with length 8.
0.344s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 56 bytes buffered for this call.
0.344s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.344s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.344s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.345s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.345s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.345s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 0 with length 8.
0.348s SERVER Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware - Debug: Request matched endpoint 'gRPC - /DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'
0.348s SERVER Microsoft.AspNetCore.Routing.EndpointMiddleware - Information: Executing endpoint 'gRPC - /DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'
0.349s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.349s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB1Q46LVNPI", Request id "0HMB1Q46LVNPI:00000000": started reading request body.
0.349s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.349s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.349s GrpcTestContext - Information: Server received 0.
0.349s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.349s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.349s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.349s GrpcTestContext - Information: Server received 1.
0.349s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.349s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.349s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.349s GrpcTestContext - Information: Server failing at 2.
0.349s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Information: Error status code 'Unavailable' raised.
Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="")
at Grpc.AspNetCore.FunctionalTests.Client.RetryTests.<>c__DisplayClass0_0.<<ClientStreaming_MultipleWritesAndRetries_Failure>g__ClientStreamingWithReadFailures|0>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\FunctionalTests\Client\RetryTests.cs:line 53
--- End of stack trace from previous location ---
at Grpc.AspNetCore.FunctionalTests.Client.RetryTests.<>c__DisplayClass0_0.<<ClientStreaming_MultipleWritesAndRetries_Failure>g__ClientStreamingWithReadFailures|0>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\FunctionalTests\Client\RetryTests.cs:line 47
--- End of stack trace from previous location ---
at Grpc.Shared.Server.ClientStreamingServerMethodInvoker`3.Invoke(HttpContext httpContext, ServerCallContext serverCallContext, IAsyncStreamReader`1 requestStream) in C:\Development\Source\grpc-dotnet\src\Shared\Server\ClientStreamingServerMethodInvoker.cs:line 100
at Grpc.Shared.Server.ClientStreamingServerMethodInvoker`3.Invoke(HttpContext httpContext, ServerCallContext serverCallContext, IAsyncStreamReader`1 requestStream) in C:\Development\Source\grpc-dotnet\src\Shared\Server\ClientStreamingServerMethodInvoker.cs:line 111
at Grpc.AspNetCore.Server.Internal.CallHandlers.ClientStreamingServerCallHandler`3.HandleCallAsyncCore(HttpContext httpContext, HttpContextServerCallContext serverCallContext) in C:\Development\Source\grpc-dotnet\src\Grpc.AspNetCore.Server\Internal\CallHandlers\ClientStreamingServerCallHandler.cs:line 52
at Grpc.AspNetCore.Server.Internal.CallHandlers.ServerCallHandlerBase`3.<HandleCallAsync>g__AwaitHandleCall|8_0(HttpContextServerCallContext serverCallContext, Method`2 method, Task handleCall) in C:\Development\Source\grpc-dotnet\src\Grpc.AspNetCore.Server\Internal\CallHandlers\ServerCallHandlerBase.cs:line 95
0.349s SERVER Microsoft.AspNetCore.Routing.EndpointMiddleware - Information: Executed endpoint 'gRPC - /DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'
0.349s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" sending HEADERS frame for stream ID 0 with length 149.
0.350s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,HandleEvent,[strm][0x1E782EB0750] Stream received event SEND_COMPLETE ->
0.350s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request finished HTTP/3 POST https://127.0.0.1:50019/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6 application/grpc - - 200 0 application/grpc 6.6469ms
0.350s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPI:00000000" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
0.350s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB1Q46LVNPI", Request id "0HMB1Q46LVNPI:00000000": done reading request body.
0.350s SERVER Microsoft.AspNetCore.Server.Kestrel - Information: Connection id "0HMB1Q46LVNPI", Request id "0HMB1Q46LVNPI:00000000": the application completed without reading the entire request body.
0.350s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPI:00000000" read side aborted by application with error code 256 because: "The application completed without reading the entire request body.".
0.350s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,Dispose,[strm][0x1E782EB0750] Stream disposing True ->
0.350s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,Dispose,[strm][0x1E782EB0750] Stream disposed ->
0.354s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,HandleEvent,[strm][0x1E782EE5F90] Stream received event RECEIVE ->
0.354s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,HandleEvent,[strm][0x1E782EE5F90] Stream received event RECEIVE ->
0.354s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 6563976,27207609,0,ReadFrameEnvelopeAsync,Received frame 1 of length 149. ->
0.354s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,HandleEvent,[strm][0x1E782EE5F90] Stream received event PEER_RECEIVE_ABORTED ->
0.354s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#30945470,RequestMessage,HttpResponseMessage#30945470,HttpRequestMessage#31951190 ->
0.354s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionResponseContent#13119256,.ctor, ->
0.354s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#30945470,Content,HttpResponseMessage#30945470,HttpConnectionResponseContent#13119256 ->
0.354s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,ReadAsync,[strm][0x1E782EE5F90] Stream reading into Memory of '64' bytes. ->
0.354s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,ReadAsync,[strm][0x1E782EE5F90] Stream reading into Memory of '64' bytes. ->
0.354s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,HandleEvent,[strm][0x1E782EB0750] Stream received event SEND_SHUTDOWN_COMPLETE ->
0.354s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,HandleEvent,[strm][0x1E782EE5F90] Stream received event RECEIVE ->
0.354s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,HandleEvent,[strm][0x1E782EE5F90] Stream received event PEER_SEND_SHUTDOWN ->
0.354s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,HandleEventPeerSendShutdown,[strm][0x1E782EE5F90] Stream completing resettable event source. ->
0.354s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,HandleEvent,[strm][0x1E782EB0750] Stream received event IDEAL_SEND_BUFFER_SIZE ->
0.354s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,HandleEvent,[strm][0x1E782EB0750] Stream received event SHUTDOWN_COMPLETE ->
0.354s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,HandleEventShutdownComplete,[strm][0x1E782EB0750] Stream completing resettable event source. ->
0.354s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18393173,Cleanup,[strm][0x1E782EB0750] releasing handles. ->
0.355s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_SHUTDOWN_COMPLETE ->
0.355s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,HandleEvent,[strm][0x1E782EE5F90] Stream received event SHUTDOWN_COMPLETE ->
0.355s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,HandleEventShutdownComplete,[strm][0x1E782EE5F90] Stream completing resettable event source. ->
0.355s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34930376,NativeCallbackHandler,[conn][0x1E782D36F10] Connection received event STREAMS_AVAILABLE ->
0.356s SystemNetEventSourceListener - Debug: <- Event System.Net.Http - RequestStop : ->
0.356s Grpc.Net.Client.Internal.GrpcCall - Trace: Response headers received.
0.356s Grpc.Net.Client.Internal.GrpcCall - Information: Call failed with gRPC error status. Status code: 'Unavailable', Message: '(null)'.
0.356s Grpc.Net.Client.Internal.GrpcCall - Debug: Finished gRPC call.
0.356s Grpc.Net.Client.Internal.RetryCall - Debug: Evaluated retry for failed gRPC call. Status code: 'Unavailable', Attempt: 2, Retry: True
0.356s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,Dispose,[strm][0x1E782EE5F90] Stream disposing True ->
0.356s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,Cleanup,[strm][0x1E782EE5F90] releasing handles. ->
0.356s Grpc.Net.Client.Internal.RetryCall - Trace: Starting retry delay of 00:00:00.
0.356s Grpc.Net.Client.Internal.RetryCall - Debug: Starting attempt 3.
0.356s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#8639934,Dispose,[strm][0x1E782EE5F90] Stream disposed ->
0.356s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : PushStreamContent`2#28913487,.ctor, ->
0.356s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpRequestMessage#41727345,Content,HttpRequestMessage#41727345,PushStreamContent`2#28913487 ->
0.356s Grpc.Net.Client.Internal.GrpcCall - Debug: Starting gRPC call. Method type: 'ClientStreaming', URI: 'https://127.0.0.1:50019/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'.
0.356s SystemNetEventSourceListener - Debug: <- Event System.Net.Http - RequestStart : https,127.0.0.1,50019,/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6,2,0,1 ->
0.356s GrpcTestContext - Information: Client writing message 7.
0.356s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 6563976,0,0,GetHttp3ConnectionAsync,Using existing HTTP3 connection. ->
0.356s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEvent,(null) Stream received event START_COMPLETE ->
0.356s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,.ctor,[strm][0x1E782EE5F90] Outbound bidirectional stream created in connection [conn][0x1E782D36F10]. ->
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,ReadAsync,[strm][0x1E782EE5F90] Stream reading into Memory of '64' bytes. ->
0.357s Grpc.Net.Client.Internal.RetryCall - Trace: Sending 7 buffered messages from previous failed gRPC calls.
0.357s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2256335,NativeCallbackHandler,[conn][0x1E782E9D0A0] Connection received event PEER_STREAM_STARTED ->
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,.ctor,[strm][0x1E782EB0750] Inbound bidirectional stream created in connection [conn][0x1E782E9D0A0]. ->
0.357s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.357s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.357s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.357s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.357s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.357s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.357s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPI:00000004" type Bidirectional accepted.
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.357s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.357s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.357s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.357s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEvent,[strm][0x1E782EE5F90] Stream received event IDEAL_SEND_BUFFER_SIZE ->
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.357s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.357s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.357s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.357s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.357s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 64 bytes buffered for this call.
0.357s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.357s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received HEADERS frame for stream ID 4 with length 290.
0.357s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.357s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.362s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 4 with length 8.
0.362s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request starting HTTP/3 POST https://127.0.0.1:50019/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6 application/grpc -
0.362s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 4 with length 8.
0.362s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 4 with length 8.
0.362s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 4 with length 8.
0.362s SERVER Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware - Debug: Request matched endpoint 'gRPC - /DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'
0.362s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 4 with length 8.
0.362s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 4 with length 8.
0.362s SERVER Microsoft.AspNetCore.Routing.EndpointMiddleware - Information: Executing endpoint 'gRPC - /DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'
0.362s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.362s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB1Q46LVNPI", Request id "0HMB1Q46LVNPI:00000004": started reading request body.
0.362s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.362s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.362s GrpcTestContext - Information: Server received 0.
0.362s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.362s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.362s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.362s GrpcTestContext - Information: Server received 1.
0.362s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.362s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.362s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.362s GrpcTestContext - Information: Server received 2.
0.362s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.362s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.362s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.362s GrpcTestContext - Information: Server received 3.
0.362s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.362s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.362s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.362s GrpcTestContext - Information: Server failing at 4.
0.362s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 4 with length 8.
0.362s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 4 with length 8.
0.362s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Information: Error status code 'Unavailable' raised.
Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="")
at Grpc.AspNetCore.FunctionalTests.Client.RetryTests.<>c__DisplayClass0_0.<<ClientStreaming_MultipleWritesAndRetries_Failure>g__ClientStreamingWithReadFailures|0>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\FunctionalTests\Client\RetryTests.cs:line 53
--- End of stack trace from previous location ---
at Grpc.AspNetCore.FunctionalTests.Client.RetryTests.<>c__DisplayClass0_0.<<ClientStreaming_MultipleWritesAndRetries_Failure>g__ClientStreamingWithReadFailures|0>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\FunctionalTests\Client\RetryTests.cs:line 47
--- End of stack trace from previous location ---
at Grpc.Shared.Server.ClientStreamingServerMethodInvoker`3.Invoke(HttpContext httpContext, ServerCallContext serverCallContext, IAsyncStreamReader`1 requestStream) in C:\Development\Source\grpc-dotnet\src\Shared\Server\ClientStreamingServerMethodInvoker.cs:line 100
at Grpc.Shared.Server.ClientStreamingServerMethodInvoker`3.Invoke(HttpContext httpContext, ServerCallContext serverCallContext, IAsyncStreamReader`1 requestStream) in C:\Development\Source\grpc-dotnet\src\Shared\Server\ClientStreamingServerMethodInvoker.cs:line 111
at Grpc.AspNetCore.Server.Internal.CallHandlers.ClientStreamingServerCallHandler`3.HandleCallAsyncCore(HttpContext httpContext, HttpContextServerCallContext serverCallContext) in C:\Development\Source\grpc-dotnet\src\Grpc.AspNetCore.Server\Internal\CallHandlers\ClientStreamingServerCallHandler.cs:line 52
at Grpc.AspNetCore.Server.Internal.CallHandlers.ServerCallHandlerBase`3.<HandleCallAsync>g__AwaitHandleCall|8_0(HttpContextServerCallContext serverCallContext, Method`2 method, Task handleCall) in C:\Development\Source\grpc-dotnet\src\Grpc.AspNetCore.Server\Internal\CallHandlers\ServerCallHandlerBase.cs:line 95
0.363s SERVER Microsoft.AspNetCore.Routing.EndpointMiddleware - Information: Executed endpoint 'gRPC - /DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'
0.363s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" sending HEADERS frame for stream ID 4 with length 149.
0.363s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request finished HTTP/3 POST https://127.0.0.1:50019/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6 application/grpc - - 200 0 application/grpc 1.2540ms
0.363s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB1Q46LVNPI", Request id "0HMB1Q46LVNPI:00000004": done reading request body.
0.363s SERVER Microsoft.AspNetCore.Server.Kestrel - Information: Connection id "0HMB1Q46LVNPI", Request id "0HMB1Q46LVNPI:00000004": the application completed without reading the entire request body.
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,HandleEvent,[strm][0x1E782EB0750] Stream received event SEND_COMPLETE ->
0.363s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPI:00000004" read side aborted by application with error code 256 because: "The application completed without reading the entire request body.".
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEvent,[strm][0x1E782EE5F90] Stream received event RECEIVE ->
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEvent,[strm][0x1E782EE5F90] Stream received event RECEIVE ->
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 6563976,27207609,4,ReadFrameEnvelopeAsync,Received frame 1 of length 149. ->
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#4916187,RequestMessage,HttpResponseMessage#4916187,HttpRequestMessage#41727345 ->
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionResponseContent#59231349,.ctor, ->
0.363s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPI:00000004" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#4916187,Content,HttpResponseMessage#4916187,HttpConnectionResponseContent#59231349 ->
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,ReadAsync,[strm][0x1E782EE5F90] Stream reading into Memory of '64' bytes. ->
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,ReadAsync,[strm][0x1E782EE5F90] Stream reading into Memory of '64' bytes. ->
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,HandleEvent,[strm][0x1E782EB0750] Stream received event SEND_SHUTDOWN_COMPLETE ->
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEvent,[strm][0x1E782EE5F90] Stream received event PEER_RECEIVE_ABORTED ->
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,HandleEvent,[strm][0x1E782EB0750] Stream received event IDEAL_SEND_BUFFER_SIZE ->
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,Dispose,[strm][0x1E782EB0750] Stream disposing True ->
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,Dispose,[strm][0x1E782EB0750] Stream disposed ->
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEvent,[strm][0x1E782EE5F90] Stream received event RECEIVE ->
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEvent,[strm][0x1E782EE5F90] Stream received event PEER_SEND_SHUTDOWN ->
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEventPeerSendShutdown,[strm][0x1E782EE5F90] Stream completing resettable event source. ->
0.363s SystemNetEventSourceListener - Debug: <- Event System.Net.Http - RequestStop : ->
0.363s Grpc.Net.Client.Internal.GrpcCall - Trace: Response headers received.
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,HandleEvent,[strm][0x1E782EB0750] Stream received event SHUTDOWN_COMPLETE ->
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,HandleEventShutdownComplete,[strm][0x1E782EB0750] Stream completing resettable event source. ->
0.363s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#22829829,Cleanup,[strm][0x1E782EB0750] releasing handles. ->
0.363s Grpc.Net.Client.Internal.GrpcCall - Information: Call failed with gRPC error status. Status code: 'Unavailable', Message: '(null)'.
0.363s Grpc.Net.Client.Internal.GrpcCall - Debug: Finished gRPC call.
0.364s Grpc.Net.Client.Internal.RetryCall - Debug: Evaluated retry for failed gRPC call. Status code: 'Unavailable', Attempt: 3, Retry: True
0.364s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,Dispose,[strm][0x1E782EE5F90] Stream disposing True ->
0.364s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,Dispose,[strm][0x1E782EE5F90] Stream disposed ->
0.364s Grpc.Net.Client.Internal.RetryCall - Trace: Starting retry delay of 00:00:00.
0.364s Grpc.Net.Client.Internal.RetryCall - Debug: Starting attempt 4.
0.364s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : PushStreamContent`2#17987329,.ctor, ->
0.364s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpRequestMessage#13804354,Content,HttpRequestMessage#13804354,PushStreamContent`2#17987329 ->
0.364s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_SHUTDOWN_COMPLETE ->
0.364s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEvent,[strm][0x1E782EE5F90] Stream received event SHUTDOWN_COMPLETE ->
0.364s Grpc.Net.Client.Internal.GrpcCall - Debug: Starting gRPC call. Method type: 'ClientStreaming', URI: 'https://127.0.0.1:50019/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'.
0.364s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,HandleEventShutdownComplete,[strm][0x1E782EE5F90] Stream completing resettable event source. ->
0.364s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#63462474,Cleanup,[strm][0x1E782EE5F90] releasing handles. ->
0.364s SystemNetEventSourceListener - Debug: <- Event System.Net.Http - RequestStart : https,127.0.0.1,50019,/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6,2,0,1 ->
0.364s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34930376,NativeCallbackHandler,[conn][0x1E782D36F10] Connection received event STREAMS_AVAILABLE ->
0.364s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 6563976,0,0,GetHttp3ConnectionAsync,Using existing HTTP3 connection. ->
0.364s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,HandleEvent,(null) Stream received event START_COMPLETE ->
0.364s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,.ctor,[strm][0x1E782EE5F90] Outbound bidirectional stream created in connection [conn][0x1E782D36F10]. ->
0.364s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.364s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,ReadAsync,[strm][0x1E782EE5F90] Stream reading into Memory of '64' bytes. ->
0.364s Grpc.Net.Client.Internal.RetryCall - Trace: Sending 8 buffered messages from previous failed gRPC calls.
0.364s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.364s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.364s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.364s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.364s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.364s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.364s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.364s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.364s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.364s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.364s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.364s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.364s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.364s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.364s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.364s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.365s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.365s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.365s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.365s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.365s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.365s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.365s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.365s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.367s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2256335,NativeCallbackHandler,[conn][0x1E782E9D0A0] Connection received event PEER_STREAM_STARTED ->
0.367s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#5423467,.ctor,[strm][0x1E782EB0750] Inbound bidirectional stream created in connection [conn][0x1E782E9D0A0]. ->
0.367s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#5423467,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.368s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#5423467,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.368s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#5423467,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.368s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPI:00000008" type Bidirectional accepted.
0.368s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received HEADERS frame for stream ID 8 with length 290.
0.368s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 8 with length 8.
0.368s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 8 with length 8.
0.368s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 8 with length 8.
0.368s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 8 with length 8.
0.368s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 8 with length 8.
0.368s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 8 with length 8.
0.368s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 8 with length 8.
0.368s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 8 with length 8.
0.368s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request starting HTTP/3 POST https://127.0.0.1:50019/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6 application/grpc -
0.368s SERVER Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware - Debug: Request matched endpoint 'gRPC - /DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'
0.368s SERVER Microsoft.AspNetCore.Routing.EndpointMiddleware - Information: Executing endpoint 'gRPC - /DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.368s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB1Q46LVNPI", Request id "0HMB1Q46LVNPI:00000008": started reading request body.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.368s GrpcTestContext - Information: Server received 0.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.368s GrpcTestContext - Information: Server received 1.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.368s GrpcTestContext - Information: Server received 2.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.368s GrpcTestContext - Information: Server received 3.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.368s GrpcTestContext - Information: Server received 4.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.368s GrpcTestContext - Information: Server received 5.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.368s GrpcTestContext - Information: Server received 6.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.368s GrpcTestContext - Information: Server received 7.
0.368s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.372s GrpcTestContext - Information: Client writing message 8.
0.372s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.373s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 72 bytes buffered for this call.
0.373s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.373s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.373s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.373s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#5423467,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.373s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#5423467,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.373s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 8 with length 8.
0.374s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.374s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.374s GrpcTestContext - Information: Server failing at 8.
0.374s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Information: Error status code 'Unavailable' raised.
Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="")
at Grpc.AspNetCore.FunctionalTests.Client.RetryTests.<>c__DisplayClass0_0.<<ClientStreaming_MultipleWritesAndRetries_Failure>g__ClientStreamingWithReadFailures|0>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\FunctionalTests\Client\RetryTests.cs:line 53
--- End of stack trace from previous location ---
at Grpc.AspNetCore.FunctionalTests.Client.RetryTests.<>c__DisplayClass0_0.<<ClientStreaming_MultipleWritesAndRetries_Failure>g__ClientStreamingWithReadFailures|0>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\FunctionalTests\Client\RetryTests.cs:line 47
--- End of stack trace from previous location ---
at Grpc.Shared.Server.ClientStreamingServerMethodInvoker`3.Invoke(HttpContext httpContext, ServerCallContext serverCallContext, IAsyncStreamReader`1 requestStream) in C:\Development\Source\grpc-dotnet\src\Shared\Server\ClientStreamingServerMethodInvoker.cs:line 100
at Grpc.Shared.Server.ClientStreamingServerMethodInvoker`3.Invoke(HttpContext httpContext, ServerCallContext serverCallContext, IAsyncStreamReader`1 requestStream) in C:\Development\Source\grpc-dotnet\src\Shared\Server\ClientStreamingServerMethodInvoker.cs:line 111
at Grpc.AspNetCore.Server.Internal.CallHandlers.ClientStreamingServerCallHandler`3.HandleCallAsyncCore(HttpContext httpContext, HttpContextServerCallContext serverCallContext) in C:\Development\Source\grpc-dotnet\src\Grpc.AspNetCore.Server\Internal\CallHandlers\ClientStreamingServerCallHandler.cs:line 52
at Grpc.AspNetCore.Server.Internal.CallHandlers.ServerCallHandlerBase`3.<HandleCallAsync>g__AwaitHandleCall|8_0(HttpContextServerCallContext serverCallContext, Method`2 method, Task handleCall) in C:\Development\Source\grpc-dotnet\src\Grpc.AspNetCore.Server\Internal\CallHandlers\ServerCallHandlerBase.cs:line 95
0.375s SERVER Microsoft.AspNetCore.Routing.EndpointMiddleware - Information: Executed endpoint 'gRPC - /DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'
0.377s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" sending HEADERS frame for stream ID 8 with length 149.
0.377s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request finished HTTP/3 POST https://127.0.0.1:50019/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6 application/grpc - - 200 0 application/grpc 8.8435ms
0.377s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB1Q46LVNPI", Request id "0HMB1Q46LVNPI:00000008": done reading request body.
0.377s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#5423467,HandleEvent,[strm][0x1E782EB0750] Stream received event SEND_COMPLETE ->
0.377s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPI:00000008" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
0.377s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,HandleEvent,[strm][0x1E782EE5F90] Stream received event RECEIVE ->
0.377s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,HandleEvent,[strm][0x1E782EE5F90] Stream received event RECEIVE ->
0.377s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 6563976,27207609,8,ReadFrameEnvelopeAsync,Received frame 1 of length 149. ->
0.377s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#27053925,RequestMessage,HttpResponseMessage#27053925,HttpRequestMessage#13804354 ->
0.377s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionResponseContent#17882254,.ctor, ->
0.377s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#27053925,Content,HttpResponseMessage#27053925,HttpConnectionResponseContent#17882254 ->
0.377s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,ReadAsync,[strm][0x1E782EE5F90] Stream reading into Memory of '64' bytes. ->
0.377s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,ReadAsync,[strm][0x1E782EE5F90] Stream reading into Memory of '64' bytes. ->
0.377s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,HandleEvent,[strm][0x1E782EE5F90] Stream received event RECEIVE ->
0.377s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,HandleEvent,[strm][0x1E782EE5F90] Stream received event PEER_SEND_SHUTDOWN ->
0.377s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,HandleEventPeerSendShutdown,[strm][0x1E782EE5F90] Stream completing resettable event source. ->
0.377s SystemNetEventSourceListener - Debug: <- Event System.Net.Http - RequestStop : ->
0.377s Grpc.Net.Client.Internal.GrpcCall - Trace: Response headers received.
0.377s Grpc.Net.Client.Internal.GrpcCall - Information: Call failed with gRPC error status. Status code: 'Unavailable', Message: '(null)'.
0.377s Grpc.Net.Client.Internal.GrpcCall - Debug: Finished gRPC call.
0.377s Grpc.Net.Client.Internal.RetryCall - Debug: Evaluated retry for failed gRPC call. Status code: 'Unavailable', Attempt: 4, Retry: True
0.377s Grpc.Net.Client.Internal.RetryCall - Trace: Starting retry delay of 00:00:00.
0.377s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,Dispose,[strm][0x1E782EE5F90] Stream disposing True ->
0.377s Grpc.Net.Client.Internal.RetryCall - Debug: Starting attempt 5.
0.377s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,Dispose,[strm][0x1E782EE5F90] Stream disposed ->
0.377s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : PushStreamContent`2#8998912,.ctor, ->
0.377s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpRequestMessage#7180297,Content,HttpRequestMessage#7180297,PushStreamContent`2#8998912 ->
0.377s Grpc.Net.Client.Internal.GrpcCall - Debug: Starting gRPC call. Method type: 'ClientStreaming', URI: 'https://127.0.0.1:50019/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'.
0.377s SystemNetEventSourceListener - Debug: <- Event System.Net.Http - RequestStart : https,127.0.0.1,50019,/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6,2,0,1 ->
0.377s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 6563976,0,0,GetHttp3ConnectionAsync,Using existing HTTP3 connection. ->
0.377s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#5423467,HandleEvent,[strm][0x1E782EB0750] Stream received event SEND_SHUTDOWN_COMPLETE ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#5423467,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#5423467,HandleEvent,[strm][0x1E782EB0750] Stream received event PEER_SEND_SHUTDOWN ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#5423467,HandleEventPeerSendShutdown,[strm][0x1E782EB0750] Stream completing resettable event source. ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#5423467,HandleEvent,[strm][0x1E782EB0750] Stream received event SHUTDOWN_COMPLETE ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#5423467,HandleEventShutdownComplete,[strm][0x1E782EB0750] Stream completing resettable event source. ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,(null) Stream received event START_COMPLETE ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,.ctor,[strm][0x1E782D3BFF0] Outbound bidirectional stream created in connection [conn][0x1E782D36F10]. ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_SHUTDOWN_COMPLETE ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,HandleEvent,[strm][0x1E782EE5F90] Stream received event SHUTDOWN_COMPLETE ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,HandleEventShutdownComplete,[strm][0x1E782EE5F90] Stream completing resettable event source. ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,ReadAsync,[strm][0x1E782D3BFF0] Stream reading into Memory of '64' bytes. ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#57720030,Cleanup,[strm][0x1E782EE5F90] releasing handles. ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34930376,NativeCallbackHandler,[conn][0x1E782D36F10] Connection received event STREAMS_AVAILABLE ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SEND_COMPLETE ->
0.378s Grpc.Net.Client.Internal.RetryCall - Trace: Sending 9 buffered messages from previous failed gRPC calls.
0.378s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SEND_COMPLETE ->
0.378s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.378s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2256335,NativeCallbackHandler,[conn][0x1E782E9D0A0] Connection received event PEER_STREAM_STARTED ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SEND_COMPLETE ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,.ctor,[strm][0x1E782D3D2D0] Inbound bidirectional stream created in connection [conn][0x1E782E9D0A0]. ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event RECEIVE ->
0.378s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.378s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SEND_COMPLETE ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,ReadAsync,[strm][0x1E782D3D2D0] Stream reading into Memory of '4096' bytes. ->
0.378s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.378s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,ReadAsync,[strm][0x1E782D3D2D0] Stream reading into Memory of '4096' bytes. ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event RECEIVE ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SEND_COMPLETE ->
0.378s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.378s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.378s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPI:0000000C" type Bidirectional accepted.
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event RECEIVE ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,ReadAsync,[strm][0x1E782D3D2D0] Stream reading into Memory of '4096' bytes. ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SEND_COMPLETE ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,ReadAsync,[strm][0x1E782D3D2D0] Stream reading into Memory of '4096' bytes. ->
0.378s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.378s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SEND_COMPLETE ->
0.378s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received HEADERS frame for stream ID 12 with length 290.
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event RECEIVE ->
0.378s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.378s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.378s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 12 with length 8.
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,ReadAsync,[strm][0x1E782D3D2D0] Stream reading into Memory of '4096' bytes. ->
0.378s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 12 with length 8.
0.378s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 12 with length 8.
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SEND_COMPLETE ->
0.378s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 12 with length 8.
0.378s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 12 with length 8.
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event RECEIVE ->
0.378s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event IDEAL_SEND_BUFFER_SIZE ->
0.378s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.378s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request starting HTTP/3 POST https://127.0.0.1:50019/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6 application/grpc -
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,ReadAsync,[strm][0x1E782D3D2D0] Stream reading into Memory of '4096' bytes. ->
0.378s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 12 with length 8.
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SEND_COMPLETE ->
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event RECEIVE ->
0.378s SERVER Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware - Debug: Request matched endpoint 'gRPC - /DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'
0.378s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.378s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.378s SERVER Microsoft.AspNetCore.Server.Kestrel - Information: Connection id "0HMB1Q46LVNPI", Request id "0HMB1Q46LVNPI:00000008": the application completed without reading the entire request body.
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,ReadAsync,[strm][0x1E782D3D2D0] Stream reading into Memory of '4096' bytes. ->
0.378s SERVER Microsoft.AspNetCore.Routing.EndpointMiddleware - Information: Executing endpoint 'gRPC - /DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'
0.378s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPI:00000008" read side aborted by application with error code 256 because: "The application completed without reading the entire request body.".
0.378s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SEND_COMPLETE ->
0.378s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 12 with length 8.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.379s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.379s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB1Q46LVNPI", Request id "0HMB1Q46LVNPI:0000000C": started reading request body.
0.379s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event RECEIVE ->
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.379s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#5423467,Dispose,[strm][0x1E782EB0750] Stream disposing True ->
0.379s GrpcTestContext - Information: Server received 0.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.379s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,ReadAsync,[strm][0x1E782D3D2D0] Stream reading into Memory of '4096' bytes. ->
0.379s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 12 with length 8.
0.379s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event RECEIVE ->
0.379s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#5423467,Cleanup,[strm][0x1E782EB0750] releasing handles. ->
0.379s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 12 with length 8.
0.379s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,ReadAsync,[strm][0x1E782D3D2D0] Stream reading into Memory of '4096' bytes. ->
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.379s GrpcTestContext - Information: Server received 1.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.379s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#5423467,Dispose,[strm][0x1E782EB0750] Stream disposed ->
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.379s GrpcTestContext - Information: Server received 2.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.379s GrpcTestContext - Information: Server received 3.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.379s GrpcTestContext - Information: Server received 4.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.379s GrpcTestContext - Information: Server received 5.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.379s GrpcTestContext - Information: Server received 6.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.379s GrpcTestContext - Information: Server received 7.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.379s GrpcTestContext - Information: Server received 8.
0.379s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.387s GrpcTestContext - Information: Client writing message 9.
0.388s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.388s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 80 bytes buffered for this call.
0.388s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.388s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SEND_COMPLETE ->
0.388s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.388s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event RECEIVE ->
0.388s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,ReadAsync,[strm][0x1E782D3D2D0] Stream reading into Memory of '4096' bytes. ->
0.388s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 12 with length 8.
0.388s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.388s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.389s GrpcTestContext - Information: Server received 9.
0.389s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.403s GrpcTestContext - Information: Client writing message 10.
0.404s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.404s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 88 bytes buffered for this call.
0.404s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.404s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SEND_COMPLETE ->
0.404s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.404s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event RECEIVE ->
0.404s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,ReadAsync,[strm][0x1E782D3D2D0] Stream reading into Memory of '4096' bytes. ->
0.404s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 12 with length 8.
0.404s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.404s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.404s GrpcTestContext - Information: Server received 10.
0.404s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.419s GrpcTestContext - Information: Client writing message 11.
0.420s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.420s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 96 bytes buffered for this call.
0.420s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.420s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SEND_COMPLETE ->
0.420s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.421s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event RECEIVE ->
0.421s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,ReadAsync,[strm][0x1E782D3D2D0] Stream reading into Memory of '4096' bytes. ->
0.421s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 12 with length 8.
0.421s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.421s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.421s GrpcTestContext - Information: Server received 11.
0.421s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.434s GrpcTestContext - Information: Client writing message 12.
0.435s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.435s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 104 bytes buffered for this call.
0.435s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.435s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SEND_COMPLETE ->
0.435s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.435s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event RECEIVE ->
0.435s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,ReadAsync,[strm][0x1E782D3D2D0] Stream reading into Memory of '4096' bytes. ->
0.435s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 12 with length 8.
0.435s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.435s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.435s GrpcTestContext - Information: Server received 12.
0.435s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.450s GrpcTestContext - Information: Client writing message 13.
0.451s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.451s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 112 bytes buffered for this call.
0.451s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.451s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SEND_COMPLETE ->
0.451s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.451s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event RECEIVE ->
0.451s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,ReadAsync,[strm][0x1E782D3D2D0] Stream reading into Memory of '4096' bytes. ->
0.451s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 12 with length 8.
0.451s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.451s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.451s GrpcTestContext - Information: Server received 13.
0.451s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.466s GrpcTestContext - Information: Client writing message 14.
0.467s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.467s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 120 bytes buffered for this call.
0.467s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.467s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SEND_COMPLETE ->
0.467s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.467s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event RECEIVE ->
0.467s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 12 with length 8.
0.467s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,ReadAsync,[strm][0x1E782D3D2D0] Stream reading into Memory of '4096' bytes. ->
0.467s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.467s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.467s GrpcTestContext - Information: Server received 14.
0.467s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.482s GrpcTestContext - Information: Client writing message 15.
0.482s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.482s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 128 bytes buffered for this call.
0.482s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.483s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SEND_COMPLETE ->
0.483s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.483s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event RECEIVE ->
0.483s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,ReadAsync,[strm][0x1E782D3D2D0] Stream reading into Memory of '4096' bytes. ->
0.483s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 12 with length 8.
0.483s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.483s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.483s GrpcTestContext - Information: Server received 15.
0.483s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.497s GrpcTestContext - Information: Client writing message 16.
0.497s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.497s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 136 bytes buffered for this call.
0.497s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.498s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SEND_COMPLETE ->
0.498s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.498s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event RECEIVE ->
0.498s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,ReadAsync,[strm][0x1E782D3D2D0] Stream reading into Memory of '4096' bytes. ->
0.498s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 12 with length 8.
0.498s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.498s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.498s GrpcTestContext - Information: Server failing at 16.
0.498s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Information: Error status code 'Unavailable' raised.
Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="")
at Grpc.AspNetCore.FunctionalTests.Client.RetryTests.<>c__DisplayClass0_0.<<ClientStreaming_MultipleWritesAndRetries_Failure>g__ClientStreamingWithReadFailures|0>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\FunctionalTests\Client\RetryTests.cs:line 53
--- End of stack trace from previous location ---
at Grpc.AspNetCore.FunctionalTests.Client.RetryTests.<>c__DisplayClass0_0.<<ClientStreaming_MultipleWritesAndRetries_Failure>g__ClientStreamingWithReadFailures|0>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\FunctionalTests\Client\RetryTests.cs:line 47
--- End of stack trace from previous location ---
at Grpc.Shared.Server.ClientStreamingServerMethodInvoker`3.Invoke(HttpContext httpContext, ServerCallContext serverCallContext, IAsyncStreamReader`1 requestStream) in C:\Development\Source\grpc-dotnet\src\Shared\Server\ClientStreamingServerMethodInvoker.cs:line 100
at Grpc.Shared.Server.ClientStreamingServerMethodInvoker`3.Invoke(HttpContext httpContext, ServerCallContext serverCallContext, IAsyncStreamReader`1 requestStream) in C:\Development\Source\grpc-dotnet\src\Shared\Server\ClientStreamingServerMethodInvoker.cs:line 111
at Grpc.AspNetCore.Server.Internal.CallHandlers.ClientStreamingServerCallHandler`3.HandleCallAsyncCore(HttpContext httpContext, HttpContextServerCallContext serverCallContext) in C:\Development\Source\grpc-dotnet\src\Grpc.AspNetCore.Server\Internal\CallHandlers\ClientStreamingServerCallHandler.cs:line 52
at Grpc.AspNetCore.Server.Internal.CallHandlers.ServerCallHandlerBase`3.<HandleCallAsync>g__AwaitHandleCall|8_0(HttpContextServerCallContext serverCallContext, Method`2 method, Task handleCall) in C:\Development\Source\grpc-dotnet\src\Grpc.AspNetCore.Server\Internal\CallHandlers\ServerCallHandlerBase.cs:line 95
0.499s SERVER Microsoft.AspNetCore.Routing.EndpointMiddleware - Information: Executed endpoint 'gRPC - /DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'
0.499s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" sending HEADERS frame for stream ID 12 with length 149.
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event SEND_COMPLETE ->
0.499s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request finished HTTP/3 POST https://127.0.0.1:50019/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6 application/grpc - - 200 0 application/grpc 120.4801ms
0.499s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB1Q46LVNPI", Request id "0HMB1Q46LVNPI:0000000C": done reading request body.
0.499s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPI:0000000C" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
0.499s SERVER Microsoft.AspNetCore.Server.Kestrel - Information: Connection id "0HMB1Q46LVNPI", Request id "0HMB1Q46LVNPI:0000000C": the application completed without reading the entire request body.
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event RECEIVE ->
0.499s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPI:0000000C" read side aborted by application with error code 256 because: "The application completed without reading the entire request body.".
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event RECEIVE ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 6563976,27207609,12,ReadFrameEnvelopeAsync,Received frame 1 of length 149. ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#19062057,RequestMessage,HttpResponseMessage#19062057,HttpRequestMessage#7180297 ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionResponseContent#24807524,.ctor, ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#19062057,Content,HttpResponseMessage#19062057,HttpConnectionResponseContent#24807524 ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,ReadAsync,[strm][0x1E782D3BFF0] Stream reading into Memory of '64' bytes. ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event SEND_SHUTDOWN_COMPLETE ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,ReadAsync,[strm][0x1E782D3BFF0] Stream reading into Memory of '64' bytes. ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event IDEAL_SEND_BUFFER_SIZE ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event RECEIVE ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event PEER_SEND_SHUTDOWN ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEventPeerSendShutdown,[strm][0x1E782D3BFF0] Stream completing resettable event source. ->
0.499s SystemNetEventSourceListener - Debug: <- Event System.Net.Http - RequestStop : ->
0.499s Grpc.Net.Client.Internal.GrpcCall - Trace: Response headers received.
0.499s Grpc.Net.Client.Internal.GrpcCall - Information: Call failed with gRPC error status. Status code: 'Unavailable', Message: '(null)'.
0.499s Grpc.Net.Client.Internal.GrpcCall - Debug: Finished gRPC call.
0.499s Grpc.Net.Client.Internal.RetryCall - Debug: Evaluated retry for failed gRPC call. Status code: 'Unavailable', Attempt: 5, Retry: True
0.499s Grpc.Net.Client.Internal.RetryCall - Trace: Starting retry delay of 00:00:00.
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,Dispose,[strm][0x1E782D3BFF0] Stream disposing True ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,Dispose,[strm][0x1E782D3BFF0] Stream disposed ->
0.499s Grpc.Net.Client.Internal.RetryCall - Debug: Starting attempt 6.
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : PushStreamContent`2#53553410,.ctor, ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpRequestMessage#24624665,Content,HttpRequestMessage#24624665,PushStreamContent`2#53553410 ->
0.499s Grpc.Net.Client.Internal.GrpcCall - Debug: Starting gRPC call. Method type: 'ClientStreaming', URI: 'https://127.0.0.1:50019/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'.
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event RECEIVE ->
0.499s SystemNetEventSourceListener - Debug: <- Event System.Net.Http - RequestStart : https,127.0.0.1,50019,/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6,2,0,1 ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event PEER_SEND_SHUTDOWN ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEventPeerSendShutdown,[strm][0x1E782D3D2D0] Stream completing resettable event source. ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEvent,[strm][0x1E782D3D2D0] Stream received event SHUTDOWN_COMPLETE ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 6563976,0,0,GetHttp3ConnectionAsync,Using existing HTTP3 connection. ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,HandleEventShutdownComplete,[strm][0x1E782D3D2D0] Stream completing resettable event source. ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,(null) Stream received event START_COMPLETE ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SEND_SHUTDOWN_COMPLETE ->
0.499s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x1E782D3BFF0] Stream received event SHUTDOWN_COMPLETE ->
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEventShutdownComplete,[strm][0x1E782D3BFF0] Stream completing resettable event source. ->
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,.ctor,[strm][0x1E782EE5F90] Outbound bidirectional stream created in connection [conn][0x1E782D36F10]. ->
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,Cleanup,[strm][0x1E782D3BFF0] releasing handles. ->
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#34930376,NativeCallbackHandler,[conn][0x1E782D36F10] Connection received event STREAMS_AVAILABLE ->
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,ReadAsync,[strm][0x1E782EE5F90] Stream reading into Memory of '64' bytes. ->
0.500s Grpc.Net.Client.Internal.RetryCall - Trace: Sending 17 buffered messages from previous failed gRPC calls.
0.500s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2256335,NativeCallbackHandler,[conn][0x1E782E9D0A0] Connection received event PEER_STREAM_STARTED ->
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,.ctor,[strm][0x1E782EB0750] Inbound bidirectional stream created in connection [conn][0x1E782E9D0A0]. ->
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.500s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.500s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.500s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q46LVNPI:00000010" type Bidirectional accepted.
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.500s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.500s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.500s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received HEADERS frame for stream ID 16 with length 290.
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.500s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.500s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.500s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request starting HTTP/3 POST https://127.0.0.1:50019/DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6 application/grpc -
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.500s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.500s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.500s SERVER Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware - Debug: Request matched endpoint 'gRPC - /DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'
0.500s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.500s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.500s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.500s SERVER Microsoft.AspNetCore.Routing.EndpointMiddleware - Information: Executing endpoint 'gRPC - /DynamicService/d74b4053-eb67-4e47-8f28-512d6f1a8ae6'
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.500s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.500s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.500s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event IDEAL_SEND_BUFFER_SIZE ->
0.500s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.500s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB1Q46LVNPI", Request id "0HMB1Q46LVNPI:00000010": started reading request body.
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.500s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.506s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.506s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.506s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.506s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.506s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.506s GrpcTestContext - Information: Server received 0.
0.506s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.506s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.506s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.506s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.506s GrpcTestContext - Information: Server received 1.
0.506s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.506s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,Dispose,[strm][0x1E782E25F00] Stream disposing False ->
0.506s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.506s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.506s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.506s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,Cleanup,[strm][0x1E782E25F00] releasing handles. ->
0.506s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.506s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.506s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.506s GrpcTestContext - Information: Server received 2.
0.506s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.506s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54752321,Dispose,[strm][0x1E782E25F00] Stream disposed ->
0.506s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.506s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.506s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.506s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.506s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.506s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,Dispose,[strm][0x1E782E02200] Stream disposing False ->
0.506s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.506s GrpcTestContext - Information: Server received 3.
0.506s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,Cleanup,[strm][0x1E782E02200] releasing handles. ->
0.506s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.506s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.506s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.506s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24388906,RemoveStream,[conn][0x1E782D99020] releasing handle after last stream. ->
0.506s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.506s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.506s GrpcTestContext - Information: Server received 4.
0.506s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.506s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.506s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.506s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.506s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.507s GrpcTestContext - Information: Server received 5.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#65532796,Dispose,[strm][0x1E782E02200] Stream disposed ->
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.507s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.507s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.507s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.507s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.507s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.507s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.507s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.507s GrpcTestContext - Information: Server received 6.
0.507s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.507s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.507s GrpcTestContext - Information: Server received 7.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.507s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.507s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.507s GrpcTestContext - Information: Server received 8.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.507s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.507s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.507s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.507s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.507s GrpcTestContext - Information: Server received 9.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.507s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.507s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.507s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.507s GrpcTestContext - Information: Server received 10.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.507s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.507s GrpcTestContext - Information: Server received 11.
0.507s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.507s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.507s GrpcTestContext - Information: Server received 12.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.507s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.507s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.507s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.507s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.507s GrpcTestContext - Information: Server received 13.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.507s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.507s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.507s GrpcTestContext - Information: Server received 14.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.507s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.507s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.507s GrpcTestContext - Information: Server received 15.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.507s GrpcTestContext - Information: Server received 16.
0.507s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.510s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,Dispose,[strm][0x1E782D3D2D0] Stream disposing True ->
0.510s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,Cleanup,[strm][0x1E782D3D2D0] releasing handles. ->
0.510s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#54287094,Dispose,[strm][0x1E782D3D2D0] Stream disposed ->
0.512s GrpcTestContext - Information: Client writing message 17.
0.512s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.512s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 144 bytes buffered for this call.
0.512s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.513s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.513s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.513s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.513s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.513s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.513s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.513s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.513s GrpcTestContext - Information: Server received 17.
0.513s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.528s GrpcTestContext - Information: Client writing message 18.
0.528s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.529s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 152 bytes buffered for this call.
0.529s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.529s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.529s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.529s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.529s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.529s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.529s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.529s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.529s GrpcTestContext - Information: Server received 18.
0.529s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.545s GrpcTestContext - Information: Client writing message 19.
0.545s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 3 byte message.
0.545s Grpc.Net.Client.Internal.RetryCall - Trace: Message with 8 bytes added to the buffer. There are 160 bytes buffered for this call.
0.545s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
0.545s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_COMPLETE ->
0.545s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
0.545s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.545s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,ReadAsync,[strm][0x1E782EB0750] Stream reading into Memory of '4096' bytes. ->
0.545s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q46LVNPI" received DATA frame for stream ID 16 with length 8.
0.545s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 3 byte message to 'Streaming.DataMessage'.
0.545s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
0.545s GrpcTestContext - Information: Server received 19.
0.545s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
0.560s GrpcTestContext - Information: Client completing request stream.
0.562s Grpc.Net.Client.Internal.HttpContentClientStreamWriter - Debug: Completing client stream.
0.563s GrpcTestContext - Information: Client waiting for response.
0.563s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.563s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event PEER_SEND_SHUTDOWN ->
0.563s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEventPeerSendShutdown,[strm][0x1E782EB0750] Stream completing resettable event source. ->
0.563s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_SHUTDOWN_COMPLETE ->
5.586s GrpcTestContext - Information: Finishing RetryTests.ClientStreaming_MultipleWritesAndRetries_Failure
At the end the logs have the client request stream being completed, and then timing out while waiting for the response:
0.560s GrpcTestContext - Information: Client completing request stream.
0.562s Grpc.Net.Client.Internal.HttpContentClientStreamWriter - Debug: Completing client stream.
0.563s GrpcTestContext - Information: Client waiting for response.
0.563s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event RECEIVE ->
0.563s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEvent,[strm][0x1E782EB0750] Stream received event PEER_SEND_SHUTDOWN ->
0.563s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#11713312,HandleEventPeerSendShutdown,[strm][0x1E782EB0750] Stream completing resettable event source. ->
0.563s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#37531193,HandleEvent,[strm][0x1E782EE5F90] Stream received event SEND_SHUTDOWN_COMPLETE ->
5.586s GrpcTestContext - Information: Finishing RetryTests.ClientStreaming_MultipleWritesAndRetries_Failure
Success logs:
This is the end of log output when the test succeeds (so the server receives a notification that the request stream is finished).
0.673s GrpcTestContext - Information: Client completing request stream.
0.675s Grpc.Net.Client.Internal.HttpContentClientStreamWriter - Debug: Completing client stream.
0.675s GrpcTestContext - Information: Client waiting for response.
0.676s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x281706988C0] Stream received event RECEIVE ->
0.676s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x281706988C0] Stream received event PEER_SEND_SHUTDOWN ->
0.676s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEventPeerSendShutdown,[strm][0x281706988C0] Stream completing resettable event source. ->
0.676s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMB1Q5IH4JDD", Request id "0HMB1Q5IH4JDD:00000010": done reading request body.
0.676s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43285446,HandleEvent,[strm][0x281706985F0] Stream received event SEND_SHUTDOWN_COMPLETE ->
0.676s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: No message returned.
0.676s GrpcTestContext - Information: Server returning response.
0.679s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q5IH4JDD" sending HEADERS frame for stream ID 16 with length 115.
0.679s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Sending message.
0.680s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Serialized 'Streaming.DataMessage' to 22 byte message.
0.681s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Message sent.
0.682s SERVER Microsoft.AspNetCore.Routing.EndpointMiddleware - Information: Executed endpoint 'gRPC - /DynamicService/b02dc0f4-b85c-48a1-afd7-4c8238a4ca27'
0.682s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q5IH4JDD" sending DATA frame for stream ID 16 with length 27.
0.682s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x281706988C0] Stream received event SEND_COMPLETE ->
0.682s SERVER Microsoft.AspNetCore.Server.Kestrel.Http3 - Trace: Connection id "0HMB1Q5IH4JDD" sending HEADERS frame for stream ID 16 with length 17.
0.682s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request finished HTTP/3 POST https://127.0.0.1:50019/DynamicService/b02dc0f4-b85c-48a1-afd7-4c8238a4ca27 application/grpc - - 200 - application/grpc 76.6524ms
0.683s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43285446,HandleEvent,[strm][0x281706985F0] Stream received event RECEIVE ->
0.683s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43285446,HandleEvent,[strm][0x281706985F0] Stream received event RECEIVE ->
0.683s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 6563976,7877106,16,ReadFrameEnvelopeAsync,Received frame 1 of length 115. ->
0.683s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x281706988C0] Stream received event SEND_COMPLETE ->
0.683s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#38190077,RequestMessage,HttpResponseMessage#38190077,HttpRequestMessage#7625314 ->
0.683s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionResponseContent#46115443,.ctor, ->
0.683s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#38190077,Content,HttpResponseMessage#38190077,HttpConnectionResponseContent#46115443 ->
0.683s SERVER Microsoft.AspNetCore.Server.Kestrel.Transport.Quic - Debug: Stream id "0HMB1Q5IH4JDD:00000010" shutting down writes because: "The QUIC transport's send loop completed gracefully.".
0.683s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43285446,ReadAsync,[strm][0x281706985F0] Stream reading into Memory of '64' bytes. ->
0.683s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43285446,HandleEvent,[strm][0x281706985F0] Stream received event RECEIVE ->
0.683s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,Dispose,[strm][0x281706988C0] Stream disposing True ->
0.683s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,Dispose,[strm][0x281706988C0] Stream disposed ->
0.683s SystemNetEventSourceListener - Debug: <- Event System.Net.Http - RequestStop : ->
0.683s Grpc.Net.Client.Internal.GrpcCall - Trace: Response headers received.
0.683s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x281706988C0] Stream received event SEND_SHUTDOWN_COMPLETE ->
0.683s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEvent,[strm][0x281706988C0] Stream received event SHUTDOWN_COMPLETE ->
0.683s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,HandleEventShutdownComplete,[strm][0x281706988C0] Stream completing resettable event source. ->
0.683s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#12803693,Cleanup,[strm][0x281706988C0] releasing handles. ->
0.683s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#55353446,NativeCallbackHandler,[conn][0x281707D8220] Connection received event STREAMS_AVAILABLE ->
0.688s Grpc.Net.Client.Internal.RetryCall - Debug: Call commited. Reason: ResponseHeadersReceived
0.690s Grpc.Net.Client.Internal.GrpcCall - Debug: Reading message.
0.691s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 6563976,7877106,16,ReadFrameEnvelopeAsync,Received frame 0 of length 27. ->
0.693s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43285446,ReadAsync,[strm][0x281706985F0] Stream reading into Memory of '19' bytes. ->
0.693s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43285446,HandleEvent,[strm][0x281706985F0] Stream received event RECEIVE ->
0.694s Grpc.Net.Client.Internal.GrpcCall - Trace: Deserializing 22 byte message to 'Streaming.DataMessage'.
0.694s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43285446,ReadAsync,[strm][0x281706985F0] Stream reading into Memory of '64' bytes. ->
0.694s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 6563976,7877106,16,ReadFrameEnvelopeAsync,Received frame 1 of length 17. ->
0.694s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43285446,HandleEvent,[strm][0x281706985F0] Stream received event PEER_SEND_SHUTDOWN ->
0.694s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43285446,HandleEventPeerSendShutdown,[strm][0x281706985F0] Stream completing resettable event source. ->
0.694s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43285446,HandleEvent,[strm][0x281706985F0] Stream received event SHUTDOWN_COMPLETE ->
0.694s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43285446,HandleEventShutdownComplete,[strm][0x281706985F0] Stream completing resettable event source. ->
0.696s Grpc.Net.Client.Internal.GrpcCall - Trace: Received message.
0.697s Grpc.Net.Client.Internal.RetryCall - Trace: Stopping retry worker.
0.697s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43285446,Dispose,[strm][0x281706985F0] Stream disposing True ->
0.697s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43285446,Cleanup,[strm][0x281706985F0] releasing handles. ->
0.697s SystemNetEventSourceListener - Debug: <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43285446,Dispose,[strm][0x281706985F0] Stream disposed ->
0.697s Grpc.Net.Client.Internal.GrpcCall - Debug: Finished gRPC call.
0.700s GrpcTestContext - Information: Finishing RetryTests.ClientStreaming_MultipleWritesAndRetries_Failure
SDK:
.NET SDK (reflecting any global.json):
Version: 6.0.100-rc.1.21417.11
Commit: ca60baef37
I'm pretty sure this SDK predates the ReadsCompleted property being added. Kestrel certainly isn't using it yet.