Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

PartitionAvailable always return false, but partition is avail #70

Open
sinjimmyi opened this issue Oct 19, 2016 · 5 comments
Open

PartitionAvailable always return false, but partition is avail #70

sinjimmyi opened this issue Oct 19, 2016 · 5 comments

Comments

@sinjimmyi
Copy link

I got a topic name paidorder which has two partitions and I have set up two broker.
I try to follow Advance Producer as following. But I found out that PartitionAvailable function would return true no matter which partition is in use, then when I try to produce any other message, it would return false. However the message is produced successfully and could be consumed.

using (var kafkaProducer = KafkaHelper.GenerateProducer())
                    {
                        var topicConfig = new TopicConfig
                        {
                            CustomPartitioner = (top, key, cnt) =>
                            {
                                var kt = (key != null) ? Encoding.UTF8.GetString(key, 0, key.Length) : "(null)";
                                int partition = new Random().Next(0, 2); ;
                                bool available = top.PartitionAvailable(partition);
                                log.Info($"Partitioner topic: {top.Name} key: {kt} partition count: {cnt} -> {partition} {available}");
                                return partition;
                            }
                        };
                        using (Topic topic = kafkaProducer.Topic("paidorder", topicConfig))
                        {
                            byte[] data = Encoding.UTF8.GetBytes(order.orderid.ToString());
                            Task<DeliveryReport> deliveryReport = topic.Produce(data, data);
                            var unused = deliveryReport.ContinueWith(task =>
                            {
                                    log.Info($"Partition: {task.Result.Partition}, Offset: {task.Result.Offset}");
                            });
                        }
                    }

image
@ah-
Copy link
Owner

ah- commented Oct 19, 2016

Probably @edenhill can help you more.

I'm not entirely sure what's going on there, could you run this with a bit more debug logging? I wonder if anything happens between True and False that makes librdkafka change it's view on whether there's a leader broker.

@edenhill
Copy link

Yeah I'm not really sure either. Try enable debug=metadata,topic,msg and see if anything interesting is turning up between those partitioner calls.

@ah-
Copy link
Owner

ah- commented Nov 9, 2016

There's now a 0.9.2 build up. Could you check if you can still reproduce it with that?

@sinjimmyi
Copy link
Author

sinjimmyi commented Nov 15, 2016 •
edited
Loading

I try 0.9.2-ci-177 with my previous code, it's host by a windows service application, I still got the same result . I don't know how to get the librdkafka debug message in windows service application.
image
In order to get the debug message, this time I produce three message in an console application. the Availbility of partition in console application still seems weird. The debug=metadata,topic,msg is as following

