Too many ReadTimeoutException when peon is submitting SegmentInsertAction task to overlord

When indexing task is in progress and after segment is uploaded to S3 , ReadTimeoutException occurs too much while submitting SegmentInsertAction task to overlord.
Once ReadTimeoutException occurs, next exception takes place exactly after 15 minutes.

Oddly after about dozen times of exception, task marks ‘SUCCESS’ to overlord and indexing job is done.

Log from the peon is below and this logs iterate about dozen times:

(I deleted some private info)

2016-01-15T08:02:38,603 INFO [task-runner-0] io.druid.storage.s3.S3DataSegmentPusher - Deleting descriptor file[/tmp/druid5137238559226221499descriptor.json]

2016-01-15T08:02:38,604 INFO [task-runner-0] io.druid.indexing.common.index.YeOldePlumberSchool - Uploaded segment[data_troubleshoot_2016-01-05T14:00:00.000Z_2016-01-05T15:00:00.000Z_2016-01-15T07:25:16.851Z]

2016-01-15T08:02:38,604 INFO [task-runner-0] io.druid.indexing.common.index.YeOldePlumberSchool - Deleting Index File[/tmp/persistent/task/index_data_troubleshoot_2016-01-15T07:25:16.515Z/work/data_troubleshoot_2016-01-05T14:00:00.000Z_2016-01-05T15:00:00.000Z_2016-01-15T07:25:16.851Z_0/merged]

2016-01-15T08:02:38,604 INFO [task-runner-0] io.druid.indexing.common.task.IndexTask - Task[index_data_troubleshoot_2016-01-15T07:25:16.515Z] interval[2016-01-05T14:00:00.000Z/2016-01-05T15:00:00.000Z] partition[0] took in 9,609,880 rows (3,202,879 processed, 0 unparseable, 6,407,001 thrown away) and output 2,207,250 rows

2016-01-15T08:02:38,613 INFO [task-runner-0] io.druid.indexing.common.actions.RemoteTaskActionClient - Performing action for task[index_data_troubleshoot_2016-01-15T07:25:16.515Z]: SegmentInsertAction{segments=[DataSegment{size=118845238, shardSpec=NoneShardSpec, metrics=[…], dimensions=[…], version=‘2016-01-15T07:25:16.851Z’, loadSpec={type=s3_zip, bucket=, key=data_troubleshoot/2016-01-05T14:00:00.000Z_2016-01-05T15:00:00.000Z/2016-01-15T07:25:16.851Z/0/index.zip}, interval=2016-01-05T14:00:00.000Z/2016-01-05T15:00:00.000Z, dataSource=’…’, binaryVersion=‘9’}]}

2016-01-15T08:02:38,619 INFO [task-runner-0] io.druid.indexing.common.actions.RemoteTaskActionClient - Submitting action for task[index_data_troubleshoot_2016-01-15T07:25:16.515Z] to overlord[http://:/druid/indexer/v1/action]: SegmentInsertAction{segments=[DataSegment{size=118845238, shardSpec=NoneShardSpec, metrics=[…], dimensions=[…], version=‘2016-01-15T07:25:16.851Z’, loadSpec={type=s3_zip, bucket=, key=data_troubleshoot/2016-01-05T14:00:00.000Z_2016-01-05T15:00:00.000Z/2016-01-15T07:25:16.851Z/0/index.zip}, interval=2016-01-05T14:00:00.000Z/2016-01-05T15:00:00.000Z, dataSource=’…’, binaryVersion=‘9’}]}

2016-01-15T08:02:38,620 DEBUG [task-runner-0] com.metamx.http.client.NettyHttpClient - [POST http://:/druid/indexer/v1/action] starting

2016-01-15T08:17:38,670 DEBUG [HttpClient-Netty-Worker-2] com.metamx.http.client.NettyHttpClient - [POST http://:/druid/indexer/v1/action] Caught exception

2016-01-15T08:17:38,678 WARN [task-runner-0] io.druid.indexing.common.actions.RemoteTaskActionClient - Exception submitting action for task[index_data_troubleshoot_2016-01-15T07:25:16.515Z]

org.jboss.netty.handler.timeout.ReadTimeoutException

at org.jboss.netty.handler.timeout.ReadTimeoutHandler.(ReadTimeoutHandler.java:84) ~[druid-services-0.8.0-selfcontained.jar:0.8.0]

at com.metamx.http.client.NettyHttpClient.go(NettyHttpClient.java:173) ~[druid-services-0.8.0-selfcontained.jar:0.8.0]

at io.druid.indexing.common.actions.RemoteTaskActionClient.submit(RemoteTaskActionClient.java:99) ~[druid-services-0.8.0-selfcontained.jar:0.8.0]

at io.druid.indexing.common.task.AbstractFixedIntervalTask.isReady(AbstractFixedIntervalTask.java:67) ~[druid-services-0.8.0-selfcontained.jar:0.8.0]

at io.druid.indexing.worker.executor.ExecutorLifecycle.start(ExecutorLifecycle.java:120) ~[druid-services-0.8.0-selfcontained.jar:0.8.0]

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_66]

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_66]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_66]

