Frequent failures for data frame tests in CI

[mark-vieira]

I've noticed an increase in the number of failures around the data frame integration tests. These don't reliable reproduce as it seems they are mostly timeout related. Here you can see this increase in failures began around last week.

https://gradle-enterprise.elastic.co/scans/failures?failures.failureClassification=verification&failures.failureMessage=Execution%20failed%20for%20task%20%27:x-pack:plugin:data-frame:qa:*:integTestRunner%27.%0A%3E%20There%20were%20failing%20tests.%20See%20the%20report%20at:%20*&list.offset=0&list.size=50&list.sortColumn=startTime&list.sortOrder=desc&search.buildToolType=gradle&search.buildToolType=maven&search.startTimeMin=0&trends.section=overview&trends.timeResolution=day&viewer.tzOffset=-420

@atorok can you think of anything CI or build related that could impact this?

[elasticmachine]

Pinging @elastic/ml-core

[benwtrent]

I will be looking into this from the ML side of things.

Here are some interesting logs from that latest failure. The test that is failing is one that tests how we handle failed states in transforms (ironic...).

[2019-08-14T17:11:13,081][INFO ][o.e.x.d.t.DataFrameTransformTask] [integTest-0] Updating state for data frame transform [test-force-stop-failed-transform] to [{"task_state":"started","indexer_state":"stopped","checkpoint":0}]
...
[2019-08-14T17:11:14,183][WARN ][o.e.x.d.t.DataFrameTransformTask] [integTest-0] Data frame transform [test-force-stop-failed-transform] encountered an exception: 
org.elasticsearch.xpack.dataframe.transforms.DataFrameTransformTask$BulkIndexingException: Bulk index experienced failures. See the logs of the node running the transform for details.
...
[2019-08-14T17:11:14,249][ERROR][o.e.x.d.t.DataFrameTransformTask] [integTest-0] Data frame transform [test-force-stop-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-14T17:11:14,642][INFO ][o.e.x.d.t.DataFrameTransformTask] [integTest-0] Data frame transform [test-force-stop-failed-transform] has stopped
[2019-08-14T17:11:14,818][INFO ][o.e.x.d.t.DataFrameTransformTask] [integTest-0] Data frame transform [test-force-stop-failed-transform] has stopped
[2019-08-14T17:11:14,822][WARN ][o.e.x.d.t.DataFrameTransformTask] [integTest-0] Data frame transform [test-force-stop-failed-transform] encountered an exception: 
org.elasticsearch.xpack.dataframe.transforms.DataFrameTransformTask$BulkIndexingException: Bulk index experienced failures. See the logs of the node running the transform for details.
...
[2019-08-14T17:11:14,855][ERROR][o.e.x.d.t.DataFrameTransformTask] [integTest-0] Data frame transform [test-force-stop-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-14T17:11:14,913][WARN ][o.e.p.PersistentTasksClusterService] [integTest-0] trying to update state on non-existing task test-force-stop-failed-transform
[2019-08-14T17:11:14,959][ERROR][o.e.x.d.t.DataFrameTransformTask] [integTest-0] Failed to update state for data frame transform [test-force-stop-failed-transform]
...
[2019-08-14T17:11:14,961][ERROR][o.e.x.d.t.DataFrameTransformTask] [integTest-0] Failed to set task state as failed to cluster state
org.elasticsearch.ResourceNotFoundException: the task with id test-force-stop-failed-transform and allocation id 2 doesn't exist

We definitely have some sort of race condition, you can see by how many times we get the same log message. Many of those "failure" log messages referencing the task should realistically only be logged once.

The has stopped logs are very interesting. We spin wait for the task to be set to failed within the test before attempting to stop them by force. The time between creating the transform and it reaching a failed state is ~2 seconds. Our timeout on the spinwait is 30 seconds...something is racing here.

What it seems like, is that something came in and called stop on the data frame transform while it was failing. So, the task got canceled and removed from cluster state before it could be moved over to a failed state. In real practice, this should be OK. For CI, this is an issue :/. I am looking into what could have called _stop against it.

FWIW: there is a PR right now that should help with some mysterious CI failures that I am going to merge (as soon as CI passes).

EDIT: From what I can tell, this cascaded failure is occurring because the indexer is getting triggered twice. It did not finish the failure path on the first trigger before the second trigger fired. This will cause some strange internal state interactions for user as we assume that only one trigger is firing at a time.

[benwtrent]

One PR merged to help with data frame instability: #45511

[benwtrent]

Another PR to address the failure state tests #45627

[mark-vieira]

I was just about to report this one: https://gradle-enterprise.elastic.co/s/cnsrqikafhkm4/tests/failed

I'll update my branch and try again.

[benwtrent]

@mark-vieira that build had my commit. I am re-muting that test. I see the cause, it is different than the ones I fixed.