runtime: [HTTP/2] RTT pings shutting down connection in gRPC CI - regression in .NET 6

Description

gRPC has a set of interop tests that test various scenarios. These are run as part of a CI process. Upgrading the .NET client from .NET 5 to .NET 6 resulted in some of the tests failing 50% of the time.

Most tests continue to pass. The four that fail are:

  • large_unary
  • jwt_token_creds
  • server_streaming
  • compute_engine_creds

Reproduction Steps

I attempted to reproduce this from my local machine by calling the remote server using the failing tests, but I couldn’t get them to fail.

These tests are failing in most CI builds here - https://source.cloud.google.com/results/invocations/f72f83db-c93b-467e-94cb-6b4ff7aeb286/targets;collapsed=/github%2Fgrpc%2Finterop_test/tests;group=tests;test=cloud_to_prod:aspnetcore:default:server_streaming:tls;row=2

Expected behavior

Expect tests to continue passing after upgrading to .NET 6

Actual behavior

Tests often fail.

Error detail (consistent across the 4 failing tests):

IOException: The request was aborted. IOException: The response ended prematurely while waiting for the next frame from the server.", DebugException="System.IO.IOException: The request was aborted.
 ---> System.IO.IOException: The response ended prematurely while waiting for the next frame from the server.
   at System.Net.Http.Http2Connection.<ReadFrameAsync>g__ThrowMissingFrame|57_1()
   at System.Net.Http.Http2Connection.ReadFrameAsync(Boolean initialFrame)
   at System.Net.Http.Http2Connection.ProcessIncomingFramesAsync()
   --- End of inner exception stack trace ---
   at System.Net.Http.Http2Connection.ThrowRequestAborted(Exception innerException)
   at System.Net.Http.Http2Connection.Http2Stream.CheckResponseBodyState()
   at System.Net.Http.Http2Connection.Http2Stream.TryReadFromBuffer(Span`1 buffer, Boolean partOfSyncRead)
   at System.Net.Http.Http2Connection.Http2Stream.ReadDataAsync(Memory`1 buffer, HttpResponseMessage responseMessage, CancellationToken cancellationToken)
   at Grpc.Net.Client.StreamExtensions.ReadMessageContent(Stream responseStream, Memory`1 messageData, Int32 length, CancellationToken cancellationToken) in /var/local/git/grpc-dotnet/src/Grpc.Net.Client/Internal/StreamExtensions.cs:line 224

Complete logging from test failure (including from HTTP event source):

Runtime: 6.0.0-rtm.21522.10+4822e3c3aa77eb82b2fb33c9321f923cf11ddde6
Use TLS: True
Use WinHttp: False
Use HTTP/3: False
Use GrpcWebMode:
Use Test CA: False
Client type: httpclient
Server host: grpc-test.sandbox.googleapis.com
Server port: 443
dbug: HttpEventSourceListener[0]
      Starting HttpEventSourceListener.
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpClientHandler#17324607,.ctor, ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Http - Info : SocketsHttpHandler#21703739,.ctor, ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Http - Info : BalancerHttpHandler#51442863,.ctor, ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Http - Associate : BalancerHttpHandler#51442863,InnerHandler,BalancerHttpHandler#51442863,HttpClientHandler#17324607 ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpMessageInvoker#60332585,.ctor,HttpMessageInvoker#60332585,BalancerHttpHandler#51442863 ->
info: Grpc.Shared.TestAssets.InteropClient[0]
      Running large_unary
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Http - Info : PushUnaryContent`2#37689768,.ctor, ->
dbug: HttpEventSourceListener[0]
      <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpRequestMessage#11898202,Content,HttpRequestMessage#11898202,PushUnaryContent`2#37689768 ->
dbug: Grpc.Net.Client.Internal.GrpcCall[1]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Starting gRPC call. Method type: 'Unary', URI: 'https://grpc-test.sandbox.googleapis.com/grpc.testing.TestService/UnaryCall'.
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event System.Net.Http - RequestStart : https,grpc-test.sandbox.googleapis.com,443,/grpc.testing.TestService/UnaryCall,2,0,1 ->
trce: Grpc.Net.Client.Balancer.Resolver[4]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Resolver result with status code 'OK' and 1 addresses.
dbug: Grpc.Net.Client.Balancer.Subchannel[1]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Subchannel id '1' created with addresses: grpc-test.sandbox.googleapis.com:443
dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[4]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Channel picker updated.
trce: Grpc.Net.Client.Balancer.Subchannel[4]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Subchannel id '1' connection requested.
dbug: Grpc.Net.Client.Balancer.Subchannel[11]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Subchannel id '1' state changed to Connecting. Detail: 'Connection requested.'.
trce: Grpc.Net.Client.Balancer.PickFirstBalancer[1]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Processing subchannel id '1' state changed to Connecting. Detail: 'Connection requested.'.
dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[3]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Channel state updated to Connecting.
trce: Grpc.Net.Client.Balancer.Subchannel[6]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Subchannel id '1' connecting to transport.
dbug: Grpc.Net.Client.Balancer.Subchannel[11]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Subchannel id '1' state changed to Ready. Detail: 'Passively connected.'.
trce: Grpc.Net.Client.Balancer.PickFirstBalancer[1]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Processing subchannel id '1' state changed to Ready. Detail: 'Passively connected.'.
dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[3]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Channel state updated to Ready.
dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[4]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Channel picker updated.
trce: Grpc.Net.Client.Balancer.Resolver[1]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Resolver refresh requested.
trce: Grpc.Net.Client.Balancer.Internal.ConnectionManager[5]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Pick started.
dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[6]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Successfully picked subchannel id '1' with address grpc-test.sandbox.googleapis.com:443.
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionHandler#16745860,.ctor, ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - Info : DiagnosticsHandler#16495015,.ctor, ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - Info : RedirectHandler#14237410,.ctor, ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,0,0,.ctor,HttpConnectionPool https://grpc-test.sandbox.googleapis.com:443 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,0,0,GetHttp2ConnectionAsync,No available HTTP/2 connections; request queued. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,0,0,AddHttp2ConnectionAsync,Creating new HTTP/2 connection for pool. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,.ctor,_connectionWindow. initialCredit=65535 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event System.Net.Http - ConnectionEstablished : 2,0 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,TraceConnection,Http2Connection(HttpConnectionPool https://grpc-test.sandbox.googleapis.com:443). SslProtocol:Tls12, NegotiatedApplicationProtocol:h2, NegotiatedCipherSuite:TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, CipherAlgorithm:Aes128, CipherStrength:128, HashAlgorithm:None, HashStrength:0, KeyExchangeAlgorithm:DiffieHellman, KeyExchangeStrength:0, LocalCertificate:, RemoteCertificate:[Subject]
        CN=sandbox.google.com

      [Issuer]
        CN=GTS CA 1C3, O=Google Trust Services LLC, C=US

      [Serial Number]
        3389206B6531BCB90A00000001195361

      [Not Before]
        11/01/2021 02:57:44

      [Not After]
        01/24/2022 02:57:43

      [Thumbprint]
        2B171D3A18BBAE6F0378BDB886FC966D3CFA343A
       ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,SetupAsync,Initial connection-level WINDOW_UPDATE, windowUpdateAmount=67043329 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReadFrameAsync,initialFrame=True ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessIncomingFramesAsync,Frame 0: StreamId=0; Type=Settings; Flags=None; PayloadLength=18. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ChangeMaxConcurrentStreams,newValue=100, _streamsInUse=0, _availableStreamsWaiter?=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,SignalAvailableStreamsWaiter,result=True, _availableStreamsWaiter?=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ChangeInitialWindowSize,newSize=1048576 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReadFrameAsync,initialFrame=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessIncomingFramesAsync,Frame 1: StreamId=0; Type=WindowUpdate; Flags=None; PayloadLength=4. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessWindowUpdateFrame,StreamId=0; Type=WindowUpdate; Flags=None; PayloadLength=4. amount=983041 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,AdjustCredit,_connectionWindow. amount=983041, current=65535 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReadFrameAsync,initialFrame=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessIncomingFramesAsync,Frame 2: StreamId=0; Type=Settings; Flags=Ack; PayloadLength=0. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,RefreshRtt,[FlowControl] Updated MinRtt: 8.1517 ms ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=9 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,SendSettingsAckAsync,Started writing. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=9 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReturnHttp2Connection,isNewConnection=True ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReturnHttp2Connection,Dequeued waiting HTTP/2 request. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReturnHttp2Connection,Put HTTP/2 connection in pool. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event System.Net.Http - RequestLeftQueue : 277.7211,2,0 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,SendAsync,Method: POST, RequestUri: 'https://grpc-test.sandbox.googleapis.com/grpc.testing.TestService/UnaryCall', Version: 2.0, Content: Grpc.Net.Client.Internal.PushUnaryContent`2[Grpc.Testing.SimpleRequest,Grpc.Testing.SimpleResponse], Headers:
      {
        User-Agent: grpc-dotnet/2.42.0-dev (.NET 6.0.0-rtm.21522.10; CLR 6.0.0; net6.0; linux; x64)
        TE: trailers
        grpc-accept-encoding: identity,gzip
        Transfer-Encoding: chunked
        traceparent: 00-bb263d1a36b396fadbdf3366aa682351-064c1f7d2336c9e4-00
        Content-Type: application/grpc
      } ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event System.Net.Http - RequestHeadersStart :  ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,WriteHeaders, ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,WriteIndexedHeader,index=3 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,WriteIndexedHeader,index=7 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,WriteBytes,Length=34 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,WriteIndexedHeader,index=4, value=/grpc.testing.TestService/UnaryCall ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,WriteHeaderCollection, ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,WriteBytes,Length=2 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,WriteLiteralHeaderValues,values=grpc-dotnet/2.42.0-dev (.NET 6.0.0-rtm.21522.10; CLR 6.0.0; net6.0; linux; x64) ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,WriteBytes,Length=4 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,WriteLiteralHeaderValue,value=trailers ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,WriteLiteralHeader,name=grpc-accept-encoding, values=identity,gzip ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,WriteLiteralHeader,name=traceparent, values=00-bb263d1a36b396fadbdf3366aa682351-064c1f7d2336c9e4-00 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,WriteHeaderCollection, ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,WriteBytes,Length=2 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,WriteLiteralHeaderValues,values=application/grpc ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,.ctor,[FlowControl] InitialClientStreamWindowSize: 65535, StreamWindowThreshold: 8191, WindowScaleThresholdMultiplier: 1 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#45330878,RequestMessage,HttpResponseMessage#45330878,HttpRequestMessage#11898202 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - Info : HttpConnectionResponseContent#66629781,.ctor, ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - Associate : HttpResponseMessage#45330878,Content,HttpResponseMessage#45330878,HttpConnectionResponseContent#66629781 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=301 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,SendHeadersAsync,Started writing. Total header bytes=292 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,Initialize,Method: POST, RequestUri: 'https://grpc-test.sandbox.googleapis.com/grpc.testing.TestService/UnaryCall', Version: 2.0, Content: Grpc.Net.Client.Internal.PushUnaryContent`2[Grpc.Testing.SimpleRequest,Grpc.Testing.SimpleResponse], Headers:
      {
        User-Agent: grpc-dotnet/2.42.0-dev (.NET 6.0.0-rtm.21522.10; CLR 6.0.0; net6.0; linux; x64)
        TE: trailers
        grpc-accept-encoding: identity,gzip
        traceparent: 00-bb263d1a36b396fadbdf3366aa682351-064c1f7d2336c9e4-00
        Content-Type: application/grpc
      }, initialWindowSize=1048576 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendHeadersAsync,Wrote HEADERS frame. Length=292, flags=EndHeaders ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event System.Net.Http - RequestHeadersStop :  ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendRequestBodyAsync,Grpc.Net.Client.Internal.PushUnaryContent`2[Grpc.Testing.SimpleRequest,Grpc.Testing.SimpleResponse] ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event System.Net.Http - RequestContentStart :  ->
dbug: Grpc.Net.Client.Internal.GrpcCall[18]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Sending message.
trce: Grpc.Net.Client.Internal.GrpcCall[21]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Serialized 'Grpc.Testing.SimpleRequest' to 271840 byte message.
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,TryRequestCreditNoLock,_connectionWindow. requested=16384, current=1048576, granted=16384 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendStreamDataAsync,Started writing. Length=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,TryRequestCreditNoLock,_connectionWindow. requested=16384, current=1032192, granted=16384 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=16694 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendStreamDataAsync,Started writing. Length=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,TryRequestCreditNoLock,_connectionWindow. requested=16384, current=1015808, granted=16384 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendStreamDataAsync,Started writing. Length=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,TryRequestCreditNoLock,_connectionWindow. requested=16384, current=999424, granted=16384 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendStreamDataAsync,Started writing. Length=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,TryRequestCreditNoLock,_connectionWindow. requested=16384, current=983040, granted=16384 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendStreamDataAsync,Started writing. Length=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,TryRequestCreditNoLock,_connectionWindow. requested=16384, current=966656, granted=16384 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendStreamDataAsync,Started writing. Length=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,TryRequestCreditNoLock,_connectionWindow. requested=16384, current=950272, granted=16384 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendStreamDataAsync,Started writing. Length=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,TryRequestCreditNoLock,_connectionWindow. requested=16384, current=933888, granted=16384 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendStreamDataAsync,Started writing. Length=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,TryRequestCreditNoLock,_connectionWindow. requested=16384, current=917504, granted=16384 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendStreamDataAsync,Started writing. Length=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,TryRequestCreditNoLock,_connectionWindow. requested=16384, current=901120, granted=16384 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event System.Net.Http - ResponseHeadersStart :  ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendStreamDataAsync,Started writing. Length=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,TryRequestCreditNoLock,_connectionWindow. requested=16384, current=884736, granted=16384 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendStreamDataAsync,Started writing. Length=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,TryRequestCreditNoLock,_connectionWindow. requested=16384, current=868352, granted=16384 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendStreamDataAsync,Started writing. Length=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,TryRequestCreditNoLock,_connectionWindow. requested=16384, current=851968, granted=16384 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendStreamDataAsync,Started writing. Length=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,TryRequestCreditNoLock,_connectionWindow. requested=16384, current=835584, granted=16384 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendStreamDataAsync,Started writing. Length=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,TryRequestCreditNoLock,_connectionWindow. requested=16384, current=819200, granted=16384 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendStreamDataAsync,Started writing. Length=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,TryRequestCreditNoLock,_connectionWindow. requested=16384, current=802816, granted=16384 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendStreamDataAsync,Started writing. Length=16393 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,TryRequestCreditNoLock,_connectionWindow. requested=9701, current=786432, granted=9701 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=9710 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendStreamDataAsync,Started writing. Length=9710 ->
trce: Grpc.Net.Client.Internal.GrpcCall[19]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Message sent.
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event System.Net.Http - RequestContentStop : 271845 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendRequestBodyAsync,Finished sending request body. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=9 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendEndStreamAsync,Started writing. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=26112 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReadFrameAsync,initialFrame=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessIncomingFramesAsync,Frame 3: StreamId=0; Type=WindowUpdate; Flags=None; PayloadLength=4. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessWindowUpdateFrame,StreamId=0; Type=WindowUpdate; Flags=None; PayloadLength=4. amount=2158568 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,AdjustCredit,_connectionWindow. amount=2158568, current=776731 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReadFrameAsync,initialFrame=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessIncomingFramesAsync,Frame 4: StreamId=0; Type=Settings; Flags=None; PayloadLength=6. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ChangeInitialWindowSize,newSize=3108840 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=9 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,SendSettingsAckAsync,Started writing. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=9 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReadFrameAsync,initialFrame=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessIncomingFramesAsync,Frame 5: StreamId=1; Type=Headers; Flags=EndHeaders; PayloadLength=48. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessHeadersFrame,StreamId=1; Type=Headers; Flags=EndHeaders; PayloadLength=48 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,OnDataOrHeadersReceived,[FlowControl] Sending RTT PING with payload -1 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=17 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,SendPingAsync,Started writing. pingContent=-1 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=17 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,OnStatus,Status code is 200 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,OnHeader,Content-Disposition: attachment ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,OnHeader,Content-Type: application/grpc ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,OnHeader,Date: Tue, 30 Nov 2021 22:18:15 GMT ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReadFrameAsync,initialFrame=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessIncomingFramesAsync,Frame 6: StreamId=1; Type=Data; Flags=None; PayloadLength=7817. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ExtendWindow,amount=7817 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ExtendWindow,_pendingWindowUpdate 7817 < 8388608. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReadFrameAsync,initialFrame=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessIncomingFramesAsync,Frame 7: StreamId=1; Type=Data; Flags=None; PayloadLength=8192. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ExtendWindow,amount=8192 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ExtendWindow,_pendingWindowUpdate 16009 < 8388608. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReadFrameAsync,initialFrame=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessIncomingFramesAsync,Frame 8: StreamId=0; Type=Ping; Flags=Ack; PayloadLength=8. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessPingFrame,Received PING frame, content:-1 ack: True ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,RefreshRtt,[FlowControl] Updated MinRtt: 2.5505 ms ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event System.Net.Http - ResponseHeadersStop :  ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event System.Net.Http - RequestStop :  ->
trce: Grpc.Net.Client.Internal.GrpcCall[2]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Response headers received.
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReadFrameAsync,initialFrame=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessIncomingFramesAsync,Frame 9: StreamId=1; Type=Data; Flags=None; PayloadLength=8192. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,OnDataOrHeadersReceived,[FlowControl] Sending RTT PING with payload -2 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ExtendWindow,amount=8192 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ExtendWindow,_pendingWindowUpdate 24201 < 8388608. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReadFrameAsync,initialFrame=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessIncomingFramesAsync,Frame 10: StreamId=1; Type=Data; Flags=None; PayloadLength=8192. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ExtendWindow,amount=8192 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ExtendWindow,_pendingWindowUpdate 32393 < 8388608. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=17 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,SendPingAsync,Started writing. pingContent=-2 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=17 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReadFrameAsync,initialFrame=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessIncomingFramesAsync,Frame 11: StreamId=0; Type=Ping; Flags=Ack; PayloadLength=8. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessPingFrame,Received PING frame, content:-2 ack: True ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,RefreshRtt,[FlowControl] Updated MinRtt: 2.5505 ms ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReadFrameAsync,initialFrame=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessIncomingFramesAsync,Frame 12: StreamId=1; Type=Data; Flags=None; PayloadLength=8192. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,OnDataOrHeadersReceived,[FlowControl] Sending RTT PING with payload -3 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ExtendWindow,amount=8192 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ExtendWindow,_pendingWindowUpdate 40585 < 8388608. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessOutgoingFramesAsync,writeBytes=17 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,SendPingAsync,Started writing. pingContent=-3 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FlushOutgoingBytesAsync,ActiveLength=17 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReadFrameAsync,initialFrame=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessIncomingFramesAsync,Frame 13: StreamId=1; Type=Data; Flags=None; PayloadLength=8192. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ExtendWindow,amount=8192 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ExtendWindow,_pendingWindowUpdate 48777 < 8388608. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReadFrameAsync,initialFrame=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessIncomingFramesAsync,Frame 14: StreamId=0; Type=GoAway; Flags=None; PayloadLength=22. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessGoAwayFrame,lastStreamId=1, errorCode=EnhanceYourCalm ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,Shutdown,_shutdown=False, _abortException= ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,SignalAvailableStreamsWaiter,result=False, _availableStreamsWaiter?=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,SignalShutdownWaiter,_shutdownWaiter?=True ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReadFrameAsync,initialFrame=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,InvalidateHttp2Connection, ->
dbug: Grpc.Net.Client.Internal.GrpcCall[13]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Reading message.
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,Dispose,_disposed=False, _streamsInUse=1 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,SignalAvailableStreamsWaiter,result=False, _availableStreamsWaiter?=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,SignalShutdownWaiter,_shutdownWaiter?=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ProcessIncomingFramesAsync,ProcessIncomingFramesAsync: The response ended prematurely while waiting for the next frame from the server. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,Abort,abortException==System.IO.IOException: The response ended prematurely while waiting for the next frame from the server.
         at System.Net.Http.Http2Connection.<ReadFrameAsync>g__ThrowMissingFrame|57_1()
         at System.Net.Http.Http2Connection.ReadFrameAsync(Boolean initialFrame)
         at System.Net.Http.Http2Connection.ProcessIncomingFramesAsync() ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,Shutdown,_shutdown=True, _abortException=System.IO.IOException: The response ended prematurely while waiting for the next frame from the server.
         at System.Net.Http.Http2Connection.<ReadFrameAsync>g__ThrowMissingFrame|57_1()
         at System.Net.Http.Http2Connection.ReadFrameAsync(Boolean initialFrame)
         at System.Net.Http.Http2Connection.ProcessIncomingFramesAsync() ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,SignalAvailableStreamsWaiter,result=False, _availableStreamsWaiter?=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,SignalShutdownWaiter,_shutdownWaiter?=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,LogExceptions,Exception from asynchronous processing: System.IO.IOException: The response ended prematurely while waiting for the next frame from the server.
         at System.Net.Http.Http2Connection.<ReadFrameAsync>g__ThrowMissingFrame|57_1()
         at System.Net.Http.Http2Connection.ReadFrameAsync(Boolean initialFrame)
         at System.Net.Http.Http2Connection.ProcessIncomingFramesAsync() ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,OnReset,resetException=System.IO.IOException: The response ended prematurely while waiting for the next frame from the server.
         at System.Net.Http.Http2Connection.<ReadFrameAsync>g__ThrowMissingFrame|57_1()
         at System.Net.Http.Http2Connection.ReadFrameAsync(Boolean initialFrame)
         at System.Net.Http.Http2Connection.ProcessIncomingFramesAsync(), resetStreamErrorCode= ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,Cancel, ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,SendReset,Stream reset. Request=Completed, Response=Failed. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,Complete,Stream complete. Request=Completed, Response=Failed. ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,RemoveStream, ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,ReleaseStream,_streamsInUse=1 ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,SignalAvailableStreamsWaiter,result=True, _availableStreamsWaiter?=False ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,0,FinalTeardown, ->
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event System.Net.Http - ConnectionClosed : 2,0 ->
fail: Grpc.Net.Client.Internal.GrpcCall[17]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Error reading message.
System.IO.IOException: The request was aborted.
 ---> System.IO.IOException: The response ended prematurely while waiting for the next frame from the server.
   at System.Net.Http.Http2Connection.<ReadFrameAsync>g__ThrowMissingFrame|57_1()
   at System.Net.Http.Http2Connection.ReadFrameAsync(Boolean initialFrame)
   at System.Net.Http.Http2Connection.ProcessIncomingFramesAsync()
   --- End of inner exception stack trace ---
   at System.Net.Http.Http2Connection.ThrowRequestAborted(Exception innerException)
   at System.Net.Http.Http2Connection.Http2Stream.CheckResponseBodyState()
   at System.Net.Http.Http2Connection.Http2Stream.TryReadFromBuffer(Span`1 buffer, Boolean partOfSyncRead)
   at System.Net.Http.Http2Connection.Http2Stream.ReadDataAsync(Memory`1 buffer, HttpResponseMessage responseMessage, CancellationToken cancellationToken)
   at Grpc.Net.Client.StreamExtensions.ReadMessageContent(Stream responseStream, Memory`1 messageData, Int32 length, CancellationToken cancellationToken) in /var/local/git/grpc-dotnet/src/Grpc.Net.Client/Internal/StreamExtensions.cs:line 224
   at Grpc.Net.Client.StreamExtensions.ReadMessageAsync[TResponse](Stream responseStream, GrpcCall call, Func`2 deserializer, String grpcEncoding, Boolean singleMessage, CancellationToken cancellationToken) in /var/local/git/grpc-dotnet/src/Grpc.Net.Client/Internal/StreamExtensions.cs:line 112
info: Grpc.Net.Client.Internal.GrpcCall[3]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Call failed with gRPC error status. Status code: 'Unavailable', Message: 'Error starting gRPC call. IOException: The request was aborted. IOException: The response ended prematurely while waiting for the next frame from the server.'.
dbug: Grpc.Net.Client.Internal.GrpcCall[4]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      Finished gRPC call.
dbug: Grpc.Net.Client.Internal.GrpcCall[8]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      gRPC call canceled.
dbug: HttpEventSourceListener[0]
      => GrpcMethodType:Unary GrpcUri:/grpc.testing.TestService/UnaryCall
      <- Event Private.InternalDiagnostics.System.Net.Http - HandlerMessage : 63220684,25474675,1,Cancel, ->
info: Grpc.Shared.TestAssets.InteropClient[0]
      Failed!
Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="Error starting gRPC call. IOException: The request was aborted. IOException: The response ended prematurely while waiting for the next frame from the server.", DebugException="System.IO.IOException: The request was aborted.
 ---> System.IO.IOException: The response ended prematurely while waiting for the next frame from the server.
   at System.Net.Http.Http2Connection.<ReadFrameAsync>g__ThrowMissingFrame|57_1()
   at System.Net.Http.Http2Connection.ReadFrameAsync(Boolean initialFrame)
   at System.Net.Http.Http2Connection.ProcessIncomingFramesAsync()
   --- End of inner exception stack trace ---
   at System.Net.Http.Http2Connection.ThrowRequestAborted(Exception innerException)
   at System.Net.Http.Http2Connection.Http2Stream.CheckResponseBodyState()
   at System.Net.Http.Http2Connection.Http2Stream.TryReadFromBuffer(Span`1 buffer, Boolean partOfSyncRead)
   at System.Net.Http.Http2Connection.Http2Stream.ReadDataAsync(Memory`1 buffer, HttpResponseMessage responseMessage, CancellationToken cancellationToken)
   at Grpc.Net.Client.StreamExtensions.ReadMessageContent(Stream responseStream, Memory`1 messageData, Int32 length, CancellationToken cancellationToken) in /var/local/git/grpc-dotnet/src/Grpc.Net.Client/Internal/StreamExtensions.cs:line 224
   at Grpc.Net.Client.StreamExtensions.ReadMessageAsync[TResponse](Stream responseStream, GrpcCall call, Func`2 deserializer, String grpcEncoding, Boolean singleMessage, CancellationToken cancellationToken) in /var/local/git/grpc-dotnet/src/Grpc.Net.Client/Internal/StreamExtensions.cs:line 112
   at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout)")
   at Grpc.Shared.TestAssets.InteropClient.RunLargeUnary(IChannelWrapper channel, ClientOptions options) in /var/local/git/grpc-dotnet/testassets/Shared/InteropClient.cs:line 315
   at Grpc.Shared.TestAssets.InteropClient.RunTestCaseAsync(IChannelWrapper channel, ClientOptions options) in /var/local/git/grpc-dotnet/testassets/Shared/InteropClient.cs:line 295
   at Grpc.Shared.TestAssets.InteropClient.Run() in /var/local/git/grpc-dotnet/testassets/Shared/InteropClient.cs:line 86
dbug: HttpEventSourceListener[0]
      Stopping HttpEventSourceListener.
Unhandled exception: Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="Error starting gRPC call. IOException: The request was aborted. IOException: The response ended prematurely while waiting for the next frame from the server.", DebugException="System.IO.IOException: The request was aborted.
 ---> System.IO.IOException: The response ended prematurely while waiting for the next frame from the server.
   at System.Net.Http.Http2Connection.<ReadFrameAsync>g__ThrowMissingFrame|57_1()
   at System.Net.Http.Http2Connection.ReadFrameAsync(Boolean initialFrame)
   at System.Net.Http.Http2Connection.ProcessIncomingFramesAsync()
   --- End of inner exception stack trace ---
   at System.Net.Http.Http2Connection.ThrowRequestAborted(Exception innerException)
   at System.Net.Http.Http2Connection.Http2Stream.CheckResponseBodyState()
   at System.Net.Http.Http2Connection.Http2Stream.TryReadFromBuffer(Span`1 buffer, Boolean partOfSyncRead)
   at System.Net.Http.Http2Connection.Http2Stream.ReadDataAsync(Memory`1 buffer, HttpResponseMessage responseMessage, CancellationToken cancellationToken)
   at Grpc.Net.Client.StreamExtensions.ReadMessageContent(Stream responseStream, Memory`1 messageData, Int32 length, CancellationToken cancellationToken) in /var/local/git/grpc-dotnet/src/Grpc.Net.Client/Internal/StreamExtensions.cs:line 224
   at Grpc.Net.Client.StreamExtensions.ReadMessageAsync[TResponse](Stream responseStream, GrpcCall call, Func`2 deserializer, String grpcEncoding, Boolean singleMessage, CancellationToken cancellationToken) in /var/local/git/grpc-dotnet/src/Grpc.Net.Client/Internal/StreamExtensions.cs:line 112
   at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout)")
   at Grpc.Shared.TestAssets.InteropClient.RunLargeUnary(IChannelWrapper channel, ClientOptions options) in /var/local/git/grpc-dotnet/testassets/Shared/InteropClient.cs:line 315
   at Grpc.Shared.TestAssets.InteropClient.RunTestCaseAsync(IChannelWrapper channel, ClientOptions options) in /var/local/git/grpc-dotnet/testassets/Shared/InteropClient.cs:line 295
   at Grpc.Shared.TestAssets.InteropClient.Run() in /var/local/git/grpc-dotnet/testassets/Shared/InteropClient.cs:line 86
   at InteropTestsClient.Program.<>c.<<Main>b__0_1>d.MoveNext() in /var/local/git/grpc-dotnet/testassets/InteropTestsClient/Program.cs:line 75
--- End of stack trace from previous location ---
   at System.CommandLine.Invocation.CommandHandler.GetResultCodeAsync(Object value, InvocationContext context)
   at System.CommandLine.Invocation.ModelBindingCommandHandler.InvokeAsync(InvocationContext context)
   at System.CommandLine.Invocation.InvocationPipeline.<>c__DisplayClass4_0.<<BuildInvocationChain>b__0>d.MoveNext()
--- End of stack trace from previous location ---
   at System.CommandLine.Builder.CommandLineBuilderExtensions.<>c.<<UseParseErrorReporting>b__20_0>d.MoveNext()
--- End of stack trace from previous location ---
   at System.CommandLine.Builder.CommandLineBuilderExtensions.<>c__DisplayClass15_0.<<UseHelp>b__0>d.MoveNext()
--- End of stack trace from previous location ---
   at System.CommandLine.Builder.CommandLineBuilderExtensions.<>c__DisplayClass24_0.<<UseVersionOption>b__0>d.MoveNext()
--- End of stack trace from previous location ---
   at System.CommandLine.Builder.CommandLineBuilderExtensions.<>c__DisplayClass22_0.<<UseTypoCorrections>b__0>d.MoveNext()
--- End of stack trace from previous location ---
   at System.CommandLine.Builder.CommandLineBuilderExtensions.<>c.<<UseSuggestDirective>b__21_0>d.MoveNext()
--- End of stack trace from previous location ---
   at System.CommandLine.Builder.CommandLineBuilderExtensions.<>c.<<UseParseDirective>b__19_0>d.MoveNext()
--- End of stack trace from previous location ---
   at System.CommandLine.Builder.CommandLineBuilderExtensions.<>c.<<UseDebugDirective>b__11_0>d.MoveNext()
--- End of stack trace from previous location ---
   at System.CommandLine.Builder.CommandLineBuilderExtensions.<>c.<<RegisterWithDotnetSuggest>b__10_0>d.MoveNext()
--- End of stack trace from previous location ---
   at System.CommandLine.Builder.CommandLineBuilderExtensions.<>c__DisplayClass13_0.<<UseExceptionHandler>b__0>d.MoveNext()

2021-11-30 14:18:15,540 FAILED: cloud_to_prod:aspnetcore:default:large_unary:tls [ret=1, pid=14653, time=1.5sec]

Regression?

Yes, this worked in .NET 5. The only change has been updating the client app to .NET 6.

Known Workarounds

No response

Configuration

Runtime: 6.0.0-rtm.21522.10+4822e3c3aa77eb82b2fb33c9321f923cf11ddde6

Other information

No response

About this issue

  • Original URL
  • State: closed
  • Created 3 years ago
  • Comments: 32 (27 by maintainers)

Most upvoted comments

I think there are two issues here:

  • Too many pings are causing the end server to kill the connection.
  • Less important, but SocketsHttpHandler could provide better error details in the exception. While “The response ended prematurely while waiting for the next frame from the server.” is technically correct, reporting the ENHANCE_YOUR_CALM status from the server would make it clearer what is going on.
+3
JamesNK on Dec 1, 2021

We did some research with @jtattermusch, and this turned out that the GOAWAY comes from a proxy in google’s internal backends.

There are proxies in the wild which do different ping accounting than what is specified in the “server enforcement” document, resetting their ping counter upon receiving frames.

We should adjust our implementation to make sure we don’t send more than 2 RTT PING-s without sending DATA, HEADERS or WINDOW_UPDATE.

+2
antonfirsov on May 16, 2022

Good spotting on the pings. Some servers are very strict about the number of pings allowed before they kill the connection. The endpoint is a sandbox Google production environment. A hardened edge server is validating traffic.

(Kestrel processes pings so quickly we don’t bother being strict about them)

+2
JamesNK on Dec 1, 2021

@karelz We are currently also experiencing the issue in a real world implementation. Some calls to gRPC streaming services randomly fail. Both the services and clients are implemented with .NET 6 and are hosted on GCP Cloud Run instances. The connection is dropped after the server side received too many pings. According to logs we receive “GoAway” frame with “EnhanceYourCalm” because we send 3 ping frames.

Disabling dynamic window sizing also helped in our case. As dynamic window sizing is activated by default, more people will run into this issue.

+1
fhaubner on Apr 29, 2022

No need to decipher docs. The server is publicly available to test against.

+1
JamesNK on Dec 4, 2021

and pings received more frequently than once every 5 minutes are considered unsolicited.

@chwarr if my understanding of those guidelines is correct, this is not fully accurate.

Note that the Keepalive User Guide for gRPC Core repeatedly talks about stuff like:

number of pings that can be sent when there is no data/header frame to be sent

or

When there isn’t any data/header being sent on the transport, gRPC clients restrict the number of pings to 2 by default.

The details are not clarified in that document, but it references the Client-side Keepalive guide, where the server enforcement section clarifies that the unsolicited ping counter is being reset to 0 whenever a DATA or HEADERS frame is being sent. This aligns with the fact that PINGs are not harmful as long as the client is actually consuming the server stream.

Let me know if you think I’m misunderstanding those docs.

+1
antonfirsov on Dec 3, 2021
Read more comments on GitHub
← runtime: HTTP/2: Rare data corruption when stress testing against Kestrel
runtime: HTTP2: SocketsHttpHandler setting Ssl.AllowRenegotiation=false incorrectly →