Encountered a retryable error. Will Retry with exponential backoff

[13142025891]

My log is very large, a single JSON can reach up to 5M, so I set http_compression => true, but as long as http_compression is turned on, I will report an error, and then repeat the error. After a while, logstash will automatically exit if there is insufficient memory. If I don't set it Http_compression is fine, but the traffic is very large.

• Version: logstash 6.2.3 6.5.4
• Version: logstash-output-elasticsearch 9.0 9.3
• Operating System: windows
• Config File
  output config
  elasticsearch {
  hosts => ["xxx:9200"]
  index => "xmllog-%{[@metadata][index]}"
  document_type => "xmllogdb"
  http_compression => true #I set http_compression => true so error
  }
  logstash config
  queue.type: persisted
  queue.max_bytes: 10gb
  queue.page_capacity: 200mb
  log.level: info
  node.name: logstash4xml
  #pipeline.batch.delay: 1000
  dead_letter_queue.enable: true

logstash log
### logstash-output-elasticsearch 9.0 log
[2019-01-08T10:30:31,872][ERROR][logstash.outputs.elasticsearch] Encountered a retryable error. Will Retry with exponential backoff {:code=>400, :url=>"http://172.18.21.126:9200/_bulk", :body=>"{\"error\":{\"root_cause\":[{\"type\":\"illegal_argument_exception\",\"reason\":\"The bulk request must be terminated by a newline [\\n]\"}],\"type\":\"illegal_argument_exception\",\"reason\":\"The bulk request must be terminated by a newline [\\n]\"},\"status\":400}"}

### Update logstash-output-elasticsearch 9.3 log
[2019-01-08T16:34:56,213][ERROR][logstash.outputs.elasticsearch] Attempted to send a bulk request to elasticsearch' but Elasticsearch appears to be unreachable or down! {:error_message=>"Elasticsearch Unreachable: [http://172.18.21.126:9200/][Manticore::SocketException] Connection reset by peer: socket write error", :class=>"LogStash::Outputs::ElasticSearch::HttpClient::Pool::HostUnreachableError", :will_retry_in_seconds=>64} [2019-01-08T16:34:58,052][INFO ][logstash.outputs.elasticsearch] Running health check to see if an Elasticsearch connection is working {:healthcheck_url=>http://172.18.21.126:9200/, :path=>"/"} [2019-01-08T16:34:58,064][WARN ][logstash.outputs.elasticsearch] Restored connection to ES instance {:url=>"http://172.18.21.126:9200/"} [2019-01-08T16:36:07,142][WARN ][logstash.outputs.elasticsearch] Marking url as dead. Last error: [LogStash::Outputs::ElasticSearch::HttpClient::Pool::HostUnreachableError] Elasticsearch Unreachable: [http://172.18.21.126:9200/][Manticore::SocketException] Connection reset by peer: socket write error {:url=>http://172.18.21.126:9200/, :error_message=>"Elasticsearch Unreachable: [http://172.18.21.126:9200/][Manticore::SocketException] Connection reset by peer: socket write error", :error_class=>"LogStash::Outputs::ElasticSearch::HttpClient::Pool::HostUnreachableError"} [2019-01-08T16:36:07,145][ERROR][logstash.outputs.elasticsearch] Attempted to send a bulk request to elasticsearch' but Elasticsearch appears to be unreachable or down! {:error_message=>"Elasticsearch Unreachable: [http://172.18.21.126:9200/][Manticore::SocketException] Connection reset by peer: socket write error", :class=>"LogStash::Outputs::ElasticSearch::HttpClient::Pool::HostUnreachableError", :will_retry_in_seconds=>64} [2019-01-08T16:36:08,155][INFO ][logstash.outputs.elasticsearch] Running health check to see if an Elasticsearch connection is working {:healthcheck_url=>http://172.18.21.126:9200/, :path=>"/"} [2019-01-08T16:36:08,206][WARN ][logstash.outputs.elasticsearch] Restored connection to ES instance {:url=>"http://172.18.21.126:9200/"}
But elasricsearch is good. I tested it

OR the log is like

[2019-01-08T17:03:26,765][ERROR][logstash.outputs.elasticsearch] Encountered a retryable error. Will Retry with exponential backoff {:code=>413, :url=>"http://172.18.21.126:9200/_bulk"} [2019-01-08T17:03:35,459][ERROR][logstash.outputs.elasticsearch] Encountered a retryable error. Will Retry with exponential backoff {:code=>413, :url=>"http://172.18.21.126:9200/_bulk"} [2019-01-08T17:03:46,042][ERROR][logstash.outputs.elasticsearch] Encountered a retryable error. Will Retry with exponential backoff {:code=>413, :url=>"http://172.18.21.126:9200/_bulk"} [2019-01-08T17:04:00,736][ERROR][logstash.outputs.elasticsearch] Encountered a retryable error. Will Retry with exponential backoff {:code=>413, :url=>"http://172.18.21.126:9200/_bulk"}

elasticsearch log

### logstash-output-elasticsearch 9.0 log
[2019-01-08T10:31:38,430][DEBUG][r.suppressed ] path: /_bulk, params: {} java.lang.IllegalArgumentException: The bulk request must be terminated by a newline [ ] at org.elasticsearch.action.bulk.BulkRequest.findNextMarker(BulkRequest.java:537) ~[elasticsearch-6.2.3.jar:6.2.3] at org.elasticsearch.action.bulk.BulkRequest.add(BulkRequest.java:403) ~[elasticsearch-6.2.3.jar:6.2.3] at org.elasticsearch.rest.action.document.RestBulkAction.prepareRequest(RestBulkAction.java:94) ~[elasticsearch-6.2.3.jar:6.2.3] at org.elasticsearch.rest.BaseRestHandler.handleRequest(BaseRestHandler.java:80) ~[elasticsearch-6.2.3.jar:6.2.3] at org.elasticsearch.rest.RestController.dispatchRequest(RestController.java:240) [elasticsearch-6.2.3.jar:6.2.3] at org.elasticsearch.rest.RestController.tryAllHandlers(RestController.java:336) [elasticsearch-6.2.3.jar:6.2.3] at org.elasticsearch.rest.RestController.dispatchRequest(RestController.java:174) [elasticsearch-6.2.3.jar:6.2.3] at org.elasticsearch.http.netty4.Netty4HttpServerTransport.dispatchRequest(Netty4HttpServerTransport.java:500) [transport-netty4-6.2.3.jar:6.2.3] at org.elasticsearch.http.netty4.Netty4HttpRequestHandler.channelRead0(Netty4HttpRequestHandler.java:80) [transport-netty4-6.2.3.jar:6.2.3] at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at org.elasticsearch.http.netty4.pipelining.HttpPipeliningHandler.channelRead(HttpPipeliningHandler.java:68) [transport-netty4-6.2.3.jar:6.2.3] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at org.elasticsearch.http.netty4.cors.Netty4CorsHandler.channelRead(Netty4CorsHandler.java:76) [transport-netty4-6.2.3.jar:6.2.3] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102) [netty-codec-4.1.16.Final.jar:4.1.16.Final] at io.netty.handler.codec.MessageToMessageCodec.channelRead(MessageToMessageCodec.java:111) [netty-codec-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102) [netty-codec-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102) [netty-codec-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:310) [netty-codec-4.1.16.Final.jar:4.1.16.Final] at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:284) [netty-codec-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286) [netty-handler-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1359) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:935) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:134) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:545) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:499) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:459) [netty-transport-4.1.16.Final.jar:4.1.16.Final] at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858) [netty-common-4.1.16.Final.jar:4.1.16.Final] at java.lang.Thread.run(Unknown Source) [?:1.8.0_31]

