Producer gets stuck in an infinite loop and never produces

[queil]

Description

On some boxes producer fails to produce messages and gets stuck in an infinite loop with the following message:

Debug|2018-08-23 13:06:23.288|KafkaProducerTest.exe#producer-1|TOPPAR| [thrd:192
.168.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/3: my.topicname [0] 1
 message(s) in xmit queue (0 added from partition queue)

Also afterwards I can see high CPU usage caused by librdkafka.

How to reproduce

EDIT: Even using a very basic example it hangs on Windows Server 2012.

It's rather tricky because it works fine on some boxes while does not on others. The code is very simple:

var producer = new Producer<Empty, SomeType>(settings, new ProtoSerializer<Empty>(), new ProtoSerializer<SomeType>());
await producer.ProduceAsync("my.topic", new Message<Empty, SomeType> {Value = new SomeType
            {
              PropertyX =...,
              PropertyY= ...
            }
            });

Checklist

Please provide the following information:

• Confluent.Kafka nuget version:1.0.0-experimental-4 (also 1.0.0-experimental-10)
• Apache Kafka version: 1.0.0
• Client configuration:

    {
	"batch.num.messages":1,
	"socket.nagle.disable":"true",
	"socket.blocking.max.ms":50,
	"queue.buffering.max.ms":1,
	"log.connection.close":"false",
	"group.id":"KafkaProducerTest.exe",
	"client.id":"KafkaProducerTest.exe",
	"enable.auto.commit":"false",
	"acks":1,
	"bootstrap.servers":"192.168.XXX.UUU:9092, 192.168.XXX.ZZZ:9092, 192.168.XXX.YYY:9092",
	"request.required.acks":1,
	"debug":"all"
}

• Operating system: clients: Windows Server 2012; brokers: Ubuntu 16.04
• Provide logs (with "debug" : "..." as necessary in configuration)

Debug|2018-08-23 13:06:16.200|KafkaProducerTest.exe#producer-1|STATE| [thrd:192.
168.XXX.UUU:9092/bootstrap]: 192.168.XXX.UUU:9092/bootstrap: Broker changed state
APIVERSION_QUERY -> UP
Debug|2018-08-23 13:06:16.200|KafkaProducerTest.exe#producer-1|BROADCAST| [thrd:
192.168.XXX.UUU:9092/bootstrap]: Broadcasting state change
Debug|2018-08-23 13:06:16.200|KafkaProducerTest.exe#producer-1|METADATA| [thrd:1
92.168.XXX.UUU:9092/bootstrap]: Skipping metadata refresh of 1 topic(s): connecte
d: already being requested
Debug|2018-08-23 13:06:16.197|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.ZZZ:9092/bootstrap: ClusterId: x2DnsDHoRUGMd2-kONsKeg, Control
lerId: 1
Debug|2018-08-23 13:06:16.201|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.ZZZ:9092/bootstrap: 3 brokers, 1 topics
Debug|2018-08-23 13:06:16.196|KafkaProducerTest.exe#producer-1|APIVERSION| [thrd
:192.168.XXX.YYY:9092/bootstrap]: 192.168.XXX.YYY:9092/bootstrap: Enabling feature
 SaslHandshake
Debug|2018-08-23 13:06:16.201|KafkaProducerTest.exe#producer-1|APIVERSION| [thrd
:192.168.XXX.YYY:9092/bootstrap]: 192.168.XXX.YYY:9092/bootstrap:  Feature LZ4: Gr
oupCoordinator (0..0) supported by broker
Debug|2018-08-23 13:06:16.201|KafkaProducerTest.exe#producer-1|APIVERSION| [thrd
:192.168.XXX.YYY:9092/bootstrap]: 192.168.XXX.YYY:9092/bootstrap: Enabling feature
 LZ4
Debug|2018-08-23 13:06:16.202|KafkaProducerTest.exe#producer-1|APIVERSION| [thrd
:192.168.XXX.YYY:9092/bootstrap]: 192.168.XXX.YYY:9092/bootstrap:  Feature OffsetT
ime: Offset (1..1) supported by broker
Debug|2018-08-23 13:06:16.202|KafkaProducerTest.exe#producer-1|APIVERSION| [thrd
:192.168.XXX.YYY:9092/bootstrap]: 192.168.XXX.YYY:9092/bootstrap: Enabling feature
 OffsetTime
