keeping getting these errors - middlemanager/overlord

[Samah Sohrab]

Hi,

I keep getting these errors on my overlord, and middle manager. I'm not sure what I'm supposed to fix.

MIDDLEMANAGER

 "exceptionMessage" : "java.lang.RuntimeException: java.io.IOException: Stream closed",
    "exceptionStackTrace" : "java.util.concurrent.ExecutionException: java.lang.RuntimeException: java.io.IOException: Stream closed\n\tat java.util.concurrent.FutureTask.report(FutureTask.java:122)\n\tat java.util.concurrent.FutureTask.get(FutureTask.java:192)\n\tat io.druid.indexing.worker.WorkerTaskMonitor$1$1.run(WorkerTaskMonitor.java:131)\n\tat java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)\n\tat java.util.concurrent.FutureTask.run(FutureTask.java:266)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)\n\tat java.lang.Thread.run(Thread.java:745)\nCaused by: java.lang.RuntimeException: java.io.IOException: Stream closed\n\tat com.google.common.base.Throwables.propagate(Throwables.java:160)\n\tat io.druid.indexing.overlord.ForkingTaskRunner$1.call(ForkingTaskRunner.java:264)\n\tat io.druid.indexing.overlord.ForkingTaskRunner$1.call(ForkingTaskRunner.java:120)\n\t... 4 more\nCaused by: java.io.IOException: Stream closed\n\tat java.io.BufferedInputStream.getBufIfOpen(BufferedInputStream.java:170)\n\tat java.io.BufferedInputStream.read1(BufferedInputStream.java:291)\n\tat java.io.BufferedInputStream.read(BufferedInputStream.java:345)\n\tat java.io.FilterInputStream.read(FilterInputStream.java:107)\n\tat com.google.common.io.ByteStreams.copy(ByteStreams.java:175)\n\tat io.druid.indexing.overlord.ForkingTaskRunner$1.call(ForkingTaskRunner.java:237)\n\t... 5 more\n",
    "task" : "index_realtime_trace_annotation_2015-09-07T20:00:00.000Z_0_0_cebncaek"
  },
  "description" : "I can't build there. Failed to run task",

OVERLORD

  "exceptionMessage" : "Active task not found: index_realtime_cmp_panoramix_2015-09-07T19:00:00.000Z_0_0_inbphgee",
    "exceptionStackTrace" : "java.lang.IllegalStateException: Active task not found: index_realtime_cmp_panoramix_2015-09-07T19:00:00.000Z_0_0_inbphgee\n\tat io.druid.indexing.overlord.DbTaskStorage.setStatus(DbTaskStorage.java:183)\n\tat io.druid.indexing.overlord.TaskQueue.notifyStatus(TaskQueue.java:392)\n\tat io.druid.indexing.overlord.TaskQueue.access$500(TaskQueue.java:64)\n\tat io.druid.indexing.overlord.TaskQueue$4.handleStatus(TaskQueue.java:456)\n\tat io.druid.indexing.overlord.TaskQueue$4.onSuccess(TaskQueue.java:432)\n\tat io.druid.indexing.overlord.TaskQueue$4.onSuccess(TaskQueue.java:427)\n\tat com.google.common.util.concurrent.Futures$4.run(Futures.java:1181)\n\tat com.google.common.util.concurrent.MoreExecutors$SameThreadExecutorService.execute(MoreExecutors.java:297)\n\tat com.google.common.util.concurrent.ExecutionList.executeListener(ExecutionList.java:156)\n\tat com.google.common.util.concurrent.ExecutionList.execute(ExecutionList.java:145)\n\tat com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:185)\n\tat com.google.common.util.concurrent.SettableFuture.set(SettableFuture.java:53)\n\tat io.druid.indexing.overlord.RemoteTaskRunnerWorkItem.setResult(RemoteTaskRunnerWorkItem.java:81)\n\tat io.druid.indexing.overlord.RemoteTaskRunner.taskComplete(RemoteTaskRunner.java:869)\n\tat io.druid.indexing.overlord.RemoteTaskRunner.access$900(RemoteTaskRunner.java:97)\n\tat io.druid.indexing.overlord.RemoteTaskRunner$5.childEvent(RemoteTaskRunner.java:716)\n\tat org.apache.curator.framework.recipes.cache.PathChildrenCache$5.apply(PathChildrenCache.java:516)\n\tat org.apache.curator.framework.recipes.cache.PathChildrenCache$5.apply(PathChildrenCache.java:510)\n\tat org.apache.curator.framework.listen.ListenerContainer$1.run(ListenerContainer.java:92)\n\tat com.google.common.util.concurrent.MoreExecutors$SameThreadExecutorService.execute(MoreExecutors.java:297)\n\tat org.apache.curator.framework.listen.ListenerContainer.forEach(ListenerContainer.java:83)\n\tat org.apache.curator.framework.recipes.cache.PathChildrenCache.callListeners(PathChildrenCache.java:507)\n\tat org.apache.curator.framework.recipes.cache.EventOperation.invoke(EventOperation.java:35)\n\tat org.apache.curator.framework.recipes.cache.PathChildrenCache$9.run(PathChildrenCache.java:759)\n\tat java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)\n\tat java.util.concurrent.FutureTask.run(FutureTask.java:266)\n\tat java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)\n\tat java.util.concurrent.FutureTask.run(FutureTask.java:266)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)\n\tat java.lang.Thread.run(Thread.java:745)\n",
    "task" : "index_realtime_cmp_panoramix_2015-09-07T19:00:00.000Z_0_0_inbphgee",
    "statusCode" : "SUCCESS"
  },
  "description" : "Failed to persist status for task",

[Gian Merlino]

Hey Samah,

Which version of Druid are you using?

From the stack trace, the "Failed to persist status for task" looks like it's happening when the overlord tries to write a finished status for a task, and finds that this has already been done. Is this occurring around overlord leadership changes, or restarts, by any chance? Or is there anything else interesting going on at the time that these alerts get fired?

The "I can't build there. Failed to run task" alert with "Stream closed" as the exceptionMessage *should* only happen if the task was being ordered to shut down anyway. I wonder if this is the case for that task. Do you see anything in the logs like "Killing process for task"?

--
You received this message because you are subscribed to the Google Groups "Druid User" group.
To unsubscribe from this group and stop receiving emails from it, send an email to druid-user+...@googlegroups.com.
To post to this group, send email to druid...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/druid-user/ae7bd756-27d0-4aa8-999f-cc0047cf0b20%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Kiran Jagtap]

Hi Gian,

We are getting similar error for index job when multiple jobs are executing in parallel, 

but jobs are successful for sequential execution.

We are getting "Killing process for task" in middle manager logs.

Druid version : 0.12.3

Cluster size : 15 nodes

Each node : 2 core, 8 GB RAM

Nodes distributions :

3 nodes : coordinator, overload, zookeeper (three processes on each node)

3 nodes : middle manager (single process on each node)

3 nodes : broker (single process on each node)

6 nodes : historical (single process on each node)

Task Id : "index_fiat_20181130_mul_2018-11-30T10:53:05.415Z"

Middle Manager Log :

2018-11-30T10:54:35,017 INFO [qtp2071364564-40] io.druid.indexing.overlord.ForkingTaskRunner - Killing process for task: index_fiat_20181130_mul_201\

8-11-30T10:53:05.415Z

2018-11-30T10:54:35,018 INFO [forking-task-runner-0] io.druid.storage.s3.S3TaskLogs - Pushing task log var/druid/task/index_fiat_20181130_mul_2018-1\

1-30T10:53:05.415Z/log to: druid/indexing-logs/index_fiat_20181130_mul_2018-11-30T10:53:05.415Z/log

2018-11-30T10:54:35,230 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_191]

        at java.io.BufferedInputStream.read1(BufferedInputStream.java:291) ~[?:1.8.0_191]

        at java.io.BufferedInputStream.read(BufferedInputStream.java:345) ~[?:1.8.0_191]

        at java.io.FilterInputStream.read(FilterInputStream.java:107) ~[?:1.8.0_191]

        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.3.jar:0.12.3]

        at io.druid.indexing.overlord.ForkingTaskRunner$1.call(ForkingTaskRunner.java:224) [druid-indexing-service-0.12.3.jar:0.12.3]

        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_191]

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_191]

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_191]

        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_191]

2018-11-30T10:54:35,231 INFO [forking-task-runner-0] io.druid.indexing.overlord.ForkingTaskRunner - Removing task directory: var/druid/task/index_fi\

at_20181130_mul_2018-11-30T10:53:05.415Z

2018-11-30T10:54:35,282 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Job's finished. Completed [index_fiat_20181130_mul_201\

8-11-30T10:53:05.415Z] with status [FAILED]

Overlord log

2018-11-30T10:54:35,015 INFO [TaskQueue-Manager] io.druid.indexing.overlord.TaskQueue - Asking taskRunner to clean up 1 tasks.

2018-11-30T10:54:35,029 INFO [TaskQueue-Manager] io.druid.indexing.overlord.RemoteTaskRunner - Sent shutdown message to worker: {IP}:8091, s\

tatus 200 OK, response: {"task":"index_fiat_20181130_mul_2018-11-30T10:53:05.415Z"}

2018-11-30T10:54:35,284 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Worker[{ip}:8091] wrote FAILED stat\

us for task [index_fiat_20181130_mul_2018-11-30T10:53:05.415Z] on [TaskLocation{host='{ip}', port=8100, tlsPort=-1}]

2018-11-30T10:54:35,284 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Worker[{ip}:8091] completed task[in\

dex_fiat_20181130_mul_2018-11-30T10:53:05.415Z] with status[FAILED]

2018-11-30T10:54:35,284 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskQueue - Received FAILED status for task: index_fiat_201811\

30_mul_2018-11-30T10:53:05.415Z

2018-11-30T10:54:35,284 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Cleaning up task[index_fiat_20181130_mul_20\

18-11-30T10:53:05.415Z] on worker[{ip}:8091]

2018-11-30T10:54:35,287 WARN [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskQueue - Unknown task completed: index_fiat_20181130_mul_20\

18-11-30T10:53:05.415Z

2018-11-30T10:54:35,287 INFO [Curator-PathChildrenCache-1] io.druid.java.util.emitter.core.LoggingEmitter - Event [{"feed":"metrics","timestamp":"20\

18-11-30T10:54:35.287Z","service":"druid/epsilon-prod/overlord","host":"{ip}:8090","version":"0.12.3","metric":"task/run/time","value":89811,\

"dataSource":"fiat_20181130_mul","taskStatus":"FAILED","taskType":"index"}]

2018-11-30T10:54:35,287 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskQueue - Task FAILED: AbstractTask{id='index_fiat_20181130_\

mul_2018-11-30T10:53:05.415Z', groupId='index_append_fiat_20181130_mul', taskResource=TaskResource{availabilityGroup='index_fiat_20181130_mul_2018-1\

1-30T10:53:05.415Z', requiredCapacity=1}, dataSource='fiat_20181130_mul', context={}} (89811 run duration)

2018-11-30T10:54:35,287 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_fiat_20181130_mul_2018-11-30T10:\

53:05.415Z] status changed to [FAILED].

2018-11-30T10:54:35,287 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Task[index_fiat_20181130_mul_2018-11-30T10:\

53:05.415Z] went bye bye.

Any help or idea would really appreciated !!!

Thanks,

Kiran

[Kiran Jagtap]

Hi team,

I confirm individual middle manager, its working fine, but when I perform multiple index jobs with 3 middle manager nodes cluster, one of job failed each time.

Druid version : 0.12.3

Cluster size : 15 nodes

Each node : 2 core, 8 GB RAM

Broker : 2 nodes

Middle Manager : 3 nodes

Historical : 6 nodes

Overlord & coordinator : 2 nodes

zookeeper : 2 nodes 

Any ides/help would really appreciated

Thanks,

Kiran

[Jihoon Son]

Hi Kiran,

the middleManager logs above just say that they killed the running processes successfully and it's fine to ignore. Rather, you need to check why the supervisor killed those tasks. Would you please check the overlord logs to see anything interesting? What I usually do is 'grep @{killed_task_id} overlord.log | less'.

Jihoon

--

You received this message because you are subscribed to the Google Groups "Druid User" group.
To unsubscribe from this group and stop receiving emails from it, send an email to druid-user+...@googlegroups.com.
To post to this group, send email to druid...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/druid-user/464fec91-a5e0-48fe-9ece-7b4f83a666c0%40googlegroups.com.

[Kiran Jagtap]

Hi Jihoon,

first highly appreciated your help to debug !!!

I have checked both middle manager & overlord logs related to task, but no luck to find out root cause.

data ingestion is fine if I execute commands one after other. 

Since I have 3 middle manager, If I tried to execute 3 data load commands simultaneous, one command always fails which is last submitted.

In today's scenario : failed task id : "index_fiat_t4_2018-12-04T09:08:52.280Z"

Druid version : 0.12.3

Cluster size : 15 nodes

Each node : 2 core, 8 GB RAM

Broker : 2 nodes

Middle Manager : 3 nodes

Historical : 6 nodes

Overlord & coordinator : 2 nodes

zookeeper : 2 nodes

Middle Manager Task Error Log :

2018-12-04T09:08:52,482 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Submitting runnable for task[index_fiat_t4_2018-12-04T09:08:52.280Z]

2018-12-04T09:08:52,494 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Affirmative. Running task [index_fiat_t4_2018-12-04T09:08:52.280Z]

2018-12-04T09:08:52,553 INFO [forking-task-runner-0] io.druid.indexing.overlord.ForkingTaskRunner - Running command: java -cp conf/druid/_common:conf/druid/middleManager:lib/janino-2.7.6.jar:lib/netty-buffer-4.0.52.Final.jar:lib/jetty-servlets-9.3.19.v20170502.jar:lib/jackson-datatype-guava-2.4.6.jar:lib/aether-connector-file-0.9.0.M2.jar:lib/guava-16.0.1.jar:lib/reactive-streams-1.0.0.jar:lib/httpcore-4.4.3.jar:lib/maven-aether-provider-3.1.1.jar:lib/druid-indexing-hadoop-0.12.3.jar:lib/jersey-core-1.19.3.jar:lib/netty-resolver-dns-2.0.37.jar:lib/javax.el-3.0.0.jar:lib/jetty-server-9.3.19.v20170502.jar:lib/jackson-module-jaxb-annotations-2.4.6.jar:lib/slf4j-api-1.6.4.jar:lib/validation-api-1.1.0.Final.jar:lib/javax.inject-1.jar:lib/jetty-io-9.3.19.v20170502.jar:lib/log4j-api-2.5.jar:lib/zookeeper-3.4.10.jar:lib/maven-model-builder-3.1.1.jar:lib/aws-java-sdk-ec2-1.10.77.jar:lib/netty-common-4.0.52.Final.jar:lib/jackson-databind-2.4.6.jar:lib/config-magic-0.9.jar:lib/jersey-guice-1.19.3.jar:lib/commons-pool-1.6.jar:lib/aggdesigner-algorithm-6.0.jar:lib/java-xmlbuilder-1.1.jar:lib/curator-x-discovery-4.0.0.jar:lib/jackson-mapper-asl-1.9.13.jar:lib/netty-codec-http-4.0.52.Final.jar:lib/commons-pool2-2.2.jar:lib/jetty-client-9.3.19.v20170502.jar:lib/jackson-core-2.4.6.jar:lib/tesla-aether-0.0.5.jar:lib/druid-api-0.12.3.jar:lib/joni-2.1.11.jar:lib/jetty-util-9.3.19.v20170502.jar:lib/aopalliance-1.0.jar:lib/caffeine-2.5.5.jar:lib/avatica-core-1.10.0.jar:lib/protobuf-java-3.1.0.jar:lib/plexus-utils-3.0.15.jar:lib/aether-impl-0.9.0.M2.jar:lib/commons-math3-3.6.1.jar:lib/opencsv-2.3.jar:lib/calcite-linq4j-1.15.0.jar:lib/jackson-jaxrs-json-provider-2.4.6.jar:lib/calcite-core-1.15.0.jar:lib/guice-multibindings-4.1.0.jar:lib/curator-client-4.0.0.jar:lib/derby-10.11.1.1.jar:lib/guice-4.1.0.jar:lib/aether-connector-okhttp-0.0.9.jar:lib/jboss-logging-3.1.3.GA.jar:lib/netty-codec-4.0.52.Final.jar:lib/commons-lang-2.6.jar:lib/jetty-continuation-9.3.19.v20170502.jar:lib/jetty-http-9.3.19.v20170502.jar:lib/irc-api-1.0-0014.jar:lib/asm-5.2.jar:lib/netty-transport-native-epoll-4.0.52.Final-linux-x86_64.jar:lib/classmate-1.0.0.jar:lib/maven-settings-builder-3.1.1.jar:lib/commons-cli-1.2.jar:lib/json-path-2.1.0.jar:lib/plexus-interpolation-1.19.jar:lib/druid-hll-0.12.3.jar:lib/aether-spi-0.9.0.M2.jar:lib/maven-model-3.1.1.jar:lib/jackson-core-asl-1.9.13.jar:lib/jackson-dataformat-cbor-2.5.3.jar:lib/jersey-server-1.19.3.jar:lib/geoip2-0.4.0.jar:lib/jersey-servlet-1.19.3.jar:lib/okhttp-1.0.2.jar:lib/compress-lzf-1.0.4.jar:lib/aether-util-0.9.0.M2.jar:lib/curator-framework-4.0.0.jar:lib/jackson-jaxrs-base-2.4.6.jar:lib/netty-3.10.6.Final.jar:lib/asm-commons-5.2.jar:lib/maxminddb-0.2.0.jar:lib/asm-tree-5.2.jar:lib/icu4j-54.1.1.jar:lib/async-http-client-netty-utils-2.0.37.jar:lib/commons-dbcp-1.4.jar:lib/netty-transport-4.0.52.Final.jar:lib/maven-settings-3.1.1.jar:lib/async-http-client-2.0.37.jar:lib/airline-0.7.jar:lib/commons-io-2.5.jar:lib/netty-resolver-2.0.37.jar:lib/netty-handler-4.0.52.Final.jar:lib/base64-2.3.8.jar:lib/esri-geometry-api-2.0.0.jar:lib/jets3t-0.9.4.jar:lib/derbynet-10.11.1.1.jar:lib/log4j-jul-2.5.jar:lib/netty-reactive-streams-1.0.8.jar:lib/netty-codec-dns-2.0.37.jar:lib/jcodings-1.0.13.jar:lib/log4j-core-2.5.jar:lib/druid-indexing-service-0.12.3.jar:lib/mapdb-1.0.8.jar:lib/log4j-1.2-api-2.5.jar:lib/jcl-over-slf4j-1.7.12.jar:lib/guice-servlet-4.1.0.jar:lib/commons-compiler-2.7.6.jar:lib/jvm-attach-api-1.2.jar:lib/jetty-security-9.3.19.v20170502.jar:lib/disruptor-3.3.6.jar:lib/extendedset-0.12.3.jar:lib/commons-logging-1.1.1.jar:lib/antlr4-runtime-4.5.1.jar:lib/derbyclient-10.11.1.1.jar:lib/fastutil-8.1.0.jar:lib/aether-api-0.9.0.M2.jar:lib/jackson-datatype-joda-2.4.6.jar:lib/avatica-metrics-1.10.0.jar:lib/druid-server-0.12.3.jar:lib/hibernate-validator-5.1.3.Final.jar:lib/activation-1.1.1.jar:lib/aws-java-sdk-core-1.10.77.jar:lib/druid-console-0.0.2.jar:lib/joda-time-2.9.9.jar:lib/log4j-slf4j-impl-2.5.jar:lib/jline-0.9.94.jar:lib/jetty-proxy-9.3.19.v20170502.jar:lib/commons-lang3-3.2.jar:lib/jackson-jaxrs-smile-provider-2.4.6.jar:lib/RoaringBitmap-0.5.18.jar:lib/commons-codec-1.7.jar:lib/netty-all-4.0.52.Final.jar:lib/lz4-1.3.0.jar:lib/avatica-server-1.10.0.jar:lib/java-util-0.12.3.jar:lib/javax.el-api-3.0.0.jar:lib/jackson-annotations-2.4.6.jar:lib/druid-aws-common-0.12.3.jar:lib/bcprov-jdk15on-1.52.jar:lib/maven-repository-metadata-3.1.1.jar:lib/wagon-provider-api-2.4.jar:lib/jackson-jq-0.0.7.jar:lib/rhino-1.7R5.jar:lib/jdbi-2.63.1.jar:lib/druid-common-0.12.3.jar:lib/httpclient-4.5.1.jar:lib/commons-dbcp2-2.0.1.jar:lib/druid-processing-0.12.3.jar:lib/druid-services-0.12.3.jar:lib/jetty-servlet-9.3.19.v20170502.jar:lib/jackson-dataformat-smile-2.4.6.jar:lib/spymemcached-2.12.3.jar:lib/jsr311-api-1.1.1.jar:lib/jsr305-2.0.1.jar:lib/javax.servlet-api-3.1.0.jar:lib/druid-sql-0.12.3.jar:lib/curator-recipes-4.0.0.jar: -server -Xmx5g -Duser.timezone=UTC -Dfile.encoding=UTF-8 -Djava.util.logging.manager=org.apache.logging.log4j.jul.LogManager -Ddruid.indexer.logs.s3Bucket=epsilon-druid -Ddruid.indexer.task.baseTaskDir=var/druid/task -Ddruid.host={ip} -Ddruid.storage.bucket=epsilon-druid -Ddruid.discovery.curator.path=/epsilon-prod/discovery -Ddruid.metadata.storage.connector.password={password} -Ddruid.indexer.fork.property.druid.processing.numThreads=1 -Ddruid.emitter.logging.logLevel=info -Ddruid.storage.baseKey=druid/segments -Ddruid.emitter=logging -Ddruid.indexer.fork.property.druid.processing.buffer.sizeBytes=419430400 -Duser.timezone=UTC -Ddruid.cache.sizeInBytes=10485760 -Ddruid.cache.readBufferSize=10485760 -Ddruid.indexer.logs.s3Prefix=druid/indexing-logs -Dfile.encoding.pkg=sun.io -Ddruid.selectors.coordinator.serviceName=druid/epsilon-prod/coordinator -Ddruid.selectors.indexing.serviceName=druid/epsilon-prod/overlord -Ddruid.indexing.doubleStorage=double -Ddruid.port=8091 -Ddruid.request.logging.type=emitter -Ddruid.server.http.numThreads=40 -Ddruid.worker.capacity=1 -Ddruid.cache.type=local -Ddruid.request.logging.feed=druid_requests -Ddruid.s3.accessKey={key} -Ddruid.s3.secretKey={scecretekey} -Ddruid.service=druid/epsilon-prod/middleManager -Ddruid.metadata.storage.connector.user=druid -Ddruid.metadata.storage.type=mysql -Ddruid.metadata.storage.connector.connectURI=jdbc:{rdsip} -Djava.io.tmpdir=/tmp -Ddruid.extensions.loadList=["druid-s3-extensions", "druid-histogram", "mysql-metadata-storage"] -Ddruid.sql.enable=true -Ddruid.startup.logging.logProperties=true -Ddruid.zk.service.host={zookeeper1},{zookeeper2} -Ddruid.monitoring.monitors=["io.druid.java.util.metrics.JvmMonitor"] -Ddruid.zk.paths.base=/druid/epsilon-prod -Dfile.encoding=UTF-8 -Ddruid.indexer.task.defaultHadoopCoordinates=["org.apache.hadoop:hadoop-client:2.7.3"] -Ddruid.storage.type=s3 -Ddruid.indexer.task.hadoopWorkingPath=var/druid/hadoop-tmp -Ddruid.indexer.logs.type=s3 -Ddruid.processing.numThreads=1 -Ddruid.processing.buffer.sizeBytes=419430400 -Ddruid.metrics.emitter.dimension.dataSource=fiat_t4 -Ddruid.metrics.emitter.dimension.taskId=index_fiat_t4_2018-12-04T09:08:52.280Z -Ddruid.host={ip} -Ddruid.port=8100 -Ddruid.tlsPort=-1 io.druid.cli.Main internal peon var/druid/task/index_fiat_t4_2018-12-04T09:08:52.280Z/task.json var/druid/task/index_fiat_t4_2018-12-04T09:08:52.280Z/a46b6db2-5874-4504-8e10-2f454e612319/status.json

2018-12-04T09:08:52,575 INFO [forking-task-runner-0] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_fiat_t4_2018-12-04T09:08:52.280Z] location changed to [TaskLocation{host='{ip}', port=8100, tlsPort=-1}].

