Skip to content

Problems with IP change of Redis instances in failure scenarios #1891

Open
Open
Problems with IP change of Redis instances in failure scenarios#1891
Labels
⚙️ area:connection⚙️ area:sentinel💬 needs-info

Description

@ThomasTosik
ThomasTosik
opened on Oct 21, 2021

Hi,

we are testing failure scenarios and have some issues that we can not resolve. We are killing a Redis pod and some seconds later a new pod is spawned with a new IP. The Sentinel and Redis conglomerate has no issue with this scenario as far as we can tell from the logs. The newly joined Redis pod will be detected. Also a simulated Sentinel outage seems not problematic. Our application is also running without issues as long as Redis stays up.
The StackExchange.Redis initially notices that the old Redis pod is not available and reports correctly "StackExchange.Redis.RedisConnectionException: No connection is active/available to service this operation". But there is no switch to one of the other running Redis. He insists on using the old IP of the not anymore existing Redis pod. Even after the new Redis pod is available (with a new IP).
We can reliably produce this situation on all of our Kuberntes clusters. The only thing that currently works is restarting the affected application pod.
It seems we are missing something either in our Sentinel/Redis Cluster config or some secret in StackExchange.Redis ;).

Architecture:
3 Sentinels and 3 Redis in Kubernetes

Redis operator:
https://github.com/spotahome/redis-operator
redis alpine image 5.0.14

StackExchange.Redis version
2.2.79

We tried some client related stuff from other issues with no effect:

  • abortConnect and resolveDns had no effect
  • Register on ConnectionFailed events and try Configure or PublishReconfigure

Log from starting sequence:

Connecting (sync) on .NET 5.0.11
14:49:40.1726: rfs-redisfailover-persistent.redis.svc.cluster.local:26379,serviceName=mymaster,password=*****,abortConnect=False,resolveDns=True,$NONE=,$APPEND=,$ASKING=,$BGREWRITEAOF=,$BGSAVE=,$BITCOUNT=,$BITOP=,$BITPOS=,$BLPOP=,$BRPOP=,$BRPOPLPUSH=,$CLIENT=,$CLUSTER=,$CONFIG=,$DBSIZE=,$DEBUG=,$DECR=,$DECRBY=,$DEL=,$DISCARD=,$DUMP=,$ECHO=,$EVAL=,$EVALSHA=,$EXEC=,$EXISTS=,$EXPIRE=,$EXPIREAT=,$FLUSHALL=,$FLUSHDB=,$GEOADD=,$GEODIST=,$GEOHASH=,$GEOPOS=,$GEORADIUS=,$GEORADIUSBYMEMBER=,$GET=,$GETBIT=,$GETDEL=,$GETRANGE=,$GETSET=,$HDEL=,$HEXISTS=,$HGET=,$HGETALL=,$HINCRBY=,$HINCRBYFLOAT=,$HKEYS=,$HLEN=,$HMGET=,$HMSET=,$HSCAN=,$HSET=,$HSETNX=,$HSTRLEN=,$HVALS=,$INCR=,$INCRBY=,$INCRBYFLOAT=,$KEYS=,$LASTSAVE=,$LATENCY=,$LINDEX=,$LINSERT=,$LLEN=,$LPOP=,$LPUSH=,$LPUSHX=,$LRANGE=,$LREM=,$LSET=,$LTRIM=,$MEMORY=,$MGET=,$MIGRATE=,$MONITOR=,$MOVE=,$MSET=,$MSETNX=,$MULTI=,$OBJECT=,$PERSIST=,$PEXPIRE=,$PEXPIREAT=,$PFADD=,$PFCOUNT=,$PFMERGE=,$PSETEX=,$PTTL=,$PUBLISH=,$PUBSUB=,$QUIT=,$RANDOMKEY=,$READONLY=,$READWRITE=,$RENAME=,$RENAMENX=,$REPLICAOF=,$RESTORE=,$RPOP=,$RPOPLPUSH=,$RPUSH=,$RPUSHX=,$SADD=,$SAVE=,$SCAN=,$SCARD=,$SCRIPT=,$SDIFF=,$SDIFFSTORE=,$SELECT=,$SET=,$SETBIT=,$SETEX=,$SETNX=,$SETRANGE=,$SINTER=,$SINTERSTORE=,$SISMEMBER=,$SLAVEOF=,$SLOWLOG=,$SMEMBERS=,$SMOVE=,$SORT=,$SPOP=,$SRANDMEMBER=,$SREM=,$STRLEN=,$SUNION=,$SUNIONSTORE=,$SSCAN=,$SWAPDB=,$SYNC=,$TIME=,$TOUCH=,$TTL=,$TYPE=,$UNLINK=,$UNWATCH=,$WATCH=,$XACK=,$XADD=,$XCLAIM=,$XDEL=,$XGROUP=,$XINFO=,$XLEN=,$XPENDING=,$XRANGE=,$XREAD=,$XREADGROUP=,$XREVRANGE=,$XTRIM=,$ZADD=,$ZCARD=,$ZCOUNT=,$ZINCRBY=,$ZINTERSTORE=,$ZLEXCOUNT=,$ZPOPMAX=,$ZPOPMIN=,$ZRANGE=,$ZRANGEBYLEX=,$ZRANGEBYSCORE=,$ZRANK=,$ZREM=,$ZREMRANGEBYLEX=,$ZREMRANGEBYRANK=,$ZREMRANGEBYSCORE=,$ZREVRANGE=,$ZREVRANGEBYLEX=,$ZREVRANGEBYSCORE=,$ZREVRANK=,$ZSCAN=,$ZSCORE=,$ZUNIONSTORE=,$UNKNOWN=

