Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

IndicesRequestCacheIT#testQueryRewrite fails #32827

Closed
dnhatn opened this issue Aug 13, 2018 · 31 comments · Fixed by #54071
Closed

IndicesRequestCacheIT#testQueryRewrite fails #32827

dnhatn opened this issue Aug 13, 2018 · 31 comments · Fixed by #54071
Assignees
Labels
:Search/Search Search-related issues that do not fall into other categories >test-failure Triaged test failures from CI

Comments

@dnhatn
Copy link
Member

dnhatn commented Aug 13, 2018

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

@dnhatn dnhatn added :Search/Search Search-related issues that do not fall into other categories >test-failure Triaged test failures from CI labels Aug 13, 2018
@elasticmachine
Copy link
Collaborator

Pinging @elastic/es-search-aggs

@javanna
Copy link
Member

javanna commented Aug 28, 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)

@colings86 colings86 self-assigned this Aug 31, 2018
colings86 added a commit that referenced this issue Sep 3, 2018
* Adds code to help with IndicesRequestCacheIT failures

Relates to #32827

* Adds comment

* Fixes test failure
@colings86
Copy link
Contributor

I merged #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

@imotov
Copy link
Contributor

imotov commented Sep 25, 2018

@colings86
Copy link
Contributor

I opened #34180 to add some more logging information and hopefully see whats going on better

@colings86
Copy link
Contributor

#34180 is now merged. Please ping me if this fails again as the PR only adds debugging information.

colings86 added a commit that referenced this issue Oct 3, 2018
* Adds trace logging to IndicesRequestCache

This change adds trace level logging to `IndicesrrequestCache` witht eh
primary aim of helping to identify the cause of teh failures in
#32827. The cache will
log at trace level when a cache hit or miss occurs including the reader
version and the cache key. Note that this change adds a
`cacheKeyRenderer` whcih supplies a human readable String of the cache
key since the actual cache key itself is a `BytesReference` containing
the wire protocol serialised form of the request.

Logging is also added for the case where a search timeout occurs and fr
that reason the cache entry is invalidated.

* Adds comment to remaind us to remove cacheKeyRenderer
kcm pushed a commit that referenced this issue Oct 30, 2018
* Adds trace logging to IndicesRequestCache

This change adds trace level logging to `IndicesrrequestCache` witht eh
primary aim of helping to identify the cause of teh failures in
#32827. The cache will
log at trace level when a cache hit or miss occurs including the reader
version and the cache key. Note that this change adds a
`cacheKeyRenderer` whcih supplies a human readable String of the cache
key since the actual cache key itself is a `BytesReference` containing
the wire protocol serialised form of the request.

Logging is also added for the case where a search timeout occurs and fr
that reason the cache entry is invalidated.

* Adds comment to remaind us to remove cacheKeyRenderer
@cbuescher
Copy link
Member

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.

@jbaiera
Copy link
Member

jbaiera commented Nov 20, 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)

@iverase
Copy link
Contributor

iverase commented Nov 26, 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)

@mayya-sharipova
Copy link
Contributor

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

@jtibshirani
Copy link
Contributor

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

@polyfractal
Copy link
Contributor

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?

@colings86 colings86 removed their assignment Feb 19, 2019
@mayya-sharipova mayya-sharipova self-assigned this Feb 19, 2019
@mayya-sharipova
Copy link
Contributor

mayya-sharipova commented Feb 21, 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 added a commit that referenced this issue Feb 21, 2019
Adds code to help with IndicesRequestCacheIT failures

Relates to #32827
Backport for #33313
@romseygeek
Copy link
Contributor

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

@colings86
Copy link
Contributor

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
Copy link
Contributor

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

@imotov
Copy link
Contributor

imotov commented Oct 10, 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)

tlrx added a commit that referenced this issue Feb 6, 2020
@tlrx
Copy link
Member

tlrx commented Feb 6, 2020

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 de4cf2b.

@albertzaharovits
Copy link
Contributor

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
Copy link
Contributor

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.

@mark-vieira
Copy link
Contributor

mark-vieira commented Feb 7, 2020

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

mayya-sharipova added a commit to mayya-sharipova/elasticsearch that referenced this issue Mar 19, 2020
This adds reenables IndicesRequestCacheIT.testQueryRewrite
and enables logging for it.

Relates to elastic#32827
mayya-sharipova added a commit that referenced this issue Mar 23, 2020
This adds reenables IndicesRequestCacheIT.testQueryRewrite
and enables logging for it.

Relates to #32827
@albertzaharovits
Copy link
Contributor

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

@mayya-sharipova
Copy link
Contributor

mayya-sharipova commented Mar 24, 2020

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
Copy link
Contributor

mayya-sharipova commented Mar 24, 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":{}}}}

jimczi added a commit to jimczi/elasticsearch that referenced this issue Mar 24, 2020
This commit ensures that we don't use the non-deterministic canReturnNullResponseIfMatchNoDocs
boolean in the cache key of the ShardSearchRequest. The value of this boolean has no influence
on the cacheability of the request.

Closes elastic#32827
jimczi added a commit that referenced this issue Mar 24, 2020
This commit ensures that we don't use the non-deterministic canReturnNullResponseIfMatchNoDocs
boolean in the cache key of the ShardSearchRequest. The value of this boolean has no influence
on the cacheability of the request.

Closes #32827
jimczi added a commit that referenced this issue Mar 24, 2020
This commit ensures that we don't use the non-deterministic canReturnNullResponseIfMatchNoDocs
boolean in the cache key of the ShardSearchRequest. The value of this boolean has no influence
on the cacheability of the request.

Closes #32827
javanna added a commit to javanna/elasticsearch that referenced this issue Sep 17, 2020
In the context of of a recurring test failure tracked by elastic#32827, we added trace logging and an extra cache key renderer argument to IndicesRequestCache#getOrCompute (see elastic#39475 and elastic#34180).

We addressed the issue with elastic#54071, but the extra argument was left behind, with a NORELEASE comment saying it should be removed.

With this commit, we remove the extra cache key rendered argument and the corresponding log lines which are not so useful without it.

Closes elastic#55837
javanna added a commit that referenced this issue Sep 18, 2020
In the context of of a recurring test failure tracked by #32827, we added trace logging and an extra cache key renderer argument to IndicesRequestCache#getOrCompute (see #39475 and #34180).

We addressed the issue with #54071, but the extra argument was left behind, with a NORELEASE comment saying it should be removed.

With this commit, we remove the extra cache key rendered argument and the corresponding log lines which are not so useful without it.

Closes #55837
javanna added a commit to javanna/elasticsearch that referenced this issue Sep 18, 2020
…62534)

In the context of of a recurring test failure tracked by elastic#32827, we added trace logging and an extra cache key renderer argument to IndicesRequestCache#getOrCompute (see elastic#39475 and elastic#34180).

We addressed the issue with elastic#54071, but the extra argument was left behind, with a NORELEASE comment saying it should be removed.

With this commit, we remove the extra cache key rendered argument and the corresponding log lines which are not so useful without it.

Closes elastic#55837
javanna added a commit that referenced this issue Sep 18, 2020
In the context of of a recurring test failure tracked by #32827, we added trace logging and an extra cache key renderer argument to IndicesRequestCache#getOrCompute (see #39475 and #34180).

We addressed the issue with #54071, but the extra argument was left behind, with a NORELEASE comment saying it should be removed.

With this commit, we remove the extra cache key rendered argument and the corresponding log lines which are not so useful without it.

Closes #55837
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
:Search/Search Search-related issues that do not fall into other categories >test-failure Triaged test failures from CI
Projects
None yet
Development

Successfully merging a pull request may close this issue.