fatal error on the network layer

[tomsommer]

My client node is suddenly crashing with this error:

[2017-01-02T20:40:22,663][ERROR][o.e.t.n.Netty4Utils      ] fatal error on the network layer
        at org.elasticsearch.transport.netty4.Netty4Utils.maybeDie(Netty4Utils.java:141)
        at org.elasticsearch.http.netty4.Netty4HttpRequestHandler.exceptionCaught(Netty4HttpRequestHandler.java:76)
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:296)
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:275)
        at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:267)
        at io.netty.channel.ChannelInboundHandlerAdapter.exceptionCaught(ChannelInboundHandlerAdapter.java:131)
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:296)
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:275)
        at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:267)
        at io.netty.channel.ChannelInboundHandlerAdapter.exceptionCaught(ChannelInboundHandlerAdapter.java:131)
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:296)
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:275)
        at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:267)
        at io.netty.channel.ChannelInboundHandlerAdapter.exceptionCaught(ChannelInboundHandlerAdapter.java:131)
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:296)
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:275)
        at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:267)
        at io.netty.channel.ChannelHandlerAdapter.exceptionCaught(ChannelHandlerAdapter.java:78)
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:296)
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:275)
        at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:267)
        at io.netty.channel.ChannelInboundHandlerAdapter.exceptionCaught(ChannelInboundHandlerAdapter.java:131)
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:296)
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:275)
        at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:267)
        at io.netty.channel.ChannelInboundHandlerAdapter.exceptionCaught(ChannelInboundHandlerAdapter.java:131)
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:296)
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:275)
        at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:267)
        at io.netty.channel.ChannelInboundHandlerAdapter.exceptionCaught(ChannelInboundHandlerAdapter.java:131)
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:296)
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:275)
        at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:267)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.exceptionCaught(DefaultChannelPipeline.java:1301)
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:296)
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:275)
        at io.netty.channel.DefaultChannelPipeline.fireExceptionCaught(DefaultChannelPipeline.java:914)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.handleReadException(AbstractNioByteChannel.java:99)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:140)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:651)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:536)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:490)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:450)
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:873)
        at java.lang.Thread.run(Thread.java:745)

What triggers this? I'm thinking it might be due to too many concurrent connections, but the error tells me nothing?

[jasontedor]

There should be a caused by exception below this. Can you please share it here?

[jasontedor]

It would look something like:

\[\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2},\d{3}\]\[ERROR\]\[o\.e\.b\.ElasticsearchUncaughtExceptionHandler\] \[\] fatal error in thread \[Thread-\d+\], exiting

with another exception stack trace below it.

[tomsommer]

[2017-01-02T21:38:53,488][WARN ][o.e.m.j.JvmGcMonitorService] [elasticclient] [gc][2285] overhead, spent [3.5s] collecting in the last [3.8s]
[2017-01-02T21:38:49,758][ERROR][o.e.b.ElasticsearchUncaughtExceptionHandler] [elasticclient] fatal error in thread [Thread-5], exiting
java.lang.OutOfMemoryError: Java heap space
        at io.netty.buffer.PoolArena$HeapArena.newChunk(PoolArena.java:656) ~[?:?]
        at io.netty.buffer.PoolArena.allocateNormal(PoolArena.java:237) ~[?:?]
        at io.netty.buffer.PoolArena.allocate(PoolArena.java:221) ~[?:?]
        at io.netty.buffer.PoolArena.allocate(PoolArena.java:141) ~[?:?]
        at io.netty.buffer.PooledByteBufAllocator.newHeapBuffer(PooledByteBufAllocator.java:247) ~[?:?]
        at io.netty.buffer.AbstractByteBufAllocator.heapBuffer(AbstractByteBufAllocator.java:160) ~[?:?]
        at io.netty.buffer.AbstractByteBufAllocator.heapBuffer(AbstractByteBufAllocator.java:151) ~[?:?]
        at io.netty.buffer.AbstractByteBufAllocator.ioBuffer(AbstractByteBufAllocator.java:133) ~[?:?]
        at io.netty.channel.DefaultMaxMessagesRecvByteBufAllocator$MaxMessageHandle.allocate(DefaultMaxMessagesRecvByteBufAllocator.java:73) ~[?:?]
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:117) ~[?:?]
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:651) ~[?:?]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:536) ~[?:?]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:490) ~[?:?]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:450) ~[?:?]
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:873) ~[?:?]
        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_111]
