Not able to get Tranquility working

[Maxime Nay]

Hi,

I am trying to use tranquility for the first time on a simple data source, but for some reason, it doesn't seem to do anything. I created a BeamFactory, and used it to create a BeamBolt. It seems curator starts properly (or at least, stays quiet when curator.start() is called)
My indexing service is running in distributed mode with only 1 overlord and 1 middle manager (3 peons available), and I can see it registered in druid's zookeeper at /prod/discovery/druid:prod:indexer.

I am using your storm distribution, as recommended in the wiki.

I don't have any log. The topology is not throwing any exception/logging anything. There is nothing concerning this data source in the overlord/middle manager logs.

Any idea on how I could debug this?

Thanks
Maxime

[Andres Gomez Ferrer]

What version of zookeeper do you use? Do you configure on middleManager.properties the "druid.indexer.task.chathandler.type=announce" ??

Regards, 

Andrés

[Maxime Nay]

Hi Andrés,

My Druid cluster is using zookeeper 3.4.6. The topology jar is using zookeeper 3.4.6. I am not sure my topology is using any zookeeper since I am running it in local mode with a LocalCluster.
My middle manager's conf has druid.indexer.task.chathandler.type=announce set, and it actually works to index data or perform merge tasks.

Thanks
Maxime

[Gian Merlino]

Can you share your storm logs? If not, I'm wondering if you have any log messages along the lines of "Sending %,d queued events." or "Updating instances for service[%s] to %s" or "Sent %,d, ignored %,d queued events.". Possibly others too but those are usually good things to check for first. They are logged when tranquility decides to send events, finishes sending events, and discovers druid indexing services, respectively.

[Maxime Nay]

Hi Gian,

For some reason I can't see any meaningful log messages related to my beam bolt. I only have:

2014-05-30 10:24:11,684 DEBUG org.jboss.logging - Logging Provider: org.jboss.logging.Log4jLoggerProvider
2014-05-30 10:24:11,685 INFO  org.hibernate.validator.internal.util.Version - HV000001: Hibernate Validator 5.0.1.Final
2014-05-30 10:24:11,693 DEBUG  org.hibernate.validator.internal.engine.resolver.DefaultTraversableResolver - Cannot find javax.persistence.Persistence on classpath. Assuming non JPA 2 environment. All properties will per default be traversable.
2014-05-30 10:24:11,697 DEBUG  org.hibernate.validator.internal.xml.ValidationXmlParser - Trying to load META-INF/validation.xml for XML based Validator configuration.
2014-05-30 10:24:11,700 DEBUG  org.hibernate.validator.internal.xml.ValidationXmlParser - No META-INF/validation.xml found. Using annotation based configuration only.

I made sure the topology is actually emitting messages to the bolt.  It seems to be stuck in the DruidBeams....buildBeam()
It is probably some silly mistake, but since I am not too good at understanding scala, I couldn't figure out what I was doing wrong by looking into the sources.

And as I said earlier, the topology is not running on a real storm cluster. I am running this locally using a LocalCluster

Where is how I am building the BoltBeam:

        return DruidBeams
            .builder(new Timestamper<Map<String, Object>>() {

                @Override
                public DateTime timestamp(Map<String, Object> map) {
                    return new DateTime(map.get(TIMESTAMP.toString()));
                }

            })
            .curator(curator)
            .discoveryPath(discoveryPath)
            .location(new DruidLocation(new DruidEnvironment(indexService, firehosePattern), dataSource))
            .rollup(DruidRollup.create(DruidDimensions.specific(dimensions), aggregators, QueryGranularity.MINUTE))
            .tuning(ClusteredBeamTuning.create(Granularity.HOUR, new Period("PT0M"), new Period("PT10M"), 1, 1))
            .buildBeam();

It seems that curator starts properly.
The discovery path exists in Druid's zookeeper, and the indexService node seems to be there. (verified using exhibitor)
My firehose pattern is the default druid:firehose:%s

[Gian Merlino]

Interesting. If it is stuck in buildBeam, can you trigger a thread dump and see where exactly it is stuck? (kill -3 or use jstack)

[Maxime Nay]

Hi Giam,

Here is the thread dump of the thread running the beam bolt.