Debug|2018-08-23 13:06:16.202|KafkaProducerTest.exe#producer-1|APIVERSION| [thrd
:192.168.XXX.YYY:9092/bootstrap]: 192.168.XXX.YYY:9092/bootstrap:  Feature : Creat
eTopics (0..0) supported by broker
Debug|2018-08-23 13:06:16.202|KafkaProducerTest.exe#producer-1|APIVERSION| [thrd
:192.168.XXX.YYY:9092/bootstrap]: 192.168.XXX.YYY:9092/bootstrap:  Feature : Delet
eTopics (0..0) supported by broker
Debug|2018-08-23 13:06:16.203|KafkaProducerTest.exe#producer-1|APIVERSION| [thrd
:192.168.XXX.YYY:9092/bootstrap]: 192.168.XXX.YYY:9092/bootstrap: Enabling feature

Debug|2018-08-23 13:06:16.203|KafkaProducerTest.exe#producer-1|FEATURE| [thrd:19
2.168.XXX.YYY:9092/bootstrap]: 192.168.XXX.YYY:9092/bootstrap: Updated enabled pro
tocol features to MsgVer1,ApiVersion,BrokerBalancedConsumer,ThrottleTime,Sasl,Sa
slHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2
Debug|2018-08-23 13:06:16.203|KafkaProducerTest.exe#producer-1|STATE| [thrd:192.
168.XXX.YYY:9092/bootstrap]: 192.168.XXX.YYY:9092/bootstrap: Broker changed state
APIVERSION_QUERY -> UP
Debug|2018-08-23 13:06:16.203|KafkaProducerTest.exe#producer-1|BROADCAST| [thrd:
192.168.XXX.YYY:9092/bootstrap]: Broadcasting state change
Debug|2018-08-23 13:06:16.203|KafkaProducerTest.exe#producer-1|METADATA| [thrd:1
92.168.XXX.YYY:9092/bootstrap]: Skipping metadata refresh of 1 topic(s): connecte
d: already being requested
Debug|2018-08-23 13:06:16.201|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.ZZZ:9092/bootstrap:   Broker #0/3: 192.168.XXX.UUU:9092 NodeId
2
Debug|2018-08-23 13:06:16.204|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.ZZZ:9092/bootstrap:   Broker #1/3: 192.168.XXX.YYY:9092 NodeId
1
Debug|2018-08-23 13:06:16.204|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.ZZZ:9092/bootstrap:   Broker #2/3: 192.168.XXX.ZZZ:9092 NodeId
 3
Debug|2018-08-23 13:06:16.205|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.ZZZ:9092/bootstrap:   Topic #0/1: my.topicname with 1
partitions
Debug|2018-08-23 13:06:16.205|KafkaProducerTest.exe#producer-1|STATE| [thrd:main
]: Topic my.topicname changed state unknown -> exists
Debug|2018-08-23 13:06:16.205|KafkaProducerTest.exe#producer-1|PARTCNT| [thrd:ma
in]: Topic my.topicname partition count changed from 0 to 1
Debug|2018-08-23 13:06:16.205|KafkaProducerTest.exe#producer-1|TOPPARNEW| [thrd:
main]: NEW my.topicname [0] 00000062A60D3580 (at rd_kafka_topic_partitio
n_cnt_update:587)
Debug|2018-08-23 13:06:16.206|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]:   Topic my.topicname partition 0 Leader 3
Debug|2018-08-23 13:06:16.206|KafkaProducerTest.exe#producer-1|BRKDELGT| [thrd:m
ain]: my.topicname [0]: delegate to broker (none) (rktp 00000062A60D3580
, term 0, ref 2, remove 0)
Debug|2018-08-23 13:06:16.206|KafkaProducerTest.exe#producer-1|BRKDELGT| [thrd:m
ain]: my.topicname [0]: broker :0/internal is now leader for partition w
ith 0 messages (0 bytes) queued
Debug|2018-08-23 13:06:16.206|KafkaProducerTest.exe#producer-1|BRKMIGR| [thrd:ma
in]: Migrating topic my.topicname [0] 00000062A60D3580 from (none) to :0
/internal (sending PARTITION_JOIN to :0/internal)
Debug|2018-08-23 13:06:16.206|KafkaProducerTest.exe#producer-1|PARTCNT| [thrd:ma
in]: Partitioning 1 unassigned messages in topic my.topicname to 1 parti
tions
Debug|2018-08-23 13:06:16.206|KafkaProducerTest.exe#producer-1|TOPBRK| [thrd::0/
internal]: :0/internal: Topic my.topicname [0]: joining broker (rktp 000
00062A60D3580)
Debug|2018-08-23 13:06:16.207|KafkaProducerTest.exe#producer-1|FETCHADD| [thrd::
0/internal]: :0/internal: Added my.topicname [0] to active list (1 entri
es, opv 0)
Debug|2018-08-23 13:06:16.207|KafkaProducerTest.exe#producer-1|BROADCAST| [thrd:
:0/internal]: Broadcasting state change
Debug|2018-08-23 13:06:16.207|KafkaProducerTest.exe#producer-1|UAS| [thrd:main]:
 1/1 messages were partitioned in topic my.topicname