[2017-01-02T21:38:49,689][ERROR][o.e.b.ElasticsearchUncaughtExceptionHandler] [elasticclient] fatal error in thread [Thread-8], exiting
java.lang.OutOfMemoryError: Java heap space
        at io.netty.buffer.PoolArena$HeapArena.newChunk(PoolArena.java:656) ~[?:?]
        at io.netty.buffer.PoolArena.allocateNormal(PoolArena.java:237) ~[?:?]
        at io.netty.buffer.PoolArena.allocate(PoolArena.java:221) ~[?:?]
        at io.netty.buffer.PoolArena.allocate(PoolArena.java:141) ~[?:?]
        at io.netty.buffer.PooledByteBufAllocator.newHeapBuffer(PooledByteBufAllocator.java:247) ~[?:?]
        at io.netty.buffer.AbstractByteBufAllocator.heapBuffer(AbstractByteBufAllocator.java:160) ~[?:?]
        at io.netty.buffer.AbstractByteBufAllocator.heapBuffer(AbstractByteBufAllocator.java:151) ~[?:?]
        at io.netty.buffer.AbstractByteBufAllocator.ioBuffer(AbstractByteBufAllocator.java:133) ~[?:?]
        at io.netty.channel.DefaultMaxMessagesRecvByteBufAllocator$MaxMessageHandle.allocate(DefaultMaxMessagesRecvByteBufAllocator.java:73) ~[?:?]
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:117) ~[?:?]
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:651) ~[?:?]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:536) ~[?:?]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:490) ~[?:?]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:450) ~[?:?]
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:873) ~[?:?]
        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_111]

This started happening after I increased Logstash pipeline.workers to 164 and pipeline.output.workers to 2, and pipeline.batch.size to 512. I can't find the counter to watch. The client is running node.data: false and node.master: false, heap is 5g atm, server has 10g.

node stats (after restart though):