2018-12-04T09:08:52,575 INFO [forking-task-runner-0] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_fiat_t4_2018-12-04T09:08:52.280Z] status changed to [RUNNING].

2018-12-04T09:08:52,576 INFO [forking-task-runner-0] io.druid.indexing.overlord.ForkingTaskRunner - Logging task index_fiat_t4_2018-12-04T09:08:52.280Z output to: var/druid/task/index_fiat_t4_2018-12-04T09:08:52.280Z/log

2018-12-04T09:08:52,577 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Updating task [index_fiat_t4_2018-12-04T09:08:52.280Z] announcement with location [TaskLocation{host='{ip}', port=8100, tlsPort=-1}]

2018-12-04T09:10:30,740 INFO [qtp2071364564-62] io.druid.indexing.overlord.ForkingTaskRunner - Killing process for task: index_fiat_t4_2018-12-04T09:08:52.280Z

2018-12-04T09:10:30,769 INFO [forking-task-runner-0] io.druid.storage.s3.S3TaskLogs - Pushing task log var/druid/task/index_fiat_t4_2018-12-04T09:08:52.280Z/log to: druid/indexing-logs/index_fiat_t4_2018-12-04T09:08:52.280Z/log

2018-12-04T09:10:31,349 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_191]

at java.io.BufferedInputStream.read1(BufferedInputStream.java:291) ~[?:1.8.0_191]

at java.io.BufferedInputStream.read(BufferedInputStream.java:345) ~[?:1.8.0_191]

at java.io.FilterInputStream.read(FilterInputStream.java:107) ~[?:1.8.0_191]

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.3.jar:0.12.3]

at io.druid.indexing.overlord.ForkingTaskRunner$1.call(ForkingTaskRunner.java:224) [druid-indexing-service-0.12.3.jar:0.12.3]

at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_191]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_191]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_191]

at java.lang.Thread.run(Thread.java:748) [?:1.8.0_191]

2018-12-04T09:10:31,360 INFO [forking-task-runner-0] io.druid.indexing.overlord.ForkingTaskRunner - Removing task directory: var/druid/task/index_fiat_t4_2018-12-04T09:08:52.280Z

2018-12-04T09:10:31,422 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Job's finished. Completed [index_fiat_t4_2018-12-04T09:08:52.280Z] with status [FAILED]

Overlord Task Error Log :

2018-12-04T09:08:52,280 INFO [qtp634210724-70] io.druid.indexing.overlord.MetadataTaskStorage - Inserting task index_fiat_t4_2018-12-04T09:08:52.280Z with status: TaskStatus{id=index_fiat_t4_2018-12-04T09:08:52.280Z, status=RUNNING, duration=-1}

2018-12-04T09:08:52,292 INFO [qtp634210724-70] io.druid.indexing.overlord.TaskLockbox - Adding task[index_fiat_t4_2018-12-04T09:08:52.280Z] to activeTasks

2018-12-04T09:08:52,292 INFO [TaskQueue-Manager] io.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_fiat_t4_2018-12-04T09:08:52.280Z]: LockListAction{}

2018-12-04T09:08:52,293 INFO [TaskQueue-Manager] io.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_fiat_t4_2018-12-04T09:08:52.280Z]: LockTryAcquireAction{lockType=EXCLUSIVE, interval=2018-08-01T00:00:00.000Z/2018-11-30T00:00:00.000Z}

2018-12-04T09:08:52,293 INFO [TaskQueue-Manager] io.druid.indexing.overlord.TaskLockbox - Added task[index_fiat_t4_2018-12-04T09:08:52.280Z] to TaskLock[index_fiat_t4_2018-12-04T09:08:52.280Z]

2018-12-04T09:08:52,293 INFO [TaskQueue-Manager] io.druid.indexing.overlord.MetadataTaskStorage - Adding lock on interval[2018-08-01T00:00:00.000Z/2018-11-30T00:00:00.000Z] version[2018-12-04T09:08:52.293Z] for task: index_fiat_t4_2018-12-04T09:08:52.280Z

2018-12-04T09:08:52,303 INFO [TaskQueue-Manager] io.druid.indexing.overlord.TaskQueue - Asking taskRunner to run: index_fiat_t4_2018-12-04T09:08:52.280Z

2018-12-04T09:08:52,303 INFO [TaskQueue-Manager] io.druid.indexing.overlord.RemoteTaskRunner - Added pending task index_fiat_t4_2018-12-04T09:08:52.280Z

2018-12-04T09:08:52,304 INFO [rtr-pending-tasks-runner-0] io.druid.indexing.overlord.RemoteTaskRunner - Coordinator asking Worker[{ip}:8091] to add task[index_fiat_t4_2018-12-04T09:08:52.280Z]

2018-12-04T09:08:52,310 INFO [rtr-pending-tasks-runner-0] io.druid.indexing.overlord.RemoteTaskRunner - Task index_fiat_t4_2018-12-04T09:08:52.280Z switched from pending to running (on [{ip}:8091])

2018-12-04T09:08:52,310 INFO [rtr-pending-tasks-runner-0] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_fiat_t4_2018-12-04T09:08:52.280Z] status changed to [RUNNING].

2018-12-04T09:08:52,495 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Worker[{ip}:8091] wrote RUNNING status for task [index_fiat_t4_2018-12-04T09:08:52.280Z] on [TaskLocation{host='null', port=-1, tlsPort=-1}]

2018-12-04T09:08:52,584 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Worker[{ip}:8091] wrote RUNNING status for task [index_fiat_t4_2018-12-04T09:08:52.280Z] on [TaskLocation{host='{ip}', port=8100, tlsPort=-1}]

2018-12-04T09:08:52,584 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_fiat_t4_2018-12-04T09:08:52.280Z] location changed to [TaskLocation{host='{ip}', port=8100, tlsPort=-1}].

2018-12-04T09:08:56,930 INFO [qtp634210724-103] io.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_fiat_t4_2018-12-04T09:08:52.280Z]: LockListAction{}

2018-12-04T09:08:57,006 INFO [qtp634210724-105] io.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_fiat_t4_2018-12-04T09:08:52.280Z]: LockListAction{}

2018-12-04T09:10:30,525 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskLockbox - Removing task[index_fiat_t4_2018-12-04T09:08:52.280Z] from activeTasks

2018-12-04T09:10:30,526 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskLockbox - Removing task[index_fiat_t4_2018-12-04T09:08:52.280Z] from TaskLock[index_fiat_t4_2018-12-04T09:08:52.280Z]

2018-12-04T09:10:30,526 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskLockbox - TaskLock is now empty: TaskLock{type=EXCLUSIVE, groupId=index_fiat_t4_2018-12-04T09:08:52.280Z, dataSource=fiat_t4, interval=2018-08-01T00:00:00.000Z/2018-11-30T00:00:00.000Z, version=2018-12-04T09:08:52.293Z, priority=50, revoked=false}

2018-12-04T09:10:30,543 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.MetadataTaskStorage - Deleting TaskLock with id[225]: TaskLock{type=EXCLUSIVE, groupId=index_fiat_t4_2018-12-04T09:08:52.280Z, dataSource=fiat_t4, interval=2018-08-01T00:00:00.000Z/2018-11-30T00:00:00.000Z, version=2018-12-04T09:08:52.293Z, priority=50, revoked=false}

2018-12-04T09:10:30,779 INFO [TaskQueue-Manager] io.druid.indexing.overlord.RemoteTaskRunner - Sent shutdown message to worker: {ip}:8091, status 200 OK, response: {"task":"index_fiat_t4_2018-12-04T09:08:52.280Z"}

2018-12-04T09:10:31,423 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Worker[{ip}:8091] wrote FAILED status for task [index_fiat_t4_2018-12-04T09:08:52.280Z] on [TaskLocation{host='{ip}', port=8100, tlsPort=-1}]

2018-12-04T09:10:31,423 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Worker[{ip}:8091] completed task[index_fiat_t4_2018-12-04T09:08:52.280Z] with status[FAILED]

2018-12-04T09:10:31,424 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskQueue - Received FAILED status for task: index_fiat_t4_2018-12-04T09:08:52.280Z

2018-12-04T09:10:31,424 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Cleaning up task[index_fiat_t4_2018-12-04T09:08:52.280Z] on worker[{ip}:8091]

2018-12-04T09:10:31,429 WARN [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskQueue - Unknown task completed: index_fiat_t4_2018-12-04T09:08:52.280Z

2018-12-04T09:10:31,429 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskQueue - Task FAILED: AbstractTask{id='index_fiat_t4_2018-12-04T09:08:52.280Z', groupId='index_fiat_t4_2018-12-04T09:08:52.280Z', taskResource=TaskResource{availabilityGroup='index_fiat_t4_2018-12-04T09:08:52.280Z', requiredCapacity=1}, dataSource='fiat_t4', context={}} (98910 run duration)

2018-12-04T09:10:31,429 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_fiat_t4_2018-12-04T09:08:52.280Z] status changed to [FAILED].

2018-12-04T09:10:31,429 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Task[index_fiat_t4_2018-12-04T09:08:52.280Z] went bye bye.

Any idea/help would be really appreciated ... since It looks like our druid cluster is not completely utilising all 3 middle manager nodes.

Thanks,

Kiran

[Jihoon Son]

Thanks Kiran,

the symptom you described sounds really strange.. I haven't heard about such behavior before.

I'm sorry, but the above overlord logs are not enough. It seems that something happened but 'grep' filtered out those logs.

Would you please check the overlord logs again if there's anything interesting?

Or, if you can, please post the full logs omitted in the below part.

Thanks for your patience.

Jihoon

2018-12-04T09:08:52,584 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_fiat_t4_2018-12-04T09:08:52.280Z] location changed to [TaskLocation{host='{ip}', port=8100, tlsPort=-1}].

2018-12-04T09:08:56,930 INFO [qtp634210724-103] io.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_fiat_t4_2018-12-04T09:08:52.280Z]: LockListAction{}

2018-12-04T09:08:57,006 INFO [qtp634210724-105] io.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_fiat_t4_2018-12-04T09:08:52.280Z]: LockListAction{}

// there should be something interesting

2018-12-04T09:10:30,525 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskLockbox - Removing task[index_fiat_t4_2018-12-04T09:08:52.280Z] from activeTasks

2018-12-04T09:10:30,526 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskLockbox - Removing task[index_fiat_t4_2018-12-04T09:08:52.280Z] from TaskLock[index_fiat_t4_2018-12-04T09:08:52.280Z]

--

You received this message because you are subscribed to the Google Groups "Druid User" group.
To unsubscribe from this group and stop receiving emails from it, send an email to druid-user+...@googlegroups.com.
To post to this group, send email to druid...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/druid-user/3068fd8c-3d25-4094-9f15-c514539b73a9%40googlegroups.com.

[Kiran Jagtap]

Hi Jihoon

Something is strange happening with our druid cluster index jobs, 

and I'm not able to figure out from last couple of days.

Druid version : 0.12.3

Cluster size : 20 nodes

Each node : 2 core, 8 GB RAM

Nodes distributions :

Zookeeper : 3 nodes

coordinator :  1 node

overlord : 1 node

middlemanager : 4 nodes

historical : 8 nodes

broker : 3 nodes

Operation : Load data from s3 location csv files with index job into druid 

Success Scenario :

If I give just 1-2 s3 files, data loaded successfully. 

Failed scenario :

If I give around 9-10 s3 files, index jobs getting failed.

Each data file size is less than 15MB

(If I load these files one by one, data load is successful)

Overlord Complete Log :

2018-12-07T10:01:28,049 INFO [main] io.druid.guice.PropertiesModule - Loading properties from common.runtime.properties

2018-12-07T10:01:28,052 INFO [main] io.druid.guice.PropertiesModule - Loading properties from runtime.properties

2018-12-07T10:01:28,077 INFO [main] org.hibernate.validator.internal.util.Version - HV000001: Hibernate Validator 5.1.3.Final

2018-12-07T10:01:28,466 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.guice.ExtensionsConfig] from props[druid.extensions.] as [ExtensionsConfig{searchCurrentClassloader=true, directory='extensions', hadoopDependenciesDir='hadoop-dependencies', hadoopContainerDruidClasspath='null', addExtensionsToHadoopContainer=false, loadList=[druid-s3-extensions, druid-histogram, mysql-metadata-storage]}]

2018-12-07T10:01:28,519 INFO [main] io.druid.initialization.Initialization - Loading extension [druid-s3-extensions] for class [interface io.druid.cli.CliCommandCreator]

2018-12-07T10:01:28,528 INFO [main] io.druid.initialization.Initialization - added URL[file:/opt/druid-0.12.3/extensions/druid-s3-extensions/druid-s3-extensions-0.12.3.jar]

2018-12-07T10:01:28,529 INFO [main] io.druid.initialization.Initialization - Loading extension [druid-histogram] for class [interface io.druid.cli.CliCommandCreator]

2018-12-07T10:01:28,529 INFO [main] io.druid.initialization.Initialization - added URL[file:/opt/druid-0.12.3/extensions/druid-histogram/druid-histogram-0.12.3.jar]

2018-12-07T10:01:28,530 INFO [main] io.druid.initialization.Initialization - Loading extension [mysql-metadata-storage] for class [interface io.druid.cli.CliCommandCreator]

2018-12-07T10:01:28,530 INFO [main] io.druid.initialization.Initialization - added URL[file:/opt/druid-0.12.3/extensions/mysql-metadata-storage/mysql-connector-java-5.1.38.jar]

2018-12-07T10:01:28,530 INFO [main] io.druid.initialization.Initialization - added URL[file:/opt/druid-0.12.3/extensions/mysql-metadata-storage/mysql-metadata-storage-0.12.3.jar]

2018-12-07T10:01:28,579 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.guice.ModulesConfig] from props[druid.modules.] as [ModulesConfig{excludeList=[]}]

2018-12-07T10:01:28,661 INFO [main] io.druid.initialization.Initialization - Loading extension [druid-s3-extensions] for class [interface io.druid.initialization.DruidModule]

2018-12-07T10:01:28,743 INFO [main] io.druid.initialization.Initialization - Adding implementation [io.druid.storage.s3.S3StorageDruidModule] for class [interface io.druid.initialization.DruidModule] from local file system extension

2018-12-07T10:01:28,744 INFO [main] io.druid.initialization.Initialization - Adding implementation [io.druid.firehose.s3.S3FirehoseDruidModule] for class [interface io.druid.initialization.DruidModule] from local file system extension

2018-12-07T10:01:28,744 INFO [main] io.druid.initialization.Initialization - Loading extension [druid-histogram] for class [interface io.druid.initialization.DruidModule]

2018-12-07T10:01:28,746 INFO [main] io.druid.initialization.Initialization - Adding implementation [io.druid.query.aggregation.histogram.ApproximateHistogramDruidModule] for class [interface io.druid.initialization.DruidModule] from local file system extension

2018-12-07T10:01:28,746 INFO [main] io.druid.initialization.Initialization - Loading extension [mysql-metadata-storage] for class [interface io.druid.initialization.DruidModule]

2018-12-07T10:01:28,747 INFO [main] io.druid.initialization.Initialization - Adding implementation [io.druid.metadata.storage.mysql.MySQLMetadataStorageModule] for class [interface io.druid.initialization.DruidModule] from local file system extension

1.935: [GC (Allocation Failure) 1.936: [ParNew: 209792K->19666K(235968K), 0.0433121 secs] 209792K->19666K(4168128K), 0.0433634 secs] [Times: user=0.08 sys=0.01, real=0.04 secs] 

