Integration-Test with grpc server does cancel streamed requests.

[buehler]

Dear grpc dotnet team.

I'm currently using aspnet.grpc with .net core 3.1 and I did catch some strange behaviour.

When using the testing framework of asp.net core to create integration tests, any call that uses serverside or client side streams is cancelled instead of correctly resolved.

Funny enough, when running the tests locally on the developer workstation it does run as intended and when running the tests on ci in docker build, they fail and are cancelled.

Parallel testing is disabled and everything should run serial.

An example of such a test is:

[Fact(Skip = "Does not work on ci.")]
public async Task Throws_On_Deleted_File()
{
    var file = await UploadFile();
    await Client.DeleteAsync(new DeleteRequest { Id = file.Id });
    var ex = await Assert.ThrowsAsync<RpcException>(
        async () =>
        {
            using var call = Client.Replace();
            await call.RequestStream.WriteAsync(
                new ReplaceRequest
                {
                    Metadata = new ReplaceMetadata
                    {
                        FileId = file.Id,
                        TotalSize = 42,
                    },
                });
            await call.RequestStream.CompleteAsync();
            await call.ResponseAsync;
        });
    ex.Status.StatusCode.Should().Be(StatusCode.NotFound);
}

This test is intended for a storage system that has file information. Now when a file is deleted, obviously the correct RpcException would be NotFound. But on CI the result is an RpcException with Cancelled. It's the horror to debug since it does work as intended locally and the debugger does step to the correct elements.

Do you guys have any idea what could go sideways with those calls? Or something that I need to change?

Regards
Chris

[JunTaoLuo]

Logging would help here, please try the instructions at https://docs.microsoft.com/en-us/aspnet/core/grpc/diagnostics?view=aspnetcore-3.1#grpc-client-logging.

[buehler]

Alright, here are the logs:

Locally (which works):

Starting test execution, please wait...

A total of 1 test files matched the specified pattern.

[xUnit.net 00:00:01.15]     Dok.Store.Test.GrpcServices.FileService.UploadFileTest.Throws_When_First_Chunk_Doesnt_Contain_Metadata [FAIL]

  X Dok.Store.Test.GrpcServices.FileService.UploadFileTest.Throws_When_First_Chunk_Doesnt_Contain_Metadata [488ms]
  Error Message:
   Grpc.Core.RpcException : Status(StatusCode=FailedPrecondition, Detail="Invalid first chunk / metadata.")
  Stack Trace:
     at Dok.Store.Test.GrpcServices.FileService.UploadFileTest.Throws_When_First_Chunk_Doesnt_Contain_Metadata() in C:\Users\Christoph\Documents\Development\customers\abraxas\abraxas-dokumente\dok-store\dok-store\tests\Dok.Store.Test\GrpcServices\FileService\UploadFile.Test.cs:line 46
--- End of stack trace from previous location where exception was thrown ---
  Standard Output Messages:
 Grpc.Net.Client.Internal.GrpcCall [StartingCall] Starting gRPC call. Method type: 'ClientStreaming', URI: 'http://localhost:39743/dok.store.file.FileService/Upload'.
 Grpc.Net.Client.Internal.GrpcCall [SendingMessage] Sending message.
 Grpc.Net.Client.Internal.GrpcCall [SerializedMessage] Serialized 'Dok.Store.File.UploadRequest' to 0 byte message.
 Grpc.Net.Client.Internal.GrpcCall [MessageSent] Message sent.
 Grpc.Net.Client.Internal.HttpContentClientStreamWriter [CompletingClientStream] Completing client stream.
 Grpc.Net.Client.Internal.GrpcCall [ResponseHeadersReceived] Response headers received.
 Grpc.Net.Client.Internal.GrpcCall [GrpcStatusError] Call failed with gRPC error status. Status code: 'FailedPrecondition', Message: 'Invalid first chunk / metadata.'.
 Grpc.Net.Client.Internal.GrpcCall [FinishedCall] Finished gRPC call.

(I did rethrow the exception on purpose to see the log output)
Expected is the Invalid first chunk exception.

Now on the ci pipeline the following happens:

3195 [xUnit.net 00:00:08.08]     Dok.Store.Test.GrpcServices.FileService.ReplaceFileTest.Throws_When_First_Chunk_Doesnt_Contain_Metadata [FAIL]
3196 dbug: Grpc.Net.Client.Internal.GrpcCall[1]
3197       Starting gRPC call. Method type: 'ClientStreaming', URI: 'http://localhost:33881/dok.store.file.FileService/Replace'.
3198 dbug: Grpc.Net.Client.Internal.GrpcCall[18]
3199       Sending message.
3200 trce: Grpc.Net.Client.Internal.GrpcCall[2]
3201       Response headers received.
3202 trce: Grpc.Net.Client.Internal.GrpcCall[21]
3203       Serialized 'Dok.Store.File.ReplaceRequest' to 51 byte message.
3204 fail: Grpc.Net.Client.Internal.GrpcCall[3]
3205       Call failed with gRPC error status. Status code: 'FailedPrecondition', Message: 'Invalid first chunk / metadata.'.
3206 dbug: Grpc.Net.Client.Internal.GrpcCall[4]
3207       Finished gRPC call.
3208 fail: Grpc.Net.Client.Internal.GrpcCall[20]
3209       Error sending message.
3210 System.OperationCanceledException: Flush was canceled on underlying PipeWriter.
3211    at System.IO.Pipelines.ThrowHelper.ThrowOperationCanceledException_FlushCanceled()
3212    at System.IO.Pipelines.PipeWriterStream.GetFlushResultAsTask(ValueTask`1 valueTask)
3213    at System.IO.Pipelines.PipeWriterStream.FlushAsync(CancellationToken cancellationToken)
3214    at Grpc.Net.Client.StreamExtensions.WriteMessageAsync[TMessage](Stream stream, ILogger logger, TMessage message, Action`2 serializer, String grpcEncoding, Nullable`1 maximumMessageSize, Dictionary`2 compressionProviders, CallOptions callOptions)
3215 dbug: Grpc.Net.Client.Internal.GrpcCall[8]
3216       gRPC call canceled.

As it seems, there is something happening with the System.IO.Pipe that is used to forward the chunks that are received.

The code that processes the stream is the following:

        private async Task<StoredFile> ProcessStream<TChunk>(
            StoredFile file,
            Func<TChunk, byte[]?> processChunk,
            IAsyncStreamReader<TChunk> dataStream)
        {
            var pipe = new Pipe();
            var uploadTask = _s3Storage.UploadFile(file.Id, file.Size, pipe.Reader.AsStream());

            await foreach (var chunk in dataStream.ReadAllAsync())
            {
                var data = processChunk(chunk);
                if (data == null)
                {
                    continue;
                }

                if (string.IsNullOrWhiteSpace(file.MimeType))
                {
                    file.MimeType = _interrogator.DetectType(data)?.MimeType ?? DefaultMimeType;
                    _logger.LogTrace($"Set file-type to {file.MimeType}.");
                }

                _logger.LogTrace($"Upload chunk for file {file.Id} with {data.Length} bytes.");
                await pipe.Writer.WriteAsync(new ReadOnlyMemory<byte>(data));
            }

            await Task.WhenAll(pipe.Writer.CompleteAsync().AsTask(), uploadTask);
            _logger.LogDebug(
                $"Upload completed for file {file.Id} with mime type '{file.MimeType}' and size {file.Size}");

            return file;
        }

Is this, because we don't check for the cancellation (in the await foreach) or is it in the underlaying grpc methods?

[JunTaoLuo]

Ah I think this is a bug we recently fixed: #723. Please try the next release or a nightly build: https://github.com/grpc/grpc-dotnet#grpc-nuget-feed

[JunTaoLuo]

Were you able to try the nightly packages @buehler ?

[buehler]

Not until today... Going to test it and give you feedback @JunTaoLuo

[JamesNK]

You don't need to use a nightly build. 2.27.0 on NuGet contains that fix.

[buehler]

I upgraded everything to 2.27.0 and sadly, the same problem persists:

Expected ex.Status.StatusCode to be InvalidArgument, but found Cancelled.

This seems to be cancelled before the status is returned.

Do you need additional logs ? cc @JamesNK cc @JunTaoLuo

[JamesNK]

I'm pretty sure the problem is that the test server doesn't handle a request that is streaming content to the server, and your call uses client streaming.

There is a bugfix in 3.1.2 for this. I have added tests for server errors to this test PR - #668.

You could try updating to 3.1 and referencing 3.1.2 of Microsoft.AspNetCore.TestHost. You'll need to get it from a preview feed that you can see in the PR.

Alternatively you can wait a week or two until 3.1.2 is released publically.

[buehler]

Alright, it is already 3.1, so I'm waiting for 3.1.2.

I'll give you guys feedback as soon as I can.

Thanks for the help

[analogrelay]

This is fixed in 3.1.2 which should be released now!

[buehler]

@anurse Let me check...

[buehler]

Nice, it seems to be working. Thanks to all participants!
Regards