search

grpc / grpc-dotnet

gRPC for .NET
Apache License 2.0
4.17k stars 768 forks source link

`HttpRequestException` repeated 3 times results in endless `Error connecting to subchannel` #2454

Open kolonist opened 4 months ago

kolonist commented 4 months ago

Hi, @JamesNK

Moved this issue from another thread as you said.

We got endless Error connecting to subchannel expeptions after HttpRequestException repeated 3 times.

At first we catched this problem after SSL Error when we used wrong certificate so we thought that the problem is just wrong message and there is nothing to worry about.

But recently we got exactly the same error after this exception:

Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="Error starting gRPC call. HttpRequestException: An error occurred while sending the request. IOException: The request was aborted. IOException: Unable to read data from the transport connection: Connection reset by peer. SocketException: Connection reset by peer", DebugException="System.Net.Http.HttpRequestException: An error occurred while sending the request.")

It was temporary error while we restarted target GRPC-service. This exception expected to be stoped after a second or so, but it not only didn't stopp but it started to fail all requests with Error connecting to subchannel exceptions which stopped only after our application restarted.

So I believe that HttpRequestException repeated several times (3 times in reproduction below) results in subchannel poisoning.

We use grpc-dotnet, branch v2.63.x.

Reproduction:

We use GRPC to connect to third-party server written in Go programming language (if it is important) with TLS certificates to authenticate.

Code used to authenticate:

.ConfigureChannel((provider, options) =>
{
    // very simple factory with very simple resolver
    ResolverFactory factory = provider.GetRequiredService<MyResolverFactory>();

    var grpcServices = new ServiceCollection();
    grpcServices.AddSingleton(factory);

    options.ServiceProvider = grpcServices.BuildServiceProvider();

    options.Credentials = ChannelCredentials.SecureSsl;

    options.ServiceConfig = new ServiceConfig
    {
        LoadBalancingConfigs = { new RoundRobinConfig() },
        MethodConfigs = {
            new MethodConfig
            {
                RetryPolicy = new RetryPolicy
                {
                    MaxAttempts = ...,
                    RetryableStatusCodes =
                    {
                        StatusCode.Aborted,
                        StatusCode.DeadlineExceeded,
                        StatusCode.ResourceExhausted,
                        StatusCode.Unavailable
                    }
                }
            }
        }
    };
})
.ConfigurePrimaryHttpMessageHandler(serviceProvider =>
{
    var socketsHandler = new SocketsHttpHandler
    {
        ConnectTimeout = ...,
        PooledConnectionIdleTimeout = ...,
        KeepAlivePingDelay = ...,
        KeepAlivePingTimeout = ...,
        EnableMultipleHttp2Connections = true
    };

    var clientX509Certificate = X509Certificate2.CreateFromPem(ClientCert, ClientKey);

    var clientX509CertificatesCollection = new X509CertificateCollection(
        new X509Certificate[]
        {
            clientX509Certificate
        });

    socketsHandler.SslOptions.ClientCertificates = clientX509CertificatesCollection;

    var certificatesChain = ParseCertificates(certificates.CaCertChain);

    socketsHandler.SslOptions.RemoteCertificateValidationCallback = CreateCertificateValidator(certificatesChain);

    return socketsHandler;
});

...
private static RemoteCertificateValidationCallback CreateCertificateValidator(X509Certificate2[] ca)
{
    return (_, cert, chain, _) =>
    {
        if (chain is null || cert is null)
        {
            return false;
        }

        chain.ChainPolicy.TrustMode = X509ChainTrustMode.CustomRootTrust;
        chain.ChainPolicy.CustomTrustStore.AddRange(ca);
        return chain.Build(new X509Certificate2(cert));
    };
}

I use this simple code to reproduce this issue:

var client = host.Services.GetRequiredService<3rdPartyService.3rdPartyServiceClient>();

for (var i = 0; i < 200; i++)
{
    try
    {
        logger.LogWarning("##### START LOOP");

        var request = new 3rdPartyServiceRequest
        {
            SomeFieldName = ByteString.CopyFrom("lllllllll", Encoding.UTF8)
        };

        logger.LogWarning("##### BEFORE Unary call");

        var response = await client.3rdPartyServicePerformRequestAsync(request);

        logger.LogWarning("##### Response: {Response}", response.SomeResponceFieldName.ToString());
    }
    catch (Exception ex)
    {
        logger.LogError(ex, "##### SOME ERROR");
    }
    finally
    {
        logger.LogWarning("##### BEFORE Delay");
        // await Task.Delay(1 * 1000);
        logger.LogWarning("##### END LOOP");
    }
}

