IndexFollowingIT#testCloseLeaderIndex failure

[gwbrown]

Popped up in 7.x intake build: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+7.x+intake/1076/testReport/

Per build-stats, it looks like this is the first time this has happened and it doesn't reproduce so I'm not going to mute this yet.

Looking at the test, it looks like it's failing because an index is closed, but I have no idea how that index would have gotten closed.

Reproduce line (does not reproduce locally for me):

./gradlew :x-pack:plugin:ccr:internalClusterTest --tests "org.elasticsearch.xpack.ccr.IndexFollowingIT.testCloseLeaderIndex" \
  -Dtests.seed=60525086BCE99CCF \
  -Dtests.security.manager=true \
  -Dtests.locale=es-PR \
  -Dtests.timezone=Asia/Seoul \
  -Dcompiler.java=12 \
  -Druntime.java=8

Stack trace:

[index2/QWN8pEUgQ0G8g5sZ8wFqbg] IndexClosedException[closed]
	at __randomizedtesting.SeedInfo.seed([60525086BCE99CCF:28F2D7030DA1CCC4]:0)
	at org.elasticsearch.cluster.metadata.IndexNameExpressionResolver.concreteIndices(IndexNameExpressionResolver.java:234)
	at org.elasticsearch.cluster.metadata.IndexNameExpressionResolver.concreteIndices(IndexNameExpressionResolver.java:138)
	at org.elasticsearch.action.search.TransportSearchAction.resolveLocalIndices(TransportSearchAction.java:456)
	at org.elasticsearch.action.search.TransportSearchAction.executeSearch(TransportSearchAction.java:470)
	at org.elasticsearch.action.search.TransportSearchAction.executeLocalSearch(TransportSearchAction.java:399)
	at org.elasticsearch.action.search.TransportSearchAction.lambda$doExecute$3(TransportSearchAction.java:211)
	at org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:62)
	at org.elasticsearch.action.search.TransportSearchAction.doExecute(TransportSearchAction.java:239)
	at org.elasticsearch.action.search.TransportSearchAction.doExecute(TransportSearchAction.java:86)
	at org.elasticsearch.action.support.TransportAction$RequestFilterChain.proceed(TransportAction.java:145)
	at org.elasticsearch.action.support.TransportAction.execute(TransportAction.java:121)
	at org.elasticsearch.action.support.TransportAction.execute(TransportAction.java:64)
	at org.elasticsearch.client.node.NodeClient.executeLocally(NodeClient.java:83)
	at org.elasticsearch.client.node.NodeClient.doExecute(NodeClient.java:72)
	at org.elasticsearch.client.support.AbstractClient.execute(AbstractClient.java:394)
	at org.elasticsearch.client.support.AbstractClient.execute(AbstractClient.java:383)
	at org.elasticsearch.action.ActionRequestBuilder.execute(ActionRequestBuilder.java:45)
	at org.elasticsearch.action.ActionRequestBuilder.get(ActionRequestBuilder.java:52)
	at org.elasticsearch.xpack.ccr.IndexFollowingIT.lambda$testCloseLeaderIndex$17(IndexFollowingIT.java:628)
	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:850)
	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:836)
	at org.elasticsearch.xpack.ccr.IndexFollowingIT.testCloseLeaderIndex(IndexFollowingIT.java:628)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1750)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:938)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:974)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:988)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:947)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:832)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:883)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:894)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
	at java.lang.Thread.run(Thread.java:748)

[elasticmachine]

Pinging @elastic/es-distributed

[ywelsch]

Logs are lost here and no recent failures -> closing

[iverase]

This test failed again today in branch 7.2, logs can be found here:
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+7.2+matrix-java-periodic/ES_BUILD_JAVA=openjdk12,ES_RUNTIME_JAVA=zulu11,nodes=immutable&&linux&&docker/7/console

This is the stack trace when test seems to fail:

08:00:13   1> [2019-05-27T15:30:11,861][INFO ][o.e.x.c.IndexFollowingIT ] [testFollowIndex_backlog] --> asserting seq_no_stats between index1 and index2
08:00:13   1> [2019-05-27T15:30:11,887][INFO ][o.e.x.c.a.ShardFollowNodeTask] [follower0] [index2][0] shard follow task has been stopped
08:00:13   1> [2019-05-27T15:30:11,910][INFO ][o.e.x.c.a.ShardFollowNodeTask] [follower1] [index2][1] shard follow task has been stopped
08:00:13   1> [2019-05-27T15:30:11,966][INFO ][o.e.c.m.MetaDataDeleteIndexService] [leader0] [index1/fzvi0S-DR8GBNJ4HNxxiGw] deleting index
08:00:13   1> [2019-05-27T15:30:12,255][INFO ][o.e.c.m.MetaDataDeleteIndexService] [follower0] [index2/VyRPF0jFTk6N1d6aS_VFfA] deleting index
08:00:13   1> [2019-05-27T15:30:12,332][INFO ][o.e.x.c.IndexFollowingIT ] [testFollowIndex_backlog] after test
08:00:13   1> [2019-05-27T15:30:12,336][INFO ][o.e.n.Node               ] [suite] stopping ...
08:00:13   1> [2019-05-27T15:30:12,351][INFO ][o.e.n.Node               ] [suite] stopped
08:00:13   1> [2019-05-27T15:30:12,351][INFO ][o.e.n.Node               ] [suite] closing ...
08:00:13   1> [2019-05-27T15:30:12,353][INFO ][o.e.c.s.ClusterApplierService] [leader1] master node changed {previous [{leader0}{0BOPY_IMT6GWLBs5hS3m7A}{1GFWshYAQO2LNUyZnrCeuA}{127.0.0.1}{127.0.0.1:40639}{xpack.installed=true}], current []}, term: 1, version: 122, reason: becoming candidate: onLeaderFailure
08:00:13   1> [2019-05-27T15:30:12,353][WARN ][o.e.t.RemoteClusterConnection] [follower1] fetching nodes from external cluster [leader_cluster] failed
08:00:13   1> org.elasticsearch.transport.ConnectTransportException: [][127.0.0.1:40639] connect_exception
08:00:13   1> 	at org.elasticsearch.transport.TcpTransport$ChannelsConnectedListener.onFailure(TcpTransport.java:972) ~[elasticsearch-7.2.0-SNAPSHOT.jar:7.2.0-SNAPSHOT]
08:00:13   1> 	at org.elasticsearch.action.ActionListener.lambda$toBiConsumer$3(ActionListener.java:161) ~[elasticsearch-7.2.0-SNAPSHOT.jar:7.2.0-SNAPSHOT]
08:00:13   1> 	at org.elasticsearch.common.concurrent.CompletableContext.lambda$addListener$0(CompletableContext.java:42) ~[elasticsearch-core-7.2.0-SNAPSHOT.jar:7.2.0-SNAPSHOT]
08:00:13   1> 	at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859) ~[?:?]
08:00:13   1> 	at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:837) ~[?:?]
08:00:13   1> 	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
08:00:13   1> 	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088) ~[?:?]
08:00:13   1> 	at org.elasticsearch.common.concurrent.CompletableContext.completeExceptionally(CompletableContext.java:57) ~[elasticsearch-core-7.2.0-SNAPSHOT.jar:7.2.0-SNAPSHOT]
08:00:13   1> 	at org.elasticsearch.nio.SocketChannelContext.connect(SocketChannelContext.java:120) ~[elasticsearch-nio-7.2.0-SNAPSHOT.jar:7.2.0-SNAPSHOT]
08:00:13   1> 	at org.elasticsearch.nio.EventHandler.handleConnect(EventHandler.java:97) ~[elasticsearch-nio-7.2.0-SNAPSHOT.jar:7.2.0-SNAPSHOT]
08:00:13   1> 	at org.elasticsearch.transport.nio.TestEventHandler.handleConnect(TestEventHandler.java:97) ~[framework-7.2.0-SNAPSHOT.jar:7.2.0-SNAPSHOT]
08:00:13   1> 	at org.elasticsearch.nio.NioSelector.attemptConnect(NioSelector.java:405) ~[elasticsearch-nio-7.2.0-SNAPSHOT.jar:7.2.0-SNAPSHOT]
08:00:13   1> 	at org.elasticsearch.nio.NioSelector.setUpNewChannels(NioSelector.java:422) ~[elasticsearch-nio-7.2.0-SNAPSHOT.jar:7.2.0-SNAPSHOT]
08:00:13   1> 	at org.elasticsearch.nio.NioSelector.preSelect(NioSelector.java:261) ~[elasticsearch-nio-7.2.0-SNAPSHOT.jar:7.2.0-SNAPSHOT]
08:00:13   1> 	at org.elasticsearch.nio.NioSelector.singleLoop(NioSelector.java:153) ~[elasticsearch-nio-7.2.0-SNAPSHOT.jar:7.2.0-SNAPSHOT]
08:00:13   1> 	at org.elasticsearch.nio.NioSelector.runLoop(NioSelector.java:129) ~[elasticsearch-nio-7.2.0-SNAPSHOT.jar:7.2.0-SNAPSHOT]
08:00:13   1> 	at java.lang.Thread.run(Thread.java:834) [?:?]
08:00:13   1> Caused by: java.net.ConnectException: Connection refused
08:00:13   1> 	at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) ~[?:?]
08:00:13   1> 	at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:779) ~[?:?]
08:00:13   1> 	at org.elasticsearch.nio.SocketChannelContext.connect(SocketChannelContext.java:117) ~[elasticsearch-nio-7.2.0-SNAPSHOT.jar:7.2.0-SNAPSHOT]
08:00:13   1> 	... 8 more
08:00:13   1> [2019-05-27T15:30:12,354][WARN ][o.e.t.RemoteClusterConnection] [follower0] fetching nodes from external cluster [leader_cluster] failed
08:00:13   1> org.elasticsearch.transport.ConnectTransportException: [][127.0.0.1:40639] connect_exception
08:00:13   1> 	at org.elasticsearch.transport.TcpTransport$ChannelsConnectedListener.onFailure(TcpTransport.java:972) ~[elasticsearch-7.2.0-SNAPSHOT.jar:7.2.0-SNAPSHOT]

