Re: [druid-user] Exception when indexing service job is done but no data.

[Nishant Bangarwa]

Hi, 

The errors you are seeing seems related to https://github.com/druid-io/druid/issues/1962

Since your task status is success, the data should be indexed properly and pushed to deep storage. 

If you are not able to query the data, there might be issues with segment loading on the historical nodes. 

Can you check that your historical nodes have enough free capacity and are not having any exceptions while trying to load the segments ? 

On Wed, Apr 20, 2016 at 11:40 PM Noppanit Charassinvichai <noppa...@gmail.com> wrote:

I'm trying to ingest our data again. I got this exception when the job is finished. 

2016-04-20T18:05:38,945 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.server.coordination.AbstractDataSegmentAnnouncer.stop()] on object[io.druid.server.coordination.BatchDataSegmentAnnouncer@6a0c76e2].
2016-04-20T18:05:38,945 INFO [main] io.druid.server.coordination.AbstractDataSegmentAnnouncer - Stopping class io.druid.server.coordination.BatchDataSegmentAnnouncer with config[io.druid.server.initialization.ZkPathsConfig@22e2266d]
2016-04-20T18:05:38,945 INFO [main] io.druid.curator.announcement.Announcer - unannouncing [/druid/announcements/10.91.45.226:8252]
2016-04-20T18:05:38,957 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.indexing.worker.executor.ExecutorLifecycle.stop() throws java.lang.Exception] on object[io.druid.indexing.worker.executor.ExecutorLifecycle@55e6418e].
2016-04-20T18:05:38,960 INFO [main] org.eclipse.jetty.server.ServerConnector - Stopped ServerConnector@4a28278{HTTP/1.1}{0.0.0.0:8252}
2016-04-20T18:05:38,961 INFO [main] org.eclipse.jetty.server.handler.ContextHandler - Stopped o.e.j.s.ServletContextHandler@7abd275b{/,null,UNAVAILABLE}
2016-04-20T18:05:38,966 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.indexing.overlord.ThreadPoolTaskRunner.stop()] on object[io.druid.indexing.overlord.ThreadPoolTaskRunner@37638d4f].
2016-04-20T18:05:38,967 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.curator.discovery.ServerDiscoverySelector.stop() throws java.io.IOException] on object[io.druid.curator.discovery.ServerDiscoverySelector@4ae5989f].
2016-04-20T18:05:38,969 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.curator.announcement.Announcer.stop()] on object[io.druid.curator.announcement.Announcer@441b08e7].
2016-04-20T18:05:38,970 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.curator.discovery.ServerDiscoverySelector.stop() throws java.io.IOException] on object[io.druid.curator.discovery.ServerDiscoverySelector@713e545d].
2016-04-20T18:05:38,970 INFO [main] io.druid.curator.CuratorModule - Stopping Curator
2016-04-20T18:05:38,973 INFO [main] org.apache.zookeeper.ZooKeeper - Session: 0x152a8adacdc085e closed
2016-04-20T18:05:38,973 INFO [main-EventThread] org.apache.zookeeper.ClientCnxn - EventThread shut down
2016-04-20T18:05:38,973 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void com.metamx.http.client.NettyHttpClient.stop()] on object[com.metamx.http.client.NettyHttpClient@2ce17337].
2016-04-20T18:05:38,982 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void com.metamx.metrics.MonitorScheduler.stop()] on object[com.metamx.metrics.MonitorScheduler@1c51fd3d].
2016-04-20T18:05:38,982 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void com.metamx.emitter.service.ServiceEmitter.close() throws java.io.IOException] on object[com.metamx.emitter.service.ServiceEmitter@6c49a53].
2016-04-20T18:05:38,982 INFO [main] LoggingEmitter - Close: started [false]
2016-04-20T18:05:38,982 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner.stop()] on object[io.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner@22591643].
2016-04-20T18:05:38,982 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void com.metamx.emitter.core.LoggingEmitter.close() throws java.io.IOException] on object[com.metamx.emitter.core.LoggingEmitter@b9bc34c].
2016-04-20T18:05:38,982 INFO [main] io.druid.cli.CliPeon - Finished peon task
2016-04-20T18:05:38,983 INFO [Thread-53] io.druid.cli.CliPeon - Running shutdown hook
2016-04-20T18:05:38,984 INFO [Thread-53] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.server.coordination.AbstractDataSegmentAnnouncer.stop()] on object[io.druid.server.coordination.BatchDataSegmentAnnouncer@6a0c76e2].
2016-04-20T18:05:38,984 INFO [Thread-53] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.indexing.worker.executor.ExecutorLifecycle.stop() throws java.lang.Exception] on object[io.druid.indexing.worker.executor.ExecutorLifecycle@55e6418e].
2016-04-20T18:05:38,985 ERROR [Thread-53] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Exception when stopping method[public void io.druid.indexing.worker.executor.ExecutorLifecycle.stop() throws java.lang.Exception] on object[io.druid.indexing.worker.executor.ExecutorLifecycle@55e6418e]
java.lang.reflect.InvocationTargetException
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.7.0_91]
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[?:1.7.0_91]
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.7.0_91]
 at java.lang.reflect.Method.invoke(Method.java:606) ~[?:1.7.0_91]
 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.7.0_91]
