Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Refreshing slots cache infinite loop issue #1766

Open
NurimOnsemiro opened this issue Jun 8, 2023 · 4 comments
Open

Refreshing slots cache infinite loop issue #1766

NurimOnsemiro opened this issue Jun 8, 2023 · 4 comments

Comments

@NurimOnsemiro
Copy link

NurimOnsemiro commented Jun 8, 2023

Environment

  • ElastiCache (Redis 7.0.7)
  • Shard count: 3
  • Node Per Shard Count: 2 (1 Master and 1 Replica)
  • ioredis v5.2.4

Symptoms

When I call any command through the ioredis library, it throws a MOVED error, performs a refreshing slot cache, and succeeds in getting the correct cluster slot information. However, in the reset part, it is not reset correctly, causing a loop in the refreshing slot cache operation.
If the loop continues like that and exceeds the maximum number of times specified in the options, it will exit with a 'Too Many Redirections' error.

Redis Cluster Setup

this._client = new Redis.Cluster([{
  host,
  port
}], {
  scaleReads: 'slave',
  maxRedirections: envManager.atcsRedisClusterMaxRedirections,
  retryDelayOnMoved: 1000,
  redisOptions: {
    username: user,
    password,
    tls: isLocalEnv ? undefined : {
      host,
      port,
      rejectUnauthorized: false
    }
  }
})

ioredis debug log