"BeamBolt-Emitter-IMAGE_REVIEW_DRUID_BOLT-0" daemon prio=10 tid=0x00007ff90c957000 nid=0xd04 in Object.wait() [0x00007ffa17efd000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x000000070c703a38> (a java.lang.Object)
    at com.metamx.tranquility.storm.BeamBolt$$anonfun$1.apply$mcV$sp(BeamBolt.scala:77)
    - locked <0x000000070c703a38> (a java.lang.Object)
    at com.metamx.tranquility.storm.BeamBolt$$anonfun$1.apply(BeamBolt.scala:55)
    at com.metamx.tranquility.storm.BeamBolt$$anonfun$1.apply(BeamBolt.scala:55)
    at com.metamx.common.scala.concurrent.package$$anon$1.run(package.scala:37)
    at java.lang.Thread.run(Thread.java:745)

"Thread-18-IMAGE_REVIEW_DRUID_BOLT-EventThread" daemon prio=10 tid=0x00007ff90c04c800 nid=0xce2 waiting on condition [0x00007ffa1debc000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x000000070c792df8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:494)

"Thread-18-IMAGE_REVIEW_DRUID_BOLT-SendThread(xx:2181)" daemon prio=10 tid=0x00007ff90c030000 nid=0xce1 runnable [0x00007ffa1dfbd000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
    - locked <0x000000070c7d1ab8> (a sun.nio.ch.Util$2)
    - locked <0x000000070c7d1aa8> (a java.util.Collections$UnmodifiableSet)
    - locked <0x000000070c7d1688> (a sun.nio.ch.EPollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
    at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:349)
    at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1081)

"Thread-18-IMAGE_REVIEW_DRUID_BOLT" prio=10 tid=0x00007ff93408b800 nid=0xcd1 waiting on condition [0x00007ffa1f5f4000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x000000070b015530> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2176)
    at com.lmax.disruptor.BlockingWaitStrategy.waitFor(BlockingWaitStrategy.java:87)
    at com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarrier.java:54)
    at backtype.storm.utils.DisruptorQueue.consumeBatchWhenAvailable(DisruptorQueue.java:76)
    at backtype.storm.disruptor$consume_batch_when_available.invoke(disruptor.clj:77)
    at backtype.storm.daemon.executor$eval5279$fn__5280$fn__5292$fn__5339.invoke(executor.clj:745)
    at backtype.storm.util$async_loop$fn__398.invoke(util.clj:433)
    at clojure.lang.AFn.run(AFn.java:24)
    at java.lang.Thread.run(Thread.java:745)

Thanks
Maxime

[Maxime Nay]

Oh, and I just found out that if I let it run for about 25 minutes, I get:

Jun 02 2014 10:04:13 AM ERROR (c.m.c.s.concurrent.package$$anon$1) - Killed by exception
java.lang.InterruptedException: null
    at java.lang.Object.wait(Native Method) ~[na:1.7.0_55]
    at com.metamx.tranquility.storm.BeamBolt$$anonfun$1.apply$mcV$sp(BeamBolt.scala:77) ~[tranquility-0.1.19.jar:na]
    at com.metamx.tranquility.storm.BeamBolt$$anonfun$1.apply(BeamBolt.scala:55) ~[tranquility-0.1.19.jar:na]
    at com.metamx.tranquility.storm.BeamBolt$$anonfun$1.apply(BeamBolt.scala:55) ~[tranquility-0.1.19.jar:na]
    at com.metamx.common.scala.concurrent.package$$anon$1.run(package.scala:37) ~[scala-util_2.9.1-1.5.9.jar:na]
    at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]

[Gian Merlino]

That looks like the bolt is sitting around waiting for data to show up. If you don't ever see the log message "Sending %,d queued events" then I would guess the most likely reason is that no tuples are actually being sent to the bolt. Is it possible something is stuck further upstream in the topology, or that the bolts and spouts are not wired up?

If you can rebuild tranquility, or run in a debugger, maybe try sticking a log message or breakpoint in BeamBolt's execute(tuple) method, to confirm that it is actually seeing data.

[Gian Merlino]

That thread should get interrupted when storm calls the bolt's "cleanup" method. I think that should only happen if storm is trying to rebalance the task (which I don't think should happen in local mode…) or shut down the topology.

[Maxime Nay]

