IndexStatsIT#testFilterCacheStats fails

[dnhatn]

I think this failure relates to Lucene-7.5.

I can't reproduce this locally with this command:

./gradlew :server:integTest -Dtests.seed=528FC320ADC916D8 \
-Dtests.class=org.elasticsearch.indices.stats.IndexStatsIT \
-Dtests.method="testFilterCacheStats" \
-Dtests.security.manager=true \
-Dtests.locale=kk-KZ \
-Dtests.timezone=America/Scoresbysund

FAILURE 0.63s J0 | IndexStatsIT.testFilterCacheStats <<< FAILURES!
   > Throwable #1: java.lang.AssertionError: 
   > Expected: a value greater than <0L>
   >      but: <0L> was equal to <0L>
   > 	at __randomizedtesting.SeedInfo.seed([528FC320ADC916D8:37B03E651DC111A1]:0)
   > 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
   > 	at org.elasticsearch.indices.stats.IndexStatsIT.testFilterCacheStats(IndexStatsIT.java:1046)
   > 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
   > 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
   > 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
   > 	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
   > 	at java.base/java.lang.Thread.run(Thread.java:834)

CI: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+matrix-java-periodic/ES_BUILD_JAVA=java10,ES_RUNTIME_JAVA=java11,nodes=virtual&&linux/210/consoleText

Log: testFilterCacheStats.log

[elasticmachine]

Pinging @elastic/es-distributed

[dnhatn]

I muted this test on the master and 6.x.

[original-brownbear]

I was able to reproduce this locally by simply running the test in a loop with @Repeat (fails in ~ 1% of runs)

[dnhatn]

@original-brownbear I did not look at this yet but I think it should be caused by a background merge.

[original-brownbear]

@dnhatn I spent a little time today reading up on the background here and using trace logging I could verify that this is caused by background merges.
Tried a fix in #36143 that empirically works fine, but I'm not a 100% sure that's the best/right approach at fixing this admittedly.

[pgomulka]

seems like this happened again:
https://mail.google.com/mail/u/1/#search/build-elasticsearch%40elastic.co/FMfcgxwBTjvMmrGnFCTxMhzjZhTCmRJK

REPRODUCE WITH: ./gradlew :server:integTest \
  -Dtests.seed=8B6BB66DA52AD454 \
  -Dtests.class=org.elasticsearch.indices.stats.IndexStatsIT \
  -Dtests.method="testFilterCacheStats" \
  -Dtests.security.manager=true \
  -Dbuild.snapshot=false \
  -Dtests.jvm.argline="-Dbuild.snapshot=false" \
  -Dtests.locale=ar-SY \
  -Dtests.timezone=America/Ojinaga \
  -Dcompiler.java=11 \
  -Druntime.java=8

[original-brownbear]

Link for the above https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+release-tests/221/

I'm not sure this is the same issue that lead to the initial problem. The failure now happens in a busy polling section of the test. I'll look into this.

[original-brownbear]

Added debug logging for this test in 75bfbe9, I couldn't even reproduce a single failing assertion inside the busy assert that fails now. Maybe we can learn more from the log.

[original-brownbear]

Haven't had this happen during the last 17 days it seems. It is conceivable that this was some freak timeout from super slow CI the logging suggests that the assertBusy loop that failed above has changes in the error on a second scale when that same loop locally takes < 50ms. Maybe close this?

[ywelsch]

There was another failure of this on January 4th, but the logs are missing
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+intake/1075/console

[original-brownbear]

Right ... one day after I posted the above ... adding the logs of that failure here for reference and will look into it (now we have debug logging active on this one at least).
20190104112126-D62D8056-log-981F-639551784945182935.txt

[ywelsch]

No recent failures -> closing

[gwbrown]

This failed again on master:

Does not reproduce locally for me with:

./gradlew :server:integTest \
  -Dtests.seed=8574F392212DDB87 \
  -Dtests.class=org.elasticsearch.indices.stats.IndexStatsIT \
  -Dtests.method="testFilterCacheStats" \
  -Dtests.security.manager=true \
  -Dtests.locale=ga \
  -Dtests.timezone=SystemV/CST6CDT \
  -Dcompiler.java=12 \
  -Druntime.java=11

Stack trace:

Expected: <0L>
   >      but: was <1L>
   > 	at __randomizedtesting.SeedInfo.seed([8574F392212DDB87:E04B0ED79125DCFE]:0)
   > 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
   > 	at org.elasticsearch.indices.stats.IndexStatsIT.lambda$testFilterCacheStats$2(IndexStatsIT.java:1047)
   > 	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:862)
   > 	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:836)
   > 	at org.elasticsearch.indices.stats.IndexStatsIT.testFilterCacheStats(IndexStatsIT.java:1041)
   > 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
   > 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
   > 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
   > 	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
   > 	at java.base/java.lang.Thread.run(Thread.java:834)

Full build log:
consoleText.txt

[original-brownbear]

Just for future reference: the above is from https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+matrix-java-periodic/ES_BUILD_JAVA=openjdk12,ES_RUNTIME_JAVA=java11,nodes=immutable&&linux&&docker/313/console

I'll give this another look :)

[bizybot]

This again failed here:
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+internalClusterTest/4457/console

Did not reproduce locally:

./gradlew :server:integTest \
  -Dtests.seed=E5247230732850E0 \
  -Dtests.class=org.elasticsearch.indices.stats.IndexStatsIT \
  -Dtests.method="testFilterCacheStats" \
  -Dtests.security.manager=true \
  -Dtests.locale=vi \
  -Dtests.timezone=America/Paramaribo \
  -Dcompiler.java=12 \
  -Druntime.java=8

Stack trace:

   > Throwable #1: java.lang.AssertionError: 
   > Expected: <0L>
   >      but: was <25L>
   > 	at __randomizedtesting.SeedInfo.seed([E5247230732850E0:801B8F75C3205799]:0)
   > 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
   > 	at org.elasticsearch.indices.stats.IndexStatsIT.lambda$testFilterCacheStats$1(IndexStatsIT.java:1035)
   > 	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:862)
   > 	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:836)
   > 	at org.elasticsearch.indices.stats.IndexStatsIT.testFilterCacheStats(IndexStatsIT.java:1030)
   > 	at java.lang.Thread.run(Thread.java:748)
   > 	Suppressed: java.lang.AssertionError: 

consoleText.txt

[droberts195]

This failed again in 7.0 in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+7.0+matrix-java-periodic/ES_BUILD_JAVA=openjdk12,ES_RUNTIME_JAVA=zulu11,nodes=immutable&&linux&&docker/128/console

The error is:

  2> java.lang.AssertionError: 
    Expected: <0L>
         but: was <1L>
        at __randomizedtesting.SeedInfo.seed([DB1044CE003D83F0:BE2FB98BB0358489]:0)
        at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
        at org.junit.Assert.assertThat(Assert.java:956)
        at org.junit.Assert.assertThat(Assert.java:923)
        at org.elasticsearch.indices.stats.IndexStatsIT.lambda$testFilterCacheStats$2(IndexStatsIT.java:1047)
        at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:868)
        at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:842)
        at org.elasticsearch.indices.stats.IndexStatsIT.testFilterCacheStats(IndexStatsIT.java:1041)

I got a failure the first time I tried to reproduce locally using:

./gradlew :server:integTest --tests "org.elasticsearch.indices.stats.IndexStatsIT.testFilterCacheStats" \
  -Dtests.seed=DB1044CE003D83F0 \
  -Dtests.security.manager=true \
  -Dtests.locale=lb \
  -Dtests.timezone=Asia/Aqtobe \
  -Dcompiler.java=12 \
  -Druntime.java=11

The error I got was:

  2> java.lang.AssertionError: 
    Expected: <0L>
         but: was <12L>
        at __randomizedtesting.SeedInfo.seed([DB1044CE003D83F0:BE2FB98BB0358489]:0)
        at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
        at org.junit.Assert.assertThat(Assert.java:956)
        at org.junit.Assert.assertThat(Assert.java:923)
        at org.elasticsearch.indices.stats.IndexStatsIT.lambda$testFilterCacheStats$1(IndexStatsIT.java:1035)
        at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:868)
        at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:842)
        at org.elasticsearch.indices.stats.IndexStatsIT.testFilterCacheStats(IndexStatsIT.java:1030)

But it's not easily reproducible - I tried 5 more times and didn't see another failure.

[ywelsch]

This continues to fail, e.g. here. @dnhatn what's the issue with this test? Any ideas on why it's failing?

[davidkyle]

Another https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-unix-compatibility/os=oraclelinux-7/382/console

This has failed PR builds and fails frequently enough to warrant muting.

• master ad8591a
• 7.x 256588d

[DaveCTurner]

I have also muted this in 7.1 and 7.0:

• 7.1: 7bd161d
• 7.0: b25b61e