Thread leak with autodiscover after adding / removing a master node

[fdv]

I've had an epic bug leading to a thread leak (and ES dying because it had no more RAM to create more threads). Whole story here.

Bug description

4 nodes ES cluster on EC2. 1 routing node, 3 data nodes. The routing node acts as master (configuration provided below)

After I added and removed a master node, one of the data nodes kept sending auto discovery requests to a the gone node. This led to the remaining routing node to create about 1 thread / second (sending auto discovery requests) and never closing them.

Configuration

• ES 1.0.1 (old, I know)
• ES Transport Thrift: elasticsearch-transport-thrift-2.0.0
• AWS cloud plugin: cloud-aws-2.0.0

Routing node

bootstrap:
  mlockall: true
cloud:
  aws:
    access_key: something
    region: us-east-1
    secret_key: something
cluster:
  name: robots
discovery:
  ec2:
    ping_timeout: 360
    tag:
      Cluster: production
  type: ec2
  zen:
    minimum_master_nodes: 1
gateway:
  expected_nodes: 4
  recover_after_nodes: 4
  recover_after_time: 5m
http:
  max_content_length: 100mb
index:
  query:
    bool:
      max_clause_count: 1000000
  refresh_interval: 300
  store:
    type: mmapfs
indices:
  fielddata:
    cache:
      expire: 10m
      size: 30%
  memory:
    index_buffer_size: 10%
network:
  host: 0.0.0.0
node:
  data: false
  master: true
  name: something
path:
  data: /mnt/elasticsearch
  logs: /var/log/elasticsearch

Data nodes

bootstrap:
  mlockall: true
cloud:
  aws:
    access_key: something
    region: us-east-1
    secret_key: something
cluster:
  name: robots
discovery:
  ec2:
    ping_timeout: 360
    tag:
      Cluster: production
  type: ec2
  zen:
    minimum_master_nodes: 1
gateway:
  expected_nodes: 4
  recover_after_nodes: 4
  recover_after_time: 5m
http:
  max_content_length: 100mb
index:
  query:
    bool:
      max_clause_count: 1000000
  refresh_interval: 300
  store:
    type: mmapfs
indices:
  fielddata:
    cache:
      expire: 10m
      size: 30%
  memory:
    index_buffer_size: 10%
network:
  host: 0.0.0.0
node:
  data: true
  master: false
  name: something
path:
  data: /mnt/elasticsearch
  logs: /var/log/elasticsearch

JVM

• xmx and xms to 4G
• no fancy GC tuning

Tell me if I you need anything else.

[dadoonet]

Hi Frederic,

Would it be possible to run some other tests on your side?

• Without AWS plugin (using unicast list)
• Without Thrift plugin
• Upgrading to elasticsearch 1.3.4 and AWS 2.3.0

I would like to understand if this leak is caused by AWS plugin or one of its dependencies. In AWS plugin, we updated AWS SDK to a more recent version (1.7.13 - was 1.7.3 in AWS 2.0.0).

[imotov]

@fdv if you can reproduce the leak, could you also run the following command on the node that is leaking threads and post there the output here: curl "localhost:9200/_nodes/_local/hot_threads?threads=100000"

[clintongormley]

No further info provided. Closing

[jh12z]

I'm getting the same thread leak caused by the `MulticastZenPing` class which ends up causing an OOM (`OutOfMemoryError: unable to create new native thread`) being thrown **every second** when the limit of **2031 threads** is reached! (Mac OS X native thread limit)

It seems threads are created for the auto discovery but never disposed.

This is the stack trace for the thread creation:

java.lang.OutOfMemoryError: unable to create new native thread
    at java.lang.Thread.start0(Native Method)
    at java.lang.Thread.start(Thread.java:714)
    at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:950)
    at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1368)
    at org.elasticsearch.common.util.concurrent.EsThreadPoolExecutor.execute(EsThreadPoolExecutor.java:79)
    at org.elasticsearch.discovery.zen.ping.multicast.MulticastZenPing$Receiver.handleNodePingRequest(MulticastZenPing.java:539)
    at org.elasticsearch.discovery.zen.ping.multicast.MulticastZenPing$Receiver.onMessage(MulticastZenPing.java:429)
    at org.elasticsearch.common.network.MulticastChannel$MultiListener.onMessage(MulticastChannel.java:139)
    at org.elasticsearch.common.network.MulticastChannel$Plain$Receiver.run(MulticastChannel.java:381)
    at java.lang.Thread.run(Thread.java:745)

The result of requesting http://localhost:9200/_nodes/_local/hot_threads?threads=100000 brings back around 2000 threads with the following stack trace:

 0.0% (0s out of 500ms) cpu usage by thread 'elasticsearch[Jazz][generic][T#131]'
     10/10 snapshots sharing following 15 elements
       sun.misc.Unsafe.park(Native Method)
       java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
       java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
       java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
       java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
       java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
       java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
       org.elasticsearch.common.util.concurrent.KeyedLock.acquire(KeyedLock.java:79)
       org.elasticsearch.transport.netty.NettyTransport.connectToNode(NettyTransport.java:743)
       org.elasticsearch.transport.netty.NettyTransport.connectToNode(NettyTransport.java:731)
       org.elasticsearch.transport.TransportService.connectToNode(TransportService.java:216)
       org.elasticsearch.discovery.zen.ping.multicast.MulticastZenPing$Receiver$1.run(MulticastZenPing.java:544)
       java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
       java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
       java.lang.Thread.run(Thread.java:745)

[jh12z]

Forgot to comment this is happening with Elasticsearch 1.7.1

[clintongormley]

@bleskes any ideas?

[bleskes]

@jh12z when ever a node receives a multi cast ping, it tries to connect the source of the ping and respond. This is done on a background thread. Something seems to be blocking connections (but not rejecting them) causing these thread to accumulate. Any idea what it can be? Do you have only one node in your cluster (you mention mac os x)? can you check your host and publish addresses ? Es logs them when it starts:

[2015-10-20 11:42:07,426][INFO ][transport                ] [Meteorite] publish_address {127.0.0.1:9300}, bound_addresses {127.0.0.1:9300}, {[fe80::1]:9300}, {[::1]:9300}

[clintongormley]

No further feedback for a year. Closing