14:49:40.1785: Using DNS to resolve 'rfs-redisfailover-persistent.redis.svc.cluster.local'...
14:49:40.1897: 'rfs-redisfailover-persistent.redis.svc.cluster.local' => 10.98.84.184
14:49:40.2282: 10.98.84.184:26379/Interactive: Connecting...
14:49:40.2585: 10.98.84.184:26379: BeginConnectAsync
14:49:40.2682: 1 unique nodes specified
14:49:40.2695: 10.98.84.184:26379: OnConnectedAsync init (State=Connecting)
14:49:40.2698: Allowing 1 endpoint(s) 00:00:05 to respond...
14:49:40.2764: 10.98.84.184:26379/Interactive: Connected
14:49:40.2772: Awaiting 1 available task completion(s) for 5000ms, IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=2,Free=32765,Min=1,Max=32767)
14:49:40.2813: 10.98.84.184:26379: Server handshake
14:49:40.2814: 10.98.84.184:26379: Authenticating (password)
14:49:40.3329: 10.98.84.184:26379: Auto-configuring...
14:49:40.3352: 10.98.84.184:26379: Sending critical tracer (handshake): PING
14:49:40.3355: 10.98.84.184:26379/Interactive: Writing: PING
14:49:40.3355: 10.98.84.184:26379: Flushing outbound buffer
14:49:40.3356: 10.98.84.184:26379: OnEstablishingAsync complete
14:49:40.3379: 10.98.84.184:26379: Starting read
14:49:40.4312: 10.98.84.184:26379: Auto-configured (SENTINEL) server-type: sentinel
14:49:40.4315: 10.98.84.184:26379: Auto-configured (INFO) version: 5.0.14
14:49:40.4315: 10.98.84.184:26379: Auto-configured (INFO) server-type: sentinel
14:49:40.4322: Response from 10.98.84.184:26379/Interactive / PING: SimpleString: PONG
14:49:40.4338: 10.98.84.184:26379: OnConnectedAsync completed (From command: PING)
14:49:40.4355: All 1 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=1,Free=32766,Min=1,Max=32767)
14:49:40.4356: 10.98.84.184:26379: Endpoint is ConnectedEstablished
14:49:40.4356: 10.98.84.184:26379: Returned with success as Sentinel primary (Source: From command: PING)
14:49:40.4469: Election: Single master detected: 10.98.84.184:26379
14:49:40.4470: 10.98.84.184:26379: Clearing as RedundantMaster
14:49:40.4495: 10.98.84.184:26379: Sentinel v5.0.14, master; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
14:49:40.4521: 10.98.84.184:26379: int ops=5, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=3, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1
14:49:40.4553: 10.98.84.184:26379: Circular op-count snapshot; int: 0+5=5 (0.50 ops/s; spans 10s); sub: 0+3=3 (0.30 ops/s; spans 10s)
14:49:40.4555: Sync timeouts: 0; async timeouts: 0; fire and forget: 0; last heartbeat: -1s ago
14:49:40.4556: Starting heartbeat...
Connecting (sync) on .NET 5.0.11
14:49:40.5619: 10.244.3.188:6379,10.244.2.245:6379,10.244.1.16:6379,serviceName=mymaster,password=*****,abortConnect=False,resolveDns=True

