confluentinc / librdkafka

The Apache Kafka C/C++ library

Other

206 stars 3.14k forks source link

librdkafka producer uses 100% of the CPU when a bad MTU is configured on server side #3254

Closed ghost closed 3 years ago

ghost commented 3 years ago

Description

After un upgrade of our broker infrastructure, the MTU configuration of the server has been misconfigured. Following that, all our producers fail to connect to the broker and one of the librdkafka threads is using 100% CPU.

Checklist

Please provide the following information:

[x] librdkafka version (release number or git tag): v1.6.0
[ ] Apache Kafka version: ``
[x] librdkafka client configuration: enable.idempotence=true, message.max.bytes=1000000, queue.buffering.max.kbytes=2000, queue.buffering.max.ms=500, message.timeout.ms=3600000, compression.codec=gzip, compression.level=3, debug=all
[x] Operating system: Linux 4.9
[x] Provide logs (with debug=.. as necessary) from librdkafka
[ ] Provide broker log excerpts
[ ] Critical issue

Logs

We can see that at 1612336823, we're entering an infinite loop of always the same sequence.

%7|1612336819.221|OPENSSL|rdkafka#producer-1| [thrd:app]: Using OpenSSL version OpenSSL 1.1.1i 8 Dec 2020 (0x1010109f, librdkafka built with 0x1010109f) %7|1612336819.228|SSL|rdkafka#producer-1| [thrd:app]: Loading CA certificate(s) from directory /etc/ssl/certs %7|1612336819.228|SSL|rdkafka#producer-1| [thrd:app]: Loading public key from file /etc/ssl/private/seb_custom.crt %7|1612336819.228|SSL|rdkafka#producer-1| [thrd:app]: Loading private key file from /etc/ssl/private/seb_custom.key %7|1612336819.228|WAKEUPFD|rdkafka#producer-1| [thrd:app]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Enabled low-latency ops queue wake-ups %7|1612336819.228|BROKER|rdkafka#producer-1| [thrd:app]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Added new broker with NodeId -1 %7|1612336819.228|CONNECT|rdkafka#producer-1| [thrd:app]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Selected for cluster connection: bootstrap servers added (broker has 0 connection attempt(s)) %7|1612336819.228|BRKMAIN|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Enter main broker thread %7|1612336819.228|CONNECT|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Received CONNECT op %7|1612336819.228|STATE|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Broker changed state INIT -> TRY_CONNECT %7|1612336819.228|BROADCAST|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: Broadcasting state change %7|1612336819.228|CONNECT|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: broker in state TRY_CONNECT connecting %7|1612336819.228|STATE|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Broker changed state TRY_CONNECT -> CONNECT %7|1612336819.228|BROADCAST|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: Broadcasting state change %7|1612336819.229|FAIL|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Failed to resolve 'iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443': Temporary failure in name resolution (after 0ms in state CONNECT) (_RESOLVE) %3|1612336819.229|FAIL|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Failed to resolve 'iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443': Temporary failure in name resolution (after 0ms in state CONNECT) %7|1612336819.229|STATE|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Broker changed state CONNECT -> DOWN %7|1612336819.229|BROADCAST|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: Broadcasting state change %7|1612336819.229|BUFQ|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Purging bufq with 0 buffers %7|1612336819.229|BUFQ|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Purging bufq with 0 buffers %7|1612336819.229|BUFQ|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Updating 0 buffers on connection reset %7|1612336819.229|BRKMAIN|rdkafka#producer-1| [thrd::0/internal]: :0/internal: Enter main broker thread %7|1612336819.229|IDEMPSTATE|rdkafka#producer-1| [thrd:main]: Idempotent producer state change Init -> RequestPID %7|1612336819.229|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Starting idempotent producer %7|1612336819.229|INIT|rdkafka#producer-1| [thrd:app]: librdkafka v1.6.0 (0x10600ff) rdkafka#producer-1 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_plain,sasl_scram,plugins,sasl_oauthbearer, CC CXX PKGCONFIG INSTALL GNULD LDS LIBDL PLUGINS ZLIB SSL HDRHISTOGRAM SYSLOG SNAPPY SOCKEM SASL_SCRAM SASL_OAUTHBEARER CRC32C_HW, debug 0xfffff) %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: Client configuration: %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: client.software.version = 1.6.0 %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: metadata.broker.list = iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443 %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: message.max.bytes = 1000000 %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: debug = generic,broker,topic,metadata,feature,queue,msg,protocol,cgrp,security,fetch,interceptor,plugin,consumer,admin,eos,mock,assignor,conf,all %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: error_cb = 0x4112f8 %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: getaddrinfo_cb = 0x41175c %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: socket_cb = 0x4118b2 %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: default_topic_conf = 0x62cc60 %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: security.protocol = ssl %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: ssl.key.location = [redacted] %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: ssl.certificate.location = /etc/ssl/private/seb_custom.crt %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: ssl.ca.location = /etc/ssl/certs %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: ssl.endpoint.identification.algorithm = https %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: enable.idempotence = true %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: queue.buffering.max.kbytes = 2000 %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: queue.buffering.max.ms = 500 %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: compression.codec = gzip %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: dr_msg_cb = 0x411248 %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: Default topic configuration: %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: message.timeout.ms = 3600000 %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: compression.level = 3 %7|1612336819.229|TOPIC|rdkafka#producer-1| [thrd:app]: New local topic: domain.sdn.2dplatform.supervision %7|1612336819.229|TOPPARNEW|rdkafka#producer-1| [thrd:app]: NEW domain.sdn.2dplatform.supervision [-1] 0x663520 refcnt 0x6635b0 (at rd_kafka_topic_new0:465) %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: Topic "domain.sdn.2dplatform.supervision" configuration (default_topic_conf): %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: message.timeout.ms = 3600000 %7|1612336819.229|CONF|rdkafka#producer-1| [thrd:app]: compression.level = 3 %7|1612336819.229|CONNECT|rdkafka#producer-1| [thrd:app]: Not selecting any broker for cluster connection: still suppressed for 48ms: leader query %7|1612336819.229|METADATA|rdkafka#producer-1| [thrd:app]: Hinted cache of 1/1 topic(s) being queried %7|1612336819.229|METADATA|rdkafka#producer-1| [thrd:app]: Skipping metadata refresh of 1 topic(s): leader query: no usable brokers %7|1612336819.729|IDEMPSTATE|rdkafka#producer-1| [thrd:main]: Idempotent producer state change RequestPID -> WaitTransport %7|1612336819.729|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612336819.729|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612336819.729|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612336820.229|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision metadata information unknown %7|1612336820.229|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision partition count is zero: should refresh metadata %7|1612336820.229|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: refresh unavailable topics %7|1612336820.229|METADATA|rdkafka#producer-1| [thrd:main]: Hinted cache of 1/1 topic(s) being queried %7|1612336820.229|METADATA|rdkafka#producer-1| [thrd:main]: Skipping metadata refresh of 1 topic(s): refresh unavailable topics: no usable brokers %7|1612336820.229|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection %7|1612336820.229|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: acquire ProducerID %7|1612336820.229|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612336820.229|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612336820.229|STATE|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Broker changed state DOWN -> INIT %7|1612336820.229|BROADCAST|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: Broadcasting state change %7|1612336820.729|CONNECT|rdkafka#producer-1| [thrd:main]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Selected for cluster connection: acquire ProducerID (broker has 1 connection attempt(s)) %7|1612336820.729|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612336820.729|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612336820.729|CONNECT|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Received CONNECT op %7|1612336820.729|STATE|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Broker changed state INIT -> TRY_CONNECT %7|1612336820.729|BROADCAST|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: Broadcasting state change %7|1612336820.729|CONNECT|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: broker in state TRY_CONNECT connecting %7|1612336820.729|STATE|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Broker changed state TRY_CONNECT -> CONNECT %7|1612336820.729|BROADCAST|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: Broadcasting state change %7|1612336820.730|FAIL|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Failed to resolve 'iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443': Temporary failure in name resolution (after 0ms in state CONNECT, 1 identical error(s) suppressed) (_RESOLVE): identical to last error %3|1612336820.730|FAIL|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Failed to resolve 'iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443': Temporary failure in name resolution (after 0ms in state CONNECT, 1 identical error(s) suppressed) %7|1612336820.730|STATE|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Broker changed state CONNECT -> DOWN %7|1612336820.730|BROADCAST|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: Broadcasting state change %7|1612336820.730|BUFQ|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Purging bufq with 0 buffers %7|1612336820.730|BUFQ|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Purging bufq with 0 buffers %7|1612336820.730|BUFQ|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Updating 0 buffers on connection reset %7|1612336821.229|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision partition count is zero: should refresh metadata %7|1612336821.229|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: refresh unavailable topics %7|1612336821.229|METADATA|rdkafka#producer-1| [thrd:main]: Hinted cache of 1/1 topic(s) being queried %7|1612336821.229|METADATA|rdkafka#producer-1| [thrd:main]: Skipping metadata refresh of 1 topic(s): refresh unavailable topics: no usable brokers %7|1612336821.229|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection %7|1612336821.229|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: acquire ProducerID %7|1612336821.229|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612336821.229|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612336821.729|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612336821.729|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612336821.729|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612336821.730|STATE|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Broker changed state DOWN -> INIT %7|1612336821.730|BROADCAST|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: Broadcasting state change %7|1612336822.229|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision metadata information unknown %7|1612336822.229|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision partition count is zero: should refresh metadata %7|1612336822.229|CONNECT|rdkafka#producer-1| [thrd:main]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Selected for cluster connection: refresh unavailable topics (broker has 2 connection attempt(s)) %7|1612336822.229|METADATA|rdkafka#producer-1| [thrd:main]: Hinted cache of 1/1 topic(s) being queried %7|1612336822.229|METADATA|rdkafka#producer-1| [thrd:main]: Skipping metadata refresh of 1 topic(s): refresh unavailable topics: no usable brokers %7|1612336822.229|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection %7|1612336822.229|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: acquire ProducerID %7|1612336822.229|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612336822.229|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612336822.229|CONNECT|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Received CONNECT op %7|1612336822.230|STATE|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Broker changed state INIT -> TRY_CONNECT %7|1612336822.230|BROADCAST|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: Broadcasting state change %7|1612336822.230|CONNECT|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: broker in state TRY_CONNECT connecting %7|1612336822.230|STATE|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Broker changed state TRY_CONNECT -> CONNECT %7|1612336822.230|BROADCAST|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: Broadcasting state change %7|1612336822.314|CONNECT|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Connecting to ipv4#51.103.83.25:443 (ssl) with socket 19 %7|1612336822.362|CONNECT|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Connected to ipv4#51.103.83.25:443 %7|1612336822.362|ENDPOINT|rdkafka#producer-1| [thrd:ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/boot]: ssl://iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com:443/bootstrap: Enabled endpoint identification using hostname iv-sdwan-broker-acc-fc1-02-01.infovistacloud.com %7|1612336822.729|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612336822.730|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612336822.730|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up

