Unrecoverable error in KIS 0.12.2 and 0.12.1

[pdeva]

all the tasks keep restarting with this error in the logs:
I tried:

• upgrading node from 0.12.1 to 0.12.2
• spinning a whole new server and created a replica.
  Completely unrecoverable!

2018-08-13 15:41:48,555 INFO i.d.i.o.ForkingTaskRunner [forking-task-runner-1] Exception caught during execution
java.io.IOException: Stream closed
	at java.io.BufferedInputStream.getBufIfOpen(BufferedInputStream.java:170) ~[?:1.8.0_181]
	at java.io.BufferedInputStream.read1(BufferedInputStream.java:291) ~[?:1.8.0_181]
	at java.io.BufferedInputStream.read(BufferedInputStream.java:345) ~[?:1.8.0_181]
	at java.io.FilterInputStream.read(FilterInputStream.java:107) ~[?:1.8.0_181]
	at com.google.common.io.ByteStreams.copy(ByteStreams.java:175) ~[guava-16.0.1.jar:?]
	at io.druid.indexing.overlord.ForkingTaskRunner$1.call(ForkingTaskRunner.java:452) [druid-indexing-service-0.12.2.jar:0.12.2]
	at io.druid.indexing.overlord.ForkingTaskRunner$1.call(ForkingTaskRunner.java:224) [druid-indexing-service-0.12.2.jar:0.12.2]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_181]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_181]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_181]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_181]

Even posted a thread here:
https://groups.google.com/forum/#!topic/druid-user/K7YmcBJM6T4

More details:

• Coord+overlord node is still at 0.12.1 (we havent upgraded it yet, for fear of more damage)
• another replica of MM node (we deploy 2) has been running without issue. we are very, very scared that if that replica dies and gets stuck like this, ALL ingestion will stop!

All help is highly appreciated.

[gianm]

Hi @pdeva,

Are you able to see task logs for any of the tasks that are complaining about 'connection refused'? Do they show up in the overlord web ui? For example: index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf?

Do you see references to these tasks in the middleManager logs? Does anything interesting show up there?

[pdeva]

@gianm here is a video of the overlord console:
https://www.screencast.com/t/z4eXgbaGe5fy

as you can see, the tasks dont really product any output at all. which is what makes it really tough to debug this issue. (ignore the dripstat agent output in the logs in the video, they dont affect the tasks)
they just start and shut down.

the video shows that the one replica seems to be working, but we had to take down the other replica since it kept on spawing new tasks (which fail) almost every minute.

the coordinator(+overlord) show that it tries to spawn the tasks, but it cannot connect to it, so it seems to kill it. (coordinator logs are in the users-group thread i linked to).

[pdeva]

logs from splunk for search term index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf

2018-08-13 14:24:41,632 INFO i.d.i.o.RemoteTaskRunner [Curator-PathChildrenCache-1] Task[index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf] went bye bye.
2018-08-13 14:24:41,632 INFO i.d.i.o.TaskRunnerUtils [Curator-PathChildrenCache-1] Task [index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf] status changed to [FAILED].
2018-08-13 14:24:41,632 INFO i.d.i.o.TaskQueue [Curator-PathChildrenCache-1] Task FAILED: KafkaIndexTask{id=index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf, type=index_kafka, dataSource=sqltrace-minute} (66829 run duration)
2018-08-13 14:24:41,632 WARN i.d.i.o.TaskQueue [Curator-PathChildrenCache-1] Unknown task completed: index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf
2018-08-13 14:24:41,629 INFO i.d.i.o.RemoteTaskRunner [Curator-PathChildrenCache-1] Cleaning up task[index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf] on worker[10.240.0.4:8091]
2018-08-13 14:24:41,629 INFO i.d.i.o.TaskQueue [Curator-PathChildrenCache-1] Received FAILED status for task: index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf
2018-08-13 14:24:41,629 INFO i.d.i.o.RemoteTaskRunner [Curator-PathChildrenCache-1] Worker[10.240.0.4:8091] completed task[index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf] with status[FAILED]
2018-08-13 14:24:41,629 INFO i.d.i.o.RemoteTaskRunner [Curator-PathChildrenCache-1] Worker[10.240.0.4:8091] wrote FAILED status for task [index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf] on [TaskLocation{host='10.240.0.4', port=8102, tlsPort=-1}]
2018-08-13 14:24:41,435 INFO i.d.i.o.RemoteTaskRunner [TaskQueue-Manager] Sent shutdown message to worker: 10.240.0.4:8091, status 200 OK, response: {"task":"index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf"}
2018-08-13 14:24:41,408 WARN i.d.i.k.s.KafkaSupervisor [KafkaSupervisor-sqltrace-minute] Task [index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf] failed to return start time, killing task
2018-08-13 14:24:41,395 INFO i.d.i.k.s.KafkaSupervisor [KafkaSupervisor-sqltrace-minute] {id='sqltrace-minute', generationTime=2018-08-13T14:24:41.395Z, payload={dataSource='sqltrace-minute', topic='sqltraces', partitions=1, replicas=2, durationSeconds=43200, active=[{id='index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf', startTime=null, remainingSeconds=null}, {id='index_kafka_sqltrace-minute_ceadf276f5e05e5_khmmcjjo', startTime=2018-08-13T05:51:52.618Z, remainingSeconds=12431}], publishing=[]}}
2018-08-13 14:24:41,392 INFO i.d.i.o.RemoteTaskRunner [TaskQueue-Manager] Sent shutdown message to worker: 10.240.0.4:8091, status 200 OK, response: {"task":"index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf"}
2018-08-13 14:24:41,388 INFO i.d.i.o.TaskQueue [KafkaSupervisor-sqltrace-minute] Task done: KafkaIndexTask{id=index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf, type=index_kafka, dataSource=sqltrace-minute}
2018-08-13 14:24:41,378 INFO i.d.i.o.MetadataTaskStorage [KafkaSupervisor-sqltrace-minute] Updating task index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf to status: TaskStatus{id=index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf, status=FAILED, duration=-1}
2018-08-13 14:24:41,375 INFO i.d.i.o.TaskLockbox [KafkaSupervisor-sqltrace-minute] Removing task[index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf] from activeTasks
2018-08-13 14:24:41,375 INFO i.d.i.o.RemoteTaskRunner [KafkaSupervisor-sqltrace-minute] Sent shutdown message to worker: 10.240.0.4:8091, status 200 OK, response: {"task":"index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf"}
2018-08-13 14:24:41,372 WARN i.d.i.k.s.KafkaSupervisor [KafkaSupervisor-sqltrace-minute] Task [index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf] failed to return start time, killing task
2018-08-13 14:24:41,372 WARN i.d.i.k.KafkaIndexTaskClient [KafkaIndexTaskClient-sqltrace-minute-1] Retries exhausted for [http://10.240.0.4:8102/druid/worker/v1/chat/index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf/time/start], last exception:
java.net.ConnectException: Connection refused (Connection refused)
	at java.net.PlainSocketImpl.socketConnect(Native Method) ~[?:1.8.0_181]
	at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350) ~[?:1.8.0_181]
	at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206) ~[?:1.8.0_181]
	at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188) ~[?:1.8.0_181]
	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[?:1.8.0_181]
	at java.net.Socket.connect(Socket.java:589) ~[?:1.8.0_181]
	at java.net.Socket.connect(Socket.java:538) ~[?:1.8.0_181]
	at java.net.Socket.<init>(Socket.java:434) ~[?:1.8.0_181]
	at java.net.Socket.<init>(Socket.java:211) ~[?:1.8.0_181]
	at io.druid.indexing.kafka.KafkaIndexTaskClient.checkConnection(KafkaIndexTaskClient.java:484) ~[druid-kafka-indexing-service-0.12.1.jar:0.12.1]
	at io.druid.indexing.kafka.KafkaIndexTaskClient.submitRequest(KafkaIndexTaskClient.java:532) [druid-kafka-indexing-service-0.12.1.jar:0.12.1]
	at io.druid.indexing.kafka.KafkaIndexTaskClient.submitRequest(KafkaIndexTaskClient.java:489) [druid-kafka-indexing-service-0.12.1.jar:0.12.1]
	at io.druid.indexing.kafka.KafkaIndexTaskClient.getStartTime(KafkaIndexTaskClient.java:244) [druid-kafka-indexing-service-0.12.1.jar:0.12.1]
	at io.druid.indexing.kafka.KafkaIndexTaskClient$9.call(KafkaIndexTaskClient.java:417) [druid-kafka-indexing-service-0.12.1.jar:0.12.1]
	at io.druid.indexing.kafka.KafkaIndexTaskClient$9.call(KafkaIndexTaskClient.java:413) [druid-kafka-indexing-service-0.12.1.jar:0.12.1]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_181]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_181]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_181]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_181]