### Update logstash-output-elasticsearch 9.3 log
[2019-01-08T17:06:11,456][DEBUG][r.suppressed ] path: /bad-request, params: {}
java.lang.IllegalArgumentException: invalid version format: ƨ`T0*���
at io.netty.handler.codec.http.HttpVersion.(HttpVersion.java:121) ~[netty-codec-http-4.1.16.Final.jar:4.1.16.Final]
at io.netty.handler.codec.http.HttpVersion.valueOf(HttpVersion.java:76) ~[netty-codec-http-4.1.16.Final.jar:4.1.16.Final]
at io.netty.handler.codec.http.HttpRequestDecoder.createMessage(HttpRequestDecoder.java:87) ~[netty-codec-http-4.1.16.Final.

[13142025891]

Can this problem recur?

[jsvd]

this seems to be caused by ES rejecting a bulk request due to it being larger than http.max_content_length after being uncompressed. currently logstash checks for the size of the bulk request after compression, which means that a heavily compressed bulk request of 200kb can carry 200mb of data, causing a 413.

This plugin needs to be changed to perform the size check before compression

[joydragon]

Hello,

Is there a workaround to this issue, because whenever it happens to me the only "solution" is to restart logstash and lose all the data that was causing this issue.
Can I patch the code somehow to get this check done in advance?

Thanks

[inglemr]

We are running into this too. We increased http.max_content_length but would like to a more permanent fix.

[jjeanj1]

We are running into this too. We increased http.max_content_length but would like to a more permanent fix.

@inglemr how did you enable the http.max_content_length? We are having the same issue, did this resolved your issue?

[cc-stjm]

In case it's helpful to anyone else, I got here by searching for the same error message - "Encountered a retryable error. Will Retry with exponential backoff" - but my issue turned out to be trying to insert two documents with the same ID.

[immunochomik]

When you set --log.level debug then this error message will include information about reason. It would be nice if that error message included reason in any log level. In my case the error was document id being an empty string.

[nickbabkin]

Hi.
Any estimation when will this be fixed?

Our logstash fails roughly once per month and only full restart along with clearing the queue helps. We're also losing valuable logs by doing so.

Disabling http_compression is not an option for now.