7|2016-11-15 15:50:18.319|rdkafka#producer-1|TOPIC| New local topic: paidorder
7|2016-11-15 15:50:18.327|rdkafka#producer-1|METADATA| 192.168.1.129:9092/bootstrap: Request metadata for locally known topics: connected
7|2016-11-15 15:50:18.327|rdkafka#producer-1|METADATA| 192.168.1.129:9092/bootstrap: Request metadata for locally known topics: connected
7|2016-11-15 15:50:18.337|rdkafka#producer-1|METADATA| 192.168.198.3:9092/bootstrap: Request metadata for locally known topics: connected
7|2016-11-15 15:50:18.338|rdkafka#producer-1|METADATA| 192.168.198.3:9092/bootstrap: Request metadata for locally known topics: connected
7|2016-11-15 15:50:18.347|rdkafka#producer-1|METADATA| 192.168.1.129:9092/bootstrap: ===== Received metadata =====
7|2016-11-15 15:50:18.347|rdkafka#producer-1|METADATA| 192.168.1.129:9092/bootstrap: 2 brokers, 1 topics
7|2016-11-15 15:50:18.347|rdkafka#producer-1|METADATA| 192.168.1.129:9092/bootstrap:   Broker #0/2: DESKTOP-TVSNFCI:9092 NodeId 1
7|2016-11-15 15:50:18.347|rdkafka#producer-1|METADATA| 192.168.1.129:9092/bootstrap:   Broker #1/2: i-ynchf9uc:9092 NodeId 0
7|2016-11-15 15:50:18.347|rdkafka#producer-1|METADATA| 192.168.1.129:9092/bootstrap:   Topic #0/1: paidorder with 2 partitions
7|2016-11-15 15:50:18.347|rdkafka#producer-1|STATE| Topic paidorder changed state unknown -> exists
7|2016-11-15 15:50:18.347|rdkafka#producer-1|PARTCNT| Topic paidorder partition count changed from 0 to 2
7|2016-11-15 15:50:18.348|rdkafka#producer-1|METADATA| 192.168.1.129:9092/bootstrap:   Topic paidorder partition 1 Leader 1
7|2016-11-15 15:50:18.348|rdkafka#producer-1|BRKDELGT| Broker DESKTOP-TVSNFCI:9092/1 is now leader for topic paidorder [1] with 0 messages (0 bytes) queued
7|2016-11-15 15:50:18.348|rdkafka#producer-1|BRKMIGR| Migrating topic paidorder [1] from (none) to DESKTOP-TVSNFCI:9092/1
7|2016-11-15 15:50:18.348|rdkafka#producer-1|METADATA| 192.168.1.129:9092/bootstrap:   Topic paidorder partition 0 Leader 1
7|2016-11-15 15:50:18.348|rdkafka#producer-1|BRKDELGT| Broker DESKTOP-TVSNFCI:9092/1 is now leader for topic paidorder [0] with 0 messages (0 bytes) queued
7|2016-11-15 15:50:18.348|rdkafka#producer-1|BRKMIGR| Migrating topic paidorder [0] from (none) to DESKTOP-TVSNFCI:9092/1
7|2016-11-15 15:50:18.348|rdkafka#producer-1|PARTCNT| Partitioning 1 unassigned messages in topic paidorder to 2 partitions
Partitioner topic: paidorder key: 1042 partition count: 2 -> 0 False
7|2016-11-15 15:50:18.351|rdkafka#producer-1|UAS| 1/1 messages were partitioned in topic paidorder
7|2016-11-15 15:50:18.353|rdkafka#producer-1|TOPBRK| DESKTOP-TVSNFCI:9092/1: Topic paidorder [1]: joining broker
7|2016-11-15 15:50:18.353|rdkafka#producer-1|TOPBRK| DESKTOP-TVSNFCI:9092/1: Topic paidorder [0]: joining broker
7|2016-11-15 15:50:18.364|rdkafka#producer-1|METADATA| DESKTOP-TVSNFCI:9092/1: Request metadata for locally known topics: connected
7|2016-11-15 15:50:18.364|rdkafka#producer-1|METADATA| DESKTOP-TVSNFCI:9092/1: Request metadata for locally known topics: connected
7|2016-11-15 15:50:18.364|rdkafka#producer-1|PRODUCE| DESKTOP-TVSNFCI:9092/1: produce messageset with 1 messages (34 bytes)
7|2016-11-15 15:50:18.366|rdkafka#producer-1|METADATA| DESKTOP-TVSNFCI:9092/1: ===== Received metadata =====
7|2016-11-15 15:50:18.366|rdkafka#producer-1|METADATA| DESKTOP-TVSNFCI:9092/1: 2 brokers, 1 topics
7|2016-11-15 15:50:18.367|rdkafka#producer-1|METADATA| DESKTOP-TVSNFCI:9092/1:   Broker #0/2: DESKTOP-TVSNFCI:9092 NodeId 1
7|2016-11-15 15:50:18.373|rdkafka#producer-1|METADATA| i-ynchf9uc:9092/0: Request metadata for locally known topics: connected
7|2016-11-15 15:50:18.374|rdkafka#producer-1|METADATA| DESKTOP-TVSNFCI:9092/1:   Broker #1/2: i-ynchf9uc:9092 NodeId 0
7|2016-11-15 15:50:18.375|rdkafka#producer-1|METADATA| DESKTOP-TVSNFCI:9092/1:   Topic #0/1: paidorder with 2 partitions
7|2016-11-15 15:50:18.376|rdkafka#producer-1|METADATA| DESKTOP-TVSNFCI:9092/1:   Topic paidorder partition 1 Leader 1
7|2016-11-15 15:50:18.377|rdkafka#producer-1|METADATA| DESKTOP-TVSNFCI:9092/1:   Topic paidorder partition 0 Leader 1
7|2016-11-15 15:50:18.374|rdkafka#producer-1|METADATA| i-ynchf9uc:9092/0: Request metadata for locally known topics: connected
7|2016-11-15 15:50:18.379|rdkafka#producer-1|MSGSET| DESKTOP-TVSNFCI:9092/1: MessageSet with 1 message(s) delivered
7|2016-11-15 15:50:18.382|rdkafka#producer-1|DESTROY| Terminating instance
Partition: 0, Offset: 15
7|2016-11-15 15:50:18.439|rdkafka#producer-1|METADATA| 192.168.198.3:9092/bootstrap: ===== Received metadata =====
7|2016-11-15 15:50:18.439|rdkafka#producer-1|DESTROY| Destroy internal
7|2016-11-15 15:50:18.440|rdkafka#producer-1|DESTROY| Remove all topics
7|2016-11-15 15:50:18.440|rdkafka#producer-1|PARTCNT| Topic paidorder partition count changed from 2 to 0
7|2016-11-15 15:50:18.440|rdkafka#producer-1|BRKDELGT| Broker DESKTOP-TVSNFCI:9092/1 no longer leader for topic paidorder [0]
7|2016-11-15 15:50:18.440|rdkafka#producer-1|BRKDELGT| No broker is leader for topic paidorder [0]
7|2016-11-15 15:50:18.440|rdkafka#producer-1|BRKMIGR| Migrating topic paidorder [0] from DESKTOP-TVSNFCI:9092/1 to (none)
7|2016-11-15 15:50:18.441|rdkafka#producer-1|BRKDELGT| Broker DESKTOP-TVSNFCI:9092/1 no longer leader for topic paidorder [1]
7|2016-11-15 15:50:18.441|rdkafka#producer-1|BRKDELGT| No broker is leader for topic paidorder [1]
7|2016-11-15 15:50:18.441|rdkafka#producer-1|BRKMIGR| Migrating topic paidorder [1] from DESKTOP-TVSNFCI:9092/1 to (none)
7|2016-11-15 15:50:18.441|rdkafka#producer-1|TOPPARREMOVE| Removing toppar paidorder [-1]
7|2016-11-15 15:50:18.465|rdkafka#producer-1|METADATA| i-ynchf9uc:9092/0: ===== Received metadata =====
7|2016-11-15 15:50:18.468|rdkafka#producer-1|TOPBRK| DESKTOP-TVSNFCI:9092/1: Topic paidorder [0]: leaving broker (next leader (none))
7|2016-11-15 15:50:18.468|rdkafka#producer-1|TOPPARREMOVE| Removing toppar paidorder [0]
7|2016-11-15 15:50:18.468|rdkafka#producer-1|TOPBRK| DESKTOP-TVSNFCI:9092/1: Topic paidorder [1]: leaving broker (next leader (none))
7|2016-11-15 15:50:18.468|rdkafka#producer-1|TOPPARREMOVE| Removing toppar paidorder [1]
7|2016-11-15 15:50:28.471|rdkafka#producer-2|TOPIC| New local topic: paidorder
7|2016-11-15 15:50:28.492|rdkafka#producer-2|METADATA| 192.168.198.3:9092/bootstrap: Request metadata for locally known topics: connected
7|2016-11-15 15:50:28.492|rdkafka#producer-2|METADATA| 192.168.198.3:9092/bootstrap: Request metadata for locally known topics: connected
7|2016-11-15 15:50:28.495|rdkafka#producer-2|METADATA| 192.168.1.129:9092/bootstrap: Request metadata for locally known topics: connected
7|2016-11-15 15:50:28.495|rdkafka#producer-2|METADATA| 192.168.1.129:9092/bootstrap: Request metadata for locally known topics: connected
7|2016-11-15 15:50:28.516|rdkafka#producer-2|METADATA| 192.168.1.129:9092/bootstrap: ===== Received metadata =====
7|2016-11-15 15:50:28.516|rdkafka#producer-2|METADATA| 192.168.1.129:9092/bootstrap: 2 brokers, 1 topics
7|2016-11-15 15:50:28.518|rdkafka#producer-2|METADATA| 192.168.1.129:9092/bootstrap:   Broker #0/2: DESKTOP-TVSNFCI:9092 NodeId 1
7|2016-11-15 15:50:28.524|rdkafka#producer-2|METADATA| 192.168.1.129:9092/bootstrap:   Broker #1/2: i-ynchf9uc:9092 NodeId 0
7|2016-11-15 15:50:28.525|rdkafka#producer-2|METADATA| 192.168.1.129:9092/bootstrap:   Topic #0/1: paidorder with 2 partitions
7|2016-11-15 15:50:28.526|rdkafka#producer-2|STATE| Topic paidorder changed state unknown -> exists
7|2016-11-15 15:50:28.527|rdkafka#producer-2|PARTCNT| Topic paidorder partition count changed from 0 to 2
7|2016-11-15 15:50:28.529|rdkafka#producer-2|METADATA| 192.168.1.129:9092/bootstrap:   Topic paidorder partition 1 Leader 1
7|2016-11-15 15:50:28.530|rdkafka#producer-2|BRKDELGT| Broker DESKTOP-TVSNFCI:9092/1 is now leader for topic paidorder [1] with 0 messages (0 bytes) queued
7|2016-11-15 15:50:28.531|rdkafka#producer-2|BRKMIGR| Migrating topic paidorder [1] from (none) to DESKTOP-TVSNFCI:9092/1
7|2016-11-15 15:50:28.532|rdkafka#producer-2|METADATA| 192.168.1.129:9092/bootstrap:   Topic paidorder partition 0 Leader 1
7|2016-11-15 15:50:28.533|rdkafka#producer-2|BRKDELGT| Broker DESKTOP-TVSNFCI:9092/1 is now leader for topic paidorder [0] with 0 messages (0 bytes) queued
7|2016-11-15 15:50:28.532|rdkafka#producer-2|METADATA| DESKTOP-TVSNFCI:9092/1: Request metadata for locally known topics: connected
7|2016-11-15 15:50:28.539|rdkafka#producer-2|METADATA| DESKTOP-TVSNFCI:9092/1: Request metadata for locally known topics: connected
7|2016-11-15 15:50:28.540|rdkafka#producer-2|TOPBRK| DESKTOP-TVSNFCI:9092/1: Topic paidorder [1]: joining broker
7|2016-11-15 15:50:28.534|rdkafka#producer-2|BRKMIGR| Migrating topic paidorder [0] from (none) to DESKTOP-TVSNFCI:9092/1
7|2016-11-15 15:50:28.542|rdkafka#producer-2|PARTCNT| Partitioning 1 unassigned messages in topic paidorder to 2 partitions
7|2016-11-15 15:50:28.542|rdkafka#producer-2|TOPBRK| DESKTOP-TVSNFCI:9092/1: Topic paidorder [0]: joining broker
Partitioner topic: paidorder key: 1157 partition count: 2 -> 0 True
7|2016-11-15 15:50:28.544|rdkafka#producer-2|UAS| 1/1 messages were partitioned in topic paidorder
7|2016-11-15 15:50:28.545|rdkafka#producer-2|METADATA| DESKTOP-TVSNFCI:9092/1: ===== Received metadata =====
7|2016-11-15 15:50:28.546|rdkafka#producer-2|METADATA| DESKTOP-TVSNFCI:9092/1: 2 brokers, 1 topics
7|2016-11-15 15:50:28.547|rdkafka#producer-2|METADATA| DESKTOP-TVSNFCI:9092/1:   Broker #0/2: DESKTOP-TVSNFCI:9092 NodeId 1
7|2016-11-15 15:50:28.548|rdkafka#producer-2|METADATA| DESKTOP-TVSNFCI:9092/1:   Broker #1/2: i-ynchf9uc:9092 NodeId 0
7|2016-11-15 15:50:28.551|rdkafka#producer-2|METADATA| DESKTOP-TVSNFCI:9092/1:   Topic #0/1: paidorder with 2 partitions
7|2016-11-15 15:50:28.547|rdkafka#producer-2|METADATA| i-ynchf9uc:9092/0: Request metadata for locally known topics: connected
7|2016-11-15 15:50:28.553|rdkafka#producer-2|METADATA| i-ynchf9uc:9092/0: Request metadata for locally known topics: connected
7|2016-11-15 15:50:28.552|rdkafka#producer-2|METADATA| DESKTOP-TVSNFCI:9092/1:   Topic paidorder partition 1 Leader 1
7|2016-11-15 15:50:28.555|rdkafka#producer-2|METADATA| DESKTOP-TVSNFCI:9092/1:   Topic paidorder partition 0 Leader 1
7|2016-11-15 15:50:28.593|rdkafka#producer-2|METADATA| 192.168.198.3:9092/bootstrap: ===== Received metadata =====
7|2016-11-15 15:50:28.593|rdkafka#producer-2|METADATA| 192.168.198.3:9092/bootstrap: 2 brokers, 1 topics
7|2016-11-15 15:50:28.601|rdkafka#producer-2|METADATA| 192.168.198.3:9092/bootstrap:   Broker #0/2: DESKTOP-TVSNFCI:9092 NodeId 1
7|2016-11-15 15:50:28.601|rdkafka#producer-2|METADATA| 192.168.198.3:9092/bootstrap:   Broker #1/2: i-ynchf9uc:9092 NodeId 0
7|2016-11-15 15:50:28.602|rdkafka#producer-2|METADATA| 192.168.198.3:9092/bootstrap:   Topic #0/1: paidorder with 2 partitions
7|2016-11-15 15:50:28.604|rdkafka#producer-2|METADATA| 192.168.198.3:9092/bootstrap:   Topic paidorder partition 1 Leader 1
7|2016-11-15 15:50:28.606|rdkafka#producer-2|METADATA| 192.168.198.3:9092/bootstrap:   Topic paidorder partition 0 Leader 1
7|2016-11-15 15:50:28.645|rdkafka#producer-2|PRODUCE| DESKTOP-TVSNFCI:9092/1: produce messageset with 1 messages (34 bytes)
7|2016-11-15 15:50:28.646|rdkafka#producer-2|MSGSET| DESKTOP-TVSNFCI:9092/1: MessageSet with 1 message(s) delivered
Partition: 0, Offset: 16
7|2016-11-15 15:50:28.647|rdkafka#producer-2|DESTROY| Terminating instance
7|2016-11-15 15:50:28.648|rdkafka#producer-2|METADATA| i-ynchf9uc:9092/0: ===== Received metadata =====
7|2016-11-15 15:50:28.648|rdkafka#producer-2|DESTROY| Destroy internal
7|2016-11-15 15:50:28.649|rdkafka#producer-2|DESTROY| Remove all topics
7|2016-11-15 15:50:28.650|rdkafka#producer-2|PARTCNT| Topic paidorder partition count changed from 2 to 0
7|2016-11-15 15:50:28.650|rdkafka#producer-2|BRKDELGT| Broker DESKTOP-TVSNFCI:9092/1 no longer leader for topic paidorder [0]
7|2016-11-15 15:50:28.651|rdkafka#producer-2|BRKDELGT| No broker is leader for topic paidorder [0]
7|2016-11-15 15:50:28.652|rdkafka#producer-2|BRKMIGR| Migrating topic paidorder [0] from DESKTOP-TVSNFCI:9092/1 to (none)
7|2016-11-15 15:50:28.652|rdkafka#producer-2|BRKDELGT| Broker DESKTOP-TVSNFCI:9092/1 no longer leader for topic paidorder [1]
7|2016-11-15 15:50:28.653|rdkafka#producer-2|BRKDELGT| No broker is leader for topic paidorder [1]
7|2016-11-15 15:50:28.654|rdkafka#producer-2|BRKMIGR| Migrating topic paidorder [1] from DESKTOP-TVSNFCI:9092/1 to (none)
7|2016-11-15 15:50:28.654|rdkafka#producer-2|TOPPARREMOVE| Removing toppar paidorder [-1]
7|2016-11-15 15:50:28.747|rdkafka#producer-2|TOPBRK| DESKTOP-TVSNFCI:9092/1: Topic paidorder [0]: leaving broker (next leader (none))
7|2016-11-15 15:50:28.747|rdkafka#producer-2|TOPPARREMOVE| Removing toppar paidorder [0]
7|2016-11-15 15:50:28.748|rdkafka#producer-2|TOPBRK| DESKTOP-TVSNFCI:9092/1: Topic paidorder [1]: leaving broker (next leader (none))
7|2016-11-15 15:50:28.748|rdkafka#producer-2|TOPPARREMOVE| Removing toppar paidorder [1]
7|2016-11-15 15:50:38.752|rdkafka#producer-3|TOPIC| New local topic: paidorder
7|2016-11-15 15:50:38.762|rdkafka#producer-3|METADATA| 192.168.1.129:9092/bootstrap: Request metadata for locally known topics: connected
7|2016-11-15 15:50:38.772|rdkafka#producer-3|METADATA| 192.168.198.3:9092/bootstrap: Request metadata for locally known topics: connected
7|2016-11-15 15:51:04.915|rdkafka#producer-3|METADATA| 192.168.198.3:9092/bootstrap: Request metadata for paidorder: leader query
7|2016-11-15 15:51:07.383|rdkafka#producer-3|METADATA| 192.168.1.129:9092/bootstrap: Request metadata for locally known topics: connected
7|2016-11-15 15:51:07.386|rdkafka#producer-3|METADATA| 192.168.198.3:9092/bootstrap: Request metadata: scheduled: not in broker thread
7|2016-11-15 15:51:07.385|rdkafka#producer-3|METADATA| 192.168.198.3:9092/bootstrap: Request metadata for locally known topics: connected
7|2016-11-15 15:51:07.389|rdkafka#producer-3|METADATA| 192.168.198.3:9092/bootstrap: Request metadata for paidorder: leader query
7|2016-11-15 15:51:07.392|rdkafka#producer-3|METADATA| 192.168.198.3:9092/bootstrap: Request metadata for paidorder: leader query
7|2016-11-15 15:51:07.407|rdkafka#producer-3|METADATA| 192.168.1.129:9092/bootstrap: ===== Received metadata =====
7|2016-11-15 15:51:07.407|rdkafka#producer-3|METADATA| 192.168.1.129:9092/bootstrap: 2 brokers, 1 topics
7|2016-11-15 15:51:07.408|rdkafka#producer-3|METADATA| 192.168.1.129:9092/bootstrap:   Broker #0/2: DESKTOP-TVSNFCI:9092 NodeId 1
7|2016-11-15 15:51:07.409|rdkafka#producer-3|METADATA| 192.168.1.129:9092/bootstrap:   Broker #1/2: i-ynchf9uc:9092 NodeId 0
7|2016-11-15 15:51:07.411|rdkafka#producer-3|METADATA| 192.168.1.129:9092/bootstrap:   Topic #0/1: paidorder with 2 partitions
7|2016-11-15 15:51:07.413|rdkafka#producer-3|STATE| Topic paidorder changed state unknown -> exists
7|2016-11-15 15:51:07.414|rdkafka#producer-3|PARTCNT| Topic paidorder partition count changed from 0 to 2
7|2016-11-15 15:51:07.415|rdkafka#producer-3|METADATA| 192.168.1.129:9092/bootstrap:   Topic paidorder partition 1 Leader 1
7|2016-11-15 15:51:07.416|rdkafka#producer-3|BRKDELGT| Broker DESKTOP-TVSNFCI:9092/1 is now leader for topic paidorder [1] with 0 messages (0 bytes) queued
7|2016-11-15 15:51:07.417|rdkafka#producer-3|BRKMIGR| Migrating topic paidorder [1] from (none) to DESKTOP-TVSNFCI:9092/1
7|2016-11-15 15:51:07.418|rdkafka#producer-3|METADATA| 192.168.1.129:9092/bootstrap:   Topic paidorder partition 0 Leader 1
7|2016-11-15 15:51:07.419|rdkafka#producer-3|BRKDELGT| Broker DESKTOP-TVSNFCI:9092/1 is now leader for topic paidorder [0] with 0 messages (0 bytes) queued
7|2016-11-15 15:51:07.418|rdkafka#producer-3|TOPBRK| DESKTOP-TVSNFCI:9092/1: Topic paidorder [1]: joining broker
7|2016-11-15 15:51:07.420|rdkafka#producer-3|BRKMIGR| Migrating topic paidorder [0] from (none) to DESKTOP-TVSNFCI:9092/1
7|2016-11-15 15:51:07.423|rdkafka#producer-3|PARTCNT| Partitioning 1 unassigned messages in topic paidorder to 2 partitions
Partitioner topic: paidorder key: 3658 partition count: 2 -> 1 True
7|2016-11-15 15:51:07.425|rdkafka#producer-3|UAS| 1/1 messages were partitioned in topic paidorder
7|2016-11-15 15:51:07.423|rdkafka#producer-3|TOPBRK| DESKTOP-TVSNFCI:9092/1: Topic paidorder [0]: joining broker
7|2016-11-15 15:51:07.437|rdkafka#producer-3|METADATA| DESKTOP-TVSNFCI:9092/1: Request metadata for locally known topics: connected
7|2016-11-15 15:51:07.437|rdkafka#producer-3|METADATA| DESKTOP-TVSNFCI:9092/1: Request metadata for locally known topics: connected
7|2016-11-15 15:51:07.445|rdkafka#producer-3|METADATA| i-ynchf9uc:9092/0: Request metadata for locally known topics: connected
7|2016-11-15 15:51:07.449|rdkafka#producer-3|METADATA| i-ynchf9uc:9092/0: Request metadata for locally known topics: connected
7|2016-11-15 15:51:07.447|rdkafka#producer-3|PRODUCE| DESKTOP-TVSNFCI:9092/1: produce messageset with 1 messages (34 bytes)
7|2016-11-15 15:51:07.453|rdkafka#producer-3|METADATA| DESKTOP-TVSNFCI:9092/1: ===== Received metadata =====
7|2016-11-15 15:51:07.453|rdkafka#producer-3|METADATA| DESKTOP-TVSNFCI:9092/1: 2 brokers, 1 topics
7|2016-11-15 15:51:07.454|rdkafka#producer-3|METADATA| DESKTOP-TVSNFCI:9092/1:   Broker #0/2: DESKTOP-TVSNFCI:9092 NodeId 1
7|2016-11-15 15:51:07.455|rdkafka#producer-3|METADATA| DESKTOP-TVSNFCI:9092/1:   Broker #1/2: i-ynchf9uc:9092 NodeId 0
7|2016-11-15 15:51:07.456|rdkafka#producer-3|METADATA| DESKTOP-TVSNFCI:9092/1:   Topic #0/1: paidorder with 2 partitions
7|2016-11-15 15:51:07.457|rdkafka#producer-3|METADATA| DESKTOP-TVSNFCI:9092/1:   Topic paidorder partition 1 Leader 1
7|2016-11-15 15:51:07.458|rdkafka#producer-3|METADATA| DESKTOP-TVSNFCI:9092/1:   Topic paidorder partition 0 Leader 1
7|2016-11-15 15:51:07.460|rdkafka#producer-3|MSGSET| DESKTOP-TVSNFCI:9092/1: MessageSet with 1 message(s) delivered
7|2016-11-15 15:51:07.462|rdkafka#producer-3|DESTROY| Terminating instance
Partition: 1, Offset: 323
7|2016-11-15 15:51:07.486|rdkafka#producer-3|METADATA| 192.168.198.3:9092/bootstrap: ===== Received metadata =====
7|2016-11-15 15:51:07.495|rdkafka#producer-3|DESTROY| Destroy internal
7|2016-11-15 15:51:07.499|rdkafka#producer-3|DESTROY| Remove all topics
7|2016-11-15 15:51:07.501|rdkafka#producer-3|PARTCNT| Topic paidorder partition count changed from 2 to 0
7|2016-11-15 15:51:07.496|rdkafka#producer-3|METADATA| 192.168.198.3:9092/bootstrap: ===== Received metadata =====
7|2016-11-15 15:51:07.503|rdkafka#producer-3|BRKDELGT| Broker DESKTOP-TVSNFCI:9092/1 no longer leader for topic paidorder [0]
7|2016-11-15 15:51:07.515|rdkafka#producer-3|BRKDELGT| No broker is leader for topic paidorder [0]
7|2016-11-15 15:51:07.526|rdkafka#producer-3|BRKMIGR| Migrating topic paidorder [0] from DESKTOP-TVSNFCI:9092/1 to (none)
7|2016-11-15 15:51:07.527|rdkafka#producer-3|BRKDELGT| Broker DESKTOP-TVSNFCI:9092/1 no longer leader for topic paidorder [1]
7|2016-11-15 15:51:07.528|rdkafka#producer-3|BRKDELGT| No broker is leader for topic paidorder [1]
7|2016-11-15 15:51:07.529|rdkafka#producer-3|BRKMIGR| Migrating topic paidorder [1] from DESKTOP-TVSNFCI:9092/1 to (none)
7|2016-11-15 15:51:07.530|rdkafka#producer-3|TOPPARREMOVE| Removing toppar paidorder [-1]
7|2016-11-15 15:51:07.537|rdkafka#producer-3|METADATA| i-ynchf9uc:9092/0: ===== Received metadata =====
7|2016-11-15 15:51:07.555|rdkafka#producer-3|TOPBRK| DESKTOP-TVSNFCI:9092/1: Topic paidorder [0]: leaving broker (next leader (none))
7|2016-11-15 15:51:07.555|rdkafka#producer-3|TOPPARREMOVE| Removing toppar paidorder [0]
7|2016-11-15 15:51:07.556|rdkafka#producer-3|TOPBRK| DESKTOP-TVSNFCI:9092/1: Topic paidorder [1]: leaving broker (next leader (none))
7|2016-11-15 15:51:07.557|rdkafka#producer-3|TOPPARREMOVE| Removing toppar paidorder [1]

