ERROR [main] io.druid.cli.CliPeon - Error when starting up. Failing

Hi guys,

Can anybody shad some light on this?

Example 1:

ERROR [main] io.druid.cli.CliPeon - Error when starting up.  Failing.
java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_111]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_111]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_111]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_111]
	at com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler.start(Lifecycle.java:350) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
	at com.metamx.common.lifecycle.Lifecycle.start(Lifecycle.java:259) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
	at io.druid.guice.LifecycleModule$2.start(LifecycleModule.java:155) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
	at io.druid.cli.GuiceRunnable.initLifecycle(GuiceRunnable.java:101) [druid-services-0.9.2-selfcontained.jar:0.9.2]
	at io.druid.cli.CliPeon.run(CliPeon.java:274) [druid-services-0.9.2-selfcontained.jar:0.9.2]
	at io.druid.cli.Main.main(Main.java:106) [druid-services-0.9.2-selfcontained.jar:0.9.2]
Caused by: java.lang.NullPointerException
	at org.codehaus.jackson.impl.ByteSourceBootstrapper.detectEncoding(ByteSourceBootstrapper.java:179) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
	at org.codehaus.jackson.impl.ByteSourceBootstrapper.constructParser(ByteSourceBootstrapper.java:224) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
	at org.codehaus.jackson.JsonFactory._createJsonParser(JsonFactory.java:821) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
	at org.codehaus.jackson.JsonFactory.createJsonParser(JsonFactory.java:604) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
	at org.codehaus.jackson.map.ObjectMapper.readValue(ObjectMapper.java:1973) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
	at org.apache.curator.x.discovery.details.JsonInstanceSerializer.deserialize(JsonInstanceSerializer.java:50) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
	at org.apache.curator.x.discovery.details.ServiceCacheImpl.addInstance(ServiceCacheImpl.java:193) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
	at org.apache.curator.x.discovery.details.ServiceCacheImpl.start(ServiceCacheImpl.java:96) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
	at org.apache.curator.x.discovery.details.ServiceProviderImpl.start(ServiceProviderImpl.java:67) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
	at io.druid.curator.discovery.ServerDiscoverySelector.start(ServerDiscoverySelector.java:118) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
	... 10 more

Example 2:


ERROR [main] io.druid.cli.CliPeon - Error when starting up. Failing.
java.lang.reflect.InvocationTargetException
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_111]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_111]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_111]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_111]
at com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler.start(Lifecycle.java:350) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
at com.metamx.common.lifecycle.Lifecycle.start(Lifecycle.java:259) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
at io.druid.guice.LifecycleModule$2.start(LifecycleModule.java:155) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
at io.druid.cli.GuiceRunnable.initLifecycle(GuiceRunnable.java:101) [druid-services-0.9.2-selfcontained.jar:0.9.2]
at io.druid.cli.CliPeon.run(CliPeon.java:274) [druid-services-0.9.2-selfcontained.jar:0.9.2]
at io.druid.cli.Main.main(Main.java:106) [druid-services-0.9.2-selfcontained.jar:0.9.2]
Caused by: java.lang.NullPointerException
at org.codehaus.jackson.io.IOContext.constructTextBuffer(IOContext.java:122) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
at org.codehaus.jackson.impl.JsonParserBase.(JsonParserBase.java:302) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
at org.codehaus.jackson.impl.Utf8StreamParser.(Utf8StreamParser.java:109) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
at org.codehaus.jackson.impl.ByteSourceBootstrapper.constructParser(ByteSourceBootstrapper.java:235) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
at org.codehaus.jackson.JsonFactory._createJsonParser(JsonFactory.java:821) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
at org.codehaus.jackson.JsonFactory.createJsonParser(JsonFactory.java:604) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
at org.codehaus.jackson.map.ObjectMapper.readValue(ObjectMapper.java:1973) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
at org.apache.curator.x.discovery.details.JsonInstanceSerializer.deserialize(JsonInstanceSerializer.java:50) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
at org.apache.curator.x.discovery.details.ServiceCacheImpl.addInstance(ServiceCacheImpl.java:193) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
at org.apache.curator.x.discovery.details.ServiceCacheImpl.start(ServiceCacheImpl.java:96) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
at org.apache.curator.x.discovery.details.ServiceProviderImpl.start(ServiceProviderImpl.java:67) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
at io.druid.curator.discovery.ServerDiscoverySelector.start(ServerDiscoverySelector.java:118) ~[druid-services-0.9.2-selfcontained.jar:0.9.2]
… 10 more