Debug|2018-08-23 13:06:16.208|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.ZZZ:9092/bootstrap: 1/1 requested topic(s) seen in metadata
Debug|2018-08-23 13:06:16.208|KafkaProducerTest.exe#producer-1|CLUSTERID| [thrd:
main]: 192.168.XXX.ZZZ:9092/bootstrap: ClusterId update "" -> "x2DnsDHoRUGMd2-kO
NsKeg"
Debug|2018-08-23 13:06:16.209|KafkaProducerTest.exe#producer-1|CONTROLLERID| [th
rd:main]: 192.168.XXX.ZZZ:9092/bootstrap: ControllerId update -1 -> 1
Debug|2018-08-23 13:06:16.209|KafkaProducerTest.exe#producer-1|BROADCAST| [thrd:
main]: Broadcasting state change
Debug|2018-08-23 13:06:17.125|KafkaProducerTest.exe#producer-1|QRYLEADER| [thrd:
main]: Topic my.topicname [0]: leader is internal: re-query
Debug|2018-08-23 13:06:17.125|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: Requesting metadata for 1/1 topics: refresh unavailable topics
Debug|2018-08-23 13:06:17.126|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.ZZZ:9092/bootstrap: Request metadata for 1 topic(s): refresh u
navailable topics
Debug|2018-08-23 13:06:17.203|KafkaProducerTest.exe#producer-1|UPDATE| [thrd:192
.168.XXX.YYY:9092/bootstrap]: 192.168.XXX.YYY:9092/bootstrap: NodeId changed from
-1 to 1
Debug|2018-08-23 13:06:17.203|KafkaProducerTest.exe#producer-1|UPDATE| [thrd:192
.168.XXX.YYY:9092/bootstrap]: 192.168.XXX.YYY:9092/1: Name changed from 192.168.12
8.73:9092/bootstrap to 192.168.XXX.YYY:9092/1
Debug|2018-08-23 13:06:17.203|KafkaProducerTest.exe#producer-1|LEADER| [thrd:192
.168.XXX.YYY:9092/bootstrap]: 192.168.XXX.YYY:9092/1: Mapped 0 partition(s) to bro
ker
Debug|2018-08-23 13:06:17.203|KafkaProducerTest.exe#producer-1|STATE| [thrd:192.
168.XXX.YYY:9092/bootstrap]: 192.168.XXX.YYY:9092/1: Broker changed state UP -> UP
DATE
Debug|2018-08-23 13:06:17.204|KafkaProducerTest.exe#producer-1|BROADCAST| [thrd:
192.168.XXX.YYY:9092/bootstrap]: Broadcasting state change
Debug|2018-08-23 13:06:17.204|KafkaProducerTest.exe#producer-1|STATE| [thrd:192.
168.XXX.YYY:9092/bootstrap]: 192.168.XXX.YYY:9092/1: Broker changed state UPDATE -
> UP
Debug|2018-08-23 13:06:17.204|KafkaProducerTest.exe#producer-1|BROADCAST| [thrd:
192.168.XXX.YYY:9092/bootstrap]: Broadcasting state change
Debug|2018-08-23 13:06:17.290|KafkaProducerTest.exe#producer-1|UPDATE| [thrd:192
.168.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/bootstrap: NodeId changed fro
m -1 to 3
Debug|2018-08-23 13:06:17.290|KafkaProducerTest.exe#producer-1|UPDATE| [thrd:192
.168.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/3: Name changed from 192.168.
XXX.ZZZ:9092/bootstrap to 192.168.XXX.ZZZ:9092/3
Debug|2018-08-23 13:06:17.290|KafkaProducerTest.exe#producer-1|TOPICUPD| [thrd:1
92.168.XXX.ZZZ:9092/bootstrap]: Topic my.topicname [0] migrated from bro
ker -1 to 3
Debug|2018-08-23 13:06:17.290|KafkaProducerTest.exe#producer-1|BRKDELGT| [thrd:1
92.168.XXX.ZZZ:9092/bootstrap]: my.topicname [0]: delegate to broker 192
.168.XXX.ZZZ:9092/3 (rktp 00000062A60D3580, term 0, ref 2, remove 0)
Debug|2018-08-23 13:06:17.291|KafkaProducerTest.exe#producer-1|BRKDELGT| [thrd:1
92.168.XXX.ZZZ:9092/bootstrap]: my.topicname [0]: broker :0/internal no
longer leader
Debug|2018-08-23 13:06:17.291|KafkaProducerTest.exe#producer-1|BRKDELGT| [thrd:1
92.168.XXX.ZZZ:9092/bootstrap]: my.topicname [0]: broker 192.168.XXX.ZZZ
:9092/3 is now leader for partition with 1 messages (74 bytes) queued
Debug|2018-08-23 13:06:17.291|KafkaProducerTest.exe#producer-1|BRKMIGR| [thrd:19
2.168.XXX.ZZZ:9092/bootstrap]: Migrating topic my.topicname [0] 00000062
A60D3580 from :0/internal to 192.168.XXX.ZZZ:9092/3 (sending PARTITION_LEAVE to
:0/internal)
Debug|2018-08-23 13:06:17.291|KafkaProducerTest.exe#producer-1|LEADER| [thrd:192
.168.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/3: Mapped 1 partition(s) to b
roker
Debug|2018-08-23 13:06:17.291|KafkaProducerTest.exe#producer-1|STATE| [thrd:192.
168.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/3: Broker changed state UP ->
UPDATE
Debug|2018-08-23 13:06:17.292|KafkaProducerTest.exe#producer-1|BROADCAST| [thrd:
192.168.XXX.ZZZ:9092/bootstrap]: Broadcasting state change
Debug|2018-08-23 13:06:17.292|KafkaProducerTest.exe#producer-1|SEND| [thrd:192.1
68.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/3: Sent MetadataRequest (v2, 61
 bytes @ 0, CorrId 3)
