Tasks stuck forever

[bra-fsn]

Opening a bug report from this forum entry:
https://discuss.elastic.co/t/get-tasks-hang-and-accumulate-on-5-4-2/92368

After several full cluster restarts there are still some queries left stuck, but at least, they don't grow.
For example this one:

        "WVpcoLjFRlu1u_n6itJLQg:18857772" : {
          "node" : "WVpcoLjFRlu1u_n6itJLQg",
          "id" : 18857772,
          "type" : "netty",
          "action" : "indices:data/write/index",
          "start_time_in_millis" : 1499661942368,
          "running_time_in_nanos" : 1242244096666339,
          "cancellable" : false
        },

which couldn't finish in two weeks.

Please tell me if more information is needed to debug this.

[ywelsch]

Can you provide

• the full task list?
• which plugins you have installed?

How did you upgrade to 5.4.2? Rolling restart or full cluster restart?

[bra-fsn]

https://pastebin.com/ycZaxf4E
I've removed sources, because they contain sensitive information.
As you can see, currently all stuck requests wait for a single shard. When we saw millions of slow/stuck requests, they were spreaded on more shards.

$ curl -s 'http://localhost:9200/_cat/shards' | grep messages_13
messages_13      0  p STARTED  26201377  13.2gb 10.6.145.206 ffe13.f.private
messages_13      0  r STARTED  26201375  13.2gb 10.6.145.204 ffe11.f.private
$ curl -s 'http://localhost:9200/_cat/segments' | grep messages_13
messages_13     0  p 10.6.145.206 _4yusv  8344687  25894849 111017     13gb 22009475 true  true  6.5.1 false
messages_13     0  p 10.6.145.206 _5396a  8549938    278936   6793  150.8mb   414051 true  true  6.5.1 true
messages_13     0  p 10.6.145.206 _53all  8551785      4064    583    2.7mb    12924 true  true  6.5.1 true
messages_13     0  p 10.6.145.206 _53cqh  8554553      2406    127    1.4mb        0 true  false 6.5.1 true
messages_13     0  p 10.6.145.206 _53da8  8555264      3280    161    2.1mb    11234 true  true  6.5.1 true
messages_13     0  p 10.6.145.206 _53e8r  8556507      2433    120    1.5mb        0 true  false 6.5.1 true
messages_13     0  p 10.6.145.206 _53epr  8557119      2506    183    1.6mb     9481 true  true  6.5.1 true
messages_13     0  p 10.6.145.206 _53fa6  8557854      3767    166    2.4mb    11582 true  true  6.5.1 true
messages_13     0  p 10.6.145.206 _53fxk  8558696       652      2    444kb        0 true  false 6.5.1 true
messages_13     0  p 10.6.145.206 _53fye  8558726       705      1  447.7kb        0 true  false 6.5.1 true
messages_13     0  p 10.6.145.206 _53fyp  8558737       668      0    450kb        0 true  false 6.5.1 true
messages_13     0  p 10.6.145.206 _53fyq  8558738         2      0    6.9kb        0 true  false 6.5.1 true
messages_13     0  p 10.6.145.206 _53fyr  8558739         1      0      6kb        0 true  false 6.5.1 true
messages_13     0  p 10.6.145.206 _53fys  8558740         3      0    7.4kb        0 true  false 6.5.1 true
messages_13     0  p 10.6.145.206 _53fyt  8558741         1      0    5.8kb        0 true  false 6.5.1 true
messages_13     0  p 10.6.145.206 _53h9s  8560432      4327     54    2.6mb    12626 false true  6.5.1 true
messages_13     0  p 10.6.145.206 _53i5f  8561571      2265     23    1.4mb     9564 false true  6.5.1 true
messages_13     0  p 10.6.145.206 _53i5p  8561581      2306     23    1.4mb     9056 false true  6.5.1 true
messages_13     0  p 10.6.145.206 _53i5z  8561591      4520     21    2.8mb    13278 false true  6.5.1 true
messages_13     0  p 10.6.145.206 _53ids  8561872       583      1  402.1kb     5447 false true  6.5.1 true
messages_13     0  p 10.6.145.206 _53idt  8561873         1      1    7.3kb     3818 false true  6.5.1 true
messages_13     0  p 10.6.145.206 _53idu  8561874         1      0    6.7kb     3191 false true  6.5.1 true
messages_13     0  p 10.6.145.206 _53idv  8561875         1      0    5.9kb     2709 false true  6.5.1 true
messages_13     0  p 10.6.145.206 _53idw  8561876         2      0    7.9kb     3848 false true  6.5.1 true
messages_13     0  p 10.6.145.206 _53idx  8561877         1      0    5.8kb     2709 false true  6.5.1 true
messages_13     0  p 10.6.145.206 _53idy  8561878         6      0   10.9kb     4195 false true  6.5.1 true
messages_13     0  p 10.6.145.206 _53idz  8561879         1      0    5.7kb     2709 false true  6.5.1 true
messages_13     0  p 10.6.145.206 _53ie0  8561880         1      0    5.9kb     2709 false true  6.5.1 true
messages_13     0  r 10.6.145.204 _4ywaz  8346635  25895205 111086     13gb 22009942 true  true  6.5.1 false
messages_13     0  r 10.6.145.204 _4ywiw  8346920       107      3   83.8kb        0 true  false 6.5.1 true
messages_13     0  r 10.6.145.204 _4ywl5  8347001       142      1  110.7kb        0 true  false 6.5.1 true
messages_13     0  r 10.6.145.204 _4yws6  8347254       137      1  105.6kb        0 true  false 6.5.1 true
messages_13     0  r 10.6.145.204 _4ywtu  8347314        96      2     70kb        0 true  false 6.5.1 true
messages_13     0  r 10.6.145.204 _4ywv8  8347364       155     11  119.2kb        0 true  false 6.5.1 true
messages_13     0  r 10.6.145.204 _4ywvi  8347374       343      0  240.3kb        0 true  false 6.5.1 true
messages_13     0  r 10.6.145.204 _4ywyk  8347484        27      0   28.4kb        0 true  false 6.5.1 true
messages_13     0  r 10.6.145.204 _4ywyu  8347494        29      0   29.4kb        0 true  false 6.5.1 true
messages_13     0  r 10.6.145.204 _4ywze  8347514        84      0   68.9kb        0 true  false 6.5.1 true
messages_13     0  r 10.6.145.204 _4yx0s  8347564        32      0   32.4kb        0 true  false 6.5.1 true
messages_13     0  r 10.6.145.204 _4yx12  8347574        33      1   33.7kb        0 true  false 6.5.1 true
messages_13     0  r 10.6.145.204 _4yx1c  8347584        41      0     37kb        0 true  false 6.5.1 true
messages_13     0  r 10.6.145.204 _4yx1m  8347594        40      0   36.6kb        0 true  false 6.5.1 true
messages_13     0  r 10.6.145.204 _5370f  8547135    268078   7613  145.6mb   402299 false true  6.5.1 true
messages_13     0  r 10.6.145.204 _53foy  8558386      6586    200      4mb    16948 false true  6.5.1 true
messages_13     0  r 10.6.145.204 _53jb2  8563070     30000    212   17.3mb    52469 false true  6.5.1 true
messages_13     0  r 10.6.145.204 _53jeo  8563200       274      9  216.2kb     7848 false true  6.5.1 true
messages_13     0  r 10.6.145.204 _53jmr  8563491       223      2  199.8kb    10763 false true  6.5.1 true
messages_13     0  r 10.6.145.204 _53jq4  8563612       391      7    285kb     5111 false true  6.5.1 true
messages_13     0  r 10.6.145.204 _53jsn  8563703       186     11  142.3kb     9884 false true  6.5.1 true
messages_13     0  r 10.6.145.204 _53juc  8563764       161      0  124.7kb     9133 false true  6.5.1 true
messages_13     0  r 10.6.145.204 _53jun  8563775       153     10  131.3kb     8969 false true  6.5.1 true
messages_13     0  r 10.6.145.204 _53juy  8563786       158      0  124.1kb     9033 false true  6.5.1 true
messages_13     0  r 10.6.145.204 _53juz  8563787         1      0    5.7kb     2709 false true  6.5.1 true
messages_13     0  r 10.6.145.204 _53jv0  8563788         3      0    7.7kb     3149 false true  6.5.1 true