{
  "_nodes": {
    "total": 1,
    "successful": 1,
    "failed": 0
  },
  "cluster_name": "elasticsearch",
  "nodes": {
    "Dvjln3ldSn2cwW4K9Zz1Kw": {
      "timestamp": 1483426687178,
      "name": "elasticclient",
      "transport_address": "xxxxx:9300",
      "host": "xxxxx",
      "ip": "xxxxxx:9300",
      "roles": [
        "ingest"
      ],
      "indices": {
        "docs": {
          "count": 0,
          "deleted": 0
        },
        "store": {
          "size_in_bytes": 0,
          "throttle_time_in_millis": 0
        },
        "indexing": {
          "index_total": 0,
          "index_time_in_millis": 0,
          "index_current": 0,
          "index_failed": 0,
          "delete_total": 0,
          "delete_time_in_millis": 0,
          "delete_current": 0,
          "noop_update_total": 0,
          "is_throttled": false,
          "throttle_time_in_millis": 0
        },
        "get": {
          "total": 0,
          "time_in_millis": 0,
          "exists_total": 0,
          "exists_time_in_millis": 0,
          "missing_total": 0,
          "missing_time_in_millis": 0,
          "current": 0
        },
        "search": {
          "open_contexts": 0,
          "query_total": 0,
          "query_time_in_millis": 0,
          "query_current": 0,
          "fetch_total": 0,
          "fetch_time_in_millis": 0,
          "fetch_current": 0,
          "scroll_total": 0,
          "scroll_time_in_millis": 0,
          "scroll_current": 0,
          "suggest_total": 0,
          "suggest_time_in_millis": 0,
          "suggest_current": 0
        },
        "merges": {
          "current": 0,
          "current_docs": 0,
          "current_size_in_bytes": 0,
          "total": 0,
          "total_time_in_millis": 0,
          "total_docs": 0,
          "total_size_in_bytes": 0,
          "total_stopped_time_in_millis": 0,
          "total_throttled_time_in_millis": 0,
          "total_auto_throttle_in_bytes": 0
        },
        "refresh": {
          "total": 0,
          "total_time_in_millis": 0
        },
        "flush": {
          "total": 0,
          "total_time_in_millis": 0
        },
        "warmer": {
          "current": 0,
          "total": 0,
          "total_time_in_millis": 0
        },
        "query_cache": {
          "memory_size_in_bytes": 0,
          "total_count": 0,
          "hit_count": 0,
          "miss_count": 0,
          "cache_size": 0,
          "cache_count": 0,
          "evictions": 0
        },
        "fielddata": {
          "memory_size_in_bytes": 0,
          "evictions": 0
        },
        "completion": {
          "size_in_bytes": 0
        },
        "segments": {
          "count": 0,
          "memory_in_bytes": 0,
          "terms_memory_in_bytes": 0,
          "stored_fields_memory_in_bytes": 0,
          "term_vectors_memory_in_bytes": 0,
          "norms_memory_in_bytes": 0,
          "points_memory_in_bytes": 0,
          "doc_values_memory_in_bytes": 0,
          "index_writer_memory_in_bytes": 0,
          "version_map_memory_in_bytes": 0,
          "fixed_bit_set_memory_in_bytes": 0,
          "max_unsafe_auto_id_timestamp": -9223372036854776000,
          "file_sizes": {

          }
        },
        "translog": {
          "operations": 0,
          "size_in_bytes": 0
        },
        "request_cache": {
          "memory_size_in_bytes": 0,
          "evictions": 0,
          "hit_count": 0,
          "miss_count": 0
        },
        "recovery": {
          "current_as_source": 0,
          "current_as_target": 0,
          "throttle_time_in_millis": 0
        }
      },
      "os": {
        "timestamp": 1483426687062,
        "cpu": {
          "percent": 59,
          "load_average": {
            "1m": 1.52,
            "5m": 1.41,
            "15m": 0.72
          }
        },
        "mem": {
          "total_in_bytes": 10368720896,
          "free_in_bytes": 3572068352,
          "used_in_bytes": 6796652544,
          "free_percent": 34,
          "used_percent": 66
        },
        "swap": {
          "total_in_bytes": 4294963200,
          "free_in_bytes": 4294963200,
          "used_in_bytes": 0
        }
      },
      "process": {
        "timestamp": 1483426687062,
        "open_file_descriptors": 610,
        "max_file_descriptors": 65536,
        "cpu": {
          "percent": 55,
          "total_in_millis": 929210
        },
        "mem": {
          "total_virtual_in_bytes": 9253572608
        }
      },
      "jvm": {
        "timestamp": 1483426687062,
        "uptime_in_millis": 453992,
        "mem": {
          "heap_used_in_bytes": 2061345056,
          "heap_used_percent": 38,
          "heap_committed_in_bytes": 5333843968,
          "heap_max_in_bytes": 5333843968,
          "non_heap_used_in_bytes": 83551800,
          "non_heap_committed_in_bytes": 88379392,
          "pools": {
            "young": {
              "used_in_bytes": 218310616,
              "max_in_bytes": 279183360,
              "peak_used_in_bytes": 279183360,
              "peak_max_in_bytes": 279183360
            },
            "survivor": {
              "used_in_bytes": 34865152,
              "max_in_bytes": 34865152,
              "peak_used_in_bytes": 34865152,
              "peak_max_in_bytes": 34865152
            },
            "old": {
              "used_in_bytes": 1808169288,
              "max_in_bytes": 5019795456,
              "peak_used_in_bytes": 4707353216,
              "peak_max_in_bytes": 5019795456
            }
          }
        },
        "threads": {
          "count": 48,
          "peak_count": 49
        },
        "gc": {
          "collectors": {
            "young": {
              "collection_count": 206,
              "collection_time_in_millis": 50089
            },
            "old": {
              "collection_count": 17,
              "collection_time_in_millis": 3922
            }
          }
        },
        "buffer_pools": {
          "direct": {
            "count": 38,
            "used_in_bytes": 228089864,
            "total_capacity_in_bytes": 228089863
          },
          "mapped": {
            "count": 0,
            "used_in_bytes": 0,
            "total_capacity_in_bytes": 0
          }
        },
        "classes": {
          "current_loaded_count": 9685,
          "total_loaded_count": 9689,
          "total_unloaded_count": 4
        }
      },
      "thread_pool": {
        "bulk": {
          "threads": 0,
          "queue": 0,
          "active": 0,
          "rejected": 0,
          "largest": 0,
          "completed": 0
        },
        "fetch_shard_started": {
          "threads": 0,
          "queue": 0,
          "active": 0,
          "rejected": 0,
          "largest": 0,
          "completed": 0
        },
        "fetch_shard_store": {
          "threads": 0,
          "queue": 0,
          "active": 0,
          "rejected": 0,
          "largest": 0,
          "completed": 0
        },
        "flush": {
          "threads": 0,
          "queue": 0,
          "active": 0,
          "rejected": 0,
          "largest": 0,
          "completed": 0
        },
        "force_merge": {
          "threads": 0,
          "queue": 0,
          "active": 0,
          "rejected": 0,
          "largest": 0,
          "completed": 0
        },
        "generic": {
          "threads": 4,
          "queue": 0,
          "active": 0,
          "rejected": 0,
          "largest": 4,
          "completed": 486
        },
        "get": {
          "threads": 0,
          "queue": 0,
          "active": 0,
          "rejected": 0,
          "largest": 0,
          "completed": 0
        },
        "index": {
          "threads": 0,
          "queue": 0,
          "active": 0,
          "rejected": 0,
          "largest": 0,
          "completed": 0
        },
        "listener": {
          "threads": 0,
          "queue": 0,
          "active": 0,
          "rejected": 0,
          "largest": 0,
          "completed": 0
        },
        "management": {
          "threads": 3,
          "queue": 0,
          "active": 1,
          "rejected": 0,
          "largest": 3,
          "completed": 584
        },
        "refresh": {
          "threads": 0,
          "queue": 0,
          "active": 0,
          "rejected": 0,
          "largest": 0,
          "completed": 0
        },
        "search": {
          "threads": 7,
          "queue": 0,
          "active": 0,
          "rejected": 0,
          "largest": 7,
          "completed": 108
        },
        "snapshot": {
          "threads": 0,
          "queue": 0,
          "active": 0,
          "rejected": 0,
          "largest": 0,
          "completed": 0
        },
        "warmer": {
          "threads": 0,
          "queue": 0,
          "active": 0,
          "rejected": 0,
          "largest": 0,
          "completed": 0
        }
      },
      "fs": {
        "timestamp": 1483426687063,
        "total": {
          "total_in_bytes": 90230251520,
          "free_in_bytes": 83245780992,
          "available_in_bytes": 78655537152,
          "spins": "true"
        },
        "data": [
          {
            "path": "/var/lib/elasticsearch/nodes/0",
            "mount": "/var (/dev/mapper/vg-var)",
            "type": "ext4",
            "total_in_bytes": 90230251520,
            "free_in_bytes": 83245780992,
            "available_in_bytes": 78655537152,
            "spins": "true"
          }
        ],
        "io_stats": {
          "devices": [
            {
              "device_name": "dm-4",
              "operations": 298,
              "read_operations": 0,
              "write_operations": 298,
              "read_kilobytes": 0,
              "write_kilobytes": 1192
            }
          ],
          "total": {
            "operations": 298,
            "read_operations": 0,
            "write_operations": 298,
            "read_kilobytes": 0,
            "write_kilobytes": 1192
          }
        }
      },
      "transport": {
        "server_open": 112,
        "rx_count": 142865,
        "rx_size_in_bytes": 5043248958,
        "tx_count": 142888,
        "tx_size_in_bytes": 1598377422
      },
      "http": {
        "current_open": 224,
        "total_opened": 356
      },
      "breakers": {
        "request": {
          "limit_size_in_bytes": 3200306380,
          "limit_size": "2.9gb",
          "estimated_size_in_bytes": 4440736,
          "estimated_size": "4.2mb",
          "overhead": 1,
          "tripped": 0
        },
        "fielddata": {
          "limit_size_in_bytes": 3200306380,
          "limit_size": "2.9gb",
          "estimated_size_in_bytes": 0,
          "estimated_size": "0b",
          "overhead": 1.03,
          "tripped": 0
        },
        "in_flight_requests": {
          "limit_size_in_bytes": 5333843968,
          "limit_size": "4.9gb",
          "estimated_size_in_bytes": 2,
          "estimated_size": "2b",
          "overhead": 1,
          "tripped": 0
        },
        "parent": {
          "limit_size_in_bytes": 3733690777,
          "limit_size": "3.4gb",
          "estimated_size_in_bytes": 4440738,
          "estimated_size": "4.2mb",
          "overhead": 1,
          "tripped": 0
        }
      },
      "script": {
        "compilations": 0,
        "cache_evictions": 0
      },
      "discovery": {
        "cluster_state_queue": {
          "total": 0,
          "pending": 0,
          "committed": 0
        }
      },
      "ingest": {
        "total": {
          "count": 0,
          "time_in_millis": 0,
          "current": 0,
          "failed": 0
        },
        "pipelines": {

        }
      }
    }
  }
}

