Rdkafka Failed to detect broker state

[adityanahan]

Steps:

1. Configure the kafka broker on my application . librdkafka run as a produce on this application . Broker ip is 12.12.12.12, my application ip is 12.12.12.120
2. Run the kafka broker on remote server.
3. At this point the rdkfaka detects the broker state and message go fine.
4. Now when I stop the zookeeper and kafka instance on the remote server, and add the instances back.
   I see following errors on the remote server
   [2015-08-08 16:07:37,217] INFO Closing socket connection to /12.12.12.12. (kafka.network.Processor)
   [2015-08-08 16:07:37,420] INFO Closing socket connection to /12.12.12.12. (kafka.network.Processor)
   [2015-08-08 16:07:37,624] INFO Closing socket connection to /12.12.12.12. (kafka.network.Processor)
   [2015-08-08 16:07:37,827] INFO Closing socket connection to /12.12.12.12. (kafka.network.Processor)
5. At this point the librdkfaka fails to detect somethign gone bad. And it still thinks the server is up.
   Logs on the rdkafka producer side

Breakpoint 3, rd_kafka_log0 (rk=0x6351c0, extra=0x635ab8 "12.12.12.12:9092/bootstrap", level=7, fac=0x427ad5 "METADATA", fmt=0x427cba "Request metadata for %s: %s") at rdkafka.c:141
141 int elen = 0;
(gdb) bt
#0 rd_kafka_log0 (rk=0x6351c0, extra=0x635ab8 "12.12.12.12:9092/bootstrap", level=7, fac=0x427ad5 "METADATA", fmt=0x427cba "Request metadata for %s: %s") at rdkafka.c:141
#1 0x000000000040fb3c in rd_kafka_broker_metadata_req_op (rkb=0x635620, rko=0x7fffe80008c0) at rdkafka_broker.c:1124
#2 0x0000000000413139 in rd_kafka_broker_op_serve (rkb=0x635620, rko=0x7fffe80008c0) at rdkafka_broker.c:2513
#3 0x0000000000413205 in rd_kafka_broker_io_serve (rkb=0x635620) at rdkafka_broker.c:2541
#4 0x000000000041337c in rd_kafka_broker_ua_idle (rkb=0x635620) at rdkafka_broker.c:2586
#5 0x000000000041961e in rd_kafka_broker_thread_main (arg=0x635620) at rdkafka_broker.c:4296
#6 0x00007ffff7bc79d1 in start_thread () from /lib64/libpthread.so.0
#7 0x00007ffff74f68fd in clone () from /lib64/libc.so.6

(gdb) f 1
#1 0x000000000040fb3c in rd_kafka_broker_metadata_req_op (rkb=0x635620, rko=0x7fffe80008c0) at rdkafka_broker.c:1124

1124 rd_rkb_dbg(rkb, METADATA, "METADATA",
(gdb) p rkb->rkb_s
$4 = 7
(gdb) p rkb->rkb_state
$5 = RD_KAFKA_BROKER_STATE_UP
(gdb) dis b
(gdb) c
Continuing.
1439043710.430 RDKAFKA-7-METADATA: rdkafka#producer-0: 12.12.12.12:9092/bootstrap: Request metadata for vCPE_Events: leader query
1439043710.430 RDKAFKA-7-METADATA: rdkafka#producer-0: 12.12.12.12:9092/bootstrap: Requesting metadata for known topics
1439043710.430 RDKAFKA-7-NOINFO: rdkafka#producer-0: Topic vCPE_Events metadata information timed out (65269ms old)
1439043710.430 RDKAFKA-7-STATE: rdkafka#producer-0: Topic vCPE_Events changed state exists -> unknown
1439043710.430 RDKAFKA-7-METADATA: rdkafka#producer-0: 12.12.12.12:9092/bootstrap: Request metadata for all topics: periodic refresh
1439043710.430 RDKAFKA-7-METADATA: rdkafka#producer-0: 12.12.12.12:9092/bootstrap: Request metadata: scheduled: not in broker thread
1439043710.430 RDKAFKA-7-SEND: rdkafka#producer-0: 12.12.12.12:9092/bootstrap: Sent MetadataRequest (38 bytes, CorrId 675)
1439043710.430 RDKAFKA-7-SEND: rdkafka#producer-0: 12.12.12.12:9092/bootstrap: Sent 1 bufs
1439043710.430 RDKAFKA-7-SEND: rdkafka#producer-0: 12.12.12.12:9092/bootstrap: Sent 0 bufs
1439043710.430 RDKAFKA-7-METADATA: rdkafka#producer-0: 12.12.12.12:9092/bootstrap: Request metadata for all topics: periodic refresh
1439043710.430 RDKAFKA-7-METADATA: rdkafka#producer-0: 12.12.12.12:9092/bootstrap: Requesting metadata for all topics
1439043710.430 RDKAFKA-7-SEND: rdkafka#producer-0: 12.12.12.12:9092/bootstrap: Sent MetadataRequest (25 bytes, CorrId 676)
1439043710.430 RDKAFKA-7-SEND: rdkafka#producer-0: 12.12.12.12:9092/bootstrap: Sent 1 bufs
1439043710.430 RDKAFKA-7-SEND: rdkafka#producer-0: 12.12.12.12:9092/bootstrap: Sent 0 bufs
1439043710.440 RDKAFKA-7-RECV: rdkafka#producer-0: 12.12.12.12:9092/bootstrap: Received MetadataResponse (27 bytes, CorrId 675, rtt 10.18ms)
1439043710.440 RDKAFKA-7-METADATA: rdkafka#producer-0: 12.12.12.12:9092/bootstrap: ===== Received metadata from 12.12.12.12:9092/bootstrap =====
1439043710.440 RDKAFKA-7-METADATA: rdkafka#producer-0: 12.12.12.12:9092/bootstrap: 0 brokers, 1 topics
1439043710.440 RDKAFKA-7-METADATA: rdkafka#producer-0: 12.12.12.12:9092/bootstrap: Topic #0/1: vCPE_Events with 0 partitions: Broker: Leader not available
1439043710.440 RDKAFKA-7-METADATA: rdkafka#producer-0: 12.12.12.12:9092/bootstrap: Error in metadata reply for topic vCPE_Events (PartCnt 0): Broker: Leader not available
1439043710.440 RDKAFKA-7-STATE: rdkafka#producer-0: Topic vCPE_Events changed state unknown -> exists
1439043710.440 RDKAFKA-7-PARTCNT: rdkafka#producer-0: No change in partition count for topic vCPE_Events
1439043710.440 RDKAFKA-7-METADATA: rdkafka#producer-0: 12.12.12.12:9092/bootstrap: Requested topic vCPE_Events seen in metadata
1439043710.448 RDKAFKA-7-RECV: rdkafka#producer-0: 12.12.12.12:9092/bootstrap: Received MetadataResponse (8 bytes, CorrId 676, rtt 18.15ms)

[adityanahan]

librdkafka version 0.8.5 (0x00080500)

[edenhill]

The broker is returning problematic metadata for topic vCPE_Events:

• it has 0 partitions
• and since it has no partitions it has no leader broker

I dont think this is a problem on the librdkafka side since the above information is directly from the broker.
You should check your broker and see why it thinks the topic has zero partitions.

[edenhill]

Reopen if you see this again.