A 3-nodes cluster of YugaByte doesn't tolerate an isolation of a single node

[rystsov]

Hi folks,

I was testing how a 3-nodes cluster of YugaByte behaves (from a client perspective) when one of the nodes is isolated from the peers and observed an anomaly: the whole system became unavailable until a connection was restored.

Repo with Docker+JavaScript scripts to reproduce the problem: https://github.com/rystsov/perseus/tree/master/yugabyte

Testing environment

OS: Ubuntu 17.10
YugaByte: v0.9.1.0
NodeJS: v8.9.4
Redis's "redis" driver: "2.8.0"

A client executes three coroutines each of them connects to a corresponding YugaByte's node (yuga1, yuga2 and yuga3) and in a loop:

1. Reads a value from a db
2. Increments it
3. Writes it back

Each coroutine uses a different key to avoid collisions.

The client aggregates a number of successful iterations and dumps it every second:

#legend: time|yuga1|yuga2|yuga3|yuga1:err|yuga2:err|yuga3:err
1	70	68	118	0	0	0	2018/01/24 04:27:40
2	82	85	141	0	0	0	2018/01/24 04:27:41

The first column is the number of passed seconds since the beginning of the experiment; the next three columns contain counter of successful iterations of the clients located on each node per last second, following three columns are counters of errors and the last one is time.

After I isolated a yuga3 node the system became unavailable at least for 366 seconds:

#legend: time|yuga1|yuga2|yuga3|yuga1:err|yuga2:err|yuga3:err
1	70	68	118	0	0	0	2018/01/24 04:27:40
2	82	85	141	0	0	0	2018/01/24 04:27:41
...
12	82	68	153	0	0	0	2018/01/24 04:27:51
13	93	81	159	0	0	0	2018/01/24 04:27:52
# isolating yuga3
# isolated yuga3
14	78	78	124	0	0	0	2018/01/24 04:27:53
15	0	0	0	0	0	0	2018/01/24 04:27:54
...
380	0	0	0	0	0	0	2018/01/24 04:34:00
381	0	0	0	0	0	0	2018/01/24 04:34:01
# rejoining yuga3
# rejoined yuga3
382	0	0	0	0	0	0	2018/01/24 04:34:02
383	0	0	0	0	0	0	2018/01/24 04:34:03
...
432	0	0	0	0	0	0	2018/01/24 04:34:52
433	0	0	0	0	0	0	2018/01/24 04:34:53
434	118	111	77	1	1	1	2018/01/24 04:34:54
435	219	166	80	0	0	0	2018/01/24 04:34:55

After I reestablished a connection, the system recovered in 51 seconds.

The logs: dead.tar.gz

[kmuthukk]

Hi @amitanandaiyer - assigning this to you for initial look.

Thanks @rystsov for reporting the issue (with clear steps for repro). Much appreciated.

[amitanandaiyer]

Hi Denis,
Thanks for reporting this issue. I'm trying to repro what's happening on your end. But, haven't been able to get a similar result as yours.

A few questions regarding the repro:

1. Was this something you were able to see consistently? Or something you stumbled upon on various tries?

2. If you are able to repro consistently, would you mind adding --v=3 option to the db-yb-tserver/master.sh files.

Thanks,
-Amit
client1.log

[rystsov]

I was able to reproduce it with roughly 15% rate of success. Maybe it depends on the node you're trying to isolate. I observed the issue two times and both time I isolated a node with the higher number of RPS:

12	82	68	153	0	0	0	2018/01/24 04:27:51
13	93	81	159	0	0	0	2018/01/24 04:27:52

In this case, it's the third node. In my other try, it was the second as far as remember.

Between the tries, I stopped the containers and removed them (docker rm yuga1 yuga2 yuga3) along with the logs to have a fresh start each time.

I'll try to add the parameter in the evening --v=3. Just out of curiosity, what does it do?

[amitanandaiyer]

--v=3 is going to turn on the verbose logging, up to level 3. Hoping to see what's happening from the redis proxy layer (the shim layer listening on 6379 and converting requests to the yugabyte db) does.

[amitanandaiyer]

Thanks for the tip about stopping the containers and removing them. Will try doing that between retries.

[amitanandaiyer]

I managed to repro the issue, partially, by setting '--yb_num_total_tablets 1' in enable-redis.sh and taking out the node that's the active leader.

While I don't see all 3 nodes going to 0. Two nodes' ops go down to 0 -- instead of just the One node that was taken down.

Will analyse the logs and update my findings here.

[amitanandaiyer]

So this is what's happening.

Denis is writing to 3 rows; which can go to 3 tablets served by 3 leaders. Probabilistically, all 3 rows could end up on being served by tablets on one node.

Let's say that yuga3 is being the leader for all the 3 tablets. And that yuga3 is being taken down.

1. At the Tserver/YB layer, the remaining peers detect that the leader is missing (in < 2 sec) and run a leader election to make progress.
2. However, the Redis proxies on all 3 nodes -- which were previously sending their requests to yuga3 -- are still waiting on yuga3 for a response.

Due to the manner in which the failure is caused (iptables drop packets vs bringing yuga3 down), pre-established connections between the proxy and the tservers are not getting torn down. Requests wait for their timeout (default 60s), and return an error. However, since the deadline is past, they do not attempt a retry -- leaving the metacache still pointing to yuga3, and routing future requests to the same fate.

I have a patch that allows unsuccessful/timed-out operations to mark the leader as being suspect. This would cause the 2 available proxies to realize the leader movement, and get their ops back once the first RPC times out.

[amitanandaiyer]

@rystsov This issue has been fixed in 2ee52b6

If you download the file, and try again, you should see that things recover by redis_service_yb_client_timeout_millis (which defaults to 60sec).

To make the connection detection/recovery independent of the API timeout, I'm working on another diff to enable TCP/KeepAlive on our connections. That is in the works, and currently being tested.