%7|1612336823.229|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision metadata information unknown %7|1612336823.229|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision partition count is zero: should refresh metadata %7|1612336823.230|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: refresh unavailable topics %7|1612336823.230|METADATA|rdkafka#producer-1| [thrd:main]: Hinted cache of 1/1 topic(s) being queried %7|1612336823.230|METADATA|rdkafka#producer-1| [thrd:main]: Skipping metadata refresh of 1 topic(s): refresh unavailable topics: no usable brokers %7|1612336823.230|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection %7|1612336823.230|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: acquire ProducerID %7|1612336823.230|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612336823.230|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612336823.730|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612336823.730|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612336823.730|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up

%7|1612336824.230|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision metadata information unknown %7|1612336824.230|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision partition count is zero: should refresh metadata %7|1612336824.230|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: refresh unavailable topics %7|1612336824.230|METADATA|rdkafka#producer-1| [thrd:main]: Hinted cache of 1/1 topic(s) being queried %7|1612336824.230|METADATA|rdkafka#producer-1| [thrd:main]: Skipping metadata refresh of 1 topic(s): refresh unavailable topics: no usable brokers %7|1612336824.230|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection %7|1612336824.230|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: acquire ProducerID %7|1612336824.230|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612336824.230|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612336824.730|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612336824.730|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612336824.730|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up