Debug|2018-08-23 13:06:17.292|KafkaProducerTest.exe#producer-1|STATE| [thrd:192.
168.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/3: Broker changed state UPDATE
 -> UP
Debug|2018-08-23 13:06:17.292|KafkaProducerTest.exe#producer-1|BROADCAST| [thrd:
192.168.XXX.ZZZ:9092/bootstrap]: Broadcasting state change
Debug|2018-08-23 13:06:17.292|KafkaProducerTest.exe#producer-1|RECV| [thrd:192.1
68.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/3: Received MetadataResponse (v
2, 186 bytes, CorrId 3, rtt 0.60ms)
Debug|2018-08-23 13:06:17.293|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.ZZZ:9092/3: ===== Received metadata (for 1 requested topics):
refresh unavailable topics =====
Debug|2018-08-23 13:06:17.293|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.ZZZ:9092/3: ClusterId: x2DnsDHoRUGMd2-kONsKeg, ControllerId: 1

Debug|2018-08-23 13:06:17.293|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.ZZZ:9092/3: 3 brokers, 1 topics
Debug|2018-08-23 13:06:17.293|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.ZZZ:9092/3:   Broker #0/3: 192.168.XXX.UUU:9092 NodeId 2
Debug|2018-08-23 13:06:17.291|KafkaProducerTest.exe#producer-1|TOPBRK| [thrd::0/
internal]: :0/internal: Topic my.topicname [0]: leaving broker (0 messag
es in xmitq, next leader 192.168.XXX.ZZZ:9092/3, rktp 00000062A60D3580)
Debug|2018-08-23 13:06:17.294|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.ZZZ:9092/3:   Broker #1/3: 192.168.XXX.YYY:9092 NodeId 1
Debug|2018-08-23 13:06:17.294|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.ZZZ:9092/3:   Broker #2/3: 192.168.XXX.ZZZ:9092 NodeId 3
Debug|2018-08-23 13:06:17.294|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.ZZZ:9092/3:   Topic #0/1: my.topicname with 1 partitio
ns
Debug|2018-08-23 13:06:17.294|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]:   Topic my.topicname partition 0 Leader 3
Debug|2018-08-23 13:06:17.294|KafkaProducerTest.exe#producer-1|FETCHADD| [thrd::
0/internal]: :0/internal: Removed my.topicname [0] from active list (0 e
ntries, opv 0)
Debug|2018-08-23 13:06:17.295|KafkaProducerTest.exe#producer-1|BROADCAST| [thrd:
:0/internal]: Broadcasting state change
Debug|2018-08-23 13:06:17.295|KafkaProducerTest.exe#producer-1|BRKDELGT| [thrd:m
ain]: my.topicname [0]: delegate to broker 192.168.XXX.ZZZ:9092/3 (rktp
00000062A60D3580, term 0, ref 3, remove 0)
Debug|2018-08-23 13:06:17.295|KafkaProducerTest.exe#producer-1|BRKDELGT| [thrd:m
ain]: my.topicname [0]: broker 192.168.XXX.ZZZ:9092/3 is now leader for
partition with 1 messages (74 bytes) queued
Debug|2018-08-23 13:06:17.296|KafkaProducerTest.exe#producer-1|PARTCNT| [thrd:ma
in]: Partitioning 0 unassigned messages in topic my.topicname to 1 parti
tions
Debug|2018-08-23 13:06:17.296|KafkaProducerTest.exe#producer-1|UAS| [thrd:main]:
 0/0 messages were partitioned in topic my.topicname