[danielmitterdorfer]

Another one in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+7.x+matrix-java-periodic/ES_BUILD_JAVA=openjdk12,ES_RUNTIME_JAVA=zulu12,nodes=immutable&&linux&&docker/201/console

reproduction line (does not reproduce locally):

./gradlew :x-pack:plugin:ccr:internalClusterTest --tests "org.elasticsearch.xpack.ccr.IndexFollowingIT.testCloseLeaderIndex" -Dtests.seed=B5A055715D18E549 -Dtests.security.manager=true -Dtests.locale=sw -Dtests.timezone=Brazil/DeNoronha -Dcompiler.java=12 -Druntime.java=12

error trace:

[index2/daooU8Z6Tbud__bYXQc_SA] IndexClosedException[closed]
	at __randomizedtesting.SeedInfo.seed([B5A055715D18E549:FD00D2F4EC50B542]:0)
	at org.elasticsearch.cluster.metadata.IndexNameExpressionResolver.concreteIndices(IndexNameExpressionResolver.java:234)
	at org.elasticsearch.cluster.metadata.IndexNameExpressionResolver.concreteIndices(IndexNameExpressionResolver.java:138)
	at org.elasticsearch.action.search.TransportSearchAction.resolveLocalIndices(TransportSearchAction.java:456)
	at org.elasticsearch.action.search.TransportSearchAction.executeSearch(TransportSearchAction.java:470)
	at org.elasticsearch.action.search.TransportSearchAction.executeLocalSearch(TransportSearchAction.java:399)
	at org.elasticsearch.action.search.TransportSearchAction.lambda$doExecute$3(TransportSearchAction.java:211)
	at org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:62)
	at org.elasticsearch.action.search.TransportSearchAction.doExecute(TransportSearchAction.java:239)
	at org.elasticsearch.action.search.TransportSearchAction.doExecute(TransportSearchAction.java:86)
	at org.elasticsearch.action.support.TransportAction$RequestFilterChain.proceed(TransportAction.java:145)
	at org.elasticsearch.action.support.TransportAction.execute(TransportAction.java:121)
	at org.elasticsearch.action.support.TransportAction.execute(TransportAction.java:64)
	at org.elasticsearch.client.node.NodeClient.executeLocally(NodeClient.java:83)
	at org.elasticsearch.client.node.NodeClient.doExecute(NodeClient.java:72)
	at org.elasticsearch.client.support.AbstractClient.execute(AbstractClient.java:394)
	at org.elasticsearch.client.support.AbstractClient.execute(AbstractClient.java:383)
	at org.elasticsearch.action.ActionRequestBuilder.execute(ActionRequestBuilder.java:45)
	at org.elasticsearch.action.ActionRequestBuilder.get(ActionRequestBuilder.java:52)
	at org.elasticsearch.xpack.ccr.IndexFollowingIT.lambda$testCloseLeaderIndex$17(IndexFollowingIT.java:628)
	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:850)
	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:836)
	at org.elasticsearch.xpack.ccr.IndexFollowingIT.testCloseLeaderIndex(IndexFollowingIT.java:628)
[...]

Full output from the test failure

[dnhatn]

I opened #43067.