TopicAutocreate only works if there's at least one topic on broker

[orenorgad]

Hi there, I'm trying to troubleshoot a bruce behavior which I cannot explain.
For some reason, bruce works well with topic autocreate only if there's already at least one topic existing on kafka broker. After firing a few events into bruce for several topics nothing happens and topics are not auto created. Only as I create a dummy topic, that the other topics get created and the event are coming in.
Am I missing something?

*running with both --topic_autocreate & auto.create.topics.enable=true
Thanks in advance,
Oren

[dspeterson]

Hi orenorgad,

I have a couple of questions:

1.  Have you tried reproducing this behavior a different producer, such as the kafka-console-producer.sh program that comes with Kafka?  It would be helpful to know whether the behavior is specific to bruce, or also occurs with other producers.
2.  Is there anything in bruce's log messages that may provide insight?  Can you post the log messages bruce emits when the behavior occurs?  Likewise, can you post a counter report from bruce obtained immediately before the behavior occurs, and another one from immediately afterwards? See https://github.com/ifwe/bruce/blob/master/doc/status_monitoring.md#counter-reporting for information on how to obtain a counter report.

Thanks,
Dave

[orenorgad]

1.Well, producing with kafka-console-producer acts the same as creating a topic via kafka-topics.sh. Bruce is still stuck until I write a new text event which creates a topic. If I just run the kafka-console-producer without pushing an event, bruce is still "hanging".

1. See logs below. Looks like bruce doesn't succeed in fetching metadata request until I create the dummy topic (not appearing in logs since I don't push nothing to it through bruce), and then it starts handling new topics creation.

