[CI] GatewayIndexStateIT.testRecoverBrokenIndexMetadata failed

[henningandersen]

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+7.x+matrix-java-periodic/ES_BUILD_JAVA=openjdk12,ES_RUNTIME_JAVA=zulu8,nodes=immutable&&linux&&docker/12/testReport/org.elasticsearch.gateway/GatewayIndexStateIT/testRecoverBrokenIndexMetadata/

failed with:

ProcessClusterEventTimeoutException[failed to process cluster event (delete-index [[test/iDbV2qAfQ3m4Tno7UZjjDw]]) within 30s]
	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:688)
	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)

but the underlying cause is likely this:

giu 10, 2019 5:47:16 PM com.carrotsearch.randomizedtesting.RandomizedRunner$QueueUncaughtExceptionsHandler uncaughtException
AVVERTENZA: Uncaught exception in thread: Thread[elasticsearch[node_t0][clusterApplierService#updateTask][T#1],5,TGRP-GatewayIndexStateIT]
java.lang.AssertionError: new global checkpoint [-1] is lower than previous one [0]
	at __randomizedtesting.SeedInfo.seed([649ECAB233D0314A]:0)
	at org.elasticsearch.index.seqno.ReplicationTracker.updateGlobalCheckpointOnPrimary(ReplicationTracker.java:1006)
	at org.elasticsearch.index.seqno.ReplicationTracker.activatePrimaryMode(ReplicationTracker.java:785)
	at org.elasticsearch.index.shard.IndexShard.updateShardState(IndexShard.java:482)
	at org.elasticsearch.indices.cluster.IndicesClusterStateService.updateShard(IndicesClusterStateService.java:629)
	at org.elasticsearch.indices.cluster.IndicesClusterStateService.createOrUpdateShards(IndicesClusterStateService.java:580)
	at org.elasticsearch.indices.cluster.IndicesClusterStateService.applyClusterState(IndicesClusterStateService.java:267)
	at org.elasticsearch.cluster.service.ClusterApplierService.lambda$callClusterStateAppliers$5(ClusterApplierService.java:495)
	at java.lang.Iterable.forEach(Iterable.java:75)
	at org.elasticsearch.cluster.service.ClusterApplierService.callClusterStateAppliers(ClusterApplierService.java:493)
	at org.elasticsearch.cluster.service.ClusterApplierService.applyChanges(ClusterApplierService.java:464)
	at org.elasticsearch.cluster.service.ClusterApplierService.runTask(ClusterApplierService.java:418)
	at org.elasticsearch.cluster.service.ClusterApplierService$UpdateTask.run(ClusterApplierService.java:165)
	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:688)
	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)

I were unable to reproduce this, tried with zulu8 too, but no luck. Leaving it unmuted for now, since it seems it failed once only though it was only recently unmuted here: #40867.

[elasticmachine]

Pinging @elastic/es-distributed

[ywelsch]

@henningandersen can you enable TRACE logging for this test? This sounds potentially very dangerous (as if the doc got dropped).

[droberts195]

This failed again in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+intake/111/console

Since you're adding extra logging to investigate I'll leave it unmuted until it fails with the extra logging.

[henningandersen]

The stack trace of this new incident is different, but is likely to be another symptom with the same cause:

WARNING: Uncaught exception in thread: Thread[elasticsearch[node_t0][generic][T#3],5,TGRP-GatewayIndexStateIT]
java.lang.AssertionError: max seq. no. [-1] does not match [0]
	at __randomizedtesting.SeedInfo.seed([6A7C3CF2D433EF54]:0)
	at org.elasticsearch.index.engine.ReadOnlyEngine.assertMaxSeqNoEqualsToGlobalCheckpoint(ReadOnlyEngine.java:153)
	at org.elasticsearch.index.engine.ReadOnlyEngine.ensureMaxSeqNoEqualsToGlobalCheckpoint(ReadOnlyEngine.java:144)
	at org.elasticsearch.index.engine.ReadOnlyEngine.<init>(ReadOnlyEngine.java:114)
	at org.elasticsearch.index.engine.NoOpEngine.<init>(NoOpEngine.java:46)
	at org.elasticsearch.index.shard.IndexShard.innerOpenEngineAndTranslog(IndexShard.java:1451)
	at org.elasticsearch.index.shard.IndexShard.openEngineAndRecoverFromTranslog(IndexShard.java:1404)
	at org.elasticsearch.index.shard.StoreRecovery.internalRecoverFromStore(StoreRecovery.java:425)
	at org.elasticsearch.index.shard.StoreRecovery.lambda$recoverFromStore$0(StoreRecovery.java:95)
	at org.elasticsearch.index.shard.StoreRecovery.executeRecovery(StoreRecovery.java:300)
	at org.elasticsearch.index.shard.StoreRecovery.recoverFromStore(StoreRecovery.java:93)
	at org.elasticsearch.index.shard.IndexShard.recoverFromStore(IndexShard.java:1677)
	at org.elasticsearch.index.shard.IndexShard.lambda$startRecovery$9(IndexShard.java:2324)
	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:687)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)

[benwtrent]

Something similar happened in my PR today. Looked for additional trace logs, did not see any. Not sure if my PR had the trace log change or not. https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+pull-request-1/554/

[ywelsch]

I've looked at the TRACE logs here, and what's surprising is that the node that's restarted does not call flushAndClose on the shard (which this test relies upon). When I run it locally, flushAndClose gets reliably called. The conditions are also all correct when the method that is called is deciding between a no-flush close and a flush-close. The condition is final boolean flushEngine = deleted.get() == false && closed.get(); and the logging says that the index is not being deleted. This just does not make sense to me. One way to fix the test would be to issue an explicit flush before restarting the node, and not rely on the flush-on-close logic.