I think the bolt is properly linked to the rest of the topology and the previous bolt is actually emitting tuples. I will double check friday, maybe I did a silly mistake.

So is it normal to not see any kind of log in the topology, and to not see anything neither in the overlord/middle managers nodes, before the beam bolt actually starts receiving tuples?

I don't know if it's equivalent to directly add a log statement in the execute method of the beam bolt, but I remember trying to add a log statement in the Timestamper's implementation of the timestamp function. Nothing was getting printed.

[Gian Merlino]

I think the only log message you should see on the storm side before data comes in is DiscoResolver "Updating instances for service[XXX]" where XXX is your indexService. The rest won't appear until tuples show up. It's normal not to see anything on the overlord or middle managers until the bolt actually receives data, since it doesn't create tasks until it does.

The Timestamper gets called somewhat downstream of the bolt's execute method. I think all tuples executed should eventually make it into the Timestamper, although it is possible there is some issue in your case that causes that to not happen.

[Maxime Nay]

Hi Gian,

I extended the BeamBolt and overrode the execute method this way:
    @Override
    public void execute(Tuple tuple) {
        System.out.println("bla");
        super.execute(tuple);
    }

When I run the topology, the bolt properly prints the statement.

At some point I am getting:

Jun 06 2014 11:11:04 AM INFO  (c.g.storm.adevent.BeamBoltExtends) - Sending 113 queued events.
bla
Jun 06 2014 11:11:04 AM WARN  (c.g.storm.adevent.BeamBoltExtends) - Failed to send 113 queued events.
java.lang.ClassCastException: java.lang.Long cannot be cast to java.util.Map
    at com.gumgum.storm.adevent.ImageReviewBeamFactory$1.timestamp(ImageReviewBeamFactory.java:1) ~[test/:na]
    at com.metamx.tranquility.beam.ClusteredBeam$$anonfun$12.apply(ClusteredBeam.scala:286) ~[tranquility-0.1.20.jar:na]
    at com.metamx.tranquility.beam.ClusteredBeam$$anonfun$12.apply(ClusteredBeam.scala:286) ~[tranquility-0.1.20.jar:na]
    at com.metamx.tranquility.beam.ClusteredBeam$$anonfun$13.apply(ClusteredBeam.scala:287) ~[tranquility-0.1.20.jar:na]
    at com.metamx.tranquility.beam.ClusteredBeam$$anonfun$13.apply(ClusteredBeam.scala:287) ~[tranquility-0.1.20.jar:na]
    at scala.collection.TraversableLike$$anonfun$groupBy$1.apply(TraversableLike.scala:315) ~[scala-library-2.9.3.jar:na]
    at scala.collection.TraversableLike$$anonfun$groupBy$1.apply(TraversableLike.scala:314) ~[scala-library-2.9.3.jar:na]
    at scala.collection.Iterator$class.foreach(Iterator.scala:772) ~[scala-library-2.9.3.jar:na]
    at scala.collection.immutable.VectorIterator.foreach(Vector.scala:648) ~[scala-library-2.9.3.jar:na]
    at scala.collection.IterableLike$class.foreach(IterableLike.scala:73) ~[scala-library-2.9.3.jar:na]
    at scala.collection.immutable.Vector.foreach(Vector.scala:63) ~[scala-library-2.9.3.jar:na]
    at scala.collection.TraversableLike$class.groupBy(TraversableLike.scala:314) ~[scala-library-2.9.3.jar:na]
    at scala.collection.immutable.Vector.groupBy(Vector.scala:63) ~[scala-library-2.9.3.jar:na]
    at com.metamx.tranquility.beam.ClusteredBeam.propagate(ClusteredBeam.scala:287) ~[tranquility-0.1.20.jar:na]
    at com.metamx.tranquility.druid.DruidBeams$Builder$$anon$7.propagate(DruidBeams.scala:173) ~[tranquility-0.1.20.jar:na]
    at com.metamx.tranquility.storm.BeamBolt$$anonfun$1.apply$mcV$sp(BeamBolt.scala:64) [tranquility-0.1.20.jar:na]
    at com.metamx.tranquility.storm.BeamBolt$$anonfun$1.apply(BeamBolt.scala:55) [tranquility-0.1.20.jar:na]
    at com.metamx.tranquility.storm.BeamBolt$$anonfun$1.apply(BeamBolt.scala:55) [tranquility-0.1.20.jar:na]
    at com.metamx.common.scala.concurrent.package$$anon$1.run(package.scala:37) [scala-util_2.9.1-1.7.1.jar:na]

    at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]

