Connect timeout when reusing same config endpoint

[Wyzzcow]

Hi,
We recently updated to the latest nuget package, and noticed our tests got 50x slower with the lastest package (2.1.58-> 2.5.61)
I narrowed down the issue to this commit
d9b3c58

After some debugging, it seems Connect times out when we reuse the same endpoint multiple times. We do this in our tests to reduce the number of redis containers needed to start (so for example, instead of having 10 separate instances, we only have 1 and configure all connection strings accordingly).
It seems to only occur with redis cluster (so not with a single standalone instance).
Reproducing is trivial (I reused an existing test here):

        [Fact]
        public void ThreadPoolManagerIsDetected()
        {
            var config = new ConfigurationOptions
            {
                EndPoints = { { IPAddress.Loopback, 6379 } },
                SocketManager = SocketManager.ThreadPool
            };
            var t = new StringWriter();
            using var muxer = ConnectionMultiplexer.Connect(config, log: t);
            using var muxer2 = ConnectionMultiplexer.Connect(config, log: t);
            using var muxer3 = ConnectionMultiplexer.Connect(config, log: t);
            using var muxer4 = ConnectionMultiplexer.Connect(config, log: t);
            Log(t.ToString());
            Assert.Same(PipeScheduler.ThreadPool, muxer.SocketManager.Scheduler);
        }

when inspecting the logs

18:39:17.7888: 172.16.255.3:7000: OnConnectedAsync already connected end
18:39:22.7858: Not all available tasks completed cleanly (from ReconfigureAsync#1744, timeout 4995ms), IOCP: (Busy=0,Free=1000,Min=12,Max=1000), WORKER: (Busy=2,Free=32765,Min=12,Max=32767), POOL: (Threads=16,QueuedItems=0,CompletedItems=403)
18:39:22.7858:   Server[0] (172.16.255.2:7001) Status: RanToCompletion (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: 0, out-pipe: 0, bw: Inactive, rs: ReadAsync. ws: Idle)
18:39:22.7858:   Server[1] (172.16.255.3:7000) Status: RanToCompletion (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: 0, out-pipe: 0, bw: Inactive, rs: ReadAsync. ws: Idle)
18:39:22.7858:   Server[2] (172.16.255.4:6379) Status: WaitingForActivation (inst: 11, qs: 0, in: 0, qu: 11, aw: False, in-pipe: 0, out-pipe: 0, bw: Inactive, rs: ReadAsync. ws: Idle)

we see one of the tasks (sometimes its several) ends up being stuck in WaitingForActivation. This doesn't seem to happen on the initial connect.
That commit is rather large, so it's hard to know what broke.
Thanks!

[AdamOutcalt]

Relieved that it's not just me! We hit the same issue in our code that throws away connections that we think are unhealthy and re-creates them. (That hasn't been a problem in a long time, but we still have that code.)

[NickCraver]

