Druid: Kafka indexing tasks occasionally fail with 'Stream closed'
Hi all,
I seeing sometimes failed Kafka indexing tasks, the task log look quite empty (~180 lines) - ends with this -
2018-02-05T03:32:28,045 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.query.search.search.SearchQueryConfig] from props[druid.query.search.] as [io.druid.query.search.search.SearchQueryConfig@7c3e4b1a]
2018-02-05T03:32:28,048 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.query.metadata.SegmentMetadataQueryConfig] from props[druid.query.segmentMetadata.] as [io.druid.query.metadata.SegmentMetadataQueryConfig@41a374be]
2018-02-05T03:32:28,052 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.query.groupby.GroupByQueryConfig] from props[druid.query.groupBy.] as [io.druid.query.groupby.GroupByQueryConfig@5f96f6a2]
2018-02-05T03:32:28,071 INFO [main] io.druid.offheap.OffheapBufferGenerator - Allocating new intermediate processing buffer[0] of size[536,870,912]
2018-02-05T03:32:41,994 INFO [main] io.druid.offheap.OffheapBufferGenerator - Allocating new intermediate processing buffer[1] of size[536,870,912]
2018-02-05T03:32:56,979 INFO [main] io.druid.offheap.OffheapBufferGenerator - Allocating new result merging buffer[0] of size[536,870,912]
2018-02-05T03:33:12,481 INFO [main] io.druid.offheap.OffheapBufferGenerator - Allocating new result merging buffer[1] of size[536,870,912]
Looking at the middle manager, I see this exception -
2018-02-05T03:32:20,956 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Submitting runnable for task[index_kafka_player-events-realtime_f99c5d8777e2890_igkdbboa]
2018-02-05T03:32:20,960 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Affirmative. Running task [index_kafka_player-events-realtime_f99c5d8777e2890_igkdbboa]
2018-02-05T03:32:20,963 INFO [forking-task-runner-3] io.druid.indexing.overlord.ForkingTaskRunner - Running command: java -cp /opt/kava/conf/druid/_common:/opt/kava/conf/druid/middleManager:lib/jetty-continuation-9.3.16.v20170120.jar:lib/druid-aws-common-0.10.0.jar:lib/java-xmlbuilder-1.1.jar:lib/...
2018-02-05T03:32:20,965 INFO [forking-task-runner-3] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_player-events-realtime_f99c5d8777e2890_igkdbboa] location changed to [TaskLocation{host='ip-x-y-z-w.node.us-west-2.consul', port=8102}].
2018-02-05T03:32:20,965 INFO [forking-task-runner-3] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_player-events-realtime_f99c5d8777e2890_igkdbboa] status changed to [RUNNING].
2018-02-05T03:32:20,965 INFO [forking-task-runner-3] io.druid.indexing.overlord.ForkingTaskRunner - Logging task index_kafka_player-events-realtime_f99c5d8777e2890_igkdbboa output to: var/druid/task/index_kafka_player-events-realtime_f99c5d8777e2890_igkdbboa/log
2018-02-05T03:32:20,965 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Updating task [index_kafka_player-events-realtime_f99c5d8777e2890_igkdbboa] announcement with location [TaskLocation{host='ip-x-y-z-w.node.us-west-2.consul', port=8102}]
2018-02-05T03:33:14,778 INFO [HttpPostEmitter-1-0] com.metamx.http.client.pool.ChannelResourceFactory - Generating: http://json-push.service.us-west-2.consul:7000
2018-02-05T03:33:27,265 INFO [qtp81907268-47] io.druid.indexing.overlord.ForkingTaskRunner - Killing process for task: index_kafka_player-events-realtime_f99c5d8777e2890_igkdbboa
2018-02-05T03:33:27,286 INFO [qtp81907268-44] io.druid.indexing.overlord.ForkingTaskRunner - Killing process for task: index_kafka_player-events-realtime_f99c5d8777e2890_igkdbboa
2018-02-05T03:33:27,332 INFO [qtp81907268-57] io.druid.indexing.overlord.ForkingTaskRunner - Killing process for task: index_kafka_player-events-realtime_f99c5d8777e2890_igkdbboa
2018-02-05T03:33:27,466 INFO [forking-task-runner-3] io.druid.storage.s3.S3TaskLogs - Pushing task log var/druid/task/index_kafka_player-events-realtime_f99c5d8777e2890_igkdbboa/log to: druid/indexing-logs/index_kafka_player-events-realtime_f99c5d8777e2890_igkdbboa/log
2018-02-05T03:33:27,567 INFO [forking-task-runner-3] io.druid.indexing.overlord.ForkingTaskRunner - Exception caught during execution
java.io.IOException: Stream closed
at java.io.BufferedInputStream.getBufIfOpen(BufferedInputStream.java:170) ~[?:1.8.0_131]
at java.io.BufferedInputStream.read1(BufferedInputStream.java:291) ~[?:1.8.0_131]
at java.io.BufferedInputStream.read(BufferedInputStream.java:345) ~[?:1.8.0_131]
at java.io.FilterInputStream.read(FilterInputStream.java:107) ~[?:1.8.0_131]
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:438) [druid-indexing-service-0.10.0.jar:0.10.0]
at io.druid.indexing.overlord.ForkingTaskRunner$1.call(ForkingTaskRunner.java:220) [druid-indexing-service-0.10.0.jar:0.10.0]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_131]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_131]
2018-02-05T03:33:27,568 INFO [forking-task-runner-3] io.druid.indexing.overlord.ForkingTaskRunner - Removing task directory: var/druid/task/index_kafka_player-events-realtime_f99c5d8777e2890_igkdbboa
2018-02-05T03:33:27,572 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Job's finished. Completed [index_kafka_player-events-realtime_f99c5d8777e2890_igkdbboa] with status [FAILED]
I saw this exception was reported in https://github.com/druid-io/druid/issues/3054, but this seems to be different, as here it's sporadic. I'm mainly concerned about whether I may be losing events when it happens. If the code just spawns another task that continues from the same position, then I guess it can be ignored...
Thanks!
Eran
erankor
All 19 comments
Btw, I'm using druid-0.10.0
erankor
on 5 Feb 2018
Most probably the task got killed by overlord, check overlord logs and search for the task id. On a side note, Kafka Indexing Service is constantly being improved upon and a more stable version of which will land in 0.12.0 release.
pjain1
on 8 Feb 2018
Thanks @pjain1, unfortunately, I don't currently have these logs (few days passed...), I will make sure to check it next time it happens.
erankor
on 8 Feb 2018
@pjain1, got a few more failed tasks, I'm not sure if it's exactly the same as the first one, but I'm seeing these warnings/errors on the overlord -
2018-02-09T15:00:23,603 WARN [qtp1120043781-71] io.druid.java.util.common.RetryUtils - Failed on try 4, retrying in 8,149ms.
org.skife.jdbi.v2.exceptions.CallbackFailedException: org.skife.jdbi.v2.exceptions.UnableToExecuteStatementException: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Duplicate entry 'player-events-realtime_2018-02-09T15:00:00.000Z_2018-02-09T16:00' for key 'PRIMARY' [statement:"INSERT INTO druid_pendingSegments (id, dataSource, created_date, start, `end`, sequence_name, sequence_prev_id, sequence_name_prev_id_sha1, payload) VALUES (:id, :dataSource, :created_date, :start, :end, :sequence_name, :sequence_prev_id, :sequence_name_prev_id_sha1, :payload)", located:"INSERT INTO druid_pendingSegments (id, dataSource, created_date, start, `end`, sequence_name, sequence_prev_id, sequence_name_prev_id_sha1, payload) VALUES (:id, :dataSource, :created_date, :start, :end, :sequence_name, :sequence_prev_id, :sequence_name_prev_id_sha1, :payload)", rewritten:"INSERT INTO druid_pendingSegments (id, dataSource, created_date, start, `end`, sequence_name, sequence_prev_id, sequence_name_prev_id_sha1, payload) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?)", arguments:{ positional:{}, named:{sequence_prev_id:'player-events-realtime_2018-02-09T14:00:00.000Z_2018-02-09T15:00:00.000Z_2018-02-09T13:59:55.530Z_48',payload:[123, 34, 100, 97, 116, 97, 83, 111, 117, 114, 99, 101, 34, 58, 34, 112, 108, 97, 121, 101, 114, 45, 101, 118, 101, 110, 116, 115, 45, 114, 101, 97, 108, 116, 105, 109, 101, 34, 44, 34, 105, 110, 116, 101, 114, 118, 97, 108, 34, 58, 34, 50, 48, 49, 56, 45, 48, 50, 45, 48, 57, 84, 49, 53, 58, 48, 48, 58, 48, 48, 46, 48, 48, 48, 90, 47, 50, 48, 49, 56, 45, 48, 50, 45, 48, 57, 84, 49, 54, 58, 48, 48, 58, 48, 48, 46, 48, 48, 48, 90, 34, 44, 34, 118, 101, 114, 115, 105, 111, 110, 34, 58, 34, 50, 48, 49, 56, 45, 48, 50, 45, 48, 57, 84, 49, 52, 58, 53, 57, 58, 53, 54, 46, 51, 50, 56, 90, 34, 44, 34, 115, 104, 97, 114, 100, 83, 112, 101, 99, 34, 58, 123, 34, 116, 121, 112, 101, 34, 58, 34, 110, 117, 109, 98, 101, 114, 101, 100, 34, 44, 34, 112, 97, 114, 116, 105, 116, 105, 111, 110, 78, 117, 109, 34, 58, 52, 4
4, 34, 112, 97, 114, 116, 105, 116, 105, 111, 110, 115, 34, 58, 48, 125, 125],start:'2018-02-09T15:00:00.000Z',end:'2018-02-09T16:00:00.000Z',id:'player-events-realtime_2018-02-09T15:00:00.000Z_2018-02-09T16:00:00.000Z_2018-02-09T14:59:56.328Z_4',created_date:'2018-02-09T15:00:23.596Z',dataSource:'player-events-realtime',sequence_name:'index_kafka_player-events-realtime_440403813632ad2_4',sequence_name_prev_id_sha1:'EBB6811BF3BF43A785EF99106E7B3AA1DE272AA9'}, finder:[]}]
2018-02-09T15:01:07,983 ERROR [KafkaIndexTaskClient-player-events-historical-0] io.druid.indexing.kafka.KafkaIndexTaskClient - Task [index_kafka_player-events-historical_230f6eabcaa661a_gogiiikl] failed to pause, aborting
2018-02-09T15:01:07,984 WARN
[KafkaSupervisor-player-events-historical-Worker-3] io.druid.indexing.kafka.supervisor.KafkaSupervisor - Task [index_kafka_player-events-historical_230f6eabcaa661a_gogiiikl] failed to respond to [pause] in a timely manner, killing task
Looks like the integrity constraint violation happens quite often, don't know if this is expected -
$ journalctl -u druid_* -S -864000 | grep UnableToExecuteStatementException | grep 'Duplicate entry' | awk '{print $1" "$2" "$3}' | uniq -c
2 Feb 11 03:00:32
2 Feb 11 03:00:35
2 Feb 11 03:00:38
2 Feb 11 03:00:47
2 Feb 11 03:00:59
2 Feb 11 04:00:23
3 Feb 11 04:00:24
2 Feb 11 04:00:44
2 Feb 11 04:00:52
2 Feb 11 05:00:22
4 Feb 11 05:00:23
6 Feb 11 05:00:24
2 Feb 11 05:00:33
2 Feb 11 05:00:34
2 Feb 11 05:00:36
2 Feb 11 05:00:45
2 Feb 11 05:00:49
2 Feb 11 06:00:24
3 Feb 11 06:00:26
4 Feb 11 07:00:23
1 Feb 11 07:00:24
2 Feb 11 07:00:47
2 Feb 11 07:00:53
2 Feb 11 08:00:21
2 Feb 11 08:00:22
8 Feb 11 08:00:24
2 Feb 11 08:00:30
2 Feb 11 08:00:58
Full log - kafkaIssue.log
Thanks!
Eran
erankor
on 11 Feb 2018
I don't think integrity constraint violation is the problem, the problem is failed to respond to [pause] in a timely manner, killing task. So, I would check the task logs around this time to figure out why it did not pause, what was the task doing ? Or I would just wait and upgrade druid to 0.12.0 once it is out and see if the problem still persists.
pjain1
on 12 Feb 2018
I am using druid version .12.0, I am getting this same error, here is the error log from middle-manager,
2018-04-18T09:45:10,159 INFO [forking-task-runner-2] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_test1_4454ee7eece418b_ficeeefj] location changed to [TaskLocation{host='ubuntu16.04', port=8100, tlsPort=-1}].
2018-04-18T09:45:10,159 INFO [forking-task-runner-2] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_test1_4454ee7eece418b_ficeeefj] status changed to [RUNNING].
2018-04-18T09:45:10,159 INFO [forking-task-runner-2] io.druid.indexing.overlord.ForkingTaskRunner - Logging task index_kafka_test1_4454ee7eece418b_ficeeefj output to: var/druid/task/index_kafka_test1_4454ee7eece418b_ficeeefj/log
2018-04-18T09:45:10,159 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Updating task [index_kafka_test1_4454ee7eece418b_ficeeefj] announcement with location [TaskLocation{host='ubuntu16.04', port=8100, tlsPort=-1}]
2018-04-18T09:45:15,161 INFO [qtp1733903473-26] io.druid.indexing.overlord.ForkingTaskRunner - Killing process for task: index_kafka_test1_4454ee7eece418b_ficeeefj
2018-04-18T09:45:15,162 INFO [forking-task-runner-2] io.druid.indexing.common.tasklogs.FileTaskLogs - Wrote task log to: var/druid/indexing-logs/index_kafka_test1_4454ee7eece418b_ficeeefj.log
2018-04-18T09:45:15,163 INFO [forking-task-runner-2] io.druid.indexing.overlord.ForkingTaskRunner - Exception caught during execution
java.io.IOException: Stream closed
at java.io.BufferedInputStream.getBufIfOpen(BufferedInputStream.java:170) ~[?:1.8.0_161]
at java.io.BufferedInputStream.read1(BufferedInputStream.java:291) ~[?:1.8.0_161]
at java.io.BufferedInputStream.read(BufferedInputStream.java:345) ~[?:1.8.0_161]
at java.io.FilterInputStream.read(FilterInputStream.java:107) ~[?:1.8.0_161]
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.0.jar:0.12.0]
at io.druid.indexing.overlord.ForkingTaskRunner$1.call(ForkingTaskRunner.java:224) [druid-indexing-service-0.12.0.jar:0.12.0]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_161]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_161]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_161]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]
2018-04-18T09:45:15,165 INFO [forking-task-runner-2] io.druid.indexing.overlord.ForkingTaskRunner - Removing task directory: var/druid/task/index_kafka_test1_4454ee7eece418b_ficeeefj
2018-04-18T09:45:15,166 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Job's finished. Completed [index_kafka_test1_4454ee7eece418b_ficeeefj] with status [FAILED]
sohelsarder
on 18 Apr 2018
I am also using druid version .12.0 and I am getting this same error!
guybiecher
on 13 Jun 2018
Using Druid 0.12.0 and the problem still persists.
2018-06-18T12:56:37,107 ERROR [qtp1954133542-83]
io.druid.indexing.common.actions.SegmentAllocateAction - Could not allocate pending segment for rowInterval[2018-06-13T08:13:30.000Z/2018-06-13T08:13:30.001Z], segmentInterval[2018-06-13T08:00:00.000Z/2018-06-13T09:00:00.000Z].
2018-06-18T12:56:37,646 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskQueue - Task FAILED: KafkaIndexTask{id=index_kafka_sessions_dc85485a4576518_eckhgpcl, type=index_kafka, dataSource=sessions} (38028 run duration)
2018-06-18T12:56:37,646 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_sessions_dc85485a4576518_eckhgpcl] status changed to [FAILED].
2018-06-18T12:57:14,137 INFO [KafkaSupervisor-sessions] io.druid.indexing.overlord.RemoteTaskRunner - Sent shutdown message to worker: 0.0.0.0:8091, status 200 OK, response: {"task":"index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg"}
2018-06-18T12:57:14,137 INFO [KafkaSupervisor-sessions] io.druid.indexing.overlord.TaskLockbox - Removing task[index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg] from activeTasks
The Middle Manager logs is just strikingly similar:
2018-06-18T12:57:14,098 INFO [qtp2011636843-19] io.druid.indexing.overlord.ForkingTaskRunner - Killing process for task: index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg
2018-06-18T12:57:14,099 INFO [forking-task-runner-1] io.druid.indexing.common.tasklogs.FileTaskLogs - Wrote task log to: var/druid/indexing-logs/index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg.log
2018-06-18T12:57:14,099 INFO [forking-task-runner-1] io.druid.indexing.overlord.ForkingTaskRunner - Exception caught during execution
java.io.IOException: Stream closed
at java.io.BufferedInputStream.getBufIfOpen(BufferedInputStream.java:170) ~[?:1.8.0_161]
at java.io.BufferedInputStream.read1(BufferedInputStream.java:291) ~[?:1.8.0_161]
at java.io.BufferedInputStream.read(BufferedInputStream.java:345) ~[?:1.8.0_161]
at java.io.FilterInputStream.read(FilterInputStream.java:107) ~[?:1.8.0_161]
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.0.jar:0.12.0]
at io.druid.indexing.overlord.ForkingTaskRunner$1.call(ForkingTaskRunner.java:224) [druid-indexing-service-0.12.0.jar:0.12.0]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_161]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_161]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_161]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]
2018-06-18T12:57:14,109 INFO [forking-task-runner-1] io.druid.indexing.overlord.ForkingTaskRunner - Removing task directory: var/druid/task/index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg
2018-06-18T12:57:14,116 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Job's finished. Completed [index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg] with status [FAILED]
suhassumukh
on 26 Jun 2018
Hi guys,
if the Kafka indexing tasks failed with 'Stream closed', it means that those tasks were killed by overlords. So, we need to figure out why overlords killed those tasks. Would you post your overlord logs as well as the failed kafka task logs? The overlord logs should contain the logs written at the time when the kafka tasks failed.
jihoonson
on 27 Jun 2018
@jihoonson
Hey,
This issue happens sporadically. Thus, difficult to reproduce. Also, I don't possess the entire logs when this occurred. Below, I've added Middle Manager and Overlord logs.
Overlord:
2018-06-18T12:55:59,426 INFO [KafkaSupervisor-sessions] io.druid.indexing.kafka.supervisor.KafkaSupervisor - Number of tasks [0] does not match configured numReplicas [1] in task group [0], creating more tasks
2018-06-18T12:55:59,441 INFO [KafkaSupervisor-sessions] io.druid.indexing.overlord.MetadataTaskStorage - Inserting task index_kafka_sessions_dc85485a4576518_eckhgpcl with status: TaskStatus{id=index_kafka_sessions_dc85485a4576518_eckhgpcl, status=RUNNING, duration=-1}
2018-06-18T12:55:59,484 INFO [KafkaSupervisor-sessions] io.druid.indexing.overlord.TaskLockbox - Adding task[index_kafka_sessions_dc85485a4576518_eckhgpcl] to activeTasks
2018-06-18T12:55:59,485 INFO [TaskQueue-Manager] io.druid.indexing.overlord.TaskQueue - Asking taskRunner to run: index_kafka_sessions_dc85485a4576518_eckhgpcl
2018-06-18T12:55:59,485 INFO [TaskQueue-Manager] io.druid.indexing.overlord.RemoteTaskRunner - Added pending task index_kafka_sessions_dc85485a4576518_eckhgpcl
2018-06-18T12:55:59,503 INFO [rtr-pending-tasks-runner-0] io.druid.indexing.overlord.RemoteTaskRunner - Coordinator asking Worker[0.0.0.0:8091] to add task[index_kafka_sessions_dc85485a4576518_eckhgpcl]
2018-06-18T12:55:59,509 INFO [KafkaSupervisor-sessions] io.druid.indexing.kafka.supervisor.KafkaSupervisor - {id='sessions', generationTime=2018-06-18T12:55:59.507Z, payload={dataSource='sessions', topic='sessionstopic', partitions=1, replicas=1, durationSeconds=3600, active=[], publishing=[]}}
2018-06-18T12:55:59,522 INFO [rtr-pending-tasks-runner-0] io.druid.indexing.overlord.RemoteTaskRunner - Task index_kafka_sessions_dc85485a4576518_eckhgpcl switched from pending to running (on [0.0.0.0:8091])
2018-06-18T12:55:59,523 INFO [rtr-pending-tasks-runner-0] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_sessions_dc85485a4576518_eckhgpcl] status changed to [RUNNING].
2018-06-18T12:55:59,532 INFO [KafkaIndexTaskClient-sessions-0] io.druid.indexing.kafka.KafkaIndexTaskClient - No TaskLocation available for task [index_kafka_sessions_dc85485a4576518_eckhgpcl], this task may not have been assigned to a worker yet or may have already completed
2018-06-18T12:55:59,544 INFO [KafkaIndexTaskClient-sessions-0] io.druid.indexing.kafka.KafkaIndexTaskClient - No TaskLocation available for task [index_kafka_sessions_dc85485a4576518_eckhgpcl], this task may not have been assigned to a worker yet or may have already completed
2018-06-18T12:55:59,545 WARN [KafkaIndexTaskClient-sessions-0] io.druid.indexing.kafka.supervisor.KafkaSupervisor - Ignoring task [index_kafka_sessions_dc85485a4576518_eckhgpcl], as probably it is not started running yet
2018-06-18T12:55:59,559 INFO [KafkaIndexTaskClient-sessions-0] io.druid.indexing.kafka.KafkaIndexTaskClient - No TaskLocation available for task [index_kafka_sessions_dc85485a4576518_eckhgpcl], this task may not have been assigned to a worker yet or may have already completed
2018-06-18T12:55:59,565 INFO [KafkaSupervisor-sessions] io.druid.indexing.kafka.supervisor.KafkaSupervisor - {id='sessions', generationTime=2018-06-18T12:55:59.564Z, payload={dataSource='sessions', topic='sessionstopic', partitions=1, replicas=1, durationSeconds=3600, active=[{id='index_kafka_sessions_dc85485a4576518_eckhgpcl', startTime=null, remainingSeconds=null}], publishing=[]}}
2018-06-18T12:55:59,571 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Worker[0.0.0.0:8091] wrote RUNNING status for task [index_kafka_sessions_dc85485a4576518_eckhgpcl] on [TaskLocation{host='null', port=-1, tlsPort=-1}]
2018-06-18T12:55:59,695 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Worker[0.0.0.0:8091] wrote RUNNING status for task [index_kafka_sessions_dc85485a4576518_eckhgpcl] on [TaskLocation{host='0.0.0.0', port=8100, tlsPort=-1}]
2018-06-18T12:55:59,695 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_sessions_dc85485a4576518_eckhgpcl] location changed to [TaskLocation{host='0.0.0.0', port=8100, tlsPort=-1}].
2018-06-18T12:56:06,498 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,531 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,531 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,531 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,532 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,532 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,532 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,532 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,532 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,532 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,532 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,535 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,535 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,535 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,536 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,536 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,536 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,536 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,537 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,537 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:56:06,693 INFO [KafkaSupervisor-sessions] io.druid.indexing.kafka.supervisor.KafkaSupervisor - {id='sessions', generationTime=2018-06-18T12:56:06.693Z, payload={dataSource='sessions', topic='sessionstopic', partitions=1, replicas=1, durationSeconds=3600, active=[{id='index_kafka_sessions_dc85485a4576518_eckhgpcl', startTime=2018-06-18T12:56:05.118Z, remainingSeconds=3598}], publishing=[]}}
2018-06-18T12:56:06,785 INFO [KafkaSupervisor-sessions] io.druid.indexing.kafka.supervisor.KafkaSupervisor - {id='sessions', generationTime=2018-06-18T12:56:06.785Z, payload={dataSource='sessions', topic='sessionstopic', partitions=1, replicas=1, durationSeconds=3600, active=[{id='index_kafka_sessions_dc85485a4576518_eckhgpcl', startTime=2018-06-18T12:56:05.118Z, remainingSeconds=3598}], publishing=[]}}
2018-06-18T12:56:31,778 WARN [KafkaSupervisor-sessions-Reporting-0] io.druid.java.util.emitter.core.LoggingEmitter - Event [{"feed":"metrics","timestamp":"2018-06-18T12:56:31.778Z","service":"druid/overlord","host":"0.0.0.0:8090","version":"0.12.0","metric":"ingest/kafka/lag","value":0,"dataSource":"sessions"}]
2018-06-18T12:56:36,785 INFO [KafkaSupervisor-sessions] io.druid.indexing.kafka.supervisor.KafkaSupervisor - {id='sessions', generationTime=2018-06-18T12:56:36.785Z, payload={dataSource='sessions', topic='sessionstopic', partitions=1, replicas=1, durationSeconds=3600, active=[{id='index_kafka_sessions_dc85485a4576518_eckhgpcl', startTime=2018-06-18T12:56:05.118Z, remainingSeconds=3568}], publishing=[]}}
2018-06-18T12:56:37,046 INFO [qtp1954133542-83] io.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_kafka_sessions_dc85485a4576518_eckhgpcl]: SegmentAllocateAction{dataSource='sessions', timestamp=2018-06-13T08:13:30.000Z, queryGranularity=NoneGranularity, preferredSegmentGranularity={type=period, period=PT1H, timeZone=UTC, origin=null}, sequenceName='index_kafka_sessions_dc85485a4576518_0', previousSegmentId='null', skipSegmentLineageCheck='true'}
2018-06-18T12:56:37,093 INFO [qtp1954133542-83] io.druid.indexing.overlord.TaskLockbox - Added task[index_kafka_sessions_dc85485a4576518_eckhgpcl] to TaskLock[index_kafka_sessions]
2018-06-18T12:56:37,093 INFO [qtp1954133542-83] io.druid.indexing.overlord.MetadataTaskStorage - Adding lock on interval[2018-06-13T08:00:00.000Z/2018-06-13T09:00:00.000Z] version[2018-06-18T12:56:37.092Z] for task: index_kafka_sessions_dc85485a4576518_eckhgpcl
2018-06-18T12:56:37,105 WARN [qtp1954133542-83] io.druid.metadata.IndexerSQLMetadataStorageCoordinator - Cannot allocate new segment for dataSource[sessions], interval[2018-06-13T08:00:00.000Z/2018-06-13T09:00:00.000Z], maxVersion[2018-06-18T12:56:37.092Z]: ShardSpec class[class io.druid.timeline.partition.NoneShardSpec] used by [sessions_2018-06-13T08:00:00.000Z_2018-06-13T09:00:00.000Z_2018-06-18T08:06:21.708Z].
2018-06-18T12:56:37,107 ERROR [qtp1954133542-83] io.druid.indexing.common.actions.SegmentAllocateAction - Could not allocate pending segment for rowInterval[2018-06-13T08:13:30.000Z/2018-06-13T08:13:30.001Z], segmentInterval[2018-06-13T08:00:00.000Z/2018-06-13T09:00:00.000Z].
2018-06-18T12:56:37,622 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Worker[0.0.0.0:8091] wrote FAILED status for task [index_kafka_sessions_dc85485a4576518_eckhgpcl] on [TaskLocation{host='0.0.0.0', port=8100, tlsPort=-1}]
2018-06-18T12:56:37,622 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Worker[0.0.0.0:8091] completed task[index_kafka_sessions_dc85485a4576518_eckhgpcl] with status[FAILED]
2018-06-18T12:56:37,623 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskQueue - Received FAILED status for task: index_kafka_sessions_dc85485a4576518_eckhgpcl
2018-06-18T12:56:37,623 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Cleaning up task[index_kafka_sessions_dc85485a4576518_eckhgpcl] on worker[0.0.0.0:8091]
2018-06-18T12:56:37,626 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskLockbox - Removing task[index_kafka_sessions_dc85485a4576518_eckhgpcl] from activeTasks
2018-06-18T12:56:37,628 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskLockbox - Removing task[index_kafka_sessions_dc85485a4576518_eckhgpcl] from TaskLock[index_kafka_sessions]
2018-06-18T12:56:37,628 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskLockbox - TaskLock is now empty: TaskLock{type=EXCLUSIVE, groupId=index_kafka_sessions, dataSource=sessions, interval=2018-06-13T08:00:00.000Z/2018-06-13T09:00:00.000Z, version=2018-06-18T12:56:37.092Z, priority=75, revoked=false}
2018-06-18T12:56:37,639 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.MetadataTaskStorage - Deleting TaskLock with id[7492]: TaskLock{type=EXCLUSIVE, groupId=index_kafka_sessions, dataSource=sessions, interval=2018-06-13T08:00:00.000Z/2018-06-13T09:00:00.000Z, version=2018-06-18T12:56:37.092Z, priority=75, revoked=false}
2018-06-18T12:56:37,643 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.MetadataTaskStorage - Updating task index_kafka_sessions_dc85485a4576518_eckhgpcl to status: TaskStatus{id=index_kafka_sessions_dc85485a4576518_eckhgpcl, status=FAILED, duration=38028}
2018-06-18T12:56:37,645 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskQueue - Task done: KafkaIndexTask{id=index_kafka_sessions_dc85485a4576518_eckhgpcl, type=index_kafka, dataSource=sessions}
2018-06-18T12:56:37,646 WARN [Curator-PathChildrenCache-1] io.druid.java.util.emitter.core.LoggingEmitter - Event [{"feed":"metrics","timestamp":"2018-06-18T12:56:37.645Z","service":"druid/overlord","host":"0.0.0.0:8090","version":"0.12.0","metric":"task/run/time","value":38028,"dataSource":"sessions","taskStatus":"FAILED","taskType":"index_kafka"}]
2018-06-18T12:56:37,646 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskQueue - Task FAILED: KafkaIndexTask{id=index_kafka_sessions_dc85485a4576518_eckhgpcl, type=index_kafka, dataSource=sessions} (38028 run duration)
2018-06-18T12:56:37,646 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_sessions_dc85485a4576518_eckhgpcl] status changed to [FAILED].
2018-06-18T12:56:37,646 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Task[index_kafka_sessions_dc85485a4576518_eckhgpcl] went bye bye.
...
A few metrics /jvm/gc/mem/init
...
2018-06-18T12:56:44,364 WARN [MonitorScheduler-0] io.druid.java.util.emitter.core.LoggingEmitter - Event [{"feed":"metrics","timestamp":"2018-06-18T12:56:44.364Z","service":"druid/overlord","host":"0.0.0.0:8090","version":"0.12.0","metric":"jvm/gc/mem/init","value":252706824,"gcGen":["old"],"gcGenSpaceName":"sun.gc.generation.1.space.0.name: space\u0000 string [internal]","gcName":["g1"]}]
2018-06-18T12:56:45,740 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).
2018-06-18T12:57:06,787 WARN [KafkaSupervisor-sessions] io.druid.indexing.kafka.supervisor.KafkaSupervisor - Clearing task group [0] information as no valid tasks left the group
2018-06-18T12:57:06,788 INFO [KafkaSupervisor-sessions] io.druid.indexing.kafka.supervisor.KafkaSupervisor - Creating new task group [0] for partitions [0]
2018-06-18T12:57:06,789 WARN [KafkaSupervisor-sessions] io.druid.indexing.kafka.supervisor.KafkaSupervisor - Topic in metadata storage [topic_sessions] doesn't match spec topic [sessionstopic], ignoring stored offsets
2018-06-18T12:57:06,790 INFO [KafkaSupervisor-sessions] io.druid.indexing.kafka.supervisor.KafkaSupervisor - Number of tasks [0] does not match configured numReplicas [1] in task group [0], creating more tasks
2018-06-18T12:57:06,791 INFO [KafkaSupervisor-sessions] io.druid.indexing.overlord.MetadataTaskStorage - Inserting task index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg with status: TaskStatus{id=index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg, status=RUNNING, duration=-1}
2018-06-18T12:57:06,794 INFO [KafkaSupervisor-sessions] io.druid.indexing.overlord.TaskLockbox - Adding task[index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg] to activeTasks
2018-06-18T12:57:06,794 INFO [TaskQueue-Manager] io.druid.indexing.overlord.TaskQueue - Asking taskRunner to run: index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg
2018-06-18T12:57:06,794 INFO [TaskQueue-Manager] io.druid.indexing.overlord.RemoteTaskRunner - Added pending task index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg
2018-06-18T12:57:06,795 INFO [KafkaSupervisor-sessions] io.druid.indexing.kafka.supervisor.KafkaSupervisor - {id='sessions', generationTime=2018-06-18T12:57:06.794Z, payload={dataSource='sessions', topic='sessionstopic', partitions=1, replicas=1, durationSeconds=3600, active=[], publishing=[]}}
2018-06-18T12:57:06,795 INFO [rtr-pending-tasks-runner-0] io.druid.indexing.overlord.RemoteTaskRunner - Coordinator asking Worker[0.0.0.0:8091] to add task[index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg]
2018-06-18T12:57:06,807 INFO [rtr-pending-tasks-runner-0] io.druid.indexing.overlord.RemoteTaskRunner - Task index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg switched from pending to running (on [0.0.0.0:8091])
2018-06-18T12:57:06,807 INFO [rtr-pending-tasks-runner-0] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg] status changed to [RUNNING].
2018-06-18T12:57:06,816 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Worker[0.0.0.0:8091] wrote RUNNING status for task [index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg] on [TaskLocation{host='null', port=-1, tlsPort=-1}]
2018-06-18T12:57:06,829 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Worker[0.0.0.0:8091] wrote RUNNING status for task [index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg] on [TaskLocation{host='0.0.0.0', port=8100, tlsPort=-1}]
2018-06-18T12:57:06,829 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg] location changed to [TaskLocation{host='0.0.0.0', port=8100, tlsPort=-1}].
2018-06-18T12:57:13,802 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:57:13,935 INFO [KafkaIndexTaskClient-sessions-0] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8100
2018-06-18T12:57:13,950 WARN [KafkaSupervisor-sessions] io.druid.indexing.kafka.supervisor.KafkaSupervisor - Clearing task group [0] information as no valid tasks left the group
2018-06-18T12:57:13,950 WARN [KafkaSupervisor-sessions] io.druid.indexing.kafka.supervisor.KafkaSupervisor - Killing task [index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg], as its checkpoints [{0={0=48}}] are not consistent with group checkpoints[{0={0=48}}] or latest persisted offsets in metadata store [{0=1436430}]
2018-06-18T12:57:13,950 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:13,961 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:13,963 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:13,964 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:13,964 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:13,966 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:13,967 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:13,967 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:13,967 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:13,968 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:13,968 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:13,968 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:13,970 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:13,971 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:13,971 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:13,971 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:13,971 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:13,971 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:13,972 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:13,972 INFO [KafkaSupervisor-sessions] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://0.0.0.0:8091
2018-06-18T12:57:14,117 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Worker[0.0.0.0:8091] wrote FAILED status for task [index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg] on [TaskLocation{host='0.0.0.0', port=8100, tlsPort=-1}]
2018-06-18T12:57:14,117 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Worker[0.0.0.0:8091] completed task[index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg] with status[FAILED]
2018-06-18T12:57:14,118 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskQueue - Received FAILED status for task: index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg
2018-06-18T12:57:14,137 INFO [KafkaSupervisor-sessions] io.druid.indexing.overlord.RemoteTaskRunner - Sent shutdown message to worker: 0.0.0.0:8091, status 200 OK, response: {"task":"index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg"}
2018-06-18T12:57:14,137 INFO [KafkaSupervisor-sessions] io.druid.indexing.overlord.TaskLockbox - Removing task[index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg] from activeTasks
2018-06-18T12:57:14,139 INFO [KafkaSupervisor-sessions] io.druid.indexing.overlord.MetadataTaskStorage - Updating task index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg to status: TaskStatus{id=index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg, status=FAILED, duration=-1}
2018-06-18T12:57:14,141 INFO [KafkaSupervisor-sessions] io.druid.indexing.overlord.TaskQueue - Task done: KafkaIndexTask{id=index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg, type=index_kafka, dataSource=sessions}
2018-06-18T12:57:14,141 INFO [KafkaSupervisor-sessions] io.druid.indexing.kafka.supervisor.KafkaSupervisor - Creating new task group [0] for partitions [0]
2018-06-18T12:57:14,141 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Cleaning up task[index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg] on worker[0.0.0.0:8091]
2018-06-18T12:57:14,142 WARN [KafkaSupervisor-sessions] io.druid.indexing.kafka.supervisor.KafkaSupervisor - Topic in metadata storage [topic_sessions] doesn't match spec topic [sessionstopic], ignoring stored offsets
2018-06-18T12:57:14,143 WARN [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskQueue - Unknown task completed: index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg
2018-06-18T12:57:14,143 WARN [Curator-PathChildrenCache-1] io.druid.java.util.emitter.core.LoggingEmitter - Event [{"feed":"metrics","timestamp":"2018-06-18T12:57:14.143Z","service":"druid/overlord","host":"0.0.0.0:8090","version":"0.12.0","metric":"task/run/time","value":7295,"dataSource":"sessions","taskStatus":"FAILED","taskType":"index_kafka"}]
2018-06-18T12:57:14,143 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskQueue - Task FAILED: KafkaIndexTask{id=index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg, type=index_kafka, dataSource=sessions} (7295 run duration)
2018-06-18T12:57:14,143 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg] status changed to [FAILED].
2018-06-18T12:57:14,143 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Task[index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg] went bye bye.
2018-06-18T12:57:14,144 INFO [KafkaSupervisor-sessions] io.druid.indexing.kafka.supervisor.KafkaSupervisor - Number of tasks [0] does not match configured numReplicas [1] in task group [0], creating more tasks
Middle Manager:
2018-06-18T12:55:59,541 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Submitting runnable for task[index_kafka_sessions_dc85485a4576518_eckhgpcl]
2018-06-18T12:55:59,563 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Affirmative. Running task [index_kafka_sessions_dc85485a4576518_eckhgpcl]
2018-06-18T12:55:59,650 INFO [forking-task-runner-0] io.druid.indexing.overlord.ForkingTaskRunner - Running command: java -cp conf-quickstart/druid/_common:conf-quickstart/druid/middleManager:lib/protobuf-java-3.1.0.jar:lib/commons-codec-1.7.jar:lib/jackson-core-asl-1.9.13.jar:lib/jersey-servlet-1.19.3.jar:lib/classmate-1.0.0.jar:lib/jdbi-2.63.1.jar:lib/guice-servlet-4.1.0.jar:lib/log4j-api-2.5.jar:lib/spymemcached-2.12.3.jar:lib/icu4j-54.1.1.jar:lib/druid-api-0.12.0.jar:lib/RoaringBitmap-0.5.18.jar:lib/jetty-io-9.3.19.v20170502.jar:lib/jets3t-0.9.4.jar:lib/jersey-guice-1.19.3.jar:lib/netty-3.10.6.Final.jar:lib/aether-api-0.9.0.M2.jar:lib/jackson-jq-0.0.7.jar:lib/aggdesigner-algorithm-6.0.jar:lib/jackson-jaxrs-smile-provider-2.4.6.jar:lib/netty-handler-4.0.52.Final.jar:lib/aopalliance-1.0.jar:lib/calcite-linq4j-1.15.0.jar:lib/activation-1.1.1.jar:lib/netty-transport-4.0.52.Final.jar:lib/jackson-dataformat-smile-2.4.6.jar:lib/curator-recipes-4.0.0.jar:lib/asm-5.2.jar:lib/netty-reactive-streams-1.0.8.jar:lib/asm-tree-5.2.jar:lib/zookeeper-3.4.10.jar:lib/commons-lang3-3.2.jar:lib/jersey-server-1.19.3.jar:lib/jackson-annotations-2.4.6.jar:lib/jackson-datatype-joda-2.4.6.jar:lib/jetty-security-9.3.19.v20170502.jar:lib/netty-codec-4.0.52.Final.jar:lib/jboss-logging-3.1.3.GA.jar:lib/druid-sql-0.12.0.jar:lib/maven-settings-builder-3.1.1.jar:lib/slf4j-api-1.6.4.jar:lib/validation-api-1.1.0.Final.jar:lib/lz4-1.3.0.jar:lib/guice-multibindings-4.1.0.jar:lib/guice-4.1.0.jar:lib/avatica-core-1.10.0.jar:lib/commons-pool2-2.2.jar:lib/commons-dbcp-1.4.jar:lib/bcprov-jdk15on-1.52.jar:lib/aws-java-sdk-core-1.10.77.jar:lib/curator-framework-4.0.0.jar:lib/jetty-server-9.3.19.v20170502.jar:lib/commons-math3-3.6.1.jar:lib/druid-console-0.0.2.jar:lib/log4j-core-2.5.jar:lib/aether-connector-file-0.9.0.M2.jar:lib/jackson-mapper-asl-1.9.13.jar:lib/javax.servlet-api-3.1.0.jar:lib/extendedset-0.12.0.jar:lib/hibernate-validator-5.1.3.Final.jar:lib/guava-16.0.1.jar:lib/jackson-databind-2.4.6.jar:lib/jetty-servlet-9.3.19.v20170502.jar:lib/commons-dbcp2-2.0.1.jar:lib/curator-client-4.0.0.jar:lib/asm-commons-5.2.jar:lib/reactive-streams-1.0.0.jar:lib/netty-resolver-2.0.37.jar:lib/maven-settings-3.1.1.jar:lib/jetty-client-9.3.19.v20170502.jar:lib/plexus-utils-3.0.15.jar:lib/druid-services-0.12.0.jar:lib/derbynet-10.11.1.1.jar:lib/log4j-jul-2.5.jar:lib/curator-x-discovery-4.0.0.jar:lib/netty-codec-http-4.0.52.Final.jar:lib/jsr305-2.0.1.jar:lib/tesla-aether-0.0.5.jar:lib/netty-common-4.0.52.Final.jar:lib/jackson-module-jaxb-annotations-2.4.6.jar:lib/commons-compiler-2.7.6.jar:lib/rhino-1.7R5.jar:lib/aether-impl-0.9.0.M2.jar:lib/json-path-2.1.0.jar:lib/druid-indexing-service-0.12.0.jar:lib/commons-logging-1.1.1.jar:lib/janino-2.7.6.jar:lib/jsr311-api-1.1.1.jar:lib/fastutil-8.1.0.jar:lib/maven-model-3.1.1.jar:lib/httpcore-4.4.3.jar:lib/geoip2-0.4.0.jar:lib/jackson-dataformat-cbor-2.5.3.jar:lib/okhttp-1.0.2.jar:lib/avatica-metrics-1.10.0.jar:lib/jetty-util-9.3.19.v20170502.jar:lib/jetty-servlets-9.3.19.v20170502.jar:lib/avatica-server-1.10.0.jar:lib/log4j-slf4j-impl-2.5.jar:lib/maxminddb-0.2.0.jar:lib/calcite-core-1.15.0.jar:lib/jetty-continuation-9.3.19.v20170502.jar:lib/netty-all-4.0.52.Final.jar:lib/javax.el-api-3.0.0.jar:lib/jcodings-1.0.13.jar:lib/java-util-0.12.0.jar:lib/httpclient-4.5.1.jar:lib/async-http-client-2.0.37.jar:lib/mapdb-1.0.8.jar:lib/disruptor-3.3.6.jar:lib/java-xmlbuilder-1.1.jar:lib/plexus-interpolation-1.19.jar:lib/druid-indexing-hadoop-0.12.0.jar:lib/jvm-attach-api-1.2.jar:lib/druid-processing-0.12.0.jar:lib/druid-hll-0.12.0.jar:lib/base64-2.3.8.jar:lib/maven-model-builder-3.1.1.jar:lib/derbyclient-10.11.1.1.jar:lib/antlr4-runtime-4.5.1.jar:lib/airline-0.7.jar:lib/netty-transport-native-epoll-4.0.52.Final-linux-x86_64.jar:lib/druid-common-0.12.0.jar:lib/commons-lang-2.6.jar:lib/jetty-proxy-9.3.19.v20170502.jar:lib/aether-util-0.9.0.M2.jar:lib/javax.el-3.0.0.jar:lib/joni-2.1.11.jar:lib/jackson-jaxrs-base-2.4.6.jar:lib/javax.inject-1.jar:lib/wagon-provider-api-2.4.jar:lib/jcl-over-slf4j-1.7.12.jar:lib/jetty-http-9.3.19.v20170502.jar:lib/config-magic-0.9.jar:lib/maven-aether-provider-3.1.1.jar:lib/aws-java-sdk-ec2-1.10.77.jar:lib/maven-repository-metadata-3.1.1.jar:lib/caffeine-2.5.5.jar:lib/esri-geometry-api-2.0.0.jar:lib/commons-cli-1.2.jar:lib/druid-aws-common-0.12.0.jar:lib/log4j-1.2-api-2.5.jar:lib/derby-10.11.1.1.jar:lib/aether-connector-okhttp-0.0.9.jar:lib/jline-0.9.94.jar:lib/jackson-core-2.4.6.jar:lib/druid-server-0.12.0.jar:lib/commons-pool-1.6.jar:lib/irc-api-1.0-0014.jar:lib/jackson-jaxrs-json-provider-2.4.6.jar:lib/jackson-datatype-guava-2.4.6.jar:lib/async-http-client-netty-utils-2.0.37.jar:lib/netty-buffer-4.0.52.Final.jar:lib/joda-time-2.9.9.jar:lib/commons-io-2.5.jar:lib/aether-spi-0.9.0.M2.jar:lib/compress-lzf-1.0.4.jar:lib/netty-codec-dns-2.0.37.jar:lib/opencsv-2.3.jar:lib/jersey-core-1.19.3.jar:lib/netty-resolver-dns-2.0.37.jar -server -Xmx2g -Duser.timezone=UTC -Dfile.encoding=UTF-8 -Djava.util.logging.manager=org.apache.logging.log4j.jul.LogManager -Ddruid.indexer.task.baseTaskDir=var/druid/task -Ddruid.host=0.0.0.0 -Ddruid.metadata.storage.connector.password=diurd -Ddruid.indexer.fork.property.druid.processing.numThreads=3 -Ddruid.emitter.logging.logLevel=warn -Ddruid.emitter=logging -Ddruid.indexer.fork.property.druid.processing.buffer.sizeBytes=256000000 -Duser.timezone=UTC -Dfile.encoding.pkg=sun.io -Ddruid.storage.storageDirectory=var/druid/segments -Ddruid.selectors.coordinator.serviceName=druid/coordinator -Ddruid.selectors.indexing.serviceName=druid/overlord -Ddruid.indexer.task.baseDir=/DB/tmp -Ddruid.indexing.doubleStorage=double -Ddruid.port=8091 -Ddruid.server.http.numThreads=9 -Ddruid.worker.capacity=3 -Ddruid.service=druid/middleManager -Ddruid.metadata.storage.connector.user=druid -Ddruid.metadata.storage.type=postgresql -Ddruid.metadata.storage.connector.connectURI=jdbc:postgresql://localhost:5432/druid -Djava.io.tmpdir=var/tmp -Ddruid.extensions.loadList=["postgresql-metadata-storage", "druid-kafka-indexing-service"] -Ddruid.startup.logging.logProperties=true -Ddruid.javascript.enabled=true -Ddruid.zk.service.host=localhost -Dhadoop.hadoop.tmp.dir=var/hadoop-tmp -Ddruid.monitoring.monitors=["io.druid.java.util.metrics.JvmMonitor"] -Ddruid.indexer.logs.directory=var/druid/indexing-logs -Ddruid.zk.paths.base=/druid -Dfile.encoding=UTF-8 -Ddruid.indexer.task.defaultHadoopCoordinates=["org.apache.hadoop:hadoop-client:2.7.3"] -Ddruid.storage.type=local -Ddruid.indexer.task.hadoopWorkingPath=var/druid/hadoop-tmp -Ddruid.indexer.logs.type=file -Ddruid.processing.numThreads=3 -Ddruid.processing.buffer.sizeBytes=256000000 -Ddruid.metrics.emitter.dimension.dataSource=sessions -Ddruid.metrics.emitter.dimension.taskId=index_kafka_sessions_dc85485a4576518_eckhgpcl -Ddruid.host=0.0.0.0 -Ddruid.port=8100 -Ddruid.tlsPort=-1 io.druid.cli.Main internal peon var/druid/task/index_kafka_sessions_dc85485a4576518_eckhgpcl/task.json var/druid/task/index_kafka_sessions_dc85485a4576518_eckhgpcl/753ef934-251b-4952-a006-a36b88eeee13/status.json
2018-06-18T12:55:59,668 INFO [forking-task-runner-0] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_sessions_dc85485a4576518_eckhgpcl] location changed to [TaskLocation{host='0.0.0.0', port=8100, tlsPort=-1}].
2018-06-18T12:55:59,669 INFO [forking-task-runner-0] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_sessions_dc85485a4576518_eckhgpcl] status changed to [RUNNING].
2018-06-18T12:55:59,669 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Updating task [index_kafka_sessions_dc85485a4576518_eckhgpcl] announcement with location [TaskLocation{host='0.0.0.0', port=8100, tlsPort=-1}]
2018-06-18T12:55:59,669 INFO [forking-task-runner-0] io.druid.indexing.overlord.ForkingTaskRunner - Logging task index_kafka_sessions_dc85485a4576518_eckhgpcl output to: var/druid/task/index_kafka_sessions_dc85485a4576518_eckhgpcl/log
2018-06-18T12:56:37,603 INFO [forking-task-runner-0-[index_kafka_sessions_dc85485a4576518_eckhgpcl]] io.druid.indexing.overlord.ForkingTaskRunner - Process exited with status[0] for task: index_kafka_sessions_dc85485a4576518_eckhgpcl
2018-06-18T12:56:37,608 INFO [forking-task-runner-0] io.druid.indexing.common.tasklogs.FileTaskLogs - Wrote task log to: var/druid/indexing-logs/index_kafka_sessions_dc85485a4576518_eckhgpcl.log
2018-06-18T12:56:37,609 INFO [forking-task-runner-0] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_sessions_dc85485a4576518_eckhgpcl] status changed to [FAILED].
2018-06-18T12:56:37,611 INFO [forking-task-runner-0] io.druid.indexing.overlord.ForkingTaskRunner - Removing task directory: var/druid/task/index_kafka_sessions_dc85485a4576518_eckhgpcl
2018-06-18T12:56:37,621 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Job's finished. Completed [index_kafka_sessions_dc85485a4576518_eckhgpcl] with status [FAILED]
...
many /jvm/pool & /jvm/bufferpool metrics
...
2018-06-18T12:57:06,811 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Submitting runnable for task[index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg]
2018-06-18T12:57:06,813 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Affirmative. Running task [index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg]
2018-06-18T12:57:06,824 INFO [forking-task-runner-1] io.druid.indexing.overlord.ForkingTaskRunner - Running command: java -cp conf-quickstart/druid/_common:conf-quickstart/druid/middleManager:lib/protobuf-java-3.1.0.jar:lib/commons-codec-1.7.jar:lib/jackson-core-asl-1.9.13.jar:lib/jersey-servlet-1.19.3.jar:lib/classmate-1.0.0.jar:lib/jdbi-2.63.1.jar:lib/guice-servlet-4.1.0.jar:lib/log4j-api-2.5.jar:lib/spymemcached-2.12.3.jar:lib/icu4j-54.1.1.jar:lib/druid-api-0.12.0.jar:lib/RoaringBitmap-0.5.18.jar:lib/jetty-io-9.3.19.v20170502.jar:lib/jets3t-0.9.4.jar:lib/jersey-guice-1.19.3.jar:lib/netty-3.10.6.Final.jar:lib/aether-api-0.9.0.M2.jar:lib/jackson-jq-0.0.7.jar:lib/aggdesigner-algorithm-6.0.jar:lib/jackson-jaxrs-smile-provider-2.4.6.jar:lib/netty-handler-4.0.52.Final.jar:lib/aopalliance-1.0.jar:lib/calcite-linq4j-1.15.0.jar:lib/activation-1.1.1.jar:lib/netty-transport-4.0.52.Final.jar:lib/jackson-dataformat-smile-2.4.6.jar:lib/curator-recipes-4.0.0.jar:lib/asm-5.2.jar:lib/netty-reactive-streams-1.0.8.jar:lib/asm-tree-5.2.jar:lib/zookeeper-3.4.10.jar:lib/commons-lang3-3.2.jar:lib/jersey-server-1.19.3.jar:lib/jackson-annotations-2.4.6.jar:lib/jackson-datatype-joda-2.4.6.jar:lib/jetty-security-9.3.19.v20170502.jar:lib/netty-codec-4.0.52.Final.jar:lib/jboss-logging-3.1.3.GA.jar:lib/druid-sql-0.12.0.jar:lib/maven-settings-builder-3.1.1.jar:lib/slf4j-api-1.6.4.jar:lib/validation-api-1.1.0.Final.jar:lib/lz4-1.3.0.jar:lib/guice-multibindings-4.1.0.jar:lib/guice-4.1.0.jar:lib/avatica-core-1.10.0.jar:lib/commons-pool2-2.2.jar:lib/commons-dbcp-1.4.jar:lib/bcprov-jdk15on-1.52.jar:lib/aws-java-sdk-core-1.10.77.jar:lib/curator-framework-4.0.0.jar:lib/jetty-server-9.3.19.v20170502.jar:lib/commons-math3-3.6.1.jar:lib/druid-console-0.0.2.jar:lib/log4j-core-2.5.jar:lib/aether-connector-file-0.9.0.M2.jar:lib/jackson-mapper-asl-1.9.13.jar:lib/javax.servlet-api-3.1.0.jar:lib/extendedset-0.12.0.jar:lib/hibernate-validator-5.1.3.Final.jar:lib/guava-16.0.1.jar:lib/jackson-databind-2.4.6.jar:lib/jetty-servlet-9.3.19.v20170502.jar:lib/commons-dbcp2-2.0.1.jar:lib/curator-client-4.0.0.jar:lib/asm-commons-5.2.jar:lib/reactive-streams-1.0.0.jar:lib/netty-resolver-2.0.37.jar:lib/maven-settings-3.1.1.jar:lib/jetty-client-9.3.19.v20170502.jar:lib/plexus-utils-3.0.15.jar:lib/druid-services-0.12.0.jar:lib/derbynet-10.11.1.1.jar:lib/log4j-jul-2.5.jar:lib/curator-x-discovery-4.0.0.jar:lib/netty-codec-http-4.0.52.Final.jar:lib/jsr305-2.0.1.jar:lib/tesla-aether-0.0.5.jar:lib/netty-common-4.0.52.Final.jar:lib/jackson-module-jaxb-annotations-2.4.6.jar:lib/commons-compiler-2.7.6.jar:lib/rhino-1.7R5.jar:lib/aether-impl-0.9.0.M2.jar:lib/json-path-2.1.0.jar:lib/druid-indexing-service-0.12.0.jar:lib/commons-logging-1.1.1.jar:lib/janino-2.7.6.jar:lib/jsr311-api-1.1.1.jar:lib/fastutil-8.1.0.jar:lib/maven-model-3.1.1.jar:lib/httpcore-4.4.3.jar:lib/geoip2-0.4.0.jar:lib/jackson-dataformat-cbor-2.5.3.jar:lib/okhttp-1.0.2.jar:lib/avatica-metrics-1.10.0.jar:lib/jetty-util-9.3.19.v20170502.jar:lib/jetty-servlets-9.3.19.v20170502.jar:lib/avatica-server-1.10.0.jar:lib/log4j-slf4j-impl-2.5.jar:lib/maxminddb-0.2.0.jar:lib/calcite-core-1.15.0.jar:lib/jetty-continuation-9.3.19.v20170502.jar:lib/netty-all-4.0.52.Final.jar:lib/javax.el-api-3.0.0.jar:lib/jcodings-1.0.13.jar:lib/java-util-0.12.0.jar:lib/httpclient-4.5.1.jar:lib/async-http-client-2.0.37.jar:lib/mapdb-1.0.8.jar:lib/disruptor-3.3.6.jar:lib/java-xmlbuilder-1.1.jar:lib/plexus-interpolation-1.19.jar:lib/druid-indexing-hadoop-0.12.0.jar:lib/jvm-attach-api-1.2.jar:lib/druid-processing-0.12.0.jar:lib/druid-hll-0.12.0.jar:lib/base64-2.3.8.jar:lib/maven-model-builder-3.1.1.jar:lib/derbyclient-10.11.1.1.jar:lib/antlr4-runtime-4.5.1.jar:lib/airline-0.7.jar:lib/netty-transport-native-epoll-4.0.52.Final-linux-x86_64.jar:lib/druid-common-0.12.0.jar:lib/commons-lang-2.6.jar:lib/jetty-proxy-9.3.19.v20170502.jar:lib/aether-util-0.9.0.M2.jar:lib/javax.el-3.0.0.jar:lib/joni-2.1.11.jar:lib/jackson-jaxrs-base-2.4.6.jar:lib/javax.inject-1.jar:lib/wagon-provider-api-2.4.jar:lib/jcl-over-slf4j-1.7.12.jar:lib/jetty-http-9.3.19.v20170502.jar:lib/config-magic-0.9.jar:lib/maven-aether-provider-3.1.1.jar:lib/aws-java-sdk-ec2-1.10.77.jar:lib/maven-repository-metadata-3.1.1.jar:lib/caffeine-2.5.5.jar:lib/esri-geometry-api-2.0.0.jar:lib/commons-cli-1.2.jar:lib/druid-aws-common-0.12.0.jar:lib/log4j-1.2-api-2.5.jar:lib/derby-10.11.1.1.jar:lib/aether-connector-okhttp-0.0.9.jar:lib/jline-0.9.94.jar:lib/jackson-core-2.4.6.jar:lib/druid-server-0.12.0.jar:lib/commons-pool-1.6.jar:lib/irc-api-1.0-0014.jar:lib/jackson-jaxrs-json-provider-2.4.6.jar:lib/jackson-datatype-guava-2.4.6.jar:lib/async-http-client-netty-utils-2.0.37.jar:lib/netty-buffer-4.0.52.Final.jar:lib/joda-time-2.9.9.jar:lib/commons-io-2.5.jar:lib/aether-spi-0.9.0.M2.jar:lib/compress-lzf-1.0.4.jar:lib/netty-codec-dns-2.0.37.jar:lib/opencsv-2.3.jar:lib/jersey-core-1.19.3.jar:lib/netty-resolver-dns-2.0.37.jar -server -Xmx2g -Duser.timezone=UTC -Dfile.encoding=UTF-8 -Djava.util.logging.manager=org.apache.logging.log4j.jul.LogManager -Ddruid.indexer.task.baseTaskDir=var/druid/task -Ddruid.host=0.0.0.0 -Ddruid.metadata.storage.connector.password=diurd -Ddruid.indexer.fork.property.druid.processing.numThreads=3 -Ddruid.emitter.logging.logLevel=warn -Ddruid.emitter=logging -Ddruid.indexer.fork.property.druid.processing.buffer.sizeBytes=256000000 -Duser.timezone=UTC -Dfile.encoding.pkg=sun.io -Ddruid.storage.storageDirectory=var/druid/segments -Ddruid.selectors.coordinator.serviceName=druid/coordinator -Ddruid.selectors.indexing.serviceName=druid/overlord -Ddruid.indexer.task.baseDir=/DB/tmp -Ddruid.indexing.doubleStorage=double -Ddruid.port=8091 -Ddruid.server.http.numThreads=9 -Ddruid.worker.capacity=3 -Ddruid.service=druid/middleManager -Ddruid.metadata.storage.connector.user=druid -Ddruid.metadata.storage.type=postgresql -Ddruid.metadata.storage.connector.connectURI=jdbc:postgresql://localhost:5432/druid -Djava.io.tmpdir=var/tmp -Ddruid.extensions.loadList=["postgresql-metadata-storage", "druid-kafka-indexing-service"] -Ddruid.startup.logging.logProperties=true -Ddruid.javascript.enabled=true -Ddruid.zk.service.host=localhost -Dhadoop.hadoop.tmp.dir=var/hadoop-tmp -Ddruid.monitoring.monitors=["io.druid.java.util.metrics.JvmMonitor"] -Ddruid.indexer.logs.directory=var/druid/indexing-logs -Ddruid.zk.paths.base=/druid -Dfile.encoding=UTF-8 -Ddruid.indexer.task.defaultHadoopCoordinates=["org.apache.hadoop:hadoop-client:2.7.3"] -Ddruid.storage.type=local -Ddruid.indexer.task.hadoopWorkingPath=var/druid/hadoop-tmp -Ddruid.indexer.logs.type=file -Ddruid.processing.numThreads=3 -Ddruid.processing.buffer.sizeBytes=256000000 -Ddruid.metrics.emitter.dimension.dataSource=sessions -Ddruid.metrics.emitter.dimension.taskId=index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg -Ddruid.host=0.0.0.0 -Ddruid.port=8100 -Ddruid.tlsPort=-1 io.druid.cli.Main internal peon var/druid/task/index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg/task.json var/druid/task/index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg/ef39ca9a-50b6-46d3-b783-948947d92051/status.json
2018-06-18T12:57:06,825 INFO [forking-task-runner-1] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg] location changed to [TaskLocation{host='0.0.0.0', port=8100, tlsPort=-1}].
2018-06-18T12:57:06,825 INFO [forking-task-runner-1] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg] status changed to [RUNNING].
2018-06-18T12:57:06,825 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Updating task [index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg] announcement with location [TaskLocation{host='0.0.0.0', port=8100, tlsPort=-1}]
2018-06-18T12:57:06,825 INFO [forking-task-runner-1] io.druid.indexing.overlord.ForkingTaskRunner - Logging task index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg output to: var/druid/task/index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg/log
2018-06-18T12:57:14,098 INFO [qtp2011636843-19] io.druid.indexing.overlord.ForkingTaskRunner - Killing process for task: index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg
2018-06-18T12:57:14,099 INFO [forking-task-runner-1] io.druid.indexing.common.tasklogs.FileTaskLogs - Wrote task log to: var/druid/indexing-logs/index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg.log
2018-06-18T12:57:14,099 INFO [forking-task-runner-1] io.druid.indexing.overlord.ForkingTaskRunner - Exception caught during execution
java.io.IOException: Stream closed
at java.io.BufferedInputStream.getBufIfOpen(BufferedInputStream.java:170) ~[?:1.8.0_161]
at java.io.BufferedInputStream.read1(BufferedInputStream.java:291) ~[?:1.8.0_161]
at java.io.BufferedInputStream.read(BufferedInputStream.java:345) ~[?:1.8.0_161]
at java.io.FilterInputStream.read(FilterInputStream.java:107) ~[?:1.8.0_161]
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.0.jar:0.12.0]
at io.druid.indexing.overlord.ForkingTaskRunner$1.call(ForkingTaskRunner.java:224) [druid-indexing-service-0.12.0.jar:0.12.0]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_161]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_161]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_161]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]
2018-06-18T12:57:14,109 INFO [forking-task-runner-1] io.druid.indexing.overlord.ForkingTaskRunner - Removing task directory: var/druid/task/index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg
2018-06-18T12:57:14,116 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Job's finished. Completed [index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg] with status [FAILED]
@suhassumukhv thanks for the logs! I could see the below logs from the overlord logs.
2018-06-18T12:57:13,950 WARN [KafkaSupervisor-sessions] io.druid.indexing.kafka.supervisor.KafkaSupervisor - Clearing task group [0] information as no valid tasks left the group
2018-06-18T12:57:13,950 WARN [KafkaSupervisor-sessions] io.druid.indexing.kafka.supervisor.KafkaSupervisor - Killing task [index_kafka_sessions_f7a2b2b5692bf6c_bjaacahg], as its checkpoints [{0={0=48}}] are not consistent with group checkpoints[{0={0=48}}] or latest persisted offsets in metadata store [{0=1436430}]
So, in your case, the supervisor killed the kafka index task because its offset ([{0={0=48}}]) was much behind the one stored in your metastore ([{0=1436430}]). Would you try resetting the supervisor (http://druid.io/docs/latest/development/extensions-core/kafka-ingestion.html#reset-supervisor)?
jihoonson
on 28 Jun 2018
Thanks, @jihoonson. That really worked. And thanks for providing the literature too.
But I didn't understand the use of earliest/latest offsets while resetting. The way I understand it,
let's say server offset is 20-48, and that of the consumer is 15, then it's more prudent to reset it to 20 (earliest) than 48 (latest).
Also, if in the same scenario, the offset of the consumer is 100 and that on the server is 0-10 (say, the data on the server was reset), then again, it's better to reset it to 0 (earliest) than 10 (latest).
My concern is that I can't discern the use for resetting it to earliest offset. Can you help me here, @jihoonson?
suhassumukh
on 29 Jun 2018
@suhassumukhv it depends on your application and its ingestion state. You might want to start ingestion from the latest offset if you don't want to bother with reading all historical data in Kafka. On the other hand, you might want to start from the earliest offset if you want to add data from beginning.
jihoonson
on 2 Jul 2018
@jihoonson
if i insert some data into kafka ,the task will success! just like the task id =[index_kafka_kafka_ins_de42264b8a929b1_cpgcjopj]
There many task failed in the KIS,like this :
2018-08-15T12:04:05,611 INFO [qtp1310871029-50] io.druid.indexing.overlord.ForkingTaskRunner - Killing process for task: index_kafka_kafka_ins_a2b40069b9da776_hkjphola
2018-08-15T12:04:05,664 INFO [forking-task-runner-0] io.druid.storage.hdfs.tasklog.HdfsTaskLogs - Writing task log to: hdfs://master:9000/druid/indexing-logs/index_kafka_kafka_ins_a2b40069b9da776_hkjphola
2018-08-15T12:04:07,929 INFO [forking-task-runner-0] io.druid.storage.hdfs.tasklog.HdfsTaskLogs - Wrote task log to: hdfs://master:9000/druid/indexing-logs/index_kafka_kafka_ins_a2b40069b9da776_hkjphola
2018-08-15T12:04:07,929 INFO [forking-task-runner-0] io.druid.indexing.overlord.ForkingTaskRunner - 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.1.jar:0.12.1]
at io.druid.indexing.overlord.ForkingTaskRunner$1.call(ForkingTaskRunner.java:224) [druid-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-15T12:04:08,279 INFO [forking-task-runner-0] io.druid.indexing.overlord.ForkingTaskRunner - Removing task directory: var/druid/task/index_kafka_kafka_ins_a2b40069b9da776_hkjphola
2018-08-15T12:04:08,783 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Job's finished. Completed [index_kafka_kafka_ins_a2b40069b9da776_hkjphola] with status [FAILED]
I guess it happed because there it no message push into kafka?
i have used druid 0.10.2.0 ,kafka 2.11-1.0.0,zookeeper 3.4.10.
if you find anything error to configure,pelease tell me!
the success log like [index_kafka_kafka_ins_de42264b8a929b1_cpgcjopj]:
index_kafka_kafka_ins_de42264b8a929b1_cpgcjopj.txt
in the overlord the failed task log:
2018-08-15T12:04:06,040 INFO [KafkaSupervisor-kafka_ins] io.druid.indexing.overlord.MetadataTaskStorage - Updating task index_kafka_kafka_ins_a2b40069b9da776_hkjphola to status: TaskStatus{id=index_kafka_kafka_ins_a2b40069b9da776_hkjphola, status=FAILED, duration=-1}
2018-08-15T12:04:07,560 WARN [KafkaSupervisor-kafka_disk-Reporting-0] io.druid.indexing.kafka.supervisor.KafkaSupervisor - Lag metric: Kafka partitions [0, 1, 2] do not match task partitions []
2018-08-15T12:04:07,560 INFO [KafkaSupervisor-kafka_disk-Reporting-0] io.druid.java.util.emitter.core.LoggingEmitter - Event [{"feed":"metrics","timestamp":"2018-08-15T12:04:07.560Z","service":"druid/overlord","host":"master:8090","version":"0.12.1","metric":"ingest/kafka/lag","value":0,"dataSource":"kafka_disk"}]
2018-08-15T12:04:07,569 WARN [KafkaSupervisor-kafka_ins-Reporting-0] io.druid.indexing.kafka.supervisor.KafkaSupervisor - Lag metric: Kafka partitions [0, 1, 2] do not match task partitions []
2018-08-15T12:04:07,569 INFO [KafkaSupervisor-kafka_ins-Reporting-0] io.druid.java.util.emitter.core.LoggingEmitter - Event [{"feed":"metrics","timestamp":"2018-08-15T12:04:07.569Z","service":"druid/overlord","host":"master:8090","version":"0.12.1","metric":"ingest/kafka/lag","value":0,"dataSource":"kafka_ins"}]
2018-08-15T12:04:08,587 INFO [Curator-PathChildrenCache-3] io.druid.indexing.overlord.RemoteTaskRunner - Worker[slave2:8091] wrote FAILED status for task [index_kafka_kafka_ins_a2b40069b9da776_hkjphola] on [TaskLocation{host='slave2', port=8102, tlsPort=-1}]
2018-08-15T12:04:08,587 INFO [Curator-PathChildrenCache-3] io.druid.indexing.overlord.RemoteTaskRunner - Worker[slave2:8091] completed task[index_kafka_kafka_ins_a2b40069b9da776_hkjphola] with status[FAILED]
2018-08-15T12:04:08,587 INFO [Curator-PathChildrenCache-3] io.druid.indexing.overlord.TaskQueue - Received FAILED status for task: index_kafka_kafka_ins_a2b40069b9da776_hkjphola
2018-08-15T12:04:08,954 INFO [KafkaSupervisor-kafka_ins] io.druid.indexing.overlord.TaskQueue - Task done: KafkaIndexTask{id=index_kafka_kafka_ins_a2b40069b9da776_hkjphola, type=index_kafka, dataSource=kafka_ins}
2018-08-15T12:04:08,955 INFO [Curator-PathChildrenCache-3] io.druid.indexing.overlord.RemoteTaskRunner - Cleaning up task[index_kafka_kafka_ins_a2b40069b9da776_hkjphola] on worker[slave2:8091]
2018-08-15T12:04:08,978 WARN [Curator-PathChildrenCache-3] io.druid.indexing.overlord.TaskQueue - Unknown task completed: index_kafka_kafka_ins_a2b40069b9da776_hkjphola
2018-08-15T12:04:08,978 INFO [Curator-PathChildrenCache-3] io.druid.java.util.emitter.core.LoggingEmitter - Event [{"feed":"metrics","timestamp":"2018-08-15T12:04:08.978Z","service":"druid/overlord","host":"master:8090","version":"0.12.1","metric":"task/run/time","value":103077,"dataSource":"kafka_ins","taskStatus":"FAILED","taskType":"index_kafka"}]
2018-08-15T12:04:08,978 INFO [Curator-PathChildrenCache-3] io.druid.indexing.overlord.TaskQueue - Task FAILED: KafkaIndexTask{id=index_kafka_kafka_ins_a2b40069b9da776_hkjphola, type=index_kafka, dataSource=kafka_ins} (103077 run duration)
2018-08-15T12:04:08,978 INFO [Curator-PathChildrenCache-3] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_kafka_ins_a2b40069b9da776_hkjphola] status changed to [FAILED].
2018-08-15T12:04:08,979 INFO [Curator-PathChildrenCache-3] io.druid.indexing.overlord.RemoteTaskRunner - Task[index_kafka_kafka_ins_a2b40069b9da776_hkjphola] went bye bye.
2018-08-15T12:04:08,990 INFO [KafkaIndexTaskClient-kafka_disk-0] io.druid.indexing.kafka.KafkaIndexTaskClient - No TaskLocation available for task [index_kafka_kafka_disk_8258b8d8c8b7341_fgmoceab], this task may not have been assigned to a worker yet or may have already completed
2018-08-15T12:04:08,992 INFO [KafkaSupervisor-kafka_ins] io.druid.indexing.kafka.supervisor.KafkaSupervisor - {id='kafka_ins', generationTime=2018-08-15T12:04:08.992Z, payload={dataSource='kafka_ins', topic='ins', partitions=3, replicas=1, durationSeconds=3600, active=[{id='index_kafka_kafka_ins_a2b40069b9da776_hkjphola', startTime=null, remainingSeconds=null}], publishing=[{id='index_kafka_kafka_ins_de42264b8a929b1_cpgcjopj', startTime=2018-08-15T10:49:33.227Z, remainingSeconds=925}]}}
2018-08-15T12:04:09,001 INFO [KafkaSupervisor-kafka_disk] io.druid.indexing.kafka.supervisor.KafkaSupervisor - {id='kafka_disk', generationTime=2018-08-15T12:04:09.001Z, payload={dataSource='kafka_disk', topic='disk', partitions=3, replicas=1, durationSeconds=3600, active=[{id='index_kafka_kafka_disk_8258b8d8c8b7341_fgmoceab', startTime=null, remainingSeconds=null}], publishing=[{id='index_kafka_kafka_disk_8258b8d8c8b7341_fpojhnlo', startTime=2018-08-15T10:59:25.500Z, remainingSeconds=1650}]}}
2018-08-15T12:04:09,005 WARN [KafkaSupervisor-kafka_ins] io.druid.indexing.kafka.supervisor.KafkaSupervisor - Task [index_kafka_kafka_ins_a2b40069b9da776_hkjphola] failed to return start time, killing task
2018-08-15T12:04:09,317 INFO [KafkaSupervisor-kafka_ins] io.druid.indexing.kafka.supervisor.KafkaSupervisor - Number of tasks [0] does not match configured numReplicas [1] in task group [0], creating more tasks
2018-08-15T12:04:09,318 INFO [KafkaSupervisor-kafka_ins] io.druid.indexing.overlord.MetadataTaskStorage - Inserting task index_kafka_kafka_ins_a2b40069b9da776_epkmnncf with status: TaskStatus{id=index_kafka_kafka_ins_a2b40069b9da776_epkmnncf, status=RUNNING, duration=-1}
2018-08-15T12:04:09,983 INFO [KafkaSupervisor-kafka_ins] io.druid.indexing.overlord.TaskLockbox - Adding task[index_kafka_kafka_ins_a2b40069b9da776_epkmnncf] to activeTasks
huang2012chao
on 16 Aug 2018
Hi I am facing this issue many times with the druid 0.12.3 not sure how to make it work reliably.. Do you guys recommend using tranquillity instead of kafka indexing tasks?
usopan
on 2 Feb 2019
Hi, @jihoonson .
I found a similar error in Druid 0.13.0.
This problem probably occurs when there is not enough free memory on the server.
When an error occurred, the available memory increased from 162056 to 4570104.
During the test we were still storing data on the client and there was no loss.
However, memory usage was increasing slightly. Perhaps there was not enough memory left for the segment to be created.
middlemanager.log is below.
2019-03-18T10:21:45,196 INFO [forking-task-runner-6] org.apache.druid.indexing.overlord.ForkingTaskRunner - Removing task directory: var/druid/task/index_kafka_ds_test2_9d87293708d7ae2_pdpdjhlh
2019-03-18T10:21:46,079 INFO [WorkerTaskManager-NoticeHandler] org.apache.druid.indexing.worker.WorkerTaskManager - Job's finished. Completed [index_kafka_ds_test4_ee46e16cbb67785_okdcidna] with status [FAILED]
2019-03-18T10:21:46,097 INFO [WorkerTaskManager-NoticeHandler] org.apache.druid.indexing.worker.WorkerTaskManager - Job's finished. Completed [index_kafka_ds_test2_9d87293708d7ae2_pdpdjhlh] with status [FAILED]
2019-03-18T10:21:53,750 INFO [qtp1431064234-77] org.apache.druid.indexing.overlord.ForkingTaskRunner - Killing process for task: index_kafka_ds_test2_4d88b40775ab307_cdkfbhbk
2019-03-18T10:21:53,756 INFO [forking-task-runner-10] org.apache.druid.indexing.common.tasklogs.FileTaskLogs - Wrote task log to: var/druid/indexing-logs/index_kafka_ds_test2_4d88b40775ab307_cdkfbhbk.log
2019-03-18T10:21:53,761 INFO [forking-task-runner-10] org.apache.druid.indexing.overlord.ForkingTaskRunner - 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 org.apache.druid.indexing.overlord.ForkingTaskRunner$1.call(ForkingTaskRunner.java:438) [druid-indexing-service-0.13.0-incubating.jar:0.13.0-incubating]
at org.apache.druid.indexing.overlord.ForkingTaskRunner$1.call(ForkingTaskRunner.java:223) [druid-indexing-service-0.13.0-incubating.jar:0.13.0-incubating]
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]
2019-03-18T10:21:53,792 INFO [forking-task-runner-10] org.apache.druid.indexing.overlord.ForkingTaskRunner - Removing task directory: var/druid/task/index_kafka_ds_test2_4d88b40775ab307_cdkfbhbk
2019-03-18T10:21:53,806 INFO [WorkerTaskManager-NoticeHandler] org.apache.druid.indexing.worker.WorkerTaskManager - Job's finished. Completed [index_kafka_ds_test2_4d88b40775ab307_cdkfbhbk] with status [FAILED]
2019-03-18T10:21:54,362 INFO [WorkerTaskManager-NoticeHandler] org.apache.druid.indexing.worker.WorkerTaskManager - Task[index_kafka_ds_test2_4d88b40775ab307_knbgkefd] started.
2019-03-18T10:21:57,111 INFO [forking-task-runner-15] org.apache.druid.indexing.overlord.ForkingTaskRunner - Running command: java -cp
And overlord.log of the same time is below.
2019-03-18T10:21:53,939 INFO [KafkaSupervisor-ds_test2] org.apache.druid.indexing.overlord.TaskLockbox - TaskLock is now empty: TaskLock{type=EXCLUSIVE, groupId=index_kafka_ds_test2, dataSource=ds_test2, interval=2019-03-18T00:00:00.000Z/2019-03-19T00:00:00.000Z, version=2019-03-18T10:21:47.300Z, priority=75, revoked=false}
2019-03-18T10:21:53,946 INFO [KafkaSupervisor-ds_test2] org.apache.druid.indexing.overlord.MetadataTaskStorage - Deleting TaskLock with id[232]: TaskLock{type=EXCLUSIVE, groupId=index_kafka_ds_test2, dataSource=ds_test2, interval=2019-03-18T00:00:00.000Z/2019-03-19T00:00:00.000Z, version=2019-03-18T10:21:47.300Z, priority=75, revoked=false}
2019-03-18T10:21:53,957 INFO [KafkaSupervisor-ds_test2] org.apache.druid.indexing.overlord.MetadataTaskStorage - Updating task index_kafka_ds_test2_4d88b40775ab307_cdkfbhbk to status: TaskStatus{id=index_kafka_ds_test2_4d88b40775ab307_cdkfbhbk, status=FAILED, duration=-1, errorMsg=null}
2019-03-18T10:21:53,964 INFO [KafkaSupervisor-ds_test2] org.apache.druid.indexing.overlord.TaskQueue - Task done: AbstractTask{id='index_kafka_ds_test2_4d88b40775ab307_cdkfbhbk', groupId='index_kafka_ds_test2', taskResource=TaskResource{availabilityGroup='index_kafka_ds_test2_4d88b40775ab307', requiredCapacity=1}, dataSource='ds_test2', context={checkpoints={"0":{"0":8275}}, IS_INCREMENTAL_HANDOFF_SUPPORTED=true}}
2019-03-18T10:21:53,964 INFO [KafkaSupervisor-ds_test2] org.apache.druid.indexing.kafka.supervisor.KafkaSupervisor - Killing task [index_kafka_ds_test2_4d88b40775ab307_hbdjcjcn] in the task group
2019-03-18T10:21:53,964 INFO [Curator-PathChildrenCache-1] org.apache.druid.indexing.overlord.RemoteTaskRunner - Cleaning up task[index_kafka_ds_test2_4d88b40775ab307_cdkfbhbk] on worker[localhost:8091]
2019-03-18T10:21:53,968 WARN [Curator-PathChildrenCache-1] org.apache.druid.indexing.overlord.TaskQueue - Unknown task completed: index_kafka_ds_test2_4d88b40775ab307_cdkfbhbk
2019-03-18T10:21:53,968 INFO [KafkaSupervisor-ds_test2] org.apache.druid.indexing.overlord.RemoteTaskRunner - Removed task from pending queue: index_kafka_ds_test2_4d88b40775ab307_hbdjcjcn
2019-03-18T10:21:53,968 INFO [KafkaSupervisor-ds_test2] org.apache.druid.indexing.overlord.TaskLockbox - Removing task[index_kafka_ds_test2_4d88b40775ab307_hbdjcjcn] from activeTasks
2019-03-18T10:21:53,968 INFO [Curator-PathChildrenCache-1] org.apache.druid.java.util.emitter.core.LoggingEmitter - Event [{"feed":"metrics","timestamp":"2019-03-18T10:21:53.968Z","service":"druid/overlord","host":"localhost:8090","version":"0.13.0-incubating","metric":"task/run/time","value":34710,"dataSource":"ds_test2","taskId":"index_kafka_ds_test2_4d88b40775ab307_cdkfbhbk","taskStatus":"FAILED","taskType":"index_kafka"}]
2019-03-18T10:21:53,969 INFO [Curator-PathChildrenCache-1] org.apache.druid.indexing.overlord.TaskQueue - Task FAILED: AbstractTask{id='index_kafka_ds_test2_4d88b40775ab307_cdkfbhbk', groupId='index_kafka_ds_test2', taskResource=TaskResource{availabilityGroup='index_kafka_ds_test2_4d88b40775ab307', requiredCapacity=1}, dataSource='ds_test2', context={checkpoints={"0":{"0":8275}}, IS_INCREMENTAL_HANDOFF_SUPPORTED=true}} (34710 run duration)
2019-03-18T10:21:53,969 INFO [Curator-PathChildrenCache-1] org.apache.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_ds_test2_4d88b40775ab307_cdkfbhbk] status changed to [FAILED].
2019-03-18T10:21:53,970 INFO [Curator-PathChildrenCache-1] org.apache.druid.indexing.overlord.RemoteTaskRunner - Task[index_kafka_ds_test2_4d88b40775ab307_cdkfbhbk] went bye bye.
2019-03-18T10:21:53,972 INFO [KafkaSupervisor-ds_test2] org.apache.druid.indexing.overlord.MetadataTaskStorage - Updating task index_kafka_ds_test2_4d88b40775ab307_hbdjcjcn to status: TaskStatus{id=index_kafka_ds_test2_4d88b40775ab307_hbdjcjcn, status=FAILED, duration=-1, errorMsg=null}
2019-03-18T10:21:53,977 INFO [KafkaSupervisor-ds_test2] org.apache.druid.indexing.overlord.TaskQueue - Task done: AbstractTask{id='index_kafka_ds_test2_4d88b40775ab307_hbdjcjcn', groupId='index_kafka_ds_test2', taskResource=TaskResource{availabilityGroup='index_kafka_ds_test2_4d88b40775ab307', requiredCapacity=1}, dataSource='ds_test2', context={checkpoints={"0":{"0":8275}}, IS_INCREMENTAL_HANDOFF_SUPPORTED=true}}
2019-03-18T10:21:53,978 INFO [KafkaSupervisor-ds_test2] org.apache.druid.indexing.kafka.supervisor.KafkaSupervisor - [ds_test2] supervisor is running.
2019-03-18T10:21:53,978 INFO [KafkaSupervisor-ds_test2] org.apache.druid.indexing.kafka.supervisor.KafkaSupervisor - Creating new task group [0] for partitions [0]
And zookeeper.log of the same time is below.
2019-03-18 10:21:45,993 INFO [SyncThread:0] org.apache.zookeeper.server.ZooKeeperServer - Established session 0x169904864e50013 with negotiated timeout 30000 for client /127.0.0.1:50068
2019-03-18 10:21:53,880 INFO [ProcessThread(sid:0 cport:2181):] org.apache.zookeeper.server.PrepRequestProcessor - Processed session termination for sessionid: 0x169904864e5000d
2019-03-18 10:21:53,886 WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181] org.apache.zookeeper.server.NIOServerCnxn - caught end of stream exception
EndOfStreamException: Unable to read additional data from client sessionid 0x169904864e5000d, likely client has closed socket
at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:228)
at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203)
at java.lang.Thread.run(Thread.java:748)
2019-03-18 10:21:53,891 INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181] org.apache.zookeeper.server.NIOServerCnxn - Closed socket connection for client /127.0.0.1:49798 which had sessionid 0x169904864e5000d
2019-03-18 10:21:56,640 INFO [ProcessThread(sid:0 cport:2181):] org.apache.zookeeper.server.PrepRequestProcessor - Processed session termination for sessionid: 0x169904864e50013
JinseonyLee
on 21 Mar 2019
@huang2012chao sorry, I missed your question. If one of Kafka tasks fail, the supervisor would print the reason in the overlord log. This might not easy to find before 0.14 because the reason may be printed in different line from the log of killing tasks. But, the reason to kill tasks should be in the overlord log.
@usopan Even though we dropped Tranquility officially, it has not been updated for a while. And it doesn't support exactly-once. I would recommend using Kafka indexing service because it's more stable than Tranquility. This error doesn't necessarily mean the ingestion is failing. Rather, it's likely saying the supervisor killed some tasks for good reasons.
@Jinstarry do you mean the memory of middleManager? Do you see any OutOfMemory error in the failed task log? I guess index_kafka_ds_test2_4d88b40775ab307_cdkfbhbk is the failed task you're saying. If you don't see any errors or exceptions in the task log, that means the supervisor killed that task. And if so, the reason for killing tasks should be in the overlord log. You should be able to see logs starting with Sent shutdown message to worker to kill those tasks. The reason for killing would be around that log.
jihoonson
on 21 Mar 2019
This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.
![stale[bot] picture](https://avatars.githubusercontent.com/in/1724?v=4&s=40)
stale[bot]
on 20 Jun 2019
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.
stale[bot]
on 4 Jul 2019
Related issues
MaxOrelus
路
3Comments
rahulsingh303
路
5Comments
NicolasBielza
路
5Comments
bahadircolak44
路
5Comments
h00173922
路
3Comments
Most helpful comment
I am using druid version .12.0, I am getting this same error, here is the error log from middle-manager,
2018-04-18T09:45:10,159 INFO [forking-task-runner-2] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_test1_4454ee7eece418b_ficeeefj] location changed to [TaskLocation{host='ubuntu16.04', port=8100, tlsPort=-1}].
2018-04-18T09:45:10,159 INFO [forking-task-runner-2] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_kafka_test1_4454ee7eece418b_ficeeefj] status changed to [RUNNING].
2018-04-18T09:45:10,159 INFO [forking-task-runner-2] io.druid.indexing.overlord.ForkingTaskRunner - Logging task index_kafka_test1_4454ee7eece418b_ficeeefj output to: var/druid/task/index_kafka_test1_4454ee7eece418b_ficeeefj/log
2018-04-18T09:45:10,159 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Updating task [index_kafka_test1_4454ee7eece418b_ficeeefj] announcement with location [TaskLocation{host='ubuntu16.04', port=8100, tlsPort=-1}]
2018-04-18T09:45:15,161 INFO [qtp1733903473-26] io.druid.indexing.overlord.ForkingTaskRunner - Killing process for task: index_kafka_test1_4454ee7eece418b_ficeeefj
2018-04-18T09:45:15,162 INFO [forking-task-runner-2] io.druid.indexing.common.tasklogs.FileTaskLogs - Wrote task log to: var/druid/indexing-logs/index_kafka_test1_4454ee7eece418b_ficeeefj.log
2018-04-18T09:45:15,163 INFO [forking-task-runner-2] io.druid.indexing.overlord.ForkingTaskRunner - Exception caught during execution
java.io.IOException: Stream closed
at java.io.BufferedInputStream.getBufIfOpen(BufferedInputStream.java:170) ~[?:1.8.0_161]
at java.io.BufferedInputStream.read1(BufferedInputStream.java:291) ~[?:1.8.0_161]
at java.io.BufferedInputStream.read(BufferedInputStream.java:345) ~[?:1.8.0_161]
at java.io.FilterInputStream.read(FilterInputStream.java:107) ~[?:1.8.0_161]
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.0.jar:0.12.0]
at io.druid.indexing.overlord.ForkingTaskRunner$1.call(ForkingTaskRunner.java:224) [druid-indexing-service-0.12.0.jar:0.12.0]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_161]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_161]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_161]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]
2018-04-18T09:45:15,165 INFO [forking-task-runner-2] io.druid.indexing.overlord.ForkingTaskRunner - Removing task directory: var/druid/task/index_kafka_test1_4454ee7eece418b_ficeeefj
2018-04-18T09:45:15,166 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Job's finished. Completed [index_kafka_test1_4454ee7eece418b_ficeeefj] with status [FAILED]