Caused by: java.nio.channels.ClosedChannelException
 at sun.nio.ch.FileLockImpl.release(FileLockImpl.java:58) ~[?:1.7.0_91]
 at io.druid.indexing.worker.executor.ExecutorLifecycle.stop(ExecutorLifecycle.java:220) ~[druid-indexing-service-0.8.3.jar:0.8.3]
 ... 8 more
2016-04-20T18:05:38,990 INFO [Thread-53] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.indexing.overlord.ThreadPoolTaskRunner.stop()] on object[io.druid.indexing.overlord.ThreadPoolTaskRunner@37638d4f].
2016-04-20T18:05:38,990 INFO [Thread-53] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.curator.discovery.ServerDiscoverySelector.stop() throws java.io.IOException] on object[io.druid.curator.discovery.ServerDiscoverySelector@4ae5989f].
2016-04-20T18:05:38,990 ERROR [Thread-53] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Exception when stopping method[public void io.druid.curator.discovery.ServerDiscoverySelector.stop() throws java.io.IOException] on object[io.druid.curator.discovery.ServerDiscoverySelector@4ae5989f]
java.lang.reflect.InvocationTargetException
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.7.0_91]
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[?:1.7.0_91]
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.7.0_91]
 at java.lang.reflect.Method.invoke(Method.java:606) ~[?:1.7.0_91]
 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.7.0_91]
Caused by: java.lang.IllegalStateException: Already closed or has not been started
 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-04-20T18:05:38,991 INFO [Thread-53] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.curator.announcement.Announcer.stop()] on object[io.druid.curator.announcement.Announcer@441b08e7].
2016-04-20T18:05:38,991 INFO [Thread-53] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.curator.discovery.ServerDiscoverySelector.stop() throws java.io.IOException] on object[io.druid.curator.discovery.ServerDiscoverySelector@713e545d].
2016-04-20T18:05:38,991 ERROR [Thread-53] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Exception when stopping method[public void io.druid.curator.discovery.ServerDiscoverySelector.stop() throws java.io.IOException] on object[io.druid.curator.discovery.ServerDiscoverySelector@713e545d]
java.lang.reflect.InvocationTargetException
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.7.0_91]
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[?:1.7.0_91]
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.7.0_91]
 at java.lang.reflect.Method.invoke(Method.java:606) ~[?:1.7.0_91]
 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.7.0_91]
Caused by: java.lang.IllegalStateException: Already closed or has not been started
 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-04-20T18:05:38,991 INFO [Thread-53] io.druid.curator.CuratorModule - Stopping Curator
