FollowerFailOverIT.testFailOverOnFollower fails on CI

[tlrx]

The test FollowerFailOverIT.testFailOverOnFollower failed today on 7.0:
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+7.0+internalClusterTest/1446

It does not reproduce locally with:

 ./gradlew :x-pack:plugin:ccr:internalClusterTest \
  -Dtests.seed=D87CDC85B26F55B8 \
  -Dtests.class=org.elasticsearch.xpack.ccr.FollowerFailOverIT \
  -Dtests.method="testFailOverOnFollower" \
  -Dtests.security.manager=true \
  -Dtests.locale=id-ID \
  -Dtests.timezone=Africa/Ndjamena \
  -Dcompiler.java=11 \
  -Druntime.java=8

It is maybe related to #35403 or #38633 but I haven't found the same exact errors so I'm opening a new issue.

The log shows some timeout issues with the GlobalCheckpointListeners:

14:23:04   1> [2019-02-27T15:20:06,932][TRACE][o.e.i.s.IndexShard       ] [leader1] [leader_test_failover][0] global checkpoint listener timed out
14:23:04   1> java.util.concurrent.TimeoutException: 10ms
14:23:04   1> 	at org.elasticsearch.index.shard.GlobalCheckpointListeners.lambda$add$3(GlobalCheckpointListeners.java:141) ~[elasticsearch-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
14:23:04   1> 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_202]
14:23:04   1> 	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_202]
14:23:04   1> 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_202]
14:23:04   1> 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_202]
14:23:04   1> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_202]
14:23:04   1> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) 

And some mismatched documents:

14:23:54    > 		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
14:23:54    > 		at org.elasticsearch.xpack.CcrIntegTestCase.lambda$assertIndexFullyReplicatedToFollower$4(CcrIntegTestCase.java:505)
14:23:54    > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:856)
14:23:54    > 		... 39 more
14:23:54    > 	Suppressed: java.lang.AssertionError: mismatched documents [{0=[DocIdSeqNoAndTerm{id='133 seqNo=135 primaryTerm=1}, DocIdSeqNoAndTerm{id='132 seqNo=134 primaryTerm=1}, DocIdSeqNoAndTerm{id='131 seqNo=133 primaryTerm=1}]}]

I tried to isolate the relevant test log:
consoleText.txt

[elasticmachine]

Pinging @elastic/es-distributed

[tlrx]

cc @dnhatn

[dnhatn]

Thanks @tlrx. I am on it today.

[dnhatn]

Finally, I have an explanation for this failure. It happened as follows:

1. We are restarting a node that has the following primary running.

[2019-02-27T15:18:39,567][INFO ][o.e.t.InternalTestCluster] [testFailOverOnFollower] Restarting node [followerd4] 
[2019-02-27T15:18:39,568][INFO ][o.e.n.Node               ] [testFailOverOnFollower] stopping ...

2. The following primary just completes a bulk request containing seq#133, seq#134, and seq#135, but it can not send that bulk request to the following replica.

[2019-02-27T15:18:39,596][TRACE][o.e.x.c.a.b.TransportBulkShardOperationsAction] [followerd4] [[follower_test_failover][0]] op [indices:data/write/bulk_shard_operations[s]] completed on primary for request [BulkShardOperationsRequest{historyUUID=LAJy3qUiSLi5WipZHEQmsw, operations=3, maxSeqNoUpdates=99, shardId=[follower_test_failover][0], timeout=1m, index='follower_test_failover', waitForActiveShards=1}]
[2019-02-27T15:18:39,610][TRACE][o.e.x.c.a.b.TransportBulkShardOperationsAction] [followerd4] [[follower_test_failover][0]] failure while performing [indices:data/write/bulk_shard_operations[s]] on replica [follower_test_failover][0], node[F0IIukrhRKy9xJP_ZO6YiA], [R], s[STARTED], a[id=tnsEYc72RWKeUe8141Q7EQ], request [BulkShardOperationsRequest{historyUUID=LAJy3qUiSLi5WipZHEQmsw, operations=10, maxSeqNoUpdates=99, shardId=[follower_test_failover][0], timeout=1m, index='follower_test_failover', waitForActiveShards=DEFAULT}]
org.elasticsearch.transport.NodeDisconnectedException: [followerd1][127.0.0.1:43829][indices:data/write/bulk_shard_operations[s][r]] disconnected
[2019-02-27T15:18:39,612][WARN ][o.e.t.TransportService   ] [followerd4] Transport response handler not found of id [68]
[2019-02-27T15:18:39,615][WARN ][o.e.x.c.a.b.TransportBulkShardOperationsAction] [followerd4] [[follower_test_failover][0]] failed to perform indices:data/write/bulk_shard_operations[s] on replica [follower_test_failover][0], node[F0IIukrhRKy9xJP_ZO6YiA], [R], s[STARTED], a[id=tnsEYc72RWKeUe8141Q7EQ]
org.elasticsearch.transport.NodeDisconnectedException: [followerd1][127.0.0.1:43829][indices:data/write/bulk_shard_operations[s][r]] disconnected

3. The following primary tries to reach to the master node to fail the following replica but is unable to send the request.

[2019-02-27T15:18:39,621][WARN ][o.e.c.a.s.ShardStateAction] [followerd4] node closed while execution action [internal:cluster/shard/failure] for shard entry [shard id [[follower_test_failover][0]], allocation id [tnsEYc72RWKeUe8141Q7EQ], primary term [1], message [failed to perform indices:data/write/bulk_shard_operations[s] on replica [follower_test_failover][0], node[F0IIukrhRKy9xJP_ZO6YiA], [R], s[STARTED], a[id=tnsEYc72RWKeUe8141Q7EQ]], failure [NodeDisconnectedException[[followerd1][127.0.0.1:43829][indices:data/write/bulk_shard_operations[s][r]] disconnected]], markAsStale [true]]

4. The following primary then is able to respond SUCCESS to the ShardFollowTask.

[2019-02-27T15:18:39,663][TRACE][o.e.x.c.a.b.TransportBulkShardOperationsAction] [followerd4] operation succeeded. action [indices:data/write/bulk_shard_operations[s]],request [BulkShardOperationsRequest{historyUUID=LAJy3qUiSLi5WipZHEQmsw, operations=3, maxSeqNoUpdates=99, shardId=[follower_test_failover][0], timeout=1m, index='follower_test_failover', waitForActiveShards=1}]

5. The following replica is promoted, but it won't have seq#133, seq#134, and seq#135 for the ShardFollowTask won't send these operations unless the FollowTask is restarted.

Throwable #1: java.lang.AssertionError: mismatched documents [{0=[DocIdSeqNoAndTerm{id='133 seqNo=135 primaryTerm=1}, DocIdSeqNoAndTerm{id='132 seqNo=134 primaryTerm=1}, DocIdSeqNoAndTerm{id='131 seqNo=133 primaryTerm=1}]}]

I think this is a blocker for 6.7 and 7.0.

/cc @bleskes @ywelsch @jasontedor @martijnvg

[dnhatn]

I see two solutions here: one is to reset lastRequestedSeqNo to followerGlobalCheckpoint when the primary term on the follower increased. Another is to consider a bulk request with successful_shards < total_shards as a failure then retry.

[martijnvg]

@dnhatn Thanks for the detailed explanation!

Another is to consider a bulk request with successful_shards < total_shards as a failure then retry.

The problem you described above, only happens when a replica shard is promoted to primary shard. successful_shards < total_shards happens when the we were unable to index into a replica shard, which I think happens more often than a primary promotion. So retrying based in that condition would result in retrying too often and most of the times it wouldn't be needed?

one is to reset lastRequestedSeqNo to followerGlobalCheckpoint when the primary term on the follower increased.

I think it makes sense to reset the followerGlobalCheckpoint to lastRequestedSeqNo in case of primary promotion to avoid the scenario that you have described.

[bleskes]

The following primary then is able to respond SUCCESS to the ShardFollowTask.

@dnhatn can you explain why a replicated write operation is finished succesfully after not being to able to fail a replica/mark it as stale?