Server-side streaming is not cancelled

[VladimirRudt]

Hey @mayuki

We encountered another issue after updating YetAnotherHttpHandler. Unity-side Cancellation token doesn't cancel server stream.

This is a client-side code:

private static async UniTask RunPreviewUpdateLoopAsync(
    ServerStreamingResult<CameraPreview> streamReader,
    StreamingThreadState streamingState,
    CancellationToken stoppingToken)
{
    try
    {
        while (await streamReader.ResponseStream.MoveNext(stoppingToken))
        {
            streamingState.PreviewBuffer.SaveFrame(streamReader.ResponseStream.Current.PreviewImage);
        }
    }
    catch (RpcException exception) when (exception.Status.StatusCode == StatusCode.Cancelled)
    {
        streamingState.Complete();
    }
    catch (Exception exception)
    {
        streamingState.Fail(exception);
    }
    finally
    {
        streamReader.Dispose();
    }
}

And a server-side code of streaming:

public async Task<ServerStreamingResult<CameraPreview>> Settings_StreamCameraPreviewAsync(CameraPreviewParametersDto previewParametersDto)
{
    var serverStream = GetServerStreamingContext<CameraPreview>();

    var cameraPreviewRequest = new StreamCameraPreviewQuery(previewParametersDto);
    var cameraPreviewStream = mediator.CreateStream(cameraPreviewRequest, Context.CallContext.CancellationToken);
    await foreach (var cameraPreview in cameraPreviewStream)
    {
        await serverStream.WriteAsync(cameraPreview);
    }

    return serverStream.Result();
}

Previously, if we cancelled stoppingToken during MoveNext execution, the server's Context.CallContext.CancellationToken token would also be cancelled. But this no longer happens.

Is this a bug? Or should we use a different approach now?

Attaching unity-side logs with enabled YAHA_ENABLE_DEBUG_TRACING

server-stream-is-not-cancelled.txt

[mayuki]

Sorry, the following minimum code could not be reproduced.

// Client-side
var a = await this.client.ServerStreaming();

var cancellationTokenSource = new CancellationTokenSource(TimeSpan.FromSeconds(3));
while (await a.ResponseStream.MoveNext(cancellationTokenSource.Token))
{

}

// Server-side
public async Task<ServerStreamingResult<string>> ServerStreaming()
{
    var s = GetServerStreamingContext<string>();

    while (!s.ServiceContext.CallContext.CancellationToken.IsCancellationRequested)
    {
        await s.WriteAsync("Hello");
    }

    return s.Result();
}

Have you specified options such as YetAnotherHttpHandler?

[VladimirRudt]

@mayuki Yes, I have. This is code of GrpcChannel and YetAnotherHttpHandler initializaztion:

var sslCredentials = new SslCredentials(certificate);

var httpHandler = new YetAnotherHttpHandler
{
    Http2KeepAliveTimeout = TimeSpan.FromMilliseconds(KeepAliveTimeoutMilliseconds),
    Http2KeepAliveInterval = TimeSpan.FromMilliseconds(KeepAliveMilliseconds),
    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,
});

I'm not sure if this is related somehow, but when we open this server stream, we already have 3 duplex streams open in parallel.

[mayuki]

Thank you for the additional information.

When you normally cancel, the following log is output, but is it also output in your environment? (It seems that the log I received before was cut off in the middle.)

Also, in the ASP.NET Core log, is the request complete? For example, if the request is complete, the following log should be output.

info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'gRPC - /IChatService/ServerStreaming'
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/2 POST http://localhost:5000/IChatService/ServerStreaming - 200 - application/grpc 9737.5187ms

[VladimirRudt]

@mayuki This is what I see in log related to request

And I also don't see cancellation on the server side.

2024-08-02 13:55:28.6105 | Info | Request starting HTTP/2 POST https://172.17.0.1:7084/ICommunicationService/Settings_StreamCameraPreviewAsync - application/grpc - | Protocol=HTTP/2, Method=POST, ContentType=application/grpc, Scheme=https, Host=172.17.0.1:7084, Path=/ICommunicationService/Settings_StreamCameraPreviewAsync, EventId=1, ConnectionId=0HN5IO07HIVC0, RequestId=0HN5IO07HIVC0:00000021, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-02 13:55:28.6105 | Debug | 3 candidate(s) found for the request path '/ICommunicationService/Settings_StreamCameraPreviewAsync' | CandidateCount=3, Path=/ICommunicationService/Settings_StreamCameraPreviewAsync, EventId=1001, EventName=CandidatesFound, ConnectionId=0HN5IO07HIVC0, RequestId=0HN5IO07HIVC0:00000021, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-02 13:55:28.6105 | 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=0HN5IO07HIVC0, RequestId=0HN5IO07HIVC0:00000021, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-02 13:55:28.6105 | 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=0HN5IO07HIVC0, RequestId=0HN5IO07HIVC0:00000021, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-02 13:55:28.6105 | 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=0HN5IO07HIVC0, RequestId=0HN5IO07HIVC0:00000021, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-02 13:55:28.6105 | Debug | Request matched endpoint 'gRPC - /ICommunicationService/Settings_StreamCameraPreviewAsync' | EndpointName=gRPC - /ICommunicationService/Settings_StreamCameraPreviewAsync, EventId=1, EventName=MatchSuccess, ConnectionId=0HN5IO07HIVC0, RequestId=0HN5IO07HIVC0:00000021, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-02 13:55:28.6105 | Info | Executing endpoint 'gRPC - /ICommunicationService/Settings_StreamCameraPreviewAsync' | EndpointName=gRPC - /ICommunicationService/Settings_StreamCameraPreviewAsync, ConnectionId=0HN5IO07HIVC0, RequestId=0HN5IO07HIVC0:00000021, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-02 13:55:28.6105 | Debug | Reading message. | EventId=10, EventName=ReadingMessage, ConnectionId=0HN5IO07HIVC0, RequestId=0HN5IO07HIVC0:00000021, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-02 13:55:28.6105 | Debug | Connection id "0HN5IO07HIVC0", Request id "0HN5IO07HIVC0:00000021": started reading request body. | ConnectionId=0HN5IO07HIVC0, TraceIdentifier=0HN5IO07HIVC0:00000021, EventId=25, EventName=RequestBodyStart, ConnectionId=0HN5IO07HIVC0, RequestId=0HN5IO07HIVC0:00000021, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-02 13:55:28.6105 | Debug | Connection id "0HN5IO07HIVC0", Request id "0HN5IO07HIVC0:00000021": done reading request body. | ConnectionId=0HN5IO07HIVC0, TraceIdentifier=0HN5IO07HIVC0:00000021, EventId=26, EventName=RequestBodyDone, ConnectionId=0HN5IO07HIVC0, RequestId=0HN5IO07HIVC0:00000021, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 
2024-08-02 13:55:28.6281 | Debug | BeginInvokeMethod type:ServerStreaming method:/ICommunicationService/Settings_StreamCameraPreviewAsync | methodType=ServerStreaming, method=/ICommunicationService/Settings_StreamCameraPreviewAsync, EventId=3, EventName=BeginInvokeMethod, ConnectionId=0HN5IO07HIVC0, RequestId=0HN5IO07HIVC0:00000021, RequestPath=/ICommunicationService/Settings_StreamCameraPreviewAsync | 

And I see this if I turn off the server

Additionally, we listen to this stream on a thread from thread pool. Not on the main thread. Maybe this can be useful.

[mayuki]

Thank you very much. I have found that it is rarely reproduced in my environment. I will continue to investigate this in detail.

[mayuki]

We have released 1.5.1, which fixes the problem. Please try this version.