at java.lang.reflect.Method.invoke(Method.java:497) ~[?:1.8.0_66]

at com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler.start(Lifecycle.java:331) ~[druid-services-0.8.0-selfcontained.jar:0.8.0]

at com.metamx.common.lifecycle.Lifecycle.addMaybeStartHandler(Lifecycle.java:236) ~[druid-services-0.8.0-selfcontained.jar:0.8.0]

at com.metamx.common.lifecycle.Lifecycle.addMaybeStartManagedInstance(Lifecycle.java:182) ~[druid-services-0.8.0-selfcontained.jar:0.8.0]

at io.druid.guice.LifecycleScope$1.get(LifecycleScope.java:57) ~[druid-services-0.8.0-selfcontained.jar:0.8.0]

at com.google.inject.internal.InternalFactoryToProviderAdapter.get(InternalFactoryToProviderAdapter.java:41) ~[druid-services-0.8.0-selfcontained.jar:0.8.0]

at com.google.inject.internal.InjectorImpl$3$1.call(InjectorImpl.java:1005) ~[druid-services-0.8.0-selfcontained.jar:0.8.0]

at com.google.inject.internal.InjectorImpl.callInContext(InjectorImpl.java:1051) ~[druid-services-0.8.0-selfcontained.jar:0.8.0]

at com.google.inject.internal.InjectorImpl$3.get(InjectorImpl.java:1001) ~[druid-services-0.8.0-selfcontained.jar:0.8.0]

at com.google.inject.internal.InjectorImpl.getInstance(InjectorImpl.java:1040) ~[druid-services-0.8.0-selfcontained.jar:0.8.0]

at io.druid.cli.CliPeon.run(CliPeon.java:212) ~[druid-services-0.8.0-selfcontained.jar:0.8.0]

at io.druid.cli.Main.main(Main.java:91) ~[druid-services-0.8.0-selfcontained.jar:0.8.0]

2016-01-15T08:17:38,693 INFO [task-runner-0] io.druid.indexing.common.actions.RemoteTaskActionClient - Will try again in [PT60.163S].

