Elasticsearch: IndicesRequestCacheIT#testQueryRewrite fails

Created on 14 Aug 2018  ·  31Comments  ·  Source: elastic/elasticsearch

IndicesRequestCacheIT#testQueryRewrite fails with an unexpected cache count.

FAILURE 7.39s J1 | IndicesRequestCacheIT.testQueryRewrite <<< FAILURES!
   > Throwable #1: java.lang.AssertionError: 
   > Expected: <3L>
   >      but: was <2L>
   >    at __randomizedtesting.SeedInfo.seed([7B6066660D23E3B1:8A7EC1C3E5F6C580]:0)
   >    at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
   >    at org.elasticsearch.indices.IndicesRequestCacheIT.testQueryRewrite(IndicesRequestCacheIT.java:131)
   >    at java.lang.Thread.run(Thread.java:748)

This does not reproduce locally for me.

./gradlew :server:integTest \
  -Dtests.seed=7B6066660D23E3B1 \
  -Dtests.class=org.elasticsearch.indices.IndicesRequestCacheIT \
  -Dtests.method="testQueryRewrite" \
  -Dtests.security.manager=true \
  -Dtests.locale=en \
  -Dtests.timezone=Europe/Gibraltar \
  -Dcompiler.java=10 \
  -Druntime.java=8

CI: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+periodic/6845/console
Log: testQueryRewrite.txt

:SearcSearch >test-failure
Source
picture dnhatn

All 31 comments

Pinging @elastic/es-search-aggs

elasticmachine picture elasticmachine on 14 Aug 2018

Although on a different test method in the same test class, I think this is the same failure: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+matrix-java-periodic/ES_BUILD_JAVA=java11,ES_RUNTIME_JAVA=java11,nodes=virtual&&linux/265/console . I can't repro either.

07:10:35   1> [2018-08-28T08:10:30,847][INFO ][o.e.i.IndicesRequestCacheIT] [testQueryRewriteDatesWithNow] after test
07:10:35 FAILURE 2.58s J1 | IndicesRequestCacheIT.testQueryRewriteDatesWithNow <<< FAILURES!
07:10:35    > Throwable #1: java.lang.AssertionError: 
07:10:35    > Expected: <2L>
07:10:35    >      but: was <1L>
07:10:35    >   at __randomizedtesting.SeedInfo.seed([FACB28E405660D99:4EC92144B233E176]:0)
07:10:35    >   at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
07:10:35    >   at org.elasticsearch.indices.IndicesRequestCacheIT.testQueryRewriteDatesWithNow(IndicesRequestCacheIT.java:349)
07:10:35    >   at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
07:10:35    >   at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
07:10:35    >   at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
07:10:35    >   at java.base/java.lang.reflect.Method.invoke(Method.java:566)
07:10:35    >   at java.base/java.lang.Thread.run(Thread.java:834)
javanna picture javanna on 28 Aug 2018

I merged https://github.com/elastic/elasticsearch/pull/33313 last week that should hopefully fix this and if not sure provide better information if it occurs again. I'm going to close this issue for now but please re-open if the issue re-occurs

colings86 picture colings86 on 7 Sep 2018

@colings86 after days of silence we have got two new failures in the last 10 hours. Could you take a look if they provide more information:

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+release-tests/33/console
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+matrix-java-periodic/ES_BUILD_JAVA=java11,ES_RUNTIME_JAVA=java8,nodes=virtual&&linux/22/console

imotov picture imotov on 25 Sep 2018

I opened https://github.com/elastic/elasticsearch/pull/34180 to add some more logging information and hopefully see whats going on better

colings86 picture colings86 on 1 Oct 2018

https://github.com/elastic/elasticsearch/pull/34180 is now merged. Please ping me if this fails again as the PR only adds debugging information.

colings86 picture colings86 on 3 Oct 2018

Quick new datapoint on this, I just did a search in the recent CI failures and couldn't find any new occurances of both the IndicesRequestCacheIT.testQueryRewrite and the testQueryRewriteDatesWithNow case since Sep 25th.

cbuescher picture cbuescher on 9 Nov 2018

Have a new instance of this: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+intake/255/console

06:57:43   1> [2018-11-20T14:57:38,969][INFO ][o.e.i.IndicesRequestCacheIT] [testQueryRewrite] [IndicesRequestCacheIT#testQueryRewrite]: cleaning up after test
06:57:43   1> [2018-11-20T14:57:39,018][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_sm2] [index/j7ReR8i1R1OIrDAmbZH9RA] deleting index
06:57:43   1> [2018-11-20T14:57:39,113][INFO ][o.e.c.m.MetaDataIndexTemplateService] [node_sm2] removing template [random_index_template]
06:57:43   1> [2018-11-20T14:57:39,131][INFO ][o.e.i.IndicesRequestCacheIT] [testQueryRewrite] [IndicesRequestCacheIT#testQueryRewrite]: cleaned up after test
06:57:43   1> [2018-11-20T14:57:39,131][INFO ][o.e.i.IndicesRequestCacheIT] [testQueryRewrite] after test
06:57:43 FAILURE 13.2s J6 | IndicesRequestCacheIT.testQueryRewrite <<< FAILURES!
06:57:43    > Throwable #1: java.lang.AssertionError: expected:<[6, 9, 0]> but was:<[5, 10, 0]>
06:57:43    >   at __randomizedtesting.SeedInfo.seed([48E304082D784C6:F59097E56A02A2F7]:0)
06:57:43    >   at org.elasticsearch.indices.IndicesRequestCacheIT.assertCacheState(IndicesRequestCacheIT.java:422)
06:57:43    >   at org.elasticsearch.indices.IndicesRequestCacheIT.testQueryRewrite(IndicesRequestCacheIT.java:144)
06:57:43    >   at java.lang.Thread.run(Thread.java:748)
jbaiera picture jbaiera on 20 Nov 2018

We have a couple more errors this weekend:

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+multijob-unix-compatibility/os=centos/80/console

java.lang.AssertionError: 
Expected: <1L>
     but: was <0L>
    at __randomizedtesting.SeedInfo.seed([43BC570BE27C13A6:F7BE5EAB5529FF49]: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.IndicesRequestCacheIT.testQueryRewriteDatesWithNow(IndicesRequestCacheIT.java:319)

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+multijob-unix-compatibility/os=fedora/79/console

ava.lang.AssertionError: 
Expected: <3L>
     but: was <2L>
    at __randomizedtesting.SeedInfo.seed([9A2FA9AA40878B16:6B310E0FA852AD27]: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.IndicesRequestCacheIT.testQueryRewrite(IndicesRequestCacheIT.java:130)
iverase picture iverase on 26 Nov 2018

Not testQueryRewrite, but another test from IndicesRequestCacheIT failed on master intake.

This does NOT reproduce locally on me:
./gradlew :server:integTest \
-Dtests.seed=9708FF54BBAD3138 \
-Dtests.class=org.elasticsearch.indices.IndicesRequestCacheIT \
-Dtests.method="testCacheWithFilteredAlias" \
-Dtests.security.manager=true \
-Dtests.locale=es \
-Dtests.timezone=America/Yellowknife \
-Dcompiler.java=11 \
-Druntime.java=8

Log:
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+intake/928/console

mayya-sharipova picture mayya-sharipova on 20 Dec 2018

Another example just came up on 6.6.

Link to the build: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.6+periodic/225

Command to reproduce:

./gradlew :server:integTest \
  -Dtests.seed=7D08E34E0F1FF7B9 \
  -Dtests.class=org.elasticsearch.indices.IndicesRequestCacheIT \
  -Dtests.method="testQueryRewriteDatesWithNow" \
  -Dtests.security.manager=true \
  -Dtests.locale=he \
  -Dtests.timezone=America/Recife \
  -Dcompiler.java=11 \
  -Druntime.java=8
jtibshirani picture jtibshirani on 26 Jan 2019

Haven't been able to replicate this yet, but had a thought: could time of test run be affecting the testQueryRewriteDatesWithNow tests? E.g. if the test run happens over midnight in the specified timezone, maybe one of the values is falling out of the range and affecting how the query is rewritten (and values that match)?

Perhaps the gte range could be rewritten to always go way past the last document?

polyfractal picture polyfractal on 8 Feb 2019

I have done some investigations for testQueryRewrite test case.

On 6.x it fails from time to time, and Colin's PR to use forceMerge will be backported to 6.7 to help with failures.

On master (after Colin's change) it fails very very occasionally. Last failure was in Nov, 2018.
Colin's log helped a lot to see why failure happens: 

 [2018-11-20T14:57:38,917][TRACE][o.e.i.IndicesRequestCache] [node_sd4] Cache hit for reader version [10] and request:
Shard: [index][2] 
Source:  {"size":0,"timeout":"1d","query":{"range":{"s":{"from":null,"to":null,"include_lower":true,"include_upper":true,"boost":1.0}}}}

[2018-11-20T14:57:38,952][TRACE][o.e.i.IndicesRequestCache] [node_sd4] Cache miss for reader version [11] and request:
Shard: [index][2]
Source:  {"size":0,"timeout":"1d","query":{"range":{"s":{"from":null,"to":null,"include_lower":true,"include_upper":true,"boost":1.0}}}}

The second miss was supposed to be hit (the query is still the same). But it became a miss because cache got invalidated as the reader changed its version from 10 to 11. The version change in the reader happens only where there is a change introduced by IndexWriter. I am still not sure how any index change could happened here, as we are first doing blocking forceMerge and refresh before any searches.

mayya-sharipova picture mayya-sharipova on 21 Feb 2019

We had another failure last night, this time in a different test method on the same class:

java.lang.AssertionError: expected:<[1, 1, 0]> but was:<[0, 2, 0]>
    at __randomizedtesting.SeedInfo.seed([837DAA566443EF4B:C4AE44D1149A5879]:0)
    at org.junit.Assert.fail(Assert.java:88)
    at org.junit.Assert.failNotEquals(Assert.java:834)
    at org.junit.Assert.assertEquals(Assert.java:118)
    at org.junit.Assert.assertEquals(Assert.java:144)
    at org.elasticsearch.indices.IndicesRequestCacheIT.assertCacheState(IndicesRequestCacheIT.java:424)
    at org.elasticsearch.indices.IndicesRequestCacheIT.testCacheWithFilteredAlias(IndicesRequestCacheIT.java:406)

Link to build: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+internalClusterTest/1678/console

Reproduce line (doesn't reproduce, of course):

REPRODUCE WITH: ./gradlew :server:integTest \
  -Dtests.seed=837DAA566443EF4B \
  -Dtests.class=org.elasticsearch.indices.IndicesRequestCacheIT \
  -Dtests.method="testCacheWithFilteredAlias" \
  -Dtests.security.manager=true \
  -Dtests.locale=sv-SE \
  -Dtests.timezone=Europe/Amsterdam \
  -Dcompiler.java=11 \
  -Druntime.java=8
romseygeek picture romseygeek on 22 Feb 2019

Relevant part of the logs for reader versions:

01:57:13   1> [2019-02-22T02:57:07,105][INFO ][o.e.p.PluginsService     ] [testCacheWithFilteredAlias] loaded plugin [org.elasticsearch.transport.nio.MockNioTransportPlugin]
01:57:13   1> [2019-02-22T02:57:07,745][TRACE][o.e.i.IndicesRequestCache] [node_s2] Cache miss for reader version [7] and request:
01:57:13   1>  Shard: [index][0]
01:57:13   1> Source:
01:57:13   1> {"size":0,"query":{"range":{"created_at":{"from":null,"to":null,"include_lower":true,"include_upper":true,"boost":1.0}}}}
01:57:13   1> [2019-02-22T02:57:07,808][TRACE][o.e.i.IndicesRequestCache] [node_s2] Cache miss for reader version [9] and request:
01:57:13   1>  Shard: [index][0]
01:57:13   1> Source:
01:57:13   1> {"size":0,"query":{"range":{"created_at":{"from":null,"to":null,"include_lower":true,"include_upper":true,"boost":1.0}}}}
01:57:13   1> [2019-02-22T02:57:07,831][INFO ][o.e.i.IndicesRequestCacheIT] [testCacheWithFilteredAlias] [IndicesRequestCacheIT#testCacheWithFilteredAlias]: cleaning up after test
01:57:13   1> [2019-02-22T02:57:07,863][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_s1] [index/tUjeiKVrRU2oaImpCPeTvQ] deleting index
01:57:13   1> [2019-02-22T02:57:07,932][INFO ][o.e.c.m.MetaDataIndexTemplateService] [node_s1] removing template [random_index_template]
01:57:13   1> [2019-02-22T02:57:07,954][INFO ][o.e.i.IndicesRequestCacheIT] [testCacheWithFilteredAlias] [IndicesRequestCacheIT#testCacheWithFilteredAlias]: cleaned up after test
01:57:13   1> [2019-02-22T02:57:07,954][INFO ][o.e.i.IndicesRequestCacheIT] [testCacheWithFilteredAlias] after test
01:57:13 FAILURE 2.17s J6 | IndicesRequestCacheIT.testCacheWithFilteredAlias <<< FAILURES!
01:57:13    > Throwable #1: java.lang.AssertionError: expected:<[1, 1, 0]> but was:<[0, 2, 0]>
01:57:13    >   at __randomizedtesting.SeedInfo.seed([837DAA566443EF4B:C4AE44D1149A5879]:0)
01:57:13    >   at org.elasticsearch.indices.IndicesRequestCacheIT.assertCacheState(IndicesRequestCacheIT.java:424)
01:57:13    >   at org.elasticsearch.indices.IndicesRequestCacheIT.testCacheWithFilteredAlias(IndicesRequestCacheIT.java:406)
01:57:13    >   at java.lang.Thread.run(Thread.java:748)
colings86 picture colings86 on 22 Feb 2019

The forcemerge request before we start sending search requests should be blocking until it completes. My only thoughts on how we could still end up with a refresh after this is:

  1. The forcemerge request timed out. I don't think this can be the case since the check on the response would fail if that happened
  2. The forcemerge is blocking but it doesn't block waiting for the subsequent refresh. If it does not wait for the refresh then its possible that there is a race condition between the search requests and the refresh particularly on CI workers with a high load. Not sure about this so we should investigate if this scenario is possible.
  3. A refresh from a merge is pending whilst the forcemerge refresh happens and completes (unblocking the test) and then the pending refresh happens changing the reader. Again I'm not sure if this is possible
colings86 picture colings86 on 22 Feb 2019
👍1

2. The forcemerge is blocking but it doesn't block waiting for the subsequent refresh. If it does not wait for the refresh then its possible that there is a race condition between the search requests and the refresh particularly on CI workers with a high load. Not sure about this so we should investigate if this scenario is possible.

From what I can see the flush operation is synchronous with the forcemerge inside InternalEngine so scenario 2 does not seem to be possible

colings86 picture colings86 on 22 Feb 2019

One thing that might help, though I don't think will solve the issue entirely is to move the refresh() so its after the forcemerge request. The testCacheWithFilteredAlias is the only test method where we refresh and then forcemerge rather than the other way around. The reason I don't think it will solve the issue entirely is that the testQueryRewrite still fails.

colings86 picture colings86 on 22 Feb 2019

Some failure analysis:

Colin introduced fixes of forceMerge in Sep 2018. Since then we had 17 failures of IndicesRequestCacheIT.assertCacheState:

screenshot 2019-02-26 10 21 40

From these 17 failures:

  • 15 with testCacheWithFilteredAlias
  • 1 with testQueryRewrite on Nov 20, 2018
  • 1 with testQueryRewriteDates on Sep 25, 2018

39401 should fix failures with testCacheWithFilteredAlias, then we are only left with two unaddressed failures that we can't explain and that have not happened for more than 3 months. We will monitor failures with IndicesRequestCacheIT, but if they don't happen again, we may think of closing this test failure issue.

mayya-sharipova picture mayya-sharipova on 26 Feb 2019

@mayya-sharipova I wonder if there is any more debug logging we could add to determine where the extra flush is coming from if the failures do re-occur? Maybe we could put some extra debug or trace logging in the flush code to log extra info when this happens?

colings86 picture colings86 on 26 Feb 2019
👍1

@colings86 Looks like IndexReader updates its version (and hence invalidates a cache) in two scenarios:
1) IndexWriter has written something new, created a new segment
2) There was a flush operation (a new Lucene commit) even if there was not any new data. I don't know what causes flush (translog causes it, synchronization?), and when it happens, but as you suggested I have created a PR #39475 to add extra debugging information for flush. This will help us to see if there was some unexpected flush operation.

mayya-sharipova picture mayya-sharipova on 27 Feb 2019

Another failure in testQueryRewriteDatesWithNow on 6.6

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.6+multijob-unix-compatibility/os=ubuntu-16.04&&immutable/172/console

test.log

The reproduce line, obviously it does not reproduce

./gradlew :server:integTest \
  -Dtests.seed=3E9D64409C145E8A \
  -Dtests.class=org.elasticsearch.indices.IndicesRequestCacheIT \
  -Dtests.method="testQueryRewriteDatesWithNow" \
  -Dtests.security.manager=true \
  -Dtests.locale=es-SV \
  -Dtests.timezone=Africa/Sao_Tome \
  -Dcompiler.java=11 \
  -Druntime.java=8
davidkyle picture davidkyle on 15 Mar 2019
👍1

Another one in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.8+periodic/390/console

Failure:

FAILURE 1.41s J7 | IndicesRequestCacheIT.testQueryRewriteDatesWithNow <<< FAILURES!
17:44:20    > Throwable #1: java.lang.AssertionError: expected:<[1, 1]> but was:<[0, 2]>
17:44:20    >   at __randomizedtesting.SeedInfo.seed([C2622D4632A7E5E8:766024E685F20907]:0)
17:44:20    >   at org.elasticsearch.indices.IndicesRequestCacheIT.assertCacheState(IndicesRequestCacheIT.java:418)
17:44:20    >   at org.elasticsearch.indices.IndicesRequestCacheIT.testQueryRewriteDatesWithNow(IndicesRequestCacheIT.java:286)
17:44:20    >   at java.lang.Thread.run(Thread.java:748)
dimitris-athanasiou picture dimitris-athanasiou on 8 Aug 2019

Looks like we had another instance of it in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.8+matrix-java-periodic/ES_BUILD_JAVA=openjdk12,ES_RUNTIME_JAVA=adoptopenjdk8,nodes=general-purpose/256/console

java.lang.AssertionError: expected:<[2, 1]> but was:<[1, 2]>
    at __randomizedtesting.SeedInfo.seed([2F95A00A75A8377F:9B97A9AAC2FDDB90]:0)
    at org.junit.Assert.fail(Assert.java:88)
    at org.junit.Assert.failNotEquals(Assert.java:834)
    at org.junit.Assert.assertEquals(Assert.java:118)
    at org.junit.Assert.assertEquals(Assert.java:144)
    at org.elasticsearch.indices.IndicesRequestCacheIT.assertCacheState(IndicesRequestCacheIT.java:418)
    at org.elasticsearch.indices.IndicesRequestCacheIT.testQueryRewriteDatesWithNow(IndicesRequestCacheIT.java:295)
    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)
imotov picture imotov on 10 Oct 2019

This test failed again today: https://gradle-enterprise.elastic.co/s/zbfbykxpdnfye

with the error:

:server:integTest » org.elasticsearch.indices.IndicesRequestCacheIT » testQueryRewrite (0.800s)
expected:<[6, 9, 0]> but was:<[5, 10, 0]>
java.lang.AssertionError
: 
expected:<[6, 9, 0]> but was:<[5, 10, 0]>
Close stacktrace
at __randomizedtesting.SeedInfo.seed([3C191AB6FF3E40A2:CD07BD1317EB6693]:0)
at org.junit.Assert.fail(Assert.java:88)
at org.junit.Assert.failNotEquals(Assert.java:834)
at org.junit.Assert.assertEquals(Assert.java:118)
at org.junit.Assert.assertEquals(Assert.java:144)
at org.elasticsearch.indices.IndicesRequestCacheIT.assertCacheState(IndicesRequestCacheIT.java:469)
at org.elasticsearch.indices.IndicesRequestCacheIT.testQueryRewrite(IndicesRequestCacheIT.java:150)

Because this test is failing regularly on master so I muted it in de4cf2b7f6e6b50dc7286b654b74c6f13863f0b3.

tlrx picture tlrx on 6 Feb 2020

It also fails on 7.x https://gradle-enterprise.elastic.co/s/tkfitlc3lhwmw

REPRODUCE WITH: ./gradlew ':server:integTest' --tests "org.elasticsearch.indices.IndicesRequestCacheIT.testQueryRewrite" -Dtests.seed=7353DB5A0E87365D -Dtests.security.manager=true -Dtests.locale=sl-SI -Dtests.timezone=America/Hermosillo -Dcompiler.java=13    
  2> java.lang.AssertionError: expected:<[6, 9, 0]> but was:<[5, 10, 0]>    
        at __randomizedtesting.SeedInfo.seed([7353DB5A0E87365D:824D7CFFE652106C]:0) 
        at org.junit.Assert.fail(Assert.java:88)    
        at org.junit.Assert.failNotEquals(Assert.java:834)  
        at org.junit.Assert.assertEquals(Assert.java:118)   
        at org.junit.Assert.assertEquals(Assert.java:144)   
        at org.elasticsearch.indices.IndicesRequestCacheIT.assertCacheState(IndicesRequestCacheIT.java:469) 
        at org.elasticsearch.indices.IndicesRequestCacheIT.testQueryRewrite(IndicesRequestCacheIT.java:150)

I'll wait for one more failure before muting on 7.x as well.

albertzaharovits picture albertzaharovits on 7 Feb 2020

Another time, and also testQueryRewriteDatesWithNow fails:

REPRODUCE WITH: ./gradlew ':server:integTest' --tests "org.elasticsearch.indices.IndicesRequestCacheIT.testQueryRewrite" -Dtests.seed=F4D7D8FF9792A390 -Dtests.security.manager=true -Dtests.locale=ms-MY -Dtests.timezone=America/Ensenada -Dcompiler.java=13  

org.elasticsearch.indices.IndicesRequestCacheIT > testQueryRewrite FAILED   
    java.lang.AssertionError: expected:<[3, 7, 0]> but was:<[2, 8, 0]>  
        at __randomizedtesting.SeedInfo.seed([F4D7D8FF9792A390:5C97F5A7F4785A1]:0)  
        at org.junit.Assert.fail(Assert.java:88)    
        at org.junit.Assert.failNotEquals(Assert.java:834)  
        at org.junit.Assert.assertEquals(Assert.java:118)   
        at org.junit.Assert.assertEquals(Assert.java:144)   
        at org.elasticsearch.indices.IndicesRequestCacheIT.assertCacheState(IndicesRequestCacheIT.java:469) 
        at org.elasticsearch.indices.IndicesRequestCacheIT.testQueryRewrite(IndicesRequestCacheIT.java:141) 

REPRODUCE WITH: ./gradlew ':server:integTest' --tests "org.elasticsearch.indices.IndicesRequestCacheIT.testQueryRewriteDatesWithNow" -Dtests.seed=F4D7D8FF9792A390 -Dtests.security.manager=true -Dtests.locale=ms-MY -Dtests.timezone=America/Ensenada -Dcompiler.java=13  

org.elasticsearch.indices.IndicesRequestCacheIT > testQueryRewriteDatesWithNow FAILED   
    java.lang.AssertionError: expected:<[2, 1, 0]> but was:<[1, 2, 0]>  
        at __randomizedtesting.SeedInfo.seed([F4D7D8FF9792A390:40D5D15F20C74F7F]:0) 
        at org.junit.Assert.fail(Assert.java:88)    
        at org.junit.Assert.failNotEquals(Assert.java:834)  
        at org.junit.Assert.assertEquals(Assert.java:118)   
        at org.junit.Assert.assertEquals(Assert.java:144)   
        at org.elasticsearch.indices.IndicesRequestCacheIT.assertCacheState(IndicesRequestCacheIT.java:469) 
        at org.elasticsearch.indices.IndicesRequestCacheIT.testQueryRewriteDatesWithNow(IndicesRequestCacheIT.java:305)

I'm going to mute this in both master and 7.x, please feel free to revert if I'm being too aggressive.

albertzaharovits picture albertzaharovits on 7 Feb 2020

I've muted testQueryRewriteDatesWithNow in both master (55f303e469d94b4b10b703d1018afc5c206c6f30) and 7.x (e5a9e44ca4de423b4b9e0e2458b1b4346b3b7816) since as mentioned above it has started failing with a similar error.

mark-vieira picture mark-vieira on 7 Feb 2020

Muted testQueryRewrite on master.
See the following three build failures:
https://gradle-enterprise.elastic.co/s/fhw4lkpjv5htu
https://gradle-enterprise.elastic.co/s/6xl6mgypqp26w
https://gradle-enterprise.elastic.co/s/4g5dsdqtiu5m6

albertzaharovits picture albertzaharovits on 24 Mar 2020
👍1

Analyzing console output from this build: https://gradle-enterprise.elastic.co/s/2gsqxhzsvwdjq
expected:<[3, 7, 0]> but was:<[2, 8, 0]>

query: from":"2016-03-19","to":"2016-03-25"

Shard: [index][0] – _doesn't have any docs_
[node_s1] Cache miss for reader version [5], max_doc[0] and request:
Source:
{"size":0,"query":{"match_none":{"boost":1.0}},"aggregations":{"global":{"global":{}}}}

Shard: [index][1] – _doesn't have any docs_
[node_s2] Cache miss for reader version [5], max_doc[0] and request:
Source: {"size":0,"query":{"match_none":{"boost":1.0}},"aggregations":{"global":{"global":{}}}}

Shard: [index][2] – has docs 2016-03-22 – 2016-03-24 – match_all
[node_s0] Cache miss for reader version [9], max_doc[3] and request:
Source: {"size":0,"query":{"range":{"s":{"from":null,"to":null,"include_lower":true,"include_upper":true,"boost":1.0}}},"aggregations":{"global":{"global":{}}}}

Shard: [index][3] – has docs 2016-03-19 – 2016-03-21– match_all
[node_s1] Cache miss for reader version [9], max_doc[3] and request:
Source:{"size":0,"query":{"range":{"s":{"from":null,"to":null,"include_lower":true,"include_upper":true,"boost":1.0}}},"aggregations":{"global":{"global":{}}}}

Shard: [index][4] – _has docs 2016-03-25 – 2016-03-27_
[node_s2] Cache miss for reader version [9], max_doc[3] and request:
Source:{"size":0,"query":{"range":{"s":{"from":"2016-03-19","to":"2016-03-25","include_lower":true,"include_upper":true,"boost":1.0}}},"aggregations":{"global":{"global":{}}}}

query: from":"2016-03-20","to":"2016-03-26"

Shard: [index][0]
[node_s1] Cache hit for reader version [5], max_doc[0] and request:
Source:{"size":0,"query":{"match_none":{"boost":1.0}},"aggregations":{"global":{"global":{}}}}

Shard: [index][1]
[node_s2] Cache hit for reader version [5], max_doc[0] and request:
Source:{"size":0,"query":{"match_none":{"boost":1.0}},"aggregations":{"global":{"global":{}}}}

Shard: [index][2] – has docs 2016-03-22 – 2016-03-24 – match_all
[node_s0] Cache miss for reader version [9], max_doc[3] and request:
Source:{"size":0,"query":{"range":{"s":{"from":null,"to":null,"include_lower":true,"include_upper":true,"boost":1.0}}},"aggregations":{"global":{"global":{}}}}

Shard: [index][3] – –has docs 2016-03-19 – 2016-03-21–
[node_s1] Cache miss for reader version [9], max_doc[3] and request:
Source:{"size":0,"query":{"range":{"s":{"from":"2016-03-20","to":"2016-03-26","include_lower":true,"include_upper":true,"boost":1.0}}},"aggregations":{"global":{"global":{}}}}

Shard: [index][4] – _has docs 2016-03-25 – 2016-03-27_
[node_s2] Cache miss for reader version [9], max_doc[3] and request:
Source:{"size":0,"query":{"range":{"s":{"from":"2016-03-20","to":"2016-03-26","include_lower":true,"include_upper":true,"boost":1.0}}},"aggregations":{"global":{"global":{}}}}

Shard: [index][2] as it rewrites to match_all for both queries should be a hit in the second time, but it was a miss. Looks like cache doesn't work well

mayya-sharipova picture mayya-sharipova on 24 Mar 2020

from another build: https://gradle-enterprise.elastic.co/s/fhw4lkpjv5htu
The similar situation, even if the query was rewritten to the exact same form, we have got the miss, but should have got a hit. This should not happen, as the reader version did not change, and there were not any cache evictions.

expected miss for the 1st time

[node_s0] Cache miss for reader version [10], max_doc[5] and request:
Shard: [index][2]
Source:
{"size":0,"timeout":"1d","query":{"range":{"s":{"from":null,"to":null,"include_lower":true,"include_upper":true,"boost":1.0}}},"aggregations":{"global":{"global":{}}}}

expected hit for the 2nd time

[node_s0] Cache hit for reader version [10], max_doc[5] and request:
Shard: [index][2]
Source:
{"size":0,"timeout":"1d","query":{"range":{"s":{"from":null,"to":null,"include_lower":true,"include_upper":true,"boost":1.0}}},"aggregations":{"global":{"global":{}}}}

unexpected miss for the 3rd time

[node_s0] Cache miss for reader version [10], max_doc[5] and request:
Shard: [index][2]
Source:
{"size":0,"timeout":"1d","query":{"range":{"s":{"from":null,"to":null,"include_lower":true,"include_upper":true,"boost":1.0}}},"aggregations":{"global":{"global":{}}}}

mayya-sharipova picture mayya-sharipova on 24 Mar 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

abtpst picture abtpst  ·  3Comments
makeyang picture makeyang  ·  3Comments
ppf2 picture ppf2  ·  3Comments
dawi picture dawi  ·  3Comments
DhairyashilBhosale picture DhairyashilBhosale  ·  3Comments