So I guess if I do something like:
               final BeamBolt<Map<String, Object>> imageReviewBolt = new BeamBolt<Map<String, Object>>(new ImageReviewBeamFactory());
it's not sending anything to the bolt (since I never get "Sending 113 queued events.") , but if I do:
        final BeamBolt<Map<String, Object>> imageReviewBolt = new BeamBoltExtends<Map<String, Object>>(new ImageReviewBeamFactory());

it does.
Any idea?

[Gian Merlino]

That behavior seems really weird. I can't think of a reason why overriding execute like that would change how tuples are processed. Is nothing else different?

That aside, the exception you are seeing looks like the BeamBolt is getting a Long rather than the Map that it expects. The BeamBolt expects its event type (Map in your case) to be in the first field of the tuple-- i.e. tuple.getValue(0). You might have to tweak how the previous bolt or spout is emitting tuples in order to get this to be the case.

[Maxime Nay]

Ok, so I fixed the long/map error, and now the timestamp method from the original BeamBolt displays properly my log statement.
But I still can't see any "Sending %s queued events" statements.

And I think you mentioned "Updating instances for service[XXX] earlier". I can't see this statement either.

[Maxime Nay]

By switching again to my BeamBolt subclass I get some "Sending XXX queued events."
Then:
Jun 06 2014 15:12:21 PM WARN  (c.g.storm.adevent.BeamBoltExtends) - Failed to send XXX queued events.
java.lang.IllegalStateException: Failed to save new beam for identifier[druid:prod:indexer/image_review_test] timestamp[2014-06-06T00:00:00.000-07:00]
    at com.metamx.tranquility.beam.ClusteredBeam$$anonfun$10.apply(ClusteredBeam.scala:224) ~[tranquility-0.1.20.jar:na]
    at com.metamx.tranquility.beam.ClusteredBeam$$anonfun$10.apply(ClusteredBeam.scala:221) ~[tranquility-0.1.20.jar:na]
    at com.twitter.util.Future$$anonfun$rescue$1.apply(Future.scala:802) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Future$$anonfun$rescue$1.apply(Future.scala:801) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise$Transformer.liftedTree1$1(Promise.scala:93) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise$Transformer.k(Promise.scala:93) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise$Transformer.apply(Promise.scala:102) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise$Transformer.apply(Promise.scala:84) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise$$anon$2.run(Promise.scala:324) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.concurrent.LocalScheduler$Activation.run(Scheduler.scala:175) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.concurrent.LocalScheduler$Activation.submit(Scheduler.scala:146) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.concurrent.LocalScheduler.submit(Scheduler.scala:201) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.concurrent.Scheduler$.submit(Scheduler.scala:79) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise.runq(Promise.scala:310) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise.updateIfEmpty(Promise.scala:605) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.ExecutorServiceFuturePool$$anon$2.run(FuturePool.scala:111) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) ~[na:1.7.0_55]
    at java.util.concurrent.FutureTask.run(FutureTask.java:262) ~[na:1.7.0_55]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) ~[na:1.7.0_55]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) ~[na:1.7.0_55]

    at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]

