[CI] FollowerFailOverIT testReadRequestsReturnsLatestMappingVersion failed

[droberts195]

org.elasticsearch.xpack.ccr.FollowerFailOverIT testReadRequestsReturnsLatestMappingVersion failed in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+intake/1474/console

The test got an unexpected InterruptedException:

Uncaught exception in thread: Thread[elasticsearch[leaderd2][clusterApplierService#updateTask][T#1],5,TGRP-FollowerFailOverIT]
java.lang.AssertionError: java.lang.InterruptedException
	at __randomizedtesting.SeedInfo.seed([D0B1EF2765FCDBBC]:0)
	at org.elasticsearch.xpack.ccr.FollowerFailOverIT.lambda$testReadRequestsReturnsLatestMappingVersion$4(FollowerFailOverIT.java:261)
	at org.elasticsearch.cluster.service.ClusterApplierService.lambda$callClusterStateAppliers$6(ClusterApplierService.java:487)
	at java.lang.Iterable.forEach(Iterable.java:75)
	at org.elasticsearch.cluster.service.ClusterApplierService.callClusterStateAppliers(ClusterApplierService.java:484)
	at org.elasticsearch.cluster.service.ClusterApplierService.applyChanges(ClusterApplierService.java:471)
	at org.elasticsearch.cluster.service.ClusterApplierService.runTask(ClusterApplierService.java:421)
	at org.elasticsearch.cluster.service.ClusterApplierService$UpdateTask.run(ClusterApplierService.java:165)
	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:662)
	at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.runAndClean(PrioritizedEsThreadPoolExecutor.java:252)
	at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.run(PrioritizedEsThreadPoolExecutor.java:215)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.InterruptedException
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:998)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
	at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)
	at org.elasticsearch.xpack.ccr.FollowerFailOverIT.lambda$testReadRequestsReturnsLatestMappingVersion$4(FollowerFailOverIT.java:259)
	... 12 more

The repro command is:

./gradlew :x-pack:plugin:ccr:internalClusterTest \
  -Dtests.seed=97C386C4128137C7 \
  -Dtests.class=org.elasticsearch.xpack.ccr.FollowerFailOverIT \
  -Dtests.method="testReadRequestsReturnsLatestMappingVersion" \
  -Dtests.security.manager=true \
  -Dtests.locale=fi \
  -Dtests.timezone=Europe/Mariehamn \
  -Dcompiler.java=11 \
  -Druntime.java=8

This did not reproduce locally for me.

[droberts195]

I muted the test on master in f12bfb4

[alpar-t]

This reproduces for me locally with:

 ./gradlew :x-pack:plugin:ccr:internalClusterTest -Dtests.seed=FE7DE10DFB70778B -Dtests.class=org.elasticsearch.xpack.ccr.FollowerFailOverIT 

[droberts195]

The actual test failure in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+intake/1474/consoleText was:

ERROR   60.8s J5 | FollowerFailOverIT.testReadRequestsReturnsLatestMappingVersion <<< FAILURES!
   > Throwable #1: ProcessClusterEventTimeoutException[failed to process cluster event (put-mapping) within 23s]
   > 	at org.elasticsearch.cluster.service.MasterService$Batcher.lambda$onTimeout$0(MasterService.java:134)
   > 	at java.util.ArrayList.forEach(ArrayList.java:1257)
   > 	at org.elasticsearch.cluster.service.MasterService$Batcher.lambda$onTimeout$1(MasterService.java:133)
   > 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:662)
   > 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
   > 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
   > 	at java.lang.Thread.run(Thread.java:748)Throwable #2: java.lang.AssertionError: AcknowledgedResponse failed - not acked
   > Expected: <true>
   >      but: was <false>
   > 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
   > 	at org.elasticsearch.test.hamcrest.ElasticsearchAssertions.assertAcked(ElasticsearchAssertions.java:112)
   > 	at org.elasticsearch.test.hamcrest.ElasticsearchAssertions.assertAcked(ElasticsearchAssertions.java:116)
   > 	at org.elasticsearch.test.TestCluster.wipeIndices(TestCluster.java:142)
   > 	at org.elasticsearch.test.TestCluster.wipe(TestCluster.java:79)
   > 	at org.elasticsearch.xpack.CcrIntegTestCase.afterTest(CcrIntegTestCase.java:178)
   > 	at java.lang.Thread.run(Thread.java:748)

[droberts195]