To reproduce the issue we need to specify well-formed TLS-certificate but without proper permissions (there were some cases when we used invalid certificates and got the same issue but we can't reproduce it now). For this example I took only one endpoint in balancing, but if I have more then I get the same result for every endpoint.

Log is as foollows:

...
# application logs, nothing useful
...

[13:41:56 DBG ]  Starting gRPC call. Method type: 'Unary', URI: 'https://loadbalancer.temporary.invalid/3rdpartynspace.3rdPartyService/3rdPartyServicePerformRequest'.
[13:41:56 VRB ]  Starting deadline timeout. Duration: 00:00:29.9928750.
[13:41:56 VRB ]  MyResolver refresh requested.
[13:41:56 WRN ]  ##### START LOOP
[13:41:56 WRN ]  ##### BEFORE Unary call
[13:41:56 DBG ]  Starting gRPC call. Method type: 'Unary', URI: 'https://loadbalancer.temporary.invalid/3rdpartynspace.3rdPartyService/3rdPartyServicePerformRequest'.
[13:41:56 VRB ]  MyResolver result with status code 'OK' and 1 addresses.
[13:41:56 DBG ]  Subchannel id '3-1' created with addresses: service-endpoint.zone:2379

# it's from `SocketConnectivitySubchannelTransport.cs`, constructor, after all initialization
[13:41:56 WRN ]  ##### SocketConnectivitySubchannelTransport Created

[13:41:56 VRB ]  Subchannel id '3-1' state changed registration '3-1-1' created.
[13:41:56 VRB ]  Subchannel id '3-1' connection requested.
[13:41:56 DBG ]  Subchannel id '3-1' state changed to Connecting. Detail: 'Connection requested.'.
[13:41:56 VRB ]  Subchannel id '3-1' executing state changed registration '3-1-1'.
[13:41:56 VRB ]  Processing subchannel id '3-1' state changed to Connecting. Detail: 'Connection requested.'.
[13:41:56 DBG ]  Channel state updated to Connecting.
[13:41:56 DBG ]  Channel picker updated.
[13:41:56 VRB ]  MyResolver resolve task completed.
[13:41:56 VRB ]  Pick started.
[13:41:56 DBG ]  Picked queued.
[13:41:56 VRB ]  Waiting for a new picker.
[13:41:56 VRB ]  Pick started.
[13:41:56 DBG ]  Picked queued.
[13:41:56 VRB ]  Waiting for a new picker.
[13:41:56 VRB ]  Subchannel id '3-1' connecting to transport.

# it's from `SocketConnectivitySubchannelTransport.cs`, `TryConnectAsync()`, first line of the method
[13:41:56 WRN ]  ##### TryConnectAsync context.CancellationToken.IsCancellationRequested = False

[13:41:56 VRB ]  Subchannel id '3-1' connecting socket to service-endpoint.zone:2379.
[13:41:56 DBG ]  Subchannel id '3-1' connected to socket service-endpoint.zone:2379.
[13:41:56 DBG ]  Subchannel id '3-1' state changed to Ready. Detail: 'Successfully connected to socket.'.
[13:41:56 VRB ]  Subchannel id '3-1' executing state changed registration '3-1-1'.
[13:41:56 VRB ]  Processing subchannel id '3-1' state changed to Ready. Detail: 'Successfully connected to socket.'.
[13:41:56 VRB ]  Creating ready picker with 1 subchannels: id '3-1' (service-endpoint.zone:2379)
[13:41:56 DBG ]  Channel state updated to Ready.
[13:41:56 DBG ]  Channel picker updated.
[13:41:56 VRB ]  Pick started.
[13:41:56 VRB ]  Pick started.
[13:41:56 DBG ]  Successfully picked subchannel id '3-1' with address service-endpoint.zone:2379. Transport status: InitialSocket
[13:41:56 VRB ]  Sending request https://service-endpoint.zone:2379/3rdpartynspace.3rdPartyService/3rdPartyServicePerformRequest.
[13:41:56 DBG ]  Successfully picked subchannel id '3-1' with address service-endpoint.zone:2379. Transport status: InitialSocket
[13:41:56 VRB ]  Sending request https://service-endpoint.zone:2379/3rdpartynspace.3rdPartyService/3rdPartyServicePerformRequest.
[13:41:56 VRB ]  Starting connect callback for service-endpoint.zone:2379.
[13:41:56 VRB ]  Subchannel id '3-1' creating stream for service-endpoint.zone:2379.
[13:41:56 VRB ]  Subchannel id '3-1' checking socket service-endpoint.zone:2379.
[13:41:56 VRB ]  Subchannel id '3-1' created stream for service-endpoint.zone:2379 with 0 buffered bytes. Transport has 1 active streams.
[13:41:57 VRB ]  Subchannel id '3-1' disposing stream for service-endpoint.zone:2379. Transport has 0 active streams.
[13:41:57 DBG ]  Subchannel id '3-1' state changed to Idle. Detail: 'Disconnected.'.
[13:41:57 VRB ]  Subchannel id '3-1' executing state changed registration '3-1-1'.
[13:41:57 VRB ]  Processing subchannel id '3-1' state changed to Idle. Detail: 'Disconnected.'.
[13:41:57 DBG ]  Channel state updated to Connecting.
[13:41:57 DBG ]  Channel picker updated.
[13:41:57 VRB ]  Refreshing resolver because subchannel id '3-1' is in state Idle.
[13:41:57 VRB ]  MyResolver refresh requested.
[13:41:57 VRB ]  Requesting connection for subchannel id '3-1' because it is in state Idle.
[13:41:57 VRB ]  Subchannel id '3-1' connection requested.
[13:41:57 DBG ]  Subchannel id '3-1' state changed to Connecting. Detail: 'Connection requested.'.
[13:41:57 VRB ]  Subchannel id '3-1' executing state changed registration '3-1-1'.
[13:41:57 VRB ]  Processing subchannel id '3-1' state changed to Connecting. Detail: 'Connection requested.'.
[13:41:57 VRB ]  Starting connect callback for service-endpoint.zone:2379.
[13:41:57 VRB ]  Subchannel id '3-1' creating stream for service-endpoint.zone:2379.
[13:41:57 VRB ]  Subchannel id '3-1' doesn't have a connected socket available. Connecting new stream socket for service-endpoint.zone:2379.
[13:41:57 VRB ]  MyResolver result with status code 'OK' and 1 addresses.
[13:41:57 VRB ]  Subchannel id '3-1' matches address 'service-endpoint.zone:2379' and is preserved.
[13:41:57 VRB ]  Connections unchanged.
[13:41:57 VRB ]  MyResolver result with status code 'OK' and 1 addresses.
[13:41:57 VRB ]  Subchannel id '3-1' updated with addresses: service-endpoint.zone:2379
[13:41:57 DBG ]  Subchannel id '3-1' is connecting when its addresses are updated. Restarting connect.
[13:41:57 DBG ]  Subchannel id '3-1' state changed to Idle. Detail: 'Disconnected.'.
[13:41:57 VRB ]  Subchannel id '3-1' executing state changed registration '3-1-1'.
[13:41:57 VRB ]  Processing subchannel id '3-1' state changed to Idle. Detail: 'Disconnected.'.
[13:41:57 VRB ]  Refreshing resolver because subchannel id '3-1' is in state Idle.
[13:41:57 VRB ]  MyResolver refresh requested.
[13:41:57 VRB ]  MyResolver refresh ignored because resolve is already in progress.
[13:41:57 VRB ]  Requesting connection for subchannel id '3-1' because it is in state Idle.
[13:41:57 VRB ]  Subchannel id '3-1' connection requested.
[13:41:57 DBG ]  Subchannel id '3-1' state changed to Connecting. Detail: 'Connection requested.'.
[13:41:57 VRB ]  Subchannel id '3-1' executing state changed registration '3-1-1'.
[13:41:57 VRB ]  Processing subchannel id '3-1' state changed to Connecting. Detail: 'Connection requested.'.
[13:41:57 DBG ]  Subchannel id '3-1' connection requested in non-idle state of Connecting.
[13:41:57 VRB ]  Subchannel id '3-1' matches address 'service-endpoint.zone:2379' and is preserved.
[13:41:57 VRB ]  Connections unchanged.
[13:41:57 VRB ]  MyResolver resolve task completed.
[13:41:57 VRB ]  Subchannel id '3-1' connecting to transport.
[13:41:57 WRN ]  ##### TryConnectAsync context.CancellationToken.IsCancellationRequested = False
[13:41:57 VRB ]  Subchannel id '3-1' connecting socket to service-endpoint.zone:2379.
[13:41:57 DBG ]  Subchannel id '3-1' canceling connect.
[13:41:57 VRB ]  Subchannel id '3-1' connecting to transport.
[13:41:57 WRN ]  ##### TryConnectAsync context.CancellationToken.IsCancellationRequested = False
[13:41:57 VRB ]  Subchannel id '3-1' connecting socket to service-endpoint.zone:2379.
[13:41:57 DBG ]  Subchannel id '3-1' error connecting to socket service-endpoint.zone:2379.
System.OperationCanceledException: The operation was canceled.
   at System.Threading.CancellationToken.ThrowOperationCanceledException()
   at System.Threading.CancellationToken.ThrowIfCancellationRequested()
   at System.Net.Sockets.Socket.<ConnectAsync>g__WaitForConnectWithCancellation|285_0(AwaitableSocketAsyncEventArgs saea, ValueTask connectTask, CancellationToken cancellationToken)
   at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(ConnectContext context, Int32 attempt) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/SocketConnectivitySubchannelTransport.cs:line 184
[13:41:57 DBG ]  Subchannel id '3-1' state changed to TransientFailure. Detail: 'Error connecting to subchannel.'.
System.OperationCanceledException: The operation was canceled.
   at System.Threading.CancellationToken.ThrowOperationCanceledException()
   at System.Threading.CancellationToken.ThrowIfCancellationRequested()
   at System.Net.Sockets.Socket.<ConnectAsync>g__WaitForConnectWithCancellation|285_0(AwaitableSocketAsyncEventArgs saea, ValueTask connectTask, CancellationToken cancellationToken)
   at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(ConnectContext context, Int32 attempt) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/SocketConnectivitySubchannelTransport.cs:line 184
[13:41:57 VRB ]  Subchannel id '3-1' executing state changed registration '3-1-1'.
[13:41:57 VRB ]  Processing subchannel id '3-1' state changed to TransientFailure. Detail: 'Error connecting to subchannel.'.
System.OperationCanceledException: The operation was canceled.
   at System.Threading.CancellationToken.ThrowOperationCanceledException()
   at System.Threading.CancellationToken.ThrowIfCancellationRequested()
   at System.Net.Sockets.Socket.<ConnectAsync>g__WaitForConnectWithCancellation|285_0(AwaitableSocketAsyncEventArgs saea, ValueTask connectTask, CancellationToken cancellationToken)
   at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(ConnectContext context, Int32 attempt) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/SocketConnectivitySubchannelTransport.cs:line 184
[13:41:57 DBG ]  Channel state updated to TransientFailure.
[13:41:57 DBG ]  Channel picker updated.
[13:41:57 VRB ]  Refreshing resolver because subchannel id '3-1' is in state TransientFailure.
[13:41:57 VRB ]  MyResolver refresh requested.
[13:41:57 VRB ]  Subchannel id '3-1' connect canceled.
[13:41:57 VRB ]  MyResolver result with status code 'OK' and 1 addresses.
[13:41:57 VRB ]  Subchannel id '3-1' matches address 'service-endpoint.zone:2379' and is preserved.
[13:41:57 VRB ]  Connections unchanged.
[13:41:57 VRB ]  MyResolver result with status code 'OK' and 1 addresses.
[13:41:57 VRB ]  Subchannel id '3-1' matches address 'service-endpoint.zone:2379' and is preserved.
[13:41:57 VRB ]  Connections unchanged.
[13:41:57 VRB ]  MyResolver resolve task completed.

# Exception we expect - The SSL connection could not be established, see inner exception.
# AuthenticationException: Authentication failed, see inner exception. SslException: unknown Cert Authority
# OK here

[13:41:57 DBG ]  Error starting gRPC call.

[13:41:57 INF ]  Call failed with gRPC error status. Status code: 'Internal', Message: 'Error starting gRPC call. HttpRequestException: The SSL connection could not be established, see inner exception. AuthenticationException: Authentication failed, see inner exception. SslException: unknown Cert Authority'.
System.Net.Http.HttpRequestException: The SSL connection could not be established, see inner exception.
 ---> System.Security.Authentication.AuthenticationException: Authentication failed, see inner exception.
 ---> Interop+AppleCrypto+SslException: unknown Cert Authority
   --- End of inner exception stack trace ---
   at System.Net.Security.SslStream.ForceAuthenticationAsync[TIOAdapter](Boolean receiveFirst, Byte[] reAuthenticationData, CancellationToken cancellationToken)
   at System.Net.Http.ConnectHelper.EstablishSslConnectionAsync(SslClientAuthenticationOptions sslOptions, HttpRequestMessage request, Boolean async, Stream stream, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.ConnectHelper.EstablishSslConnectionAsync(SslClientAuthenticationOptions sslOptions, HttpRequestMessage request, Boolean async, Stream stream, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.ConnectAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.AddHttp2ConnectionAsync(QueueItem queueItem)
   at System.Threading.Tasks.TaskCompletionSourceWithCancellation`1.WaitWithCancellationAsync(CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler.<SendCoreAsync>g__Core|5_0(HttpRequestMessage request, Boolean useAsync, CancellationToken cancellationToken)
   at MyTestApp.Grpc.Client.ClientSideBalancing.Handlers.GrpcLoadStatisticsHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /Users/username/dev/path/to/testapp/MyTestApp/Grpc/Client/ClientSideBalancing/Handlers/GrpcLoadStatisticsHandler.cs:line 27
   at Microsoft.Extensions.Http.Logging.LoggingScopeHttpMessageHandler.<SendCoreAsync>g__Core|5_0(HttpRequestMessage request, Boolean useAsync, CancellationToken cancellationToken)
   at Grpc.Net.Client.Balancer.Internal.BalancerHttpHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/BalancerHttpHandler.cs:line 150
   at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Internal/GrpcCall.cs:line 502

[13:41:57 DBG ]  Finished gRPC call.
[13:41:57 VRB ]  Subchannel id '3-1' created stream for service-endpoint.zone:2379 with 0 buffered bytes. Transport has 1 active streams.
[13:41:57 DBG ]  Subchannel id '3-1' connected to socket service-endpoint.zone:2379.
[13:41:57 DBG ]  Subchannel id '3-1' state changed to Ready. Detail: 'Successfully connected to socket.'.
[13:41:57 VRB ]  Subchannel id '3-1' executing state changed registration '3-1-1'.
[13:41:57 VRB ]  Processing subchannel id '3-1' state changed to Ready. Detail: 'Successfully connected to socket.'.
[13:41:57 VRB ]  Creating ready picker with 1 subchannels: id '3-1' (service-endpoint.zone:2379)
[13:41:57 DBG ]  Channel state updated to Ready.
[13:41:57 DBG ]  Channel picker updated.
[13:41:57 DBG ]  gRPC call canceled.

# We captured exception above in `catch` block, it's OK

[13:41:57 ERR ]  ##### SOME ERROR
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="Error starting gRPC call. HttpRequestException: The SSL connection could not be established, see inner exception. AuthenticationException: Authentication failed, see inner exception. SslException: unknown Cert Authority", DebugException="System.Net.Http.HttpRequestException: The SSL connection could not be established, see inner exception.")
 ---> System.Net.Http.HttpRequestException: The SSL connection could not be established, see inner exception.
 ---> System.Security.Authentication.AuthenticationException: Authentication failed, see inner exception.
 ---> Interop+AppleCrypto+SslException: unknown Cert Authority
   --- End of inner exception stack trace ---
   at System.Net.Security.SslStream.ForceAuthenticationAsync[TIOAdapter](Boolean receiveFirst, Byte[] reAuthenticationData, CancellationToken cancellationToken)
   at System.Net.Http.ConnectHelper.EstablishSslConnectionAsync(SslClientAuthenticationOptions sslOptions, HttpRequestMessage request, Boolean async, Stream stream, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.ConnectHelper.EstablishSslConnectionAsync(SslClientAuthenticationOptions sslOptions, HttpRequestMessage request, Boolean async, Stream stream, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.ConnectAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.AddHttp2ConnectionAsync(QueueItem queueItem)
   at System.Threading.Tasks.TaskCompletionSourceWithCancellation`1.WaitWithCancellationAsync(CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler.<SendCoreAsync>g__Core|5_0(HttpRequestMessage request, Boolean useAsync, CancellationToken cancellationToken)
   at MyTestApp.Grpc.Client.ClientSideBalancing.Handlers.GrpcLoadStatisticsHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /Users/username/dev/path/to/testapp/MyTestApp/Grpc/Client/ClientSideBalancing/Handlers/GrpcLoadStatisticsHandler.cs:line 27
   at Microsoft.Extensions.Http.Logging.LoggingScopeHttpMessageHandler.<SendCoreAsync>g__Core|5_0(HttpRequestMessage request, Boolean useAsync, CancellationToken cancellationToken)
   at Grpc.Net.Client.Balancer.Internal.BalancerHttpHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/BalancerHttpHandler.cs:line 150
   at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Internal/GrpcCall.cs:line 502
   --- End of inner exception stack trace ---
   at Grpc.Net.Client.Internal.GrpcCall`2.GetResponseHeadersCoreAsync() in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Internal/GrpcCall.cs:line 300
   at MyTestApp.CircuitBreaker.Handlers.CircuitBreakerGrpcInterceptor.HandleExceptionAsync[TResponse](Task`1 response) in /Users/username/dev/path/to/testapp/MyTestApp/CircuitBreaker/Handlers/CircuitBreakerGrpcInterceptor.cs:line 88
   at Program.<Main>$(String[] args) in /Users/username/dev/testapp/path/MyTest.Grpc/Program.cs:line 60

[13:41:57 WRN ]  ##### BEFORE Delay

[13:41:57 VRB ]  Subchannel id '3-1' disposing stream for service-endpoint.zone:2379. Transport has 0 active streams.
[13:41:57 DBG ]  Subchannel id '3-1' state changed to Idle. Detail: 'Disconnected.'.
[13:41:57 VRB ]  Subchannel id '3-1' executing state changed registration '3-1-1'.
[13:41:57 VRB ]  Processing subchannel id '3-1' state changed to Idle. Detail: 'Disconnected.'.
[13:41:57 DBG ]  Channel state updated to Connecting.
[13:41:57 DBG ]  Channel picker updated.
[13:41:57 VRB ]  Refreshing resolver because subchannel id '3-1' is in state Idle.
[13:41:57 VRB ]  MyResolver refresh requested.
[13:41:57 VRB ]  Requesting connection for subchannel id '3-1' because it is in state Idle.
[13:41:57 VRB ]  Subchannel id '3-1' connection requested.
[13:41:57 DBG ]  Subchannel id '3-1' state changed to Connecting. Detail: 'Connection requested.'.
[13:41:57 VRB ]  Subchannel id '3-1' executing state changed registration '3-1-1'.
[13:41:57 VRB ]  Processing subchannel id '3-1' state changed to Connecting. Detail: 'Connection requested.'.

[13:41:57 DBG ]  Error starting gRPC call.

# The same exception again (But why? The same call again in another thread?)

[13:41:57 INF ]  Call failed with gRPC error status. Status code: 'Internal', Message: 'Error starting gRPC call. HttpRequestException: The SSL connection could not be established, see inner exception. AuthenticationException: Authentication failed, see inner exception. SslException: unknown Cert Authority'.
System.Net.Http.HttpRequestException: The SSL connection could not be established, see inner exception.
 ---> System.Security.Authentication.AuthenticationException: Authentication failed, see inner exception.
 ---> Interop+AppleCrypto+SslException: unknown Cert Authority
   --- End of inner exception stack trace ---
   at System.Net.Security.SslStream.ForceAuthenticationAsync[TIOAdapter](Boolean receiveFirst, Byte[] reAuthenticationData, CancellationToken cancellationToken)
   at System.Net.Http.ConnectHelper.EstablishSslConnectionAsync(SslClientAuthenticationOptions sslOptions, HttpRequestMessage request, Boolean async, Stream stream, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.ConnectHelper.EstablishSslConnectionAsync(SslClientAuthenticationOptions sslOptions, HttpRequestMessage request, Boolean async, Stream stream, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.ConnectAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.AddHttp2ConnectionAsync(QueueItem queueItem)
   at System.Threading.Tasks.TaskCompletionSourceWithCancellation`1.WaitWithCancellationAsync(CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler.<SendCoreAsync>g__Core|5_0(HttpRequestMessage request, Boolean useAsync, CancellationToken cancellationToken)
   at MyTestApp.Grpc.Client.ClientSideBalancing.Handlers.GrpcLoadStatisticsHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /Users/username/dev/path/to/testapp/MyTestApp/Grpc/Client/ClientSideBalancing/Handlers/GrpcLoadStatisticsHandler.cs:line 27
   at Microsoft.Extensions.Http.Logging.LoggingScopeHttpMessageHandler.<SendCoreAsync>g__Core|5_0(HttpRequestMessage request, Boolean useAsync, CancellationToken cancellationToken)
   at Grpc.Net.Client.Balancer.Internal.BalancerHttpHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/BalancerHttpHandler.cs:line 150
   at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Internal/GrpcCall.cs:line 502

[13:41:57 DBG ]  Finished gRPC call.
[13:41:57 DBG ]  gRPC call canceled.
[13:41:57 VRB ]  Subchannel id '3-1' connecting to transport.
[13:41:57 WRN ]  ##### TryConnectAsync context.CancellationToken.IsCancellationRequested = False
[13:41:57 VRB ]  Subchannel id '3-1' connecting socket to service-endpoint.zone:2379.
[13:41:57 VRB ]  MyResolver result with status code 'OK' and 1 addresses.
[13:41:57 VRB ]  Subchannel id '3-1' matches address 'service-endpoint.zone:2379' and is preserved.
[13:41:57 VRB ]  Connections unchanged.
[13:41:57 VRB ]  MyResolver result with status code 'OK' and 1 addresses.
[13:41:57 VRB ]  Subchannel id '3-1' matches address 'service-endpoint.zone:2379' and is preserved.
[13:41:57 VRB ]  Connections unchanged.
[13:41:57 VRB ]  MyResolver resolve task completed.
[13:41:57 DBG ]  Subchannel id '3-1' connected to socket service-endpoint.zone:2379.
[13:41:57 DBG ]  Subchannel id '3-1' state changed to Ready. Detail: 'Successfully connected to socket.'.
[13:41:57 VRB ]  Subchannel id '3-1' executing state changed registration '3-1-1'.
[13:41:57 VRB ]  Processing subchannel id '3-1' state changed to Ready. Detail: 'Successfully connected to socket.'.
[13:41:57 VRB ]  Creating ready picker with 1 subchannels: id '3-1' (service-endpoint.zone:2379)
[13:41:57 DBG ]  Channel state updated to Ready.
[13:41:57 DBG ]  Channel picker updated.

[13:41:58 WRN ]  ##### END LOOP

[13:41:58 WRN ]  ##### START LOOP

# Second attempt

[13:41:58 WRN ]  ##### BEFORE Unary call
[13:41:58 DBG ]  Starting gRPC call. Method type: 'Unary', URI: 'https://loadbalancer.temporary.invalid/3rdpartynspace.3rdPartyService/3rdPartyServicePerformRequest'.
[13:41:58 VRB ]  Pick started.
[13:41:58 DBG ]  Successfully picked subchannel id '3-1' with address service-endpoint.zone:2379. Transport status: InitialSocket
[13:41:58 VRB ]  Sending request https://service-endpoint.zone:2379/3rdpartynspace.3rdPartyService/3rdPartyServicePerformRequest.
[13:41:58 VRB ]  Starting connect callback for service-endpoint.zone:2379.
[13:41:58 VRB ]  Subchannel id '3-1' creating stream for service-endpoint.zone:2379.
[13:41:58 VRB ]  Subchannel id '3-1' checking socket service-endpoint.zone:2379.
[13:41:58 VRB ]  Subchannel id '3-1' created stream for service-endpoint.zone:2379 with 0 buffered bytes. Transport has 1 active streams.
[13:41:58 VRB ]  Subchannel id '3-1' disposing stream for service-endpoint.zone:2379. Transport has 0 active streams.
[13:41:58 DBG ]  Subchannel id '3-1' state changed to Idle. Detail: 'Disconnected.'.
[13:41:58 VRB ]  Subchannel id '3-1' executing state changed registration '3-1-1'.
[13:41:58 VRB ]  Processing subchannel id '3-1' state changed to Idle. Detail: 'Disconnected.'.
[13:41:58 DBG ]  Channel state updated to Connecting.
[13:41:58 DBG ]  Channel picker updated.
[13:41:58 VRB ]  Refreshing resolver because subchannel id '3-1' is in state Idle.
[13:41:58 VRB ]  MyResolver refresh requested.
[13:41:58 VRB ]  Requesting connection for subchannel id '3-1' because it is in state Idle.
[13:41:58 VRB ]  Subchannel id '3-1' connection requested.
[13:41:58 DBG ]  Subchannel id '3-1' state changed to Connecting. Detail: 'Connection requested.'.
[13:41:58 VRB ]  Subchannel id '3-1' executing state changed registration '3-1-1'.
[13:41:58 VRB ]  Processing subchannel id '3-1' state changed to Connecting. Detail: 'Connection requested.'.
[13:41:58 VRB ]  MyResolver result with status code 'OK' and 1 addresses.
[13:41:58 VRB ]  Subchannel id '3-1' connecting to transport.
[13:41:58 WRN ]  ##### TryConnectAsync context.CancellationToken.IsCancellationRequested = False
[13:41:58 VRB ]  Subchannel id '3-1' updated with addresses: service-endpoint.zone:2379
[13:41:58 DBG ]  Subchannel id '3-1' is connecting when its addresses are updated. Restarting connect.
[13:41:58 DBG ]  Subchannel id '3-1' canceling connect.
[13:41:58 DBG ]  Subchannel id '3-1' state changed to Idle. Detail: 'Disconnected.'.
[13:41:58 VRB ]  Subchannel id '3-1' executing state changed registration '3-1-1'.
[13:41:58 VRB ]  Processing subchannel id '3-1' state changed to Idle. Detail: 'Disconnected.'.
[13:41:58 VRB ]  Refreshing resolver because subchannel id '3-1' is in state Idle.
[13:41:58 VRB ]  MyResolver refresh requested.
[13:41:58 VRB ]  MyResolver refresh ignored because resolve is already in progress.
[13:41:58 VRB ]  Requesting connection for subchannel id '3-1' because it is in state Idle.
[13:41:58 DBG ]  Subchannel id '3-1' connection requested in non-idle state of Connecting.
[13:41:58 DBG ]  Subchannel id '3-1' connection requested in non-idle state of Connecting.
[13:41:58 VRB ]  Subchannel id '3-1' matches address 'service-endpoint.zone:2379' and is preserved.
[13:41:58 VRB ]  Connections unchanged.
[13:41:58 VRB ]  MyResolver result with status code 'OK' and 1 addresses.
[13:41:58 DBG ]  Subchannel id '3-1' state changed to Connecting. Detail: 'Connecting to socket.'.
[13:41:58 VRB ]  Subchannel id '3-1' executing state changed registration '3-1-1'.
[13:41:58 VRB ]  Processing subchannel id '3-1' state changed to Connecting. Detail: 'Connecting to socket.'.
[13:41:58 VRB ]  Subchannel id '3-1' connecting socket to service-endpoint.zone:2379.
[13:41:58 VRB ]  Subchannel id '3-1' matches address 'service-endpoint.zone:2379' and is preserved.
[13:41:58 VRB ]  Connections unchanged.
[13:41:58 VRB ]  MyResolver resolve task completed.
[13:41:58 DBG ]  Error starting gRPC call.
[13:41:58 DBG ]  Subchannel id '3-1' error connecting to socket service-endpoint.zone:2379.
System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(ConnectContext context, Int32 attempt) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/SocketConnectivitySubchannelTransport.cs:line 184
[13:41:58 DBG ]  Subchannel id '3-1' state changed to TransientFailure. Detail: 'Error connecting to subchannel.'.
System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(ConnectContext context, Int32 attempt) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/SocketConnectivitySubchannelTransport.cs:line 184
[13:41:58 VRB ]  Subchannel id '3-1' executing state changed registration '3-1-1'.

# still expected exception, it's OK

[13:41:58 INF ]  Call failed with gRPC error status. Status code: 'Internal', Message: 'Error starting gRPC call. HttpRequestException: The SSL connection could not be established, see inner exception. AuthenticationException: Authentication failed, see inner exception. SslException: unknown Cert Authority'.
System.Net.Http.HttpRequestException: The SSL connection could not be established, see inner exception.
 ---> System.Security.Authentication.AuthenticationException: Authentication failed, see inner exception.
 ---> Interop+AppleCrypto+SslException: unknown Cert Authority
   --- End of inner exception stack trace ---
   at System.Net.Security.SslStream.ForceAuthenticationAsync[TIOAdapter](Boolean receiveFirst, Byte[] reAuthenticationData, CancellationToken cancellationToken)
   at System.Net.Http.ConnectHelper.EstablishSslConnectionAsync(SslClientAuthenticationOptions sslOptions, HttpRequestMessage request, Boolean async, Stream stream, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.ConnectHelper.EstablishSslConnectionAsync(SslClientAuthenticationOptions sslOptions, HttpRequestMessage request, Boolean async, Stream stream, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.ConnectAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.AddHttp2ConnectionAsync(QueueItem queueItem)
   at System.Threading.Tasks.TaskCompletionSourceWithCancellation`1.WaitWithCancellationAsync(CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler.<SendCoreAsync>g__Core|5_0(HttpRequestMessage request, Boolean useAsync, CancellationToken cancellationToken)
   at MyTestApp.Grpc.Client.ClientSideBalancing.Handlers.GrpcLoadStatisticsHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /Users/username/dev/path/to/testapp/MyTestApp/Grpc/Client/ClientSideBalancing/Handlers/GrpcLoadStatisticsHandler.cs:line 27
   at Microsoft.Extensions.Http.Logging.LoggingScopeHttpMessageHandler.<SendCoreAsync>g__Core|5_0(HttpRequestMessage request, Boolean useAsync, CancellationToken cancellationToken)
   at Grpc.Net.Client.Balancer.Internal.BalancerHttpHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/BalancerHttpHandler.cs:line 150
   at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Internal/GrpcCall.cs:line 502
[13:41:58 DBG ]  Finished gRPC call.
[13:41:58 DBG ]  gRPC call canceled.
[13:41:58 VRB ]  Processing subchannel id '3-1' state changed to TransientFailure. Detail: 'Error connecting to subchannel.'.
System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(ConnectContext context, Int32 attempt) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/SocketConnectivitySubchannelTransport.cs:line 184
[13:41:58 DBG ]  Channel state updated to TransientFailure.
[13:41:58 DBG ]  Channel picker updated.
[13:41:58 VRB ]  Refreshing resolver because subchannel id '3-1' is in state TransientFailure.
[13:41:58 VRB ]  MyResolver refresh requested.

# catched exception

[13:41:58 ERR ]  ##### SOME ERROR
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="Error starting gRPC call. HttpRequestException: The SSL connection could not be established, see inner exception. AuthenticationException: Authentication failed, see inner exception. SslException: unknown Cert Authority", DebugException="System.Net.Http.HttpRequestException: The SSL connection could not be established, see inner exception.")
 ---> System.Net.Http.HttpRequestException: The SSL connection could not be established, see inner exception.
 ---> System.Security.Authentication.AuthenticationException: Authentication failed, see inner exception.
 ---> Interop+AppleCrypto+SslException: unknown Cert Authority
   --- End of inner exception stack trace ---
   at System.Net.Security.SslStream.ForceAuthenticationAsync[TIOAdapter](Boolean receiveFirst, Byte[] reAuthenticationData, CancellationToken cancellationToken)
   at System.Net.Http.ConnectHelper.EstablishSslConnectionAsync(SslClientAuthenticationOptions sslOptions, HttpRequestMessage request, Boolean async, Stream stream, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.ConnectHelper.EstablishSslConnectionAsync(SslClientAuthenticationOptions sslOptions, HttpRequestMessage request, Boolean async, Stream stream, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.ConnectAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.AddHttp2ConnectionAsync(QueueItem queueItem)
   at System.Threading.Tasks.TaskCompletionSourceWithCancellation`1.WaitWithCancellationAsync(CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler.<SendCoreAsync>g__Core|5_0(HttpRequestMessage request, Boolean useAsync, CancellationToken cancellationToken)
   at MyTestApp.Grpc.Client.ClientSideBalancing.Handlers.GrpcLoadStatisticsHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /Users/username/dev/path/to/testapp/MyTestApp/Grpc/Client/ClientSideBalancing/Handlers/GrpcLoadStatisticsHandler.cs:line 27
   at Microsoft.Extensions.Http.Logging.LoggingScopeHttpMessageHandler.<SendCoreAsync>g__Core|5_0(HttpRequestMessage request, Boolean useAsync, CancellationToken cancellationToken)
   at Grpc.Net.Client.Balancer.Internal.BalancerHttpHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/BalancerHttpHandler.cs:line 150
   at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Internal/GrpcCall.cs:line 502
   --- End of inner exception stack trace ---
   at Grpc.Net.Client.Internal.GrpcCall`2.GetResponseHeadersCoreAsync() in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Internal/GrpcCall.cs:line 300

# No second background request this time

[13:41:58 WRN ]  ##### BEFORE Delay
[13:41:58 VRB ]  MyResolver result with status code 'OK' and 1 addresses.
[13:41:58 VRB ]  Subchannel id '3-1' matches address 'service-endpoint.zone:2379' and is preserved.
[13:41:58 VRB ]  Connections unchanged.
[13:41:58 VRB ]  MyResolver result with status code 'OK' and 1 addresses.
[13:41:58 VRB ]  Subchannel id '3-1' matches address 'service-endpoint.zone:2379' and is preserved.
[13:41:58 VRB ]  Connections unchanged.
[13:41:58 VRB ]  MyResolver resolve task completed.
[13:41:58 VRB ]  Subchannel id '3-1' connect canceled.
[13:41:59 WRN ]  ##### END LOOP

# 3rd attempt

[13:41:59 WRN ]  ##### START LOOP
[13:41:59 WRN ]  ##### BEFORE Unary call
[13:41:59 DBG ]  Starting gRPC call. Method type: 'Unary', URI: 'https://loadbalancer.temporary.invalid/3rdpartynspace.3rdPartyService/3rdPartyServicePerformRequest'.
[13:41:59 VRB ]  Pick started.

# !!!!!!!!!                                                                       !!!!!!!!!
# !!!!!!!!! Got unexpected exception this time. No SSL, but TaskCanceledException !!!!!!!!!
# !!!!!!!!!                                                                       !!!!!!!!!

[13:41:59 DBG ]  Picked failure with status: Status(StatusCode="Unavailable", Detail="Error connecting to subchannel.", DebugException="System.Threading.Tasks.TaskCanceledException: A task was canceled.")
[13:41:59 DBG ]  Error starting gRPC call.
[13:41:59 INF ]  Call failed with gRPC error status. Status code: 'Unavailable', Message: 'Error connecting to subchannel.'.
System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(ConnectContext context, Int32 attempt) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/SocketConnectivitySubchannelTransport.cs:line 184

# `SocketConnectivitySubchannelTransport.cs:line 184` is 
# `await _socketConnect(socket, currentEndPoint, context.CancellationToken).ConfigureAwait(false);`
# (differs from original bacause of my logs)

[13:41:59 DBG ]  Finished gRPC call.
[13:41:59 DBG ]  gRPC call canceled.

[13:41:59 ERR ]  ##### SOME ERROR
Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="Error connecting to subchannel.", DebugException="System.Threading.Tasks.TaskCanceledException: A task was canceled.")
 ---> System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(ConnectContext context, Int32 attempt) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/SocketConnectivitySubchannelTransport.cs:line 184
   --- End of inner exception stack trace ---
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/ConnectionManager.cs:line 341
   at Grpc.Net.Client.Balancer.Internal.BalancerHttpHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/BalancerHttpHandler.cs:line 117
   at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Internal/GrpcCall.cs:line 502
   at MyTestApp.CircuitBreaker.Handlers.CircuitBreakerGrpcInterceptor.HandleExceptionAsync[TResponse](Task`1 response) in /Users/username/dev/path/to/testapp/MyTestApp/CircuitBreaker/Handlers/CircuitBreakerGrpcInterceptor.cs:line 88
   at Program.<Main>$(String[] args) in /Users/username/dev/testapp/path/MyTest.Grpc/Program.cs:line 60
[13:41:59 WRN ]  ##### BEFORE Delay
[13:42:00 WRN ]  ##### END LOOP
[13:42:00 WRN ]  ##### START LOOP
[13:42:00 WRN ]  ##### BEFORE Unary call
[13:42:00 DBG ]  Starting gRPC call. Method type: 'Unary', URI: 'https://loadbalancer.temporary.invalid/3rdpartynspace.3rdPartyService/3rdPartyServicePerformRequest'.
[13:42:00 VRB ]  Pick started.
[13:42:00 DBG ]  Picked failure with status: Status(StatusCode="Unavailable", Detail="Error connecting to subchannel.", DebugException="System.Threading.Tasks.TaskCanceledException: A task was canceled.")
[13:42:00 DBG ]  Error starting gRPC call.
[13:42:00 INF ]  Call failed with gRPC error status. Status code: 'Unavailable', Message: 'Error connecting to subchannel.'.
System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(ConnectContext context, Int32 attempt) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/SocketConnectivitySubchannelTransport.cs:line 184
[13:42:00 DBG ]  Finished gRPC call.
[13:42:00 DBG ]  gRPC call canceled.
[13:42:00 ERR ]  ##### SOME ERROR
Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="Error connecting to subchannel.", DebugException="System.Threading.Tasks.TaskCanceledException: A task was canceled.")
 ---> System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(ConnectContext context, Int32 attempt) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/SocketConnectivitySubchannelTransport.cs:line 184
   --- End of inner exception stack trace ---
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/ConnectionManager.cs:line 341
   at Grpc.Net.Client.Balancer.Internal.BalancerHttpHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/BalancerHttpHandler.cs:line 117
   at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Internal/GrpcCall.cs:line 502
   at MyTestApp.CircuitBreaker.Handlers.CircuitBreakerGrpcInterceptor.HandleExceptionAsync[TResponse](Task`1 response) in /Users/username/dev/path/to/testapp/MyTestApp/CircuitBreaker/Handlers/CircuitBreakerGrpcInterceptor.cs:line 88
   at Program.<Main>$(String[] args) in /Users/username/dev/testapp/path/MyTest.Grpc/Program.cs:line 60

[13:42:00 WRN ]  ##### BEFORE Delay
[13:42:01 WRN ]  ##### END LOOP

[13:42:01 WRN ]  ##### START LOOP
[13:42:01 WRN ]  ##### BEFORE Unary call
[13:42:01 DBG ]  Starting gRPC call. Method type: 'Unary', URI: 'https://loadbalancer.temporary.invalid/3rdpartynspace.3rdPartyService/3rdPartyServicePerformRequest'.
[13:42:01 VRB ]  Pick started.
[13:42:01 DBG ]  Picked failure with status: Status(StatusCode="Unavailable", Detail="Error connecting to subchannel.", DebugException="System.Threading.Tasks.TaskCanceledException: A task was canceled.")

# !!!!!!!!!                                                                   !!!!!!!!!
# !!!!!!!!! Got unexpected exception again. No SSL, but TaskCanceledException !!!!!!!!!
# !!!!!!!!!                                                                   !!!!!!!!!

[13:42:01 DBG ]  Error starting gRPC call.
[13:42:01 INF ]  Call failed with gRPC error status. Status code: 'Unavailable', Message: 'Error connecting to subchannel.'.
System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(ConnectContext context, Int32 attempt) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/SocketConnectivitySubchannelTransport.cs:line 184
[13:42:01 DBG ]  Finished gRPC call.
[13:42:01 DBG ]  gRPC call canceled.
[13:42:01 ERR ]  ##### SOME ERROR
Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="Error connecting to subchannel.", DebugException="System.Threading.Tasks.TaskCanceledException: A task was canceled.")
 ---> System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(ConnectContext context, Int32 attempt) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/SocketConnectivitySubchannelTransport.cs:line 184
   --- End of inner exception stack trace ---
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/ConnectionManager.cs:line 341
   at Grpc.Net.Client.Balancer.Internal.BalancerHttpHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/BalancerHttpHandler.cs:line 117
   at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Internal/GrpcCall.cs:line 502
   at MyTestApp.CircuitBreaker.Handlers.CircuitBreakerGrpcInterceptor.HandleExceptionAsync[TResponse](Task`1 response) in /Users/username/dev/path/to/testapp/MyTestApp/CircuitBreaker/Handlers/CircuitBreakerGrpcInterceptor.cs:line 88
   at Program.<Main>$(String[] args) in /Users/username/dev/testapp/path/MyTest.Grpc/Program.cs:line 60
[13:42:01 WRN ]  ##### BEFORE Delay
[13:42:02 WRN ]  ##### END LOOP

# !!!!!!!!!                                                                            !!!!!!!!!
# !!!!!!!!! Got unexpected exception again. We will get this exception again and again !!!!!!!!!
# !!!!!!!!!                                                                            !!!!!!!!!

[13:42:02 WRN ]  ##### START LOOP
[13:42:02 WRN ]  ##### BEFORE Unary call
[13:42:02 DBG ]  Starting gRPC call. Method type: 'Unary', URI: 'https://loadbalancer.temporary.invalid/3rdpartynspace.3rdPartyService/3rdPartyServicePerformRequest'.
[13:42:02 VRB ]  Pick started.
[13:42:02 DBG ]  Picked failure with status: Status(StatusCode="Unavailable", Detail="Error connecting to subchannel.", DebugException="System.Threading.Tasks.TaskCanceledException: A task was canceled.")
[13:42:02 DBG ]  Error starting gRPC call.
[13:42:02 INF ]  Call failed with gRPC error status. Status code: 'Unavailable', Message: 'Error connecting to subchannel.'.
System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(ConnectContext context, Int32 attempt) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/SocketConnectivitySubchannelTransport.cs:line 184
[13:42:02 DBG ]  Finished gRPC call.
[13:42:02 DBG ]  gRPC call canceled.
[13:42:02 ERR ]  ##### SOME ERROR
Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="Error connecting to subchannel.", DebugException="System.Threading.Tasks.TaskCanceledException: A task was canceled.")
 ---> System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(ConnectContext context, Int32 attempt) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/SocketConnectivitySubchannelTransport.cs:line 184
   --- End of inner exception stack trace ---
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/ConnectionManager.cs:line 341
   at Grpc.Net.Client.Balancer.Internal.BalancerHttpHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Balancer/Internal/BalancerHttpHandler.cs:line 117
   at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout) in /Users/username/dev/grpc-dotnet-forked/src/Grpc.Net.Client/Internal/GrpcCall.cs:line 502
   at MyTestApp.CircuitBreaker.Handlers.CircuitBreakerGrpcInterceptor.HandleExceptionAsync[TResponse](Task`1 response) in /Users/username/dev/path/to/testapp/MyTestApp/CircuitBreaker/Handlers/CircuitBreakerGrpcInterceptor.cs:line 88
   at Program.<Main>$(String[] args) in /Users/username/dev/testapp/path/MyTest.Grpc/Program.cs:line 60
[13:42:02 WRN ]  ##### BEFORE Delay
[13:42:03 WRN ]  ##### END LOOP
...

I waited for backoff to handle this but it has no effect here.

According to exceptions above I can guess that the problem is in stored somewhere Cancellation token which was once Cancelled and then used in every request.

Please could you look at this issue.

kolonist commented 3 months ago

Hi @JamesNK!

After using new library for a couple of weeks we noticed that with the error described above comes also memory leak. We can see endless grow of memory consumption. We can't really reproduce it now but I believe that it somehow interconnected.