[CI] FlushIT testFlushOnInactive failing

[DaveCTurner]

Actually failed on a PR branch but the PR didn't touch anything in this area I think.

Build scan:
https://gradle-enterprise.elastic.co/s/oof57yigaovuk/tests/:server:internalClusterTest/org.elasticsearch.indices.flush.FlushIT/testFlushOnInactive

Reproduction line:
./gradlew ':server:internalClusterTest' --tests "org.elasticsearch.indices.flush.FlushIT.testFlushOnInactive" -Dtests.seed=38FC56033AE2DC88 -Dtests.locale=en-IN -Dtests.timezone=Europe/Zaporozhye -Druntime.java=17

Applicable branches:
master

Reproduces locally?:
Didn't try

Failure history:
https://gradle-enterprise.elastic.co/scans/tests?tests.container=org.elasticsearch.indices.flush.FlushIT&tests.test=testFlushOnInactive

Failure excerpt:

java.lang.AssertionError: 
Expected: <0>
     but: was <2>

  at __randomizedtesting.SeedInfo.seed([38FC56033AE2DC88:DF99C84AD94DDF44]:0)
  at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:18)
  at org.junit.Assert.assertThat(Assert.java:956)
  at org.junit.Assert.assertThat(Assert.java:923)
  at org.elasticsearch.indices.flush.FlushIT.lambda$testFlushOnInactive$1(FlushIT.java:145)
  at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:1098)
  at org.elasticsearch.indices.flush.FlushIT.testFlushOnInactive(FlushIT.java:143)
  at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-2)
  at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
  at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  at java.lang.reflect.Method.invoke(Method.java:568)
  at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1758)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:946)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:982)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:996)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at org.apache.lucene.tests.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:44)
  at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
  at org.apache.lucene.tests.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:45)
  at org.apache.lucene.tests.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:60)
  at org.apache.lucene.tests.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:44)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:375)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:824)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:475)
  at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:955)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:840)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:891)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:902)
  at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at org.apache.lucene.tests.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:38)
  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 org.apache.lucene.tests.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
  at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
  at org.apache.lucene.tests.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:44)
  at org.apache.lucene.tests.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:60)
  at org.apache.lucene.tests.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:47)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:375)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl.lambda$forkTimeoutingTask$0(ThreadLeakControl.java:831)
  at java.lang.Thread.run(Thread.java:833)

[elasticmachine]

Pinging @elastic/es-distributed (Team:Distributed)

[kingherc]

Hi @DaveCTurner , I took a look at it and indeed it's reproducible (not always). I did not understand why the translog has uncommitted changes -- and not sure who commits them? But after investigating the git history, I believe the culprit is the indices.memory.interval setting. With the given test seed, it has a value of 54ms, which may be too short. I found that changing this line:
.put(IndexingMemoryController.SHARD_MEMORY_INTERVAL_TIME_SETTING.getKey(), randomTimeValue(10, 1000, "ms"))
to
.put(IndexingMemoryController.SHARD_MEMORY_INTERVAL_TIME_SETTING.getKey(), randomTimeValue(100, 1000, "ms"))
makes the problem go away. With the same test seed, this becomes a value of 679ms. I saw that this setting is the interval of the ShardsIndicesStatusChecker, which uses a lock, and maybe the short interval creates some concurrency issue. Might you think of why? I could make a PR to modify the range of the setting either way, although it'd be best to understand why this happens with such short values and whether we should introduce a minimum value for this setting.

[kingherc]

After discussion, it seems it's better to go deeper in details on why the error happens rather than just increasing the value. I will have a discussion with @fcofdez a bit on this test, what it does, etc. before trying to go deeper into it.

[kingherc]

Hi, so after a discussion with @fcofdez (thanks!), there is a thought that this may occur because the test randomly may restart the server, and the shard might be recovering while the check is happening. It's not clear why this could happen (since the test ensuresGreen()) but it would be worth checking the min gen versus the current.getGeneration in org.elasticsearch.index.translog.Translog#getMinReferencedGen when the error happens. That could possibly mean a recovery is underway. One other thing to try would be to add a sleep in the Recovery phase to see if indeed this is the issue. Like 20 seconds. In PeerRecoveryTargetService; in org.elasticsearch.indices.recovery.RecoverySourceHandler.phase2 around line 1087.

I will try to reproduce the test and try the above.

[kingherc]

I tried reproducing this on latest main, but I cannot reproduce it after multiple retries. I also run the test in 1000 iterations, and no problem. In the Gradle Enterprise test history I do not see it having happened again in the last month. It may have been implicitly fixed in the meantime. I am thinking of leaving this issue open for some time (e.g., a couple of weeks) to see if it occurs again, and then try to reproduce it once more and if I cannot then close this issue. Please tell me if I should handle it differently.

[kingherc]

@fcofdez cannot reproduce it as well. I may try to bisect PRs between then and now to see if/when it stopped reproducing.

[kingherc]

FYI, to reproduce the error we needed to:

• Comment out the following lines from ESIntegTestCase.java:

//        if (randomBoolean()) {
//            builder.put(IndexSettings.BLOOM_FILTER_ID_FIELD_ENABLED_SETTING.getKey(), randomBoolean());
//        }

• Change the following line in FlushIT.java:

.put(IndexingMemoryController.SHARD_MEMORY_INTERVAL_TIME_SETTING.getKey(), randomTimeValue(10, 10, "ms"))

Then most of times executing

./gradlew ':server:internalClusterTest' --tests "org.elasticsearch.indices.flush.FlushIT.testFlushOnInactive" -Dtests.random=$RANDOM  -Dtests.seed=38FC56033AE2DC88 -Dtests.locale=en-IN -Dtests.timezone=Europe/Zaporozhye -Druntime.java=17

makes the problem appear.