[CI] RegressionIT.testStopAndRestart failure

[astefan]

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

Repro line: gradlew ':x-pack:plugin:ml:qa:native-multi-node-tests:javaRestTest' --tests "org.elasticsearch.xpack.ml.integration.RegressionIT.testStopAndRestart" -Dtests.seed=CB002B982AFC9FE0 -Dtests.security.manager=true -Dtests.locale=bg-BG -Dtests.timezone=America/Montreal -Druntime.java=11

Reproduces locally?: No

Applicable branches: master, 7.x

Failure excerpt:

org.elasticsearch.xpack.ml.integration.RegressionIT > testStopAndRestart FAILED
    java.lang.AssertionError: Stats were: {"id":"regression_stop_and_restart","state":"started","progress":[{"phase":"reindexing","progress_percent":100},{"phase":"loading_data","progress_percent":100},{"phase":"feature_selection","progress_percent":0},{"phase":"coarse_parameter_search","progress_percent":0},{"phase":"fine_tuning_parameters","progress_percent":0},{"phase":"final_training","progress_percent":0},{"phase":"writing_results","progress_percent":0},{"phase":"inference","progress_percent":0}],"data_counts":{"training_docs_count":350,"test_docs_count":0,"skipped_docs_count":0},"memory_usage":{"timestamp":1610702364954,"peak_usage_bytes":12916,"status":"ok"},"node":{"id":"ZBQn4V3tQ7unCXAoAcsMzw","name":"javaRestTest-0","ephemeral_id":"Ocv37ZNXQBWCrMdnfHVdLw","transport_address":"127.0.0.1:59082","attributes":{"testattr":"test","ml.machine_memory":"103077928960","ml.max_open_jobs":"20","xpack.installed":"true","ml.max_jvm_size":"518979584","transform.node":"true"}},"assignment_explanation":""}
    Expected: <stopped>
         but: was <started>
        at __randomizedtesting.SeedInfo.seed([CB002B982AFC9FE0:BC48A9663E169940]:0)
        at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:18)
        at org.junit.Assert.assertThat(Assert.java:956)
        at org.elasticsearch.xpack.ml.integration.MlNativeDataFrameAnalyticsIntegTestCase.assertIsStopped(MlNativeDataFrameAnalyticsIntegTestCase.java:210)
        at org.elasticsearch.xpack.ml.integration.MlNativeDataFrameAnalyticsIntegTestCase.lambda$waitUntilAnalyticsIsStopped$0(MlNativeDataFrameAnalyticsIntegTestCase.java:156)
        at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:955)
        at org.elasticsearch.xpack.ml.integration.MlNativeDataFrameAnalyticsIntegTestCase.waitUntilAnalyticsIsStopped(MlNativeDataFrameAnalyticsIntegTestCase.java:156)
        at org.elasticsearch.xpack.ml.integration.MlNativeDataFrameAnalyticsIntegTestCase.waitUntilAnalyticsIsStopped(MlNativeDataFrameAnalyticsIntegTestCase.java:152)
        at org.elasticsearch.xpack.ml.integration.RegressionIT.testStopAndRestart(RegressionIT.java:326)
REPRODUCE WITH: gradlew ':x-pack:plugin:ml:qa:native-multi-node-tests:javaRestTest' --tests "org.elasticsearch.xpack.ml.integration.RegressionIT.testStopAndRestart" -Dtests.seed=CB002B982AFC9FE0 -Dtests.security.manager=true -Dtests.locale=bg-BG -Dtests.timezone=America/Montreal -Druntime.java=11

[elasticmachine]

Pinging @elastic/ml-core (:ml)

[dimitris-athanasiou]

Looking into the logs, these are the relevant bits:

