CLUSTER FAILOVER not working (manual failover) #1587

Closed
HeartSaVioR opened this Issue Mar 10, 2014 · 5 comments

2 participants

@HeartSaVioR

Redis version is unstable branch, commit 0f25970.

I was implementing CLUSTER FAILOVER to Jedis, but I realized it's not working after making unit tests on it.

(Unit tests: https://github.com/HeartSaVioR/jedis/blob/54afcb1776c79dcf5747e617275f7843d1330be5/src/test/java/redis/clients/jedis/tests/JedisClusterReplicateTest.java / I've marked to @Ignore)

Cluster Setup

3 master, 3 slave / 1 on 1 Replication

127.0.0.1:7379 - 127.0.0.1:7382 / slots: 0 ~ 5460
127.0.0.1:7380 - 127.0.0.1:7383 / slots: 5461 ~ 10922
127.0.0.1:7381 - 127.0.0.1:7384 / slots: 10923 ~ 16384

Cluster Setup Sequence

  • join 6 nodes into cluster (5 CLUSTER MEET commands)
  • registered slots to 3 master nodes (3 CLUSTER ADDSLOTS commands)
  • replicate node to 1on1 (3 CLUSTER REPLICATE commands)
  • wait for replicate ready & cluster ready

Situation

Two Situation exists - there's no data in master / one data in master.
(I've not tested if there are many datas in master)

A. No data in master (node 1 & 4)

  • node1 log

[16239] 10 Mar 08:51:53.193 * Max number of open files set to 10032
[16239] 10 Mar 08:51:53.206 * No cluster configuration found, I'm 5616462e188108d62205aedc397202b848e802e2
                _._
           _.-``__ ''-._
      _.-``    `.  `_.  ''-._           Redis 2.9.11 (0f259709/0) 64 bit
  .-`` .-```.  ```\/    _.,_ ''-._
 (    '      ,       .-`  | `,    )     Running in cluster mode
 |`-._`-...-` __...-.``-._|'` _.-'|     Port: 7379
 |    `-._   `._    /     _.-'    |     PID: 16239
  `-._    `-._  `-./  _.-'    _.-'
 |`-._`-._    `-.__.-'    _.-'_.-'|
 |    `-._`-._        _.-'_.-'    |           http://redis.io
  `-._    `-._`-.__.-'_.-'    _.-'
 |`-._`-._    `-.__.-'    _.-'_.-'|
 |    `-._`-._        _.-'_.-'    |
  `-._    `-._`-.__.-'_.-'    _.-'
      `-._    `-.__.-'    _.-'
          `-._        _.-'
              `-.__.-'

[16239] 10 Mar 08:51:53.209 # Server started, Redis version 2.9.11
[16239] 10 Mar 08:51:53.209 * DB loaded from disk: 0.000 seconds
[16239] 10 Mar 08:51:53.210 * The server is now ready to accept connections on port 7379
[16239] 10 Mar 08:52:00.815 # Cluster state changed: ok
[16239] 10 Mar 08:52:01.096 # Manual failover requested by slave 4e28fb2295ce524d7b3478617282bbcb9bf00245.
[16239] 10 Mar 08:52:06.157 # Manual failover timed out.
[16239] 10 Mar 08:52:06.168 # Cluster state changed: fail
[16239] 10 Mar 08:52:06.172 * Slave asks for synchronization
[16239] 10 Mar 08:52:06.172 * Full resync requested by slave.
[16239] 10 Mar 08:52:06.172 * Starting BGSAVE for SYNC
[16239] 10 Mar 08:52:06.173 * Background saving started by pid 16267
[16267] 10 Mar 08:52:06.175 * DB saved on disk
[16239] 10 Mar 08:52:06.258 * Background saving terminated with success
[16239] 10 Mar 08:52:06.259 * Synchronization with slave succeeded
  • node4 log


[16251] 10 Mar 08:51:53.282 * Max number of open files set to 10032
[16251] 10 Mar 08:51:53.304 * No cluster configuration found, I'm 4e28fb2295ce524d7b3478617282bbcb9bf00245
                _._
           _.-``__ ''-._
      _.-``    `.  `_.  ''-._           Redis 2.9.11 (0f259709/0) 64 bit
  .-`` .-```.  ```\/    _.,_ ''-._
 (    '      ,       .-`  | `,    )     Running in cluster mode
 |`-._`-...-` __...-.``-._|'` _.-'|     Port: 7382
 |    `-._   `._    /     _.-'    |     PID: 16251
  `-._    `-._  `-./  _.-'    _.-'
 |`-._`-._    `-.__.-'    _.-'_.-'|
 |    `-._`-._        _.-'_.-'    |           http://redis.io
  `-._    `-._`-.__.-'_.-'    _.-'
 |`-._`-._    `-.__.-'    _.-'_.-'|
 |    `-._`-._        _.-'_.-'    |
  `-._    `-._`-.__.-'_.-'    _.-'
      `-._    `-.__.-'    _.-'
          `-._        _.-'
              `-.__.-'

[16251] 10 Mar 08:51:53.306 # Server started, Redis version 2.9.11
[16251] 10 Mar 08:51:53.306 * DB loaded from disk: 0.000 seconds
[16251] 10 Mar 08:51:53.306 * The server is now ready to accept connections on port 7382
[16251] 10 Mar 08:52:00.649 # Handshake error: we already know node c2319636c5a6023e13b1af5ffb2edc4f12582172, updating the address if needed.
[16251] 10 Mar 08:52:00.651 # Handshake error: we already know node b16c2d0b96d8ed092d058278bd55bdc438455ef9, updating the address if needed.
[16251] 10 Mar 08:52:00.835 # Cluster state changed: ok
[16251] 10 Mar 08:52:01.096 # Manual failover user request accepted.
[16251] 10 Mar 08:52:01.115 # Received replication offset for paused master manual failover: 0
[16251] 10 Mar 08:52:01.137 # Received replication offset for paused master manual failover: 0
...
[16251] 10 Mar 08:52:01.338 # Received replication offset for paused master manual failover: 0
[16251] 10 Mar 08:52:01.418 # Received replication offset for paused master manual failover: 0
[16251] 10 Mar 08:52:01.438 * Connecting to MASTER 127.0.0.1:7379
[16251] 10 Mar 08:52:01.439 * MASTER <-> SLAVE sync started
[16251] 10 Mar 08:52:01.439 * Non blocking connect for SYNC fired the event.
[16251] 10 Mar 08:52:01.441 # Received replication offset for paused master manual failover: 0
[16251] 10 Mar 08:52:01.519 # Received replication offset for paused master manual failover: 0
...
[16251] 10 Mar 08:52:06.085 # Received replication offset for paused master manual failover: 0
[16251] 10 Mar 08:52:06.170 # Received replication offset for paused master manual failover: 0
[16251] 10 Mar 08:52:06.170 * Master replied to PING, replication can continue...
[16251] 10 Mar 08:52:06.172 * Partial resynchronization not possible (no cached master)
[16251] 10 Mar 08:52:06.173 * Full resync from master: d472d40954cfb3088663336defadc9620013773a:1
[16251] 10 Mar 08:52:06.185 # Manual failover timed out.
[16251] 10 Mar 08:52:06.259 * MASTER <-> SLAVE sync: receiving 18 bytes from master
[16251] 10 Mar 08:52:06.260 * MASTER <-> SLAVE sync: Flushing old data
[16251] 10 Mar 08:52:06.260 * MASTER <-> SLAVE sync: Loading DB in memory
[16251] 10 Mar 08:52:06.261 * MASTER <-> SLAVE sync: Finished with success

B. One data in master (node 2 & 5)

  • node2 log

[16952] 10 Mar 08:57:24.510 * Max number of open files set to 10032
[16952] 10 Mar 08:57:24.522 * No cluster configuration found, I'm ce4f4a3606e308139ee0184e2ff7ffc4de753e16
                _._
           _.-``__ ''-._
      _.-``    `.  `_.  ''-._           Redis 2.9.11 (0f259709/0) 64 bit
  .-`` .-```.  ```\/    _.,_ ''-._
 (    '      ,       .-`  | `,    )     Running in cluster mode
 |`-._`-...-` __...-.``-._|'` _.-'|     Port: 7380
 |    `-._   `._    /     _.-'    |     PID: 16952
  `-._    `-._  `-./  _.-'    _.-'
 |`-._`-._    `-.__.-'    _.-'_.-'|
 |    `-._`-._        _.-'_.-'    |           http://redis.io
  `-._    `-._`-.__.-'_.-'    _.-'
 |`-._`-._    `-.__.-'    _.-'_.-'|
 |    `-._`-._        _.-'_.-'    |
  `-._    `-._`-.__.-'_.-'    _.-'
      `-._    `-.__.-'    _.-'
          `-._        _.-'
              `-.__.-'

[16952] 10 Mar 08:57:24.523 # Server started, Redis version 2.9.11
[16952] 10 Mar 08:57:24.524 * DB loaded from disk: 0.000 seconds
[16952] 10 Mar 08:57:24.524 * The server is now ready to accept connections on port 7380
[16952] 10 Mar 08:57:50.414 # Handshake error: we already know node 6e5af227faf1e67fecf1d78f20f77bb5eff5a553, updating the address if needed.
[16952] 10 Mar 08:57:50.417 # Handshake error: we already know node c41b861f615062256a83046b55dbb2e3f1d22d31, updating the address if needed.
[16952] 10 Mar 08:57:50.514 # Handshake error: we already know node 25cac37649f562220d79c475aa982744efe6af35, updating the address if needed.
[16952] 10 Mar 08:57:50.606 # Cluster state changed: ok
[16952] 10 Mar 08:57:51.356 * Slave asks for synchronization
[16952] 10 Mar 08:57:51.356 * Full resync requested by slave.
[16952] 10 Mar 08:57:51.356 * Starting BGSAVE for SYNC
[16952] 10 Mar 08:57:51.357 * Background saving started by pid 16977
[16952] 10 Mar 08:57:51.357 # Manual failover requested by slave 5134d68918f9b0b526e3eb67f3805579bfd2b579.
[16977] 10 Mar 08:57:51.358 * DB saved on disk
[16952] 10 Mar 08:57:51.454 * Background saving terminated with success
[16952] 10 Mar 08:57:51.454 * Synchronization with slave succeeded
[16952] 10 Mar 08:57:56.446 # Manual failover timed out.
[16952] 10 Mar 08:57:56.456 # Cluster state changed: fail
  • node5 log


[16964] 10 Mar 08:57:24.593 * Max number of open files set to 10032
[16964] 10 Mar 08:57:24.605 * No cluster configuration found, I'm 5134d68918f9b0b526e3eb67f3805579bfd2b579
                _._
           _.-``__ ''-._
      _.-``    `.  `_.  ''-._           Redis 2.9.11 (0f259709/0) 64 bit
  .-`` .-```.  ```\/    _.,_ ''-._
 (    '      ,       .-`  | `,    )     Running in cluster mode
 |`-._`-...-` __...-.``-._|'` _.-'|     Port: 7383
 |    `-._   `._    /     _.-'    |     PID: 16964
  `-._    `-._  `-./  _.-'    _.-'
 |`-._`-._    `-.__.-'    _.-'_.-'|
 |    `-._`-._        _.-'_.-'    |           http://redis.io
  `-._    `-._`-.__.-'_.-'    _.-'
 |`-._`-._    `-.__.-'    _.-'_.-'|
 |    `-._`-._        _.-'_.-'    |
  `-._    `-._`-.__.-'_.-'    _.-'
      `-._    `-.__.-'    _.-'
          `-._        _.-'
              `-.__.-'

[16964] 10 Mar 08:57:24.607 # Server started, Redis version 2.9.11
[16964] 10 Mar 08:57:24.607 * DB loaded from disk: 0.000 seconds
[16964] 10 Mar 08:57:24.607 * The server is now ready to accept connections on port 7383
[16964] 10 Mar 08:57:50.504 # Handshake error: we already know node 25cac37649f562220d79c475aa982744efe6af35, updating the address if needed.
[16964] 10 Mar 08:57:50.505 # Handshake error: we already know node 6e5af227faf1e67fecf1d78f20f77bb5eff5a553, updating the address if needed.
[16964] 10 Mar 08:57:50.509 # Handshake error: we already know node c41b861f615062256a83046b55dbb2e3f1d22d31, updating the address if needed.
[16964] 10 Mar 08:57:50.516 # Handshake error: we already know node ce4f4a3606e308139ee0184e2ff7ffc4de753e16, updating the address if needed.
[16964] 10 Mar 08:57:50.582 # Cluster state changed: ok
[16964] 10 Mar 08:57:51.347 * Connecting to MASTER 127.0.0.1:7380
[16964] 10 Mar 08:57:51.347 * MASTER <-> SLAVE sync started
[16964] 10 Mar 08:57:51.348 * Non blocking connect for SYNC fired the event.
[16964] 10 Mar 08:57:51.355 * Master replied to PING, replication can continue...
[16964] 10 Mar 08:57:51.355 * Partial resynchronization not possible (no cached master)
[16964] 10 Mar 08:57:51.356 * Full resync from master: 2fe2496932cfc91db274e05f1b75b429440e4f85:1
[16964] 10 Mar 08:57:51.356 # Manual failover user request accepted.
[16964] 10 Mar 08:57:51.451 # Received replication offset for paused master manual failover: 1
[16964] 10 Mar 08:57:51.454 * MASTER <-> SLAVE sync: receiving 27 bytes from master
[16964] 10 Mar 08:57:51.455 * MASTER <-> SLAVE sync: Flushing old data
[16964] 10 Mar 08:57:51.455 * MASTER <-> SLAVE sync: Loading DB in memory
[16964] 10 Mar 08:57:51.455 * MASTER <-> SLAVE sync: Finished with success
[16964] 10 Mar 08:57:51.604 # All master replication stream processed, manual failover can start.
[16964] 10 Mar 08:57:51.604 # Start of election delayed for 0 milliseconds (rank #0, offset 1).
[16964] 10 Mar 08:57:51.805 # Start of election delayed for 0 milliseconds (rank #0, offset 1).
[16964] 10 Mar 08:57:52.007 # Start of election delayed for 0 milliseconds (rank #0, offset 1).
…
[16964] 10 Mar 08:57:55.846 # Start of election delayed for 0 milliseconds (rank #0, offset 1).
[16964] 10 Mar 08:57:56.147 # Start of election delayed for 0 milliseconds (rank #0, offset 1).
[16964] 10 Mar 08:57:56.348 # Start of election delayed for 0 milliseconds (rank #0, offset 15).
[16964] 10 Mar 08:57:56.448 # Manual failover timed out.
@antirez
Owner

Hello, my feeling is that cluster-node-timeout is set to an extremely low value, is it possible? Please node that this value is in milliseconds.

@HeartSaVioR

@antirez Hello!
I reviewed cluster node configurations and exactly you're right! It's 50 ms.
I'll change to 50000ms (all nodes are localhost) and retry.
Thank you!

@antirez antirez added this to the Redis 3.0 milestone Mar 10, 2014
@antirez
Owner

Thanks, btw if you could, please also reset it to 50 milliseconds again and retry with latest unstable commit. I believe I fixed the case where you want to manaul failover with an extremely short node-timeout. Thanks.

@HeartSaVioR

@antirez It works!
I've modified it to 100000ms, but it could be reduced (as your patch did.)
I've reduced cluster-node-timeout to 5000ms and succeed again.
Thanks a lot!

@antirez
Owner

Thanks for retesting!

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