Exceptions after hadoop batch ingestion finished with success

Hi, List.

I’m trying to do batch ingestion in Druid. The first 4 tasks finished with:

2016-08-23T17:55:59,599 INFO [task-runner-0] io.druid.indexing.worker.executor.ExecutorLifecycle - Task completed with status: {
  "id" : "index_hadoop_contador2016_2016-08-23T17:55:44.634Z",
  "status" : "SUCCESS",
  "duration" : 8942
}

after that message appears at log file, some exceptions were thrown. I think its something related to closing files by map-reduce, right?


2016-08-23T17:55:59,668 ERROR [Thread-42] 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@7f977fba]
java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_91]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_91]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_91]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.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.8.0_91]
Caused by: java.nio.channels.ClosedChannelException
	at sun.nio.ch.FileLockImpl.release(FileLockImpl.java:58) ~[?:1.8.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-08-23T17:55:59,672 INFO [Thread-42] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.indexing.overlord.ThreadPoolTaskRunner.stop()] on object[io.druid.indexing.overlord.ThreadPoolTaskRunner@78d73b1b].
2016-08-23T17:55:59,672 INFO [Thread-42] 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@3b83459e].
2016-08-23T17:55:59,672 ERROR [Thread-42] 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@3b83459e]
java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_91]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_91]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_91]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.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.8.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-08-23T17:55:59,673 INFO [Thread-42] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.curator.announcement.Announcer.stop()] on object[io.druid.curator.announcement.Announcer@46e3559f].
2016-08-23T17:55:59,673 INFO [Thread-42] 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@2262d6d5].
2016-08-23T17:55:59,673 ERROR [Thread-42] 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@2262d6d5]
java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_91]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_91]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_91]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.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.8.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-08-23T17:55:59,673 INFO [Thread-42] io.druid.curator.CuratorModule - Stopping Curator
2016-08-23T17:55:59,673 INFO [Thread-42] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void com.metamx.http.client.NettyHttpClient.stop()] on object[com.metamx.http.client.NettyHttpClient@25f15f50].
2016-08-23T17:55:59,673 INFO [Thread-42] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void com.metamx.metrics.MonitorScheduler.stop()] on object[com.metamx.metrics.MonitorScheduler@58af5076].
2016-08-23T17:55:59,674 INFO [Thread-42] 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@d675f9f].
2016-08-23T17:55:59,674 INFO [Thread-42] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner.stop()] on object[io.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner@73aeef7d].
2016-08-23T17:55:59,674 ERROR [Thread-42] 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@73aeef7d]
java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_91]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_91]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_91]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.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.8.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

Does anyone know what is the problem? What do I missing?

Note: I'm running Druid 0.8.3 (local configuration, 1 broker, 1 historical, 1 overlord and 1 coordinator)


Hi Marcelo, I am not entirely sure what is happening here, but do you have your full overlord log ready?

Hi, Fangjin.

Sure. See attached

index_nextel.br.huawei.R13_2016-08-26T18:25:18.591Z.log (812 KB)

Hi Marcelo, these messages should mostly be harmless and a part of a task shutting down. The task log you posted seems to have completed successfully. Does the data show up?

Hi, Fangjin.

Yes, the data showed up. I saw the exceptions stack trace after the message ‘success’ and I think that something was not working properly. Maybe some misconfiguration.

Thanks for the answer.