[2021-01-15T09:19:22,664][INFO ][o.e.x.m.a.TransportStartDataFrameAnalyticsAction] [javaRestTest-0] [regression_stop_and_restart] Starting data frame analytics from state [stopped]
[2021-01-15T09:19:22,731][INFO ][o.e.x.c.m.u.MlIndexAndAlias] [javaRestTest-0] About to create first concrete index [.ml-state-000001] with alias [.ml-state-write]
[2021-01-15T09:19:22,913][INFO ][o.e.x.c.m.u.MlIndexAndAlias] [javaRestTest-0] About to create first concrete index [.ml-stats-000001] with alias [.ml-stats-write]
[2021-01-15T09:19:23,103][INFO ][o.e.x.m.d.s.ReindexingStep] [javaRestTest-0] [regression_stop_and_restart] Creating destination index [regression_stop_and_restart_source_index_results]
[2021-01-15T09:19:23,308][INFO ][o.e.x.m.d.s.ReindexingStep] [javaRestTest-0] [regression_stop_and_restart] Started reindexing
[2021-01-15T09:19:23,719][INFO ][o.e.x.m.d.p.AnalyticsProcessManager] [javaRestTest-0] [regression_stop_and_restart] Started loading data
[2021-01-15T09:19:23,869][INFO ][o.e.x.m.a.TransportStopDataFrameAnalyticsAction] [javaRestTest-0] [regression_stop_and_restart] Stopping task with force [false]
[2021-01-15T09:19:23,870][INFO ][o.e.x.m.d.p.AnalyticsProcessManager] [javaRestTest-0] [regression_stop_and_restart] Closing process
[2021-01-15T09:19:23,885][INFO ][o.e.x.m.d.p.AnalyticsProcessManager] [javaRestTest-0] [regression_stop_and_restart] Closed process
[2021-01-15T09:19:23,886][INFO ][o.e.x.m.d.DataFrameAnalyticsManager] [javaRestTest-0] [regression_stop_and_restart] Marking task completed
[2021-01-15T09:19:24,304][INFO ][o.e.x.m.a.TransportStartDataFrameAnalyticsAction] [javaRestTest-0] [regression_stop_and_restart] Starting data frame analytics from state [stopped]
[2021-01-15T09:19:24,850][INFO ][o.e.x.m.d.p.AnalyticsProcessManager] [javaRestTest-0] [regression_stop_and_restart] Started loading data
[2021-01-15T09:20:30,042][INFO ][o.e.x.m.a.TransportStopDataFrameAnalyticsAction] [javaRestTest-0] [regression_stop_and_restart] Stopping task with force [false]
[2021-01-15T09:20:30,043][INFO ][o.e.x.m.d.p.AnalyticsProcessManager] [javaRestTest-0] [regression_stop_and_restart] Closing process
[2021-01-15T09:20:30,044][INFO ][o.e.x.m.d.p.AnalyticsProcessManager] [javaRestTest-0] [regression_stop_and_restart] Closed process
[2021-01-15T09:20:30,045][INFO ][o.e.x.m.d.DataFrameAnalyticsManager] [javaRestTest-0] [regression_stop_and_restart] Marking task completed

Nothing seems wrong except it took over a minute just to finish loading data after we restarted the job. This is insanely long for what the job's supposed to do so I can only imagine the CI worker happened to be incredibly busy.

In the test we expect the job to finish within one minute, so in this case that assertBusy failed resulting in the assertion error seen in the issue.

I'll leave the issue open for now to see if it fails again or was just a really bad moment for our CI worker.

[hendrikmuhs]

new failure: https://gradle-enterprise.elastic.co/s/gz76vkhfzexoe

[martijnvg]

Two more instances on master:

• https://gradle-enterprise.elastic.co/s/vbonfw4c6swwk
• https://gradle-enterprise.elastic.co/s/ytxl4l42p2feo

[dimitris-athanasiou]

OK, those look slightly different. I'm going to add some logging to figure this out.

[martijnvg]

I'm seeing more of theses failures in the past and today.

Also it looks like ClassificationIT#testStopAndRestart fails for the same reason. Are these failures related to this failure?

Maybe we should mute these tests?

[dimitris-athanasiou]

Yes, they're related. Please mute for now.