Exceptions after hadoop batch ingestion finished with success

[Marcelo Oikawa]

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)

[Fangjin Yang]

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

[Marcelo Oikawa]

Hi, Fangjin.

Sure. See attached

--
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+unsubscribe@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/fd0b0e29-f19b-4833-8b3e-086ac590e4c0%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Fangjin Yang]

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?

[Marcelo Oikawa]

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.

To view this discussion on the web visit https://groups.google.com/d/msgid/druid-user/9aaea1d1-73a2-4e16-b67b-d20677060b76%40googlegroups.com.