TLS connection taking a long time (version 2.7.33)

Hi all,

We have a Redis cluster (cluster mode enabled, 1 shard with 3 nodes, TLS required) running on Elasticache on AWS. This cluster has been set up for a couple of months now, and the code connecting to it has been using StackExchange since the start.

In the last couple of days, we started having issues connecting to it, receiving connection timeout every time we tried. Doing some trial and error we decided to disable TLS and we were then able to connect. We then decided to increase the ConnectTimeout from 5s to 60s, and we were then able to establish the connection between 30 and 50 seconds.

Since we did not change either the cluster or code we were wondering: is it normal that it takes 30+ seconds to establish a connection to a Redis cluster?

This is the code we used to test the connection to Redis:

Logger.Information($"Creating ConnectionMultiplexer with endpoint: {_redisSettings.Endpoint}");
var configurationOptions = new ConfigurationOptions
{
    Ssl = true,
    SslProtocols = SslProtocols.Tls12,
    ConnectTimeout = 60000,
    SyncTimeout = 5000,
    AsyncTimeout = 5000,
    ConnectRetry = 5
};
configurationOptions.EndPoints.Add(_redisSettings.Endpoint);
configurationOptions.CertificateValidation += (sender, certificate, chain, errors) =>
{
    Logger
        .ForContext("RedisCertificateIssuer", certificate?.Issuer)
        .ForContext("RedisCertificateIssuer", certificate?.Subject)
        .ForContext("RedisCertificatePublicKey", certificate?.GetPublicKeyString())
        .ForContext("RedisCertificateExpirationDateString", certificate?.GetExpirationDateString())
        .Information($"Redis Certificate Validation: {certificate?.ToString()}");
    
    return true;
};

var stringWriter = new StringWriter();
var redis = await ConnectionMultiplexer.ConnectAsync(configurationOptions, stringWriter);

Logger
    .ForContext("RedisConfig", redis.Configuration)
    .ForContext("RedisIsConnecting", redis.IsConnecting)
    .ForContext("RedisIsConnected", redis.IsConnected)
    .ForContext("RedisOperationCount", redis.OperationCount)
    .Information($"ConnectionMultiplexer created. Logs: ${stringWriter.ToString()}");

var redisDb = redis.GetDatabase();
var redisValue = await redisDb.StringGetAsync("a");

Logger.Information($"Retrieved value for key a: {redisValue.ToString()}");

The internal logs from the connect request were:

ConnectionMultiplexer created. Logs: $16:09:22.5761: Connecting (async) on .NET 6.0.25 (StackExchange.Redis: v2.7.33.41805)
16:09:22.8615: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379,syncTimeout=5000,asyncTimeout=5000,connectTimeout=60000,ssl=True,sslProtocols=Tls12,connectRetry=5
16:09:22.8616: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379/Interactive: Connecting...
16:09:23.0498: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: BeginConnectAsync
16:09:23.0513: 1 unique nodes specified (with tiebreaker)
16:09:23.0537: Configuring TLS
16:09:23.1603: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
16:09:23.1603: Allowing 1 endpoint(s) 00:01:00 to respond...
16:09:23.3535: Awaiting 1 available task completion(s) for 60000ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=10,Free=32757,Min=2,Max=32767), POOL: (Threads=19,QueuedItems=0,CompletedItems=5606,Timers=36)
16:09:36.5573: TLS connection established successfully using protocol: Tls12
16:09:36.5574: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379/Interactive: Connected 
16:09:36.5575: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Server handshake
16:09:36.5578: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Setting client name: ip-<IP>(SE.Redis-v2.7.33.41805)
16:09:36.5605: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Setting client lib/ver
16:09:36.5606: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Auto-configuring...
16:09:36.5614: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")...
16:09:36.5621: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379/Interactive: Writing: GET __Booksleeve_TieBreak
16:09:36.5622: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Sending critical tracer (handshake): ECHO
16:09:36.5622: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379/Interactive: Writing: ECHO
16:09:36.5622: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Flushing outbound buffer
16:09:36.5622: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: OnEstablishingAsync complete
16:09:36.5623: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Starting read
16:09:36.6498: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Auto-configured (CLIENT) connection-id: 23372
16:09:36.6498: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Auto-configured (INFO) role: primary
16:09:36.6499: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Auto-configured (INFO) version: 7.1.0
16:09:36.6516: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Auto-configured (INFO) server-type: Cluster
16:09:36.6537: Response from clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379/Interactive / GET __Booksleeve_TieBreak: (null)
16:09:36.6537: Response from clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379/Interactive / ECHO: BulkString: 16 bytes
16:09:37.6587: clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO)
16:09:37.6587: All 1 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=8,Free=32759,Min=2,Max=32767), POOL: (Threads=19,QueuedItems=0,CompletedItems=6499,Timers=36)
16:09:37.6587: Endpoint summary:
16:09:37.6626:   clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Endpoint is (Interactive: ConnectedEstablished, Subscription: ConnectedEstablished)
16:09:37.6627: Task summary:
16:09:37.6627:   clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Returned with success as Cluster primary (Source: From command: ECHO)
16:09:37.6659: ClusterName-0001-002.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
16:09:37.6659: ClusterName-0001-003.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
16:09:37.6659: ClusterName-0001-001.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
16:09:37.6659: Allowing 3 endpoint(s) 00:00:45.4950000 to respond...
16:09:37.6659: Awaiting 3 available task completion(s) for 45495ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=8,Free=32759,Min=2,Max=32767), POOL: (Threads=19,QueuedItems=0,CompletedItems=6502,Timers=40)
16:10:06.5518: ClusterName-0001-001.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO)
16:10:11.3493: ClusterName-0001-003.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO)
16:10:11.3598: ClusterName-0001-002.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO)
16:10:11.3598: All 3 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=5,Free=32762,Min=2,Max=32767), POOL: (Threads=14,QueuedItems=0,CompletedItems=7945,Timers=36)
16:10:11.3598: Endpoint summary:
16:10:11.3599:   ClusterName-0001-002.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Endpoint is (Interactive: ConnectedEstablished, Subscription: ConnectedEstablished)
16:10:11.3599:   ClusterName-0001-003.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Endpoint is (Interactive: ConnectedEstablished, Subscription: ConnectedEstablished)
16:10:11.3599:   ClusterName-0001-001.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Endpoint is (Interactive: ConnectedEstablished, Subscription: ConnectedEstablished)
16:10:11.3599: Task summary:
16:10:11.3600:   ClusterName-0001-002.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Returned with success as Cluster replica (Source: From command: ECHO)
16:10:11.3600:   ClusterName-0001-003.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Returned with success as Cluster replica (Source: From command: ECHO)
16:10:11.3600:   ClusterName-0001-001.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Returned with success as Cluster primary (Source: From command: ECHO)
16:10:11.3601: Cluster: 16384 of 16384 slots covered
16:10:11.4492: Endpoint Summary:
16:10:11.4499:   clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Cluster v7.1.0, primary; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
16:10:11.4518:   clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: int ops=14, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=6, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1
16:10:11.4647:   clustercfg.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+14=14 (1.40 ops/s; spans 10s); sub: 0+6=6 (0.60 ops/s; spans 10s)
16:10:11.4647:   ClusterName-0001-001.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Cluster v7.1.0, primary; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
16:10:11.4647:   ClusterName-0001-001.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: int ops=13, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=6, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1
16:10:11.4649:   ClusterName-0001-001.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+13=13 (1.30 ops/s; spans 10s); sub: 0+6=6 (0.60 ops/s; spans 10s)
16:10:11.4649:   ClusterName-0001-002.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Cluster v7.1.0, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
16:10:11.4649:   ClusterName-0001-002.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: int ops=14, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=6, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1
16:10:11.4649:   ClusterName-0001-002.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+14=14 (1.40 ops/s; spans 10s); sub: 0+6=6 (0.60 ops/s; spans 10s)
16:10:11.4649:   ClusterName-0001-003.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Cluster v7.1.0, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
16:10:11.4649:   ClusterName-0001-003.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: int ops=14, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=7, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1
16:10:11.4649:   ClusterName-0001-003.ClusterName.xxxxxx.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+14=14 (1.40 ops/s; spans 10s); sub: 0+7=7 (0.70 ops/s; spans 10s)
16:10:11.4650: Sync timeouts: 0; async timeouts: 0; fire and forget: 0; last heartbeat: -1s ago
16:10:11.4650: Starting heartbeat...
16:10:11.4651: Total connect time: 48,890 ms

Start at the ConnectionMultiplexer.ConnectAsync call and its ConfigurationOptions in the report, then compare the connection log timestamps around TLS setup and cluster-node handshakes. Done would require identifying and documenting the cause of the 48,890 ms connection time, but the issue does not name a source file, test, or specific code change.