Debug|2018-08-23 13:06:17.296|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.ZZZ:9092/3: 1/1 requested topic(s) seen in metadata
Debug|2018-08-23 13:06:17.302|KafkaProducerTest.exe#producer-1|UPDATE| [thrd:192
.168.XXX.UUU:9092/bootstrap]: 192.168.XXX.UUU:9092/bootstrap: NodeId changed from
-1 to 2
Debug|2018-08-23 13:06:17.302|KafkaProducerTest.exe#producer-1|UPDATE| [thrd:192
.168.XXX.UUU:9092/bootstrap]: 192.168.XXX.UUU:9092/2: Name changed from 192.168.12
8.72:9092/bootstrap to 192.168.XXX.UUU:9092/2
Debug|2018-08-23 13:06:17.302|KafkaProducerTest.exe#producer-1|LEADER| [thrd:192
.168.XXX.UUU:9092/bootstrap]: 192.168.XXX.UUU:9092/2: Mapped 0 partition(s) to bro
ker
Debug|2018-08-23 13:06:17.302|KafkaProducerTest.exe#producer-1|STATE| [thrd:192.
168.XXX.UUU:9092/bootstrap]: 192.168.XXX.UUU:9092/2: Broker changed state UP -> UP
DATE
Debug|2018-08-23 13:06:17.302|KafkaProducerTest.exe#producer-1|BROADCAST| [thrd:
192.168.XXX.UUU:9092/bootstrap]: Broadcasting state change
Debug|2018-08-23 13:06:17.303|KafkaProducerTest.exe#producer-1|STATE| [thrd:192.
168.XXX.UUU:9092/bootstrap]: 192.168.XXX.UUU:9092/2: Broker changed state UPDATE -
> UP
Debug|2018-08-23 13:06:17.303|KafkaProducerTest.exe#producer-1|BROADCAST| [thrd:
192.168.XXX.UUU:9092/bootstrap]: Broadcasting state change
Debug|2018-08-23 13:06:18.127|KafkaProducerTest.exe#producer-1|QRYLEADER| [thrd:
main]: Topic my.topicname [0]: leader is unavailable: re-query
Debug|2018-08-23 13:06:18.127|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: Requesting metadata for 1/1 topics: refresh unavailable topics
Debug|2018-08-23 13:06:18.127|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.UUU:9092/2: Request metadata for 1 topic(s): refresh unavailabl
e topics
Debug|2018-08-23 13:06:18.292|KafkaProducerTest.exe#producer-1|TOPBRK| [thrd:192
.168.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/3: Topic my.topicname
 [0]: joining broker (rktp 00000062A60D3580)