2018-08-13 14:24:22,336 INFO i.d.i.k.KafkaIndexTaskClient [KafkaIndexTaskClient-sqltrace-minute-0] submitRequest failed for [http://10.240.0.4:8102/druid/worker/v1/chat/index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf/offsets/current], with message [Connection refused (Connection refused)]
2018-08-13 14:23:52,336 INFO i.d.i.k.KafkaIndexTaskClient [KafkaIndexTaskClient-sqltrace-minute-0] submitRequest failed for [http://10.240.0.4:8102/druid/worker/v1/chat/index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf/offsets/current], with message [Connection refused (Connection refused)]
2018-08-13 14:23:34,813 INFO i.d.i.o.TaskRunnerUtils [Curator-PathChildrenCache-1] Task [index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf] location changed to [TaskLocation{host='10.240.0.4', port=8102, tlsPort=-1}].
2018-08-13 14:23:34,813 INFO i.d.i.o.RemoteTaskRunner [Curator-PathChildrenCache-1] Worker[10.240.0.4:8091] wrote RUNNING status for task [index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf] on [TaskLocation{host='10.240.0.4', port=8102, tlsPort=-1}]
2018-08-13 14:23:34,793 INFO i.d.i.o.RemoteTaskRunner [Curator-PathChildrenCache-1] Worker[10.240.0.4:8091] wrote RUNNING status for task [index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf] on [TaskLocation{host='null', port=-1, tlsPort=-1}]
2018-08-13 14:23:34,786 INFO i.d.i.o.TaskRunnerUtils [rtr-pending-tasks-runner-0] Task [index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf] status changed to [RUNNING].
2018-08-13 14:23:34,786 INFO i.d.i.o.RemoteTaskRunner [rtr-pending-tasks-runner-0] Task index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf switched from pending to running (on [10.240.0.4:8091])
2018-08-13 14:23:34,780 INFO i.d.i.o.RemoteTaskRunner [rtr-pending-tasks-runner-0] Coordinator asking Worker[10.240.0.4:8091] to add task[index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf]
2018-08-13 14:23:34,534 INFO i.d.i.k.s.KafkaSupervisor [KafkaSupervisor-sqltrace-minute] {id='sqltrace-minute', generationTime=2018-08-13T14:23:34.534Z, payload={dataSource='sqltrace-minute', topic='sqltraces', partitions=1, replicas=2, durationSeconds=43200, active=[{id='index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf', startTime=null, remainingSeconds=null}, {id='index_kafka_sqltrace-minute_ceadf276f5e05e5_khmmcjjo', startTime=2018-08-13T05:51:52.618Z, remainingSeconds=12498}], publishing=[]}}
2018-08-13 14:23:34,526 INFO i.d.i.k.KafkaIndexTaskClient [KafkaIndexTaskClient-sqltrace-minute-0] No TaskLocation available for task [index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf], this task may not have been assigned to a worker yet or may have already completed
2018-08-13 14:23:34,519 WARN i.d.i.k.s.KafkaSupervisor [KafkaIndexTaskClient-sqltrace-minute-0] Ignoring task [index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf], as probably it is not started running yet
2018-08-13 14:23:34,519 INFO i.d.i.k.KafkaIndexTaskClient [KafkaIndexTaskClient-sqltrace-minute-0] No TaskLocation available for task [index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf], this task may not have been assigned to a worker yet or may have already completed
2018-08-13 14:23:34,514 INFO i.d.i.k.KafkaIndexTaskClient [KafkaIndexTaskClient-sqltrace-minute-1] No TaskLocation available for task [index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf], this task may not have been assigned to a worker yet or may have already completed
2018-08-13 14:23:34,507 INFO i.d.i.o.RemoteTaskRunner [TaskQueue-Manager] Added pending task index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf
2018-08-13 14:23:34,507 INFO i.d.i.o.TaskQueue [TaskQueue-Manager] Asking taskRunner to run: index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf
2018-08-13 14:23:34,507 INFO i.d.i.o.TaskLockbox [KafkaSupervisor-sqltrace-minute] Adding task[index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf] to activeTasks
2018-08-13 14:23:34,498 INFO i.d.i.o.MetadataTaskStorage [KafkaSupervisor-sqltrace-minute] Inserting task index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf with status: TaskStatus{id=index_kafka_sqltrace-minute_ceadf276f5e05e5_pkllidjf, status=RUNNING, duration=-1}

[pdeva]

so i just tried increasing the size of the faulty MM instance to an absolutely absurd amount of cpus, and that seems to have done the trick.

Here is what i think is happening:

1. When the node is started, it tries to start all the KI tasks.
2. Since the tasks have been down for a while, they saturate all cpu trying to read and process data from kafka.
3. due to cpu saturation, they cannot answer to overlord's status checks.
4. since overlord's status check fails, it kills the tasks and respawns them, thus creating an endless loop.

in fact, even with the mighty powerful cpu box the status check from overlord failed a few times (but it seems to have passed before timing out completely).

the solution would be to:

1. increase overlord timeout for individual status pings to tasks (not sure if there is an existing setting for this)
2. increase the total time and number of retries before giving up.

this issue seems to be related to #6117 and #5340 for occuring in the first place. connection problems across nodes are a huge issue with druid right now.

[stale]

This issue has been marked as stale due to 280 days of inactivity. It will be closed in 2 weeks if no further activity occurs. If this issue is still relevant, please simply write any comment. Even if closed, you can still revive the issue at any time or discuss it on the dev@druid.apache.org list. Thank you for your contributions.

[stale]

This issue has been marked as stale due to 280 days of inactivity. It will be closed in 4 weeks if no further activity occurs. If this issue is still relevant, please simply write any comment. Even if closed, you can still revive the issue at any time or discuss it on the dev@druid.apache.org list. Thank you for your contributions.

[stale]

This issue has been closed due to lack of activity. If you think that is incorrect, or the issue requires additional review, you can revive the issue at any time.