search

carlos8f / haredis

High-availability redis in Node.js.
https://npmjs.org/package/haredis
154 stars 21 forks source link

Reintroduced master not slaved until next instance failure #8

Closed sheldonh closed 11 years ago

sheldonh commented 11 years ago

I'm familiarizing myself with haredis so that I can start encouraging my team to use it.

I have noticed that instances are not reslaved when they are rediscovered. Instead, they are reslaved when the next instance failure occurs.

Is this expected behaviour? Here is an example:

$ ./get-you-some-redis-cluster status
redis-server up on port 6380 (master)
redis-server up on port 6381 (slave)
redis-server up on port 6382 (slave)
Stopping redis-server on port 6380
...
[16:47:24](haredis#1) warning: elected 127.0.0.1:6381 as master!
[16:47:24](haredis#1) info: making 127.0.0.1:6382 into a slave...
...
$ ./get-you-some-redis-cluster status
redis-server down on port 6380
redis-server up on port 6381 (master)
redis-server up on port 6382 (slave)
$ ./get-you-some-redis-cluster start 6380
Starting redis-server on port 6380
...
[16:49:34](haredis#1) warning: reorientating (evaluating 127.0.0.1:6380) in 2000ms
...
$ ./get-you-some-redis-cluster status
redis-server up on port 6380 (master)
redis-server up on port 6381 (master)
redis-server up on port 6382 (slave)

# ... The cluster stays in this state forever, until ...

$ ./get-you-some-redis-cluster stop 6381
Stopping redis-server on port 6381
...
[16:54:55](haredis#1) warning: elected 127.0.0.1:6380 as master!
[16:54:55](haredis#1) info: making 127.0.0.1:6382 into a slave...
...
$ ./get-you-some-redis-cluster status
redis-server up on port 6380 (master)
redis-server down on port 6381
redis-server up on port 6382 (slave)

I am very new to node, redis and all this good stuff, so please excuse me if this sounds silly. It seems to me that it would be good for reintroduced instances to reslave quite soon, so that when they are next required, they'll be ready faster (because they're more up to date).

What do you think?

carlos8f commented 11 years ago

if there are 2 masters active and client.connected == true, that is a bug. i'll have to play around with your script and see if i can verify that. thanks for letting me know!

sheldonh commented 11 years ago

Yeah, I think we have a bug. I will try to hack up an automatic how-to-repeat, but I'm doing it manually at the moment, and losing data:

start 6380 6381 6382 6380 elected master lpush into a key # push 1 stop 6380 6381 elected master lpush into a key # push 2 start 6380 wait stop 6381 6380 elected master

At this point, the values from push 2 are lost.

On Thu, Apr 11, 2013 at 12:59 AM, Carlos Rodriguez <notifications@github.com

wrote:

if there are 2 masters active and client.connected == true, that is a bug. i'll have to play around with your script and see if i can verify that. thanks for letting me know!

— Reply to this email directly or view it on GitHubhttps://github.com/carlos8f/haredis/issues/8#issuecomment-16207734 .

sheldonh commented 11 years ago

Okay, I've hacked up a quick and dirty script that demonstrates the problem. Here is a log which I produced as follows from haredis-sad-times:

git clone https://github.com/sheldonh/haredis-sad-times
cd haredis-sad-times
npm install
./sad-times.sh

Hope it helps.

Already stopped redis-server on port 6380
Already stopped redis-server on port 6381
Already stopped redis-server on port 6382
Wiping configuration and persistent state
Starting redis-server on port 6380
Starting redis-server on port 6381
Starting redis-server on port 6382

>>> Waiting for a master...

close a connection on port 3000 to terminate
[13:36:26](haredis#1) warning: invalid master count: 3
[13:36:26](haredis#1) warning: attempting failover!
[13:36:26](haredis#1) warning: my failover id: fdrZRr2C
[13:36:26](haredis#1) info: lock was a success!
[13:36:26](haredis#1) warning: elected 127.0.0.1:6380 as master!
[13:36:26](haredis#1) info: making 127.0.0.1:6381 into a slave...
[13:36:26](haredis#1) info: making 127.0.0.1:6382 into a slave...
[13:36:26](haredis#1) warning: gossip said 127.0.0.1:6380 was promoted!
redis-server up on port 6380 (master)
redis-server up on port 6381 (slave)
redis-server up on port 6382 (slave)

>>> Incrementing admin:test:counter

(integer) 1
redis-server up on port 6380 (master) admin:test:counter is 1
redis-server up on port 6381 (slave) admin:test:counter is 1
redis-server up on port 6382 (slave) admin:test:counter is 1

>>> Stopping 6380

Stopping redis-server on port 6380
[13:36:29](haredis#1) warning: MASTER connection dropped, reconnecting...
[13:36:29](haredis#1) warning: Error: Redis connection to 127.0.0.1:6380 failed - connect ECONNREFUSED
[13:36:29](haredis#1) warning: Error: Redis connection to 127.0.0.1:6380 failed - connect ECONNREFUSED
[13:36:29](haredis#1) warning: Error: 127.0.0.1:6380 connection dropped and reconnection failed!
[13:36:29](haredis#1) ERROR: MASTER is down! (127.0.0.1:6380)
[13:36:29](haredis#1) warning: reorientating (node down) in 2000ms
[13:36:29](haredis#1) warning: Error: Redis connection to 127.0.0.1:6380 failed - connect ECONNREFUSED
[13:36:29](haredis#1) warning: Error: Redis connection to 127.0.0.1:6380 failed - connect ECONNREFUSED
redis-server down on port 6380
redis-server up on port 6381 (slave)
redis-server up on port 6382 (slave)

>>> Waiting for a master to be elected

[13:36:30](haredis#1) warning: Error: Redis connection to 127.0.0.1:6380 failed - connect ECONNREFUSED
[13:36:30](haredis#1) warning: Error: Redis connection to 127.0.0.1:6380 failed - connect ECONNREFUSED
[13:36:31](haredis#1) warning: invalid master count: 0
[13:36:31](haredis#1) warning: attempting failover!
[13:36:31](haredis#1) warning: my failover id: O3Tpoya3
[13:36:31](haredis#1) info: lock was a success!
[13:36:31](haredis#1) warning: elected 127.0.0.1:6381 as master!
[13:36:31](haredis#1) info: making 127.0.0.1:6382 into a slave...
[13:36:31](haredis#1) warning: orientate complete, using 127.0.0.1:6381 as master
[13:36:31](haredis#1) warning: gossip said 127.0.0.1:6381 was promoted!
[13:36:31](haredis#1) warning: Error: Redis connection to 127.0.0.1:6380 failed - connect ECONNREFUSED
[13:36:31](haredis#1) warning: Error: Redis connection to 127.0.0.1:6380 failed - connect ECONNREFUSED
redis-server up on port 6381 (master)

>>> Incrementing admin:test:counter

(integer) 2
redis-server down on port 6380 admin:test:counter is 
redis-server up on port 6381 (master) admin:test:counter is 2
redis-server up on port 6382 (slave) admin:test:counter is 2

>>> Starting 6380

Starting redis-server on port 6380
[13:36:33](haredis#1) warning: reorientating (evaluating 127.0.0.1:6380) in 2000ms
redis-server up on port 6380 (master)
redis-server up on port 6381 (master)
redis-server up on port 6382 (slave)

>>> Incrementing admin:test:counter

(integer) 3
redis-server up on port 6380 (master) admin:test:counter is 1
redis-server up on port 6381 (master) admin:test:counter is 3
redis-server up on port 6382 (slave) admin:test:counter is 3

>>> Sleeping 2 seconds to give 6380 time to reorientate

redis-server up on port 6380 (master) admin:test:counter is 1
redis-server up on port 6381 (master) admin:test:counter is 3
redis-server up on port 6382 (slave) admin:test:counter is 3

>>> See? No such luck. And now for the data loss...

>>> Stopping 6381

Stopping redis-server on port 6381
[13:36:37](haredis#1) warning: MASTER connection dropped, reconnecting...
[13:36:38](haredis#1) warning: Error: Redis connection to 127.0.0.1:6381 failed - connect ECONNREFUSED
[13:36:38](haredis#1) warning: Error: Redis connection to 127.0.0.1:6381 failed - connect ECONNREFUSED
[13:36:38](haredis#1) warning: Error: 127.0.0.1:6381 connection dropped and reconnection failed!
[13:36:38](haredis#1) ERROR: MASTER is down! (127.0.0.1:6381)
[13:36:38](haredis#1) warning: reorientating (node down) in 2000ms
[13:36:38](haredis#1) warning: Error: Redis connection to 127.0.0.1:6381 failed - connect ECONNREFUSED
[13:36:38](haredis#1) warning: Error: Redis connection to 127.0.0.1:6381 failed - connect ECONNREFUSED
redis-server up on port 6380 (master)
redis-server down on port 6381
redis-server up on port 6382 (slave)
redis-server up on port 6380 (master) admin:test:counter is 1
redis-server down on port 6381 admin:test:counter is 
redis-server up on port 6382 (slave) admin:test:counter is 3

>>> Waiting for 6382 to be enslaved to 6380

[13:36:39](haredis#1) warning: Error: Redis connection to 127.0.0.1:6381 failed - connect ECONNREFUSED
[13:36:39](haredis#1) warning: Error: Redis connection to 127.0.0.1:6381 failed - connect ECONNREFUSED
[13:36:40](haredis#1) warning: master conflict detected
[13:36:40](haredis#1) warning: attempting failover!
[13:36:40](haredis#1) warning: my failover id: 6R2hfLdB
[13:36:40](haredis#1) info: lock was a success!
[13:36:40](haredis#1) warning: elected 127.0.0.1:6380 as master!
[13:36:40](haredis#1) info: making 127.0.0.1:6382 into a slave...
[13:36:40](haredis#1) warning: orientate complete, using 127.0.0.1:6380 as master
[13:36:40](haredis#1) warning: Error: Redis connection to 127.0.0.1:6381 failed - connect ECONNREFUSED
[13:36:40](haredis#1) warning: Error: Redis connection to 127.0.0.1:6381 failed - connect ECONNREFUSED
redis-server up on port 6380 (master) admin:test:counter is 1
redis-server down on port 6381 admin:test:counter is 
redis-server up on port 6382 (slave) admin:test:counter is 1

>>> That's all, folks

Stopping redis-server on port 6380
Already stopped redis-server on port 6381
Stopping redis-server on port 6382
carlos8f commented 11 years ago

putting this bug on my calendar to investigate soon.

jacklevy commented 11 years ago

it looks like the issue is related to the sequence that follows from the lib/node.js "up" event listener: https://github.com/carlos8f/haredis/blob/master/index.js#L483

when a redis server that is default-configured to be master comes back online, the node-redis "connect" event in lib/node.js in turn emits an "up" event. the haredis "up" eventlistener calls self.reorientate, which ultimately calls self.orientate after a wait time. however, the orientate() function is coded to return if this.ready is true: https://github.com/carlos8f/haredis/blob/master/index.js#L572

this.ready is set to true in this scenario, since the cluster is functioning properly with a re-elected master, which skips the reorientation, and leaves the reconnected master in its orphaned state.

as one data point, if i remove the this.ready check and allow orientate() to run, i can confirm that it does properly detect the dual-master configuration and reconfigure the reconnected node server to become a slave of the current master. but i am guessing that the this.ready check was deliberately added to address some other issues, so i can't confidently say that removing this check is an appropriate fix.

carlos8f commented 11 years ago

good catch, I think the this.ready check was added to ensure that orientate doesn't run unnecessarily if one just ran (a situation which could arise from a race condition), but I'm not sure if that race condition exists or what circumstances would trigger it. needs more thought.

i think there needs to be an "orientate anyway" if since the last orientate a downed node comes back up, instead of just checking this.ready.

sdarwin commented 11 years ago

What are the best practices currently for end-users to handle this bug? manually issue SLAVEOF command on a returned master?

If this happens every time that a master dies and then comes back online, it's a pretty big deal, in terms of data loss.

carlos8f commented 11 years ago

@sdarwin I agree it's a big deal. In theory @jacklevy 's suggestion of removing the this.ready check is a workaround with no obvious drawback, other than the orientate process may run more times than necessary. I need to write proper failover tests (#11) in order to verify a fix for this issue, but in the mean time you could fork the project with that small change applied. I don't recommend issuing SLAVEOF commands yourself, if you are running haredis.

carlos8f commented 11 years ago

@sheldonh @jacklevy @sdarwin published v0.2.11 which should fix this. Please let me know if you experience otherwise!

carlos8f commented 11 years ago

FYI additionally I found two more issues:

  1. with v0.2.11, there was a small gap of time (2 seconds) between when the old master came online and when reorientate() takes effect, during which there are two masters in play resulting in strange stuff.
  2. also the opcounterDiviser option defaults to 100, so 100 writes need to be done for the opcounter to change. this means in the event of an opcounter "tie", a stale node could be promoted. This is intended to prevent too much overhead from opcounter increments, but is obviously flawed. (Probably this needs to be changed to a throttling system, i.e. increment the opcounter after 500ms unless another write is triggered before that, with a write limit to force an increment)

For issue 1, I switched to an immediate orientate() which will prevent that gap of multiple masters.

For issue 2, instead of the first node in the node list having priority in event of an opcounter tie, the priority is sorted by uptime of the socket to redis. This way if a node disconnects and then reconnects, that node will not have priority over a node which was connected for the duration.

Fixes published in v0.2.12.