What could be causing these tasks to fail? Some Druid options misconfiguration?

Note that related JSON data files can be ingested later on manually.

If there’s any additional info needed please just let me know.

Thanks in advance!

Regards,

Shinesun

Believe that any thought on this would just push things forward, so if you have any possible ideas of what could causing this in the back of your mind please drop here a line. Thanks!

Regards,

Shinesun

Maybe some tweaks in middle manager peon’s resources/properties could do the trick? Please let me know if you’ve experienced something similar to the issue above.

Can you check overlord logs once please - search with taskId there and you might get to know what is causing this.

Hi Arpan,

Thanks for the follow up.

Here’s what I’ve found there (no errors):

2017-05-02T15:35:15,707 INFO [qtp621486957-72] io.druid.indexing.overlord.MetadataTaskStorage - Inserting task index_stats_2017-05-02T15:35:15.707Z with status: TaskStatus{id=index_stats_2017-05-02T15:35:15.707Z, status=RUNNING, duration=-1}

2017-05-02T15:35:15,708 INFO [qtp621486957-72] io.druid.indexing.overlord.TaskLockbox - Adding task[index_stats_2017-05-02T15:35:15.707Z] to activeTasks

2017-05-02T15:35:15,709 INFO [TaskQueue-Manager] io.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_stats_2017-05-02T15:35:15.707Z]: LockTryAcquireAction{interval=2016-11-20T00:00:00.000Z/2017-04-16T00:00:00.000Z}

2017-05-02T15:35:22,250 INFO [TaskQueue-Manager] io.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_stats_2017-05-02T15:35:15.707Z]: LockTryAcquireAction{interval=2016-11-20T00:00:00.000Z/2017-04-16T00:00:00.000Z}

2017-05-02T15:35:22,250 INFO [TaskQueue-Manager] io.druid.indexing.overlord.TaskLockbox - Created new TaskLockPosse: TaskLockPosse{taskLock=TaskLock{groupId=index_stats_2017-05-02T15:35:15.707Z, dataSource=stats, interval=2016-11-20T00:00:00.000Z/2017-04-16T00:00:00.000Z, version=2017-05-02T15:35:22.250Z}, taskIds=}

2017-05-02T15:35:22,250 INFO [TaskQueue-Manager] io.druid.indexing.overlord.TaskLockbox - Added task[index_stats_2017-05-02T15:35:15.707Z] to TaskLock[index_stats_2017-05-02T15:35:15.707Z]

2017-05-02T15:35:22,250 INFO [TaskQueue-Manager] io.druid.indexing.overlord.MetadataTaskStorage - Adding lock on interval[2016-11-20T00:00:00.000Z/2017-04-16T00:00:00.000Z] version[2017-05-02T15:35:22.250Z] for task: index_stats_2017-05-02T15:35:15.707Z

2017-05-02T15:35:22,250 INFO [TaskQueue-Manager] io.druid.indexing.overlord.TaskQueue - Asking taskRunner to run: index_stats_2017-05-02T15:35:15.707Z