1.983: [GC (CMS Initial Mark) [1 CMS-initial-mark: 0K(3932160K)] 25926K(4168128K), 0.0055189 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

1.989: [CMS-concurrent-mark-start]

2.006: [CMS-concurrent-mark: 0.018/0.018 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 

2.009: [CMS-concurrent-preclean-start]

2.033: [CMS-concurrent-preclean: 0.015/0.015 secs] [Times: user=0.04 sys=0.00, real=0.03 secs] 

2.033: [CMS-concurrent-abortable-preclean-start]

2018-12-07T10:01:29,896 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.metadata.MetadataStorageConnectorConfig] from props[druid.metadata.storage.connector.] as [DbConnectorConfig{createTables=true, connectURI='j{jdbcurl}', user='druid', passwordProvider=io.druid.metadata.DefaultPasswordProvider}]

2018-12-07T10:01:29,925 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.metadata.MetadataStorageTablesConfig] from props[druid.metadata.storage.tables.] as [io.druid.metadata.MetadataStorageTablesConfig@2c16fadb]

2018-12-07T10:01:29,944 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.metadata.storage.mysql.MySQLConnectorConfig] from props[druid.metadata.mysql.ssl.] as [MySQLConnectorConfig{useSSL='false', clientCertificateKeyStoreUrl='null', clientCertificateKeyStoreType='null', verifyServerCertificate='false', trustCertificateKeyStoreUrl='null', trustCertificateKeyStoreType='null', enabledSSLCipherSuites=null, enabledTLSProtocols=null}]

2018-12-07T10:01:30,044 INFO [main] io.druid.metadata.storage.mysql.MySQLConnector - Configured MySQL as metadata storage

2018-12-07T10:01:30,104 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.common.config.ConfigManagerConfig] from props[druid.manager.config.] as [io.druid.common.config.ConfigManagerConfig@3cd59ef5]

2018-12-07T10:01:30,116 INFO [main] io.druid.metadata.storage.mysql.MySQLConnector - Configured MySQL as metadata storage

2018-12-07T10:01:30,154 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.DruidNode] from props[druid.] as [DruidNode{serviceName='druid/epsilon-prod/overlord', host='{overlord_IP}', port=-1, plaintextPort=8090, enablePlaintextPort=true, tlsPort=-1, enableTlsPort=false}]

2018-12-07T10:01:30,157 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.java.util.emitter.core.LoggingEmitterConfig] from props[druid.emitter.logging.] as [LoggingEmitterConfig{loggerClass='io.druid.java.util.emitter.core.LoggingEmitter', logLevel='debug'}]

2018-12-07T10:01:30,171 INFO [main] io.druid.server.emitter.EmitterModule - Underlying emitter for ServiceEmitter: LoggingEmitter{log=Logger{name=[io.druid.java.util.emitter.core.LoggingEmitter], class[class org.apache.logging.slf4j.Log4jLogger]}, level=DEBUG}

2018-12-07T10:01:30,172 INFO [main] io.druid.server.emitter.EmitterModule - Extra service dimensions: {version=0.12.3}

2018-12-07T10:01:30,174 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.audit.SQLAuditManagerConfig] from props[druid.audit.manager.] as [io.druid.server.audit.SQLAuditManagerConfig@8bffb8b]

2018-12-07T10:01:30,186 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.curator.CuratorConfig] from props[druid.zk.service.] as [io.druid.curator.CuratorConfig@35dd9ed3]

2018-12-07T10:01:30,196 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.curator.ExhibitorConfig] from props[druid.exhibitor.service.] as [io.druid.curator.ExhibitorConfig@71dfcf21]

2018-12-07T10:01:30,253 INFO [main] org.apache.curator.utils.Compatibility - Running in ZooKeeper 3.4.x compatibility mode

2018-12-07T10:01:30,255 WARN [main] org.apache.curator.retry.ExponentialBackoffRetry - maxRetries too large (30). Pinning to 29

2018-12-07T10:01:30,287 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.initialization.ZkPathsConfig] from props[druid.zk.paths.] as [io.druid.server.initialization.ZkPathsConfig@1845610a]

2018-12-07T10:01:30,289 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[interface io.druid.server.security.Escalator] from props[druid.escalator.] as [io.druid.server.security.NoopEscalator@28e19366]

2018-12-07T10:01:30,297 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.security.AuthConfig] from props[druid.auth.] as [AuthConfig{authenticatorChain=null, authorizers=null, allowUnauthenticatedHttpOptions=false}]

2018-12-07T10:01:30,302 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.metrics.DruidMonitorSchedulerConfig] from props[druid.monitoring.] as [io.druid.server.metrics.DruidMonitorSchedulerConfig@47fbc56]

2018-12-07T10:01:30,306 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.metrics.MonitorsConfig] from props[druid.monitoring.] as [MonitorsConfig{monitors=[class io.druid.java.util.metrics.JvmMonitor]}]

2018-12-07T10:01:30,320 INFO [main] io.druid.server.metrics.MetricsModule - Adding monitor[io.druid.java.util.metrics.JvmMonitor@2d9f64c9]

2018-12-07T10:01:30,320 INFO [main] io.druid.server.metrics.MetricsModule - Adding monitor[io.druid.server.initialization.jetty.JettyServerModule$JettyMonitor@715d6168]

2018-12-07T10:01:30,323 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.log.StartupLoggingConfig] from props[druid.startup.logging.] as [io.druid.server.log.StartupLoggingConfig@7be71476]

2018-12-07T10:01:30,324 INFO [main] io.druid.cli.CliOverlord - Starting up with processors[2], memory[4,268,163,072], maxMemory[4,268,163,072].

2018-12-07T10:01:30,325 INFO [main] io.druid.cli.CliOverlord - * awt.toolkit: sun.awt.X11.XToolkit

2018-12-07T10:01:30,325 INFO [main] io.druid.cli.CliOverlord - * druid.cache.readBufferSize: 10485760

2018-12-07T10:01:30,325 INFO [main] io.druid.cli.CliOverlord - * druid.cache.sizeInBytes: 10485760

2018-12-07T10:01:30,325 INFO [main] io.druid.cli.CliOverlord - * druid.cache.type: local

2018-12-07T10:01:30,325 INFO [main] io.druid.cli.CliOverlord - * druid.discovery.curator.path: /epsilon-prod/discovery

2018-12-07T10:01:30,325 INFO [main] io.druid.cli.CliOverlord - * druid.emitter: logging

2018-12-07T10:01:30,325 INFO [main] io.druid.cli.CliOverlord - * druid.emitter.logging.logLevel: debug

2018-12-07T10:01:30,325 INFO [main] io.druid.cli.CliOverlord - * druid.extensions.loadList: ["druid-s3-extensions", "druid-histogram", "mysql-metadata-storage"]

2018-12-07T10:01:30,325 INFO [main] io.druid.cli.CliOverlord - * druid.host: {overlord_IP}

2018-12-07T10:01:30,325 INFO [main] io.druid.cli.CliOverlord - * druid.indexer.logs.s3Bucket: {s3_bucket}

2018-12-07T10:01:30,325 INFO [main] io.druid.cli.CliOverlord - * druid.indexer.logs.s3Prefix: druid/indexing-logs

2018-12-07T10:01:30,326 INFO [main] io.druid.cli.CliOverlord - * druid.indexer.logs.type: s3

2018-12-07T10:01:30,326 INFO [main] io.druid.cli.CliOverlord - * druid.indexer.queue.startDelay: PT30S

2018-12-07T10:01:30,326 INFO [main] io.druid.cli.CliOverlord - * druid.indexer.runner.type: remote

2018-12-07T10:01:30,326 INFO [main] io.druid.cli.CliOverlord - * druid.indexer.storage.type: metadata

2018-12-07T10:01:30,326 INFO [main] io.druid.cli.CliOverlord - * druid.indexing.doubleStorage: double

2018-12-07T10:01:30,326 INFO [main] io.druid.cli.CliOverlord - * druid.metadata.storage.connector.connectURI: {jdbc url}

2018-12-07T10:01:30,326 INFO [main] io.druid.cli.CliOverlord - * druid.metadata.storage.connector.password: <masked>

2018-12-07T10:01:30,326 INFO [main] io.druid.cli.CliOverlord - * druid.metadata.storage.connector.user: druid

2018-12-07T10:01:30,326 INFO [main] io.druid.cli.CliOverlord - * druid.metadata.storage.type: mysql

2018-12-07T10:01:30,326 INFO [main] io.druid.cli.CliOverlord - * druid.monitoring.monitors: ["io.druid.java.util.metrics.JvmMonitor"]

2018-12-07T10:01:30,326 INFO [main] io.druid.cli.CliOverlord - * druid.port: 8090

2018-12-07T10:01:30,326 INFO [main] io.druid.cli.CliOverlord - * druid.request.logging.feed: druid_requests

2018-12-07T10:01:30,326 INFO [main] io.druid.cli.CliOverlord - * druid.request.logging.type: emitter

2018-12-07T10:01:30,326 INFO [main] io.druid.cli.CliOverlord - * druid.s3.accessKey: {accesskey}

2018-12-07T10:01:30,327 INFO [main] io.druid.cli.CliOverlord - * druid.s3.secretKey: <masked>

2018-12-07T10:01:30,327 INFO [main] io.druid.cli.CliOverlord - * druid.selectors.coordinator.serviceName: druid/epsilon-prod/coordinator

2018-12-07T10:01:30,327 INFO [main] io.druid.cli.CliOverlord - * druid.selectors.indexing.serviceName: druid/epsilon-prod/overlord

2018-12-07T10:01:30,327 INFO [main] io.druid.cli.CliOverlord - * druid.service: druid/epsilon-prod/overlord

2018-12-07T10:01:30,327 INFO [main] io.druid.cli.CliOverlord - * druid.sql.enable: true

2018-12-07T10:01:30,327 INFO [main] io.druid.cli.CliOverlord - * druid.startup.logging.logProperties: true

2018-12-07T10:01:30,327 INFO [main] io.druid.cli.CliOverlord - * druid.storage.baseKey: druid/segments

2018-12-07T10:01:30,327 INFO [main] io.druid.cli.CliOverlord - * druid.storage.bucket: {s3 bucket}

2018-12-07T10:01:30,327 INFO [main] io.druid.cli.CliOverlord - * druid.storage.type: s3

2018-12-07T10:01:30,327 INFO [main] io.druid.cli.CliOverlord - * druid.zk.paths.base: /druid/epsilon-prod

2018-12-07T10:01:30,327 INFO [main] io.druid.cli.CliOverlord - * druid.zk.service.host: {zookeeperIp1},{zookeeperIp2},{zookeeperIp3}

2018-12-07T10:01:30,327 INFO [main] io.druid.cli.CliOverlord - * file.encoding: UTF-8

2018-12-07T10:01:30,328 INFO [main] io.druid.cli.CliOverlord - * file.encoding.pkg: sun.io

2018-12-07T10:01:30,328 INFO [main] io.druid.cli.CliOverlord - * file.separator: /

2018-12-07T10:01:30,328 INFO [main] io.druid.cli.CliOverlord - * java.awt.graphicsenv: sun.awt.X11GraphicsEnvironment

2018-12-07T10:01:30,328 INFO [main] io.druid.cli.CliOverlord - * java.awt.printerjob: sun.print.PSPrinterJob

2018-12-07T10:01:30,328 INFO [main] io.druid.cli.CliOverlord - * java.class.path: conf/druid/_common:conf/druid/overlord:lib/janino-2.7.6.jar:lib/netty-buffer-4.0.52.Final.jar:lib/jetty-servlets-9.3.19.v20170502.jar:lib/jackson-datatype-guava-2.4.6.jar:lib/aether-connector-file-0.9.0.M2.jar:lib/guava-16.0.1.jar:lib/reactive-streams-1.0.0.jar:lib/httpcore-4.4.3.jar:lib/maven-aether-provider-3.1.1.jar:lib/druid-indexing-hadoop-0.12.3.jar:lib/jersey-core-1.19.3.jar:lib/netty-resolver-dns-2.0.37.jar:lib/javax.el-3.0.0.jar:lib/jetty-server-9.3.19.v20170502.jar:lib/jackson-module-jaxb-annotations-2.4.6.jar:lib/slf4j-api-1.6.4.jar:lib/validation-api-1.1.0.Final.jar:lib/javax.inject-1.jar:lib/jetty-io-9.3.19.v20170502.jar:lib/log4j-api-2.5.jar:lib/zookeeper-3.4.10.jar:lib/maven-model-builder-3.1.1.jar:lib/aws-java-sdk-ec2-1.10.77.jar:lib/netty-common-4.0.52.Final.jar:lib/jackson-databind-2.4.6.jar:lib/config-magic-0.9.jar:lib/jersey-guice-1.19.3.jar:lib/commons-pool-1.6.jar:lib/aggdesigner-algorithm-6.0.jar:lib/java-xmlbuilder-1.1.jar:lib/curator-x-discovery-4.0.0.jar:lib/jackson-mapper-asl-1.9.13.jar:lib/netty-codec-http-4.0.52.Final.jar:lib/commons-pool2-2.2.jar:lib/jetty-client-9.3.19.v20170502.jar:lib/jackson-core-2.4.6.jar:lib/tesla-aether-0.0.5.jar:lib/druid-api-0.12.3.jar:lib/joni-2.1.11.jar:lib/jetty-util-9.3.19.v20170502.jar:lib/aopalliance-1.0.jar:lib/caffeine-2.5.5.jar:lib/avatica-core-1.10.0.jar:lib/protobuf-java-3.1.0.jar:lib/plexus-utils-3.0.15.jar:lib/aether-impl-0.9.0.M2.jar:lib/commons-math3-3.6.1.jar:lib/opencsv-2.3.jar:lib/calcite-linq4j-1.15.0.jar:lib/jackson-jaxrs-json-provider-2.4.6.jar:lib/calcite-core-1.15.0.jar:lib/guice-multibindings-4.1.0.jar:lib/curator-client-4.0.0.jar:lib/derby-10.11.1.1.jar:lib/guice-4.1.0.jar:lib/aether-connector-okhttp-0.0.9.jar:lib/jboss-logging-3.1.3.GA.jar:lib/netty-codec-4.0.52.Final.jar:lib/commons-lang-2.6.jar:lib/jetty-continuation-9.3.19.v20170502.jar:lib/jetty-http-9.3.19.v20170502.jar:lib/irc-api-1.0-0014.jar:lib/asm-5.2.jar:lib/netty-transport-native-epoll-4.0.52.Final-linux-x86_64.jar:lib/classmate-1.0.0.jar:lib/maven-settings-builder-3.1.1.jar:lib/commons-cli-1.2.jar:lib/json-path-2.1.0.jar:lib/plexus-interpolation-1.19.jar:lib/druid-hll-0.12.3.jar:lib/aether-spi-0.9.0.M2.jar:lib/maven-model-3.1.1.jar:lib/jackson-core-asl-1.9.13.jar:lib/jackson-dataformat-cbor-2.5.3.jar:lib/jersey-server-1.19.3.jar:lib/geoip2-0.4.0.jar:lib/jersey-servlet-1.19.3.jar:lib/okhttp-1.0.2.jar:lib/compress-lzf-1.0.4.jar:lib/aether-util-0.9.0.M2.jar:lib/curator-framework-4.0.0.jar:lib/jackson-jaxrs-base-2.4.6.jar:lib/netty-3.10.6.Final.jar:lib/asm-commons-5.2.jar:lib/maxminddb-0.2.0.jar:lib/asm-tree-5.2.jar:lib/icu4j-54.1.1.jar:lib/async-http-client-netty-utils-2.0.37.jar:lib/commons-dbcp-1.4.jar:lib/netty-transport-4.0.52.Final.jar:lib/maven-settings-3.1.1.jar:lib/async-http-client-2.0.37.jar:lib/airline-0.7.jar:lib/commons-io-2.5.jar:lib/netty-resolver-2.0.37.jar:lib/netty-handler-4.0.52.Final.jar:lib/base64-2.3.8.jar:lib/esri-geometry-api-2.0.0.jar:lib/jets3t-0.9.4.jar:lib/derbynet-10.11.1.1.jar:lib/log4j-jul-2.5.jar:lib/netty-reactive-streams-1.0.8.jar:lib/netty-codec-dns-2.0.37.jar:lib/jcodings-1.0.13.jar:lib/log4j-core-2.5.jar:lib/druid-indexing-service-0.12.3.jar:lib/mapdb-1.0.8.jar:lib/log4j-1.2-api-2.5.jar:lib/jcl-over-slf4j-1.7.12.jar:lib/guice-servlet-4.1.0.jar:lib/commons-compiler-2.7.6.jar:lib/jvm-attach-api-1.2.jar:lib/jetty-security-9.3.19.v20170502.jar:lib/disruptor-3.3.6.jar:lib/extendedset-0.12.3.jar:lib/commons-logging-1.1.1.jar:lib/antlr4-runtime-4.5.1.jar:lib/derbyclient-10.11.1.1.jar:lib/fastutil-8.1.0.jar:lib/aether-api-0.9.0.M2.jar:lib/jackson-datatype-joda-2.4.6.jar:lib/avatica-metrics-1.10.0.jar:lib/druid-server-0.12.3.jar:lib/hibernate-validator-5.1.3.Final.jar:lib/activation-1.1.1.jar:lib/aws-java-sdk-core-1.10.77.jar:lib/druid-console-0.0.2.jar:lib/joda-time-2.9.9.jar:lib/log4j-slf4j-impl-2.5.jar:lib/jline-0.9.94.jar:lib/jetty-proxy-9.3.19.v20170502.jar:lib/commons-lang3-3.2.jar:lib/jackson-jaxrs-smile-provider-2.4.6.jar:lib/RoaringBitmap-0.5.18.jar:lib/commons-codec-1.7.jar:lib/netty-all-4.0.52.Final.jar:lib/lz4-1.3.0.jar:lib/avatica-server-1.10.0.jar:lib/java-util-0.12.3.jar:lib/javax.el-api-3.0.0.jar:lib/jackson-annotations-2.4.6.jar:lib/druid-aws-common-0.12.3.jar:lib/bcprov-jdk15on-1.52.jar:lib/maven-repository-metadata-3.1.1.jar:lib/wagon-provider-api-2.4.jar:lib/jackson-jq-0.0.7.jar:lib/rhino-1.7R5.jar:lib/jdbi-2.63.1.jar:lib/druid-common-0.12.3.jar:lib/httpclient-4.5.1.jar:lib/commons-dbcp2-2.0.1.jar:lib/druid-processing-0.12.3.jar:lib/druid-services-0.12.3.jar:lib/jetty-servlet-9.3.19.v20170502.jar:lib/jackson-dataformat-smile-2.4.6.jar:lib/spymemcached-2.12.3.jar:lib/jsr311-api-1.1.1.jar:lib/jsr305-2.0.1.jar:lib/javax.servlet-api-3.1.0.jar:lib/druid-sql-0.12.3.jar:lib/curator-recipes-4.0.0.jar:

2018-12-07T10:01:30,328 INFO [main] io.druid.cli.CliOverlord - * java.class.version: 52.0

2018-12-07T10:01:30,328 INFO [main] io.druid.cli.CliOverlord - * java.endorsed.dirs: /usr/lib/jvm/java-8-openjdk-amd64/jre/lib/endorsed

2018-12-07T10:01:30,328 INFO [main] io.druid.cli.CliOverlord - * java.ext.dirs: /usr/lib/jvm/java-8-openjdk-amd64/jre/lib/ext:/usr/java/packages/lib/ext

2018-12-07T10:01:30,328 INFO [main] io.druid.cli.CliOverlord - * java.home: /usr/lib/jvm/java-8-openjdk-amd64/jre

2018-12-07T10:01:30,328 INFO [main] io.druid.cli.CliOverlord - * java.io.tmpdir: /tmp

2018-12-07T10:01:30,328 INFO [main] io.druid.cli.CliOverlord - * java.library.path: /usr/java/packages/lib/amd64:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib

2018-12-07T10:01:30,328 INFO [main] io.druid.cli.CliOverlord - * java.runtime.name: OpenJDK Runtime Environment

2018-12-07T10:01:30,328 INFO [main] io.druid.cli.CliOverlord - * java.runtime.version: 1.8.0_191-8u191-b12-0ubuntu0.16.04.1-b12

2018-12-07T10:01:30,328 INFO [main] io.druid.cli.CliOverlord - * java.specification.name: Java Platform API Specification