Caused by: com.metamx.tranquility.druid.IndexServiceTransientException: Service call failed with status: 500 Server Error
    at com.metamx.tranquility.druid.IndexService$$anonfun$call$1$$anonfun$apply$6.apply(IndexService.scala:102) ~[tranquility-0.1.20.jar:na]
    at com.metamx.tranquility.druid.IndexService$$anonfun$call$1$$anonfun$apply$6.apply(IndexService.scala:84) ~[tranquility-0.1.20.jar:na]
    at com.twitter.util.Future$$anonfun$map$1$$anonfun$apply$4.apply(Future.scala:821) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Try$.apply(Try.scala:13) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Future$.apply(Future.scala:82) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Future$$anonfun$map$1.apply(Future.scala:821) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Future$$anonfun$map$1.apply(Future.scala:821) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Future$$anonfun$flatMap$1.apply(Future.scala:784) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Future$$anonfun$flatMap$1.apply(Future.scala:783) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise$Transformer.liftedTree1$1(Promise.scala:93) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise$Transformer.k(Promise.scala:93) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise$Transformer.apply(Promise.scala:102) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise$Transformer.apply(Promise.scala:84) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise$$anon$2.run(Promise.scala:333) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.concurrent.LocalScheduler$Activation.run(Scheduler.scala:175) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.concurrent.LocalScheduler$Activation.submit(Scheduler.scala:146) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.concurrent.LocalScheduler.submit(Scheduler.scala:201) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.concurrent.Scheduler$.submit(Scheduler.scala:79) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise.runq(Promise.scala:310) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise.updateIfEmpty(Promise.scala:605) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise.update(Promise.scala:583) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise.setValue(Promise.scala:559) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.concurrent.AsyncQueue.offer(AsyncQueue.scala:76) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.finagle.transport.ChannelTransport.handleUpstream(ChannelTransport.scala:45) ~[finagle-core_2.9.2-6.16.0.jar:6.16.0]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.handler.codec.http.HttpContentDecoder.messageReceived(HttpContentDecoder.java:108) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.handler.codec.http.HttpChunkAggregator.messageReceived(HttpChunkAggregator.java:145) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:459) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:536) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:435) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.handler.codec.http.HttpClientCodec.handleUpstream(HttpClientCodec.java:92) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.SimpleChannelHandler.messageReceived(SimpleChannelHandler.java:142) ~[netty-3.9.1.Final.jar:na]
    at com.twitter.finagle.channel.ChannelStatsHandler.messageReceived(ChannelStatsHandler.scala:81) ~[finagle-core_2.9.2-6.16.0.jar:6.16.0]
    at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:88) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.SimpleChannelHandler.messageReceived(SimpleChannelHandler.java:142) ~[netty-3.9.1.Final.jar:na]
    at com.twitter.finagle.channel.ChannelRequestStatsHandler.messageReceived(ChannelRequestStatsHandler.scala:35) ~[finagle-core_2.9.2-6.16.0.jar:6.16.0]
    at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:88) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:88) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:108) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:318) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:89) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) ~[netty-3.9.1.Final.jar:na]
    at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42) ~[netty-3.9.1.Final.jar:na]
    ... 3 common frames omitted


And I can now see a /tranquility/beams/druid:prod:indexer/image_review_test/... path in Druid's zookeeper.

[Maxime Nay]

And the exception in the overlord logs:

SEVERE: The exception contained within MappableContainerException could not be mapped to a response, re-throwing to the HTTP container
com.fasterxml.jackson.databind.JsonMappingException: Instantiation of [simple type, class io.druid.indexing.common.task.RealtimeIndexTask] value failed: null
        at com.fasterxml.jackson.databind.deser.std.StdValueInstantiator.wrapException(StdValueInstantiator.java:440)
        at com.fasterxml.jackson.databind.deser.std.StdValueInstantiator.createFromObjectWith(StdValueInstantiator.java:244)
        at com.fasterxml.jackson.databind.deser.impl.PropertyBasedCreator.build(PropertyBasedCreator.java:158)
        at com.fasterxml.jackson.databind.deser.BeanDeserializer._deserializeUsingPropertyBased(BeanDeserializer.java:401)
        at com.fasterxml.jackson.databind.deser.BeanDeserializerBase.deserializeFromObjectUsingNonDefault(BeanDeserializerBase.java:977)
        at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserializeFromObject(BeanDeserializer.java:276)
        at com.fasterxml.jackson.databind.deser.BeanDeserializer._deserializeOther(BeanDeserializer.java:157)
        at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:123)
        at com.fasterxml.jackson.databind.jsontype.impl.AsPropertyTypeDeserializer._deserializeTypedForId(AsPropertyTypeDeserializer.java:113)
        at com.fasterxml.jackson.databind.jsontype.impl.AsPropertyTypeDeserializer.deserializeTypedFromObject(AsPropertyTypeDeserializer.java:82)
        at com.fasterxml.jackson.databind.deser.AbstractDeserializer.deserializeWithType(AbstractDeserializer.java:106)
        at com.fasterxml.jackson.databind.deser.impl.TypeWrappedDeserializer.deserialize(TypeWrappedDeserializer.java:36)
        at com.fasterxml.jackson.databind.ObjectReader._bind(ObjectReader.java:1179)