Debug|2018-08-23 13:06:18.292|KafkaProducerTest.exe#producer-1|FETCHADD| [thrd:1
92.168.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/3: Added atech.depositreque
st [0] to active list (1 entries, opv 0)
Debug|2018-08-23 13:06:18.292|KafkaProducerTest.exe#producer-1|BROADCAST| [thrd:
192.168.XXX.ZZZ:9092/bootstrap]: Broadcasting state change
Debug|2018-08-23 13:06:18.302|KafkaProducerTest.exe#producer-1|SEND| [thrd:192.1
68.XXX.UUU:9092/bootstrap]: 192.168.XXX.UUU:9092/2: Sent MetadataRequest (v2, 61 b
ytes @ 0, CorrId 2)
Debug|2018-08-23 13:06:18.302|KafkaProducerTest.exe#producer-1|RECV| [thrd:192.1
68.XXX.UUU:9092/bootstrap]: 192.168.XXX.UUU:9092/2: Received MetadataResponse (v2,
 186 bytes, CorrId 2, rtt 0.37ms)
Debug|2018-08-23 13:06:18.302|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.UUU:9092/2: ===== Received metadata (for 1 requested topics): r
efresh unavailable topics =====
Debug|2018-08-23 13:06:18.303|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.UUU:9092/2: ClusterId: x2DnsDHoRUGMd2-kONsKeg, ControllerId: 1
Debug|2018-08-23 13:06:18.303|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.UUU:9092/2: 3 brokers, 1 topics
Debug|2018-08-23 13:06:18.303|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.UUU:9092/2:   Broker #0/3: 192.168.XXX.UUU:9092 NodeId 2
Debug|2018-08-23 13:06:18.303|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.UUU:9092/2:   Broker #1/3: 192.168.XXX.YYY:9092 NodeId 1
Debug|2018-08-23 13:06:18.303|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.UUU:9092/2:   Broker #2/3: 192.168.XXX.ZZZ:9092 NodeId 3
Debug|2018-08-23 13:06:18.303|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.UUU:9092/2:   Topic #0/1: my.topicname with 1 partition
s
Debug|2018-08-23 13:06:18.304|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]:   Topic my.topicname partition 0 Leader 3
Debug|2018-08-23 13:06:18.304|KafkaProducerTest.exe#producer-1|METADATA| [thrd:m
ain]: 192.168.XXX.UUU:9092/2: 1/1 requested topic(s) seen in metadata
Debug|2018-08-23 13:06:19.291|KafkaProducerTest.exe#producer-1|TOPPAR| [thrd:192
.168.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/3: my.topicname [0] 1
 message(s) in xmit queue (1 added from partition queue)
Debug|2018-08-23 13:06:20.290|KafkaProducerTest.exe#producer-1|TOPPAR| [thrd:192
.168.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/3: my.topicname [0] 1
 message(s) in xmit queue (0 added from partition queue)
Debug|2018-08-23 13:06:21.290|KafkaProducerTest.exe#producer-1|TOPPAR| [thrd:192
.168.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/3: my.topicname [0] 1
 message(s) in xmit queue (0 added from partition queue)
Debug|2018-08-23 13:06:22.289|KafkaProducerTest.exe#producer-1|TOPPAR| [thrd:192
.168.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/3: my.topicname [0] 1
 message(s) in xmit queue (0 added from partition queue)
Debug|2018-08-23 13:06:23.288|KafkaProducerTest.exe#producer-1|TOPPAR| [thrd:192
.168.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/3: my.topicname [0] 1
 message(s) in xmit queue (0 added from partition queue)
Debug|2018-08-23 13:06:24.287|KafkaProducerTest.exe#producer-1|TOPPAR| [thrd:192
.168.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/3: my.topicname [0] 1
 message(s) in xmit queue (0 added from partition queue)
Debug|2018-08-23 13:06:25.286|KafkaProducerTest.exe#producer-1|TOPPAR| [thrd:192
.168.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/3: my.topicname [0] 1
 message(s) in xmit queue (0 added from partition queue)
Debug|2018-08-23 13:06:26.286|KafkaProducerTest.exe#producer-1|TOPPAR| [thrd:192
.168.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/3: my.topicname [0] 1
 message(s) in xmit queue (0 added from partition queue)
Debug|2018-08-23 13:06:27.285|KafkaProducerTest.exe#producer-1|TOPPAR| [thrd:192
.168.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/3: my.topicname [0] 1
 message(s) in xmit queue (0 added from partition queue)
