[CI] wipeRollupJobs fails to cleanup job and causes multiple test failures

[tvernum]

From https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+7.x+intake/92/consoleFull

The first failure seems to have been actually running the stop-job snippet:

23:26:34   1> [2019-02-14T00:24:33,170][ERROR][o.e.s.DocsClientYamlTestSuiteIT] [test] This failing test was generated by documentation starting at reference/rollup/apis/stop-job.asciidoc:line_54. It may include many snippets. See docs/README.asciidoc for an explanation of test generation.
23:26:34 ERROR   10.4s | DocsClientYamlTestSuiteIT.test {yaml=reference/rollup/apis/stop-job/line_54} <<< FAILURES!
23:26:34    > Throwable #1: org.elasticsearch.client.ResponseException: method [POST], host [http://[::1]:39829], URI [/_rollup/job/sensor/_stop?wait_for_completion=true&timeout=10s], status line [HTTP/1.1 500 Internal Server Error]
23:26:34    > {"error":{"root_cause":[{"type":"timeout_exception","reason":"Timed out after [10s] while waiting for rollup job [sensor] to stop. State was [STOPPING]"}],"type":"timeout_exception","reason":"Timed out after [10s] while waiting for rollup job [sensor] to stop. State was [STOPPING]"},"status":500}
23:26:34    > 	at __randomizedtesting.SeedInfo.seed([4C8232EC98ABC116:C4D60D363657ACEE]:0)
23:26:34    > 	at org.elasticsearch.client.RestClient.convertResponse(RestClient.java:260)
23:26:34    > 	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:238)
23:26:34    > 	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:212)
23:26:34    > 	at org.elasticsearch.test.rest.ESRestTestCase.wipeRollupJobs(ESRestTestCase.java:597)
23:26:34    > 	at org.elasticsearch.test.rest.ESRestTestCase.wipeCluster(ESRestTestCase.java:509)
23:26:34    > 	at org.elasticsearch.test.rest.ESRestTestCase.cleanUpCluster(ESRestTestCase.java:295)
23:26:34    > 	at java.lang.Thread.run(Thread.java:748)
23:26:34   1> [2019-02-14T00:24:33,179][INFO ][o.e.s.DocsClientYamlTestSuiteIT] [test] [yaml=reference/ml/detector-custom-rules/line_146] before test
23:26:34   1> [2019-02-14T00:24:43,241][INFO ][o.e.s.DocsClientY

But this caused other doc snippets to fail as they tried to clean up the cluster

23:26:34 ERROR   10.2s | DocsClientYamlTestSuiteIT.test {yaml=reference/indices/forcemerge/line_47} <<< FAILURES!
23:26:34    > Throwable #1: org.elasticsearch.client.ResponseException: method [POST], host [http://[::1]:39829], URI [/_rollup/job/sensor/_stop?wait_for_completion=true&timeout=10s], status line [HTTP/1.1 500 Internal Server Error]
23:26:34    > {"error":{"root_cause":[{"type":"timeout_exception","reason":"Timed out after [10s] while waiting for rollup job [sensor] to stop. State was [STOPPING]"}],"type":"timeout_exception","reason":"Timed out after [10s] while waiting for rollup job [sensor] to stop. State was [STOPPING]"},"status":500}
23:26:34    > 	at __randomizedtesting.SeedInfo.seed([4C8232EC98ABC116:C4D60D363657ACEE]:0)
23:26:34    > 	at org.elasticsearch.client.RestClient.convertResponse(RestClient.java:260)
23:26:34    > 	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:238)
23:26:34    > 	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:212)
23:26:34    > 	at org.elasticsearch.test.rest.ESRestTestCase.wipeRollupJobs(ESRestTestCase.java:597)
23:26:34    > 	at org.elasticsearch.test.rest.ESRestTestCase.wipeCluster(ESRestTestCase.java:509)
23:26:34    > 	at org.elasticsearch.test.rest.ESRestTestCase.cleanUpCluster(ESRestTestCase.java:295)
23:26:34    > 	at java.lang.Thread.run(Thread.java:748)
23:26:34   1> [2019-02-14T00:25:03,686][INFO ][o.e.s.DocsClientYamlTestSuiteIT] [test] [yaml=reference/how-to/search-speed/line_87] before test
23:26:34   1> [2019-02-14T00:25:13,898][INFO ][o.e.s.DocsClientYamlTestSuiteIT] [test] [yaml=reference/how-to/search-speed/line_87] after test
23:26:34   1> [2019-02-14T00:25:13,898][ERROR][o.e.s.DocsClientYamlTestSuiteIT] [test] This failing test was generated by documentation starting at reference/how-to/search-speed.asciidoc:line_87. It may include many snippets. See docs/README.asciidoc for an explanation of test generation.
23:26:34 ERROR   10.2s | DocsClientYamlTestSuiteIT.test {yaml=reference/how-to/search-speed/line_87} <<< FAILURES!
23:26:34    > Throwable #1: org.elasticsearch.client.ResponseException: method [POST], host [http://[::1]:39829], URI [/_rollup/job/sensor/_stop?wait_for_completion=true&timeout=10s], status line [HTTP/1.1 500 Internal Server Error]
23:26:34    > {"error":{"root_cause":[{"type":"timeout_exception","reason":"Timed out after [10s] while waiting for rollup job [sensor] to stop. State was [STOPPING]"}],"type":"timeout_exception","reason":"Timed out after [10s] while waiting for rollup job [sensor] to stop. State was [STOPPING]"},"status":500}
23:26:34    > 	at __randomizedtesting.SeedInfo.seed([4C8232EC98ABC116:C4D60D363657ACEE]:0)
23:26:34    > 	at org.elasticsearch.client.RestClient.convertResponse(RestClient.java:260)
23:26:34    > 	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:238)
23:26:34    > 	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:212)
23:26:34    > 	at org.elasticsearch.test.rest.ESRestTestCase.wipeRollupJobs(ESRestTestCase.java:597)
23:26:34    > 	at org.elasticsearch.test.rest.ESRestTestCase.wipeCluster(ESRestTestCase.java:509)
23:26:34    > 	at org.elasticsearch.test.rest.ESRestTestCase.cleanUpCluster(ESRestTestCase.java:295)
23:26:34    > 	at java.lang.Thread.run(Thread.java:748)
23:26:34   1> [2019-02-14T00:25:13,905][INFO ][o.e.s.DocsClientYamlTestSuiteIT] [test] [yaml=reference/aggregations/bucket/terms-aggregation/line_57] before test

With an end result of these failures

• DocsClientYamlTestSuiteIT test {yaml=reference/frozen-indices/line_52}
• DocsClientYamlTestSuiteIT test {yaml=reference/how-to/search-speed/line_87}
• DocsClientYamlTestSuiteIT test {yaml=reference/indices/forcemerge/line_47}
• DocsClientYamlTestSuiteIT test {yaml=reference/ml/detector-custom-rules/line_146}
• DocsClientYamlTestSuiteIT test {yaml=reference/rollup/apis/stop-job/line_54}

It (unsurprisingly) doesn't reproduce for me.
job-92-consoleLog.txt.gz

[elasticmachine]

Pinging @elastic/es-analytics-geo

[polyfractal]

Will take a closer look tomorrow, but I think this is another manifestation of #35295. Good news is that I think I've uncovered the sequence of events that leads to this issue (see last comment in that thread). Unfortunately when I increased logging verbosity to nail it down it has made the reproduction even more rare :(

If I can't nail it down for certain, I have a potential fix which I can optimistically apply. Going to give it another day or two of tweaking before I give up though.

Sorry for the noise! Will take a look at the logs tomorrow

[droberts195]

The same thing happened in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+7.x+multijob-unix-compatibility/os=ubuntu-14.04&&immutable/16/console

The following tests failed:

org.elasticsearch.smoketest.DocsClientYamlTestSuiteIT test {yaml=reference/query-dsl/percolate-query/line_15}
org.elasticsearch.smoketest.DocsClientYamlTestSuiteIT test {yaml=reference/rollup/apis/rollup-job-config/line_17}
org.elasticsearch.smoketest.DocsClientYamlTestSuiteIT test {yaml=reference/rollup/apis/stop-job/line_54}
org.elasticsearch.smoketest.DocsClientYamlTestSuiteIT test {yaml=reference/search/search-template/line_41}