%7|1612336825.231|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision metadata information unknown %7|1612336825.231|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision partition count is zero: should refresh metadata %7|1612336825.231|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: refresh unavailable topics %7|1612336825.231|METADATA|rdkafka#producer-1| [thrd:main]: Hinted cache of 1/1 topic(s) being queried %7|1612336825.231|METADATA|rdkafka#producer-1| [thrd:main]: Skipping metadata refresh of 1 topic(s): refresh unavailable topics: no usable brokers %7|1612336825.231|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection %7|1612336825.231|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: acquire ProducerID %7|1612336825.231|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612336825.231|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612336825.731|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612336825.731|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612336825.731|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up

%7|1612336826.233|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision metadata information unknown %7|1612336826.233|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision partition count is zero: should refresh metadata %7|1612336826.233|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: refresh unavailable topics %7|1612336826.233|METADATA|rdkafka#producer-1| [thrd:main]: Hinted cache of 1/1 topic(s) being queried %7|1612336826.233|METADATA|rdkafka#producer-1| [thrd:main]: Skipping metadata refresh of 1 topic(s): refresh unavailable topics: no usable brokers %7|1612336826.233|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection %7|1612336826.233|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: acquire ProducerID %7|1612336826.233|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612336826.233|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612336826.733|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612336826.733|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612336826.733|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up