Are these by chance Sentinel connections? Asking because of port ranges and an issue with config re-use there (addressed in #2242). But there's also a chance it's a threadpool issue because I see you're explicitly opting into the .NET threadpool. Though whether that's an issue depends on your context and machine size (e.g. a small machine at startup can do this since you're fully synchronous).

For context: asking because I can't repro this on current...but it's possible we fixed it in some other way too.

[Wyzzcow]

Hi!
For the threadpool, I just re-used an existing test. Even when I remove the SocketManager option (so just endpoint configuration), it still is an issue.
I also re-tested on main, and the issue is still present.

The cluster is not sentinel, I use pretty much the same docker compose as what is described here
https://github.com/cpapidas/docker-compose-redis-cluster

[NickCraver]

I'm admittedly not following here. The docker compose linked does not listen on 6379, and the test config you're showing me is trying to connect on 6379 explicitly. I would expect this to fail, but also in the test config in this issue you're not connecting to 7001/7002 and I do see that in the logs...so I can't reconcile the code/docker/results here. What am I missing?

[Wyzzcow]

Hi,
My docker-compose is in a internal gitlab, so I couldn't share via a link. Here it is:

services:
  redis:
    image: library/redis:5.0.9
    ports:
      - "6379:6379"
      - "16379:16379"
    volumes:
      - ./docker-data/redis-cluster1.tmpl:/usr/local/etc/redis/redis.conf
    command: redis-server /usr/local/etc/redis/redis.conf
    networks:
      cluster:
        ipv4_address: 172.16.255.4
        
  redis2:
    image: library/redis:5.0.9
    ports:
      - "7000:7000"
      - "17000:17000"
    volumes:
      - ./docker-data/redis-cluster2.tmpl:/usr/local/etc/redis/redis.conf
    command: redis-server /usr/local/etc/redis/redis.conf
    networks:
      cluster:
        ipv4_address: 172.16.255.3
        
  redis3:
    image: library/redis:5.0.9
    ports:
      - "7001:7001"
      - "17001:17001"
    volumes:
      - ./docker-data/redis-cluster3.tmpl:/usr/local/etc/redis/redis.conf
    command: redis-server /usr/local/etc/redis/redis.conf
    networks:
      cluster:
        ipv4_address: 172.16.255.2
        
  redis-cluster:
    image: library/redis:5.0.9
    entrypoint: ["redis-cli", "--cluster-yes", "--cluster", "create", "--cluster-replicas", "0", "172.16.255.4:6379", "172.16.255.3:7000", "172.16.255.2:7001"]
    depends_on:
      - redis
      - redis2
      - redis3
    networks:
      cluster:
        ipv4_address: 172.16.255.7
networks:
  cluster:
    ipam:
      config:
        - subnet: 172.16.255.0/24

Sorry for the misleading information.

[NickCraver]

What's in the config files there? Can you connect to 6379 successfully with redis-cli, and are you running any other tests against this? I'm betting this is something with 6379 vs. other in the test suite but it's also a lot to get your setup and configs running to repro. Suggest changing ports to say 7000-7002 and see if it repros, or if something else is interfering. Also worth looking at the container logs and seeing if a failover or anything is being triggered.

Sorry for the back and forth but thus far: I can't repro, so can't confirm any reasoning.

[Wyzzcow]

So I decided to use the redis cluster setup from this repo https://github.com/cpapidas/docker-compose-redis-cluster/blob/master/docker-compose.yml but I modified the docker-compose to not have to build redis since its a bit long

version: '3'
services:
  redis1:
    image: "library/redis:5.0.9"
    ports:
      - "7000:7000"
    volumes:
      - ./docker-data/redis-cluster1.tmpl:/usr/local/etc/redis/redis.conf
    command: redis-server /usr/local/etc/redis/redis.conf
    networks:
      app_net:
        ipv4_address: 173.17.0.2
  redis2:
    image: "library/redis:5.0.9"
    ports:
      - "7001:7001"
    volumes:
      - ./docker-data/redis-cluster2.tmpl:/usr/local/etc/redis/redis.conf
    command: redis-server /usr/local/etc/redis/redis.conf
    networks:
      app_net:
        ipv4_address: 173.17.0.3
  redis3:
    image: "library/redis:5.0.9"
    ports:
      - "7002:7002"
    volumes:
      - ./docker-data/redis-cluster3.tmpl:/usr/local/etc/redis/redis.conf
    command: redis-server /usr/local/etc/redis/redis.conf
    networks:
      app_net:
        ipv4_address: 173.17.0.4
  redis-cluster:
    tty: true
    image: "library/redis:5.0.9"
    entrypoint: ["redis-cli", "--cluster-yes", "--cluster", "create", "--cluster-replicas", "0", "173.17.0.2:7000", "173.17.0.3:7001", "173.17.0.4:7002"]
    hostname: server
    depends_on:
      - redis1
      - redis2
      - redis3
    networks:
      app_net:
        ipv4_address: 173.17.0.5
networks:
  app_net:
    driver: bridge
    ipam:
      driver: default
      config:
        - subnet: 173.17.0.0/16

I've also attached the logs from the test run.
Test Output for ThreadPoolManagerIsDetected.Byxuqog.txt

[NickCraver]

@Wyzzcow Sorry I missed updating this - I believe you were affected by the issue resolved in #2268, available in the 2.6.70+ releases. Can you please see if you're still having issues after a 2.6.70 update?

[Wyzzcow]

Hi,
Just pulled latest main and still the same problem.
Test Output for DefaultThreadPoolManagerIsDetected.Ralumyt.txt
I've attached the logs in case you were curious.

[NickCraver]

It looks like it's connecting to 127.0.0.1 which is telling it the cluster IPs are on 172.16.255.2-4 - are you sure the client machine can connect to that entirely different subnet? I'd assume this is a networking issue based on what I'm seeing - would verify by running redis-cli in the container trying to connect to for example 172.16.255.3:7000 directly.

[Wyzzcow]

Hi,
thanks for pointing that out. I recently changed computers and I must have done something to redirect the docker internal ip for the cluster to point to localhost.
In any case, I have done that now, and indeed the regression is no more, tests are back to being executed without timeouts when reusing the same connection string.

[NickCraver]

Excellent, glad you figured it out!