The errors in the log are all about stopping rollup jobs. Again the first failure is on line 54 of stop-job.asciidoc:

  1> [2019-02-14T05:59:11,136][ERROR][o.e.s.DocsClientYamlTestSuiteIT] [test] This failing test was generated by documentation starting at reference/rollup/apis/stop-job.asciidoc:line_54. It may include many snippets. See docs/README.asciidoc for an explanation of test generation.
ERROR   10.4s | DocsClientYamlTestSuiteIT.test {yaml=reference/rollup/apis/stop-job/line_54} <<< FAILURES!
   > Throwable #1: org.elasticsearch.client.ResponseException: method [POST], host [http://[::1]:34393], URI [/_rollup/job/sensor/_stop?wait_for_completion=true&timeout=10s], status line [HTTP/1.1 500 Internal Server Error]
   > {"error":{"root_cause":[{"type":"timeout_exception","reason":"Timed out after [10s] while waiting for rollup job [sensor] to stop. State was [STOPPING]"}],"type":"timeout_exception","reason":"Timed out after [10s] while waiting for rollup job [sensor] to stop. State was [STOPPING]"},"status":500}
   > 	at __randomizedtesting.SeedInfo.seed([3CF41B673DF39E7C:B4A024BD930FF384]:0)
   > 	at org.elasticsearch.client.RestClient.convertResponse(RestClient.java:260)
   > 	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:238)
   > 	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:212)
   > 	at org.elasticsearch.test.rest.ESRestTestCase.wipeRollupJobs(ESRestTestCase.java:597)
   > 	at org.elasticsearch.test.rest.ESRestTestCase.wipeCluster(ESRestTestCase.java:509)
   > 	at org.elasticsearch.test.rest.ESRestTestCase.cleanUpCluster(ESRestTestCase.java:295)
   > 	at java.lang.Thread.run(Thread.java:748)

The node log from the test cluster shows a race on the sensor_rollup index - it looks like the rollup job was competing with the cleanup the test framework does in between tests:

[2019-02-14T08:59:00,884][INFO ][o.e.c.m.MetaDataCreateIndexService] [node-0] [sensor_rollup] creating index, cause [api], templates [], shards [1]/[1], mappings [_doc]
[2019-02-14T08:59:00,992][INFO ][o.e.x.r.j.RollupJobTask  ] [node-0] Rollup job [sensor] created.
[2019-02-14T08:59:01,034][INFO ][o.e.c.m.MetaDataMappingService] [node-0] [sensor_rollup/oWDagWPqRnOaTLlmaRwpeg] update_mapping [_doc]
[2019-02-14T08:59:01,049][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node-0] [sensor_rollup/oWDagWPqRnOaTLlmaRwpeg] deleting index
[2019-02-14T08:59:01,049][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node-0] [sensor-1/f2x_8Qc4T4eiBLUPV4ItZQ] deleting index
[2019-02-14T08:59:01,082][DEBUG][o.e.a.a.i.m.p.TransportPutMappingAction] [node-0] failed to put mappings on indices [[[sensor_rollup/oWDagWPqRnOaTLlmaRwpeg]]], type [_doc]
org.elasticsearch.index.IndexNotFoundException: no such index [sensor_rollup]
    at org.elasticsearch.cluster.metadata.MetaData.getIndexSafe(MetaData.java:662) ~[elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at org.elasticsearch.cluster.metadata.MetaDataMappingService$PutMappingExecutor.execute(MetaDataMappingService.java:230) ~[elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at org.elasticsearch.cluster.service.MasterService.executeTasks(MasterService.java:687) ~[elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at org.elasticsearch.cluster.service.MasterService.calculateTaskOutputs(MasterService.java:310) ~[elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at org.elasticsearch.cluster.service.MasterService.runTasks(MasterService.java:210) [elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT] 
    at org.elasticsearch.cluster.service.MasterService$Batcher.run(MasterService.java:142) [elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at org.elasticsearch.cluster.service.TaskBatcher.runIfNotProcessed(TaskBatcher.java:150) [elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at org.elasticsearch.cluster.service.TaskBatcher$BatchedTask.run(TaskBatcher.java:188) [elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:681) [elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.runAndClean(PrioritizedEsThreadPoolExecutor.java:252) [elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.run(PrioritizedEsThreadPoolExecutor.java:215) [elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
[2019-02-14T08:59:01,085][INFO ][o.e.c.m.MetaDataIndexTemplateService] [node-0] removing template [.logstash-management]
[2019-02-14T08:59:01,085][DEBUG][o.e.a.b.TransportShardBulkAction] [node-0] [sensor_rollup][0] failed to execute bulk item (index) index {[sensor_rollup][_doc][sensor$ToQ8SQy-5KVQG7BBOaHaCw], source[{"node.terms.value":"c","voltage.avg.value":4.0,"timestamp.date_histogram.time_zone":"UTC","timestamp.date_histogram.timestamp":1516294800000,"temperature.sum.value":202.0,"temperature.max.value":202.0,"_rollup.version":2,"voltage.avg._count":1.0,"node.terms._count":1,"timestamp.date_histogram.interval":"1h","timestamp.date_histogram._count":1,"temperature.min.value":202.0,"_rollup.id":"sensor"}]}
org.elasticsearch.index.IndexNotFoundException: no such index [sensor_rollup] 
    at org.elasticsearch.cluster.metadata.MetaData.getIndexSafe(MetaData.java:662) ~[elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at org.elasticsearch.cluster.metadata.MetaDataMappingService$PutMappingExecutor.execute(MetaDataMappingService.java:230) ~[elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at org.elasticsearch.cluster.service.MasterService.executeTasks(MasterService.java:687) ~[elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at org.elasticsearch.cluster.service.MasterService.calculateTaskOutputs(MasterService.java:310) ~[elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at org.elasticsearch.cluster.service.MasterService.runTasks(MasterService.java:210) ~[elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at org.elasticsearch.cluster.service.MasterService$Batcher.run(MasterService.java:142) ~[elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at org.elasticsearch.cluster.service.TaskBatcher.runIfNotProcessed(TaskBatcher.java:150) ~[elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at org.elasticsearch.cluster.service.TaskBatcher$BatchedTask.run(TaskBatcher.java:188) ~[elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:681) ~[elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.runAndClean(PrioritizedEsThreadPoolExecutor.java:252) ~[elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.run(PrioritizedEsThreadPoolExecutor.java:215) ~[elasticsearch-7.1.0-SNAPSHOT.jar:7.1.0-SNAPSHOT]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
[2019-02-14T08:59:01,101][INFO ][o.e.c.m.TemplateUpgradeService] [node-0] Starting template upgrade to version 7.1.0, 1 templates will be updated and 0 will be removed

The full node log from this test run is docs_integTestCluster.zip

[jkakavas]

This looks like it has been resolved by #38930 as all the latest failures are unrelated. I suggest we leave this open until the latest errors are triaged so that we can be sure that the previous problem is resolved instead of just masked

[polyfractal]

Works for me. Note that I didnt get a chance to backport these last week (looks like Tal put up some backports yesterday while I was out), so non-master branches may keep failing with this error until the backports merge.

[talevy]

backports were merged. We should be able to give it another 24HRs before making a decision since the failures were common enough. If they are persisting, they should show up soon

[markharwood]

Build-stats link for the failures with "waiting for rollup job"

[polyfractal]

Thanks for that @markharwood ... looks like the last one was on the 20th (the day the backports merged). Fingers crossed we dont see this pop up again :) 🤞

I'll check on the stats after the weekend and see about closing the issue

[polyfractal]

Just failed on 6.6, but looks like that branch didn't get a backport. I'll backport or, if there was a reason that branch was skiped, mute.

[polyfractal]

Backported. Gonna close as the other branches have been silent so far (:crossed_fingers: ), but will keep an eye on it. :)