%7|1612336827.234|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision metadata information unknown %7|1612336827.234|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision partition count is zero: should refresh metadata %7|1612336827.234|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: refresh unavailable topics %7|1612336827.234|METADATA|rdkafka#producer-1| [thrd:main]: Hinted cache of 1/1 topic(s) being queried %7|1612336827.234|METADATA|rdkafka#producer-1| [thrd:main]: Skipping metadata refresh of 1 topic(s): refresh unavailable topics: no usable brokers %7|1612336827.234|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection %7|1612336827.234|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: acquire ProducerID %7|1612336827.234|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612336827.234|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612336827.734|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612336827.734|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612336827.734|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up

...

%7|1612340219.755|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision metadata information unknown %7|1612340219.755|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision partition count is zero: should refresh metadata %7|1612340219.755|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: refresh unavailable topics %7|1612340219.755|METADATA|rdkafka#producer-1| [thrd:main]: Hinted cache of 1/1 topic(s) being queried %7|1612340219.755|METADATA|rdkafka#producer-1| [thrd:main]: Skipping metadata refresh of 1 topic(s): refresh unavailable topics: no usable brokers %7|1612340219.755|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection %7|1612340220.061|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340220.061|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340220.061|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612340220.561|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340220.561|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340220.561|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up

%7|1612340220.755|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision metadata information unknown %7|1612340220.755|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision partition count is zero: should refresh metadata %7|1612340220.755|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: refresh unavailable topics %7|1612340220.755|METADATA|rdkafka#producer-1| [thrd:main]: Hinted cache of 1/1 topic(s) being queried %7|1612340220.755|METADATA|rdkafka#producer-1| [thrd:main]: Skipping metadata refresh of 1 topic(s): refresh unavailable topics: no usable brokers %7|1612340220.755|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection %7|1612340221.062|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340221.062|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340221.062|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612340221.562|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340221.562|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340221.562|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up

%7|1612340221.755|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision metadata information unknown %7|1612340221.755|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision partition count is zero: should refresh metadata %7|1612340221.755|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: refresh unavailable topics %7|1612340221.755|METADATA|rdkafka#producer-1| [thrd:main]: Hinted cache of 1/1 topic(s) being queried %7|1612340221.755|METADATA|rdkafka#producer-1| [thrd:main]: Skipping metadata refresh of 1 topic(s): refresh unavailable topics: no usable brokers %7|1612340221.755|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection %7|1612340222.062|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340222.062|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340222.062|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612340222.562|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340222.562|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340222.562|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up

%7|1612340222.757|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision metadata information unknown %7|1612340222.757|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision partition count is zero: should refresh metadata %7|1612340222.757|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: refresh unavailable topics %7|1612340222.757|METADATA|rdkafka#producer-1| [thrd:main]: Hinted cache of 1/1 topic(s) being queried %7|1612340222.757|METADATA|rdkafka#producer-1| [thrd:main]: Skipping metadata refresh of 1 topic(s): refresh unavailable topics: no usable brokers %7|1612340222.757|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection %7|1612340223.063|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340223.063|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340223.063|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612340223.565|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340223.565|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340223.565|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up

