Not able to ingest data using batch ingestion

Hello ,

We are getting the following exception while loading the data through batch ingestion in druid. We have used deep storage as HDFS. Also we using the latest stable version of druid i.e. 0.9.1

Here are the exception logs:

016-07-05T23:08:43,653 INFO [task-runner-0-priority-0] io.druid.indexer.JobHelper - Deleting path[var/druid/hadoop-tmp/localytics/2016-07-05T230730.231Z/be1499775f6a427499a49f2c5065b7b1]

2016-07-05T23:08:43,673 ERROR [task-runner-0-priority-0] io.druid.indexing.overlord.ThreadPoolTaskRunner - Exception while running task[HadoopIndexTask{id=index_hadoop_localytics_2016-07-05T23:07:30.152Z, type=index_hadoop, dataSource=localytics}]

java.lang.RuntimeException: java.lang.reflect.InvocationTargetException

at com.google.common.base.Throwables.propagate(Throwables.java:160) ~[guava-16.0.1.jar:?]

at io.druid.indexing.common.task.HadoopTask.invokeForeignLoader(HadoopTask.java:204) ~[druid-indexing-service-0.9.1.1.jar:0.9.1.1]

at io.druid.indexing.common.task.HadoopIndexTask.run(HadoopIndexTask.java:208) ~[druid-indexing-service-0.9.1.1.jar:0.9.1.1]

at io.druid.indexing.overlord.ThreadPoolTaskRunner$ThreadPoolTaskRunnerCallable.call(ThreadPoolTaskRunner.java:436) [druid-indexing-service-0.9.1.1.jar:0.9.1.1]

at io.druid.indexing.overlord.ThreadPoolTaskRunner$ThreadPoolTaskRunnerCallable.call(ThreadPoolTaskRunner.java:408) [druid-indexing-service-0.9.1.1.jar:0.9.1.1]

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

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_91]

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

at java.lang.Thread.run(Thread.java:745) [?:1.8.0_91]

Caused by: 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 io.druid.indexing.common.task.HadoopTask.invokeForeignLoader(HadoopTask.java:201) ~[druid-indexing-service-0.9.1.1.jar:0.9.1.1]

… 7 more

Caused by: com.metamx.common.ISE: Job[class io.druid.indexer.IndexGeneratorJob] failed!

at io.druid.indexer.JobHelper.runJobs(JobHelper.java:343) ~[druid-indexing-hadoop-0.9.1.1.jar:0.9.1.1]

at io.druid.indexer.HadoopDruidIndexerJob.run(HadoopDruidIndexerJob.java:94) ~[druid-indexing-hadoop-0.9.1.1.jar:0.9.1.1]

at io.druid.indexing.common.task.HadoopIndexTask$HadoopIndexGeneratorInnerProcessing.runTask(HadoopIndexTask.java:261) ~[druid-indexing-service-0.9.1.1.jar:0.9.1.1]

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 io.druid.indexing.common.task.HadoopTask.invokeForeignLoader(HadoopTask.java:201) ~[druid-indexing-service-0.9.1.1.jar:0.9.1.1]

… 7 more

2016-07-05T23:08:43,681 INFO [task-runner-0-priority-0] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_hadoop_localytics_2016-07-05T23:07:30.152Z] status changed to [FAILED].

2016-07-05T23:08:43,684 INFO [task-runner-0-priority-0] io.druid.indexing.worker.executor.ExecutorLifecycle - Task completed with status: {

“id” : “index_hadoop_localytics_2016-07-05T23:07:30.152Z”,

“status” : “FAILED”,

“duration” : 51587

}

2016-07-05T23:08:43,691 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@4a62062a].

2016-07-05T23:08:43,691 INFO [main] io.druid.server.coordination.AbstractDataSegmentAnnouncer - Stopping class io.druid.server.coordination.BatchDataSegmentAnnouncer with config[io.druid.server.initialization.ZkPathsConfig@22e2266d]