...
Caused by: java.lang.NullPointerException
        at io.druid.indexing.common.task.RealtimeIndexTask.<init>(RealtimeIndexTask.java:117)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
        at com.fasterxml.jackson.databind.introspect.AnnotatedConstructor.call(AnnotatedConstructor.java:125)
        at com.fasterxml.jackson.databind.deser.std.StdValueInstantiator.createFromObjectWith(StdValueInstantiator.java:240)
        ... 64 more

2014-06-06 15:21:39,762 WARN [qtp1601945612-36] org.eclipse.jetty.servlet.ServletHandler -
javax.servlet.ServletException: com.fasterxml.jackson.databind.JsonMappingException: Instantiation of [simple type, class io.druid.indexing.common.task.RealtimeIndexTask] value failed: null
        at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:420)
        at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:538)
        at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:716)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
        at com.google.inject.servlet.ServletDefinition.doServiceImpl(ServletDefinition.java:278)
        at com.google.inject.servlet.ServletDefinition.doService(ServletDefinition.java:268)
        at com.google.inject.servlet.ServletDefinition.service(ServletDefinition.java:180)
        at com.google.inject.servlet.ManagedServletPipeline.service(ManagedServletPipeline.java:93)
...
Caused by: com.fasterxml.jackson.databind.JsonMappingException: Instantiation of [simple type, class io.druid.indexing.common.task.RealtimeIndexTask] value failed: null
        at com.fasterxml.jackson.databind.deser.std.StdValueInstantiator.wrapException(StdValueInstantiator.java:440)
        at com.fasterxml.jackson.databind.deser.std.StdValueInstantiator.createFromObjectWith(StdValueInstantiator.java:244)
        at com.fasterxml.jackson.databind.deser.impl.PropertyBasedCreator.build(PropertyBasedCreator.java:158)
...

[Gian Merlino]

The weirdness with BeamBolt vs BeamBoltExtends log messages sounds like it might be a logging config thing. Does your logging configuration let through INFO messages from com.metamx.tranquility?

The NPE sounds like a serialization problem. What version of tranquility and what version of druid are you using?

[Maxime Nay]

About the log messages, that's what I thought also, I just fixed it I think. (and I am now able to properly see tranquility's logs. It should help a lot :D)

I was using com.metamx:tranquility:0.1.20. Most of our Druid cluster is running on the latest stable (0.6.105).
I just noticed tranquility 0.1.20 seems to ship io.druid:druid-server:0.6.121. That was the problem. I reverted back to 0.1.19, and it seems it's able to create the realtime task now.