%7|1612340223.757|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision metadata information unknown %7|1612340223.757|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision partition count is zero: should refresh metadata %7|1612340223.757|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: refresh unavailable topics %7|1612340223.757|METADATA|rdkafka#producer-1| [thrd:main]: Hinted cache of 1/1 topic(s) being queried %7|1612340223.757|METADATA|rdkafka#producer-1| [thrd:main]: Skipping metadata refresh of 1 topic(s): refresh unavailable topics: no usable brokers %7|1612340223.757|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection %7|1612340224.065|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340224.065|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340224.065|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612340224.565|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340224.566|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340224.566|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up

%7|1612340224.757|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision metadata information unknown %7|1612340224.757|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision partition count is zero: should refresh metadata %7|1612340224.757|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: refresh unavailable topics %7|1612340224.757|METADATA|rdkafka#producer-1| [thrd:main]: Hinted cache of 1/1 topic(s) being queried %7|1612340224.757|METADATA|rdkafka#producer-1| [thrd:main]: Skipping metadata refresh of 1 topic(s): refresh unavailable topics: no usable brokers %7|1612340224.757|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection %7|1612340225.067|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340225.067|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340225.067|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612340225.567|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340225.567|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340225.567|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up

%7|1612340225.757|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision metadata information unknown %7|1612340225.757|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision partition count is zero: should refresh metadata %7|1612340225.757|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: refresh unavailable topics %7|1612340225.757|METADATA|rdkafka#producer-1| [thrd:main]: Hinted cache of 1/1 topic(s) being queried %7|1612340225.757|METADATA|rdkafka#producer-1| [thrd:main]: Skipping metadata refresh of 1 topic(s): refresh unavailable topics: no usable brokers %7|1612340225.757|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection %7|1612340226.068|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340226.068|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340226.068|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612340226.568|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340226.568|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340226.568|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up

%7|1612340226.758|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision metadata information unknown %7|1612340226.758|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision partition count is zero: should refresh metadata %7|1612340226.758|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: refresh unavailable topics %7|1612340226.758|METADATA|rdkafka#producer-1| [thrd:main]: Hinted cache of 1/1 topic(s) being queried %7|1612340226.758|METADATA|rdkafka#producer-1| [thrd:main]: Skipping metadata refresh of 1 topic(s): refresh unavailable topics: no usable brokers %7|1612340226.758|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection %7|1612340227.069|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340227.069|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340227.069|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612340227.569|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340227.569|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340227.569|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up

%7|1612340227.759|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision metadata information unknown %7|1612340227.759|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision partition count is zero: should refresh metadata %7|1612340227.759|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: refresh unavailable topics %7|1612340227.759|METADATA|rdkafka#producer-1| [thrd:main]: Hinted cache of 1/1 topic(s) being queried %7|1612340227.759|METADATA|rdkafka#producer-1| [thrd:main]: Skipping metadata refresh of 1 topic(s): refresh unavailable topics: no usable brokers %7|1612340227.759|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection %7|1612340228.070|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340228.070|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340228.070|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612340228.570|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340228.570|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340228.570|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up

%7|1612340228.759|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision metadata information unknown %7|1612340228.759|NOINFO|rdkafka#producer-1| [thrd:main]: Topic domain.sdn.2dplatform.supervision partition count is zero: should refresh metadata %7|1612340228.759|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: refresh unavailable topics %7|1612340228.759|METADATA|rdkafka#producer-1| [thrd:main]: Hinted cache of 1/1 topic(s) being queried %7|1612340228.759|METADATA|rdkafka#producer-1| [thrd:main]: Skipping metadata refresh of 1 topic(s): refresh unavailable topics: no usable brokers %7|1612340228.759|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection %7|1612340229.071|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340229.071|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340229.071|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up %7|1612340229.573|CONNECT|rdkafka#producer-1| [thrd:main]: Cluster connection already in progress: acquire ProducerID %7|1612340229.573|PIDBROKER|rdkafka#producer-1| [thrd:main]: No brokers available for Idempotent producer (1 broker(s) known) %7|1612340229.573|TXN|rdkafka#producer-1| [thrd:main]: Starting PID FSM timer: Coordinator not up