2018-12-07T10:01:30,329 INFO [main] io.druid.cli.CliOverlord - * java.specification.vendor: Oracle Corporation

2018-12-07T10:01:30,329 INFO [main] io.druid.cli.CliOverlord - * java.specification.version: 1.8

2018-12-07T10:01:30,329 INFO [main] io.druid.cli.CliOverlord - * java.util.logging.manager: org.apache.logging.log4j.jul.LogManager

2018-12-07T10:01:30,329 INFO [main] io.druid.cli.CliOverlord - * java.vendor: Oracle Corporation

2018-12-07T10:01:30,329 INFO [main] io.druid.cli.CliOverlord - * java.vendor.url: http://java.oracle.com/

2018-12-07T10:01:30,329 INFO [main] io.druid.cli.CliOverlord - * java.vendor.url.bug: http://bugreport.sun.com/bugreport/

2018-12-07T10:01:30,329 INFO [main] io.druid.cli.CliOverlord - * java.version: 1.8.0_191

2018-12-07T10:01:30,329 INFO [main] io.druid.cli.CliOverlord - * java.vm.info: mixed mode

2018-12-07T10:01:30,329 INFO [main] io.druid.cli.CliOverlord - * java.vm.name: OpenJDK 64-Bit Server VM

2018-12-07T10:01:30,329 INFO [main] io.druid.cli.CliOverlord - * java.vm.specification.name: Java Virtual Machine Specification

2018-12-07T10:01:30,329 INFO [main] io.druid.cli.CliOverlord - * java.vm.specification.vendor: Oracle Corporation

2018-12-07T10:01:30,329 INFO [main] io.druid.cli.CliOverlord - * java.vm.specification.version: 1.8

2018-12-07T10:01:30,329 INFO [main] io.druid.cli.CliOverlord - * java.vm.vendor: Oracle Corporation

2018-12-07T10:01:30,329 INFO [main] io.druid.cli.CliOverlord - * java.vm.version: 25.191-b12

2018-12-07T10:01:30,329 INFO [main] io.druid.cli.CliOverlord - * line.separator: 

2018-12-07T10:01:30,330 INFO [main] io.druid.cli.CliOverlord - * log4j.shutdownCallbackRegistry: io.druid.common.config.Log4jShutdown

2018-12-07T10:01:30,330 INFO [main] io.druid.cli.CliOverlord - * log4j.shutdownHookEnabled: true

2018-12-07T10:01:30,330 INFO [main] io.druid.cli.CliOverlord - * os.arch: amd64

2018-12-07T10:01:30,330 INFO [main] io.druid.cli.CliOverlord - * os.name: Linux

2018-12-07T10:01:30,330 INFO [main] io.druid.cli.CliOverlord - * os.version: 4.4.0-1072-aws

2018-12-07T10:01:30,330 INFO [main] io.druid.cli.CliOverlord - * path.separator: :

2018-12-07T10:01:30,330 INFO [main] io.druid.cli.CliOverlord - * sun.arch.data.model: 64

2018-12-07T10:01:30,330 INFO [main] io.druid.cli.CliOverlord - * sun.boot.class.path: /usr/lib/jvm/java-8-openjdk-amd64/jre/lib/resources.jar:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/rt.jar:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/sunrsasign.jar:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/jsse.jar:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/jce.jar:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/charsets.jar:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/jfr.jar:/usr/lib/jvm/java-8-openjdk-amd64/jre/classes

2018-12-07T10:01:30,330 INFO [main] io.druid.cli.CliOverlord - * sun.boot.library.path: /usr/lib/jvm/java-8-openjdk-amd64/jre/lib/amd64

2018-12-07T10:01:30,330 INFO [main] io.druid.cli.CliOverlord - * sun.cpu.endian: little

2018-12-07T10:01:30,330 INFO [main] io.druid.cli.CliOverlord - * sun.cpu.isalist: 

2018-12-07T10:01:30,330 INFO [main] io.druid.cli.CliOverlord - * sun.io.unicode.encoding: UnicodeLittle

2018-12-07T10:01:30,330 INFO [main] io.druid.cli.CliOverlord - * sun.java.command: io.druid.cli.Main server overlord

2018-12-07T10:01:30,331 INFO [main] io.druid.cli.CliOverlord - * sun.java.launcher: SUN_STANDARD

2018-12-07T10:01:30,331 INFO [main] io.druid.cli.CliOverlord - * sun.jnu.encoding: UTF-8

2018-12-07T10:01:30,331 INFO [main] io.druid.cli.CliOverlord - * sun.management.compiler: HotSpot 64-Bit Tiered Compilers

2018-12-07T10:01:30,331 INFO [main] io.druid.cli.CliOverlord - * sun.os.patch.level: unknown

2018-12-07T10:01:30,331 INFO [main] io.druid.cli.CliOverlord - * user.country: US

2018-12-07T10:01:30,331 INFO [main] io.druid.cli.CliOverlord - * user.dir: /opt/druid-0.12.3

2018-12-07T10:01:30,331 INFO [main] io.druid.cli.CliOverlord - * user.home: /root

2018-12-07T10:01:30,332 INFO [main] io.druid.cli.CliOverlord - * user.language: en

2018-12-07T10:01:30,332 INFO [main] io.druid.cli.CliOverlord - * user.name: root

2018-12-07T10:01:30,332 INFO [main] io.druid.cli.CliOverlord - * user.timezone: UTC

2018-12-07T10:01:30,337 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.initialization.ServerConfig] from props[druid.server.http.] as [io.druid.server.initialization.ServerConfig@893d5e45]

2018-12-07T10:01:30,342 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.initialization.TLSServerConfig] from props[druid.server.https.] as [TLSServerConfig{keyStorePath='null', keyStoreType='null', certAlias='null', keyManagerFactoryAlgorithm='null', includeCipherSuites=null, excludeCipherSuites=null, includeProtocols=null, excludeProtocols=null}]

2018-12-07T10:01:30,351 INFO [main] org.eclipse.jetty.util.log - Logging initialized @3068ms

2018-12-07T10:01:30,360 INFO [main] io.druid.server.initialization.jetty.JettyServerModule - Creating http connector with port [8090]

2018-12-07T10:01:30,446 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.indexing.overlord.config.TaskQueueConfig] from props[druid.indexer.queue.] as [io.druid.indexing.overlord.config.TaskQueueConfig@77ec6a3d]

2018-12-07T10:01:30,449 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.indexing.common.config.TaskStorageConfig] from props[druid.indexer.storage.] as [io.druid.indexing.common.config.TaskStorageConfig@6cfd9a54]

3.170: [CMS-concurrent-abortable-preclean: 0.884/1.137 secs] [Times: user=2.21 sys=0.03, real=1.13 secs] 

3.170: [GC (CMS Final Remark) [YG occupancy: 129730 K (235968 K)]3.170: [Rescan (parallel) , 0.0274405 secs]3.198: [weak refs processing, 0.0000199 secs]3.198: [class unloading, 0.0038392 secs]3.202: [scrub symbol table, 0.0042242 secs]3.206: [scrub string table, 0.0004318 secs][1 CMS-remark: 0K(3932160K)] 129730K(4168128K), 0.0368487 secs] [Times: user=0.06 sys=0.00, real=0.04 secs] 

3.212: [CMS-concurrent-sweep-start]

3.212: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

3.212: [CMS-concurrent-reset-start]

3.231: [CMS-concurrent-reset: 0.020/0.020 secs] [Times: user=0.03 sys=0.01, real=0.01 secs] 

2018-12-07T10:01:30,518 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.indexing.overlord.config.RemoteTaskRunnerConfig] from props[druid.indexer.runner.] as [RemoteTaskRunnerConfig{taskAssignmentTimeout=PT5M, taskCleanupTimeout=PT15M, minWorkerVersion='0', maxZnodeBytes=524288, taskShutdownLinkTimeout=PT1M, pendingTasksRunnerNumThreads=1, maxRetriesBeforeBlacklist=5, taskBlackListBackoffTimeMillis=PT15M, taskBlackListCleanupPeriod=PT5M, maxPercentageBlacklistWorkers= 20}]

2018-12-07T10:01:30,522 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.initialization.IndexerZkConfig] from props[druid.zk.paths.indexer.] as [io.druid.server.initialization.IndexerZkConfig@c539cc0a]

2018-12-07T10:01:30,525 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.guice.http.DruidHttpClientConfig] from props[druid.global.http.] as [io.druid.guice.http.DruidHttpClientConfig@9b21bd3]

2018-12-07T10:01:30,589 INFO [main] io.druid.common.config.ConfigManager - Creating watch for key[worker.config]

3.334: [GC (Allocation Failure) 3.334: [ParNew: 229458K->15554K(235968K), 0.0642744 secs] 229458K->22899K(4168128K), 0.0643457 secs] [Times: user=0.11 sys=0.02, real=0.06 secs] 

2018-12-07T10:01:30,684 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.indexing.overlord.autoscaling.ProvisioningSchedulerConfig] from props[druid.indexer.autoscale.] as [io.druid.indexing.overlord.autoscaling.ProvisioningSchedulerConfig@10f7c76]

2018-12-07T10:01:30,688 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.indexing.overlord.autoscaling.SimpleWorkerProvisioningConfig] from props[druid.indexer.autoscale.] as [io.druid.indexing.overlord.autoscaling.SimpleWorkerProvisioningConfig@7724704f]

2018-12-07T10:01:30,690 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.initialization.CuratorDiscoveryConfig] from props[druid.discovery.curator.] as [io.druid.server.initialization.CuratorDiscoveryConfig@3d4e405e]

2018-12-07T10:01:30,794 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.coordinator.CoordinatorOverlordServiceConfig] from props[druid.coordinator.asOverlord.] as [io.druid.server.coordinator.CoordinatorOverlordServiceConfig@5e1dde44]

2018-12-07T10:01:30,798 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.storage.s3.S3TaskLogsConfig] from props[druid.indexer.logs.] as [io.druid.storage.s3.S3TaskLogsConfig@6f76c2cc]

2018-12-07T10:01:30,800 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.common.aws.AWSCredentialsConfig] from props[druid.s3.] as [io.druid.common.aws.AWSCredentialsConfig@34b9eb03]

2018-12-07T10:01:30,852 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.indexing.overlord.helpers.TaskLogAutoCleanerConfig] from props[druid.indexer.logs.kill.] as [TaskLogAutoCleanerConfig{enabled=false, initialDelay=198790, delay=21600000, durationToRetain=9223372036854775807}]

2018-12-07T10:01:31,196 INFO [main] io.druid.metadata.SQLMetadataConnector - Table[druid_config] already exists

2018-12-07T10:01:31,197 INFO [main] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.common.config.ConfigManager.start()] on object[io.druid.common.config.ConfigManager@79aee22a].

2018-12-07T10:01:31,204 INFO [main] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.java.util.emitter.core.LoggingEmitter.start()] on object[LoggingEmitter{log=Logger{name=[io.druid.java.util.emitter.core.LoggingEmitter], class[class org.apache.logging.slf4j.Log4jLogger]}, level=DEBUG}].

2018-12-07T10:01:31,207 INFO [main] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.java.util.emitter.service.ServiceEmitter.start()] on object[ServiceEmitter{serviceDimensions={service=druid/epsilon-prod/overlord, host={overlord_IP}:8090, version=0.12.3}, emitter=LoggingEmitter{log=Logger{name=[io.druid.java.util.emitter.core.LoggingEmitter], class[class org.apache.logging.slf4j.Log4jLogger]}, level=DEBUG}}].

2018-12-07T10:01:31,240 INFO [main] io.druid.metadata.SQLMetadataConnector - Table[druid_audit] already exists

2018-12-07T10:01:31,240 INFO [main] io.druid.curator.CuratorModule - Starting Curator

2018-12-07T10:01:31,240 INFO [main] org.apache.curator.framework.imps.CuratorFrameworkImpl - Starting

2018-12-07T10:01:31,249 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:zookeeper.version=3.4.10-39d3a4f269333c922ed3db283be479f9deacaa0f, built on 03/23/2017 10:13 GMT

2018-12-07T10:01:31,249 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:host.name=ip-{overlord_IP}.ec2.internal

2018-12-07T10:01:31,249 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:java.version=1.8.0_191

2018-12-07T10:01:31,249 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:java.vendor=Oracle Corporation

2018-12-07T10:01:31,249 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:java.home=/usr/lib/jvm/java-8-openjdk-amd64/jre

2018-12-07T10:01:31,249 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:java.class.path=conf/druid/_common:conf/druid/overlord:lib/janino-2.7.6.jar:lib/netty-buffer-4.0.52.Final.jar:lib/jetty-servlets-9.3.19.v20170502.jar:lib/jackson-datatype-guava-2.4.6.jar:lib/aether-connector-file-0.9.0.M2.jar:lib/guava-16.0.1.jar:lib/reactive-streams-1.0.0.jar:lib/httpcore-4.4.3.jar:lib/maven-aether-provider-3.1.1.jar:lib/druid-indexing-hadoop-0.12.3.jar:lib/jersey-core-1.19.3.jar:lib/netty-resolver-dns-2.0.37.jar:lib/javax.el-3.0.0.jar:lib/jetty-server-9.3.19.v20170502.jar:lib/jackson-module-jaxb-annotations-2.4.6.jar:lib/slf4j-api-1.6.4.jar:lib/validation-api-1.1.0.Final.jar:lib/javax.inject-1.jar:lib/jetty-io-9.3.19.v20170502.jar:lib/log4j-api-2.5.jar:lib/zookeeper-3.4.10.jar:lib/maven-model-builder-3.1.1.jar:lib/aws-java-sdk-ec2-1.10.77.jar:lib/netty-common-4.0.52.Final.jar:lib/jackson-databind-2.4.6.jar:lib/config-magic-0.9.jar:lib/jersey-guice-1.19.3.jar:lib/commons-pool-1.6.jar:lib/aggdesigner-algorithm-6.0.jar:lib/java-xmlbuilder-1.1.jar:lib/curator-x-discovery-4.0.0.jar:lib/jackson-mapper-asl-1.9.13.jar:lib/netty-codec-http-4.0.52.Final.jar:lib/commons-pool2-2.2.jar:lib/jetty-client-9.3.19.v20170502.jar:lib/jackson-core-2.4.6.jar:lib/tesla-aether-0.0.5.jar:lib/druid-api-0.12.3.jar:lib/joni-2.1.11.jar:lib/jetty-util-9.3.19.v20170502.jar:lib/aopalliance-1.0.jar:lib/caffeine-2.5.5.jar:lib/avatica-core-1.10.0.jar:lib/protobuf-java-3.1.0.jar:lib/plexus-utils-3.0.15.jar:lib/aether-impl-0.9.0.M2.jar:lib/commons-math3-3.6.1.jar:lib/opencsv-2.3.jar:lib/calcite-linq4j-1.15.0.jar:lib/jackson-jaxrs-json-provider-2.4.6.jar:lib/calcite-core-1.15.0.jar:lib/guice-multibindings-4.1.0.jar:lib/curator-client-4.0.0.jar:lib/derby-10.11.1.1.jar:lib/guice-4.1.0.jar:lib/aether-connector-okhttp-0.0.9.jar:lib/jboss-logging-3.1.3.GA.jar:lib/netty-codec-4.0.52.Final.jar:lib/commons-lang-2.6.jar:lib/jetty-continuation-9.3.19.v20170502.jar:lib/jetty-http-9.3.19.v20170502.jar:lib/irc-api-1.0-0014.jar:lib/asm-5.2.jar:lib/netty-transport-native-epoll-4.0.52.Final-linux-x86_64.jar:lib/classmate-1.0.0.jar:lib/maven-settings-builder-3.1.1.jar:lib/commons-cli-1.2.jar:lib/json-path-2.1.0.jar:lib/plexus-interpolation-1.19.jar:lib/druid-hll-0.12.3.jar:lib/aether-spi-0.9.0.M2.jar:lib/maven-model-3.1.1.jar:lib/jackson-core-asl-1.9.13.jar:lib/jackson-dataformat-cbor-2.5.3.jar:lib/jersey-server-1.19.3.jar:lib/geoip2-0.4.0.jar:lib/jersey-servlet-1.19.3.jar:lib/okhttp-1.0.2.jar:lib/compress-lzf-1.0.4.jar:lib/aether-util-0.9.0.M2.jar:lib/curator-framework-4.0.0.jar:lib/jackson-jaxrs-base-2.4.6.jar:lib/netty-3.10.6.Final.jar:lib/asm-commons-5.2.jar:lib/maxminddb-0.2.0.jar:lib/asm-tree-5.2.jar:lib/icu4j-54.1.1.jar:lib/async-http-client-netty-utils-2.0.37.jar:lib/commons-dbcp-1.4.jar:lib/netty-transport-4.0.52.Final.jar:lib/maven-settings-3.1.1.jar:lib/async-http-client-2.0.37.jar:lib/airline-0.7.jar:lib/commons-io-2.5.jar:lib/netty-resolver-2.0.37.jar:lib/netty-handler-4.0.52.Final.jar:lib/base64-2.3.8.jar:lib/esri-geometry-api-2.0.0.jar:lib/jets3t-0.9.4.jar:lib/derbynet-10.11.1.1.jar:lib/log4j-jul-2.5.jar:lib/netty-reactive-streams-1.0.8.jar:lib/netty-codec-dns-2.0.37.jar:lib/jcodings-1.0.13.jar:lib/log4j-core-2.5.jar:lib/druid-indexing-service-0.12.3.jar:lib/mapdb-1.0.8.jar:lib/log4j-1.2-api-2.5.jar:lib/jcl-over-slf4j-1.7.12.jar:lib/guice-servlet-4.1.0.jar:lib/commons-compiler-2.7.6.jar:lib/jvm-attach-api-1.2.jar:lib/jetty-security-9.3.19.v20170502.jar:lib/disruptor-3.3.6.jar:lib/extendedset-0.12.3.jar:lib/commons-logging-1.1.1.jar:lib/antlr4-runtime-4.5.1.jar:lib/derbyclient-10.11.1.1.jar:lib/fastutil-8.1.0.jar:lib/aether-api-0.9.0.M2.jar:lib/jackson-datatype-joda-2.4.6.jar:lib/avatica-metrics-1.10.0.jar:lib/druid-server-0.12.3.jar:lib/hibernate-validator-5.1.3.Final.jar:lib/activation-1.1.1.jar:lib/aws-java-sdk-core-1.10.77.jar:lib/druid-console-0.0.2.jar:lib/joda-time-2.9.9.jar:lib/log4j-slf4j-impl-2.5.jar:lib/jline-0.9.94.jar:lib/jetty-proxy-9.3.19.v20170502.jar:lib/commons-lang3-3.2.jar:lib/jackson-jaxrs-smile-provider-2.4.6.jar:lib/RoaringBitmap-0.5.18.jar:lib/commons-codec-1.7.jar:lib/netty-all-4.0.52.Final.jar:lib/lz4-1.3.0.jar:lib/avatica-server-1.10.0.jar:lib/java-util-0.12.3.jar:lib/javax.el-api-3.0.0.jar:lib/jackson-annotations-2.4.6.jar:lib/druid-aws-common-0.12.3.jar:lib/bcprov-jdk15on-1.52.jar:lib/maven-repository-metadata-3.1.1.jar:lib/wagon-provider-api-2.4.jar:lib/jackson-jq-0.0.7.jar:lib/rhino-1.7R5.jar:lib/jdbi-2.63.1.jar:lib/druid-common-0.12.3.jar:lib/httpclient-4.5.1.jar:lib/commons-dbcp2-2.0.1.jar:lib/druid-processing-0.12.3.jar:lib/druid-services-0.12.3.jar:lib/jetty-servlet-9.3.19.v20170502.jar:lib/jackson-dataformat-smile-2.4.6.jar:lib/spymemcached-2.12.3.jar:lib/jsr311-api-1.1.1.jar:lib/jsr305-2.0.1.jar:lib/javax.servlet-api-3.1.0.jar:lib/druid-sql-0.12.3.jar:lib/curator-recipes-4.0.0.jar:

2018-12-07T10:01:31,249 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib

2018-12-07T10:01:31,249 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:java.io.tmpdir=/tmp

2018-12-07T10:01:31,249 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:java.compiler=<NA>

2018-12-07T10:01:31,249 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:os.name=Linux

2018-12-07T10:01:31,249 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:os.arch=amd64

2018-12-07T10:01:31,249 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:os.version=4.4.0-1072-aws

2018-12-07T10:01:31,249 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:user.name=root

2018-12-07T10:01:31,249 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:user.home=/root

2018-12-07T10:01:31,249 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:user.dir=/opt/druid-0.12.3

2018-12-07T10:01:31,250 INFO [main] org.apache.zookeeper.ZooKeeper - Initiating client connection, connectString={zookeeperIp1},{zookeeperIp2},{zookeeperIp3} sessionTimeout=30000 watcher=org.apache.curator.ConnectionState@5dbb50f3

2018-12-07T10:01:31,286 INFO [main] org.apache.curator.framework.imps.CuratorFrameworkImpl - Default schema

2018-12-07T10:01:31,287 INFO [main] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.curator.announcement.Announcer.start()] on object[io.druid.curator.announcement.Announcer@33a55bd8].

2018-12-07T10:01:31,287 INFO [main] io.druid.curator.announcement.Announcer - Starting announcer

2018-12-07T10:01:31,287 INFO [main] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner.start()] on object[io.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner@73a8e994].

2018-12-07T10:01:31,287 INFO [main] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.java.util.metrics.MonitorScheduler.start()] on object[io.druid.java.util.metrics.MonitorScheduler@42383cb0].

2018-12-07T10:01:31,289 INFO [main] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.indexing.overlord.MetadataTaskStorage.start()] on object[io.druid.indexing.overlord.MetadataTaskStorage@267cde2e].

2018-12-07T10:01:31,293 INFO [main-SendThread(ip-{zookeeperIp1}.ec2.internal:2181)] org.apache.zookeeper.ClientCnxn - Opening socket connection to server ip-{zookeeperIp1}.ec2.internal/{zookeeperIp1}:2181. Will not attempt to authenticate using SASL (unknown error)

2018-12-07T10:01:31,299 INFO [main-SendThread(ip-{zookeeperIp1}.ec2.internal:2181)] org.apache.zookeeper.ClientCnxn - Socket connection established to ip-{zookeeperIp1}.ec2.internal/{zookeeperIp1}:2181, initiating session

2018-12-07T10:01:31,299 INFO [main] io.druid.metadata.SQLMetadataConnector - Table[druid_tasks] already exists

2018-12-07T10:01:31,307 INFO [main] io.druid.metadata.SQLMetadataConnector - Table[druid_tasklogs] already exists

2018-12-07T10:01:31,310 INFO [main-SendThread(ip-{zookeeperIp1}.ec2.internal:2181)] org.apache.zookeeper.ClientCnxn - Session establishment complete on server ip-{zookeeperIp1}.ec2.internal/{zookeeperIp1}:2181, sessionid = 0x16784378a890010, negotiated timeout = 30000

2018-12-07T10:01:31,317 INFO [main-EventThread] org.apache.curator.framework.state.ConnectionStateManager - State change: CONNECTED

2018-12-07T10:01:31,320 INFO [main] io.druid.metadata.SQLMetadataConnector - Table[druid_tasklocks] already exists

2018-12-07T10:01:31,320 INFO [main] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.metadata.IndexerSQLMetadataStorageCoordinator.start()] on object[io.druid.metadata.IndexerSQLMetadataStorageCoordinator@2b1cd7bc].

2018-12-07T10:01:31,328 INFO [main] io.druid.metadata.SQLMetadataConnector - Table[druid_dataSource] already exists

2018-12-07T10:01:31,335 INFO [main] io.druid.metadata.SQLMetadataConnector - Table[druid_pendingSegments] already exists

2018-12-07T10:01:31,341 INFO [main] io.druid.metadata.SQLMetadataConnector - Table[druid_segments] already exists

2018-12-07T10:01:31,342 INFO [main] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.metadata.SQLMetadataSupervisorManager.start()] on object[io.druid.metadata.SQLMetadataSupervisorManager@55fee662].

2018-12-07T10:01:31,350 INFO [main] io.druid.metadata.SQLMetadataConnector - Table[druid_supervisors] already exists

2018-12-07T10:01:31,352 INFO [main] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.java.util.http.client.NettyHttpClient.start()] on object[io.druid.java.util.http.client.NettyHttpClient@10c47c79].

2018-12-07T10:01:31,353 INFO [main] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.indexing.overlord.TaskMaster.start()] on object[io.druid.indexing.overlord.TaskMaster@12a2585b].

2018-12-07T10:01:31,362 INFO [main] io.druid.server.initialization.jetty.JettyServerModule - Starting Jetty Server...

2018-12-07T10:01:31,363 INFO [main] org.eclipse.jetty.server.Server - jetty-9.3.19.v20170502

2018-12-07T10:01:31,442 INFO [LeaderSelector[/druid/epsilon-prod/overlord/_OVERLORD]] io.druid.indexing.overlord.TaskMaster - By the power of Grayskull, I have the power!

2018-12-07T10:01:31,450 INFO [LeaderSelector[/druid/epsilon-prod/overlord/_OVERLORD]] io.druid.indexing.overlord.TaskLockbox - Synced 0 locks for 0 activeTasks from storage (0 locks ignored).

2018-12-07T10:01:31,483 INFO [LeaderSelector[/druid/epsilon-prod/overlord/_OVERLORD]] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.indexing.overlord.RemoteTaskRunner.start()] on object[io.druid.indexing.overlord.RemoteTaskRunner@73fa1a3f].

2018-12-07T10:01:31,515 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Registering com.fasterxml.jackson.jaxrs.smile.JacksonSmileProvider as a provider class

2018-12-07T10:01:31,515 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Registering com.fasterxml.jackson.jaxrs.json.JacksonJsonProvider as a provider class

2018-12-07T10:01:31,515 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Registering io.druid.server.initialization.jetty.CustomExceptionMapper as a provider class

2018-12-07T10:01:31,516 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Registering io.druid.server.initialization.jetty.ForbiddenExceptionMapper as a provider class

2018-12-07T10:01:31,516 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Registering io.druid.server.StatusResource as a root resource class

2018-12-07T10:01:31,517 INFO [main] com.sun.jersey.server.impl.application.WebApplicationImpl - Initiating Jersey application, version 'Jersey: 1.19.3 10/24/2016 03:43 PM'

2018-12-07T10:01:31,558 INFO [Curator-PathChildrenCache-0] io.druid.indexing.overlord.RemoteTaskRunner - Worker[{middlemanager_IP_2}:8091] reportin' for duty!

2018-12-07T10:01:31,567 INFO [Curator-PathChildrenCache-0] io.druid.indexing.overlord.RemoteTaskRunner - Worker[{middlemanager_IP_3}:8091] reportin' for duty!

2018-12-07T10:01:31,568 INFO [Curator-PathChildrenCache-0] io.druid.indexing.overlord.RemoteTaskRunner - Worker[{middlemanager_IP}:8091] reportin' for duty!

2018-12-07T10:01:31,569 INFO [Curator-PathChildrenCache-0] io.druid.indexing.overlord.RemoteTaskRunner - Worker[{middlemanager_IP_1}:8091] reportin' for duty!

2018-12-07T10:01:31,631 INFO [LeaderSelector[/druid/epsilon-prod/overlord/_OVERLORD]] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.indexing.overlord.TaskQueue.start()] on object[io.druid.indexing.overlord.TaskQueue@37249243].

2018-12-07T10:01:31,635 INFO [LeaderSelector[/druid/epsilon-prod/overlord/_OVERLORD]] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:01:31,638 INFO [TaskQueue-Manager] io.druid.indexing.overlord.TaskQueue - Beginning management in PT30S.

2018-12-07T10:01:31,642 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Binding io.druid.server.initialization.jetty.CustomExceptionMapper to GuiceManagedComponentProvider with the scope "Singleton"

2018-12-07T10:01:31,642 INFO [LeaderSelector[/druid/epsilon-prod/overlord/_OVERLORD]] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.indexing.overlord.supervisor.SupervisorManager.start()] on object[io.druid.indexing.overlord.supervisor.SupervisorManager@822a616].

2018-12-07T10:01:31,642 INFO [LeaderSelector[/druid/epsilon-prod/overlord/_OVERLORD]] io.druid.indexing.overlord.supervisor.SupervisorManager - Loading stored supervisors from database

2018-12-07T10:01:31,648 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Binding io.druid.server.initialization.jetty.ForbiddenExceptionMapper to GuiceManagedComponentProvider with the scope "Singleton"

2018-12-07T10:01:31,649 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Binding com.fasterxml.jackson.jaxrs.smile.JacksonSmileProvider to GuiceManagedComponentProvider with the scope "Singleton"

2018-12-07T10:01:31,657 INFO [LeaderSelector[/druid/epsilon-prod/overlord/_OVERLORD]] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.indexing.overlord.helpers.OverlordHelperManager.start()] on object[io.druid.indexing.overlord.helpers.OverlordHelperManager@517ae92b].

2018-12-07T10:01:31,657 INFO [LeaderSelector[/druid/epsilon-prod/overlord/_OVERLORD]] io.druid.indexing.overlord.helpers.OverlordHelperManager - OverlordHelperManager is starting.

2018-12-07T10:01:31,657 INFO [LeaderSelector[/druid/epsilon-prod/overlord/_OVERLORD]] io.druid.indexing.overlord.helpers.OverlordHelperManager - OverlordHelperManager is started.

2018-12-07T10:01:31,659 INFO [LeaderSelector[/druid/epsilon-prod/overlord/_OVERLORD]] io.druid.curator.discovery.CuratorServiceAnnouncer - Announcing service[DruidNode{serviceName='druid/epsilon-prod/overlord', host='{overlord_IP}', port=-1, plaintextPort=8090, enablePlaintextPort=true, tlsPort=-1, enableTlsPort=false}]

2018-12-07T10:01:31,669 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Binding com.fasterxml.jackson.jaxrs.json.JacksonJsonProvider to GuiceManagedComponentProvider with the scope "Singleton"

2018-12-07T10:01:31,936 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Binding io.druid.server.http.security.StateResourceFilter to GuiceInstantiatedComponentProvider

2018-12-07T10:01:31,938 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Binding io.druid.indexing.overlord.http.security.TaskResourceFilter to GuiceInstantiatedComponentProvider

2018-12-07T10:01:31,942 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Binding io.druid.server.http.security.ConfigResourceFilter to GuiceInstantiatedComponentProvider

2018-12-07T10:01:31,960 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Binding io.druid.indexing.overlord.http.OverlordResource to GuiceInstantiatedComponentProvider

2018-12-07T10:01:31,966 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Binding io.druid.indexing.overlord.http.security.SupervisorResourceFilter to GuiceInstantiatedComponentProvider

2018-12-07T10:01:31,969 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Binding io.druid.indexing.overlord.supervisor.SupervisorResource to GuiceInstantiatedComponentProvider

2018-12-07T10:01:31,970 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Binding io.druid.server.StatusResource to GuiceManagedComponentProvider with the scope "Undefined"

2018-12-07T10:01:31,982 INFO [main] org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@733e6df7{/,[jar:file:/opt/druid-0.12.3/lib/druid-server-0.12.3.jar!/static, jar:file:/opt/druid-0.12.3/lib/druid-indexing-service-0.12.3.jar!/indexer_static],AVAILABLE}

2018-12-07T10:01:31,990 INFO [main] org.eclipse.jetty.server.AbstractConnector - Started ServerConnector@4d4436d0{HTTP/1.1,[http/1.1]}{0.0.0.0:8090}

2018-12-07T10:01:31,990 INFO [main] org.eclipse.jetty.server.Server - Started @4707ms

2018-12-07T10:01:31,990 INFO [main] io.druid.curator.discovery.CuratorDruidNodeAnnouncer - Announcing [DiscoveryDruidNode{druidNode=DruidNode{serviceName='druid/epsilon-prod/overlord', host='{overlord_IP}', port=-1, plaintextPort=8090, enablePlaintextPort=true, tlsPort=-1, enableTlsPort=false}, nodeType='overlord', services={}}].

2018-12-07T10:01:32,011 INFO [main] io.druid.curator.discovery.CuratorDruidNodeAnnouncer - Announced [DiscoveryDruidNode{druidNode=DruidNode{serviceName='druid/epsilon-prod/overlord', host='{overlord_IP}', port=-1, plaintextPort=8090, enablePlaintextPort=true, tlsPort=-1, enableTlsPort=false}, nodeType='overlord', services={}}].

2018-12-07T10:02:29,104 INFO [qtp634210724-65] io.druid.indexing.overlord.MetadataTaskStorage - Inserting task index_f2_2018-12-07T10:02:29.102Z with status: TaskStatus{id=index_f2_2018-12-07T10:02:29.102Z, status=RUNNING, duration=-1}

2018-12-07T10:02:29,196 INFO [qtp634210724-65] io.druid.indexing.overlord.TaskLockbox - Adding task[index_f2_2018-12-07T10:02:29.102Z] to activeTasks

2018-12-07T10:02:29,197 INFO [TaskQueue-Manager] io.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_f2_2018-12-07T10:02:29.102Z]: LockListAction{}

2018-12-07T10:02:29,201 INFO [TaskQueue-Manager] io.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_f2_2018-12-07T10:02:29.102Z]: LockTryAcquireAction{lockType=EXCLUSIVE, interval=2018-12-01T00:00:00.000Z/2018-12-03T00:00:00.000Z}

2018-12-07T10:02:29,202 INFO [TaskQueue-Manager] io.druid.indexing.overlord.TaskLockbox - Added task[index_f2_2018-12-07T10:02:29.102Z] to TaskLock[index_f2_2018-12-07T10:02:29.102Z]

2018-12-07T10:02:29,202 INFO [TaskQueue-Manager] io.druid.indexing.overlord.MetadataTaskStorage - Adding lock on interval[2018-12-01T00:00:00.000Z/2018-12-03T00:00:00.000Z] version[2018-12-07T10:02:29.201Z] for task: index_f2_2018-12-07T10:02:29.102Z

2018-12-07T10:02:29,226 INFO [TaskQueue-Manager] io.druid.indexing.overlord.TaskQueue - Asking taskRunner to run: index_f2_2018-12-07T10:02:29.102Z

2018-12-07T10:02:29,226 INFO [TaskQueue-Manager] io.druid.indexing.overlord.RemoteTaskRunner - Added pending task index_f2_2018-12-07T10:02:29.102Z

2018-12-07T10:02:29,242 INFO [rtr-pending-tasks-runner-0] io.druid.indexing.overlord.RemoteTaskRunner - Coordinator asking Worker[{middlemanager_IP}:8091] to add task[index_f2_2018-12-07T10:02:29.102Z]

2018-12-07T10:02:29,258 INFO [rtr-pending-tasks-runner-0] io.druid.indexing.overlord.RemoteTaskRunner - Task index_f2_2018-12-07T10:02:29.102Z switched from pending to running (on [{middlemanager_IP}:8091])

2018-12-07T10:02:29,259 INFO [rtr-pending-tasks-runner-0] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_f2_2018-12-07T10:02:29.102Z] status changed to [RUNNING].

2018-12-07T10:02:29,434 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Worker[{middlemanager_IP}:8091] wrote RUNNING status for task [index_f2_2018-12-07T10:02:29.102Z] on [TaskLocation{host='null', port=-1, tlsPort=-1}]

2018-12-07T10:02:29,505 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Worker[{middlemanager_IP}:8091] wrote RUNNING status for task [index_f2_2018-12-07T10:02:29.102Z] on [TaskLocation{host='{middlemanager_IP}', port=8100, tlsPort=-1}]

2018-12-07T10:02:29,505 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_f2_2018-12-07T10:02:29.102Z] location changed to [TaskLocation{host='{middlemanager_IP}', port=8100, tlsPort=-1}].

2018-12-07T10:02:31,642 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 1 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:02:33,953 INFO [qtp634210724-82] io.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_f2_2018-12-07T10:02:29.102Z]: LockListAction{}

2018-12-07T10:02:34,016 INFO [qtp634210724-85] io.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_f2_2018-12-07T10:02:29.102Z]: LockListAction{}

2018-12-07T10:03:31,645 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 1 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:04:31,641 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskLockbox - Removing task[index_f2_2018-12-07T10:02:29.102Z] from activeTasks

2018-12-07T10:04:31,642 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskLockbox - Removing task[index_f2_2018-12-07T10:02:29.102Z] from TaskLock[index_f2_2018-12-07T10:02:29.102Z]

2018-12-07T10:04:31,642 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskLockbox - TaskLock is now empty: TaskLock{type=EXCLUSIVE, groupId=index_f2_2018-12-07T10:02:29.102Z, dataSource=f2, interval=2018-12-01T00:00:00.000Z/2018-12-03T00:00:00.000Z, version=2018-12-07T10:02:29.201Z, priority=50, revoked=false}

2018-12-07T10:04:31,652 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.MetadataTaskStorage - Deleting TaskLock with id[420]: TaskLock{type=EXCLUSIVE, groupId=index_f2_2018-12-07T10:02:29.102Z, dataSource=f2, interval=2018-12-01T00:00:00.000Z/2018-12-03T00:00:00.000Z, version=2018-12-07T10:02:29.201Z, priority=50, revoked=false}

2018-12-07T10:04:31,665 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 1 tasks removed).

2018-12-07T10:04:31,665 INFO [TaskQueue-Manager] io.druid.indexing.overlord.TaskQueue - Asking taskRunner to clean up 1 tasks.

2018-12-07T10:04:31,671 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

2018-12-07T10:04:31,706 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

2018-12-07T10:04:31,706 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

2018-12-07T10:04:31,707 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

2018-12-07T10:04:31,707 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

2018-12-07T10:04:31,707 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

2018-12-07T10:04:31,707 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

2018-12-07T10:04:31,707 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

2018-12-07T10:04:31,707 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

2018-12-07T10:04:31,707 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

2018-12-07T10:04:31,707 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

2018-12-07T10:04:31,708 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

2018-12-07T10:04:31,708 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

184.427: [GC (Allocation Failure) 184.427: [ParNew: 225346K->25678K(235968K), 0.0414502 secs] 232691K->33024K(4168128K), 0.0415317 secs] [Times: user=0.08 sys=0.00, real=0.04 secs] 

2018-12-07T10:04:31,752 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

2018-12-07T10:04:31,752 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

2018-12-07T10:04:31,753 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

2018-12-07T10:04:31,753 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

2018-12-07T10:04:31,753 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

2018-12-07T10:04:31,753 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

2018-12-07T10:04:31,753 INFO [TaskQueue-Manager] io.druid.java.util.http.client.pool.ChannelResourceFactory - Generating: http://{middlemanager_IP}:8091

2018-12-07T10:04:31,948 INFO [TaskQueue-Manager] io.druid.indexing.overlord.RemoteTaskRunner - Sent shutdown message to worker: {middlemanager_IP}:8091, status 200 OK, response: {"task":"index_f2_2018-12-07T10:02:29.102Z"}

2018-12-07T10:04:32,576 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Worker[{middlemanager_IP}:8091] wrote FAILED status for task [index_f2_2018-12-07T10:02:29.102Z] on [TaskLocation{host='{middlemanager_IP}', port=8100, tlsPort=-1}]

2018-12-07T10:04:32,576 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Worker[{middlemanager_IP}:8091] completed task[index_f2_2018-12-07T10:02:29.102Z] with status[FAILED]

2018-12-07T10:04:32,577 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskQueue - Received FAILED status for task: index_f2_2018-12-07T10:02:29.102Z

2018-12-07T10:04:32,577 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Cleaning up task[index_f2_2018-12-07T10:02:29.102Z] on worker[{middlemanager_IP}:8091]

2018-12-07T10:04:32,583 WARN [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskQueue - Unknown task completed: index_f2_2018-12-07T10:02:29.102Z

2018-12-07T10:04:32,583 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskQueue - Task FAILED: AbstractTask{id='index_f2_2018-12-07T10:02:29.102Z', groupId='index_f2_2018-12-07T10:02:29.102Z', taskResource=TaskResource{availabilityGroup='index_f2_2018-12-07T10:02:29.102Z', requiredCapacity=1}, dataSource='f2', context={}} (123127 run duration)

2018-12-07T10:04:32,583 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_f2_2018-12-07T10:02:29.102Z] status changed to [FAILED].