Now I am getting this exception (even after adding: .timestampSpec(new TimestampSpec("timestamp", "millis")) to my DruidBeams builder):
Jun 06 2014 16:46:07 PM WARN  (c.m.tranquility.finagle.FutureRetry$) - Transient error, will try again in 1159 ms
java.io.IOException: Unable to push events to task: index_realtime_image_review_test_2014-06-06T00:00:00.000-07:00_0_0_mmpdmdbg (status = TaskRunning)
    at com.metamx.tranquility.druid.DruidBeam$$anonfun$4$$anonfun$apply$2$$anonfun$apply$4$$anonfun$apply$5$$anonfun$apply$7$$anonfun$apply$9.apply(DruidBeam.scala:148) ~[tranquility-0.1.19.jar:na]
    at com.metamx.tranquility.druid.DruidBeam$$anonfun$4$$anonfun$apply$2$$anonfun$apply$4$$anonfun$apply$5$$anonfun$apply$7$$anonfun$apply$9.apply(DruidBeam.scala:134) ~[tranquility-0.1.19.jar:na]

    at com.twitter.util.Future$$anonfun$map$1$$anonfun$apply$4.apply(Future.scala:821) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Try$.apply(Try.scala:13) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Future$.apply(Future.scala:82) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Future$$anonfun$map$1.apply(Future.scala:821) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Future$$anonfun$map$1.apply(Future.scala:821) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Future$$anonfun$flatMap$1.apply(Future.scala:784) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Future$$anonfun$flatMap$1.apply(Future.scala:783) ~[util-core_2.9.2-6.16.0.jar:6.16.0]

    at com.twitter.util.Promise$Transformer.liftedTree1$1(Promise.scala:93) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise$Transformer.k(Promise.scala:93) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise$Transformer.apply(Promise.scala:102) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise$Transformer.apply(Promise.scala:84) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise$$anon$2.run(Promise.scala:324) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.concurrent.LocalScheduler$Activation.run(Scheduler.scala:175) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.concurrent.LocalScheduler$Activation.submit(Scheduler.scala:146) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.concurrent.LocalScheduler.submit(Scheduler.scala:201) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.concurrent.Scheduler$.submit(Scheduler.scala:79) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise.runq(Promise.scala:310) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise.updateIfEmpty(Promise.scala:600) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise.update(Promise.scala:583) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise.setValue(Promise.scala:559) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.concurrent.AsyncQueue.offer(AsyncQueue.scala:76) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.finagle.transport.ChannelTransport.handleUpstream(ChannelTransport.scala:41) [finagle-core_2.9.2-6.11.1.jar:6.11.1]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.handler.codec.http.HttpContentDecoder.messageReceived(HttpContentDecoder.java:108) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.handler.codec.http.HttpChunkAggregator.messageReceived(HttpChunkAggregator.java:194) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:459) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:536) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:435) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.handler.codec.http.HttpClientCodec.handleUpstream(HttpClientCodec.java:92) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.SimpleChannelHandler.messageReceived(SimpleChannelHandler.java:142) [netty-3.9.0.Final.jar:na]
    at com.twitter.finagle.channel.ChannelStatsHandler.messageReceived(ChannelStatsHandler.scala:81) [finagle-core_2.9.2-6.11.1.jar:6.11.1]
    at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:88) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.SimpleChannelHandler.messageReceived(SimpleChannelHandler.java:142) [netty-3.9.0.Final.jar:na]
    at com.twitter.finagle.channel.ChannelRequestStatsHandler.messageReceived(ChannelRequestStatsHandler.scala:35) [finagle-core_2.9.2-6.11.1.jar:6.11.1]
    at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:88) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.9.0.Final.jar:na]
    at com.twitter.finagle.netty3.SimpleChannelSnooper.handleUpstream(ChannelSnooper.scala:84) [finagle-core_2.9.2-6.11.1.jar:6.11.1]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:88) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:108) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:318) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:89) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42) [netty-3.9.0.Final.jar:na]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]

    at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]

Caused by: java.io.IOException: Failed to propagate 7 events for 2014-06-06T00:00:00.000-07:00: 500 Server Error
    at com.metamx.tranquility.druid.DruidBeam$$anonfun$4$$anonfun$apply$2$$anonfun$apply$4$$anonfun$apply$5$$anonfun$apply$6.apply(DruidBeam.scala:122) ~[tranquility-0.1.19.jar:na]
    at com.metamx.tranquility.druid.DruidBeam$$anonfun$4$$anonfun$apply$2$$anonfun$apply$4$$anonfun$apply$5$$anonfun$apply$6.apply(DruidBeam.scala:109) ~[tranquility-0.1.19.jar:na]

    at com.twitter.util.Future$$anonfun$map$1$$anonfun$apply$4.apply(Future.scala:821) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Try$.apply(Try.scala:13) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Future$.apply(Future.scala:82) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Future$$anonfun$map$1.apply(Future.scala:821) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Future$$anonfun$map$1.apply(Future.scala:821) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Future$$anonfun$flatMap$1.apply(Future.scala:784) ~[util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Future$$anonfun$flatMap$1.apply(Future.scala:783) ~[util-core_2.9.2-6.16.0.jar:6.16.0]

    at com.twitter.util.Promise$Transformer.liftedTree1$1(Promise.scala:93) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise$Transformer.k(Promise.scala:93) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise$Transformer.apply(Promise.scala:102) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise$Transformer.apply(Promise.scala:84) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise$$anon$2.run(Promise.scala:333) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.concurrent.LocalScheduler$Activation.run(Scheduler.scala:175) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.concurrent.LocalScheduler$Activation.submit(Scheduler.scala:146) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.concurrent.LocalScheduler.submit(Scheduler.scala:201) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.concurrent.Scheduler$.submit(Scheduler.scala:79) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise.runq(Promise.scala:310) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise.updateIfEmpty(Promise.scala:600) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise.update(Promise.scala:583) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.util.Promise.setValue(Promise.scala:559) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.concurrent.AsyncQueue.offer(AsyncQueue.scala:76) [util-core_2.9.2-6.16.0.jar:6.16.0]
    at com.twitter.finagle.transport.ChannelTransport.handleUpstream(ChannelTransport.scala:41) [finagle-core_2.9.2-6.11.1.jar:6.11.1]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.handler.codec.http.HttpContentDecoder.messageReceived(HttpContentDecoder.java:108) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.9.0.Final.jar:na]
    at org.jboss.netty.handler.codec.http.HttpChunkAggregator.messageReceived(HttpChunkAggregator.java:145) [netty-3.9.0.Final.jar:na]
    ... 36 common frames omitted