2016-07-05T23:08:43,691 INFO [main] io.druid.curator.announcement.Announcer - unannouncing [/druid/announcements/druid-middlemanager-002.in.inshorts.com:8100]

2016-07-05T23:08:43,701 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.server.listener.announcer.ListenerResourceAnnouncer.stop()] on object[io.druid.query.lookup.LookupResourceListenerAnnouncer@6e9a0bea].

2016-07-05T23:08:43,701 INFO [main] io.druid.curator.announcement.Announcer - unannouncing [/druid/listeners/lookups/__default/druid-middlemanager-002.in.inshorts.com:8100]

2016-07-05T23:08:43,703 INFO [main] io.druid.server.listener.announcer.ListenerResourceAnnouncer - Unannouncing start time on [/druid/listeners/lookups/__default/druid-middlemanager-002.in.inshorts.com:8100]

2016-07-05T23:08:43,703 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.query.lookup.LookupReferencesManager.stop()] on object[io.druid.query.lookup.LookupReferencesManager@3e856100].

2016-07-05T23:08:43,703 INFO [main] io.druid.query.lookup.LookupReferencesManager - Stopping lookup factory references manager

2016-07-05T23:08:43,705 INFO [main] org.eclipse.jetty.server.ServerConnector - Stopped ServerConnector@26c77f54{HTTP/1.1}{0.0.0.0:8100}

2016-07-05T23:08:43,706 INFO [main] org.eclipse.jetty.server.handler.ContextHandler - Stopped o.e.j.s.ServletContextHandler@1a14fdf0{/,null,UNAVAILABLE}

2016-07-05T23:08:43,708 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@2e62ead7].

2016-07-05T23:08:43,708 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@687389a6].

2016-07-05T23:08:43,709 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@4346808].

2016-07-05T23:08:43,712 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@235b4cb8].

2016-07-05T23:08:43,712 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@1e79d43].

2016-07-05T23:08:43,712 INFO [main] io.druid.curator.CuratorModule - Stopping Curator

2016-07-05T23:08:43,712 INFO [Curator-Framework-0] org.apache.curator.framework.imps.CuratorFrameworkImpl - backgroundOperationsLoop exiting

2016-07-05T23:08:43,721 INFO [main] org.apache.zookeeper.ZooKeeper - Session: 0x155a87b88be005b closed

2016-07-05T23:08:43,721 INFO [main-EventThread] org.apache.zookeeper.ClientCnxn - EventThread shut down for session: 0x155a87b88be005b

2016-07-05T23:08:43,721 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@6d6d480c].

2016-07-05T23:08:43,728 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void com.metamx.metrics.MonitorScheduler.stop()] on object[com.metamx.metrics.MonitorScheduler@fa5f81c].

2016-07-05T23:08:43,729 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@73a0f2b].

2016-07-05T23:08:43,729 INFO [main] com.metamx.emitter.core.LoggingEmitter - Close: started [false]

2016-07-05T23:08:43,729 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@26ca61bf].

2016-07-05 23:08:43,750 Thread-2 ERROR Unable to register shutdown hook because JVM is shutting down. java.lang.IllegalStateException: Not started

at io.druid.common.config.Log4jShutdown.addShutdownCallback(Log4jShutdown.java:45)

at org.apache.logging.log4j.core.impl.Log4jContextFactory.addShutdownCallback(Log4jContextFactory.java:273)

at org.apache.logging.log4j.core.LoggerContext.setUpShutdownHook(LoggerContext.java:256)

at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:216)

at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:145)

at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:41)

at org.apache.logging.log4j.LogManager.getContext(LogManager.java:182)

at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getContext(AbstractLoggerAdapter.java:103)

at org.apache.logging.slf4j.Log4jLoggerFactory.getContext(Log4jLoggerFactory.java:43)

at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:42)

at org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:29)

at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:284)

at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:155)

at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:132)

at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:685)

