How to find out which bolt is not acking in a Storm Topology?

Viewed 394

I´ve been working on a Storm Topology and I´m facing some tuple failures. I suspect that one of the bolts is not acking in a specific case causing these failures by timeout. Is there a way in Apache Storm API (0.10.0) to identify which bolt is not acking as expected?

Let´s suppose we have MySpout, BoltA and BoltB as components of this topology and MySpout emits tuples for both bolts expecting they´re going to ack after processing tuples. BoltA in executeTuple() method is always acking, but BoltB is acking only for even values it receives. All tuples with odd values are going to fail after 10 minutes they were emmitted.

In this small sample, it´s easy to identify the failed flow. But in a complex system that we can follow dozens of different flows having multiple bolts it´s like looking for a needle in a haystack. Is there any smart way to find this failure?

public class MySpout extends BaseRichSpout {
    protected SpoutOutputCollector collector;
    //...
    @Override
    public void nextTuple() {
        Integer msgId = new Integer((int)(Math.random() * 5000 + 1));
        collector.emit(new Values(msgId), msgId);
    }
    @Override
    public void fail(Object msgId) {
        new Exception("Failed tuple. msgId="+msgId).printStackTrace();
    }
}

public class BoltA extends BaseRichBolt {
    private OutputCollector outputCollector;
    //...
    @Override
    protected void executeTuple(Tuple input) {
        Integer n = (Integer) input.getValues().get(0);
        outputCollector.ack(input);
    }
}

public class BoltB extends BaseRichBolt {
    private OutputCollector outputCollector;
    //...
    @Override
    protected void executeTuple(Tuple input) {
        Integer n = (Integer) input.getValues().get(0);
        if (n%2==0) {
            outputCollector.ack(input);
        }
    }
}

A timeout value of 10 minutes was configured for this Storm.

<!-- storm config -->
<property>
    <name>topology.enable.message.timeouts</name>
    <value>true</value>
</property>
<property>
    <!-- 10 mins -->
    <name>topology.message.timeout.secs</name>
    <value>600</value>
</property>

This is the stack trace we see when a tuple fails. I was trying to extract some information of the tuple failure flow. It didn´t say anything that helped me.

java.lang.Exception: Failed tuple. msgId=1234
at MySpout.fail(MySpout.java:127) [myJar.jar:?]
at backtype.storm.daemon.executor$fail_spout_msg.invoke(executor.clj:401) [storm-core-0.10.0-beta1.jar:0.10.0-beta1]
at backtype.storm.daemon.executor$fn$reify__4467.expire(executor.clj:461) [storm-core-0.10.0-beta1.jar:0.10.0-beta1]
at backtype.storm.utils.RotatingMap.rotate(RotatingMap.java:73) [storm-core-0.10.0-beta1.jar:0.10.0-beta1]
at backtype.storm.daemon.executor$fn__4464$tuple_action_fn__4470.invoke(executor.clj:466) [storm-core-0.10.0-beta1.jar:0.10.0-beta1]
at backtype.storm.daemon.executor$mk_task_receiver$fn__4455.invoke(executor.clj:433) [storm-core-0.10.0-beta1.jar:0.10.0-beta1]
at backtype.storm.disruptor$clojure_handler$reify__4029.onEvent(disruptor.clj:58) [storm-core-0.10.0-beta1.jar:0.10.0-beta1]
at backtype.storm.utils.DisruptorQueue.consumeBatchToCursor(DisruptorQueue.java:125) [storm-core-0.10.0-beta1.jar:0.10.0-beta1]
at backtype.storm.utils.DisruptorQueue.consumeBatch(DisruptorQueue.java:87) [storm-core-0.10.0-beta1.jar:0.10.0-beta1]
at backtype.storm.disruptor$consume_batch.invoke(disruptor.clj:76) [storm-core-0.10.0-beta1.jar:0.10.0-beta1]
at backtype.storm.daemon.executor$fn__4464$fn__4479$fn__4510.invoke(executor.clj:578) [storm-core-0.10.0-beta1.jar:0.10.0-beta1]
at backtype.storm.util$async_loop$fn__543.invoke(util.clj:475) [storm-core-0.10.0-beta1.jar:0.10.0-beta1]
at clojure.lang.AFn.run(AFn.java:22) [clojure-1.6.0.jar:?]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_45]
1 Answers

The spout doesn't know which bolt caused the tuple to fail, which is why you can't see anything in the stack trace.

I'll use the 1.2.2 code to respond. It's likely you can do the same in 0.10.0, but that version is ancient and I don't want to go digging around in it.

A way to debug this is to enable Storm's debug logging when you submit the topology.

Config config = new Config();
config.setDebug(true);
//submit your topology using this Config

When a tuple fails, you will get a log like

2019-06-29 12:16:09.552 o.a.s.d.executor Thread-11-word-executor[16 16] [INFO] SPOUT Failing 32496024444700129: {:stream "default", :values [84 1561716922356 116]} REASON: TIMEOUT MSG-ID: 116

You can then figure out which bolt didn't ack the tuple by elimination. If you search your log for the tuple id (here it's the 32496024444700129 value), you will see logs for each transfer to a bolt of that tuple, e.g.

2019-06-29 12:15:22.356 o.a.s.d.executor Thread-11-word-executor[16 16] [INFO] TRANSFERING tuple [dest: 4 tuple: source: word:16, stream: default, id: {32496024444700129=5923978744049352856}, [84, 1561716922356, 116]]

This tells me that the tuple was transferred to task 4. When the topology started, it logged which bolt was task 4, you can also see this in Storm UI.

2019-06-29 12:15:08.801 o.a.s.d.executor main [INFO] Loading executor exclaim1:[4 4]

I can see that task 4 acked the tuple, so it isn't the reason the tuple timed out

2019-06-29 12:15:22.359 o.a.s.d.task Thread-17-exclaim1-executor[4 4] [INFO] Emitting: exclaim1 __ack_ack [32496024444700129 7387867738466240036]

I can also see that task 4 transferred the tuple to task 8

2019-06-29 12:15:22.359 o.a.s.d.executor Thread-17-exclaim1-executor[4 4] [INFO] TRANSFERING tuple [dest: 8 tuple: source: exclaim1:4, stream: default, id: {32496024444700129=3796756412183316156}, [84!!!]]

and that task 8 processed it

2019-06-29 12:15:22.363 o.a.s.d.executor Thread-5-exclaim2-executor[8 8] [INFO] Processing received message FOR 8 TUPLE: source: exclaim1:4, stream: default, id: {32496024444700129=3796756412183316156}, [84!!!]

There is no log that task 8 acked that tuple, so task 8 is the bolt that didn't ack correctly.

I go look up task 8 in the log and get

2019-06-29 12:15:08.446 o.a.s.d.executor main [INFO] Loaded executor tasks exclaim2:[8 8]

So "exclaim2" is the bolt in my topology that doesn't ack correctly.

Related