testForceStartFailedTransform fails with STARTED expected FAILED

[benwtrent]

Failure: https://gradle-enterprise.elastic.co/s/cnsrqikafhkm4/

Looking at the logs, it appears as if a second trigger fired quickly after the first one started and BEFORE it had the chance to transition the indexer state? This should not really be possible, but the two calls may be on the same thread???

Investigating.

[2019-08-16T15:23:02,003][TRACE][o.e.x.d.t.p.SchemaUtil   ] [integTest-0] Extracted type for [reviewer] : [long] from index [failure_pivot_reviews]
[2019-08-16T15:23:02,097][TRACE][o.e.x.d.t.DataFrameTransformPersistentTasksExecutor] [integTest-0] [test-force-start-failed-transform] No stats found(new transform), starting the task
[2019-08-16T15:23:02,128][DEBUG][o.e.x.d.t.DataFrameTransformTask] [integTest-0] [test-force-start-failed-transform] start called with force [false] and state [{"task_state":"stopped","indexer_state":"stopped","checkpoint":0}]
[2019-08-16T15:23:02,129][INFO ][o.e.x.d.t.DataFrameTransformTask] [integTest-0] Updating state for data frame transform [test-force-start-failed-transform] to [{"task_state":"started","indexer_state":"stopped","checkpoint":0}]
[2019-08-16T15:23:02,214][DEBUG][o.e.x.d.t.DataFrameTransformTask] [integTest-0] Successfully updated state for data frame transform [test-force-start-failed-transform] to [{"task_state":"started","indexer_state":"stopped","checkpoint":0}]
[2019-08-16T15:23:02,262][DEBUG][o.e.x.d.t.DataFrameTransformTask] [integTest-0] Data frame indexer [data_frame/transforms/schedule_test-force-start-failed-transform] schedule has triggered, state: [STARTED]
[2019-08-16T15:23:02,263][DEBUG][o.e.x.d.t.DataFrameTransformTask] [integTest-0] Trigger initial run
[2019-08-16T15:23:02,281][INFO ][o.e.x.d.t.DataFrameTransformPersistentTasksExecutor] [integTest-0] Successfully completed and scheduled task in node operation
[2019-08-16T15:23:02,323][DEBUG][o.e.x.d.t.DataFrameTransformTask] [integTest-0] [test-force-start-failed-transform] successfully refreshed data frame transform config from index.
...
[2019-08-16T15:23:02,926][DEBUG][o.e.x.d.t.DataFrameTransformTask] [integTest-0] Updating persistent state of transform [test-force-start-failed-transform] to [{"task_state":"started","indexer_state":"started","checkpoint":0,"progress":{"docs_remaining":0,"total_docs":10,"percent_complete":100.0,"docs_indexed":7,"docs_processed":10}}]
[2019-08-16T15:23:03,267][DEBUG][o.e.x.d.t.DataFrameTransformTask] [integTest-0] Data frame indexer [data_frame/transforms/schedule_test-force-start-failed-transform] schedule has triggered, state: [STARTED]
[2019-08-16T15:23:03,271][DEBUG][o.e.x.d.t.DataFrameTransformTask] [integTest-0] Trigger initial run
[2019-08-16T15:23:03,166][WARN ][o.e.x.d.t.DataFrameTransformTask] [integTest-0] Data frame transform [test-force-start-failed-transform] encountered an exception: 
...
[2019-08-16T15:23:03,319][ERROR][o.e.x.d.t.DataFrameTransformTask] [integTest-0] Data frame transform [test-force-start-failed-transform]: task encountered more than 0 failures; latest failure: Bulk index experienced failures. See the logs of the node running the transform for details.
[2019-08-16T15:26:33,852][DEBUG][o.e.x.d.a.TransportStopDataFrameTransformAction] [integTest-0] failed to execute on node [M_XX4Nr4Tc-fh-NbzFbOqQ]

integTest.log

[elasticmachine]

Pinging @elastic/ml-core

[benwtrent]

The previous PR meant to fix these problems put many checks in place to validate that we can set the state to failed without things breaking.

#45627

However, this "window of opportunity" has been exploited twice by CI and trigger seems to be making it past state checks. Need to see where this is occurring. We may have to add a flag to prevent triggering as we have such complicated onFinish and onFailure

[benwtrent]

This issue is occurring because doSaveState is called with the indexer state being transitioned to STARTED before onFailure. If onFailure is called before the indexer is changed from INDEXING to STARTED we will be able to synchronously change the task state to FAILED.