@treziac
Copy link
Contributor

treziac commented Dec 6, 2016 •
edited
Loading

I could reproduce with the same code on 0.9.2 this afternoon (had time to spend on it and wanted to understand s long post which give more questions than answers, sorry)
Weird things are happening at producer and topic initizalization, depending of when broker are joining the topic and what bootrstrap are used

TL;DR;
there seem to be a lag between topic creation and broker identification, wat a bit after topic creation or call Metadata() seems to solve the problem
Also, you are constantly recreating a producer and a topic, only create it once and store it in your app, you will get fare better throughput and less odd behaviour

Long part:
I have two kafka brokers, b0(kafka:9192) and b1(kafka:9193). My topic has three partition, b0 is leader on P0 and P2, B1 on P1. Note that both brokers are on same machine in my dev env, but it's not on the machine running the program below

string broker = "kafka:9192";
int roundRObinPartition = -1;

TopicConfig.Partitioner randomPartitionerPrintAvailable = (top, key, cnt) =>
{
	//round robin
	try
	{ 
		int partition = Interlocked.Increment(ref roundRObinPartition) % cnt;
		Console.WriteLine($"{DateTime.Now:HH:mm:ss.fff} -> {partition} {top.PartitionAvailable(partition)}");
		return partition;
	}
	catch
	{
		Console.WriteLine("custom partitioner error");
		return 0;
	}
};
var config = new Config
{
	["debug"] = "topic",
	Logger = (handle,level,fac,message) =>
	{
		if(fac == "TOPBRK")
		{
			Console.WriteLine($"{DateTime.Now:HH:mm:ss.fff} {handle} {level} {fac} {message}");
		}
	}
};

