CI: RunDataFrameAnalyticsIT testStopOutlierDetectionWithEnoughDocumentsToScroll fails with : all shards failed

[alpar-t]

Example build failure

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob+fast+part2/40/

Reproduction line

does not reproduce locally

 ./gradlew :x-pack:plugin:ml:qa:native-multi-node-tests:integTestRunner --tests "org.elasticsearch.xpack.ml.integration.RunDataFrameAnalyticsIT.testStopOutlierDetectionWithEnoughDocumentsToScroll" -Dtests.seed=B75F80A8A58CBE98 -Dtests.security.manager=true -Dtests.locale=ca-AD -Dtests.timezone=America/Sitka -Dcompiler.java=12 -Druntime.java=11

Example relevant log:

Failed to execute phase [query], all shards failed
	at __randomizedtesting.SeedInfo.seed([B75F80A8A58CBE98:27AE758C22D139A2]:0)
	at org.elasticsearch.action.search.AbstractSearchAsyncAction.onPhaseFailure(AbstractSearchAsyncAction.java:305)
	at org.elasticsearch.action.search.AbstractSearchAsyncAction.executeNextPhase(AbstractSearchAsyncAction.java:139)
	at org.elasticsearch.action.search.AbstractSearchAsyncAction.onPhaseDone(AbstractSearchAsyncAction.java:264)
	at org.elasticsearch.action.search.InitialSearchPhase.onShardFailure(InitialSearchPhase.java:105)
	at org.elasticsearch.action.search.InitialSearchPhase$2.onFailure(InitialSearchPhase.java:273)
	at org.elasticsearch.action.search.SearchExecutionStatsCollector.onFailure(SearchExecutionStatsCollector.java:73)
	at org.elasticsearch.action.ActionListenerResponseHandler.handleException(ActionListenerResponseHandler.java:59)
	at org.elasticsearch.action.search.SearchTransportService$ConnectionCountingHandler.handleException(SearchTransportService.java:441)
	at org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleException(TransportService.java:1101)
	at org.elasticsearch.transport.InboundHandler.lambda$handleException$2(InboundHandler.java:246)
	at org.elasticsearch.common.util.concurrent.EsExecutors$DirectExecutorService.execute(EsExecutors.java:193)
	at org.elasticsearch.transport.InboundHandler.handleException(InboundHandler.java:244)
	at org.elasticsearch.transport.InboundHandler.handlerResponseError(InboundHandler.java:236)
	at org.elasticsearch.transport.InboundHandler.messageReceived(InboundHandler.java:139)
	at org.elasticsearch.transport.InboundHandler.inboundMessage(InboundHandler.java:105)
	at org.elasticsearch.transport.TcpTransport.inboundMessage(TcpTransport.java:660)
	at org.elasticsearch.transport.netty4.Netty4MessageChannelHandler.channelRead(Netty4MessageChannelHandler.java:62)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:323)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:297)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
	at io.netty.handler.logging.LoggingHandler.channelRead(LoggingHandler.java:241)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
	at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1478)
	at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1227)
	at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1274)
	at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:502)
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:441)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:278)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1408)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:930)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:682)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:582)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:536)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:906)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at java.base/java.lang.Thread.run(Thread.java:834)

Frequency

12 times in the past 6 days across branches

[elasticmachine]

Pinging @elastic/ml-core

[alpar-t]

Muted on master, 7.x and 7.3

[dimitris-athanasiou]

This looks quite strange. I cannot understand where this stacktrace comes from, I can't see it neither in the node logs nor the console output. The stacktrace itself doesn't help understand where this search came from or what it was doing. I have run the test locally with many iterations and I can't reproduce. I think we should enable low level logging and re-enable the test to get more to go with.

[mayya-sharipova]

More recent failure: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob+fast+part2/49/console

Doesn't reproduce for me as well.

Indeed not much info in the console log .

[davidkyle]

This is the relevant part of the log

[2019-07-04T14:14:35,405][INFO ][o.e.x.m.a.TransportStartDataFrameAnalyticsAction] [integTest-2] [test_stop_outlier_detection_with_enough_docs_to_scroll] Starting data frame analytics
[2019-07-04T14:14:35,460][INFO ][o.e.x.m.d.DataFrameAnalyticsManager] [integTest-2] [test_stop_outlier_detection_with_enough_docs_to_scroll] Creating destination index [test-stop-outlier-detection-with-enough-docs-to-scroll-results]
[2019-07-04T14:14:35,480][INFO ][o.e.x.m.a.TransportStopDataFrameAnalyticsAction] [integTest-2] [test_stop_outlier_detection_with_enough_docs_to_scroll] Stopping task with force [false]
[2019-07-04T14:14:36,152][WARN ][o.e.a.a.i.r.TransportShardRefreshAction] [integTest-2] unexpected error during the primary phase for action [indices:admin/refresh[s]], request [BasicReplicationRequest{[test-stop-outlier-detection-with-enough-docs-to-scroll-results][0]}]
org.elasticsearch.index.IndexNotFoundException: no such index [test-stop-outlier-detection-with-enough-docs-to-scroll-results]
at org.elasticsearch.cluster.metadata.IndexNameExpressionResolver.concreteIndices(IndexNameExpressionResolver.java:194) ~[elasticsearch-7.4.0-SNAPSHOT.jar:7.4.0-SNAPSHOT]
at org.elasticsearch.cluster.metadata.IndexNameExpressionResolver.concreteIndices(IndexNameExpressionResolver.java:120) ~[elasticsearch-7.4.0-SNAPSHOT.jar:7.4.0-SNAPSHOT]
at org.elasticsearch.cluster.metadata.IndexNameExpressionResolver.concreteSingleIndex(IndexNameExpressionResolver.java:282) ~[elasticsearch-7.4.0-SNAPSHOT.jar:7.4.0-SNAPSHOT]
at org.elasticsearch.action.support.replication.TransportReplicationAction.concreteIndex(TransportReplicationAction.java:235) ~[elasticsearch-7.4.0-SNAPSHOT.jar:7.4.0-SNAPSHOT]
at org.elasticsearch.action.support.replication.TransportReplicationAction.access$1600(TransportReplicationAction.java:97) ~[elasticsearch-7.4.0-SNAPSHOT.jar:7.4.0-SNAPSHOT]
at org.elasticsearch.action.support.replication.TransportReplicationAction$ReroutePhase.doRun(TransportReplicationAction.java:656) [elasticsearch-7.4.0-SNAPSHOT.jar:7.4.0-SNAPSHOT]
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elasticsearch-7.4.0-SNAPSHOT.jar:7.4.0-SNAPSHOT]
at org.elasticsearch.action.support.replication.TransportReplicationAction$ReroutePhase$2.onNewClusterState(TransportReplicationAction.java:802) [elasticsearch-7.4.0-SNAPSHOT.jar:7.4.0-SNAPSHOT]
at org.elasticsearch.cluster.ClusterStateObserver$ContextPreservingListener.onNewClusterState(ClusterStateObserver.java:311) [elasticsearch-7.4.0-SNAPSHOT.jar:7.4.0-SNAPSHOT]
at org.elasticsearch.cluster.ClusterStateObserver$ObserverClusterStateListener.postAdded(ClusterStateObserver.java:220) [elasticsearch-7.4.0-SNAPSHOT.jar:7.4.0-SNAPSHOT]
at org.elasticsearch.cluster.service.ClusterApplierService$1.run(ClusterApplierService.java:288) [elasticsearch-7.4.0-SNAPSHOT.jar:7.4.0-SNAPSHOT]
at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:688) [elasticsearch-7.4.0-SNAPSHOT.jar:7.4.0-SNAPSHOT]
at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.runAndClean(PrioritizedEsThreadPoolExecutor.java:252) [elasticsearch-7.4.0-SNAPSHOT.jar:7.4.0-SNAPSHOT]
at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.run(PrioritizedEsThreadPoolExecutor.java:215) [elasticsearch-7.4.0-SNAPSHOT.jar:7.4.0-SNAPSHOT]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_212]
[2019-07-04T14:14:36,157][WARN ][o.e.p.PersistentTasksNodeService] [integTest-2] attempt to complete task [xpack/ml/data_frame/analytics[c]] with id [data_frame_analytics-test_stop_outlier_detection_with_enough_docs_to_scroll] in the [COMPLETED] state
[2019-07-04T14:14:38,490][INFO ][o.e.x.m.a.TransportStartDataFrameAnalyticsAction] [integTest-2] [test_outlier_detection_with_enough_docs_to_scroll] Starting data frame analytics
[2019-07-04T14:14:38,546][INFO ][o.e.x.m.d.DataFrameAnalyticsManager] [integTest-2] [test_outlier_detection_with_enough_docs_to_scroll] Creating destination index [test-outlier-detection-with-enough-docs-to-scroll-results]
[2019-07-04T14:14:39,363][INFO ][o.e.x.m.d.p.AnalyticsProcessManager] [integTest-2] [test_outlier_detection_with_enough_docs_to_scroll] Waiting for result processor to complete
[2019-07-04T14:14:39,728][INFO ][o.e.x.m.d.p.AnalyticsProcessManager] [integTest-2] [test_outlier_detection_with_enough_docs_to_scroll] Result processor has completed
[2019-07-04T14:14:39,728][INFO ][o.e.x.m.d.p.AnalyticsProcessManager] [integTest-2] [test_outlier_detection_with_enough_docs_to_scroll] Closing process
[2019-07-04T14:14:39,729][INFO ][o.e.x.m.d.p.AnalyticsProcessManager] [integTest-2] [test_outlier_detection_with_enough_docs_to_scroll] Closed process
[2019-07-04T14:14:39,729][INFO ][o.e.x.m.d.p.AnalyticsProcessManager] [integTest-2] [test_outlier_detection_with_enough_docs_to_scroll] Marking task completed

Could there be a race between creating the destination index and stopping the Data frame analysis or is it somehow deleted before the BasicReplicationRequest