[CI] MlDistributedFailureIT.testCloseUnassignedFailedJobAndStopUnassignedStoppingDatafeed failed with NPE

[mark-vieira]

This one didn't reproduce locally for me but NPEs in tests seem suspect. This is the first instance of such a failure and it happened in a 7.6 build.

java.lang.NullPointerException: (No message provided)Close stacktrace
at org.elasticsearch.xpack.ml.integration.MlDistributedFailureIT.testCloseUnassignedFailedJobAndStopUnassignedStoppingDatafeed(MlDistributedFailureIT.java:248)
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)

[elasticmachine]

Pinging @elastic/ml-core (:ml)

[davidkyle]

Thanks for raising this @mark-vieira the build link is missing I've added those details here:

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+7.6+multijob-unix-compatibility/os=sles-15&&immutable/73/console
https://gradle-enterprise.elastic.co/s/7u76m7hino3a6
and log

./gradlew ':x-pack:plugin:ml:internalClusterTest' --tests "org.elasticsearch.xpack.ml.integration.MlDistributedFailureIT.testCloseUnassignedFailedJobAndStopUnassignedStoppingDatafeed" \
  -Dtests.seed=2D1FFA30C2A5A434 \
  -Dtests.security.manager=true \
  -Dtests.locale=he-IL \
  -Dtests.timezone=Pacific/Tongatapu \
  -Dcompiler.java=13

[davidkyle]

The NPE is in this code

PersistentTasksCustomMetaData.PersistentTask<?> task = MlTasks.getDatafeedTask(datafeedId, tasks);
UpdatePersistentTaskStatusAction.Request updatePersistentTaskStatusRequest =
            new UpdatePersistentTaskStatusAction.Request(task.getId(), task.getAllocationId(), DatafeedState.STOPPING);       <-- NPE here

task must be null which means the datafeed has no task looking in the log we see the reason why.

[2020-02-21T12:00:01,140][WARN ][o.e.p.AllocatedPersistentTask] [node_tc4] task datafeed-test-stop-unassigned-datafeed-for-failed-job-datafeed failed with an exception
org.elasticsearch.xpack.ml.datafeed.DatafeedJob$AnalysisProblemException: ElasticsearchStatusException[Cannot flush because job [test-stop-unassigned-datafeed-for-failed-job] does not have a corresponding autodetect process]
	at org.elasticsearch.xpack.ml.datafeed.DatafeedJob.flushJob(DatafeedJob.java:470) ~[main/:?]
	at org.elasticsearch.xpack.ml.datafeed.DatafeedJob.run(DatafeedJob.java:411) ~[main/:?]
	at org.elasticsearch.xpack.ml.datafeed.DatafeedJob.runRealtime(DatafeedJob.java:190) ~[main/:?]
	at org.elasticsearch.xpack.ml.datafeed.DatafeedManager$Holder.executeRealTime(DatafeedManager.java:421) [main/:?]
	at org.elasticsearch.xpack.ml.datafeed.DatafeedManager$Holder.access$600(DatafeedManager.java:304) [main/:?]
	at org.elasticsearch.xpack.ml.datafeed.DatafeedManager$3.doRun(DatafeedManager.java:234) [main/:?]
...

Flush is a TransportJobTaskAction the request is directed to the node where the job is running but there is a tiny window where the job dies after the Transport Action has started but before flush has executed. The data feed correctly considers this a fatal error as there is no point continuing once the job has failed so the datafeed fails itself. This is not a problem as the errors are handled properly but the test does not expect this situation.

[droberts195]

This is a symptom of the way the test tries to simulate an incredibly unlikely situation by directly messing with task states as there is no easy way to create it (i.e. an unassigned stopping datafeed whose associated job is also unassigned and in the failed state).

The problem here would not happen in production code. It is trying to set up the rare situation to test that the production code copes with that, but fails during the setup process.

Since the test fails so rarely in this way and the alternatives for reliably creating an unassigned stopping datafeed whose associated job is also unassigned and in the failed state are basically non-existent I wonder if the best solution is just to catch the NPE and redo the entire test?

[mark-vieira]

@davidkyle We got another failure here. It seems assumeFalse isn't resulting in the behavior we are looking for.

https://gradle-enterprise.elastic.co/s/w7kppcm2ut4ay/tests/lf2lfu4ufazso-de42uixmysp7e?open-stacktraces=WzBd

[droberts195]

The fatal problem occurs in the cleanup code:

    java.lang.RuntimeException: Had to resort to force-closing job, something went wrong?

We need to get rid of the failed job before assumeing, because the standard post test cleanup treats leftover failed jobs as fatal errors.

I will open a PR.