[Gian Merlino]

Ah, ok. Yeah, tranquility 0.1.19 is the stable one right now too, and it should work well with the stable druid. The newer tranquilities will probably be promoted to stable when the corresponding druid release is promoted.

Does the druid indexing task log have anything interesting in it (for task index_realtime_image_review_test_2014-06-06T00:00:00.000-07:00_0_0_mmpdmdbg)? The tranquility exception said that it got an HTTP 500 from indexing, so maybe the task log has a more interesting exception.

[Maxime Nay]

When this task was created, .timestampSpec(new TimestampSpec("timestamp", "millis")) was not specified.
I killed the task (to do so I killed the peon and deleted the znode in zookeeper. Is there an easier way to do so?) and restarted the topology. And now it seems to properly send the events. I can see my new data source, and I can query it. However I think I am facing more issues due to the fact that I am using PST timezone. (I remember having the same issue with druid 0.6.105, and I had to upgrade to 0.6.114 to fix the issue)

Btw, when I try to look at the logs using the overlord consoler (overlord/console.html), and I click on the task's "log (all)", I get:

<html>
<head>
<meta http-equiv="Content-Type" content="text/html;charset=ISO-8859-1"/>
<title>Error 404 </title>
</head>
<body>
<h2>HTTP ERROR: 404</h2>
<p>Problem accessing /druid/worker/v1/task/index_realtime_image_review_test_2014-06-06T00:00:00.000-07:00_0_0_mmpdmdbg/log. Reason:
<pre>    Not Found</pre></p>
<hr /><i><small>Powered by Jetty://</small></i>
</body>
</html>

[Gian Merlino]

There's a task shutdown api. Just POST an empty body to http://overlord/druid/indexer/v1/task_id/shutdown (e.g. curl -XPOST http://overlord/druid/indexer/v1/task_id/shutdown).

As discussed on IRC, maybe try the latest versions from master rather than the stables, which might work better in non-utc timezones: druid-0.6.121 and tranquility-0.1.20.

For the log thing, keep in mind that currently-running task logs are served directly by the middle manager, but logs for completed tasks are served from a TaskLogs provider. The default provider uses the local file system, which means that the overlord won't be able to find the logs (since they're not on *its* filesystem). If you are using S3, you can set druid.indexer.logs.type=s3 along with druid.indexer.logs.s3Bucket and druid.indexer.logs.s3Prefix to store the logs on S3 and allow the overlord to find them. If you are using HDFS, there isn't yet an HDFSTaskLogs implementation, but of course contributions are welcome :)

[Maxime Nay]

Thanks for the shutdown tip.

Upgrading the middle managers, the overlord to 0.6.121 and using tranquility 0.1.20 seems to fix the segment interval problem. I think I am now able to use tranquility with a non-utc timezone and a segment granularity of 1 day. And the inserted data seems accurate so far. I should be able to use tranquility for all our datasources now! :)

[Fangjin Yang]

Hi Maxime, great to hear. Tranquility should hopefully provide you with high availability, schema changes with no downtime, and much easier scalability.

--
You received this message because you are subscribed to the Google Groups "Druid Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to druid-developm...@googlegroups.com.
To post to this group, send email to druid-de...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/druid-development/f3c81878-5e66-4b33-9f88-a59c73ce2ff3%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.