var topicConfig = new TopicConfig { CustomPartitioner = randomPartitionerPrintAvailable };

using (var kafkaProducer = new Producer(config, broker))
{
	//A
	using (Topic topic = kafkaProducer.Topic("paidorder", topicConfig))
	{
		//B
		for (int i = 0; i < 20; i++)
		{
			Task.Delay(2).Wait();
			topic.Produce(null);
		}
	}
}

Task.Delay(2).Wait() is here to see the result properly, or i have to produce thousand of message to show what i observe
Will write B0 or B1 for bootstrap server
A and B are place where i will put kafkaProducer.Metadata() to show behaviour
Proucing null or a array give same results, null here for simplicity

Use B0 as bootstrap
rdkafka#producer-1 7 TOPBRK kafka:9193/1: Topic paidorder [1]: joining broker (rktp 0000020394A37890)
rdkafka#producer-1 7 TOPBRK :0/internal: Topic paidorder [2]: joining broker (rktp 0000020394A37DC0)
rdkafka#producer-1 7 TOPBRK :0/internal: Topic paidorder [0]: joining broker (rktp 0000020394A37360)
17:10:33.407 -> 0 False
17:10:33.411 -> 1 True
rdkafka#producer-1 7 TOPBRK :0/internal: Topic paidorder [2]: leaving broker (0 messages in xmitq, next leader kafka:9192/0, rktp 0000020394A37DC0)
rdkafka#producer-1 7 TOPBRK :0/internal: Topic paidorder [0]: leaving broker (0 messages in xmitq, next leader kafka:9192/0, rktp 0000020394A37360)//
17:10:33.423 -> 2 False
17:10:33.439 -> 0 False
17:10:33.455 -> 1 True
rdkafka#producer-1 7 TOPBRK kafka:9192/0: Topic paidorder [2]: joining broker (rktp 0000020394A37DC0)
rdkafka#producer-1 7 TOPBRK kafka:9192/0: Topic paidorder [0]: joining broker (rktp 0000020394A37360)
17:10:33.470 -> 2 True
17:10:33.486 -> 0 True
17:10:33.501 -> 1 True
...