Nov 13 21:26:40 ip-10-0-2-15 bruce[13774]: Initial metadata request failed for all known brokers, waiting 66783 milliseconds before retry
Nov 13 21:26:59 ip-10-0-2-15 bruce[13638]: Bad metadata response: broker count 0 topic count 0
Nov 13 21:26:59 ip-10-0-2-15 bruce[13638]: Router thread did not get valid metadata response from broker
Nov 13 21:26:59 ip-10-0-2-15 bruce[13638]: Initial metadata request failed for all known brokers, waiting 103787 milliseconds before retry
Nov 13 21:27:41 ip-10-0-2-15 bruce[13570]: Bad metadata response: broker count 0 topic count 0
Nov 13 21:27:41 ip-10-0-2-15 bruce[13570]: Router thread did not get valid metadata response from broker
Nov 13 21:27:41 ip-10-0-2-15 bruce[13570]: Initial metadata request failed for all known brokers, waiting 109523 milliseconds before retry
Nov 13 21:27:47 ip-10-0-2-15 bruce[13774]: Bad metadata response: broker count 0 topic count 0
Nov 13 21:27:47 ip-10-0-2-15 bruce[13774]: Router thread did not get valid metadata response from broker
Nov 13 21:27:47 ip-10-0-2-15 bruce[13774]: Initial metadata request failed for all known brokers, waiting 83244 milliseconds before retry
Nov 13 21:28:01 ip-10-0-2-15 bruce[13706]: Bad metadata response: broker count 0 topic count 0
Nov 13 21:28:01 ip-10-0-2-15 bruce[13706]: Router thread did not get valid metadata response from broker
Nov 13 21:28:01 ip-10-0-2-15 bruce[13706]: Initial metadata request failed for all known brokers, waiting 72605 milliseconds before retry
Nov 13 21:28:43 ip-10-0-2-15 bruce[13638]: Bad metadata response: broker count 0 topic count 0
Nov 13 21:28:43 ip-10-0-2-15 bruce[13638]: Router thread did not get valid metadata response from broker
Nov 13 21:28:43 ip-10-0-2-15 bruce[13638]: Initial metadata request failed for all known brokers, waiting 71320 milliseconds before retry
Nov 13 21:29:10 ip-10-0-2-15 bruce[13774]: Router thread starting dispatcher during initialization
Nov 13 21:29:10 ip-10-0-2-15 bruce[13774]: Starting connector thread for broker index 0 (Kafka ID 100215)
Nov 13 21:29:10 ip-10-0-2-15 bruce[13774]: Router thread finished initialization
Nov 13 21:29:10 ip-10-0-2-15 bruce[13774]: Connector thread 14802 (index 0 broker 100215) started
Nov 13 21:29:10 ip-10-0-2-15 bruce[13774]: Connector thread 14802 (index 0 broker 100215) connecting to host px-centos-67 port 9092
Nov 13 21:29:10 ip-10-0-2-15 bruce[13774]: Connector thread 14802 (index 0 broker 100215) connect successful
Nov 13 21:29:10 ip-10-0-2-15 bruce[13774]: Automatic creation of topic [rawdata_User] was successful: updating metadata
Nov 13 21:29:13 ip-10-0-2-15 bruce[13774]: Router thread starting fast dispatcher shutdown for metadata refresh
Nov 13 21:29:13 ip-10-0-2-15 bruce[13774]: Sending fast shutdown request to connector thread (index 0 broker 100215)
Nov 13 21:29:13 ip-10-0-2-15 bruce[13774]: Waiting for shutdown ACK from connector thread (index 0 broker 100215)
Nov 13 21:29:13 ip-10-0-2-15 bruce[13774]: Connector thread 14802 (index 0 broker 100215) sending ACK for fast shutdown
Nov 13 21:29:13 ip-10-0-2-15 bruce[13774]: Connector thread 14802 (index 0 broker 100215) finished normally
Nov 13 21:29:13 ip-10-0-2-15 bruce[13774]: All connector threads finished shutting down
Nov 13 21:29:13 ip-10-0-2-15 bruce[13774]: Got shutdown ACK from connector thread (index 0 broker 100215)
Nov 13 21:29:13 ip-10-0-2-15 bruce[13774]: Router thread started fast dispatcher shutdown for metadata refresh
Nov 13 21:29:13 ip-10-0-2-15 bruce[13774]: Waiting for dispatcher shutdown to finish
Nov 13 21:29:13 ip-10-0-2-15 bruce[13774]: Start waiting for dispatcher shutdown status
Nov 13 21:29:13 ip-10-0-2-15 bruce[13774]: Finished waiting for dispatcher shutdown status
Nov 13 21:29:13 ip-10-0-2-15 bruce[13774]: Router thread finished waiting for dispatcher shutdown on metadata refresh
Nov 13 21:29:13 ip-10-0-2-15 bruce[13774]: Router thread finished metadata fetch for refresh: starting dispatcher
Nov 13 21:29:13 ip-10-0-2-15 bruce[13774]: Starting connector thread for broker index 0 (Kafka ID 100215)
Nov 13 21:29:13 ip-10-0-2-15 bruce[13774]: Router thread started dispatcher
Nov 13 21:29:13 ip-10-0-2-15 bruce[13774]: Automatic creation of topic [online_Classifier] was successful: updating metadata
Nov 13 21:29:13 ip-10-0-2-15 bruce[13774]: Connector thread 14809 (index 0 broker 100215) started
Nov 13 21:29:13 ip-10-0-2-15 bruce[13774]: Connector thread 14809 (index 0 broker 100215) connecting to host px-centos-67 port 9092
Nov 13 21:29:13 ip-10-0-2-15 bruce[13774]: Connector thread 14809 (index 0 broker 100215) connect successful
Nov 13 21:29:14 ip-10-0-2-15 bruce[13706]: Router thread starting dispatcher during initialization
Nov 13 21:29:14 ip-10-0-2-15 bruce[13706]: Starting connector thread for broker index 0 (Kafka ID 100215)
Nov 13 21:29:14 ip-10-0-2-15 bruce[13706]: Router thread finished initialization
Nov 13 21:29:14 ip-10-0-2-15 bruce[13706]: Connector thread 14813 (index 0 broker 100215) started
Nov 13 21:29:14 ip-10-0-2-15 bruce[13706]: Connector thread 14813 (index 0 broker 100215) connecting to host px-centos-67 port 9092
Nov 13 21:29:14 ip-10-0-2-15 bruce[13706]: Connector thread 14813 (index 0 broker 100215) connect successful
Nov 13 21:29:16 ip-10-0-2-15 bruce[13774]: Router thread starting fast dispatcher shutdown for metadata refresh
Nov 13 21:29:16 ip-10-0-2-15 bruce[13774]: Sending fast shutdown request to connector thread (index 0 broker 100215)
Nov 13 21:29:16 ip-10-0-2-15 bruce[13774]: Waiting for shutdown ACK from connector thread (index 0 broker 100215)
Nov 13 21:29:16 ip-10-0-2-15 bruce[13774]: Connector thread 14809 (index 0 broker 100215) sending ACK for fast shutdown
Nov 13 21:29:16 ip-10-0-2-15 bruce[13774]: Connector thread 14809 (index 0 broker 100215) finished normally
Nov 13 21:29:16 ip-10-0-2-15 bruce[13774]: All connector threads finished shutting down
Nov 13 21:29:16 ip-10-0-2-15 bruce[13774]: Got shutdown ACK from connector thread (index 0 broker 100215)
Nov 13 21:29:16 ip-10-0-2-15 bruce[13774]: Router thread started fast dispatcher shutdown for metadata refresh
Nov 13 21:29:16 ip-10-0-2-15 bruce[13774]: Waiting for dispatcher shutdown to finish
Nov 13 21:29:16 ip-10-0-2-15 bruce[13774]: Start waiting for dispatcher shutdown status
Nov 13 21:29:16 ip-10-0-2-15 bruce[13774]: Finished waiting for dispatcher shutdown status
Nov 13 21:29:16 ip-10-0-2-15 bruce[13774]: Router thread finished waiting for dispatcher shutdown on metadata refresh
Nov 13 21:29:16 ip-10-0-2-15 bruce[13774]: Router thread finished metadata fetch for refresh: starting dispatcher
Nov 13 21:29:16 ip-10-0-2-15 bruce[13774]: Starting connector thread for broker index 0 (Kafka ID 100215)
Nov 13 21:29:16 ip-10-0-2-15 bruce[13774]: Router thread started dispatcher
Nov 13 21:29:16 ip-10-0-2-15 bruce[13774]: Connector thread 14814 (index 0 broker 100215) started
Nov 13 21:29:16 ip-10-0-2-15 bruce[13774]: Connector thread 14814 (index 0 broker 100215) connecting to host px-centos-67 port 9092
Nov 13 21:29:16 ip-10-0-2-15 bruce[13774]: Connector thread 14814 (index 0 broker 100215) connect successful