2016-01-15T08:18:38,858 INFO [task-runner-0] io.druid.indexing.common.actions.RemoteTaskActionClient - Submitting action for task[index_data_troubleshoot_2016-01-15T07:25:16.515Z] to overlord[http://:/druid/indexer/v1/action]: SegmentInsertAction{segments=[DataSegment{size=118845238, shardSpec=NoneShardSpec, metrics=[…], dimensions=[…], version=‘2016-01-15T07:25:16.851Z’, loadSpec={type=s3_zip, bucket=, key=data_troubleshoot/2016-01-05T14:00:00.000Z_2016-01-05T15:00:00.000Z/2016-01-15T07:25:16.851Z/0/index.zip}, interval=2016-01-05T14:00:00.000Z/2016-01-05T15:00:00.000Z, dataSource=‘data_troubleshoot’, binaryVersion=‘9’}]}

2016-01-15T08:18:38,858 DEBUG [task-runner-0] com.metamx.http.client.NettyHttpClient - [POST http://:/druid/indexer/v1/action] starting

Hi Trevor, can you provide some more details about your setup? Specifically, what kind of env are the middle managers and overlords running in?

Ah, I forgot providing some details.

We are using Druid v.0.8.0 and specification and properties of each druid nodes are below:

(I omitted private info such as ip and passwords, and everything else I didn’t manually set is considered to be set default values.

[Druid Common Properties]

druid.extensions.coordinates=[“io.druid.extensions:druid-s3-extensions”, “io.druid.extensions:mysql-metadata-storage”]

druid.zk.service.sessionTimeoutMs=120000

druid.request.logging.type=file

druid.monitoring.emissionPeriod=PT1m

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

druid.emitter=noop

druid.metadata.storage.type=mysql

druid.storage.type=s3

[Overlord] - 4 cores, 14gb memory

druid.indexer.logs.type=s3

druid.indexer.runner.type=remote

druid.indexer.storage.type=metadata

druid.indexer.queue.startDelay=PT5M

druid.indexer.runner.maxZnodeBytes=2524288

[Middlemanager] - 16 cores, 112gb memory
druid.indexer.logs.type=file

druid.indexer.logs.directory=/tmp/druid/taskLog

druid.indexer.runner.allowedPrefixes=[“com.metamx”, “druid”, “io.druid”, “user.timezone”,“file.encoding”]

druid.indexer.runner.compressZnodes=true

druid.indexer.runner.javaCommand=java

druid.indexer.runner.javaOpts=-server -Xloggc:/tmp/gc/log -Xmx3g -XX:+UseG1GC -XX:MaxGCPauseMillis=100

druid.indexer.runner.maxZnodeBytes=2524288

druid.worker.capacity=12

druid.indexer.fork.property.druid.processing.numThreads=2

druid.indexer.fork.property.druid.processing.buffer.sizeBytes=524288000

Are you running overlords and middleManagers in AWS? Are they under the same availability zone?

Also, what version of Druid is this?

All druid version is 0.8.0.

I am running one overlord on AWS and middlemanagers on on Microsoft Azure.
However same problem happened when all overlords and middlemanagers ran on AWS but didn’t check whether they are in same availability zone.

Is there any issue when nodes are in same zone?

The error is a communication timeout and I suspect it is because the overlord and middle managers are in different services. Is there any way you can put them both on azure or AWS and see how things are?

My apologies. Currently both an overlord and middlemanagers are running on Azure.
Is there any chance that you have some other suspect?

Hey Trevor,

Can you connect to that ip:port directly from the middlemanager node? Something like: curl http://ip:port/status

If that times out too, that might be a security/firewall issue. That’s probably the most likely cause. I’m not too familiar with Azure, but in AWS that would usually be due to security groups not allowing traffic between those machines on that port.

If that doesn’t time out too, there might be some issue on the overlord preventing it from serving the request. In that case, try checking out a thread dump of the overlord while one of the requests is pending, and seeing if any of them are stuck. You can paste the thread dump here too.

Attached is a thread dump of peon process that throws ReadTimeoutException while performing SegmentInsertAction to overlord.
I took 3 dumps every 30 seconds.

I am still struggling to figure out what was wrong, but couldn’t get the point so far.

thread_analysis (547 KB)

Hey Trevor, sorry, I meant a thread dump of the overlord (it should be handling that action-- I’m wondering if it’s stuck in a handler somehow).

Also did you have a chance to try connecting directly to the overlord ip:port from the middlemanager node? Something like: curl http://ip:port/status

Hi Gian, Got your point.

There is no problem connecting to the overlord from middlemanager.

I tested it with ‘curl http://<overlord_ip:port>/status’ and got response below:

{“version”:“0.8.0”,“modules”:[{“name”:“io.druid.storage.s3.S3StorageDruidModule”,“artifact”:“druid-s3-extensions”,“version”:“0.8.0”},{“name”:“io.druid.metadata.storage.mysql.MySQLMetadataStorageModule”,“artifact”:“mysql-metadata-storage”,“version”:“0.8.0”},{“name”:“io.druid.firehose.s3.S3FirehoseDruidModule”,“artifact”:“druid-s3-extensions”,“version”:“0.8.0”},{“name”:“io.druid.firehose.szrkafka.SZRKafkaSevenDruidModule”}],“memory”:{“maxMemory”:2112618496,“totalMemory”:2112618496,“freeMemory”:1852596848,“usedMemory”:260021648}}

And also I attached thread dump of overlord when it is stuck.

Trevor.

overlord_thread_dump (738 KB)

Hey Trevor,

From that thread dump it looks like the overlord is not actually handling any requests. So I would guess that the task is for some reason unable to connect to the port. Since you could connect with curl it’s probably not that port being blocked- could you double check that the task is actually discovering the correct overlord ip and port? It should log where it’s trying to connect.

Hey Gian,

I copied and pasted one line of log that Peon emitted while it stuck:

2016-02-18T07:43:41,944 INFO [task-runner-0] io.druid.indexing.common.actions.RemoteTaskActionClient - Submitting action for task[index_data_troubleshoot_2016-02-18T06:53:34.525Z] to overlord[http://:/druid/indexer/v1/action]: SegmentInsertAction{…}

``

If the ip and port info above is what you told, those information is correct corresponding my Overlord node.

If not, please tell me where I can check that.

Trevor.

Yeah, that’s the right log message to look at. From what you’ve said this feels like a networking or dns related issue (especially given that the overlord thread dump doesn’t show it really doing anything). I’m not familiar enough with Azure to give you more specific suggestions, but maybe analyzing the traffic with tcpdump or wireshark would bring something to light.