Skip to content

Conversation

@JamesNK
Copy link
Member

@JamesNK JamesNK commented Oct 6, 2021

Fix race condition that caused flakey test failure:

  Failed Unary_ServerResetCancellationStatus_DeadlineStatus [316 ms]
  Error Message:
   System.InvalidOperationException : Unable to get the status because the call is not complete.
  Stack Trace:
     at Grpc.Net.Client.Internal.GrpcCall`2.GetStatus() in /home/runner/work/grpc-dotnet/grpc-dotnet/src/Grpc.Net.Client/Internal/GrpcCall.cs:line 332
   at Grpc.Net.Client.Internal.HttpClientCallInvoker.Callbacks`2.<>c.<.cctor>b__4_1(Object state) in /home/runner/work/grpc-dotnet/grpc-dotnet/src/Grpc.Net.Client/Internal/HttpClientCallInvoker.cs:line 173
   at Grpc.Core.AsyncCallState.GetStatus()
   at Grpc.Core.AsyncUnaryCall`1.GetStatus()
   at Grpc.AspNetCore.FunctionalTests.Client.DeadlineTests.Unary_ServerResetCancellationStatus_DeadlineStatus() in /home/runner/work/grpc-dotnet/grpc-dotnet/test/FunctionalTests/Client/DeadlineTests.cs:line 99
   at NUnit.Framework.Internal.TaskAwaitAdapter.GenericAdapter`1.BlockUntilCompleted()
   at NUnit.Framework.Internal.MessagePumpStrategy.NoMessagePumpStrategy.WaitForCompletion(AwaitAdapter awaiter)
   at NUnit.Framework.Internal.AsyncToSyncAdapter.Await(Func`1 invoke)
   at NUnit.Framework.Internal.Commands.TestMethodCommand.RunTestMethod(TestExecutionContext context)
   at NUnit.Framework.Internal.Commands.TestMethodCommand.Execute(TestExecutionContext context)
   at NUnit.Framework.Internal.Commands.BeforeAndAfterTestCommand.<>c__DisplayClass1_0.<Execute>b__0()
   at NUnit.Framework.Internal.Commands.BeforeAndAfterTestCommand.RunTestMethodInThreadAbortSafeZone(TestExecutionContext context, Action action)
  Standard Output Messages:
 0.000s GrpcTestContext - Information: Starting DeadlineTests.Unary_ServerResetCancellationStatus_DeadlineStatus
 0.002s SERVER Grpc.AspNetCore.Server.Model.Internal.ServiceRouteBuilder - Trace: Discovering gRPC methods for FunctionalTestsWebsite.Infrastructure.DynamicService.
 0.002s SERVER Grpc.AspNetCore.Server.Model.Internal.BinderServiceMethodProvider - Debug: Could not find bind method for FunctionalTestsWebsite.Infrastructure.DynamicService.
 0.002s SERVER Grpc.AspNetCore.Server.Model.Internal.ServiceRouteBuilder - Trace: Added gRPC method 'f8b4c348-4425-4d68-aad8-870fa2142f12' to service 'DynamicService'. Method type: 'Unary', route pattern: '/DynamicService/f8b4c348-4425-4d68-aad8-870fa2142f12'.
 0.002s Grpc.Net.Client.Internal.GrpcCall - Debug: Starting gRPC call. Method type: 'Unary', URI: 'http://127.0.0.1:50050/DynamicService/f8b4c348-4425-4d68-aad8-870fa2142f12'.
 0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMC7MCHT2FMG" accepted.
 0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Connections - Debug: Connection id "0HMC7MCHT2FMG" started.
 0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMC7MCHT2FMG" sending SETTINGS frame for stream ID 0 with length 18 and flags NONE.
 0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMC7MCHT2FMG" sending WINDOW_UPDATE frame for stream ID 0 with length 4 and flags 0x0.
 0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMC7MCHT2FMG" received SETTINGS frame for stream ID 0 with length 12 and flags NONE.
 0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMC7MCHT2FMG" sending SETTINGS frame for stream ID 0 with length 0 and flags ACK.
 0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMC7MCHT2FMG" received WINDOW_UPDATE frame for stream ID 0 with length 4 and flags 0x0.
 0.004s Grpc.Net.Client.Internal.GrpcCall - Debug: Sending message.
 0.004s Grpc.Net.Client.Internal.GrpcCall - Trace: Serialized 'Streaming.DataMessage' to 0 byte message.
 0.004s Grpc.Net.Client.Internal.GrpcCall - Trace: Message sent.
 0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMC7MCHT2FMG" received HEADERS frame for stream ID 1 with length 311 and flags END_HEADERS.
 0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMC7MCHT2FMG" received DATA frame for stream ID 1 with length 5 and flags NONE.
 0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMC7MCHT2FMG" received DATA frame for stream ID 1 with length 0 and flags END_STREAM.
 0.004s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMC7MCHT2FMG" received SETTINGS frame for stream ID 0 with length 0 and flags ACK.
 0.004s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request starting HTTP/2 POST http://127.0.0.1:50050/DynamicService/f8b4c348-4425-4d68-aad8-870fa2142f12 application/grpc -
 0.024s SERVER Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware - Debug: Request matched endpoint 'gRPC - /DynamicService/f8b4c348-4425-4d68-aad8-870fa2142f12'
 0.024s SERVER Microsoft.AspNetCore.Routing.EndpointMiddleware - Information: Executing endpoint 'gRPC - /DynamicService/f8b4c348-4425-4d68-aad8-870fa2142f12'
 0.026s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Request deadline timeout of 00:00:00.2990000 started.
 0.026s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Reading message.
 0.026s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMC7MCHT2FMG", Request id "0HMC7MCHT2FMG:00000001": started reading request body.
 0.026s SERVER Microsoft.AspNetCore.Server.Kestrel - Debug: Connection id "0HMC7MCHT2FMG", Request id "0HMC7MCHT2FMG:00000001": done reading request body.
 0.026s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Deserializing 0 byte message to 'Streaming.DataMessage'.
 0.026s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Received message.
 0.308s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Debug: Trace id "0HMC7MCHT2FMG:00000001": HTTP/2 stream error "CANCEL". A Reset is being sent to the stream.
 Microsoft.AspNetCore.Connections.ConnectionAbortedException: The HTTP/2 stream was reset by the application with error code CANCEL.
 0.308s SERVER Microsoft.AspNetCore.Server.Kestrel.Http2 - Trace: Connection id "0HMC7MCHT2FMG" sending RST_STREAM frame for stream ID 1 with length 4 and flags 0x0.
 0.311s Grpc.Net.Client.Internal.GrpcCall - Warning: gRPC call deadline exceeded.
 0.311s Grpc.Net.Client.Internal.GrpcCall - Information: Call failed with gRPC error status. Status code: 'DeadlineExceeded', Message: 'Error starting gRPC call. HttpRequestException: An error occurred while sending the request. IOException: The request was aborted. Http2StreamException: The HTTP/2 server reset the stream. HTTP/2 error code 'CANCEL' (0x8).'.
 0.311s Grpc.Net.Client.Internal.GrpcCall - Debug: Finished gRPC call.
 0.312s Grpc.Net.Client.Internal.GrpcCall - Debug: gRPC call canceled.
 0.313s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Debug: Sending message.
 0.313s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Serialized 'Streaming.DataMessage' to 0 byte message.
 0.313s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Message sent.
 0.313s SERVER Grpc.AspNetCore.Server.ServerCallHandler - Trace: Request deadline stopped.
 0.313s SERVER Microsoft.AspNetCore.Routing.EndpointMiddleware - Information: Executed endpoint 'gRPC - /DynamicService/f8b4c348-4425-4d68-aad8-870fa2142f12'
 0.313s SERVER Microsoft.AspNetCore.Hosting.Diagnostics - Information: Request finished HTTP/2 POST http://127.0.0.1:50050/DynamicService/f8b4c348-4425-4d68-aad8-870fa2142f12 application/grpc - - 200 - application/grpc 309.0698ms
 0.317s GrpcTestContext - Information: Finishing DeadlineTests.Unary_ServerResetCancellationStatus_DeadlineStatus

@JamesNK JamesNK requested a review from captainsafia October 6, 2021 04:45
Copy link
Contributor

@captainsafia captainsafia left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM -- I assume that monitoring test flakiness is a sufficient way to validate this fix?

@JamesNK
Copy link
Member Author

JamesNK commented Oct 6, 2021

It's the best we can do. I can't think of a way to reliably test this 😢

@JamesNK JamesNK merged commit cb2f9d7 into grpc:master Oct 7, 2021
@JamesNK JamesNK deleted the jamesnk/response-flakeytest branch October 7, 2021 21:30
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants