UpdateByQueryBasicTests#testMultipleSources fails in CI

[danielmitterdorfer]

test failure link: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+intake/850/console (full build log and test-cluster logs)

failure:

14:43:59 FAILURE 33.8s J2 | UpdateByQueryBasicTests.testMultipleSources <<< FAILURES!
14:43:59    > Throwable #1: java.lang.AssertionError: Delete Index failed - not acked
14:43:59    > Expected: <true>
14:43:59    >      but: was <false>
14:43:59    > 	at __randomizedtesting.SeedInfo.seed([9604E02021D6042D:11ADCC34CB9CAA79]:0)
14:43:59    > 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
14:43:59    > 	at org.elasticsearch.test.hamcrest.ElasticsearchAssertions.assertAcked(ElasticsearchAssertions.java:133)
14:43:59    > 	at org.elasticsearch.test.hamcrest.ElasticsearchAssertions.assertAcked(ElasticsearchAssertions.java:129)
14:43:59    > 	at org.elasticsearch.test.TestCluster.wipeIndices(TestCluster.java:142)
14:43:59    > 	at org.elasticsearch.test.TestCluster.wipe(TestCluster.java:79)
14:43:59    > 	at org.elasticsearch.test.ESIntegTestCase.afterInternal(ESIntegTestCase.java:578)
14:43:59    > 	at org.elasticsearch.test.ESIntegTestCase.cleanUpCluster(ESIntegTestCase.java:2068)
14:43:59    > 	at java.lang.Thread.run(Thread.java:748)

So the test fails to delete the index that is used. Above the failure we see in the log:

14:43:59   1> [2017-12-14T14:43:25,919][INFO ][o.e.i.r.UpdateByQueryBasicTests] [UpdateByQueryBasicTests#testMultipleSources]: cleaning up after test
14:43:59   1> [2017-12-14T14:43:25,996][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_sm0] [test1/GI9mScCtQfCfA1HbjOufZw] deleting index
14:43:59   1> [2017-12-14T14:43:25,996][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_sm0] [test0/_LQPQ_6NQ7-Niuo1voVfRQ] deleting index
14:43:59   1> [2017-12-14T14:43:55,996][WARN ][o.e.d.z.PublishClusterStateAction] [node_sm0] timed out waiting for all nodes to process published state [23] (timeout [30s], pending nodes: [{node_sd1}{JRpUXkrPT2K8ZVQyA9u6uw}{Qft0uWCtRmSiN19dSn_flg}{127.0.0.1}{127.0.0.1:9602}])

So I think the test may just be the victim and the root cause is in the test infrastructure. If you agree, please feel free to reassign.

reproduction line:

gradle :modules:reindex:test \
  -Dtests.seed=9604E02021D6042D \
  -Dtests.class=org.elasticsearch.index.reindex.UpdateByQueryBasicTests \
  -Dtests.method="testMultipleSources" \
  -Dtests.security.manager=true \
  -Dtests.locale=es-PR \
  -Dtests.timezone=Africa/Monrovia

reproduces locally: no

failure frequency: this test failed once in CI within the last year

[andyb-elastic]

Hmm, I wasn't able to reproduce this at the method, class, or project level. I also don't see anything in the build or test cluster logs that indicates a cause. @danielmitterdorfer do you have any advice for further ruling out a problem with the test

[danielmitterdorfer]

We do see the following in the log:

  1> [2017-12-14T14:43:25,996][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_sm0] [test1/GI9mScCtQfCfA1HbjOufZw] deleting index
  1> [2017-12-14T14:43:25,996][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_sm0] [test0/_LQPQ_6NQ7-Niuo1voVfRQ] deleting index
  1> [2017-12-14T14:43:55,996][WARN ][o.e.d.z.PublishClusterStateAction] [node_sm0] timed out waiting for all nodes to process published state [23] (timeout [30s], pending nodes: [{node_sd1}{JRpUXkrPT2K8ZVQyA9u6uw}{Qft0uWCtRmSiN19dSn_flg}{127.0.0.1}{127.0.0.1:9602}])
[...]
  1> [2017-12-14T14:43:57,573][WARN ][o.e.c.s.MasterService    ] [node_sm0] cluster state update task [delete-index [[test1/GI9mScCtQfCfA1HbjOufZw], [test0/_LQPQ_6NQ7-Niuo1voVfRQ]]] took [31.5s] above the warn threshold of 30s
  1> [2017-12-14T14:43:57,739][WARN ][o.e.c.s.ClusterApplierService] [node_sd1] cluster state applier task [apply cluster state (from master [master {node_sm0}{A0mc7ckXQp2nqeAoajchpA}{1zRMtijCQlKk0lIE2NiwKw}{127.0.0.1}{127.0.0.1:9601} committed version [23]])] took [31.6s] above the warn threshold of 30s

So it seems that for some reason these nodes were hanging but this is all I can see in the log. Maybe it makes sense to increase the log level to get more info in case this test fails again?

[andyb-elastic]

Gotcha, I'll increase the test log level since it can't hurt. Since this is the only time this test has failed I'm inclined to think it may be caused by something else

[nik9000]

This looks like the node hanging for an unreasonable amount of time. The failure isn't particularly reindex based either. And we haven't seen another thing like this since. I'm going to close this and we'll reopen if we see something similar.

[jtibshirani]

A recent failure popped up that may be related. The test timed out while attempting to process cluster events for 'put mapping'. I don't see general slowness or node hangs, but the logs are difficult to understand because lines from different outputs are interleaved.

Reproduction line:

./gradlew :modules:reindex:test --tests "org.elasticsearch.index.reindex.UpdateByQueryBasicTests.testMultipleSources" \
  -Dtests.seed=2CC9E93C207EC061 \
  -Dtests.security.manager=true \
  -Dtests.locale=ee-GH \
  -Dtests.timezone=US/Pacific-New \
  -Dcompiler.java=12 \
  -Druntime.java=11

Link to build logs: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-unix-compatibility/os=debian-9/320/console

Relevant excerpt:

 2> java.lang.AssertionError: 
    Expected: an empty iterable
  1> --------[test3][3], node[ijtePTJlRCOtyTK6Cmekyw], [P], s[STARTED], a[id=ZBh60YktReS7ukvj5RG8-g]
         but: [<ProcessClusterEventTimeoutException[failed to process cluster event (put-mapping) within 13s]>,<ProcessClusterEventTimeoutException[failed to process cluster event (put-mapping) within 13s]>,<ProcessClusterEventTimeoutException[failed to process cluster event (put-mapping) within 13s]>,<ProcessClusterEventTimeoutException[failed to process cluster event (put-mapping) within 13s]>]
        at __randomizedtesting.SeedInfo.seed([2CC9E93C207EC061:AB60C528CA346E35]:0)
        at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
  1> --------[test3][2], node[ijtePTJlRCOtyTK6Cmekyw], [R], s[STARTED], a[id=AofokK8sQv26mX0qWHqW-g]
  1> --------[test3][7], node[ijtePTJlRCOtyTK6Cmekyw], [P], s[STARTED], a[id=9rHRKFY3QsqIN5SIFwtymQ]
        at org.junit.Assert.assertThat(Assert.java:956)
        at org.junit.Assert.assertThat(Assert.java:923)
  1> --------[test3][8], node[ijtePTJlRCOtyTK6Cmekyw], [R], s[STARTED], a[id=os7XYhW1StKht1dCdlNHMg]
  1> --------[test3][5], node[ijtePTJlRCOtyTK6Cmekyw], [P], s[STARTED], a[id=u4X28Zq6RaedP9u9bRUO_Q]
  1> --------[test3][4], node[ijtePTJlRCOtyTK6Cmekyw], [R], s[STARTED], a[id=ZoCBY6WoTmi_zstDsmUoYQ]
        at org.elasticsearch.test.ESIntegTestCase.indexRandom(ESIntegTestCase.java:1521)