2018-12-07T10:04:32,583 INFO [Curator-PathChildrenCache-1] io.druid.indexing.overlord.RemoteTaskRunner - Task[index_f2_2018-12-07T10:02:29.102Z] went bye bye.

2018-12-07T10:05:31,642 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:06:31,642 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:07:31,642 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:08:31,642 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:09:31,642 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:10:31,642 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:11:31,642 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:12:31,643 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:13:31,643 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:14:31,643 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:15:31,647 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:16:31,643 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:17:31,644 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:18:31,644 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:19:31,665 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:20:31,644 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:21:31,644 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:22:31,644 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:23:31,645 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:24:31,645 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:25:31,645 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:26:31,645 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

2018-12-07T10:27:31,646 INFO [TaskQueue-StorageSync] io.druid.indexing.overlord.TaskQueue - Synced 0 tasks from storage (0 tasks added, 0 tasks removed).

MiddleManager Complete Log :

0.261: [GC (Allocation Failure) 0.261: [ParNew: 17472K->2176K(19648K), 0.0040952 secs] 17472K->2275K(63360K), 0.0041518 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

0.378: [GC (Allocation Failure) 0.378: [ParNew: 19648K->1748K(19648K), 0.0055257 secs] 19747K->2798K(63360K), 0.0055689 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

0.581: [GC (Allocation Failure) 0.581: [ParNew: 19220K->1602K(19648K), 0.0030123 secs] 20270K->3027K(63360K), 0.0030541 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

0.728: [GC (Allocation Failure) 0.728: [ParNew: 19074K->2176K(19648K), 0.0048762 secs] 20499K->4936K(63360K), 0.0049180 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

2018-12-07T10:00:58,586 INFO [main] io.druid.guice.PropertiesModule - Loading properties from common.runtime.properties

2018-12-07T10:00:58,588 INFO [main] io.druid.guice.PropertiesModule - Loading properties from runtime.properties

2018-12-07T10:00:58,614 INFO [main] org.hibernate.validator.internal.util.Version - HV000001: Hibernate Validator 5.1.3.Final

0.826: [GC (Allocation Failure) 0.826: [ParNew: 19648K->1248K(19648K), 0.0023355 secs] 22408K->4319K(63360K), 0.0023789 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

0.954: [GC (Allocation Failure) 0.954: [ParNew: 18720K->2175K(19648K), 0.0049065 secs] 21791K->5538K(63360K), 0.0049474 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

1.072: [GC (Allocation Failure) 1.072: [ParNew: 19647K->2055K(19648K), 0.0030274 secs] 23010K->5775K(63360K), 0.0030686 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2018-12-07T10:00:58,993 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.guice.ExtensionsConfig] from props[druid.extensions.] as [ExtensionsConfig{searchCurrentClassloader=true, directory='extensions', hadoopDependenciesDir='hadoop-dependencies', hadoopContainerDruidClasspath='null', addExtensionsToHadoopContainer=false, loadList=[druid-s3-extensions, druid-histogram, mysql-metadata-storage]}]

2018-12-07T10:00:59,040 INFO [main] io.druid.initialization.Initialization - Loading extension [druid-s3-extensions] for class [interface io.druid.cli.CliCommandCreator]

1.212: [GC (Allocation Failure) 1.212: [ParNew: 19527K->1238K(19648K), 0.0027125 secs] 23247K->5219K(63360K), 0.0027508 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

2018-12-07T10:00:59,052 INFO [main] io.druid.initialization.Initialization - added URL[file:/opt/druid-0.12.3/extensions/druid-s3-extensions/druid-s3-extensions-0.12.3.jar]

2018-12-07T10:00:59,053 INFO [main] io.druid.initialization.Initialization - Loading extension [druid-histogram] for class [interface io.druid.cli.CliCommandCreator]

2018-12-07T10:00:59,054 INFO [main] io.druid.initialization.Initialization - added URL[file:/opt/druid-0.12.3/extensions/druid-histogram/druid-histogram-0.12.3.jar]

2018-12-07T10:00:59,054 INFO [main] io.druid.initialization.Initialization - Loading extension [mysql-metadata-storage] for class [interface io.druid.cli.CliCommandCreator]

2018-12-07T10:00:59,054 INFO [main] io.druid.initialization.Initialization - added URL[file:/opt/druid-0.12.3/extensions/mysql-metadata-storage/mysql-connector-java-5.1.38.jar]

2018-12-07T10:00:59,054 INFO [main] io.druid.initialization.Initialization - added URL[file:/opt/druid-0.12.3/extensions/mysql-metadata-storage/mysql-metadata-storage-0.12.3.jar]

2018-12-07T10:00:59,103 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.guice.ModulesConfig] from props[druid.modules.] as [ModulesConfig{excludeList=[]}]

1.321: [GC (Allocation Failure) 1.321: [ParNew: 18710K->1730K(19648K), 0.0036718 secs] 22691K->6137K(63360K), 0.0037129 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

2018-12-07T10:00:59,197 INFO [main] io.druid.initialization.Initialization - Loading extension [druid-s3-extensions] for class [interface io.druid.initialization.DruidModule]

2018-12-07T10:00:59,261 INFO [main] io.druid.initialization.Initialization - Adding implementation [io.druid.storage.s3.S3StorageDruidModule] for class [interface io.druid.initialization.DruidModule] from local file system extension

2018-12-07T10:00:59,262 INFO [main] io.druid.initialization.Initialization - Adding implementation [io.druid.firehose.s3.S3FirehoseDruidModule] for class [interface io.druid.initialization.DruidModule] from local file system extension

2018-12-07T10:00:59,262 INFO [main] io.druid.initialization.Initialization - Loading extension [druid-histogram] for class [interface io.druid.initialization.DruidModule]

2018-12-07T10:00:59,264 INFO [main] io.druid.initialization.Initialization - Adding implementation [io.druid.query.aggregation.histogram.ApproximateHistogramDruidModule] for class [interface io.druid.initialization.DruidModule] from local file system extension

2018-12-07T10:00:59,264 INFO [main] io.druid.initialization.Initialization - Loading extension [mysql-metadata-storage] for class [interface io.druid.initialization.DruidModule]

2018-12-07T10:00:59,265 INFO [main] io.druid.initialization.Initialization - Adding implementation [io.druid.metadata.storage.mysql.MySQLMetadataStorageModule] for class [interface io.druid.initialization.DruidModule] from local file system extension

1.540: [GC (Allocation Failure) 1.540: [ParNew: 19199K->2176K(19648K), 0.0049548 secs] 23606K->7567K(63360K), 0.0049993 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

1.545: [GC (CMS Initial Mark) [1 CMS-initial-mark: 5391K(43712K)] 7631K(63360K), 0.0011923 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

1.546: [CMS-concurrent-mark-start]

1.553: [CMS-concurrent-mark: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

1.553: [CMS-concurrent-preclean-start]

1.553: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

1.556: [GC (CMS Final Remark) [YG occupancy: 2591 K (19648 K)]1.556: [Rescan (parallel) , 0.0016286 secs]1.557: [weak refs processing, 0.0000305 secs]1.557: [class unloading, 0.0026793 secs]1.560: [scrub symbol table, 0.0035128 secs]1.564: [scrub string table, 0.0004536 secs][1 CMS-remark: 5391K(43712K)] 7983K(63360K), 0.0085860 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 

1.568: [CMS-concurrent-sweep-start]

1.575: [CMS-concurrent-sweep: 0.006/0.006 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 

1.575: [CMS-concurrent-reset-start]

1.576: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

1.756: [GC (Allocation Failure) 1.756: [ParNew: 19648K->2175K(19648K), 0.0061821 secs] 24512K->8789K(63360K), 0.0062269 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

1.925: [GC (Allocation Failure) 1.925: [ParNew: 19647K->1775K(19648K), 0.0049197 secs] 26261K->9683K(63360K), 0.0049641 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

2.075: [GC (Allocation Failure) 2.075: [ParNew: 19247K->1657K(19648K), 0.0042368 secs] 27155K->10209K(63360K), 0.0042795 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

2.205: [GC (Allocation Failure) 2.205: [ParNew: 19129K->1045K(19648K), 0.0076808 secs] 27681K->10356K(63360K), 0.0077255 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 

2018-12-07T10:01:00,056 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.DruidNode] from props[druid.] as [DruidNode{serviceName='druid/epsilon-prod/middleManager', host='{middlemanagerIP}', port=-1, plaintextPort=8091, enablePlaintextPort=true, tlsPort=-1, enableTlsPort=false}]

2018-12-07T10:01:00,070 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.curator.CuratorConfig] from props[druid.zk.service.] as [io.druid.curator.CuratorConfig@c446b14]

2018-12-07T10:01:00,080 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.curator.ExhibitorConfig] from props[druid.exhibitor.service.] as [io.druid.curator.ExhibitorConfig@52fc5eb1]

2018-12-07T10:01:00,127 INFO [main] org.apache.curator.utils.Compatibility - Running in ZooKeeper 3.4.x compatibility mode

2018-12-07T10:01:00,129 WARN [main] org.apache.curator.retry.ExponentialBackoffRetry - maxRetries too large (30). Pinning to 29

2018-12-07T10:01:00,161 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.initialization.ZkPathsConfig] from props[druid.zk.paths.] as [io.druid.server.initialization.ZkPathsConfig@1845610a]

2018-12-07T10:01:00,165 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.java.util.emitter.core.LoggingEmitterConfig] from props[druid.emitter.logging.] as [LoggingEmitterConfig{loggerClass='io.druid.java.util.emitter.core.LoggingEmitter', logLevel='debug'}]

2.334: [GC (Allocation Failure) 2.334: [ParNew: 18517K->2175K(19648K), 0.0028734 secs] 27828K->11528K(63360K), 0.0029101 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

2018-12-07T10:01:00,179 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[interface io.druid.server.security.Escalator] from props[druid.escalator.] as [io.druid.server.security.NoopEscalator@27d57a2c]

2018-12-07T10:01:00,187 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.security.AuthConfig] from props[druid.auth.] as [AuthConfig{authenticatorChain=null, authorizers=null, allowUnauthenticatedHttpOptions=false}]

2018-12-07T10:01:00,233 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.metrics.DruidMonitorSchedulerConfig] from props[druid.monitoring.] as [io.druid.server.metrics.DruidMonitorSchedulerConfig@1fcf9739]

2018-12-07T10:01:00,238 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.metrics.MonitorsConfig] from props[druid.monitoring.] as [MonitorsConfig{monitors=[class io.druid.java.util.metrics.JvmMonitor]}]

2018-12-07T10:01:00,238 INFO [main] io.druid.server.emitter.EmitterModule - Underlying emitter for ServiceEmitter: LoggingEmitter{log=Logger{name=[io.druid.java.util.emitter.core.LoggingEmitter], class[class org.apache.logging.slf4j.Log4jLogger]}, level=DEBUG}

2018-12-07T10:01:00,238 INFO [main] io.druid.server.emitter.EmitterModule - Extra service dimensions: {version=0.12.3}

2018-12-07T10:01:00,252 INFO [main] io.druid.server.metrics.MetricsModule - Adding monitor[io.druid.java.util.metrics.JvmMonitor@60acd609]

2018-12-07T10:01:00,252 INFO [main] io.druid.server.metrics.MetricsModule - Adding monitor[io.druid.server.initialization.jetty.JettyServerModule$JettyMonitor@5f18f9d2]

2018-12-07T10:01:00,256 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.log.StartupLoggingConfig] from props[druid.startup.logging.] as [io.druid.server.log.StartupLoggingConfig@563a89b5]

2018-12-07T10:01:00,256 INFO [main] io.druid.cli.CliMiddleManager - Starting up with processors[2], memory[64,880,640], maxMemory[64,880,640].

2018-12-07T10:01:00,257 INFO [main] io.druid.cli.CliMiddleManager - * awt.toolkit: sun.awt.X11.XToolkit

2018-12-07T10:01:00,258 INFO [main] io.druid.cli.CliMiddleManager - * druid.cache.readBufferSize: 10485760

2018-12-07T10:01:00,258 INFO [main] io.druid.cli.CliMiddleManager - * druid.cache.sizeInBytes: 10485760

2018-12-07T10:01:00,258 INFO [main] io.druid.cli.CliMiddleManager - * druid.cache.type: local

2018-12-07T10:01:00,258 INFO [main] io.druid.cli.CliMiddleManager - * druid.discovery.curator.path: /epsilon-prod/discovery

2018-12-07T10:01:00,258 INFO [main] io.druid.cli.CliMiddleManager - * druid.emitter: logging

2018-12-07T10:01:00,258 INFO [main] io.druid.cli.CliMiddleManager - * druid.emitter.logging.logLevel: debug

2018-12-07T10:01:00,258 INFO [main] io.druid.cli.CliMiddleManager - * druid.extensions.loadList: ["druid-s3-extensions", "druid-histogram", "mysql-metadata-storage"]

2018-12-07T10:01:00,258 INFO [main] io.druid.cli.CliMiddleManager - * druid.host: {middlemanagerIP}

2018-12-07T10:01:00,258 INFO [main] io.druid.cli.CliMiddleManager - * druid.indexer.fork.property.druid.monitoring.monitors: ["com.metamx.metrics.JvmMonitor"]

2018-12-07T10:01:00,258 INFO [main] io.druid.cli.CliMiddleManager - * druid.indexer.fork.property.druid.processing.buffer.sizeBytes: 419430400

2018-12-07T10:01:00,258 INFO [main] io.druid.cli.CliMiddleManager - * druid.indexer.fork.property.druid.processing.numThreads: 1

2018-12-07T10:01:00,258 INFO [main] io.druid.cli.CliMiddleManager - * druid.indexer.logs.s3Bucket: {s3bucket_name}

2018-12-07T10:01:00,258 INFO [main] io.druid.cli.CliMiddleManager - * druid.indexer.logs.s3Prefix: druid/indexing-logs

2018-12-07T10:01:00,259 INFO [main] io.druid.cli.CliMiddleManager - * druid.indexer.logs.type: s3

2018-12-07T10:01:00,259 INFO [main] io.druid.cli.CliMiddleManager - * druid.indexer.runner.javaOpts: -server -Xmx3g -XX:+UseG1GC -XX:MaxGCPauseMillis=100 -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Duser.timezone=UTC -Dfile.encoding=UTF-8 -Djava.util.logging.manager=org.apache.logging.log4j.jul.LogManager

2018-12-07T10:01:00,259 INFO [main] io.druid.cli.CliMiddleManager - * druid.indexer.task.baseTaskDir: var/druid/task

2018-12-07T10:01:00,259 INFO [main] io.druid.cli.CliMiddleManager - * druid.indexer.task.defaultHadoopCoordinates: ["org.apache.hadoop:hadoop-client:2.7.3"]

2018-12-07T10:01:00,259 INFO [main] io.druid.cli.CliMiddleManager - * druid.indexer.task.hadoopWorkingPath: var/druid/hadoop-tmp

2018-12-07T10:01:00,259 INFO [main] io.druid.cli.CliMiddleManager - * druid.indexing.doubleStorage: double

2018-12-07T10:01:00,259 INFO [main] io.druid.cli.CliMiddleManager - * druid.metadata.storage.connector.connectURI: {jdbcurl}

2018-12-07T10:01:00,259 INFO [main] io.druid.cli.CliMiddleManager - * druid.metadata.storage.connector.password: <masked>

2018-12-07T10:01:00,259 INFO [main] io.druid.cli.CliMiddleManager - * druid.metadata.storage.connector.user: druid

2018-12-07T10:01:00,259 INFO [main] io.druid.cli.CliMiddleManager - * druid.metadata.storage.type: mysql

2018-12-07T10:01:00,259 INFO [main] io.druid.cli.CliMiddleManager - * druid.monitoring.monitors: ["io.druid.java.util.metrics.JvmMonitor"]

2018-12-07T10:01:00,259 INFO [main] io.druid.cli.CliMiddleManager - * druid.port: 8091

2018-12-07T10:01:00,260 INFO [main] io.druid.cli.CliMiddleManager - * druid.request.logging.feed: druid_requests

2018-12-07T10:01:00,260 INFO [main] io.druid.cli.CliMiddleManager - * druid.request.logging.type: emitter

2018-12-07T10:01:00,260 INFO [main] io.druid.cli.CliMiddleManager - * druid.s3.accessKey: {key}

2018-12-07T10:01:00,260 INFO [main] io.druid.cli.CliMiddleManager - * druid.s3.secretKey: <masked>

2018-12-07T10:01:00,260 INFO [main] io.druid.cli.CliMiddleManager - * druid.selectors.coordinator.serviceName: druid/epsilon-prod/coordinator

2018-12-07T10:01:00,260 INFO [main] io.druid.cli.CliMiddleManager - * druid.selectors.indexing.serviceName: druid/epsilon-prod/overlord

2018-12-07T10:01:00,260 INFO [main] io.druid.cli.CliMiddleManager - * druid.server.http.numThreads: 40

2018-12-07T10:01:00,260 INFO [main] io.druid.cli.CliMiddleManager - * druid.service: druid/epsilon-prod/middleManager

2018-12-07T10:01:00,260 INFO [main] io.druid.cli.CliMiddleManager - * druid.sql.enable: true

2018-12-07T10:01:00,260 INFO [main] io.druid.cli.CliMiddleManager - * druid.startup.logging.logProperties: true

2018-12-07T10:01:00,260 INFO [main] io.druid.cli.CliMiddleManager - * druid.storage.baseKey: druid/segments

2018-12-07T10:01:00,260 INFO [main] io.druid.cli.CliMiddleManager - * druid.storage.bucket: epsilon-druid

2018-12-07T10:01:00,260 INFO [main] io.druid.cli.CliMiddleManager - * druid.storage.type: s3

2018-12-07T10:01:00,261 INFO [main] io.druid.cli.CliMiddleManager - * druid.worker.capacity: 1

2018-12-07T10:01:00,261 INFO [main] io.druid.cli.CliMiddleManager - * druid.zk.paths.base: /druid/epsilon-prod

2018-12-07T10:01:00,261 INFO [main] io.druid.cli.CliMiddleManager - * druid.zk.service.host: zk1.net,zk2.net,zk3.net

2018-12-07T10:01:00,261 INFO [main] io.druid.cli.CliMiddleManager - * file.encoding: UTF-8

2018-12-07T10:01:00,261 INFO [main] io.druid.cli.CliMiddleManager - * file.encoding.pkg: sun.io

2018-12-07T10:01:00,261 INFO [main] io.druid.cli.CliMiddleManager - * file.separator: /

2018-12-07T10:01:00,261 INFO [main] io.druid.cli.CliMiddleManager - * java.awt.graphicsenv: sun.awt.X11GraphicsEnvironment

2018-12-07T10:01:00,261 INFO [main] io.druid.cli.CliMiddleManager - * java.awt.printerjob: sun.print.PSPrinterJob

2018-12-07T10:01:00,261 INFO [main] io.druid.cli.CliMiddleManager - * java.class.path: conf/druid/_common:conf/druid/middleManager:lib/janino-2.7.6.jar:lib/netty-buffer-4.0.52.Final.jar:lib/jetty-servlets-9.3.19.v20170502.jar:lib/jackson-datatype-guava-2.4.6.jar:lib/aether-connector-file-0.9.0.M2.jar:lib/guava-16.0.1.jar:lib/reactive-streams-1.0.0.jar:lib/httpcore-4.4.3.jar:lib/maven-aether-provider-3.1.1.jar:lib/druid-indexing-hadoop-0.12.3.jar:lib/jersey-core-1.19.3.jar:lib/netty-resolver-dns-2.0.37.jar:lib/javax.el-3.0.0.jar:lib/jetty-server-9.3.19.v20170502.jar:lib/jackson-module-jaxb-annotations-2.4.6.jar:lib/slf4j-api-1.6.4.jar:lib/validation-api-1.1.0.Final.jar:lib/javax.inject-1.jar:lib/jetty-io-9.3.19.v20170502.jar:lib/log4j-api-2.5.jar:lib/zookeeper-3.4.10.jar:lib/maven-model-builder-3.1.1.jar:lib/aws-java-sdk-ec2-1.10.77.jar:lib/netty-common-4.0.52.Final.jar:lib/jackson-databind-2.4.6.jar:lib/config-magic-0.9.jar:lib/jersey-guice-1.19.3.jar:lib/commons-pool-1.6.jar:lib/aggdesigner-algorithm-6.0.jar:lib/java-xmlbuilder-1.1.jar:lib/curator-x-discovery-4.0.0.jar:lib/jackson-mapper-asl-1.9.13.jar:lib/netty-codec-http-4.0.52.Final.jar:lib/commons-pool2-2.2.jar:lib/jetty-client-9.3.19.v20170502.jar:lib/jackson-core-2.4.6.jar:lib/tesla-aether-0.0.5.jar:lib/druid-api-0.12.3.jar:lib/joni-2.1.11.jar:lib/jetty-util-9.3.19.v20170502.jar:lib/aopalliance-1.0.jar:lib/caffeine-2.5.5.jar:lib/avatica-core-1.10.0.jar:lib/protobuf-java-3.1.0.jar:lib/plexus-utils-3.0.15.jar:lib/aether-impl-0.9.0.M2.jar:lib/commons-math3-3.6.1.jar:lib/opencsv-2.3.jar:lib/calcite-linq4j-1.15.0.jar:lib/jackson-jaxrs-json-provider-2.4.6.jar:lib/calcite-core-1.15.0.jar:lib/guice-multibindings-4.1.0.jar:lib/curator-client-4.0.0.jar:lib/derby-10.11.1.1.jar:lib/guice-4.1.0.jar:lib/aether-connector-okhttp-0.0.9.jar:lib/jboss-logging-3.1.3.GA.jar:lib/netty-codec-4.0.52.Final.jar:lib/commons-lang-2.6.jar:lib/jetty-continuation-9.3.19.v20170502.jar:lib/jetty-http-9.3.19.v20170502.jar:lib/irc-api-1.0-0014.jar:lib/asm-5.2.jar:lib/netty-transport-native-epoll-4.0.52.Final-linux-x86_64.jar:lib/classmate-1.0.0.jar:lib/maven-settings-builder-3.1.1.jar:lib/commons-cli-1.2.jar:lib/json-path-2.1.0.jar:lib/plexus-interpolation-1.19.jar:lib/druid-hll-0.12.3.jar:lib/aether-spi-0.9.0.M2.jar:lib/maven-model-3.1.1.jar:lib/jackson-core-asl-1.9.13.jar:lib/jackson-dataformat-cbor-2.5.3.jar:lib/jersey-server-1.19.3.jar:lib/geoip2-0.4.0.jar:lib/jersey-servlet-1.19.3.jar:lib/okhttp-1.0.2.jar:lib/compress-lzf-1.0.4.jar:lib/aether-util-0.9.0.M2.jar:lib/curator-framework-4.0.0.jar:lib/jackson-jaxrs-base-2.4.6.jar:lib/netty-3.10.6.Final.jar:lib/asm-commons-5.2.jar:lib/maxminddb-0.2.0.jar:lib/asm-tree-5.2.jar:lib/icu4j-54.1.1.jar:lib/async-http-client-netty-utils-2.0.37.jar:lib/commons-dbcp-1.4.jar:lib/netty-transport-4.0.52.Final.jar:lib/maven-settings-3.1.1.jar:lib/async-http-client-2.0.37.jar:lib/airline-0.7.jar:lib/commons-io-2.5.jar:lib/netty-resolver-2.0.37.jar:lib/netty-handler-4.0.52.Final.jar:lib/base64-2.3.8.jar:lib/esri-geometry-api-2.0.0.jar:lib/jets3t-0.9.4.jar:lib/derbynet-10.11.1.1.jar:lib/log4j-jul-2.5.jar:lib/netty-reactive-streams-1.0.8.jar:lib/netty-codec-dns-2.0.37.jar:lib/jcodings-1.0.13.jar:lib/log4j-core-2.5.jar:lib/druid-indexing-service-0.12.3.jar:lib/mapdb-1.0.8.jar:lib/log4j-1.2-api-2.5.jar:lib/jcl-over-slf4j-1.7.12.jar:lib/guice-servlet-4.1.0.jar:lib/commons-compiler-2.7.6.jar:lib/jvm-attach-api-1.2.jar:lib/jetty-security-9.3.19.v20170502.jar:lib/disruptor-3.3.6.jar:lib/extendedset-0.12.3.jar:lib/commons-logging-1.1.1.jar:lib/antlr4-runtime-4.5.1.jar:lib/derbyclient-10.11.1.1.jar:lib/fastutil-8.1.0.jar:lib/aether-api-0.9.0.M2.jar:lib/jackson-datatype-joda-2.4.6.jar:lib/avatica-metrics-1.10.0.jar:lib/druid-server-0.12.3.jar:lib/hibernate-validator-5.1.3.Final.jar:lib/activation-1.1.1.jar:lib/aws-java-sdk-core-1.10.77.jar:lib/druid-console-0.0.2.jar:lib/joda-time-2.9.9.jar:lib/log4j-slf4j-impl-2.5.jar:lib/jline-0.9.94.jar:lib/jetty-proxy-9.3.19.v20170502.jar:lib/commons-lang3-3.2.jar:lib/jackson-jaxrs-smile-provider-2.4.6.jar:lib/RoaringBitmap-0.5.18.jar:lib/commons-codec-1.7.jar:lib/netty-all-4.0.52.Final.jar:lib/lz4-1.3.0.jar:lib/avatica-server-1.10.0.jar:lib/java-util-0.12.3.jar:lib/javax.el-api-3.0.0.jar:lib/jackson-annotations-2.4.6.jar:lib/druid-aws-common-0.12.3.jar:lib/bcprov-jdk15on-1.52.jar:lib/maven-repository-metadata-3.1.1.jar:lib/wagon-provider-api-2.4.jar:lib/jackson-jq-0.0.7.jar:lib/rhino-1.7R5.jar:lib/jdbi-2.63.1.jar:lib/druid-common-0.12.3.jar:lib/httpclient-4.5.1.jar:lib/commons-dbcp2-2.0.1.jar:lib/druid-processing-0.12.3.jar:lib/druid-services-0.12.3.jar:lib/jetty-servlet-9.3.19.v20170502.jar:lib/jackson-dataformat-smile-2.4.6.jar:lib/spymemcached-2.12.3.jar:lib/jsr311-api-1.1.1.jar:lib/jsr305-2.0.1.jar:lib/javax.servlet-api-3.1.0.jar:lib/druid-sql-0.12.3.jar:lib/curator-recipes-4.0.0.jar:

2018-12-07T10:01:00,261 INFO [main] io.druid.cli.CliMiddleManager - * java.class.version: 52.0

2018-12-07T10:01:00,261 INFO [main] io.druid.cli.CliMiddleManager - * java.endorsed.dirs: /usr/lib/jvm/java-8-openjdk-amd64/jre/lib/endorsed

2018-12-07T10:01:00,261 INFO [main] io.druid.cli.CliMiddleManager - * java.ext.dirs: /usr/lib/jvm/java-8-openjdk-amd64/jre/lib/ext:/usr/java/packages/lib/ext

2018-12-07T10:01:00,261 INFO [main] io.druid.cli.CliMiddleManager - * java.home: /usr/lib/jvm/java-8-openjdk-amd64/jre

2018-12-07T10:01:00,261 INFO [main] io.druid.cli.CliMiddleManager - * java.io.tmpdir: /tmp

2018-12-07T10:01:00,262 INFO [main] io.druid.cli.CliMiddleManager - * java.library.path: /usr/java/packages/lib/amd64:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib

2018-12-07T10:01:00,262 INFO [main] io.druid.cli.CliMiddleManager - * java.runtime.name: OpenJDK Runtime Environment

2018-12-07T10:01:00,262 INFO [main] io.druid.cli.CliMiddleManager - * java.runtime.version: 1.8.0_191-8u191-b12-0ubuntu0.16.04.1-b12

2018-12-07T10:01:00,262 INFO [main] io.druid.cli.CliMiddleManager - * java.specification.name: Java Platform API Specification

2018-12-07T10:01:00,262 INFO [main] io.druid.cli.CliMiddleManager - * java.specification.vendor: Oracle Corporation

2018-12-07T10:01:00,262 INFO [main] io.druid.cli.CliMiddleManager - * java.specification.version: 1.8

2018-12-07T10:01:00,262 INFO [main] io.druid.cli.CliMiddleManager - * java.util.logging.manager: org.apache.logging.log4j.jul.LogManager

2018-12-07T10:01:00,262 INFO [main] io.druid.cli.CliMiddleManager - * java.vendor: Oracle Corporation

2018-12-07T10:01:00,262 INFO [main] io.druid.cli.CliMiddleManager - * java.vendor.url: http://java.oracle.com/

2018-12-07T10:01:00,262 INFO [main] io.druid.cli.CliMiddleManager - * java.vendor.url.bug: http://bugreport.sun.com/bugreport/

2018-12-07T10:01:00,262 INFO [main] io.druid.cli.CliMiddleManager - * java.version: 1.8.0_191

2018-12-07T10:01:00,262 INFO [main] io.druid.cli.CliMiddleManager - * java.vm.info: mixed mode

2018-12-07T10:01:00,262 INFO [main] io.druid.cli.CliMiddleManager - * java.vm.name: OpenJDK 64-Bit Server VM

2018-12-07T10:01:00,262 INFO [main] io.druid.cli.CliMiddleManager - * java.vm.specification.name: Java Virtual Machine Specification

2018-12-07T10:01:00,263 INFO [main] io.druid.cli.CliMiddleManager - * java.vm.specification.vendor: Oracle Corporation

2018-12-07T10:01:00,263 INFO [main] io.druid.cli.CliMiddleManager - * java.vm.specification.version: 1.8

2018-12-07T10:01:00,263 INFO [main] io.druid.cli.CliMiddleManager - * java.vm.vendor: Oracle Corporation

2018-12-07T10:01:00,263 INFO [main] io.druid.cli.CliMiddleManager - * java.vm.version: 25.191-b12

2018-12-07T10:01:00,263 INFO [main] io.druid.cli.CliMiddleManager - * line.separator: 

2018-12-07T10:01:00,263 INFO [main] io.druid.cli.CliMiddleManager - * log4j.shutdownCallbackRegistry: io.druid.common.config.Log4jShutdown

2018-12-07T10:01:00,263 INFO [main] io.druid.cli.CliMiddleManager - * log4j.shutdownHookEnabled: true

2018-12-07T10:01:00,263 INFO [main] io.druid.cli.CliMiddleManager - * os.arch: amd64

2018-12-07T10:01:00,263 INFO [main] io.druid.cli.CliMiddleManager - * os.name: Linux

2018-12-07T10:01:00,263 INFO [main] io.druid.cli.CliMiddleManager - * os.version: 4.4.0-1072-aws

2018-12-07T10:01:00,263 INFO [main] io.druid.cli.CliMiddleManager - * path.separator: :

2018-12-07T10:01:00,263 INFO [main] io.druid.cli.CliMiddleManager - * sun.arch.data.model: 64

2018-12-07T10:01:00,263 INFO [main] io.druid.cli.CliMiddleManager - * sun.boot.class.path: /usr/lib/jvm/java-8-openjdk-amd64/jre/lib/resources.jar:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/rt.jar:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/sunrsasign.jar:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/jsse.jar:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/jce.jar:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/charsets.jar:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/jfr.jar:/usr/lib/jvm/java-8-openjdk-amd64/jre/classes

2018-12-07T10:01:00,263 INFO [main] io.druid.cli.CliMiddleManager - * sun.boot.library.path: /usr/lib/jvm/java-8-openjdk-amd64/jre/lib/amd64

2018-12-07T10:01:00,263 INFO [main] io.druid.cli.CliMiddleManager - * sun.cpu.endian: little

2018-12-07T10:01:00,264 INFO [main] io.druid.cli.CliMiddleManager - * sun.cpu.isalist: 

2018-12-07T10:01:00,264 INFO [main] io.druid.cli.CliMiddleManager - * sun.io.unicode.encoding: UnicodeLittle

2018-12-07T10:01:00,264 INFO [main] io.druid.cli.CliMiddleManager - * sun.java.command: io.druid.cli.Main server middleManager

2018-12-07T10:01:00,264 INFO [main] io.druid.cli.CliMiddleManager - * sun.java.launcher: SUN_STANDARD

2018-12-07T10:01:00,264 INFO [main] io.druid.cli.CliMiddleManager - * sun.jnu.encoding: UTF-8

2018-12-07T10:01:00,264 INFO [main] io.druid.cli.CliMiddleManager - * sun.management.compiler: HotSpot 64-Bit Tiered Compilers

2018-12-07T10:01:00,264 INFO [main] io.druid.cli.CliMiddleManager - * sun.os.patch.level: unknown

2018-12-07T10:01:00,264 INFO [main] io.druid.cli.CliMiddleManager - * user.country: US

2018-12-07T10:01:00,264 INFO [main] io.druid.cli.CliMiddleManager - * user.dir: /opt/druid-0.12.3

2018-12-07T10:01:00,264 INFO [main] io.druid.cli.CliMiddleManager - * user.home: /root

2018-12-07T10:01:00,264 INFO [main] io.druid.cli.CliMiddleManager - * user.language: en

2018-12-07T10:01:00,264 INFO [main] io.druid.cli.CliMiddleManager - * user.name: root

2018-12-07T10:01:00,264 INFO [main] io.druid.cli.CliMiddleManager - * user.timezone: UTC

2018-12-07T10:01:00,268 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.initialization.IndexerZkConfig] from props[druid.zk.paths.indexer.] as [io.druid.server.initialization.IndexerZkConfig@c539cc0a]

2018-12-07T10:01:00,278 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.indexing.overlord.config.RemoteTaskRunnerConfig] from props[druid.indexer.runner.] as [RemoteTaskRunnerConfig{taskAssignmentTimeout=PT5M, taskCleanupTimeout=PT15M, minWorkerVersion='0', maxZnodeBytes=524288, taskShutdownLinkTimeout=PT1M, pendingTasksRunnerNumThreads=1, maxRetriesBeforeBlacklist=5, taskBlackListBackoffTimeMillis=PT15M, taskBlackListCleanupPeriod=PT5M, maxPercentageBlacklistWorkers= 20}]

2018-12-07T10:01:00,284 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.indexing.worker.config.WorkerConfig] from props[druid.worker.] as [io.druid.indexing.worker.config.WorkerConfig@28fd3dc1]

2018-12-07T10:01:00,301 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.indexing.overlord.config.ForkingTaskRunnerConfig] from props[druid.indexer.runner.] as [io.druid.indexing.overlord.config.ForkingTaskRunnerConfig@5c20aab9]

2018-12-07T10:01:00,308 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.indexing.common.config.TaskConfig] from props[druid.indexer.task.] as [io.druid.indexing.common.config.TaskConfig@43f61afb]

2018-12-07T10:01:00,310 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.storage.s3.S3TaskLogsConfig] from props[druid.indexer.logs.] as [io.druid.storage.s3.S3TaskLogsConfig@670ce331]

2018-12-07T10:01:00,314 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.common.aws.AWSCredentialsConfig] from props[druid.s3.] as [io.druid.common.aws.AWSCredentialsConfig@2416498e]

2.486: [GC (Allocation Failure) 2.486: [ParNew: 19647K->1389K(19648K), 0.0048172 secs] 29000K->11556K(63360K), 0.0048576 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2018-12-07T10:01:00,389 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.initialization.ServerConfig] from props[druid.server.http.] as [io.druid.server.initialization.ServerConfig@893d5e45]

2018-12-07T10:01:00,394 INFO [main] io.druid.guice.JsonConfigurator - Loaded class[class io.druid.server.initialization.TLSServerConfig] from props[druid.server.https.] as [TLSServerConfig{keyStorePath='null', keyStoreType='null', certAlias='null', keyManagerFactoryAlgorithm='null', includeCipherSuites=null, excludeCipherSuites=null, includeProtocols=null, excludeProtocols=null}]

2018-12-07T10:01:00,403 INFO [main] org.eclipse.jetty.util.log - Logging initialized @2565ms

2018-12-07T10:01:00,412 INFO [main] io.druid.server.initialization.jetty.JettyServerModule - Creating http connector with port [8091]

2.628: [GC (Allocation Failure) 2.628: [ParNew: 18861K->1770K(19648K), 0.0072118 secs] 29028K->12521K(63360K), 0.0072573 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 

2018-12-07T10:01:00,518 INFO [main] io.druid.curator.CuratorModule - Starting Curator

2018-12-07T10:01:00,518 INFO [main] org.apache.curator.framework.imps.CuratorFrameworkImpl - Starting

2018-12-07T10:01:00,527 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:zookeeper.version=3.4.10-39d3a4f269333c922ed3db283be479f9deacaa0f, built on 03/23/2017 10:13 GMT

2018-12-07T10:01:00,527 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:host.name=ip-{middlemanagerIp}.ec2.internal

2018-12-07T10:01:00,527 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:java.version=1.8.0_191

2018-12-07T10:01:00,527 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:java.vendor=Oracle Corporation

2018-12-07T10:01:00,527 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:java.home=/usr/lib/jvm/java-8-openjdk-amd64/jre

2018-12-07T10:01:00,527 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:java.class.path=conf/druid/_common:conf/druid/middleManager:lib/janino-2.7.6.jar:lib/netty-buffer-4.0.52.Final.jar:lib/jetty-servlets-9.3.19.v20170502.jar:lib/jackson-datatype-guava-2.4.6.jar:lib/aether-connector-file-0.9.0.M2.jar:lib/guava-16.0.1.jar:lib/reactive-streams-1.0.0.jar:lib/httpcore-4.4.3.jar:lib/maven-aether-provider-3.1.1.jar:lib/druid-indexing-hadoop-0.12.3.jar:lib/jersey-core-1.19.3.jar:lib/netty-resolver-dns-2.0.37.jar:lib/javax.el-3.0.0.jar:lib/jetty-server-9.3.19.v20170502.jar:lib/jackson-module-jaxb-annotations-2.4.6.jar:lib/slf4j-api-1.6.4.jar:lib/validation-api-1.1.0.Final.jar:lib/javax.inject-1.jar:lib/jetty-io-9.3.19.v20170502.jar:lib/log4j-api-2.5.jar:lib/zookeeper-3.4.10.jar:lib/maven-model-builder-3.1.1.jar:lib/aws-java-sdk-ec2-1.10.77.jar:lib/netty-common-4.0.52.Final.jar:lib/jackson-databind-2.4.6.jar:lib/config-magic-0.9.jar:lib/jersey-guice-1.19.3.jar:lib/commons-pool-1.6.jar:lib/aggdesigner-algorithm-6.0.jar:lib/java-xmlbuilder-1.1.jar:lib/curator-x-discovery-4.0.0.jar:lib/jackson-mapper-asl-1.9.13.jar:lib/netty-codec-http-4.0.52.Final.jar:lib/commons-pool2-2.2.jar:lib/jetty-client-9.3.19.v20170502.jar:lib/jackson-core-2.4.6.jar:lib/tesla-aether-0.0.5.jar:lib/druid-api-0.12.3.jar:lib/joni-2.1.11.jar:lib/jetty-util-9.3.19.v20170502.jar:lib/aopalliance-1.0.jar:lib/caffeine-2.5.5.jar:lib/avatica-core-1.10.0.jar:lib/protobuf-java-3.1.0.jar:lib/plexus-utils-3.0.15.jar:lib/aether-impl-0.9.0.M2.jar:lib/commons-math3-3.6.1.jar:lib/opencsv-2.3.jar:lib/calcite-linq4j-1.15.0.jar:lib/jackson-jaxrs-json-provider-2.4.6.jar:lib/calcite-core-1.15.0.jar:lib/guice-multibindings-4.1.0.jar:lib/curator-client-4.0.0.jar:lib/derby-10.11.1.1.jar:lib/guice-4.1.0.jar:lib/aether-connector-okhttp-0.0.9.jar:lib/jboss-logging-3.1.3.GA.jar:lib/netty-codec-4.0.52.Final.jar:lib/commons-lang-2.6.jar:lib/jetty-continuation-9.3.19.v20170502.jar:lib/jetty-http-9.3.19.v20170502.jar:lib/irc-api-1.0-0014.jar:lib/asm-5.2.jar:lib/netty-transport-native-epoll-4.0.52.Final-linux-x86_64.jar:lib/classmate-1.0.0.jar:lib/maven-settings-builder-3.1.1.jar:lib/commons-cli-1.2.jar:lib/json-path-2.1.0.jar:lib/plexus-interpolation-1.19.jar:lib/druid-hll-0.12.3.jar:lib/aether-spi-0.9.0.M2.jar:lib/maven-model-3.1.1.jar:lib/jackson-core-asl-1.9.13.jar:lib/jackson-dataformat-cbor-2.5.3.jar:lib/jersey-server-1.19.3.jar:lib/geoip2-0.4.0.jar:lib/jersey-servlet-1.19.3.jar:lib/okhttp-1.0.2.jar:lib/compress-lzf-1.0.4.jar:lib/aether-util-0.9.0.M2.jar:lib/curator-framework-4.0.0.jar:lib/jackson-jaxrs-base-2.4.6.jar:lib/netty-3.10.6.Final.jar:lib/asm-commons-5.2.jar:lib/maxminddb-0.2.0.jar:lib/asm-tree-5.2.jar:lib/icu4j-54.1.1.jar:lib/async-http-client-netty-utils-2.0.37.jar:lib/commons-dbcp-1.4.jar:lib/netty-transport-4.0.52.Final.jar:lib/maven-settings-3.1.1.jar:lib/async-http-client-2.0.37.jar:lib/airline-0.7.jar:lib/commons-io-2.5.jar:lib/netty-resolver-2.0.37.jar:lib/netty-handler-4.0.52.Final.jar:lib/base64-2.3.8.jar:lib/esri-geometry-api-2.0.0.jar:lib/jets3t-0.9.4.jar:lib/derbynet-10.11.1.1.jar:lib/log4j-jul-2.5.jar:lib/netty-reactive-streams-1.0.8.jar:lib/netty-codec-dns-2.0.37.jar:lib/jcodings-1.0.13.jar:lib/log4j-core-2.5.jar:lib/druid-indexing-service-0.12.3.jar:lib/mapdb-1.0.8.jar:lib/log4j-1.2-api-2.5.jar:lib/jcl-over-slf4j-1.7.12.jar:lib/guice-servlet-4.1.0.jar:lib/commons-compiler-2.7.6.jar:lib/jvm-attach-api-1.2.jar:lib/jetty-security-9.3.19.v20170502.jar:lib/disruptor-3.3.6.jar:lib/extendedset-0.12.3.jar:lib/commons-logging-1.1.1.jar:lib/antlr4-runtime-4.5.1.jar:lib/derbyclient-10.11.1.1.jar:lib/fastutil-8.1.0.jar:lib/aether-api-0.9.0.M2.jar:lib/jackson-datatype-joda-2.4.6.jar:lib/avatica-metrics-1.10.0.jar:lib/druid-server-0.12.3.jar:lib/hibernate-validator-5.1.3.Final.jar:lib/activation-1.1.1.jar:lib/aws-java-sdk-core-1.10.77.jar:lib/druid-console-0.0.2.jar:lib/joda-time-2.9.9.jar:lib/log4j-slf4j-impl-2.5.jar:lib/jline-0.9.94.jar:lib/jetty-proxy-9.3.19.v20170502.jar:lib/commons-lang3-3.2.jar:lib/jackson-jaxrs-smile-provider-2.4.6.jar:lib/RoaringBitmap-0.5.18.jar:lib/commons-codec-1.7.jar:lib/netty-all-4.0.52.Final.jar:lib/lz4-1.3.0.jar:lib/avatica-server-1.10.0.jar:lib/java-util-0.12.3.jar:lib/javax.el-api-3.0.0.jar:lib/jackson-annotations-2.4.6.jar:lib/druid-aws-common-0.12.3.jar:lib/bcprov-jdk15on-1.52.jar:lib/maven-repository-metadata-3.1.1.jar:lib/wagon-provider-api-2.4.jar:lib/jackson-jq-0.0.7.jar:lib/rhino-1.7R5.jar:lib/jdbi-2.63.1.jar:lib/druid-common-0.12.3.jar:lib/httpclient-4.5.1.jar:lib/commons-dbcp2-2.0.1.jar:lib/druid-processing-0.12.3.jar:lib/druid-services-0.12.3.jar:lib/jetty-servlet-9.3.19.v20170502.jar:lib/jackson-dataformat-smile-2.4.6.jar:lib/spymemcached-2.12.3.jar:lib/jsr311-api-1.1.1.jar:lib/jsr305-2.0.1.jar:lib/javax.servlet-api-3.1.0.jar:lib/druid-sql-0.12.3.jar:lib/curator-recipes-4.0.0.jar:

2018-12-07T10:01:00,527 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib

2018-12-07T10:01:00,528 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:java.io.tmpdir=/tmp

2018-12-07T10:01:00,528 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:java.compiler=<NA>

2018-12-07T10:01:00,528 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:os.name=Linux

2018-12-07T10:01:00,528 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:os.arch=amd64

2018-12-07T10:01:00,528 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:os.version=4.4.0-1072-aws

2018-12-07T10:01:00,528 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:user.name=root

2018-12-07T10:01:00,528 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:user.home=/root

2018-12-07T10:01:00,528 INFO [main] org.apache.zookeeper.ZooKeeper - Client environment:user.dir=/opt/druid-0.12.3

2018-12-07T10:01:00,529 INFO [main] org.apache.zookeeper.ZooKeeper - Initiating client connection, connectString=zk1.net,zk2.net,zk3.net sessionTimeout=30000 watcher=org.apache.curator.ConnectionState@9aa2002

2018-12-07T10:01:00,529 INFO [main] org.apache.zookeeper.ZooKeeper - Initiating client connection, connectString=zk1.net,zk2.net,zk3.net sessionTimeout=30000 watcher=org.apache.curator.ConnectionState@9aa2002

2018-12-07T10:01:00,553 INFO [main] org.apache.curator.framework.imps.CuratorFrameworkImpl - Default schema

2018-12-07T10:01:00,554 INFO [main] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.curator.announcement.Announcer.start()] on object[io.druid.curator.announcement.Announcer@3fe46690].

2018-12-07T10:01:00,554 INFO [main] io.druid.curator.announcement.Announcer - Starting announcer

2018-12-07T10:01:00,555 INFO [main] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.java.util.emitter.core.LoggingEmitter.start()] on object[LoggingEmitter{log=Logger{name=[io.druid.java.util.emitter.core.LoggingEmitter], class[class org.apache.logging.slf4j.Log4jLogger]}, level=DEBUG}].

