ConnectTimeout option doesn't work since version 2.44 #1828
Description
What version of gRPC and what language are you using?
Grpc.Net.Client 2.47.0 /C#
What operating system (Linux, Windows,...) and version?
Linux
What runtime / compiler are you using (e.g. .NET Core SDK version dotnet --info)
.NET SDK 6.0.102
What did you do?
I used SocketsHttpHandler.ConnectTimeout to limit the connection handshake time when the remote host is not responding.
Unfortunately I found that this option is ignored and the connection ends after some large default timeout.
MRE:
var loggerFactory = LoggerFactory.Create(logging =>
{
logging.AddConsole(x => x.TimestampFormat = "[HH:mm:ss] ");
logging.SetMinimumLevel(LogLevel.Trace);
});
Stopwatch stopwatch = new Stopwatch();
stopwatch.Start();
try
{
var handler = new SocketsHttpHandler()
{
ConnectTimeout = TimeSpan.FromSeconds(10),
};
var endpoint = "http://1.1.1.1:2379"; // any endpoint that silently ignores all connections
var channel = GrpcChannel.ForAddress(endpoint, new GrpcChannelOptions(){HttpHandler = handler, LoggerFactory = loggerFactory});
var client = new Greeter.GreeterClient(channel);
var reply = await client.SayHelloAsync(new HelloRequest { Name = "test" });
Console.WriteLine("Greeting: " + reply.Message);
}
catch (Exception e)
{
Console.WriteLine($"Exception: {e}");
}
stopwatch.Stop();
Console.WriteLine($"Elapsed: {stopwatch.Elapsed}");
What did you expect to see?
A error after 10 seconds
What did you see instead?
A error after ~130 seconds
More logs
[17:19:04] dbug: Grpc.Net.Client.Internal.GrpcCall[1]
Starting gRPC call. Method type: 'Unary', URI: 'http://1.1.1.1:2379/tutorial.Greeter/SayHello'.
[17:19:04] dbug: Grpc.Net.Client.Balancer.Subchannel[1]
Subchannel id '1' created with addresses: 1.1.1.1:2379
[17:19:04] dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[4]
Channel picker updated.
[17:19:04] trce: Grpc.Net.Client.Balancer.Subchannel[4]
Subchannel id '1' connection requested.
[17:19:04] dbug: Grpc.Net.Client.Balancer.Subchannel[11]
Subchannel id '1' state changed to Connecting. Detail: 'Connection requested.'.
[17:19:04] trce: Grpc.Net.Client.Balancer.PickFirstBalancer[1]
Processing subchannel id '1' state changed to Connecting. Detail: 'Connection requested.'.
[17:19:04] dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[3]
Channel state updated to Connecting.
[17:19:04] trce: Grpc.Net.Client.Balancer.Subchannel[6]
Subchannel id '1' connecting to transport.
[17:19:04] trce: Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport[1]
Subchannel id '1' connecting socket to 1.1.1.1:2379.
[17:19:04] trce: Grpc.Net.Client.Balancer.Internal.ConnectionManager[5]
Pick started.
[17:19:04] dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[8]
Picked queued.
[17:19:04] trce: Grpc.Net.Client.Balancer.Internal.ConnectionManager[11]
Waiting for a new picker.
[17:21:15] dbug: Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport[3]
Subchannel id '1' error connecting to socket 1.1.1.1:2379.
System.Net.Sockets.SocketException (110): Connection timed out
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token)
at System.Net.Sockets.Socket.<ConnectAsync>g__WaitForConnectWithCancellation|277_0(AwaitableSocketAsyncEventArgs saea, ValueTask connectTask, CancellationToken cancellationToken)
at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(CancellationToken cancellationToken)
[17:21:15] dbug: Grpc.Net.Client.Balancer.Subchannel[11]
Subchannel id '1' state changed to TransientFailure. Detail: 'Error connecting to subchannel.'.
System.Net.Sockets.SocketException (110): Connection timed out
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token)
at System.Net.Sockets.Socket.<ConnectAsync>g__WaitForConnectWithCancellation|277_0(AwaitableSocketAsyncEventArgs saea, ValueTask connectTask, CancellationToken cancellationToken)
at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(CancellationToken cancellationToken)
[17:21:15] trce: Grpc.Net.Client.Balancer.PickFirstBalancer[1]
Processing subchannel id '1' state changed to TransientFailure. Detail: 'Error connecting to subchannel.'.
System.Net.Sockets.SocketException (110): Connection timed out
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token)
at System.Net.Sockets.Socket.<ConnectAsync>g__WaitForConnectWithCancellation|277_0(AwaitableSocketAsyncEventArgs saea, ValueTask connectTask, CancellationToken cancellationToken)
at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(CancellationToken cancellationToken)
[17:21:15] dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[3]
Channel state updated to TransientFailure.
[17:21:15] dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[4]
Channel picker updated.
[17:21:15] trce: Grpc.Net.Client.Balancer.Internal.ConnectionManager[5]
Pick started.
[17:21:15] dbug: Grpc.Net.Client.Balancer.Internal.ConnectionManager[9]
Picked failure with status: Status(StatusCode="Unavailable", Detail="Error connecting to subchannel.", DebugException="System.Net.Sockets.SocketException (110): Connection timed out
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token)
at System.Net.Sockets.Socket.<ConnectAsync>g__WaitForConnectWithCancellation|277_0(AwaitableSocketAsyncEventArgs saea, ValueTask connectTask, CancellationToken cancellationToken)
at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(CancellationToken cancellationToken)")
[17:21:15] trce: Grpc.Net.Client.Balancer.Subchannel[7]
Subchannel id '1' starting connect backoff of 00:00:00.8447185.
[17:21:15] fail: Grpc.Net.Client.Internal.GrpcCall[6]
Error starting gRPC call.
Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="Error connecting to subchannel.", DebugException="System.Net.Sockets.SocketException (110): Connection timed out
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token)
at System.Net.Sockets.Socket.<ConnectAsync>g__WaitForConnectWithCancellation|277_0(AwaitableSocketAsyncEventArgs saea, ValueTask connectTask, CancellationToken cancellationToken)
at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(CancellationToken cancellationToken)")
at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken)
at Grpc.Net.Client.Balancer.Internal.BalancerHttpHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout)
[17:21:15] info: Grpc.Net.Client.Internal.GrpcCall[3]
Call failed with gRPC error status. Status code: 'Unavailable', Message: 'Error connecting to subchannel.'.
[17:21:15] dbug: Grpc.Net.Client.Internal.GrpcCall[4]
Finished gRPC call.
[17:21:15] dbug: Grpc.Net.Client.Internal.GrpcCall[8]
gRPC call canceled.
Exception: Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="Error connecting to subchannel.", DebugException="System.Net.Sockets.SocketException (110): Connection timed out
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token)
at System.Net.Sockets.Socket.<ConnectAsync>g__WaitForConnectWithCancellation|277_0(AwaitableSocketAsyncEventArgs saea, ValueTask connectTask, CancellationToken cancellationToken)
at Grpc.Net.Client.Balancer.Internal.SocketConnectivitySubchannelTransport.TryConnectAsync(CancellationToken cancellationToken)")
at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken)
at Grpc.Net.Client.Balancer.Internal.BalancerHttpHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
at Grpc.Net.Client.Internal.GrpcCall`2.RunCall(HttpRequestMessage request, Nullable`1 timeout)
at TestEtcd.Program.Main(String[] args) in /home/alex/Projects/Test/Program.cs:line 233
Elapsed: 00:02:11.2987933
Process finished with exit code 0.
Anything else we should know about your project / environment?
It works fine in version 2.43.0.