[CI] ML job snapshot upgrade IT can leave task behind

[hendrikmuhs]

The snapshot upgrade API introduced in #64665 can leave tasks behind that cause unrelated tests to fail during teardown. Note: The same issue can happen in different flavors, with different (but similar) stack traces, different testcases. The root cause is always a dangling persistent task.

Build scan:https://gradle-enterprise.elastic.co/s/w2rrhghfdrz2g

Repro line: ./gradlew ':client:rest-high-level:integTest' --tests "org.elasticsearch.client.TransformIT.testGetMissingTransform" -Dtests.seed=5A311E3B23B621C1 -Dtests.security.manager=true -Dtests.locale=hi-IN -Dtests.timezone=Cuba -Druntime.java=8

Reproduces locally?: no

Applicable branches: 7.x, master

Failure history:

Failure excerpt:

org.elasticsearch.client.TransformIT > testGetAllAndPageTransforms FAILED
12:26:30     java.lang.AssertionError: 1 active tasks found:
12:26:30     xpack/ml/job/snapshot/upgrade[c] UMEUON07QrON2VzuzOvTzw:18696 cluster:31                   persistent 1606129934335 11:12:14 14.2m       127.0.0.1 integTest-0 job-snapshot-upgrade-test-upgrade-job-model-snapshot-1541587919
12:26:30      expected:<0> but was:<1>
12:26:30         at __randomizedtesting.SeedInfo.seed([5A311E3B23B621C1:3633578F9FE53698]:0)
12:26:30         at org.junit.Assert.fail(Assert.java:88)
12:26:30         at org.junit.Assert.failNotEquals(Assert.java:834)
12:26:30         at org.junit.Assert.assertEquals(Assert.java:645)
12:26:30         at org.elasticsearch.test.rest.ESRestTestCase.lambda$waitForPendingTasks$3(ESRestTestCase.java:418)
12:26:30         at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:1011)
12:26:30         at org.elasticsearch.test.rest.ESRestTestCase.waitForPendingTasks(ESRestTestCase.java:394)
12:26:30         at org.elasticsearch.test.rest.ESRestTestCase.waitForPendingTasks(ESRestTestCase.java:381)
12:26:30         at org.elasticsearch.client.TransformIT.cleanUpTransformsAndLogAudits(TransformIT.java:166)

[elasticmachine]

Pinging @elastic/ml-core (:ml)

[hendrikmuhs]

Further down in the log it looks like it seems the upgrade itself failed:

ERROR][o.e.x.m.j.p.StateStreamer] [integTest-0] Expected 1 documents for model state for test-upgrade-job-model-snapshot snapshot 1541587919 but failed to find test-upgrade-job-model-snapshot_model_state_1541587919#1
12:27:09 » ERROR][o.e.x.m.p.l.CppLogMessageHandler] [integTest-0] [test-upgrade-job-model-snapshot-1541587919] [autodetect/144185] [CStateDecompressor.cc@112] Failed to find valid JSON
12:27:09 » ERROR][o.e.x.m.p.l.CppLogMessageHandler] [integTest-0] [test-upgrade-job-model-snapshot-1541587919] [autodetect/144185] [CAnomalyJob.cc@877] Expected persisted state but no state exists
12:27:09 » ERROR][o.e.x.m.p.l.CppLogMessageHandler] [integTest-0] [test-upgrade-job-model-snapshot-1541587919] [autodetect/144185] [CAnomalyJob.cc@825] Failed to restore detectors
12:27:09 » ERROR][o.e.x.m.p.AbstractNativeProcess] [integTest-0] [test-upgrade-job-model-snapshot] autodetect process stopped unexpectedly: Failed to find valid JSON
12:27:09 »  Expected persisted state but no state exists
12:27:09 »  Failed to restore detectors
12:27:09 »  Failed to restore state
12:27:09 »  ML anomaly detector job failed
12:27:09 »  
12:27:09 » WARN ][o.e.x.m.p.l.CppLogMessageHandler] [integTest-0] [controller/105366] [CDetachedProcessSpawner.cc@193] Child process with PID 144185 has exited with exit code 1
12:27:09 » ERROR][o.e.x.m.j.p.a.JobModelSnapshotUpgrader] [integTest-0] [test-upgrade-job-model-snapshot] Unexpected exception writing to process
12:27:09 »  org.elasticsearch.ElasticsearchException: [test-upgrade-job-model-snapshot] Unexpected death of autodetect: Failed to find valid JSON
12:27:09 »  Expected persisted state but no state exists
12:27:09 »  Failed to restore detectors
12:27:09 »  Failed to restore state
12:27:09 »  ML anomaly detector job failed
12:27:09 »  
12:27:09 »  	at org.elasticsearch.xpack.ml.job.process.autodetect.JobModelSnapshotUpgrader$Executor.checkProcessIsAlive(JobModelSnapshotUpgrader.java:279) ~[?:?]
12:27:09 »  	at org.elasticsearch.xpack.ml.job.process.autodetect.JobModelSnapshotUpgrader$Executor.access$500(JobModelSnapshotUpgrader.java:156) ~[?:?]
12:27:09 »  	at org.elasticsearch.xpack.ml.job.process.autodetect.JobModelSnapshotUpgrader$Executor$1.doRun(JobModelSnapshotUpgrader.java:269) ~[?:?]
12:27:09 »  	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:737) ~[elasticsearch-7.11.0-SNAPSHOT.jar:7.11.0-SNAPSHOT]
12:27:09 »  	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) ~[elasticsearch-7.11.0-SNAPSHOT.jar:7.11.0-SNAPSHOT]
12:27:09 »  	at org.elasticsearch.xpack.ml.job.process.autodetect.AutodetectWorkerExecutorService.start(AutodetectWorkerExecutorService.java:94) ~[?:?]
12:27:09 »  	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_241]
12:27:09 »  	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_241]
12:27:09 »  	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:678) [elasticsearch-7.11.0-SNAPSHOT.jar:7.11.0-SNAPSHOT]
12:27:09 »  	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_241]
12:27:09 »  	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_241]
12:27:09 »  	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_241]
12:27:09 » ERROR][o.e.x.m.j.p.a.w.JsonDataToProcessWriter] [integTest-0] Cannot parse timestamp '' as epoch value
12:27:09 »   ↑ repeated 3 times ↑

• is the dangling task a failed p-task?
• does the test miss a success check?

[benwtrent]

ML anomaly detector job failed

The task should have definitely ended. Especially since this was during the snapshot writing phase.