Debug|2018-08-23 13:06:28.284|KafkaProducerTest.exe#producer-1|TOPPAR| [thrd:192
.168.XXX.ZZZ:9092/bootstrap]: 192.168.XXX.ZZZ:9092/3: my.topicname [0] 1
 message(s) in xmit queue (0 added from partition queue)
^C

• [] Provide broker log excerpts
  Can provide if needed.
• [] Critical issue

Not that much critical but it's a production issue.

[mhowlett]

please try 1.0-experimental-10. In particular, #545 has been resolved since 1.0-experimental-4.

[mhowlett]

[labeled as question as I believe this is most likely an issue that's been resolved in a later build]

[queil]

@mhowlett Cool, I will try it tomorrow.

[queil]

@mhowlett I've got some bad news. I've just tested it with 1.0-experimental-10 and the issue is still there.

[edenhill]

Could you try to reproduce when commenting out the following config properties?:

	"batch.num.messages":1,
	"socket.nagle.disable":"true",
	"socket.blocking.max.ms":50,
	"queue.buffering.max.ms":1,
	"log.connection.close":"false",

Also note that the following properties are for the consumer and are ignored for the producer:

	"group.id":"KafkaProducerTest.exe",
	"enable.auto.commit":"false",

[queil]

@edenhill no success. However, I've noticed that the code (without your proposed config changes) works on Windows Server 2016 but it does not on Windows Server 2012 (regardless with or without the proposed config changes). The consumer config is OK as I've got both producer and consumer in my test app. Thanks for a very prompt response.

[edenhill]

Do any of the producer examples here work?

[queil]

@edenhill Let me try.

[queil]

@edenhill I've just tried this one. It hangs too.

[queil]

@edenhill @mhowlett Ok, my initial hypothesis about the issue being OS related fails. I have found a Windows Server 2012 machine where it works just fine. I am very confused now.

[queil]

@edenhill For some reason rd_clock() is returning negative values on some of my boxes. It looks like it's due to an overflow when reading QueryPerformanceCounter values. After rebooting the offending box it started working (QueryPerformanceCounter got reset). I've put the following code in rd_kafka_broker_producer_serve just after now is set:

rd_rkb_dbg(rkb, QUEUE, "CLOCK", "now %"PRId64"", now);

Output from a working box:

Debug|2018-08-29 14:54:25.898|rdkafka#producer-1|CLOCK| [thrd:zzz.zzz.zzz.zzz:9092/bootstrap]: zzz.zzz.zzz.zzz:9092/3:

 now 14951693103

Output from not working box:

Debug|2018-08-29 14:53:49.300|rdkafka#producer-1|CLOCK| [thrd:xxx.xxx.xxx.xxx:9092/bootstrap]: xxx.xxx.xxx.xxx:9092/2: 

now -102503745224

EDIT: QueryPerformanceCounter values from a non-working box:

Before reboot:
QueryPerformanceCounter: 219923348897693
QueryPerformanceFrequency: 14318180

After reboot:
QueryPerformanceCounter: 10132389946
QueryPerformanceFrequency: 14318180

[ecparra]

This issue is also apparent in 0.11.5 but not in 0.11.4 and below. Rebooting the machine did resolve the problem but not sure if I should continue to use 0.11.5.

[queil]

@edenhill @mhowlett @ecparra I believe the issue is in the following piece of code from rdtime.h:

static RD_INLINE rd_ts_t rd_clock (void) {
//some other code

        return (now.QuadPart * 1000000) / freq.QuadPart;

//some other code
}

QuadPart is a long long so the max value for that is 9223372036854775807 which means the max value before it overflows on the multiplication by 1000000 can be 9223372036854. With a freq of 14318180 (that was on my failing box) it corresponds to slightly more than 7 days:

//counter value / counter freq / seconds in an hour / hours in a day
9223372036854 / 14318180 / 3600 / 24 = about 7.45 days

In 0.11.4 it was implemented using return (rd_ts_t)GetTickCount64() * 1000LLU; that's why it wouldn't have that bug. Does this make sense?

EDIT: Could we just change the order of the calculation to: (now.QuadPart / freq.QuadPart) * 1000000 ; ignore it. According to Microsoft this does not make sense:
// // We now have the elapsed number of ticks, along with the // number of ticks-per-second. We use these values // to convert to the number of elapsed microseconds. // To guard against loss-of-precision, we convert // to microseconds *before* dividing by ticks-per-second. //

[edenhill]

@queil Great analysis! Will look into it, thank you!