2016-04-20T18:05:38,992 INFO [Thread-53] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void com.metamx.http.client.NettyHttpClient.stop()] on object[com.metamx.http.client.NettyHttpClient@2ce17337].
2016-04-20T18:05:38,992 INFO [Thread-53] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void com.metamx.metrics.MonitorScheduler.stop()] on object[com.metamx.metrics.MonitorScheduler@1c51fd3d].
2016-04-20T18:05:38,992 INFO [Thread-53] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void com.metamx.emitter.service.ServiceEmitter.close() throws java.io.IOException] on object[com.metamx.emitter.service.ServiceEmitter@6c49a53].
2016-04-20T18:05:38,992 INFO [Thread-53] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner.stop()] on object[io.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner@22591643].
2016-04-20T18:05:38,992 ERROR [Thread-53] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Exception when stopping method[public void io.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner.stop()] on object[io.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner@22591643]
java.lang.reflect.InvocationTargetException
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.7.0_91]
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[?:1.7.0_91]
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.7.0_91]
 at java.lang.reflect.Method.invoke(Method.java:606) ~[?:1.7.0_91]
 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.7.0_91]
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-04-20T18:05:38,993 INFO [Thread-53] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void com.metamx.emitter.core.LoggingEmitter.close() throws java.io.IOException] on object[com.metamx.emitter.core.LoggingEmitter@b9bc34c].
2016-04-20T18:05:39,343 INFO [forking-task-runner-4] io.druid.indexing.overlord.ForkingTaskRunner - Process exited with status[0] for task: index_firehose-web_2016-04-20T18:04:57.304Z
2016-04-20T18:05:39,343 INFO [forking-task-runner-4] io.druid.indexing.common.tasklogs.FileTaskLogs - Wrote task log to: log/index_firehose-web_2016-04-20T18:04:57.304Z.log
2016-04-20T18:05:39,344 INFO [forking-task-runner-4] io.druid.indexing.overlord.ForkingTaskRunner - Removing task directory: /tmp/persistent/tasks/index-firehose-web_2016-04-20T18:04:57.304Z
2016-04-20T18:05:39,348 INFO [WorkerTaskMonitor-4] io.druid.indexing.worker.WorkerTaskMonitor - Job's finished. Completed [index_firehose-web_2016-04-20T18:04:57.304Z] with status [SUCCESS]

It looks like the status is SUCCESS but I can't query the data back. 

Here's my schema for task

{
 "type": "index",
 "spec": {
 "dataSchema": {
 "dataSource": "firehose-web",
 "parser": {
 "type": "string",
 "parseSpec": {
 "format": "json",
 "timestampSpec": {
 "column": "_ts",
 "format": "iso"
 },
 "dimensionsSpec": {
 "dimensions": [],
 "dimensionExclusions": ["uID", "uIP", "pHp", "cTi", "lCi"],
 "spatialDimensions": []
 }
 }
 },
 "metricsSpec": [{
 "type": "count",
 "name": "count"
 }, {
 "type": "hyperUnique",
 "name": "unique",
 "fieldName": "uID"
 }, {
 "type": "longSum",
 "name": "audience",
 "fieldName": "uUq"
 }, {
 "type": "longSum",
 "name": "newAudience",
 "fieldName": "uNw"
 }, {
 "type": "doubleSum",
 "name": "valueSum",
 "fieldName": "_v"
 }, {
 "type": "doubleMin",
 "name": "valueMin",
 "fieldName": "_v"
 }, {
 "type": "doubleMax",
 "name": "valueMax",
 "fieldName": "_v"
 }],
 "granularitySpec": {
 "type": "uniform",
 "segmentGranularity": "DAY",
 "queryGranularity": "NONE",
 "intervals": ["2016-04-01/2016-05-01"]
 }
 },
 "ioConfig": {
 "type": "index",
 "firehose": {
 "type": "static-s3",
                "uris": ["s3://ci/indexing/logs/2016-04-13/part-m-00000"]
 }
 },
 "tuningConfig": {
 "type": "index",
 "targetPartitionSize": 0,
 "rowFlushBoundary": 0
 }
 }
}

--
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/b9f794b8-e0ca-42c7-ab82-6f072df970fb%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.