Bidirectional streaming RPCs occasionally stall on macOS 12.6 M1 after an unrelated streaming RPC is cancelled
- Dominant language
- C#
- Stars
- 4.5k
- Forks
- 836
- Avg merge
- 6d 3h
- Merged PRs (30d)
- 7
Description
### What version of gRPC and what language are you using?
- Grpc.Net.Client 2.53.0
- Grpc.Tools 2.54.0
- .NET 7
### What operating system (Linux, Windows,...) and version?
macOS 12.6, M1 processor
### What runtime / compiler are you using (e.g. .NET Core SDK version `dotnet --info`)
.NET 7.0.306
### What did you do?
Rarely on macOS, I'm seeing a stall where code like this:
```csharp
while (await _call.ResponseStream.MoveNext(cancellationToken).ConfigureAwait(false))
{
var current = _call.ResponseStream.Current;
_logger.LogTrace($"{_uniqueAssignmentId}: Enqueuing AsyncDuplexStreamingCall: {current}");
_queue.Enqueue((current, null));
}
```
will stop iterating, even though the response stream has provided more messages. This code works perfectly fine on Windows; the stall only manifests on macOS. The connection is over an insecure HTTP2 localhost connection. As detailed later, I believe cancellation of another unrelated streaming RPC on the same server is the cause of the stall (though it's possible the root cause lies in the gRPC client or HTTP client code).
### What did you expect to see?
When the gRPC connection is working correctly, I see messages like the following in my trace logs. These trace logs are combined from the client and server (both run in the same process in this particular scenario):
```
[2023-09-25 12:37:30.452] [trce] [Redpoint.ProcessExecution.DefaultProcessExecutor] 23f52f01-9404-4e72-9692-a703256e7fbc: Received 'process.Exited' event; releasing exit semaphore...
[2023-09-25 12:37:30.452] [trce] [Redpoint.ProcessExecution.DefaultProcessExecutor] 23f52f01-9404-4e72-9692-a703256e7fbc: Received 'process.Exited' event; released exit semaphore.
[2023-09-25 12:37:30.452] [trce] [Redpoint.ProcessExecution.DefaultProcessExecutor] 23f52f01-9404-4e72-9692-a703256e7fbc: Received process exit notification via exit semaphore.
[2023-09-25 12:37:30.452] [trce] [Redpoint.ProcessExecution.DefaultProcessExecutor] 23f52f01-9404-4e72-9692-a703256e7fbc: Process has exited, awaiting the standard output reading task to completion...
[2023-09-25 12:37:30.452] [trce] [Redpoint.ProcessExecution.DefaultProcessExecutor] 23f52f01-9404-4e72-9692-a703256e7fbc: Process has exited; the standard output reading task is complete.
[2023-09-25 12:37:30.452] [trce] [Redpoint.ProcessExecution.DefaultProcessExecutor] 23f52f01-9404-4e72-9692-a703256e7fbc: Process has exited, awaiting the standard error reading task to completion...
[2023-09-25 12:37:30.452] [trce] [Redpoint.ProcessExecution.DefaultProcessExecutor] 23f52f01-9404-4e72-9692-a703256e7fbc: Process has exited; the standard error reading task is complete.
[2023-09-25 12:37:30.452] [trce] [Redpoint.ProcessExecution.DefaultProcessExecutor] 23f52f01-9404-4e72-9692-a703256e7fbc: Process has exited with exit code 0.
[2023-09-25 12:37:30.452] [trce] [Redpoint.OpenGE.Component.Worker.DefaultExecutionManager] Worker process response stream: { "response": { "exitCode": 0 } }
[2023-09-25 12:37:30.452] [trce] [Redpoint.OpenGE.Component.Worker.DefaultExecutionManager] ac3b3622-94c6-4264-87e6-5c37981412cf: Finished enumeration of returned response stream.
[2023-09-25 12:37:30.453] [trce] [Redpoint.OpenGE.Component.Worker.DefaultExecutionManager] ac3b3622-94c6-4264-87e6-5c37981412cf: Finished execution in 00:00:07.4215188 of: ...
[2023-09-25 12:37:30.453] [trce] [Redpoint.OpenGE.Component.Worker.DefaultWorkerComponent] 57c7952e-2fc9-4e0c-8198-88ba7b5ca239: Worker ReserveCoreAndExecute ExecuteTask End
[2023-09-25 12:37:30.455] [trce] [Redpoint.OpenGE.Component.Dispatcher.WorkerPool.DefaultTaskApiWorkerPool] 57c7952e-2fc9-4e0c-8198-88ba7b5ca239: Enqueuing AsyncDuplexStreamingCall: { "executeTask": { "response": { "exitCode": 0 } } }
[2023-09-25 12:37:30.455] [trce] [Redpoint.OpenGE.Component.Dispatcher.WorkerPool.DefaultTaskApiWorkerPool] 57c7952e-2fc9-4e0c-8198-88ba7b5ca239: AsyncDuplexStreamingCall yielding value: { "executeTask": { "response": { "exitCode": 0 } } }
[2023-09-25 12:37:30.455] [trce] [Redpoint.OpenGE.Component.Dispatcher.GraphExecutor.DefaultGraphExecutor] 57c7952e-2fc9-4e0c-8198-88ba7b5ca239: Received message type: ExecuteTask
[2023-09-25 12:37:30.455] [trce] [Redpoint.OpenGE.Component.Dispatcher.GraphExecutor.DefaultGraphExecutor] 57c7952e-2fc9-4e0c-8198-88ba7b5ca239: Finished streaming execution events from worker, releasing reservation request...
[2023-09-25 12:37:30.455] [trce] [Redpoint.OpenGE.Component.Dispatcher.GraphExecutor.DefaultGraphExecutor] 57c7952e-2fc9-4e0c-8198-88ba7b5ca239: Released core reservation request after execution finished.
```
### What did you see instead?
When the gRPC pipe stalls, the AsyncDuplexStreamingCall class no longer receives messages from the `MoveNext`/`Current` loop, which can be seen missing from the log output:
```
[2023-09-25 12:37:44.936] [trce] [Redpoint.ProcessExecution.DefaultProcessExecutor] 17f2f166-2f12-433b-bf18-4e64d96a58ea: Received 'process.Exited' event; releasing exit semaphore...
[2023-09-25 12:37:44.936] [trce] [Redpoint.ProcessExecution.DefaultProcessExecutor] 17f2f166-2f12-433b-bf18-4e64d96a58ea: Received 'process.Exited' event; released exit semaphore.
[2023-09-25 12:37:44.936] [trce] [Redpoint.ProcessExecution.DefaultProcessExecutor] 17f2f166-2f12-433b-bf18-4e64d96a58ea: Received process exit notification via exit semaphore.
[2023-09-25 12:37:44.936] [trce] [Redpoint.ProcessExecution.DefaultProcessExecutor] 17f2f166-2f12-433b-bf18-4e64d96a58ea: Process has exited, awaiting the standard output reading task to completion...
[2023-09-25 12:37:44.936] [trce] [Redpoint.ProcessExecution.DefaultProcessExecutor] 17f2f166-2f12-433b-bf18-4e64d96a58ea: Process has exited; the standard output reading task is complete.
[2023-09-25 12:37:44.936] [trce] [Redpoint.ProcessExecution.DefaultProcessExecutor] 17f2f166-2f12-433b-bf18-4e64d96a58ea: Process has exited, awaiting the standard error reading task to completion...
[2023-09-25 12:37:44.936] [trce] [Redpoint.ProcessExecution.DefaultProcessExecutor] 17f2f166-2f12-433b-bf18-4e64d96a58ea: Process has exited; the standard error reading task is complete.
[2023-09-25 12:37:44.936] [trce] [Redpoint.ProcessExecution.DefaultProcessExecutor] 17f2f166-2f12-433b-bf18-4e64d96a58ea: Process has exited with exit code 0.
[2023-09-25 12:37:44.937] [trce] [Redpoint.OpenGE.Component.Dispatcher.WorkerPool.DefaultTaskApiWorkerPool] SingleSourceWorkerCoreRequestFulfiller.RunAsync: Waiting to obtain the request processing lock.
[2023-09-25 12:37:44.937] [trce] [Redpoint.OpenGE.Component.Dispatcher.WorkerPool.DefaultTaskApiWorkerPool] SingleSourceWorkerCoreRequestFulfiller.RunAsync: There are 21 pending requests.
[2023-09-25 12:37:44.937] [trce] [Redpoint.OpenGE.Component.Dispatcher.WorkerPool.DefaultTaskApiWorkerPool] SingleSourceWorkerCoreRequestFulfiller.RunAsync: Waiting to be notified that requests have changed.
[2023-09-25 12:37:44.937] [trce] [Redpoint.OpenGE.Component.Worker.DefaultExecutionManager] Worker process response stream: { "response": { "exitCode": 0 } }
[2023-09-25 12:37:44.937] [trce] [Redpoint.OpenGE.Component.Worker.DefaultExecutionManager] 4f4c3a2b-bb74-4ecf-8a04-64b485ed4e73: Finished enumeration of returned response stream.
[2023-09-25 12:37:44.937] [trce] [Redpoint.OpenGE.Component.Worker.DefaultExecutionManager] 4f4c3a2b-bb74-4ecf-8a04-64b485ed4e73: Finished execution in 00:00:21.9064061 of: ...
[2023-09-25 12:37:44.937] [trce] [Redpoint.OpenGE.Component.Worker.DefaultWorkerComponent] bcae15a1-183f-4a4d-bd26-12a33abed1c6: Worker ReserveCoreAndExecute ExecuteTask End
[2023-09-25 12:37:45.187] [trce] [Redpoint.OpenGE.Component.Dispatcher.WorkerPool.DefaultTaskApiWorkerPool] SingleSourceWorkerCoreRequestFulfiller.RunAsync: Waiting to obtain the request processing lock.
[2023-09-25 12:37:45.187] [trce] [Redpoint.OpenGE.Component.Dispatcher.WorkerPool.DefaultTaskApiWorkerPool] SingleSourceWorkerCoreRequestFulfiller.RunAsync: There are 21 pending requests.
[2023-09-25 12:37:45.188] [trce] [Redpoint.OpenGE.Component.Dispatcher.WorkerPool.DefaultTaskApiWorkerPool] SingleSourceWorkerCoreRequestFulfiller.RunAsync: Waiting to be notified that requests have changed.
[2023-09-25 12:37:45.346] [trce] [Redpoint.OpenGE.Component.Dispatcher.WorkerPool.DefaultTaskApiWorkerPool] SingleSourceWorkerCoreRequestFulfiller.RunAsync: Waiting to obtain the request processing lock.
[2023-09-25 12:37:45.346] [trce] [Redpoint.OpenGE.Component.Dispatcher.WorkerPool.DefaultTaskApiWorkerPool] SingleSourceWorkerCoreRequestFulfiller.RunAsync: There are 21 pending requests.
```
When this stall happens, *all* streaming requests stall and no longer receive more messages.
When the server shuts down due to the built-in stall detection, the `AsyncDuplexStreamingCall` then sees the typical "Broken pipe" exception:
```
[2023-09-25 12:39:35.972] [trce] [Redpoint.OpenGE.Component.Dispatcher.WorkerPool.DefaultTaskApiWorkerPool] 5caf49da-506a-4245-b415-a159943f5487: AsyncDuplexStreamingCall got exception: Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="Error reading next message. IOException: The request was aborted. IOException: Unable to write data to the transport connection: Broken pipe. SocketException: Broken pipe", DebugException="System.IO.IOException: The request was aborted.")
---> System.IO.IOException: The request was aborted.
---> System.IO.IOException: Unable to write data to the transport connection: Broken pipe.
---> System.Net.Sockets.SocketException (32): Broken pipe
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.CreateException(SocketError, Boolean )
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.SendAsyncForNetworkStream(Socket, CancellationToken)
at System.Net.Sockets.NetworkStream.WriteAsync(ReadOnlyMemory`1, CancellationToken )
at Grpc.Net.Client.Balancer.Internal.StreamWrapper.WriteAsync(ReadOnlyMemory`1, CancellationToken )
at System.Net.Http.Http2Connection.FlushOutgoingBytesAsync()
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine&)
at System.Net.Http.Http2Connection.FlushOutgoingBytesAsync()
at System.Net.Http.Http2Connection.ProcessOutgoingFramesAsync()
at System.Threading.ExecutionContext.RunInternal(ExecutionContext, ContextCallback, Object)
at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread)
at System.Threading.ThreadPoolWorkQueue.Dispatch()
at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
at System.Threading.Thread.StartCallback()
--- End of stack trace from previous location ---
--- End of inner exception stack trace ---
at System.Net.Http.Http2Connection.FlushOutgoingBytesAsync()
--- End of inner exception stack trace ---
at System.Net.Http.Http2Connection.ThrowRequestAborted(Exception )
at System.Net.Http.Http2Connection.Http2Stream.CheckResponseBodyState()
at System.Net.Http.Http2Connection.Http2Stream.TryReadFromBuffer(Span`1, Boolean )
at System.Net.Http.Http2Connection.Http2Stream.ReadDataAsync(Memory`1, HttpResponseMessage, CancellationToken)
at Grpc.Net.Client.Internal.StreamExtensions.ReadMessageAsync[TResponse](Stream, GrpcCall, Func`2, String, Boolean, CancellationToken)
at Grpc.Net.Client.Internal.HttpContentClientStreamReader`2.MoveNextCore(CancellationToken)
--- End of inner exception stack trace ---
at Grpc.Net.Client.Internal.HttpContentClientStreamReader`2.MoveNextCore(CancellationToken)
at Redpoint.OpenGE.Core.BufferedAsyncDuplexStreamingCall`2.ProcessResponseStreamAsync(CancellationToken)
```
The primary clue I have is that the stall doesn't seem to happen (at least in this trace log) until after the first bidirectional RPC is cancelled by the server:
```
[2023-09-25 12:37:36.715] [trce] [Redpoint.OpenGE.Component.Worker.DefaultWorkerComponent] a472bc5a-f6f3-45f6-bee3-0c3be0764e84: The entity calling ReserveCoreAndExecute RPC idled for too long, and the call was cancelled because the reservation was not being used. The last request was None approximately 13.701302 seconds ago.
[2023-09-25 12:37:36.716] [trce] [Redpoint.OpenGE.Component.Worker.DefaultWorkerComponent] Error status code 'Cancelled' with detail 'Connection idled for too long, so the reservation was released.' raised.
[2023-09-25 12:37:36.716] [trce] [Redpoint.OpenGE.Component.Worker.DefaultWorkerComponent] Executed endpoint 'gRPC - /Redpoint.OpenGE.Protocol.TaskApi/ReserveCoreAndExecute'
[2023-09-25 12:37:36.716] [trce] [Redpoint.OpenGE.Component.Worker.DefaultWorkerComponent] Request finished HTTP/2 POST http://127.0.0.1:57865/Redpoint.OpenGE.Protocol.TaskApi/ReserveCoreAndExecute application/grpc - - 200 - application/grpc 13706.4565ms
[2023-09-25 12:37:36.716] [trce] [Redpoint.OpenGE.Component.Worker.DefaultWorkerComponent] Connection id "0HMTTE1AJRE13", Request id "0HMTTE1AJRE13:00000005": the application completed without reading the entire request body.
```
The timing order is:
- `2023-09-25 12:37:30.455`: The last time an `AsyncDuplexStreamingCall` receives a message.
- `2023-09-25 12:37:31.620`: First streaming RPC cancelled by server.
- `2023-09-25 12:37:44.937`: The next time a streaming call emits data from a worker to a dispatcher, but the dispatcher never receives the message in `AsyncDuplexStreamingCall`.
### Anything else we should know about your project / environment?
I've been tracking down this stall for weeks, adding more and more trace logs until I could narrow down the location, and I'm now pretty sure this is in the gRPC stack or the .NET HTTP stack. On an individual level it seems to be pretty rare, except that this application and deployment scenario means there's a huge number of streaming RPC calls done on any given run, so it happens relatively frequently overall.
The implementation of `BufferedAsyncDuplexStreamingCall` is located here: https://src.redpoint.games/redpointgames/uet/-/blob/main/UET/Redpoint.OpenGE.Core/BufferedAsyncDuplexStreamingCall.cs (along with the rest of the code in the repository).
Contributor guide
Assessment
This issue has not been assessed yet.