2016-03-17 10:38:34,828 INFO i.d.i.w.WorkerTaskMonitor [WorkerTaskMonitor-0] Affirmative. Running task [index_druid_monitor_month_2016-03-17T10:38:34.775-04:00]
2016-03-17 10:38:34,828 INFO i.d.i.w.WorkerTaskMonitor [WorkerTaskMonitor-0] Affirmative. Running task [index_druid_monitor_month_2016-03-17T10:38:34.775-04:00]
2016-03-17 10:38:34,843 DEBUG o.a.z.ClientCnxn [main-SendThread(
10.200.6.80:2181)] Got notification sessionid:0x353649c6bf40011
2016-03-17 10:38:34,844 DEBUG o.a.z.ClientCnxn [main-SendThread(
10.200.6.80:2181)] Got notification sessionid:0x353649c6bf40011
2016-03-17 10:38:34,844 DEBUG o.a.z.ClientCnxn [main-SendThread(
10.200.6.80:2181)] Got WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/druid/indexer/tasks/
10.200.6.63:8091 for sessionid 0x353649c6bf40011
2016-03-17 10:38:34,845 DEBUG o.a.z.ClientCnxn [main-SendThread(
10.200.6.80:2181)] Reading reply sessionid:0x353649c6bf40011, packet:: clientPath:/druid/indexer/tasks/
10.200.6.63:8091 serverPath:/druid/indexer/tasks/
10.200.6.63:8091 finished:false header:: 83,12 replyHeader:: 83,124569964497,0 request:: '/druid/indexer/tasks/
10.200.6.63:8091,T response:: v{},s{115964117260,115964117260,1444144180127,1444144180127,0,10,0,0,43,0,124569964497}
2016-03-17 10:38:34,851 INFO i.d.i.o.ForkingTaskRunner [forking-task-runner-0] Running command: java -cp /usr/local/druid/config/_common:/usr/local/druid/config/middleManager:/usr/local/druid/lib/jetty-continuation-9.2.5.v20141112.jar: .....
2016-03-17 10:38:34,852 INFO i.d.i.o.ForkingTaskRunner [forking-task-runner-0] Logging task index_druid_monitor_month_2016-03-17T10:38:34.775-04:00 output to: /nas/druid/task/index_druid_monitor_month_2016-03-17T10:38:34.775-04:00/log
2016-03-17 10:38:40,151 INFO i.d.i.w.e.ExecutorLifecycle [main] Running with task: {
"type" : "index",
"id" : "index_druid_monitor_month_2016-03-17T10:38:34.775-04:00",
"resource" : {
"availabilityGroup" : "index_druid_monitor_month_2016-03-17T10:38:34.775-04:00",
"requiredCapacity" : 1
},
"spec" : {
"dataSchema" : {
"dataSource" : "druid_monitor_month",
"parser" : {
"type" : "string",
"parseSpec" : {
"format" : "json",
"timestampSpec" : {
"column" : "timestamp",
"format" : "auto"
},
"dimensionsSpec" : {
"dimensions" : [ "service", "host", "metric", "dataSource", "user1", "user2", "user3", "user4", "user5", "user6", "user7", "user8", "user9", "user10" ],
"dimensionExclusions" : [ ],
"spatialDimensions" : [ ]
}
}
},
"metricsSpec" : [ {
"type" : "count",
"name" : "count"
}, {
"type" : "doubleSum",
"name" : "amount",
"fieldName" : "value"
} ],
"granularitySpec" : {
"type" : "uniform",
"segmentGranularity" : "MONTH",
"queryGranularity" : {
"type" : "duration",
"duration" : 60000,
"origin" : "1969-12-31T19:00:00.000-05:00"
},
"intervals" : [ "2016-03-01T00:00:00.000-05:00/2016-03-20T00:00:00.000-04:00" ]
}
},
"ioConfig" : {
"type" : "index",
"firehose" : {
"type" : "ingestSegment",
"dataSource" : "druid_monitor",
"interval" : "2016-03-01T00:00:00.000-05:00/2016-03-20T00:00:00.000-04:00",
"filter" : null,
"dimensions" : null,
"metrics" : null
}
},
"tuningConfig" : {
"type" : "index",
"targetPartitionSize" : 5000000,
"rowFlushBoundary" : 500000,
"numShards" : -1,
"indexSpec" : {
"bitmap" : {
"type" : "concise"
},
"dimensionCompression" : null,
"metricCompression" : null
}
}
},
"context" : null,
"groupId" : "index_druid_monitor_month_2016-03-17T10:38:34.775-04:00",
"dataSource" : "druid_monitor_month",
"interval" : "2016-03-01T00:00:00.000-05:00/2016-04-01T00:00:00.000-04:00"
}
2016-03-17 10:38:40,157 INFO i.d.i.w.e.ExecutorLifecycle [main] Attempting to lock file[/nas/druid/task/index_druid_monitor_month_2016-03-17T10:38:34.775-04:00/lock].
2016-03-17 10:38:40,158 INFO i.d.i.w.e.ExecutorLifecycle [main] Acquired lock file[/nas/druid/task/index_druid_monitor_month_2016-03-17T10:38:34.775-04:00/lock] in 1ms.
2016-03-17 10:38:40,162 INFO i.d.i.c.a.RemoteTaskActionClient [main] Performing action for task[index_druid_monitor_month_2016-03-17T10:38:34.775-04:00]: LockTryAcquireAction{interval=2016-03-01T00:00:00.000-05:00/2016-04-01T00:00:00.000-04:00}
2016-03-17 10:38:40,171 INFO i.d.i.c.a.RemoteTaskActionClient [main] Submitting action for task[index_druid_monitor_month_2016-03-17T10:38:34.775-04:00] to overlord[
http://10.200.6.60:8087/druid/indexer/v1/action]: LockTryAcquireAction{interval=2016-03-01T00:00:00.000-05:00/2016-04-01T00:00:00.000-04:00}
....
....
2016-03-17 10:46:31,337 WARN i.d.i.c.i.YeOldePlumberSchool [task-runner-0] Failed to spill index[0]
java.io.IOException: Unable to delete directory /nas/druid/task/index_druid_monitor_month_2016-03-17T10:38:34.775-04:00/work/druid_monitor_month_2016-03-01T00:00:00.000-05:00_2016-04-01T00:00:00.000-04:00_2016-03-17T10:38:34.779-04:00_0/druid_monitor_month_2016-03-01T00:00:00.000-05:00_2016-04-01T00:00:00.000-04:00_2016-03-17T10:38:34.779-04:00/spill0/v8-tmp.
at org.apache.commons.io.FileUtils.deleteDirectory(FileUtils.java:1206) ~[commons-io-2.0.1.jar:2.0.1]
at io.druid.segment.IndexMerger.makeIndexFiles(IndexMerger.java:969) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.segment.IndexMerger.merge(IndexMerger.java:358) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.segment.IndexMerger.persist(IndexMerger.java:197) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.segment.IndexMerger.persist(IndexMerger.java:162) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.segment.IndexMerger.persist(IndexMerger.java:139) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.indexing.common.index.YeOldePlumberSchool$1.spillIfSwappable(YeOldePlumberSchool.java:214) [druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.common.index.YeOldePlumberSchool$1.persist(YeOldePlumberSchool.java:144) [druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.common.task.IndexTask.generateSegment(IndexTask.java:396) [druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.common.task.IndexTask.run(IndexTask.java:213) [druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.overlord.ThreadPoolTaskRunner$ThreadPoolTaskRunnerCallable.call(ThreadPoolTaskRunner.java:285) [druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.overlord.ThreadPoolTaskRunner$ThreadPoolTaskRunnerCallable.call(ThreadPoolTaskRunner.java:265) [druid-indexing-service-0.8.3.jar:0.8.3]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_25]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_25]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_25]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_25]
2016-03-17 10:46:31,340 ERROR i.d.i.o.ThreadPoolTaskRunner [task-runner-0] Exception while running task[IndexTask{id=index_druid_monitor_month_2016-03-17T10:38:34.775-04:00, type=index, dataSource=druid_monitor_month}]
java.lang.RuntimeException: java.io.IOException: Unable to delete directory /nas/druid/task/index_druid_monitor_month_2016-03-17T10:38:34.775-04:00/work/druid_monitor_month_2016-03-01T00:00:00.000-05:00_2016-04-01T00:00:00.000-04:00_2016-03-17T10:38:34.779-04:00_0/druid_monitor_month_2016-03-01T00:00:00.000-05:00_2016-04-01T00:00:00.000-04:00_2016-03-17T10:38:34.779-04:00/spill0/v8-tmp.
at com.google.common.base.Throwables.propagate(Throwables.java:160) ~[guava-16.0.1.jar:?]
at io.druid.indexing.common.index.YeOldePlumberSchool$1.spillIfSwappable(YeOldePlumberSchool.java:230) ~[druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.common.index.YeOldePlumberSchool$1.persist(YeOldePlumberSchool.java:144) ~[druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.common.task.IndexTask.generateSegment(IndexTask.java:396) ~[druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.common.task.IndexTask.run(IndexTask.java:213) ~[druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.overlord.ThreadPoolTaskRunner$ThreadPoolTaskRunnerCallable.call(ThreadPoolTaskRunner.java:285) [druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.overlord.ThreadPoolTaskRunner$ThreadPoolTaskRunnerCallable.call(ThreadPoolTaskRunner.java:265) [druid-indexing-service-0.8.3.jar:0.8.3]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_25]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_25]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_25]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_25]
Caused by: java.io.IOException: Unable to delete directory /nas/druid/task/index_druid_monitor_month_2016-03-17T10:38:34.775-04:00/work/druid_monitor_month_2016-03-01T00:00:00.000-05:00_2016-04-01T00:00:00.000-04:00_2016-03-17T10:38:34.779-04:00_0/druid_monitor_month_2016-03-01T00:00:00.000-05:00_2016-04-01T00:00:00.000-04:00_2016-03-17T10:38:34.779-04:00/spill0/v8-tmp.
at org.apache.commons.io.FileUtils.deleteDirectory(FileUtils.java:1206) ~[commons-io-2.0.1.jar:2.0.1]
at io.druid.segment.IndexMerger.makeIndexFiles(IndexMerger.java:969) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.segment.IndexMerger.merge(IndexMerger.java:358) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.segment.IndexMerger.persist(IndexMerger.java:197) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.segment.IndexMerger.persist(IndexMerger.java:162) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.segment.IndexMerger.persist(IndexMerger.java:139) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.indexing.common.index.YeOldePlumberSchool$1.spillIfSwappable(YeOldePlumberSchool.java:214) ~[druid-indexing-service-0.8.3.jar:0.8.3]
... 9 more
2016-03-17 10:46:31,343 INFO i.d.i.w.e.ExecutorLifecycle [task-runner-0] Task completed with status: {
"id" : "index_druid_monitor_month_2016-03-17T10:38:34.775-04:00",
"status" : "FAILED",
"duration" : 471033
}
2016-03-17 10:46:31,361 INFO c.m.c.l.Lifecycle$AnnotationBasedHandler [main] Invoking stop method[public void io.druid.server.coordination.AbstractDataSegmentAnnouncer.stop()] on object[io.druid.server.coordination.BatchDataSegmentAnnouncer@59303963].
2016-03-17 10:46:31,362 INFO i.d.s.c.AbstractDataSegmentAnnouncer [main] Stopping class io.druid.server.coordination.BatchDataSegmentAnnouncer with config[io.druid.server.initialization.ZkPathsConfig@22e2266d]
2016-03-17 10:46:31,394 INFO i.d.c.a.Announcer [main] unannouncing [/druid/announcements/
10.200.6.63:8104]
....
....
2016-03-17 10:46:31,337 WARN i.d.i.c.i.YeOldePlumberSchool [task-runner-0] Failed to spill index[0]
java.io.IOException: Unable to delete directory /nas/druid/task/index_druid_monitor_month_2016-03-17T10:38:34.775-04:00/work/druid_monitor_month_2016-03-01T00:00:00.000-05:00_2016-04-01T00:00:00.000-04:00_2016-03-17T10:38:34.779-04:00_0/druid_monitor_month_2016-03-01T00:00:00.000-05:00_2016-04-01T00:00:00.000-04:00_2016-03-17T10:38:34.779-04:00/spill0/v8-tmp.
at org.apache.commons.io.FileUtils.deleteDirectory(FileUtils.java:1206) ~[commons-io-2.0.1.jar:2.0.1]
at io.druid.segment.IndexMerger.makeIndexFiles(IndexMerger.java:969) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.segment.IndexMerger.merge(IndexMerger.java:358) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.segment.IndexMerger.persist(IndexMerger.java:197) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.segment.IndexMerger.persist(IndexMerger.java:162) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.segment.IndexMerger.persist(IndexMerger.java:139) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.indexing.common.index.YeOldePlumberSchool$1.spillIfSwappable(YeOldePlumberSchool.java:214) [druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.common.index.YeOldePlumberSchool$1.persist(YeOldePlumberSchool.java:144) [druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.common.task.IndexTask.generateSegment(IndexTask.java:396) [druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.common.task.IndexTask.run(IndexTask.java:213) [druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.overlord.ThreadPoolTaskRunner$ThreadPoolTaskRunnerCallable.call(ThreadPoolTaskRunner.java:285) [druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.overlord.ThreadPoolTaskRunner$ThreadPoolTaskRunnerCallable.call(ThreadPoolTaskRunner.java:265) [druid-indexing-service-0.8.3.jar:0.8.3]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_25]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_25]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_25]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_25]
2016-03-17 10:46:31,340 ERROR i.d.i.o.ThreadPoolTaskRunner [task-runner-0] Exception while running task[IndexTask{id=index_druid_monitor_month_2016-03-17T10:38:34.775-04:00, type=index, dataSource=druid_monitor_month}]
java.lang.RuntimeException: java.io.IOException: Unable to delete directory /nas/druid/task/index_druid_monitor_month_2016-03-17T10:38:34.775-04:00/work/druid_monitor_month_2016-03-01T00:00:00.000-05:00_2016-04-01T00:00:00.000-04:00_2016-03-17T10:38:34.779-04:00_0/druid_monitor_month_2016-03-01T00:00:00.000-05:00_2016-04-01T00:00:00.000-04:00_2016-03-17T10:38:34.779-04:00/spill0/v8-tmp.
at com.google.common.base.Throwables.propagate(Throwables.java:160) ~[guava-16.0.1.jar:?]
at io.druid.indexing.common.index.YeOldePlumberSchool$1.spillIfSwappable(YeOldePlumberSchool.java:230) ~[druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.common.index.YeOldePlumberSchool$1.persist(YeOldePlumberSchool.java:144) ~[druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.common.task.IndexTask.generateSegment(IndexTask.java:396) ~[druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.common.task.IndexTask.run(IndexTask.java:213) ~[druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.overlord.ThreadPoolTaskRunner$ThreadPoolTaskRunnerCallable.call(ThreadPoolTaskRunner.java:285) [druid-indexing-service-0.8.3.jar:0.8.3]
at io.druid.indexing.overlord.ThreadPoolTaskRunner$ThreadPoolTaskRunnerCallable.call(ThreadPoolTaskRunner.java:265) [druid-indexing-service-0.8.3.jar:0.8.3]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_25]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_25]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_25]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_25]
Caused by: java.io.IOException: Unable to delete directory /nas/druid/task/index_druid_monitor_month_2016-03-17T10:38:34.775-04:00/work/druid_monitor_month_2016-03-01T00:00:00.000-05:00_2016-04-01T00:00:00.000-04:00_2016-03-17T10:38:34.779-04:00_0/druid_monitor_month_2016-03-01T00:00:00.000-05:00_2016-04-01T00:00:00.000-04:00_2016-03-17T10:38:34.779-04:00/spill0/v8-tmp.
at org.apache.commons.io.FileUtils.deleteDirectory(FileUtils.java:1206) ~[commons-io-2.0.1.jar:2.0.1]
at io.druid.segment.IndexMerger.makeIndexFiles(IndexMerger.java:969) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.segment.IndexMerger.merge(IndexMerger.java:358) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.segment.IndexMerger.persist(IndexMerger.java:197) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.segment.IndexMerger.persist(IndexMerger.java:162) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.segment.IndexMerger.persist(IndexMerger.java:139) ~[druid-processing-0.8.3.jar:0.8.3]
at io.druid.indexing.common.index.YeOldePlumberSchool$1.spillIfSwappable(YeOldePlumberSchool.java:214) ~[druid-indexing-service-0.8.3.jar:0.8.3]
... 9 more
2016-03-17 10:46:31,343 INFO i.d.i.w.e.ExecutorLifecycle [task-runner-0] Task completed with status: {
"id" : "index_druid_monitor_month_2016-03-17T10:38:34.775-04:00",
/index_druid_monitor_month_2016-03-17T10:38:34.775-04:00
at com.google.common.base.Preconditions.checkState(Preconditions.java:176) ~[guava-16.0.1.jar:?]
at org.apache.curator.x.discovery.details.ServiceCacheImpl.close(ServiceCacheImpl.java:104) ~[curator-x-discovery-2.9.1.jar:?]
at org.apache.curator.x.discovery.details.ServiceProviderImpl.close(ServiceProviderImpl.java:78) ~[curator-x-discovery-2.9.1.jar:?]
at io.druid.curator.discovery.ServerDiscoverySelector.stop(ServerDiscoverySelector.java:122) ~[druid-server-0.8.3.jar:0.8.3]
... 8 more
2016-03-17 10:46:31,480 INFO i.d.c.CuratorModule [Thread-55] Stopping Curator
2016-03-17 10:46:31,480 DEBUG o.a.c.f.i.CuratorFrameworkImpl [Thread-55] Closing
2016-03-17 10:46:31,480 ERROR c.m.c.l.Lifecycle$AnnotationBasedHandler [Thread-55] Exception when stopping method[public void io.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner.stop()] on object[io.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner@61514735]
java.lang.reflect.InvocationTargetException
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_25]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_25]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_25]
at java.lang.reflect.Method.invoke(Method.java:483) ~[?:1.8.0_25]
at com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler.stop(Lifecycle.java:337) [java-util-0.27.4.jar:?]
at com.metamx.common.lifecycle.Lifecycle.stop(Lifecycle.java:261) [java-util-0.27.4.jar:?]
at io.druid.cli.CliPeon$2.run(CliPeon.java:241) [druid-services-0.8.3.jar:0.8.3]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_25]
Caused by: java.lang.IllegalStateException: Expected state [STARTED] found [STOPPED]
at io.druid.common.config.Log4jShutdown.stop(Log4jShutdown.java:102) ~[druid-common-0.8.3.jar:0.8.3]
at io.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner.stop(Log4jShutterDownerModule.java:109) ~[druid-server-0.8.3.jar:0.8.3]
... 8 more
2016-03-17 10:46:31,481 INFO c.m.c.l.Lifecycle$AnnotationBasedHandler [Thread-55] Invoking stop method[public void com.metamx.emitter.core.LoggingEmitter.close() throws java.io.IOException] on object[com.metamx.emitter.core.LoggingEmitter@6bcc3f27].
2016-03-17 10:46:32,028 INFO i.d.i.w.WorkerTaskMonitor [WorkerTaskMonitor-0] Job's finished. Completed [index_druid_monitor_month_2016-03-17T10:38:34.775-04:00] with status [FAILED]