I need to add on to this. We have a single node instance for our development needs. Heap size is 2.5 GB, and the server is crashing with the same OOM heap size error from the network layer every 10-15 minutes.

It makes no sense, I am only running 3x bulk indexing processes. No searches are being executed whatsoever. fielddata in memory is exactly 0. There is no reason for our 200 MB of data to require 2.5 GB of memory - especially when no searches are being performed, and thus fielddata is not being loaded.

Something is really fishy with version 5.1.1

[jasontedor]

Can either/both of you share a heap dump from when it OOMs? (Be careful since it might contain sensitive data. If needed, we can find a mechanism to share it privately.)

And can you also try running with -Dio.netty.recycler.maxCapacityPerThread=0 and let me know if the problem persists (grab a heap dump before changing this setting though)? Note that this could negatively impact performance.

@jasontedor can you please confirm whether the option should be io.netty.recycler.maxCapacityPerThread or io.netty.recycler.maxCapacity.default?

[jasontedor]

It should be the one I stated (-Dio.netty.recycler.maxCapacityPerThread=0), I don't think the latter does anything.

[jasontedor]

Closed by #22452

[tomsommer]

#22452 did not fix it

-Dio.netty.allocator.type=unpooled does not help either.

[JorritSalverda]

Having the same issues with 5.2.0, even though heap size is 6g and available memory 12gb. I pass in the following

ES_JAVA_OPTS = -Xms6g -Xmx6g -Dio.netty.recycler.maxCapacityPerThread=0

The full log from starting the node to failing is at https://gist.github.com/JorritSalverda/eef328f1cf130f360409854394c321b6

The highest memory I've seen is 6.55GB, so I don't think it comes close to the 12GB limit at all.

[jasontedor]

As I mentioned in a previous comment, disabling the recycler is not expected to eliminate all causes of out of memory errors on the network layer. If you startup Elasticsearch with a 256m heap (and increase http.max_content_length) and send it a 512m request, you're going to have a bad time. This has nothing to do with whether or not the recycler is enabled. Disabling the recycler dealt with a specific problem but if you're still seeing heaping, then you have to take a heap dump and see what is consuming the space and adjust accordingly.