The same problem occurred on 6.x too, in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+intake/1145/consoleText

The test assertion error is:

ERROR   63.8s J6 | FollowerFailOverIT.testReadRequestsReturnsLatestMappingVersion <<< FAILURES!
   > Throwable #1: ProcessClusterEventTimeoutException[failed to process cluster event (put-mapping) within 14s]
   > 	at org.elasticsearch.cluster.service.MasterService$Batcher.lambda$onTimeout$0(MasterService.java:128)
   > 	at java.util.ArrayList.forEach(ArrayList.java:1257)
   > 	at org.elasticsearch.cluster.service.MasterService$Batcher.lambda$onTimeout$1(MasterService.java:127)
   > 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:662)
   > 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
   > 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
   > 	at java.lang.Thread.run(Thread.java:748)Throwable #2: java.lang.AssertionError: AcknowledgedResponse failed - not acked
   > Expected: <true>
   >      but: was <false>
   > 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
   > 	at org.elasticsearch.test.hamcrest.ElasticsearchAssertions.assertAcked(ElasticsearchAssertions.java:109)
   > 	at org.elasticsearch.test.hamcrest.ElasticsearchAssertions.assertAcked(ElasticsearchAssertions.java:113)
   > 	at org.elasticsearch.test.TestCluster.wipeIndices(TestCluster.java:142)
   > 	at org.elasticsearch.test.TestCluster.wipe(TestCluster.java:79)
   > 	at org.elasticsearch.xpack.CcrIntegTestCase.afterTest(CcrIntegTestCase.java:182)
   > 	at java.lang.Thread.run(Thread.java:748)

And the InterruptedException is:

ERROR   14.8s J6 | FollowerFailOverIT.testAddNewReplicasOnFollower <<< FAILURES!
   > Throwable #1: com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=602, name=elasticsearch[leaderd2][clusterApplierService#updateTask][T#1], state=RUNNABLE, group=TGRP-FollowerFailOverIT]
   > 	at __randomizedtesting.SeedInfo.seed([F6E560D2FC81DB13:4A344E072C3C7893]:0)
   > Caused by: java.lang.AssertionError: java.lang.InterruptedException
   > 	at __randomizedtesting.SeedInfo.seed([F6E560D2FC81DB13]:0)
   > 	at org.elasticsearch.xpack.ccr.FollowerFailOverIT.lambda$testReadRequestsReturnsLatestMappingVersion$4(FollowerFailOverIT.java:261)
   > 	at org.elasticsearch.cluster.service.ClusterApplierService.lambda$callClusterStateAppliers$6(ClusterApplierService.java:485)
   > 	at java.lang.Iterable.forEach(Iterable.java:75)
   > 	at org.elasticsearch.cluster.service.ClusterApplierService.callClusterStateAppliers(ClusterApplierService.java:482)
   > 	at org.elasticsearch.cluster.service.ClusterApplierService.applyChanges(ClusterApplierService.java:469)
   > 	at org.elasticsearch.cluster.service.ClusterApplierService.runTask(ClusterApplierService.java:420)
   > 	at org.elasticsearch.cluster.service.ClusterApplierService$UpdateTask.run(ClusterApplierService.java:164)
   > 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:662)
   > 	at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.runAndClean(PrioritizedEsThreadPoolExecutor.java:252)
   > 	at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.run(PrioritizedEsThreadPoolExecutor.java:215)
   > 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
   > 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
   > 	at java.lang.Thread.run(Thread.java:748)
   > Caused by: java.lang.InterruptedException
   > 	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:998)
   > 	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
   > 	at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)
   > 	at org.elasticsearch.xpack.ccr.FollowerFailOverIT.lambda$testReadRequestsReturnsLatestMappingVersion$4(FollowerFailOverIT.java:259)
   > 	... 12 more

The repro command from this build was:

./gradlew :x-pack:plugin:ccr:internalClusterTest \
  -Dtests.seed=F6E560D2FC81DB13 \
  -Dtests.class=org.elasticsearch.xpack.ccr.FollowerFailOverIT \
  -Dtests.method="testReadRequestsReturnsLatestMappingVersion" \
  -Dtests.security.manager=true \
  -Dtests.locale=ar-MA \
  -Dtests.timezone=Africa/Asmera \
  -Dcompiler.java=11 \
  -Druntime.java=8

[droberts195]

I muted the test on 6.x in c162771

[dnhatn]

I am on it today.