2023-06-08T06:44:18.333Z ioredis:delayqueue send 1 commands in moved queue
2023-06-08T06:44:18.333Z ioredis:cluster command mget is moved to <redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379
2023-06-08T06:44:18.334Z ioredis:redis write command[10.1.7.172:6379]: 0 -> mget([ '<redacted>:{9998:default:2}:max_rps', '<redacted>:{9998:default:2}:current_request_count' ])
2023-06-08T06:44:18.334Z ioredis:cluster refreshing slot caches... (triggered by MOVED error)
2023-06-08T06:44:18.334Z ioredis:cluster getting slot cache from <redacted>-0003-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379
2023-06-08T06:44:18.334Z ioredis:redis status[<redacted>-0003-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379 (ioredis-cluster(refresher))]: wait -> wait
2023-06-08T06:44:18.334Z ioredis:redis status[<redacted>-0003-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379 (ioredis-cluster(refresher))]: wait -> connecting
2023-06-08T06:44:18.334Z ioredis:redis queue command[<redacted>-0003-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379 (ioredis-cluster(refresher))]: 0 -> cluster([ 'SLOTS' ])
2023-06-08T06:44:18.344Z ioredis:redis status[10.1.1.68:6379 (ioredis-cluster(refresher))]: connecting -> connect
2023-06-08T06:44:18.344Z ioredis:redis write command[10.1.1.68:6379 (ioredis-cluster(refresher))]: 0 -> auth([ 'default', 'redispw' ])
2023-06-08T06:44:18.344Z ioredis:redis status[10.1.1.68:6379 (ioredis-cluster(refresher))]: connect -> ready
2023-06-08T06:44:18.345Z ioredis:connection set the connection name [ioredis-cluster(refresher)]
2023-06-08T06:44:18.345Z ioredis:redis write command[10.1.1.68:6379 (ioredis-cluster(refresher))]: 0 -> client([ 'setname', 'ioredis-cluster(refresher)' ])
2023-06-08T06:44:18.345Z ioredis:connection set the connection to readonly mode
2023-06-08T06:44:18.345Z ioredis:redis write command[10.1.1.68:6379 (ioredis-cluster(refresher))]: 0 -> readonly([])
2023-06-08T06:44:18.345Z ioredis:connection send 1 commands in offline queue
2023-06-08T06:44:18.345Z ioredis:redis write command[10.1.1.68:6379 (ioredis-cluster(refresher))]: 0 -> cluster([ 'SLOTS' ])
2023-06-08T06:44:18.346Z ioredis:cluster cluster slots result count: 7
2023-06-08T06:44:18.346Z ioredis:cluster cluster slots result [0]: slots 0~545 served by [
  '<redacted>-0001-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0001-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:18.346Z ioredis:cluster cluster slots result [1]: slots 546~3275 served by [
  '<redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0003-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:18.347Z ioredis:cluster cluster slots result [2]: slots 3276~5110 served by [
  '<redacted>-0001-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0001-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:18.347Z ioredis:cluster cluster slots result [3]: slots 5111~8726 served by [
  '<redacted>-0002-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0002-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:18.347Z ioredis:cluster cluster slots result [4]: slots 8727~11457 served by [
  '<redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0003-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:18.347Z ioredis:cluster cluster slots result [5]: slots 11458~13302 served by [
  '<redacted>-0002-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0002-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:18.347Z ioredis:cluster cluster slots result [6]: slots 13303~16383 served by [
  '<redacted>-0001-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0001-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:18.371Z ioredis:cluster:connectionPool Reset with '[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object  ... <REDACTED full-length="223">'
2023-06-08T06:44:18.373Z ioredis:redis status[10.1.1.68:6379 (ioredis-cluster(refresher))]: ready -> close
2023-06-08T06:44:18.373Z ioredis:connection skip reconnecting since the connection is manually closed.
2023-06-08T06:44:18.373Z ioredis:redis status[10.1.1.68:6379 (ioredis-cluster(refresher))]: close -> end
2023-06-08T06:44:19.336Z ioredis:delayqueue send 1 commands in moved queue
2023-06-08T06:44:19.336Z ioredis:cluster command mget is moved to <redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379
2023-06-08T06:44:19.336Z ioredis:redis write command[10.1.7.172:6379]: 0 -> mget([ '<redacted>:{9998:default:2}:max_rps', '<redacted>:{9998:default:2}:current_request_count' ])
2023-06-08T06:44:19.337Z ioredis:cluster refreshing slot caches... (triggered by MOVED error)
2023-06-08T06:44:19.337Z ioredis:cluster getting slot cache from <redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379
2023-06-08T06:44:19.337Z ioredis:redis status[<redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379 (ioredis-cluster(refresher))]: wait -> wait
2023-06-08T06:44:19.337Z ioredis:redis status[<redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379 (ioredis-cluster(refresher))]: wait -> connecting
2023-06-08T06:44:19.337Z ioredis:redis queue command[<redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379 (ioredis-cluster(refresher))]: 0 -> cluster([ 'SLOTS' ])
2023-06-08T06:44:19.348Z ioredis:redis status[10.1.2.174:6379 (ioredis-cluster(refresher))]: connecting -> connect
2023-06-08T06:44:19.348Z ioredis:redis write command[10.1.2.174:6379 (ioredis-cluster(refresher))]: 0 -> auth([ 'default', 'redispw' ])
2023-06-08T06:44:19.348Z ioredis:redis status[10.1.2.174:6379 (ioredis-cluster(refresher))]: connect -> ready
2023-06-08T06:44:19.348Z ioredis:connection set the connection name [ioredis-cluster(refresher)]
2023-06-08T06:44:19.348Z ioredis:redis write command[10.1.2.174:6379 (ioredis-cluster(refresher))]: 0 -> client([ 'setname', 'ioredis-cluster(refresher)' ])
2023-06-08T06:44:19.348Z ioredis:connection send 1 commands in offline queue
2023-06-08T06:44:19.348Z ioredis:redis write command[10.1.2.174:6379 (ioredis-cluster(refresher))]: 0 -> cluster([ 'SLOTS' ])
2023-06-08T06:44:19.350Z ioredis:cluster cluster slots result count: 7
2023-06-08T06:44:19.350Z ioredis:cluster cluster slots result [0]: slots 0~545 served by [
  '<redacted>-0001-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0001-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:19.350Z ioredis:cluster cluster slots result [1]: slots 546~3275 served by [
  '<redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0003-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:19.350Z ioredis:cluster cluster slots result [2]: slots 3276~5110 served by [
  '<redacted>-0001-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0001-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:19.350Z ioredis:cluster cluster slots result [3]: slots 5111~8726 served by [
  '<redacted>-0002-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0002-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:19.350Z ioredis:cluster cluster slots result [4]: slots 8727~11457 served by [
  '<redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0003-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:19.350Z ioredis:cluster cluster slots result [5]: slots 11458~13302 served by [
  '<redacted>-0002-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0002-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:19.351Z ioredis:cluster cluster slots result [6]: slots 13303~16383 served by [
  '<redacted>-0001-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0001-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:19.370Z ioredis:cluster:connectionPool Reset with '[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object  ... <REDACTED full-length="223">'
2023-06-08T06:44:19.371Z ioredis:redis status[10.1.2.174:6379 (ioredis-cluster(refresher))]: ready -> close
2023-06-08T06:44:19.371Z ioredis:connection skip reconnecting since the connection is manually closed.
2023-06-08T06:44:19.371Z ioredis:redis status[10.1.2.174:6379 (ioredis-cluster(refresher))]: close -> end
2023-06-08T06:44:20.338Z ioredis:delayqueue send 1 commands in moved queue
2023-06-08T06:44:20.338Z ioredis:cluster command mget is moved to <redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379
2023-06-08T06:44:20.338Z ioredis:redis write command[10.1.7.172:6379]: 0 -> mget([ '<redacted>:{9998:default:2}:max_rps', '<redacted>:{9998:default:2}:current_request_count' ])
2023-06-08T06:44:20.339Z ioredis:cluster refreshing slot caches... (triggered by MOVED error)
2023-06-08T06:44:20.339Z ioredis:cluster getting slot cache from <redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379
2023-06-08T06:44:20.339Z ioredis:redis status[<redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379 (ioredis-cluster(refresher))]: wait -> wait
2023-06-08T06:44:20.339Z ioredis:redis status[<redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379 (ioredis-cluster(refresher))]: wait -> connecting
2023-06-08T06:44:20.339Z ioredis:redis queue command[<redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379 (ioredis-cluster(refresher))]: 0 -> cluster([ 'SLOTS' ])
2023-06-08T06:44:20.350Z ioredis:redis status[10.1.2.174:6379 (ioredis-cluster(refresher))]: connecting -> connect
2023-06-08T06:44:20.350Z ioredis:redis write command[10.1.2.174:6379 (ioredis-cluster(refresher))]: 0 -> auth([ 'default', 'redispw' ])
2023-06-08T06:44:20.350Z ioredis:redis status[10.1.2.174:6379 (ioredis-cluster(refresher))]: connect -> ready
2023-06-08T06:44:20.350Z ioredis:connection set the connection name [ioredis-cluster(refresher)]
2023-06-08T06:44:20.350Z ioredis:redis write command[10.1.2.174:6379 (ioredis-cluster(refresher))]: 0 -> client([ 'setname', 'ioredis-cluster(refresher)' ])
2023-06-08T06:44:20.350Z ioredis:connection send 1 commands in offline queue
2023-06-08T06:44:20.351Z ioredis:redis write command[10.1.2.174:6379 (ioredis-cluster(refresher))]: 0 -> cluster([ 'SLOTS' ])
2023-06-08T06:44:20.354Z ioredis:cluster cluster slots result count: 7
2023-06-08T06:44:20.354Z ioredis:cluster cluster slots result [0]: slots 0~545 served by [
  '<redacted>-0001-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0001-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:20.355Z ioredis:cluster cluster slots result [1]: slots 546~3275 served by [
  '<redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0003-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:20.355Z ioredis:cluster cluster slots result [2]: slots 3276~5110 served by [
  '<redacted>-0001-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0001-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:20.355Z ioredis:cluster cluster slots result [3]: slots 5111~8726 served by [
  '<redacted>-0002-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0002-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:20.355Z ioredis:cluster cluster slots result [4]: slots 8727~11457 served by [
  '<redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0003-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:20.355Z ioredis:cluster cluster slots result [5]: slots 11458~13302 served by [
  '<redacted>-0002-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0002-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:20.355Z ioredis:cluster cluster slots result [6]: slots 13303~16383 served by [
  '<redacted>-0001-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0001-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:20.375Z ioredis:cluster:connectionPool Reset with '[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object  ... <REDACTED full-length="223">'
2023-06-08T06:44:20.376Z ioredis:redis status[10.1.2.174:6379 (ioredis-cluster(refresher))]: ready -> close
2023-06-08T06:44:20.376Z ioredis:connection skip reconnecting since the connection is manually closed.
2023-06-08T06:44:20.376Z ioredis:redis status[10.1.2.174:6379 (ioredis-cluster(refresher))]: close -> end
2023-06-08T06:44:21.340Z ioredis:delayqueue send 1 commands in moved queue
2023-06-08T06:44:21.341Z ioredis:cluster command mget is moved to <redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379
2023-06-08T06:44:21.341Z ioredis:redis write command[10.1.7.172:6379]: 0 -> mget([ '<redacted>:{9998:default:2}:max_rps', '<redacted>:{9998:default:2}:current_request_count' ])
2023-06-08T06:44:21.341Z ioredis:cluster refreshing slot caches... (triggered by MOVED error)
2023-06-08T06:44:21.341Z ioredis:cluster getting slot cache from <redacted>-0001-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379
2023-06-08T06:44:21.341Z ioredis:redis status[<redacted>-0001-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379 (ioredis-cluster(refresher))]: wait -> wait
2023-06-08T06:44:21.341Z ioredis:redis status[<redacted>-0001-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379 (ioredis-cluster(refresher))]: wait -> connecting
2023-06-08T06:44:21.341Z ioredis:redis queue command[<redacted>-0001-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379 (ioredis-cluster(refresher))]: 0 -> cluster([ 'SLOTS' ])
2023-06-08T06:44:21.359Z ioredis:redis status[10.1.7.172:6379 (ioredis-cluster(refresher))]: connecting -> connect
2023-06-08T06:44:21.359Z ioredis:redis write command[10.1.7.172:6379 (ioredis-cluster(refresher))]: 0 -> auth([ 'default', 'redispw' ])
2023-06-08T06:44:21.359Z ioredis:redis status[10.1.7.172:6379 (ioredis-cluster(refresher))]: connect -> ready
2023-06-08T06:44:21.359Z ioredis:connection set the connection name [ioredis-cluster(refresher)]
2023-06-08T06:44:21.360Z ioredis:redis write command[10.1.7.172:6379 (ioredis-cluster(refresher))]: 0 -> client([ 'setname', 'ioredis-cluster(refresher)' ])
2023-06-08T06:44:21.360Z ioredis:connection set the connection to readonly mode
2023-06-08T06:44:21.360Z ioredis:redis write command[10.1.7.172:6379 (ioredis-cluster(refresher))]: 0 -> readonly([])
2023-06-08T06:44:21.360Z ioredis:connection send 1 commands in offline queue
2023-06-08T06:44:21.360Z ioredis:redis write command[10.1.7.172:6379 (ioredis-cluster(refresher))]: 0 -> cluster([ 'SLOTS' ])
2023-06-08T06:44:21.364Z ioredis:cluster cluster slots result count: 7
2023-06-08T06:44:21.364Z ioredis:cluster cluster slots result [0]: slots 0~545 served by [
  '<redacted>-0001-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0001-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:21.364Z ioredis:cluster cluster slots result [1]: slots 546~3275 served by [
  '<redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0003-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:21.365Z ioredis:cluster cluster slots result [2]: slots 3276~5110 served by [
  '<redacted>-0001-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0001-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:21.365Z ioredis:cluster cluster slots result [3]: slots 5111~8726 served by [
  '<redacted>-0002-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0002-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:21.367Z ioredis:cluster cluster slots result [4]: slots 8727~11457 served by [
  '<redacted>-0003-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0003-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:21.367Z ioredis:cluster cluster slots result [5]: slots 11458~13302 served by [
  '<redacted>-0002-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0002-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:21.367Z ioredis:cluster cluster slots result [6]: slots 13303~16383 served by [
  '<redacted>-0001-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0001-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T06:44:21.390Z ioredis:cluster:connectionPool Reset with '[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object  ... <REDACTED full-length="223">'
2023-06-08T06:44:21.392Z ioredis:redis status[10.1.7.172:6379 (ioredis-cluster(refresher))]: ready -> close
2023-06-08T06:44:21.392Z ioredis:connection skip reconnecting since the connection is manually closed.
2023-06-08T06:44:21.392Z ioredis:redis status[10.1.7.172:6379 (ioredis-cluster(refresher))]: close -> end
...loop

Is anyone else experiencing similar symptoms to me?

@NurimOnsemiro
Copy link
Author

As it turns out, we get the host and port information through the CLUSTER SLOTS command, but ElastiCache is not resetting correctly and disconnecting because host is a domain address.

2023-06-08T08:27:31.634Z ioredis:redis write command[10.1.2.174:6379 (ioredis-cluster(refresher))]: 0 -> cluster([ 'SLOTS' ])
2023-06-08T08:27:31.637Z ioredis:cluster cluster slots result count: 1
2023-06-08T08:27:31.637Z ioredis:cluster cluster slots result [0]: slots 0~16383 served by [
  '<redacted>-0001-001.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379',
  '<redacted>-0001-002.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379'
]
2023-06-08T08:27:31.661Z ioredis:cluster:connectionPool Reset with [
  {
    host: '<redacted>-0001-001.<redacted>.uusa8q.apn2.cache.amazonaws.com',
    port: 6379,
    readOnly: false
  },
  {
    host: '<redacted>-0001-002.<redacted>.uusa8q.apn2.cache.amazonaws.com',
    port: 6379,
    readOnly: true
  }
]
2023-06-08T08:27:31.661Z ioredis:cluster:connectionPool Disconnect 10.1.7.172:6379 because the node does not hold any slot
2023-06-08T08:27:31.661Z ioredis:redis status[10.1.7.172:6379]: wait -> close
2023-06-08T08:27:31.661Z ioredis:connection skip reconnecting since the connection is manually closed.
2023-06-08T08:27:31.661Z ioredis:redis status[10.1.7.172:6379]: close -> end

@NurimOnsemiro
Copy link
Author

NurimOnsemiro commented Jun 8, 2023

If you change the host value in lib/cluster/index.ts on line 863 to get the IP value first if there is an IP value, the above infinite loop problem will be solved.

for (let i = 0; i < result.length; ++i) {
  const items = result[i];
  const slotRangeStart = items[0];
  const slotRangeEnd = items[1];

  const keys = [];
  for (let j = 2; j < items.length; j++) {
    if (!items[j][0]) {
      continue;
    }
    this.options.natMap[`${items[j][0]}:${items[j][1]}`] = {
      host: items[j][3]?.[1] as string ?? items[j][0],
      port: items[j][1]
    }
    const node = this.natMapper({
      host: items[j][0],
      port: items[j][1],
    });
    node.readOnly = j !== 2;
    nodes.push(node);
    keys.push(node.host + ":" + node.port);
  }

@NurimOnsemiro
Copy link
Author

NurimOnsemiro commented Jun 8, 2023

Here is a sample of the output when calling the CLUSTER SLOTS command in ElastiCache.

clustercfg.<redacted>.uusa8q.apn2.cache.amazonaws.com:6379> cluster slots
1) 1) (integer) 0
   2) (integer) 8191
   3) 1) "<redacted>-0001-001.dev-nxcmd-atcs-apn2.uusa8q.apn2.cache.amazonaws.com"
      2) (integer) 6379
      3) "912f0c3b7373a15a81b06cfc0c67bcd82b4c96cc"
      4) 1) "ip"
         2) "10.1.2.174"
   4) 1) "<redacted>-0001-002.dev-nxcmd-atcs-apn2.uusa8q.apn2.cache.amazonaws.com"
      2) (integer) 6379
      3) "285c7f723d4c530e8da544453243581bd7e4603e"
      4) 1) "ip"
         2) "10.1.7.172"
2) 1) (integer) 8192
   2) (integer) 16383
   3) 1) "<redacted>-0002-001.dev-nxcmd-atcs-apn2.uusa8q.apn2.cache.amazonaws.com"
      2) (integer) 6379
      3) "7b5d4f6e3dfe986eab9acadec48097c82c8c4fc8"
      4) 1) "ip"
         2) "10.1.7.44"
   4) 1) "<redacted>-0002-002.dev-nxcmd-atcs-apn2.uusa8q.apn2.cache.amazonaws.com"
      2) (integer) 6379
      3) "2b6ab8b3e821d14c951c0b055ae6572cab3990fd"
      4) 1) "ip"
         2) "10.1.1.80"

@NurimOnsemiro
Copy link
Author

Removing host and port from the tls attribute in the cluster constructor options eliminated the reset infinite loop issue. We need to find the cause of this symptom.

this._client = new Redis.Cluster([{
  host,
  port
}], {
  scaleReads: 'slave',
  maxRedirections: envManager.atcsRedisClusterMaxRedirections,
  retryDelayOnMoved: 100,
  redisOptions: {
    username: user,
    password,
    tls: isLocalEnv ? undefined : {
      rejectUnauthorized: false
    }
  }
})

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant