[CI] QueryProfilerIT testProfileMatchesRegular is failing

[danielmitterdorfer]

Test failure: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+intake/2432/console

fails with:

QueryProfilerIT.testProfileMatchesRegular <<< FAILURES!
> Throwable #1: java.lang.AssertionError: Profile totalHits of [127] is not close to Vanilla totalHits [129]
> Expected: <127L>
>      but: was <129L>
> 	at __randomizedtesting.SeedInfo.seed([32784220547E92F2:61AD95220536708E]:0)
> 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
> 	at org.elasticsearch.search.profile.query.QueryProfilerIT.testProfileMatchesRegular(QueryProfilerIT.java:162)
> 	at java.lang.Thread.run(Thread.java:748)

Reproduction line:

./gradlew :server:integTest \
  -Dtests.seed=32784220547E92F2 \
  -Dtests.class=org.elasticsearch.search.profile.query.QueryProfilerIT \
  -Dtests.method="testProfileMatchesRegular" \
  -Dtests.security.manager=true \
  -Dtests.locale=id \
  -Dtests.timezone=America/Curacao

(does not reproduce locally)

[elasticmachine]

Pinging @elastic/es-search-aggs

[polyfractal]

Was not able to reproduce this, even after thousands of iterations. My only idea is that there was a shard failure during the test, which caused one of the two msearch items to have partial results. That would have skewed the counts and made the hits not match identically.

I added assertions for the partial search result scenario, and added some diagnostic output in case we get another situation where the two search hits don't match (it emits the delta between the two sets, hopefully giving us an idea why they didn't match).

Unmuted, hopefully we don't see this failure again :)

[imotov]

@polyfractal Sorry https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-unix-compatibility/os=fedora/2671/console

java.lang.AssertionError: Vanilla hits were larger than profile hits.  Non-overlapping elements were: [{
  "_index" : "test",
  "_type" : "type1",
  "_id" : "111",
  "_score" : null,
  "_source" : {
    "field1" : "one hundred eleven ",
    "field2" : 111
  },
  "sort" : [
    "111"
  ]
}, {
  "_index" : "test",
  "_type" : "type1",
  "_id" : "110",
  "_score" : null,
  "_source" : {
    "field1" : "one hundred ten ",
    "field2" : 110
  },
  "sort" : [
    "110"
  ]
}, {
  "_index" : "test",
  "_type" : "type1",
  "_id" : "106",
  "_score" : null,
  "_source" : {
    "field1" : "one hundred six ",
    "field2" : 106
  },
  "sort" : [
    "106"
  ]
}, {
  "_index" : "test",
  "_type" : "type1",
  "_id" : "115",
  "_score" : null,
  "_source" : {
    "field1" : "one hundred fifteen ",
    "field2" : 115
  },
  "sort" : [
    "115"
  ]
}, {
  "_index" : "test",
  "_type" : "type1",
  "_id" : "0",
  "_score" : null,
  "_source" : {
    "field1" : "zero",
    "field2" : 0
  },
  "sort" : [
    "0"
  ]
}]
	at __randomizedtesting.SeedInfo.seed([CE010CCFED5B2245:9DD4DBCDBC13C039]:0)
	at org.junit.Assert.fail(Assert.java:88)
	at org.elasticsearch.search.profile.query.QueryProfilerIT.testProfileMatchesRegular(QueryProfilerIT.java:173)
	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)

[droberts195]

This happened again in
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+matrix-java-periodic/ES_BUILD_JAVA=java11,ES_RUNTIME_JAVA=java8,nodes=virtual&&linux/24/console

./gradlew :server:integTest \
  -Dtests.seed=D08ACC4764F29DE7 \
  -Dtests.class=org.elasticsearch.search.profile.query.QueryProfilerIT \
  -Dtests.method="testProfileMatchesRegular" \
  -Dtests.security.manager=true \
  -Dtests.locale=es-PA \
  -Dtests.timezone=Pacific/Midway \
  -Dcompiler.java=11 \
  -Druntime.java=8

FAILURE 0.58s J2 | QueryProfilerIT.testProfileMatchesRegular <<< FAILURES!
   > Throwable #1: java.lang.AssertionError: Profile hits were larger than vanilla hits.  Non-overlapping elements were: [{
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "104",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "one hundred four ",
   >     "field2" : 104
   >   },
   >   "sort" : [
   >     "104"
   >   ]
   > }, {
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "105",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "one hundred five ",
   >     "field2" : 105
   >   },
   >   "sort" : [
   >     "105"
   >   ]
   > }, {
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "103",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "one hundred three ",
   >     "field2" : 103
   >   },
   >   "sort" : [
   >     "103"
   >   ]
   > }, {
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "107",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "one hundred seven ",
   >     "field2" : 107
   >   },
   >   "sort" : [
   >     "107"
   >   ]
   > }, {
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "108",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "one hundred eight ",
   >     "field2" : 108
   >   },
   >   "sort" : [
   >     "108"
   >   ]
   > }, {
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "102",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "one hundred two ",
   >     "field2" : 102
   >   },
   >   "sort" : [
   >     "102"
   >   ]
   > }, {
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "109",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "one hundred nine ",
   >     "field2" : 109
   >   },
   >   "sort" : [
   >     "109"
   >   ]
   > }, {
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "10",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "ten ",
   >     "field2" : 10
   >   },
   >   "sort" : [
   >     "10"
   >   ]
   > }, {
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "106",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "one hundred six ",
   >     "field2" : 106
   >   },
   >   "sort" : [
   >     "106"
   >   ]
   > }, {
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "0",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "zero",
   >     "field2" : 0
   >   },
   >   "sort" : [
   >     "0"
   >   ]
   > }]
   > 	at __randomizedtesting.SeedInfo.seed([D08ACC4764F29DE7:835F1B4535BA7F9B]:0)
   > 	at org.elasticsearch.search.profile.query.QueryProfilerIT.testProfileMatchesRegular(QueryProfilerIT.java:177)
   > 	at java.lang.Thread.run(Thread.java:748)

[andyb-elastic]

Another one in master

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-unix-compatibility/os=centos/33/console

build-master-centos-33.txt.zip

  2> REPRODUCE WITH: ./gradlew :server:integTest -Dtests.seed=91857F7F3931F7A9 -Dtests.class=org.elasticsearch.search.profile.query.QueryProfilerIT -Dtests.method="testProfileMatchesRegular" -Dtests.security.manager=true -Dtests.locale=en-AU -Dtests.timezone=Etc/GMT-0 -Dcompiler.java=11 -Druntime.java=8

FAILURE 0.34s J0 | QueryProfilerIT.testProfileMatchesRegular <<< FAILURES!
   > Throwable #1: java.lang.AssertionError: Vanilla hits were larger than profile hits.  Non-overlapping elements were: [{
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "106",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "one hundred six ",
   >     "field2" : 106
   >   },
   >   "sort" : [
   >     "106"
   >   ]
   > }, {
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "104",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "one hundred four ",
   >     "field2" : 104
   >   },
   >   "sort" : [
   >     "104"
   >   ]
   > }, {
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "16",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "sixteen ",
   >     "field2" : 16
   >   },
   >   "sort" : [
   >     "16"
   >   ]
   > }, {
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "102",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "one hundred two ",
   >     "field2" : 102
   >   },
   >   "sort" : [
   >     "102"
   >   ]
   > }, {
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "13",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "thirteen ",
   >     "field2" : 13
   >   },
   >   "sort" : [
   >     "13"
   >   ]
   > }, {
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "17",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "seventeen ",
   >     "field2" : 17
   >   },
   >   "sort" : [
   >     "17"
   >   ]
   > }, {
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "11",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "eleven ",
   >     "field2" : 11
   >   },
   >   "sort" : [
   >     "11"
   >   ]
   > }, {
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "103",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "one hundred three ",
   >     "field2" : 103
   >   },
   >   "sort" : [
   >     "103"
   >   ]
   > }, {
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "14",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "fourteen ",
   >     "field2" : 14
   >   },
   >   "sort" : [
   >     "14"
   >   ]
   > }, {
   >   "_index" : "test",
   >   "_type" : "type1",
   >   "_id" : "10",
   >   "_score" : null,
   >   "_source" : {
   >     "field1" : "ten ",
   >     "field2" : 10
   >   },
   >   "sort" : [
   >     "10"
   >   ]
   > }]
   >    at __randomizedtesting.SeedInfo.seed([91857F7F3931F7A9:C250A87D687915D5]:0)
   >    at org.elasticsearch.search.profile.query.QueryProfilerIT.testProfileMatchesRegular(QueryProfilerIT.java:173)
   >    at java.lang.Thread.run(Thread.java:748)

[andyb-elastic]

The full log is attached for that last one, so in hopes that it caught the debugging info that was added I'm going to mute this again

2a60c24

[polyfractal]

Thanks for grabbing those logs @andyb-elastic! I checked quickly and it doesn't reproduce locally for me... will let it run for a few hours in the background and see if it breaks.

If anyone else from S&A wants to learn how the profiler works I'd be happy to share the debugging :) Definitely not an encouraging failure, having the hits not match...

[polyfractal]

Colin had a good idea; we should verify that all the equals() and hashCode()s are properly setup for profiler weights/queries/scores and make sure there isn't some kind of effect due to returning bad results from cache.

There are also other known caching issues too (#29024) but that deals with the request cache and I don't think it's the issue here due to the randomization. But we should double check the request cache as well just in case.