Failed to execute pipeline for a bulk using ingest node

ori.rubinfeld · March 19, 2017, 3:00pm

Hi,

I have a config of Filebeat sending data to elasticsearch.
Data can be Multiline events or Singleline Events.

After a short period, I notice the following Error in Elasticsearch Log File: Failed to execute pipeline for a bulk

And it gets stuck, not processing any more data, just continuing to output that specific error.

Cluster restart solves it.

Cluster is 5 nodes:
2: Master + Ingest
1: Master + Data
2: Data

Filebeat is configured to send data to both Ingest Nodes.

I did noticed that when stopping Filebeat from any source server, the problem starts.

Version is 5.0.0 for Filebeat and Elasticsearch.

I have same configuration running on two DC's successfully.
This is a Third DC on which the problem started to occur.

How can I find out what it is the real cause for it ? and Solve it.

Thanks,

Ori

spinscale · March 20, 2017, 9:17am

Hey,

does the logfile from Elasticsearch contain more information or even a stack trace? Can you add that one here? Thanks!

--Alex

ori.rubinfeld · March 26, 2017, 8:30am

Part 1:

[2017-03-26T08:14:31,071][ERROR][o.e.a.i.IngestActionFilter] [ldnelk06] failed to execute pipeline for a bulk request
org.elasticsearch.common.util.concurrent.EsRejectedExecutionException: rejected execution of org.elasticsearch.ingest.PipelineExecutionService$2@6077a08 on EsThreadPoolExecutor[bulk, queue capacity = 50, org.elasticsearch.common.util.concurrent.EsThreadPoolExecutor@7ea249c9[Running, pool size = 4, active threads = 4, queued tasks = 50, completed tasks = 4047]]
at org.elasticsearch.common.util.concurrent.EsAbortPolicy.rejectedExecution(EsAbortPolicy.java:50) ~[elasticsearch-5.0.0.jar:5.0.0]
at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:823) ~[?:1.8.0_102]
at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1369) ~[?:1.8.0_102]
at org.elasticsearch.common.util.concurrent.EsThreadPoolExecutor.doExecute(EsThreadPoolExecutor.java:95) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.common.util.concurrent.EsThreadPoolExecutor.execute(EsThreadPoolExecutor.java:90) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.ingest.PipelineExecutionService.executeBulkRequest(PipelineExecutionService.java:74) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.action.ingest.IngestActionFilter.processBulkIndexRequest(IngestActionFilter.java:109) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.action.ingest.IngestActionFilter.apply(IngestActionFilter.java:76) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.action.support.TransportAction$RequestFilterChain.proceed(TransportAction.java:180) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.action.support.TransportAction.execute(TransportAction.java:153) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.action.support.TransportAction.execute(TransportAction.java:87) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.client.node.NodeClient.executeLocally(NodeClient.java:75) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.client.node.NodeClient.doExecute(NodeClient.java:64) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.client.support.AbstractClient.execute(AbstractClient.java:403) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.client.support.AbstractClient.bulk(AbstractClient.java:480) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.rest.action.document.RestBulkAction.lambda$prepareRequest$0(RestBulkAction.java:100) ~[elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.rest.BaseRestHandler.handleRequest(BaseRestHandler.java:114) [elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.rest.RestController.executeHandler(RestController.java:243) [elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.rest.RestController.dispatchRequest(RestController.java:200) [elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.http.HttpServer.dispatchRequest(HttpServer.java:116) [elasticsearch-5.0.0.jar:5.0.0]
at org.elasticsearch.http.netty4.Netty4HttpServerTransport.dispatchRequest(Netty4HttpServerTransport.java:509) [transport-netty4-5.0.0.jar:5.0.0]
at org.elasticsearch.http.netty4.Netty4HttpRequestHandler.channelRead0(Netty4HttpRequestHandler.java:68) [transport-netty4-5.0.0.jar:5.0.0]
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
at org.elasticsearch.http.netty4.pipelining.HttpPipeliningHandler.channelRead(HttpPipeliningHandler.java:66) [transport-netty4-5.0.0.jar:5.0.0]

ori.rubinfeld · March 26, 2017, 8:30am

Part 2:

    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102) [netty-codec-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.handler.codec.MessageToMessageCodec.channelRead(MessageToMessageCodec.java:111) [netty-codec-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102) [netty-codec-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102) [netty-codec-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:293) [netty-codec-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:267) [netty-codec-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1334) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:926) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:129) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:610) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:513) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:467) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:437) [netty-transport-4.1.5.Final.jar:4.1.5.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:873) [netty-common-4.1.5.Final.jar:4.1.5.Final]
    at java.lang.Thread.run(Thread.java:745) [?:1.8.0_102]

spinscale · March 27, 2017, 7:26am

The first line indicates the issue here. The thread pool that is used for ingestion is over capacity. This means, you are firing too many documents against elasticsearch and need to retry those that failed later, when Elasticsearch is under less load.

ori.rubinfeld · March 27, 2017, 12:45pm

Hi,

I found there was one pipeline which was failing.
Although I set on_failure to write to a different index, it was failing the entire cluster.

There were 2 fields missing in the GROK expression, which after that, I am doing some Transformaion on them.

Very strange that it crashed the cluster, and not just entered into a failures index.

Ori

spinscale · March 27, 2017, 3:29pm

Hey,

have you tried to stop indexing, and see if the queue of the bulk thread pool goes down again instead of just restarting? Wondering why your whole cluster is affected by this - I cannot make yet the connection based on your comments.

--Alex

system · April 24, 2017, 3:29pm

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.