2017-05-02T15:35:22,252 INFO [forking-task-runner-28] io.druid.indexing.overlord.ForkingTaskRunner - Running command: java -cp /druid-conf/_common:/druid-conf/overlord:/druid/lib/druid-services-0.10.0-selfcontained.jar -server -Xmx9g -XX:MaxDirectMemorySize=10g -Ddruid.indexer.storage.type=metadata -Ddruid.host=localhost -Ddruid.processing.buffer.sizeBytes=256000000 -Ddruid.metadata.storage.connector.password=diurd -Duser.timezone=UTC -Ddruid.cache.readBufferSize=10485760 -Dfile.encoding.pkg=sun.io -Ddruid.storage.storageDirectory=/druid/localStorage -Ddruid.selectors.coordinator.serviceName=coordinator -Ddruid.cache.memcachedPrefix=d1 -Ddruid.extensions.directory=/druid/extensions -Ddruid.selectors.indexing.serviceName=overlord -Ddruid.indexer.queue.startDelay=PT10S -Ddruid.port=8090 -Ddruid.cache.expiration=2147483647 -Ddruid.cache.type=memcached -Ddruid.extensions.hadoopDependenciesDir=/druid/hadoop-dependencies -Ddruid.service=overlord -Ddruid.cache.hosts=localhost:11211 -Ddruid.metadata.storage.connector.user=druid -Ddruid.metadata.storage.type=mysql -Ddruid.cache.maxOperationQueueSize=1073741824 -Ddruid.metadata.storage.connector.connectURI=jdbc:mysql://localhost:3306/druid?characterEncoding=UTF-8 -Djava.io.tmpdir=/druid/tmp -Ddruid.extensions.loadList=[“mysql-metadata-storage”] -Ddruid.processing.numThreads=2 -Ddruid.zk.service.host=localhost -Ddruid.indexer.logs.directory=/druid/logs/tasks -Dfile.encoding=UTF-8 -Ddruid.storage.type=local -Ddruid.indexer.logs.type=file -Ddruid.metrics.emitter.dimension.dataSource=stats -Ddruid.metrics.emitter.dimension.taskId=index_stats_2017-05-02T15:35:15.707Z -Ddruid.host=localhost -Ddruid.port=8100 io.druid.cli.Main internal peon /druid/tmp/persistent/task/index_stats_2017-05-02T15:35:15.707Z/task.json /druid/tmp/persistent/task/index_stats_2017-05-02T15:35:15.707Z/fceddde8-e694-4189-93da-3a66d2d57523/status.json

2017-05-02T15:35:22,252 INFO [forking-task-runner-28] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_stats_2017-05-02T15:35:15.707Z] location changed to [TaskLocation{host=‘localhost’, port=8100}].

2017-05-02T15:35:22,252 INFO [forking-task-runner-28] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_stats_2017-05-02T15:35:15.707Z] status changed to [RUNNING].

2017-05-02T15:35:22,252 INFO [forking-task-runner-28] io.druid.indexing.overlord.ForkingTaskRunner - Logging task index_stats_2017-05-02T15:35:15.707Z output to: /druid/tmp/persistent/task/index_stats_2017-05-02T15:35:15.707Z/log

2017-05-02T15:35:25,678 INFO [qtp621486957-41] io.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_stats_2017-05-02T15:35:15.707Z]: LockTryAcquireAction{interval=2016-11-20T00:00:00.000Z/2017-04-16T00:00:00.000Z}

2017-05-02T15:35:25,679 INFO [qtp621486957-41] io.druid.indexing.overlord.TaskLockbox - Task[index_stats_2017-05-02T15:35:15.707Z] already present in TaskLock[index_stats_2017-05-02T15:35:15.707Z]

2017-05-02T15:35:26,753 INFO [forking-task-runner-28-[index_stats_2017-05-02T15:35:15.707Z]] io.druid.indexing.overlord.ForkingTaskRunner - Process exited with status[0] for task: index_stats_2017-05-02T15:35:15.707Z

2017-05-02T15:35:26,755 INFO [forking-task-runner-28] io.druid.indexing.common.tasklogs.FileTaskLogs - Wrote task log to: /druid/logs/tasks/index_stats_2017-05-02T15:35:15.707Z.log

2017-05-02T15:35:26,755 INFO [forking-task-runner-28] io.druid.indexing.overlord.TaskRunnerUtils - Task [index_stats_2017-05-02T15:35:15.707Z] status changed to [FAILED].

2017-05-02T15:35:26,770 INFO [forking-task-runner-28] io.druid.indexing.overlord.ForkingTaskRunner - Removing task directory: /druid/tmp/persistent/task/index_stats_2017-05-02T15:35:15.707Z

2017-05-02T15:35:26,771 INFO [forking-task-runner-28] io.druid.indexing.overlord.TaskQueue - Received FAILED status for task: index_stats_2017-05-02T15:35:15.707Z

2017-05-02T15:35:26,771 INFO [forking-task-runner-28] io.druid.indexing.overlord.ForkingTaskRunner - Ignoring request to cancel unknown task: index_stats_2017-05-02T15:35:15.707Z

2017-05-02T15:35:26,771 INFO [forking-task-runner-28] io.druid.indexing.overlord.TaskLockbox - Removing task[index_stats_2017-05-02T15:35:15.707Z] from activeTasks

2017-05-02T15:35:26,771 INFO [forking-task-runner-28] io.druid.indexing.overlord.TaskLockbox - Removing task[index_stats_2017-05-02T15:35:15.707Z] from TaskLock[index_stats_2017-05-02T15:35:15.707Z]