Only analysis-icu is installed.

We've started with rolling restart (from 5.1.2) then we saw an increasing amount of slowness, so we decided to go with full cluster restart (removed all traffic, shut down all nodes and restarted them).

The cluster started its life at around 2.x, but a reindex was done later. A force merge was also done.

The bulks contain index operations into multiple indices and every failed operation is retried with some wait and a retry count in new bulks. (I don't think the latter is relevant)

[ywelsch]

Thanks @bra-fsn.

What's odd is that the indexing task that got stuck is in the "starting" phase:

"x6u3Q2G7TzeZwsMi4q6P8g:17901896" : {
          "node" : "x6u3Q2G7TzeZwsMi4q6P8g",
          "id" : 17901896,
          "type" : "direct",
          "action" : "indices:data/write/bulk[s][p]",
          "status" : {
            "phase" : "starting"
          },
          "description" : "BulkShardRequest [[messages_13][0]] containing [index {[messages_13][message][9439467.1397985422], source[{}]}]",
          "start_time_in_millis" : 1499661826584,
          "running_time_in_nanos" : 1311027017177258,
          "cancellable" : false,
          "parent_task_id" : "x6u3Q2G7TzeZwsMi4q6P8g:17901895"
        },

Is it possible to get a heap dump from this node that you could share with us in private?

@bleskes this could be an issue with the IndexShardOperationsLock / IndexShardOperationPermits?

[bra-fsn]

I've sent the dumps via email.
Thanks.

[ywelsch]

Just a small update, nothing conclusive yet:

I've given the heap dump a quick look and found the object associated with the task seen above, but there are no other components besides the task manager holding a reference to it. This means that the request did not get stuck in the classical sense, but in presence of the async communication methods used by transport, there was never a response send to the channel for this request. The TransportChannelWrapper that should normally keep a reference to the task to remove it from the task manager upon sending a response has been garbage-collected, which means that a response was never sent, and that the channel object (i.e. response listener) must have gotten lost / ignored somewhere along the way. The tricky part is figuring out where this could have happened (needs more investigation).

@bra-fsn can you check whether there was a warning of the form failed to execute failure callback on in the logs of the node x6u3Q2G7TzeZwsMi4q6P8g 2 weeks ago?

[bra-fsn]

Yes:

[2017-07-10T04:51:46,388][WARN ][o.e.i.s.IndexShard       ] [ffe14.f.private] [messages_13][0] failed to execute failure callback on [org.elasticsearch.action.support.ContextPreservingActionListener@40a1
96a4]
org.elasticsearch.common.util.concurrent.EsRejectedExecutionException: rejected execution of org.elasticsearch.action.support.ThreadedActionListener$2@64ec773a on EsThreadPoolExecutor[bulk, queue capacity = 300,
 org.elasticsearch.common.util.concurrent.EsThreadPoolExecutor@1afaaa21[Running, pool size = 24, active threads = 24, queued tasks = 297, completed tasks = 2527871]]
        at org.elasticsearch.common.util.concurrent.EsAbortPolicy.rejectedExecution(EsAbortPolicy.java:50) ~[elasticsearch-5.4.2.jar:5.4.2]
        at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:823) ~[?:1.8.0_121]
        at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1369) ~[?:1.8.0_121]
        at org.elasticsearch.common.util.concurrent.EsThreadPoolExecutor.doExecute(EsThreadPoolExecutor.java:94) ~[elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.common.util.concurrent.EsThreadPoolExecutor.execute(EsThreadPoolExecutor.java:89) ~[elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.action.support.ThreadedActionListener.onFailure(ThreadedActionListener.java:110) ~[elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.index.shard.IndexShardOperationsLock.acquire(IndexShardOperationsLock.java:120) ~[elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.index.shard.IndexShardOperationsLock.lambda$blockOperations$0(IndexShardOperationsLock.java:101) ~[elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:569) [elasticsearch-5.4.2.jar:5.4.2]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_121]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_121]
        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_121]
[2017-07-10T04:51:46,388][DEBUG][o.e.a.b.TransportShardBulkAction] [ffe14.f.private] [messages_13][0] failed to execute bulk item (update) BulkShardRequest [[messages_13][0]] containing [20] requests blocking until refresh
org.elasticsearch.index.shard.IllegalIndexShardStateException: CurrentState[CLOSED] operations only allowed when shard state is one of [POST_RECOVERY, STARTED, RELOCATED]
        at org.elasticsearch.index.shard.IndexShard.readAllowed(IndexShard.java:1106) ~[elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.index.shard.IndexShard.get(IndexShard.java:614) ~[elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.index.get.ShardGetService.innerGet(ShardGetService.java:165) ~[elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.index.get.ShardGetService.get(ShardGetService.java:83) ~[elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.action.update.UpdateHelper.prepare(UpdateHelper.java:78) ~[elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.action.bulk.TransportShardBulkAction.executeUpdateRequest(TransportShardBulkAction.java:269) ~[elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.action.bulk.TransportShardBulkAction.executeBulkItemRequest(TransportShardBulkAction.java:159) [elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.action.bulk.TransportShardBulkAction.shardOperationOnPrimary(TransportShardBulkAction.java:113) [elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.action.bulk.TransportShardBulkAction.shardOperationOnPrimary(TransportShardBulkAction.java:69) [elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryShardReference.perform(TransportReplicationAction.java:939) [elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryShardReference.perform(TransportReplicationAction.java:908) [elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.action.support.replication.ReplicationOperation.execute(ReplicationOperation.java:113) [elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncPrimaryAction.onResponse(TransportReplicationAction.java:322) [elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncPrimaryAction.onResponse(TransportReplicationAction.java:264) [elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.action.support.replication.TransportReplicationAction$1.onResponse(TransportReplicationAction.java:888) [elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.action.support.replication.TransportReplicationAction$1.onResponse(TransportReplicationAction.java:885) [elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.action.support.ContextPreservingActionListener.onResponse(ContextPreservingActionListener.java:43) [elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.action.support.ThreadedActionListener$1.doRun(ThreadedActionListener.java:98) [elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:638) [elasticsearch-5.4.2.jar:5.4.2]
        at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elasticsearch-5.4.2.jar:5.4.2]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_121]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_121]
        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_121]

BTW, we use wait_for requests, I'm not sure whether there are too many of them (filling up the queue), or just the stuck tasks block them.

[ywelsch]

Great. I think I have this figured out. Will look at options to fix this tomorrow. In the meanwhile, you can disable shard balancing for primaries (The issue can only occur during primary relocations AFAICS), i.e., set cluster.routing.rebalance.enable=replicas.

[bra-fsn]

You may be right, because I couldn't cure this by restarting the nodes on which there were stuck tasks. BTW, even restarting all of the data nodes didn't help. But if I restarted the master nodes too, it seems to have normalized.
Is this in line with what you've found?