[orenorgad]

By looking at router_thread.cc, metadata is expected to have at least 1 item in it to break without failure. But when there are no topics just yet metadata will be empty.

Thanks for helping Dave.

[dspeterson]

This looks like an oversight on my part. Thanks for discovering the problem! Bruce's metadata handling code should accept without complaint a metadata response containing no topics. That would allow the router thread to break out of its loop trying to get a satisfactory metadata response, and handle the topic autocreation. I'll add fixing this issue to my to-do list but it may be a while before I get to it, since I'm currently swamped with things unrelated to bruce. In the meantime, please feel free to submit a patch.

Thanks,
Dave

[dspeterson]

fix.diff.zip

[dspeterson]

I took a closer look at the problem, and fixing it turned out to be pretty straightforward. Above is a patch containing a fix (to be applied to bruce version 1.0.28), along with some minor code cleanup. Please give it a try and let me know if you run into any issues. I tested it out, and it works for me.

A while ago, I created Dory, which is a fork of Bruce (see https://github.com/dspeterson/dory ). I recommend giving Dory a try, since it is now the focus of all of my development efforts. I created a new release of Dory containing the above fix, so it should not suffer from the problem you reported. Hopefully, if(we) will also merge the above fix into bruce some time soon. I'll ping them about it.

Dave

[dspeterson]

build_fix.diff.zip

[dspeterson]

If you are building Bruce with the latest version of SCons, you will also need the above fix to work around a build error. Dory already has this fix, so it should build without problems regardless of your SCons version.

[orenorgad]

Thanks Dave! we will give it a try.
And thank you for creating this project in the first place :)