search

Cysharp / YetAnotherHttpHandler

YetAnotherHttpHandler brings the power of HTTP/2 (and gRPC) to Unity and .NET Standard.
MIT License
345 stars 30 forks source link

Connection was lost during high load streaming. #93

Closed VladimirRudt closed 5 days ago

VladimirRudt commented 3 weeks ago

Hi @mayuki, we faced a tricky issue. It might be not a bug, but we cannot be sure without your confirmation.

Scenario of the issue. I added references to the request numbers from the attached log file.

  1. We start a server side stream [ReqSec:19] that provide us with camera preview
  2. We execute an unary call [ReqSec:20] which changes parameters of the camera preview

Sometimes the server stream crashes during the second operation and all running requests/streams are cancelled. After that the client resets the connection and closes the socket.

We use a not very stable connection to the server on another continent, and this may be the reason for the connection being dropped. We also have some other client and duplex streams [ReqSec:3, 2, 5, 6] running in the background and adding a small load as well. But the missing error code is the reason we are not sure that issues related to the bad connection:

2024.08.20 15:31:59.693 14770 14873 Info Unity [ReqSeq:19:State:0x35] Response completed: Reason=Error; H2ErrorCode=0x0

This is our client handler configuration:

var httpHandler = new YetAnotherHttpHandler
{
    Http2KeepAliveTimeout = TimeSpan.FromMilliseconds(KeepAliveTimeoutMilliseconds),  // 3 sec.
    Http2KeepAliveInterval = TimeSpan.FromMilliseconds(KeepAliveMilliseconds),                 // 3 sec.
    Http2Only = true,
};

httpHandler.RootCertificates = sslCredentials.RootCertificates;

// Initialize gRPC channel provider when the application is loaded.
GrpcChannelProviderHost.Initialize(new DefaultGrpcChannelProvider(() => new GrpcChannelOptions
{
    HttpHandler = httpHandler,
}));

GrpcChannel = GrpcChannel.ForAddress($"https://{host}:{ApiSslPort}", new GrpcChannelOptions
{
    HttpHandler = httpHandler,
    DisposeHttpClient = true,
});

We are using YetAnotherHttpHandler v1.5.2. As far as I know, the latest version v1.5.3 does not have any changes that could fix this.

Logs from the client side. We launch it on Android logcat.txt

Logs on server side regarding camera preview stream:

2024-08-20 01:31:55.1198 | Info | Request starting HTTP/2 POST https://192.168.14.59:7084/ICommunicationService/Settings_StreamCameraPreviewAsync - application/grpc - | Protocol=HTTP/2, Method=POST, ContentType=application/grpc, Scheme=https, Host=192.168.14.59:7084, Path=/ICommunicationService/Settings_StreamCameraPreviewAsync, EventId=1, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:31:55.1198 | Debug | 3 candidate(s) found for the request path '/ICommunicationService/Settings_StreamCameraPreviewAsync' | CandidateCount=3, Path=/ICommunicationService/Settings_StreamCameraPreviewAsync, EventId=1001, EventName=CandidatesFound, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:31:55.1198 | Debug | Endpoint 'gRPC - /ICommunicationService/Settings_StreamCameraPreviewAsync' with route pattern '/ICommunicationService/Settings_StreamCameraPreviewAsync' is valid for the request path '/ICommunicationService/Settings_StreamCameraPreviewAsync' | Endpoint=gRPC - /ICommunicationService/Settings_StreamCameraPreviewAsync, RoutePattern=/ICommunicationService/Settings_StreamCameraPreviewAsync, Path=/ICommunicationService/Settings_StreamCameraPreviewAsync, EventId=1005, EventName=CandidateValid, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:31:55.1198 | Debug | Endpoint 'gRPC - Unimplemented method for ICommunicationService' with route pattern 'ICommunicationService/{unimplementedMethod:grpcunimplemented}' is valid for the request path '/ICommunicationService/Settings_StreamCameraPreviewAsync' | Endpoint=gRPC - Unimplemented method for ICommunicationService, RoutePattern=ICommunicationService/{unimplementedMethod:grpcunimplemented}, Path=/ICommunicationService/Settings_StreamCameraPreviewAsync, EventId=1005, EventName=CandidateValid, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:31:55.1198 | Debug | Endpoint 'gRPC - Unimplemented service' with route pattern '{unimplementedService}/{unimplementedMethod:grpcunimplemented}' is valid for the request path '/ICommunicationService/Settings_StreamCameraPreviewAsync' | Endpoint=gRPC - Unimplemented service, RoutePattern={unimplementedService}/{unimplementedMethod:grpcunimplemented}, Path=/ICommunicationService/Settings_StreamCameraPreviewAsync, EventId=1005, EventName=CandidateValid, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:31:55.1198 | Debug | Request matched endpoint 'gRPC - /ICommunicationService/Settings_StreamCameraPreviewAsync' | EndpointName=gRPC - /ICommunicationService/Settings_StreamCameraPreviewAsync, EventId=1, EventName=MatchSuccess, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:31:55.1198 | Info | Executing endpoint 'gRPC - /ICommunicationService/Settings_StreamCameraPreviewAsync' | EndpointName=gRPC - /ICommunicationService/Settings_StreamCameraPreviewAsync, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:31:55.1198 | Debug | Reading message. | EventId=10, EventName=ReadingMessage, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:31:55.1198 | Debug | Connection id "0HN60ROQ2A0RV", Request id "0HN60ROQ2A0RV:00000025": started reading request body. | ConnectionId=0HN60ROQ2A0RV, TraceIdentifier=0HN60ROQ2A0RV:00000025, EventId=25, EventName=RequestBodyStart, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:31:55.1198 | Debug | Connection id "0HN60ROQ2A0RV", Request id "0HN60ROQ2A0RV:00000025": done reading request body. | ConnectionId=0HN60ROQ2A0RV, TraceIdentifier=0HN60ROQ2A0RV:00000025, EventId=26, EventName=RequestBodyDone, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:31:55.1198 | Debug | BeginInvokeMethod type:ServerStreaming method:/ICommunicationService/Settings_StreamCameraPreviewAsync | methodType=ServerStreaming, method=/ICommunicationService/Settings_StreamCameraPreviewAsync, EventId=3, EventName=BeginInvokeMethod, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:31:55.1717 | Info | ScannerStateChanged: Scanner has moved from Idle to CameraPreview state due to StartCameraPreview trigger | Scope=ScannerStateChanged, SourceState=Idle, DestinationState=CameraPreview, Trigger=StartCameraPreview, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:31:55.1717 | Info | Camera preview started, CameraIndex = 0, DeviceMode = Targets | CameraIndex=0, DeviceMode=Targets, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:31:55.1864 | Debug | WriteToStream type:ServerStreaming method:/ICommunicationService/Settings_StreamCameraPreviewAsync | methodType=ServerStreaming, method=/ICommunicationService/Settings_StreamCameraPreviewAsync, EventId=5, EventName=WriteToStream, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:31:55.1864 | Debug | Sending message. | EventId=15, EventName=SendingMessage, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:31:56.6402 | Debug | WriteToStream type:ServerStreaming method:/ICommunicationService/Settings_StreamCameraPreviewAsync | methodType=ServerStreaming, method=/ICommunicationService/Settings_StreamCameraPreviewAsync, EventId=5, EventName=WriteToStream, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:31:56.6402 | Debug | Sending message. | EventId=15, EventName=SendingMessage, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:31:59.1979 | Debug | WriteToStream type:ServerStreaming method:/ICommunicationService/Settings_StreamCameraPreviewAsync | methodType=ServerStreaming, method=/ICommunicationService/Settings_StreamCameraPreviewAsync, EventId=5, EventName=WriteToStream, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:31:59.1979 | Debug | Sending message. | EventId=15, EventName=SendingMessage, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:32:00.1713 | Debug | WriteToStream type:ServerStreaming method:/ICommunicationService/Settings_StreamCameraPreviewAsync | methodType=ServerStreaming, method=/ICommunicationService/Settings_StreamCameraPreviewAsync, EventId=5, EventName=WriteToStream, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:32:00.1713 | Debug | Sending message. | EventId=15, EventName=SendingMessage, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:32:00.6794 | Info | ScannerStateChanged: Scanner has moved from CameraPreview to Idle state due to StopCameraPreview trigger | Scope=ScannerStateChanged, SourceState=CameraPreview, DestinationState=Idle, Trigger=StopCameraPreview, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:32:00.6794 | Debug | EndInvokeMethod type:ServerStreaming method:/ICommunicationService/Settings_StreamCameraPreviewAsync elapsed:5555.8505 error | methodType=ServerStreaming, method=/ICommunicationService/Settings_StreamCameraPreviewAsync, elapsed=5555.8505, message=error, EventId=4, EventName=EndInvokeMethod, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:32:00.6794 | Warn | Operation cancelled | ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | System.OperationCanceledException: Request aborted while sending the message.
2024-08-20 01:32:00.6794 | Info | Error status code 'Cancelled' with detail '' raised. | StatusCode=Cancelled, EventId=7, EventName=RpcConnectionError, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:32:00.6794 | Info | Executed endpoint 'gRPC - /ICommunicationService/Settings_StreamCameraPreviewAsync' | EndpointName=gRPC - /ICommunicationService/Settings_StreamCameraPreviewAsync, EventId=1, EventName=ExecutedEndpoint, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-20 01:32:00.6794 | Info | Request finished HTTP/2 POST https://192.168.14.59:7084/ICommunicationService/Settings_StreamCameraPreviewAsync - 200 - application/grpc 5569.1302ms | ElapsedMilliseconds=5569.1302, StatusCode=200, ContentType=application/grpc, Protocol=HTTP/2, Method=POST, Scheme=https, Host=192.168.14.59:7084, Path=/ICommunicationService/Settings_StreamCameraPreviewAsync, EventId=2, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000025, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync |

Other streams which waited for response just failed:

2024-08-20 01:32:00.6346 | Info | Error reading message. | EventId=14, EventName=ErrorReadingMessage, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000003, RequestPath=/ICommunicationService/OpenInfrastructureDuplexStream | System.IO.IOException: The request stream was aborted.
 ---> Microsoft.AspNetCore.Connections.ConnectionAbortedException: The HTTP/2 connection faulted.
   --- End of inner exception stack trace ---
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2MessageBody.ReadAsync(CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
   at Grpc.AspNetCore.Server.Internal.PipeExtensions.ReadStreamMessageAsync[T](PipeReader input, HttpContextServerCallContext serverCallContext, Func`2 deserializer, CancellationToken cancellationToken)
2024-08-20 01:32:00.6346 | Info | Error reading message. | EventId=14, EventName=ErrorReadingMessage, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000009, RequestPath=/ICompensationControlService/OpenInfrastructureDuplexStream | System.IO.IOException: The request stream was aborted.
 ---> Microsoft.AspNetCore.Connections.ConnectionAbortedException: The HTTP/2 connection faulted.
   --- End of inner exception stack trace ---
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2MessageBody.ReadAsync(CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
   at Grpc.AspNetCore.Server.Internal.PipeExtensions.ReadStreamMessageAsync[T](PipeReader input, HttpContextServerCallContext serverCallContext, Func`2 deserializer, CancellationToken cancellationToken)
2024-08-20 01:32:00.6346 | Info | Error reading message. | EventId=14, EventName=ErrorReadingMessage, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:00000005, RequestPath=/ICommunicationService/Meta_OpenClientPulseStreaming | System.IO.IOException: The request stream was aborted.
 ---> Microsoft.AspNetCore.Connections.ConnectionAbortedException: The HTTP/2 connection faulted.
   --- End of inner exception stack trace ---
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2MessageBody.ReadAsync(CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
   at Grpc.AspNetCore.Server.Internal.PipeExtensions.ReadStreamMessageAsync[T](PipeReader input, HttpContextServerCallContext serverCallContext, Func`2 deserializer, CancellationToken cancellationToken)
2024-08-20 01:32:00.6346 | Info | Error reading message. | EventId=14, EventName=ErrorReadingMessage, ConnectionId=0HN60ROQ2A0RV, RequestId=0HN60ROQ2A0RV:0000000B, RequestPath=/IScanningControlService/OpenInfrastructureDuplexStream | System.IO.IOException: The request stream was aborted.
 ---> Microsoft.AspNetCore.Connections.ConnectionAbortedException: The HTTP/2 connection faulted.
   --- End of inner exception stack trace ---
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2MessageBody.ReadAsync(CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
   at Grpc.AspNetCore.Server.Internal.PipeExtensions.ReadStreamMessageAsync[T](PipeReader input, HttpContextServerCallContext serverCallContext, Func`2 deserializer, CancellationToken cancellationToken)
mayuki commented 3 weeks ago

Sorry, I have not been able to reproduce this.

[ReqSeq:19] Response completed with failure (error reading a body from connection) (0x0)

The error message in the log says “error reading a body from connection”. This is most likely due to the network connection being disconnected for some reason.

[ReqSeq:2] Response completed with failure (client error (SendRequest): http2 error) (0x0)

On the other hand, the error message ”client error (SendRequest): http2 error" is an error that is output when sending a request and before receiving a response.

I'm sorry, but at this point I cannot say for certain whether this is due to the network connection being disconnected or a library bug.

VladimirRudt commented 3 weeks ago

@mayuki Seems the reason is exactly bad connection. I could easily reproduce an issue simply turning off the server during streaming. After that I cought RpcException with Unavailable status.

The only one question, why Unity logger writes inner exception instead of original one.

What I see in during debug:

image

What Debug.LogException writes:

image