Note that I receive true for partition i after receiving TOPBRK kafka:XXXX/X: Topic paidorder [i]: joining broker
This is alays the case for all example

Use B1 as bootstrap : no internal broker
17:13:32.250 rdkafka#producer-1 7 TOPBRK kafka:9192/0: Topic paidorder [2]: joining broker (rktp 000001614698D6A0)
17:13:32.249 rdkafka#producer-1 7 TOPBRK kafka:9193/1: Topic paidorder [1]: joining broker (rktp 000001614698D170)
17:13:32.256 rdkafka#producer-1 7 TOPBRK kafka:9192/0: Topic paidorder [0]: joining broker (rktp 000001614698CC40)
17:13:32.252 -> 0 False
17:13:32.256 -> 1 True
17:13:32.266 -> 2 True
17:13:32.281 -> 0 True
...

Note the timestamp for first topicavailable on P0 (32.252), it occured before P0 joined (32.256), lines have switched
Sometimes i get the partiton available message before TOPBRK message, same behaviour

17:29:27.786 rdkafka#producer-1 7 TOPBRK kafka:9193/1: Topic paidorder [1]: joining broker (rktp 0000021EF1543D60)
17:29:27.788 -> 0 False
17:29:27.793 -> 1 True
17:29:27.787 rdkafka#producer-1 7 TOPBRK kafka:9192/0: Topic paidorder [2]: joining broker (rktp 0000021EF1544290)
17:29:27.794 rdkafka#producer-1 7 TOPBRK kafka:9192/0: Topic paidorder [0]: joining broker (rktp 0000021EF1543830)
17:29:27.808 -> 2 True
17:29:27.824 -> 0 True

