[CI] CcrRetentionLeaseIT.testRetentionLeaseIsAddedIfItDisappearsWhileFollowing timed out #41428
Description
CcrRetentionLeaseIT testRetentionLeaseIsAddedIfItDisappearsWhileFollowing failed in 7.0 due to a suite timeout in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+7.0+periodic/453/console
This doesn't reproduce locally using:
./gradlew :x-pack:plugin:ccr:internalClusterTest --tests "org.elasticsearch.xpack.ccr.CcrRetentionLeaseIT.testRetentionLeaseIsAddedIfItDisappearsWhileFollowing" \
-Dtests.seed=9B5E64A39EEE8200 \
-Dtests.security.manager=true \
-Dtests.locale=ja-JP \
-Dtests.timezone=Libya \
-Dcompiler.java=12 \
-Druntime.java=8
Possibly the cause of the failure was this exception that occurred during the test:
[2019-04-23T09:21:27,991][WARN ][o.e.x.c.a.TransportUnfollowAction] [followerm0] [follower][0] failed to remove retention lease [follower_cluster/follower/3ZSXhR8SQEWYNB5FDZ16pg-following-leader_cluster/leader/B3eTcqtzSGe4TNdx4oPtKQ] on [leader][0] while unfollowing
org.elasticsearch.transport.SendRequestTransportException: [leader1][127.0.0.1:33773][indices:admin/seq_no/remove_retention_lease]
at org.elasticsearch.transport.TransportService.sendRequestInternal(TransportService.java:645) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.transport.TransportService.sendRequest(TransportService.java:543) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.transport.RemoteClusterAwareClient.lambda$doExecute$0(RemoteClusterAwareClient.java:56) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:61) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.transport.RemoteClusterConnection.ensureConnected(RemoteClusterConnection.java:193) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.transport.RemoteClusterService.ensureConnected(RemoteClusterService.java:339) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.transport.RemoteClusterAwareClient.doExecute(RemoteClusterAwareClient.java:48) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.client.support.AbstractClient.execute(AbstractClient.java:393) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.xpack.ccr.CcrRetentionLeases.asyncRemoveRetentionLease(CcrRetentionLeases.java:173) ~[main/:?]
at org.elasticsearch.xpack.ccr.action.TransportUnfollowAction$1.removeRetentionLeaseForShard(TransportUnfollowAction.java:172) ~[main/:?]
at org.elasticsearch.xpack.ccr.action.TransportUnfollowAction$1.clusterStateProcessed(TransportUnfollowAction.java:145) ~[main/:?]
at org.elasticsearch.cluster.service.MasterService$SafeClusterStateTaskListener.clusterStateProcessed(MasterService.java:520) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.cluster.service.MasterService$TaskOutputs.lambda$processedDifferentClusterState$1(MasterService.java:407) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at java.util.ArrayList.forEach(ArrayList.java:1257) ~[?:1.8.0_202]
at org.elasticsearch.cluster.service.MasterService$TaskOutputs.processedDifferentClusterState(MasterService.java:407) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.cluster.service.MasterService.onPublicationSuccess(MasterService.java:264) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.cluster.service.MasterService.publish(MasterService.java:257) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.cluster.service.MasterService.runTasks(MasterService.java:238) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.cluster.service.MasterService$Batcher.run(MasterService.java:142) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.cluster.service.TaskBatcher.runIfNotProcessed(TaskBatcher.java:150) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.cluster.service.TaskBatcher$BatchedTask.run(TaskBatcher.java:188) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:681) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.runAndClean(PrioritizedEsThreadPoolExecutor.java:252) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.run(PrioritizedEsThreadPoolExecutor.java:215) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_202]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_202]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_202]
Caused by: org.elasticsearch.index.shard.IndexShardClosedException: CurrentState[CLOSED] Closed
at org.elasticsearch.xpack.ccr.CcrRetentionLeaseIT.lambda$testUnfollowFailsToRemoveRetentionLeases$7(CcrRetentionLeaseIT.java:500) ~[test/:?]
at org.elasticsearch.test.transport.StubbableTransport$WrappedConnection.sendRequest(StubbableTransport.java:223) ~[framework-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.transport.TransportService.sendRequestInternal(TransportService.java:633) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
... 26 more
[2019-04-23T09:21:28,005][WARN ][o.e.x.c.a.TransportUnfollowAction] [followerm0] [[follower/3ZSXhR8SQEWYNB5FDZ16pg]] failure while removing retention lease [follower_cluster/follower/3ZSXhR8SQEWYNB5FDZ16pg-following-leader_cluster/leader/B3eTcqtzSGe4TNdx4oPtKQ] on leader primary shards
org.elasticsearch.transport.SendRequestTransportException: [leader1][127.0.0.1:33773][indices:admin/seq_no/remove_retention_lease]
at org.elasticsearch.transport.TransportService.sendRequestInternal(TransportService.java:645) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.transport.TransportService.sendRequest(TransportService.java:543) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.transport.RemoteClusterAwareClient.lambda$doExecute$0(RemoteClusterAwareClient.java:56) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:61) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.transport.RemoteClusterConnection.ensureConnected(RemoteClusterConnection.java:193) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.transport.RemoteClusterService.ensureConnected(RemoteClusterService.java:339) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.transport.RemoteClusterAwareClient.doExecute(RemoteClusterAwareClient.java:48) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.client.support.AbstractClient.execute(AbstractClient.java:393) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.xpack.ccr.CcrRetentionLeases.asyncRemoveRetentionLease(CcrRetentionLeases.java:173) ~[main/:?]
at org.elasticsearch.xpack.ccr.action.TransportUnfollowAction$1.removeRetentionLeaseForShard(TransportUnfollowAction.java:172) ~[main/:?]
at org.elasticsearch.xpack.ccr.action.TransportUnfollowAction$1.clusterStateProcessed(TransportUnfollowAction.java:145) ~[main/:?]
at org.elasticsearch.cluster.service.MasterService$SafeClusterStateTaskListener.clusterStateProcessed(MasterService.java:520) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.cluster.service.MasterService$TaskOutputs.lambda$processedDifferentClusterState$1(MasterService.java:407) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at java.util.ArrayList.forEach(ArrayList.java:1257) ~[?:1.8.0_202]
at org.elasticsearch.cluster.service.MasterService$TaskOutputs.processedDifferentClusterState(MasterService.java:407) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.cluster.service.MasterService.onPublicationSuccess(MasterService.java:264) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.cluster.service.MasterService.publish(MasterService.java:257) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.cluster.service.MasterService.runTasks(MasterService.java:238) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.cluster.service.MasterService$Batcher.run(MasterService.java:142) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.cluster.service.TaskBatcher.runIfNotProcessed(TaskBatcher.java:150) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.cluster.service.TaskBatcher$BatchedTask.run(TaskBatcher.java:188) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:681) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.runAndClean(PrioritizedEsThreadPoolExecutor.java:252) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.run(PrioritizedEsThreadPoolExecutor.java:215) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_202]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_202]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_202]
Caused by: org.elasticsearch.index.shard.IndexShardClosedException: CurrentState[CLOSED] Closed
at org.elasticsearch.xpack.ccr.CcrRetentionLeaseIT.lambda$testUnfollowFailsToRemoveRetentionLeases$7(CcrRetentionLeaseIT.java:500) ~[test/:?]
at org.elasticsearch.test.transport.StubbableTransport$WrappedConnection.sendRequest(StubbableTransport.java:223) ~[framework-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
at org.elasticsearch.transport.TransportService.sendRequestInternal(TransportService.java:633) ~[elasticsearch-7.0.1-SNAPSHOT.jar:7.0.1-SNAPSHOT]
... 26 more
The logging immediately around the stall that led to the timeout is:
[2019-04-23T09:21:41,766][INFO ][o.e.x.c.a.ShardFollowTasksExecutor] [followerd2] [follower][0] Starting to track leader shard [leader][0]
[2019-04-23T09:21:41,768][INFO ][o.e.x.c.CcrRetentionLeaseIT] [testRetentionLeaseIsAddedIfItDisappearsWhileFollowing] ensure green follower indices [follower]
[2019-04-23T09:21:41,775][INFO ][o.e.x.c.a.ShardFollowNodeTask] [followerd2] [follower][0] following leader shard [leader][0], follower global checkpoint=[-1], mapping version=[1], settings version=[1]
[2019-04-23T09:41:14,028][WARN ][o.e.t.OutboundHandler ] [followerd2] send message failed [channel: NioSocketChannel{localAddress=0.0.0.0/0.0.0.0:39684, remoteAddress=127.0.0.1/127.0.0.1:45985}]
java.nio.channels.ClosedByInterruptException: null
Note the gap from 9:21 to 9:41.