2018-12-07T10:01:00,555 INFO [main] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner.start()] on object[io.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner@31a3f4de].

2018-12-07T10:01:00,556 INFO [main] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.java.util.emitter.service.ServiceEmitter.start()] on object[ServiceEmitter{serviceDimensions={service=druid/epsilon-prod/middleManager, host={middlemanagerIP}:8091, version=0.12.3}, emitter=LoggingEmitter{log=Logger{name=[io.druid.java.util.emitter.core.LoggingEmitter], class[class org.apache.logging.slf4j.Log4jLogger]}, level=DEBUG}}].

2018-12-07T10:01:00,556 INFO [main] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.java.util.metrics.MonitorScheduler.start()] on object[io.druid.java.util.metrics.MonitorScheduler@6f3e19b3].

2018-12-07T10:01:00,558 INFO [main] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.indexing.worker.WorkerCuratorCoordinator.start() throws java.lang.Exception] on object[io.druid.indexing.worker.WorkerCuratorCoordinator@10c07b8d].

2018-12-07T10:01:00,559 INFO [main] io.druid.indexing.worker.WorkerCuratorCoordinator - WorkerCuratorCoordinator good to go sir. Server[{middlemanagerIP}:8091]

2018-12-07T10:01:00,565 INFO [main-SendThread(ip-{zookeeperIp1}.ec2.internal:2181)] org.apache.zookeeper.ClientCnxn - Opening socket connection to server ip-{zookeeperIp1}.ec2.internal/{zookeeperIp1}:2181. Will not attempt to authenticate using SASL (unknown error)