call producer.Metadata on A (still B1, same results with B2), never see any internal broker

17:17:36.920 -> 0 False
17:17:36.927 -> 1 False
17:17:36.938 -> 2 False
17:17:36.953 -> 0 False
17:17:36.969 -> 1 False
17:17:36.980 rdkafka#producer-1 7 TOPBRK kafka:9192/0: Topic paidorder [2]: joining broker (rktp 0000022A6A068840)
17:17:36.980 rdkafka#producer-1 7 TOPBRK kafka:9192/0: Topic paidorder [0]: joining broker (rktp 0000022A6A067DE0)
17:17:36.983 -> 2 True
17:17:37.001 -> 0 True
17:17:37.017 -> 1 False
17:17:37.019 rdkafka#producer-1 7 TOPBRK kafka:9193/1: Topic paidorder [1]: joining broker (rktp 0000022A6A068310)
17:17:37.030 -> 2 True
17:17:37.046 -> 0 True
17:17:37.062 -> 1 True
...

If i call metadata before, i don't get the :0/internal join, and i no broker join at beginning. Same behaviour whatever bootstrap

Call Metadata on B with B1 as bootstrap : never see any internal broker

kafka:9192/0: Topic paidorder [2]: joining broker (rktp 0000023CDB91C480)
kafka:9193/1: Topic paidorder [1]: joining broker (rktp 0000023CDB91C9D0)
kafka:9192/0: Topic paidorder [0]: joining broker (rktp 0000023CDB922130)
16:52:37.809 Partitioner topic: paidorder key: (null) partition count: 3 -> 0 True
16:52:37.820 Partitioner topic: paidorder key: (null) partition count: 3 -> 1 True
16:52:37.837 Partitioner topic: paidorder key: (null) partition count: 3 -> 2 True
...

Call Metadata on B with B0 as bootstrap: always create and leave internal broker for P2 and P0

17:19:42.875 rdkafka#producer-1 7 TOPBRK :0/internal: Topic paidorder [2]: joining broker (rktp 0000022918448170)
17:19:42.882 rdkafka#producer-1 7 TOPBRK :0/internal: Topic paidorder [0]: joining broker (rktp 0000022918446F70)
17:19:42.882 rdkafka#producer-1 7 TOPBRK :0/internal: Topic paidorder [2]: leaving broker (0 messages in xmitq, next leader kafka:9192/0, rktp 0000022918448170)
17:19:42.882 rdkafka#producer-1 7 TOPBRK kafka:9192/0: Topic paidorder [2]: joining broker (rktp 0000022918448170)
17:19:42.875 rdkafka#producer-1 7 TOPBRK kafka:9193/1: Topic paidorder [1]: joining broker (rktp 00000229184474A0)
17:19:42.883 rdkafka#producer-1 7 TOPBRK :0/internal: Topic paidorder [0]: leaving broker (0 messages in xmitq, next leader kafka:9192/0, rktp 0000022918446F70)
17:19:42.883 rdkafka#producer-1 7 TOPBRK kafka:9192/0: Topic paidorder [0]: joining broker (rktp 0000022918446F70)
17:19:42.925 -> 0 True
17:19:42.936 -> 1 True
17:19:42.952 -> 2 True
...

So calling metadata after creating topic seems to be a workaround for now.
Calling Task.Delay(1000).Wait() give the same results, so i think it's only due to time for topic creation

This may depend of network. But whatever, something wrong is happening with partition avaliable

Also important
corrected in #93
@ah-
Also with this code (may be related but not sure), if i remove Task.Delay and set i to 10000 in Release, i almost always get a CallbackOnCollectedDelegate error, more specifically (in fr sorry):

Additional information: Un rappel a été effectué sur un délégué récupéré par le garbage collector de type 'RdKafka!RdKafka.Internal.LibRdKafka+PartitionerCallback::Invoke'.

even when i remove the top.PartitionAvailable and the interlocked (so only specify a partition at 0) but only when Console.WriteLine is here
So this may come from an error in the way rdkafka call rd_kafka_topic_conf_set_partitioner_cb, will look at this tomorow
If i set i to 100000, it's working. Same behabiour on net451 and netcore. It could also be a runtime error

@edenhill for info if you think it's something you already saw or if it's related to rdkafka-dotnet

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@edenhill @ah- @treziac @sinjimmyi