at org.apache.hadoop.hdfs.LeaseRenewer.(LeaseRenewer.java:72)

at org.apache.hadoop.hdfs.DFSClient.getLeaseRenewer(DFSClient.java:699)

at org.apache.hadoop.hdfs.DFSClient.close(DFSClient.java:859)

at org.apache.hadoop.hdfs.DistributedFileSystem.close(DistributedFileSystem.java:853)

at org.apache.hadoop.fs.FileSystem$Cache.closeAll(FileSystem.java:2407)

at org.apache.hadoop.fs.FileSystem$Cache$ClientFinalizer.run(FileSystem.java:2424)

at org.apache.hadoop.util.ShutdownHookManager$1.run(ShutdownHookManager.java:54)

Attached is the full stack trace as well as properties and ingestion spec. Please help out what we are doing wrong on our side.

Let us know if you need anything more.

Thanks,

Saurabh

log.txt (7.15 MB)

wikiticker-index-create.json (1.61 KB)

common_config-2 (3.96 KB)

Hi Saurabh,

Can you check your java temp directory and see if there are any problems with that?

From the log, the root exception (usually shown prior to that “InvocationTargetException”) is:

2016-07-05T23:08:42,607 INFO [Thread-8918] org.apache.hadoop.mapred.LocalJobRunner - reduce task executor complete.

2016-07-05T23:08:42,634 WARN [Thread-8918] org.apache.hadoop.mapred.LocalJobRunner - job_local715297239_0002

java.lang.Exception: java.io.IOException: No such file or directory

at org.apache.hadoop.mapred.LocalJobRunner$Job.runTasks(LocalJobRunner.java:462) ~[hadoop-mapreduce-client-common-2.3.0.jar:?]

at org.apache.hadoop.mapred.LocalJobRunner$Job.run(LocalJobRunner.java:529) [hadoop-mapreduce-client-common-2.3.0.jar:?]

Caused by: java.io.IOException: No such file or directory

at java.io.UnixFileSystem.createFileExclusively(Native Method) ~[?:1.8.0_91]

at java.io.File.createTempFile(File.java:2024) ~[?:1.8.0_91]

at java.io.File.createTempFile(File.java:2070) ~[?:1.8.0_91]

at io.druid.indexer.IndexGeneratorJob$IndexGeneratorReducer.reduce(IndexGeneratorJob.java:558) ~[druid-indexing-hadoop-0.9.1.1.jar:0.9.1.1]

at io.druid.indexer.IndexGeneratorJob$IndexGeneratorReducer.reduce(IndexGeneratorJob.java:469) ~[druid-indexing-hadoop-0.9.1.1.jar:0.9.1.1]

at org.apache.hadoop.mapreduce.Reducer.run(Reducer.java:171) ~[hadoop-mapreduce-client-core-2.3.0.jar:?]

at org.apache.hadoop.mapred.ReduceTask.runNewReducer(ReduceTask.java:627) ~[hadoop-mapreduce-client-core-2.3.0.jar:?]

at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:389) ~[hadoop-mapreduce-client-core-2.3.0.jar:?]

at org.apache.hadoop.mapred.LocalJobRunner$Job$ReduceTaskRunnable.run(LocalJobRunner.java:319) ~[hadoop-mapreduce-client-common-2.3.0.jar:?]

at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_91]

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

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[?:1.8.0_91]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[?:1.8.0_91]

at java.lang.Thread.run(Thread.java:745) ~[?:1.8.0_91]

line 558 in IndexGeneratorJob is:

File baseFlushFile = File.createTempFile("base", "flush");



Hi,Saurabh
I came with the same problem, have you solved it? And what the method is? Looking forward to your reply.

Thanks

在 2016年7月6日星期三 UTC+8上午7:27:11,SAURABH JAIN写道:

Hi Shuchao,

Checking the settings of your java.io.tmpdir to make sure it has sufficient space and you have correct permissions to that dir.