14:49:40.5620: 10.244.3.188:6379/Interactive: Connecting...
14:49:40.5622: 10.244.3.188:6379: BeginConnectAsync
14:49:40.5629: 10.244.2.245:6379/Interactive: Connecting...
14:49:40.5629: 10.244.3.188:6379/Interactive: Connected
14:49:40.5629: 10.244.3.188:6379: Server handshake
14:49:40.5629: 10.244.3.188:6379: Authenticating (password)
14:49:40.5630: 10.244.2.245:6379: BeginConnectAsync
14:49:40.5640: 10.244.1.16:6379/Interactive: Connecting...
14:49:40.5642: 10.244.1.16:6379: BeginConnectAsync
14:49:40.5645: 3 unique nodes specified
14:49:40.5645: 10.244.3.188:6379: OnConnectedAsync init (State=ConnectedEstablishing)
14:49:40.5645: 10.244.2.245:6379: OnConnectedAsync init (State=Connecting)
14:49:40.5645: 10.244.1.16:6379: OnConnectedAsync init (State=Connecting)
14:49:40.5645: Allowing 3 endpoint(s) 00:00:05 to respond...
14:49:40.5646: Awaiting 3 available task completion(s) for 5000ms, IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=1,Free=32766,Min=1,Max=32767)
14:49:40.5874: 10.244.3.188:6379: Setting client name: tenantservice-d45c7d58d-r8rtl
14:49:40.5876: 10.244.3.188:6379: Auto-configuring...
14:49:40.5887: 10.244.3.188:6379: Sending critical tracer (handshake): ECHO
14:49:40.5888: 10.244.3.188:6379/Interactive: Writing: ECHO
14:49:40.5890: 10.244.3.188:6379: Flushing outbound buffer
14:49:40.5890: 10.244.3.188:6379: OnEstablishingAsync complete
14:49:40.5890: 10.244.3.188:6379: Starting read
14:49:40.5918: 10.244.2.245:6379/Interactive: Connected
14:49:40.5918: 10.244.2.245:6379: Server handshake
14:49:40.5918: 10.244.2.245:6379: Authenticating (password)
14:49:40.5918: 10.244.2.245:6379: Setting client name: tenantservice-d45c7d58d-r8rtl
14:49:40.5919: 10.244.2.245:6379: Auto-configuring...
14:49:40.5919: 10.244.2.245:6379: Sending critical tracer (handshake): ECHO
14:49:40.5919: 10.244.2.245:6379/Interactive: Writing: ECHO
14:49:40.5919: 10.244.2.245:6379: Flushing outbound buffer
14:49:40.5919: 10.244.2.245:6379: OnEstablishingAsync complete
14:49:40.5919: 10.244.2.245:6379: Starting read
14:49:40.5922: 10.244.1.16:6379/Interactive: Connected
14:49:40.5922: 10.244.1.16:6379: Server handshake
14:49:40.5924: 10.244.1.16:6379: Authenticating (password)
14:49:40.5924: 10.244.1.16:6379: Setting client name: tenantservice-d45c7d58d-r8rtl
14:49:40.5924: 10.244.1.16:6379: Auto-configuring...
14:49:40.5924: 10.244.1.16:6379: Sending critical tracer (handshake): ECHO
14:49:40.5925: 10.244.1.16:6379/Interactive: Writing: ECHO
14:49:40.5925: 10.244.1.16:6379: Flushing outbound buffer
14:49:40.5925: 10.244.1.16:6379: OnEstablishingAsync complete
14:49:40.5925: 10.244.1.16:6379: Starting read
14:49:40.5931: 10.244.3.188:6379: Auto-configured (CONFIG) read-only replica: true
14:49:40.5931: 10.244.2.245:6379: Auto-configured (CONFIG) read-only replica: true
14:49:40.5932: 10.244.3.188:6379: Auto-configured (CONFIG) databases: 16
14:49:40.5933: 10.244.3.188:6379: Auto-configured (INFO) version: 5.0.14
14:49:40.5934: 10.244.3.188:6379: Auto-configured (INFO) server-type: standalone
14:49:40.5934: 10.244.2.245:6379: Auto-configured (CONFIG) databases: 16
14:49:40.5934: 10.244.1.16:6379: Auto-configured (CONFIG) read-only replica: true
14:49:40.5935: 10.244.2.245:6379: Auto-configured (INFO) version: 5.0.14
14:49:40.5935: 10.244.1.16:6379: Auto-configured (CONFIG) databases: 16
14:49:40.5935: 10.244.3.188:6379: Auto-configured (INFO) role: master
14:49:40.5936: 10.244.1.16:6379: Auto-configured (INFO) version: 5.0.14
14:49:40.5936: 10.244.1.16:6379: Auto-configured (INFO) server-type: standalone
14:49:40.5936: 10.244.2.245:6379: Auto-configured (INFO) server-type: standalone
14:49:40.5936: 10.244.1.16:6379: Auto-configured (INFO) role: replica
14:49:40.5937: 10.244.2.245:6379: Auto-configured (INFO) role: replica
14:49:40.5940: Response from 10.244.1.16:6379/Interactive / ECHO: BulkString: 16 bytes
14:49:40.5940: Response from 10.244.2.245:6379/Interactive / ECHO: BulkString: 16 bytes
14:49:40.5941: Response from 10.244.3.188:6379/Interactive / ECHO: BulkString: 16 bytes
14:49:40.6037: 10.244.1.16:6379: OnConnectedAsync completed (From command: ECHO)
14:49:40.6038: 10.244.2.245:6379: OnConnectedAsync completed (From command: ECHO)
14:49:40.6038: 10.244.3.188:6379: OnConnectedAsync completed (From command: ECHO)
14:49:40.6039: All 3 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=1,Free=32766,Min=1,Max=32767)
14:49:40.6039: 10.244.3.188:6379: Endpoint is ConnectedEstablished
14:49:40.6039: 10.244.2.245:6379: Endpoint is ConnectedEstablished
14:49:40.6040: 10.244.1.16:6379: Endpoint is ConnectedEstablished
14:49:40.6040: Election: Gathering tie-breakers...
14:49:40.6040: 10.244.3.188:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")...
14:49:40.6097: 10.244.3.188:6379/Interactive: Writing: GET __Booksleeve_TieBreak
14:49:40.6101: 10.244.2.245:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")...
14:49:40.6102: 10.244.2.245:6379/Interactive: Writing: GET __Booksleeve_TieBreak
14:49:40.6103: 10.244.1.16:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")...
14:49:40.6103: 10.244.1.16:6379/Interactive: Writing: GET __Booksleeve_TieBreak
14:49:40.6103: 10.244.3.188:6379: Returned with success as Standalone primary (Source: From command: ECHO)
14:49:40.6103: 10.244.2.245:6379: Returned with success as Standalone replica (Source: From command: ECHO)
14:49:40.6103: 10.244.1.16:6379: Returned with success as Standalone replica (Source: From command: ECHO)
14:49:40.6104: Waiting for tiebreakers...
14:49:40.6104: Awaiting 3 tiebreaker task completion(s) for 4955ms, IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=1,Free=32766,Min=1,Max=32767)
14:49:40.6122: Response from 10.244.3.188:6379/Interactive / GET __Booksleeve_TieBreak: (null)
14:49:40.6122: Response from 10.244.1.16:6379/Interactive / GET __Booksleeve_TieBreak: (null)
14:49:40.6123: Response from 10.244.2.245:6379/Interactive / GET __Booksleeve_TieBreak: (null)
14:49:40.6132: All 3 tiebreaker tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=1,Free=32766,Min=1,Max=32767)
14:49:40.6142: Election: 10.244.3.188:6379 had no tiebreaker set
14:49:40.6143: Election: 10.244.2.245:6379 had no tiebreaker set
14:49:40.6143: Election: 10.244.1.16:6379 had no tiebreaker set
14:49:40.6143: Election: Single master detected: 10.244.3.188:6379
14:49:40.6143: 10.244.3.188:6379: Clearing as RedundantMaster
14:49:40.6143: 10.244.3.188:6379: Standalone v5.0.14, master; 16 databases; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
14:49:40.6143: 10.244.3.188:6379: int ops=11, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=4, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1
14:49:40.6143: 10.244.3.188:6379: Circular op-count snapshot; int: 0+11=11 (1.10 ops/s; spans 10s); sub: 0+4=4 (0.40 ops/s; spans 10s)
14:49:40.6143: 10.244.2.245:6379: Standalone v5.0.14, replica; 16 databases; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
14:49:40.6144: 10.244.2.245:6379: int ops=11, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=4, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1
14:49:40.6144: 10.244.2.245:6379: Circular op-count snapshot; int: 0+11=11 (1.10 ops/s; spans 10s); sub: 0+4=4 (0.40 ops/s; spans 10s)
14:49:40.6144: 10.244.1.16:6379: Standalone v5.0.14, replica; 16 databases; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
14:49:40.6144: 10.244.1.16:6379: int ops=11, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=4, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1
14:49:40.6144: 10.244.1.16:6379: Circular op-count snapshot; int: 0+11=11 (1.10 ops/s; spans 10s); sub: 0+4=4 (0.40 ops/s; spans 10s)
14:49:40.6144: Sync timeouts: 0; async timeouts: 0; fire and forget: 0; last heartbeat: -1s ago
14:49:40.6144: Starting heartbeat...```

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    ⚙️ area:connection⚙️ area:sentinel💬 needs-info

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions