"Call failed with gRPC error status. Status code: 'Cancelled', Message: '"gRPC call disposed."" in client logs.

[lakshdeepsingheventstore]

Client logs show the following error: "Call failed with gRPC error status. Status code: 'Cancelled', Message: '"gRPC call disposed."" It is generally caused when the gRPC channel gets closed without the call being ended.

[oskardudycz]

@lakshdeepsingheventstore, as the logs are on the client, I transferred it to the .NET gRPC client repository.

[stoepa]

I just want to add to this as well.

We are getting the same behaviour on our side. We are running a catchup sub within a IHostedService, once the service is terminated or asked to shutdown gracefully. This pops up in the log, and causes the system to hang for about 30 seconds, before it is fully removed.

It can be hard terminated, but the container where it is running in then throws other non-related exceptions.

Here is a partial log.

[2022-03-10 22:34:45+00:00] [Information] Application is shutting down... [2022-03-10 22:34:45+00:00] [Information] Process worker stopped [2022-03-10 22:34:45+00:00] [Information] Call failed with gRPC error status. Status code: 'Cancelled', Message: 'gRPC call disposed.'. [2022-03-10 22:34:45+00:00] [Error] Subscription was dropped because an error occurred on the server. at EventStore.Client.Interceptors.TypedExceptionInterceptor.AsyncStreamReader1.MoveNext(CancellationToken cancellationToken) at Grpc.Core.AsyncStreamReaderExtensions.ReadAllAsyncCore[T](IAsyncStreamReader1 streamReader, CancellationToken cancellationToken)+MoveNext() at Grpc.Core.AsyncStreamReaderExtensions.ReadAllAsyncCore[T](IAsyncStreamReader1 streamReader, CancellationToken cancellationToken)+System.Threading.Tasks.Sources.IValueTaskSource<System.Boolean>.GetResult() at System.Linq.AsyncEnumerable.SelectEnumerableAsyncIterator2.MoveNextCore() in //Ix.NET/Source/System.Linq.Async/System/Linq/Operators/Select.cs:line 199 at System.Linq.AsyncIteratorBase`1.MoveNextAsync() in //Ix.NET/Source/System.Linq.Async/System/Linq/AsyncIterator.cs:line 70 at System.Linq.AsyncIteratorBase1.MoveNextAsync() in /_/Ix.NET/Source/System.Linq.Async/System/Linq/AsyncIterator.cs:line 75 at EventStore.Client.EventStoreClient.ReadInternal(ReadReq request, EventStoreClientOperationOptions operationOptions, UserCredentials userCredentials, CancellationToken cancellationToken)+MoveNext() at EventStore.Client.EventStoreClient.ReadInternal(ReadReq request, EventStoreClientOperationOptions operationOptions, UserCredentials userCredentials, CancellationToken cancellationToken)+MoveNext() at EventStore.Client.EventStoreClient.ReadInternal(ReadReq request, EventStoreClientOperationOptions operationOptions, UserCredentials userCredentials, CancellationToken cancellationToken)+System.Threading.Tasks.Sources.IValueTaskSource<System.Boolean>.GetResult() at EventStore.Client.StreamSubscription.Enumerable.Enumerator.MoveNextAsync() at EventStore.Client.StreamSubscription.Subscribe() at EventStore.Client.StreamSubscription.Subscribe() [2022-03-10 22:34:45+00:00] [Error] Subscription to all 'f155e439-9905-4314-a416-b2c1b8634fc0' dropped with 'ServerError' at EventStore.Client.Interceptors.TypedExceptionInterceptor.AsyncStreamReader1.MoveNext(CancellationToken cancellationToken) at Grpc.Core.AsyncStreamReaderExtensions.ReadAllAsyncCore[T](IAsyncStreamReader1 streamReader, CancellationToken cancellationToken)+MoveNext() at Grpc.Core.AsyncStreamReaderExtensions.ReadAllAsyncCore[T](IAsyncStreamReader1 streamReader, CancellationToken cancellationToken)+System.Threading.Tasks.Sources.IValueTaskSource.GetResult() at System.Linq.AsyncEnumerable.SelectEnumerableAsyncIterator2.MoveNextCore() in /_/Ix.NET/Source/System.Linq.Async/System/Linq/Operators/Select.cs:line 199 at System.Linq.AsyncIteratorBase1.MoveNextAsync() in //Ix.NET/Source/System.Linq.Async/System/Linq/AsyncIterator.cs:line 70 at System.Linq.AsyncIteratorBase`1.MoveNextAsync() in //Ix.NET/Source/System.Linq.Async/System/Linq/AsyncIterator.cs:line 75 at EventStore.Client.EventStoreClient.ReadInternal(ReadReq request, EventStoreClientOperationOptions operationOptions, UserCredentials userCredentials, CancellationToken cancellationToken)+MoveNext() at EventStore.Client.EventStoreClient.ReadInternal(ReadReq request, EventStoreClientOperationOptions operationOptions, UserCredentials userCredentials, CancellationToken cancellationToken)+MoveNext() at EventStore.Client.EventStoreClient.ReadInternal(ReadReq request, EventStoreClientOperationOptions operationOptions, UserCredentials userCredentials, CancellationToken cancellationToken)+System.Threading.Tasks.Sources.IValueTaskSource.GetResult() at EventStore.Client.StreamSubscription.Enumerable.Enumerator.MoveNextAsync() at EventStore.Client.StreamSubscription.Subscribe() at EventStore.Client.StreamSubscription.Subscribe() [2022-03-10 22:35:03+00:00] [Information] Process worker started

[stoepa]

I also think we are getting the wrong reason code, as pointed out in #154 . We are closing the application, so should be getting the disposed but we are actually getting a ServerError.

I will have a look tomorrow to see if I can maybe create a pull request for the correct DroppedReason

Still not sure if that would resolve the Call failed with gRPC error status. Status code: 'Cancelled', Message: 'gRPC call disposed.'.

Maybe if the log was changed from Error to Information. Will let you guys know what I find.

[stoepa]

Just looking over the code, I might be missing something here.

In StreamSubscription.cs I see the following:

private async Task Subscribe() {
            _log.LogDebug("Subscription {subscriptionId} confirmed.", SubscriptionId);
            using var _ = _disposed;
            try {
                await foreach (var resolvedEvent in _events.ConfigureAwait(false)) {
                    try {
                        _log.LogTrace("Subscription {subscriptionId} received event {streamName}@{streamRevision} {position}",
                            SubscriptionId, resolvedEvent.OriginalEvent.EventStreamId,
                            resolvedEvent.OriginalEvent.EventNumber, resolvedEvent.OriginalEvent.Position);
                        await _eventAppeared(this, resolvedEvent, _disposed.Token).ConfigureAwait(false);
                    } catch (Exception ex) when (ex is ObjectDisposedException or OperationCanceledException) {
                        if (_subscriptionDroppedInvoked != 0) {
                            return;
                        }
                        _log.LogWarning(ex,
                            "Subscription {subscriptionId} was dropped because cancellation was requested by another caller.",
                            SubscriptionId);

                        SubscriptionDropped(SubscriptionDroppedReason.Disposed);

                        return;
                    } catch (Exception ex) {

I have looked at _subscriptionDroppedInvoked and can't see that it ever changes

There is this method:

private void SubscriptionDropped(SubscriptionDroppedReason reason, Exception? ex = null) {
            if (Interlocked.CompareExchange(ref _subscriptionDroppedInvoked, 1, 0) == 1) {
                return;
            }

            try {
                _subscriptionDropped?.Invoke(this, reason, ex);
            } finally {
                _disposed.Dispose();
            }
        }

But as stated can't see if it is ever change, so will always return in the first block.

Seems like the gRPC socket is also not disposed properly, but cannot verify as of yet.

[alexeyzimarev]

Closing as duplicate of #154