edenhill commented 3 years ago

The retry loop is expected and does not happen frequently enough (every 200ms it seems) to explain 100% CPU usage. Would need a profiling run to see where the CPU is spent.

ghost commented 3 years ago

Here is a profiling from the perf top -p <pid> command:

PerfTop:    3496 irqs/sec  kernel:57.3%  exact:  0.0% [4000Hz cycles],  (target_pid: 20749)

   26.41%  [kernel]            [k] do_syscall_64
     4.93%  libpthread-2.24.so  [.] __pthread_rwlock_unlock
     4.60%  [kernel]            [k] entry_SYSCALL_64
     3.88%  [kernel]            [k] do_sys_poll
     3.30%  [vdso]              [.] 0x0000000000000981
     3.20%  [kernel]            [k] pvclock_clocksource_read
     2.24%  libcrypto.so.1.1    [.] ERR_clear_error
     1.81%  libpthread-2.24.so  [.] pthread_mutex_lock
     1.77%  [kernel]            [k] tcp_poll
     1.67%  [kernel]            [k] __fget
     1.63%  libpthread-2.24.so  [.] __pthread_mutex_unlock_usercnt
     1.54%  [vdso]              [.] __vdso_clock_gettime
     1.37%  [kernel]            [k] select_estimate_accuracy.part.2
     1.32%  [kernel]            [k] _raw_spin_unlock_irqrestore
     1.28%  libpthread-2.24.so  [.] __pthread_rwlock_rdlock
     1.23%  libssl.so.1.1       [.] state_machine
     1.10%  libpthread-2.24.so  [.] __GI___libc_read
     0.96%  [kernel]            [k] ktime_get_ts64

I'm not sure it's helpful so do not hesitate to provide me with more specific commands if necessary.

edenhill commented 3 years ago

Thanks but it doesn't really explain where the time is spent. Could you try to run it with callgrind? valgrind --tool=callgrind ./theprogram ...

Or build librdkafka with profiling; ./configure --enable-profiling --disable-optimization

ghost commented 3 years ago

Hello,

Here is the result of callgrind. The corresponding ps command looks like:

  PID   LWP %CPU     TIME S CMD
30918 30918  2.0 00:00:01 S valgrind --tool=callgrind /libexec/netdata/plugins.d/sdwan_sup.plugin 30 --quit-after-sec=330
30918 30919  0.0 00:00:00 S valgrind --tool=callgrind /libexec/netdata/plugins.d/sdwan_sup.plugin 30 --quit-after-sec=330
30918 30920  0.0 00:00:00 S valgrind --tool=callgrind /libexec/netdata/plugins.d/sdwan_sup.plugin 30 --quit-after-sec=330
30918 30921  0.0 00:00:00 S valgrind --tool=callgrind /libexec/netdata/plugins.d/sdwan_sup.plugin 30 --quit-after-sec=330
30918 30922  0.0 00:00:00 S valgrind --tool=callgrind /libexec/netdata/plugins.d/sdwan_sup.plugin 30 --quit-after-sec=330
30918 30923  0.2 00:00:00 S valgrind --tool=callgrind /libexec/netdata/plugins.d/sdwan_sup.plugin 30 --quit-after-sec=330
30918 30924  0.0 00:00:00 S valgrind --tool=callgrind /libexec/netdata/plugins.d/sdwan_sup.plugin 30 --quit-after-sec=330
30918 30925 97.8 00:01:13 R valgrind --tool=callgrind /libexec/netdata/plugins.d/sdwan_sup.plugin 30 --quit-after-sec=330

We can see one thread using almost all the CPU.

Hope it helps.

callgrind.out.30918.gz

edenhill commented 3 years ago

Thank you.

Seems like the IO/socket events are firing constantly, which is not a whole lot we can do much about seeing how this is a faulty setup.

edenhill commented 3 years ago

I believe this was fixed in #3363