2018-12-07T10:01:00,577 INFO [main-SendThread(ip-{zookeeperIp1}.ec2.internal:2181)] org.apache.zookeeper.ClientCnxn - Socket connection established to ip-{zookeeperIp1}.ec2.internal/{zookeeperIp1}:2181, initiating session

2018-12-07T10:01:00,584 INFO [main-SendThread(ip-{zookeeperIp1}.ec2.internal:2181)] org.apache.zookeeper.ClientCnxn - Session establishment complete on server ip-{zookeeperIp1}.ec2.internal/{zookeeperIp1}:2181, sessionid = 0x26784378a95000f, negotiated timeout = 30000

2018-12-07T10:01:00,590 INFO [main-EventThread] org.apache.curator.framework.state.ConnectionStateManager - State change: CONNECTED

2018-12-07T10:01:00,605 INFO [main] io.druid.curator.announcement.Announcer - Starting announcer

2.811: [GC (Allocation Failure) 2.811: [ParNew: 19242K->2093K(19648K), 0.0038136 secs] 29993K->13254K(63360K), 0.0038592 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

2018-12-07T10:01:00,652 INFO [main] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.indexing.worker.WorkerTaskMonitor.start() throws java.lang.Exception] on object[io.druid.indexing.worker.WorkerTaskMonitor@730f9695].

2018-12-07T10:01:00,661 INFO [main] io.druid.indexing.overlord.ForkingTaskRunner - Restored 0 tasks.

2018-12-07T10:01:00,663 INFO [main] io.druid.indexing.overlord.ForkingTaskRunner - Registered listener [WorkerTaskMonitor]

2018-12-07T10:01:00,670 INFO [main] io.druid.indexing.worker.WorkerTaskMonitor - Started WorkerTaskMonitor.

2018-12-07T10:01:00,670 INFO [main] io.druid.server.initialization.jetty.JettyServerModule - Starting Jetty Server...

2018-12-07T10:01:00,671 INFO [main] org.eclipse.jetty.server.Server - jetty-9.3.19.v20170502

2018-12-07T10:01:00,767 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Registering com.fasterxml.jackson.jaxrs.json.JacksonJsonProvider as a provider class

2018-12-07T10:01:00,767 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Registering com.fasterxml.jackson.jaxrs.smile.JacksonSmileProvider as a provider class

2018-12-07T10:01:00,768 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Registering io.druid.server.initialization.jetty.CustomExceptionMapper as a provider class

2018-12-07T10:01:00,768 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Registering io.druid.server.initialization.jetty.ForbiddenExceptionMapper as a provider class

2018-12-07T10:01:00,768 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Registering io.druid.server.StatusResource as a root resource class

2018-12-07T10:01:00,770 INFO [main] com.sun.jersey.server.impl.application.WebApplicationImpl - Initiating Jersey application, version 'Jersey: 1.19.3 10/24/2016 03:43 PM'

2.967: [GC (Allocation Failure) 2.967: [ParNew: 19565K->1787K(19648K), 0.0038952 secs] 30726K->13577K(63360K), 0.0039500 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2018-12-07T10:01:00,831 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Binding io.druid.server.initialization.jetty.CustomExceptionMapper to GuiceManagedComponentProvider with the scope "Singleton"

2018-12-07T10:01:00,832 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Binding io.druid.server.initialization.jetty.ForbiddenExceptionMapper to GuiceManagedComponentProvider with the scope "Singleton"

2018-12-07T10:01:00,833 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Binding com.fasterxml.jackson.jaxrs.json.JacksonJsonProvider to GuiceManagedComponentProvider with the scope "Singleton"

2018-12-07T10:01:00,838 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Binding com.fasterxml.jackson.jaxrs.smile.JacksonSmileProvider to GuiceManagedComponentProvider with the scope "Singleton"

3.070: [GC (Allocation Failure) 3.070: [ParNew: 19259K->1153K(19648K), 0.0036846 secs] 31049K->13368K(63360K), 0.0037386 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

2018-12-07T10:01:01,064 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Binding io.druid.server.http.security.ConfigResourceFilter to GuiceInstantiatedComponentProvider

2018-12-07T10:01:01,076 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Binding io.druid.server.http.security.StateResourceFilter to GuiceInstantiatedComponentProvider

2018-12-07T10:01:01,094 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Binding io.druid.indexing.worker.http.WorkerResource to GuiceInstantiatedComponentProvider

2018-12-07T10:01:01,100 INFO [main] com.sun.jersey.guice.spi.container.GuiceComponentProviderFactory - Binding io.druid.server.StatusResource to GuiceManagedComponentProvider with the scope "Undefined"

3.278: [GC (Allocation Failure) 3.278: [ParNew: 18625K->1852K(19648K), 0.0032567 secs] 30840K->14066K(63360K), 0.0033062 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2018-12-07T10:01:01,122 INFO [main] org.eclipse.jetty.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@2721044{/,null,AVAILABLE}

2018-12-07T10:01:01,130 INFO [main] org.eclipse.jetty.server.AbstractConnector - Started ServerConnector@557715a8{HTTP/1.1,[http/1.1]}{0.0.0.0:8091}

2018-12-07T10:01:01,130 INFO [main] org.eclipse.jetty.server.Server - Started @3293ms

2018-12-07T10:01:01,130 INFO [main] io.druid.curator.discovery.CuratorDruidNodeAnnouncer - Announcing [DiscoveryDruidNode{druidNode=DruidNode{serviceName='druid/epsilon-prod/middleManager', host='{middlemanagerIP}', port=-1, plaintextPort=8091, enablePlaintextPort=true, tlsPort=-1, enableTlsPort=false}, nodeType='middleManager', services={workerNodeService=WorkerNodeService{ip='ip-{middlemanagerIp}.ec2.internal', capacity=1, version='0'}}}].

2018-12-07T10:01:01,145 INFO [main] io.druid.curator.discovery.CuratorDruidNodeAnnouncer - Announced [DiscoveryDruidNode{druidNode=DruidNode{serviceName='druid/epsilon-prod/middleManager', host='{middlemanagerIP}', port=-1, plaintextPort=8091, enablePlaintextPort=true, tlsPort=-1, enableTlsPort=false}, nodeType='middleManager', services={workerNodeService=WorkerNodeService{ip='ip-{middlemanagerIp}.ec2.internal', capacity=1, version='0'}}}].

91.503: [GC (Allocation Failure) 91.503: [ParNew: 19324K->1857K(19648K), 0.0056826 secs] 31538K->15398K(63360K), 0.0057450 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

2018-12-07T10:02:29,408 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Submitting runnable for task[index_f2_2018-12-07T10:02:29.102Z]

2018-12-07T10:02:29,423 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Affirmative. Running task [index_f2_2018-12-07T10:02:29.102Z]

2018-12-07T10:02:29,489 INFO [forking-task-runner-0] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_f2_2018-12-07T10:02:29.102Z] location changed to [TaskLocation{host='{middlemanagerIP}', port=8100, tlsPort=-1}].

2018-12-07T10:02:29,489 INFO [forking-task-runner-0] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_f2_2018-12-07T10:02:29.102Z] status changed to [RUNNING].

2018-12-07T10:02:29,489 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Updating task [index_f2_2018-12-07T10:02:29.102Z] announcement with location [TaskLocation{host='{middlemanagerIP}', port=8100, tlsPort=-1}]

2018-12-07T10:02:29,490 INFO [forking-task-runner-0] io.druid.indexing.overlord.ForkingTaskRunner - Logging task index_f2_2018-12-07T10:02:29.102Z output to: var/druid/task/index_f2_2018-12-07T10:02:29.102Z/log

213.914: [GC (Allocation Failure) 213.914: [ParNew: 19329K->1780K(19648K), 0.0045082 secs] 32870K->15846K(63360K), 0.0045641 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

213.919: [GC (CMS Initial Mark) [1 CMS-initial-mark: 14065K(43712K)] 16021K(63360K), 0.0045873 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

213.924: [CMS-concurrent-mark-start]

213.967: [CMS-concurrent-mark: 0.043/0.043 secs] [Times: user=0.05 sys=0.00, real=0.05 secs] 

213.967: [CMS-concurrent-preclean-start]

213.968: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

213.968: [CMS-concurrent-abortable-preclean-start]

2018-12-07T10:04:31,850 INFO [qtp2071364564-38] io.druid.indexing.overlord.ForkingTaskRunner - Killing process for task: index_f2_2018-12-07T10:02:29.102Z

2018-12-07T10:04:31,861 INFO [forking-task-runner-0] io.druid.storage.s3.S3TaskLogs - Pushing task log var/druid/task/index_f2_2018-12-07T10:02:29.102Z/log to: druid/indexing-logs/index_f2_2018-12-07T10:02:29.102Z/log

214.212: [GC (Allocation Failure) 214.212: [ParNew: 19252K->2176K(19648K), 0.0058727 secs] 33318K->17012K(63360K), 0.0059349 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

214.301: [CMS-concurrent-abortable-preclean: 0.152/0.333 secs] [Times: user=0.41 sys=0.02, real=0.33 secs] 

214.302: [GC (CMS Final Remark) [YG occupancy: 13239 K (19648 K)]214.302: [Rescan (parallel) , 0.0030564 secs]214.305: [weak refs processing, 0.0003289 secs]214.305: [class unloading, 0.0069670 secs]214.312: [scrub symbol table, 0.0050694 secs]214.317: [scrub string table, 0.0007982 secs][1 CMS-remark: 14836K(43712K)] 28076K(63360K), 0.0165774 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 

214.318: [CMS-concurrent-sweep-start]

214.326: [CMS-concurrent-sweep: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

214.326: [CMS-concurrent-reset-start]

214.326: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

214.415: [GC (Allocation Failure) 214.415: [ParNew: 19648K->1709K(19648K), 0.0054750 secs] 30973K->14488K(63360K), 0.0055349 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

2018-12-07T10:04:32,482 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_191]

at java.io.BufferedInputStream.read1(BufferedInputStream.java:291) ~[?:1.8.0_191]

at java.io.BufferedInputStream.read(BufferedInputStream.java:345) ~[?:1.8.0_191]

at java.io.FilterInputStream.read(FilterInputStream.java:107) ~[?:1.8.0_191]

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.3.jar:0.12.3]

at io.druid.indexing.overlord.ForkingTaskRunner$1.call(ForkingTaskRunner.java:224) [druid-indexing-service-0.12.3.jar:0.12.3]

at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_191]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_191]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_191]

at java.lang.Thread.run(Thread.java:748) [?:1.8.0_191]

2018-12-07T10:04:32,487 INFO [forking-task-runner-0] io.druid.indexing.overlord.ForkingTaskRunner - Removing task directory: var/druid/task/index_f2_2018-12-07T10:02:29.102Z

2018-12-07T10:04:32,576 INFO [WorkerTaskMonitor] io.druid.indexing.worker.WorkerTaskMonitor - Job's finished. Completed [index_f2_2018-12-07T10:02:29.102Z] with status [FAILED]

Any idea/help/pointer would be really appreciated !!!

Thanks,

Kiran

[Utkarsh Sopan]

Hi All,

Did anyone find out reason for this issue?

We are also facing this issue.

Or is it a good idea to switch to different deep storage tier for realtime tasks.

...

[Sumit Khanna]

Area of these 9-10 files the various parts-* in the s3 output bucket? We as well were once indexing nearly 100 partitions worth 5-10MB  under an s3 path and it was taking ages(as many mr jobs/containers), to not failing to ingest as druid segments. 

We coalesce to 2 partitions and it worked like a charm. 

--

You received this message because you are subscribed to the Google Groups "Druid User" group.
To unsubscribe from this group and stop receiving emails from it, send an email to druid-user+...@googlegroups.com.
To post to this group, send email to druid...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/druid-user/65d4d0e2-f6f7-4356-9968-b09d3b425c4d%40googlegroups.com.