2017-05-02T15:35:26,771 INFO [forking-task-runner-28] io.druid.indexing.overlord.TaskLockbox - TaskLock is now empty: TaskLock{groupId=index_stats_2017-05-02T15:35:15.707Z, dataSource=stats, interval=2016-11-20T00:00:00.000Z/2017-04-16T00:00:00.000Z, version=2017-05-02T15:35:22.250Z}

2017-05-02T15:35:26,772 INFO [forking-task-runner-28] io.druid.indexing.overlord.MetadataTaskStorage - Deleting TaskLock with id[29708]: TaskLock{groupId=index_stats_2017-05-02T15:35:15.707Z, dataSource=stats, interval=2016-11-20T00:00:00.000Z/2017-04-16T00:00:00.000Z, version=2017-05-02T15:35:22.250Z}

2017-05-02T15:35:26,773 INFO [forking-task-runner-28] io.druid.indexing.overlord.MetadataTaskStorage - Updating task index_stats_2017-05-02T15:35:15.707Z to status: TaskStatus{id=index_stats_2017-05-02T15:35:15.707Z, status=FAILED, duration=90}

2017-05-02T15:35:26,774 INFO [forking-task-runner-28] io.druid.indexing.overlord.TaskQueue - Task done: IndexTask{id=index_stats_2017-05-02T15:35:15.707Z, type=index, dataSource=stats}

2017-05-02T15:35:26,774 INFO [forking-task-runner-28] io.druid.indexing.overlord.TaskQueue - Task FAILED: IndexTask{id=index_stats_2017-05-02T15:35:15.707Z, type=index, dataSource=stats} (90 run duration)

Errors from the first post in particular were from /druid/logs/tasks/index_stats_2017-05-02T15:35:15.707Z.log.

What I’ve just noticed are:

  1. Duplicated [TaskQueue-Manager] io.druid.indexing.common.actions.LocalTaskActionClient - Performing action for task[index_stats_2017-05-02T15:35:15.707Z]: LockTryAcquireAction{interval=2016-11-20T00:00:00.000Z/2017-04-16T00:00:00.000Z}
  2. Odd intervals that spans across couple of months.

Is it possible that there are other active tasks running with matching intervals thus throwing errors?

Also, might be that middle manager and peons need to be re-configured slightly (workers capacity etc.)?

/druid-conf/middleManager/runtime.properties

druid.host=localhost

druid.port=8091

druid.service=middlemanager

druid.indexer.logs.type=file

druid.indexer.logs.directory=/druid/logs/tasks

druid.processing.buffer.sizeBytes=256000000

druid.processing.numThreads=2

druid.indexer.runner.javaOptsArray=["-server", “-Xmx2g”, “-XX:+UseG1GC”, “-XX:MaxGCPauseMillis=100”, “-XX:+PrintGCDetails”, “-XX:+PrintGCTimeStamps”]

druid.indexer.task.baseDir=/druid

druid.indexer.task.baseTaskDir=/druid/persistent/tasks/

druid.indexer.fork.property.druid.monitoring.monitors=[“com.metamx.metrics.JvmMonitor”]

druid.indexer.fork.property.druid.segmentCache.locations=[{“path”: “/druid/indexCache”, “maxSize”: 0}]

druid.indexer.fork.property.druid.server.http.numThreads=10

druid.indexer.fork.property.druid.storage.storageDirectory=/druid/localStorage

druid.indexer.fork.property.druid.storage.type=local

druid.worker.capacity=3

druid.worker.ip=localhost

druid.worker.version=0

Regards,

Shinesun

I am not entirely sure but looks like there is some jar mismatch between curator and jackson libraries, most likely curator is trying to use wrong version of some jackson jar. Also looks like you are using shaded druid-services jar so make sure you have the correct version of classes in the shaded jar and there are not conflicting jars on the classpath.

Hi Parag,

Druid’s being actually built from source, but rather according to this Dockerfile than Build From Source doc article.

What can be done in regarding to your assumption? Is there maybe recommended way of installing Druid?

Regards,

Shinesun

You can download the latest stable release from http://druid.io/downloads.html and then check the quickstart guide to see how the Druid processes are started - http://druid.io/docs/0.10.0/tutorials/quickstart.html and see if it makes any difference