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.

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

transactional producer hangs on commit (internal flush) leading to "No PID available (idempotence state WaitPID)" #3041

Closed
7 tasks done
sanjay24 opened this issue Aug 21, 2020 · 6 comments

Comments

@sanjay24
Copy link
Contributor

Description

  • Issue occurred on a 3 node kafka cluster
  • Application hangs forever while committing a transaction. This leads to a message/transaction time out (in my case both are set to 10 mins). My brokers have a default connection idle timeout, which is also 10.
  • After 10 mins of inactivity, broker drops the connection and transaction also times out.
  • Producer retries to initialize its PID, but gets the following error
    Producer attempted to update a transaction while another concurrent operation on the same transaction was ongoing
  • Producer raises a non-abortable/non-fatal error
    Aborting with uncaught exception: abort transaction failed error=No PID available

How to reproduce

It's quite random, I couldn't reproduce this issue on demand

Checklist

IMPORTANT: We will close issues where the checklist has not been completed.

Please provide the following information:

  • librdkafka version (release number or git tag): v0.10.5
  • Apache Kafka version: 2.1.3
  • librdkafka client configuration: linger.ms=50 batch.num.messages=10000 compression.codec=snappy batch.num.messages=100000 message.timeout.ms=600000 transaction.timeout.ms=600000 retry.backoff.ms=500 enable.idempotence=true queue.buffering.max.messages=10000000 queue.buffering.max.kbytes=1048576 debug=eos,broker,msg,topic
  • Operating system: Centos 7.6
  • Provide logs (with debug=eos,broker,msg,topic as necessary) from librdkafka
  • Provide broker log excerpts: nothing exceptional on broker logs
  • Critical issue
@sanjay24
Copy link
Contributor Author

librdkafka logs

19:33:43.969444069 [Debug ] [RDK] [anonymous] [7] [WAKEUPFD] [thrd:main]: TxnCoordinator: Enabled low-latency ops queue wake-ups
19:33:43.969437206 [Debug ] [RDK] [anonymous] [7] [BRKMAIN] [thrd::0/internal]: :0/internal: Enter main broker thread
19:33:43.970171223 [Debug ] [RDK] [anonymous] [7] [BROKER] [thrd:main]: TxnCoordinator: Added new broker with NodeId -1
19:33:43.970205799 [Debug ] [RDK] [main] [7] [WAKEUPFD] [thrd:app]: kafka-test-cluster:9092/bootstrap: Enabled low-latency ops queue wake-ups
19:33:43.970329765 [Debug ] [RDK] [main] [7] [BROKER] [thrd:app]: kafka-test-cluster:9092/bootstrap: Added new broker with NodeId -1
19:33:43.970332390 [Debug ] [RDK] [main] [7] [CONNECT] [thrd:app]: kafka-test-cluster:9092/bootstrap: Selected for cluster connection: bootstrap servers added (broker has 0 connection attempt(s))
19:33:43.970341888 [Debug ] [RDK] [main] [7] [INIT] [thrd:app]: librdkafka v1.5.0 (0x10500ff) rdkafka#producer-3 initialized (builtin.features gzip,snappy,sasl,regex,lz4,sasl_plain,plugins, GCC GXX PKGCONFIG INSTALL GNULD LDS LIBDL PLUGINS ZLIB HDRHISTOGRAM SYSLOG SNAPPY SOCKEM CRC32C_HW, debug 0xfffff)
19:33:43.970420107 [Debug ] [RDK] [main] [7] [TXNAPI] [thrd:app]: Transactional API called: init_transactions
19:33:43.970439805 [Debug ] [RDK] [anonymous] [7] [TXNSTATE] [thrd:main]: Transaction state change Init -> WaitPID
19:33:43.970448101 [Debug ] [RDK] [anonymous] [7] [IDEMPSTATE] [thrd:main]: Idempotent producer state change Init -> RequestPID
19:33:43.970450335 [Debug ] [RDK] [anonymous] [7] [TXN] [thrd:main]: Starting PID FSM timer (fire immediately): Starting idempotent producer
19:33:43.970222561 [Debug ] [RDK] [anonymous] [7] [BRKMAIN] [thrd:TxnCoordinator]: TxnCoordinator: Enter main broker thread
19:33:43.970830830 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:TxnCoordinator]: TxnCoordinator: Broker changed state INIT -> TRY_CONNECT
19:33:43.970832042 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:TxnCoordinator]: Broadcasting state change
19:33:43.970833856 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:TxnCoordinator]: TxnCoordinator: broker in state TRY_CONNECT connecting
19:33:43.970834487 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:TxnCoordinator]: TxnCoordinator: broker has no address yet: postponing connect
19:33:43.971455520 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 48ms: acquire ProducerID
19:33:43.971456882 [Debug ] [RDK] [anonymous] [7] [PIDBROKER] [thrd:main]: No brokers available for Transactions (2 broker(s) known)
19:33:43.971457474 [Debug ] [RDK] [anonymous] [7] [TXNCOORD] [thrd:main]: Unable to query for transaction coordinator: No brokers available for Transactions (2 broker(s) known)
19:33:43.970343041 [Debug ] [RDK] [anonymous] [7] [BRKMAIN] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Enter main broker thread
19:33:43.971997652 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Received CONNECT op
19:33:43.971998614 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Broker changed state INIT -> TRY_CONNECT
19:33:43.971999366 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:kafka-test-cluster:9092/bootstrap]: Broadcasting state change
19:33:43.972001229 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: broker in state TRY_CONNECT connecting
19:33:43.972001900 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Broker changed state TRY_CONNECT -> CONNECT
19:33:43.972002241 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:kafka-test-cluster:9092/bootstrap]: Broadcasting state change
19:33:43.972714137 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Connecting to ipv4#10.76.128.121:9092 (plaintext) with socket 42
19:33:43.972909770 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Connected to ipv4#10.76.128.121:9092
19:33:43.972912004 [Debug ] [RDK] [anonymous] [7] [CONNECTED] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Connected (#1)
19:33:43.972918186 [Debug ] [RDK] [anonymous] [7] [FEATURE] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Updated enabled protocol features +ApiVersion to ApiVersion
19:33:43.972919067 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Broker changed state CONNECT -> APIVERSION_QUERY
19:33:43.972919769 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:kafka-test-cluster:9092/bootstrap]: Broadcasting state change
19:33:43.972943303 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Sent ApiVersionRequest (v3, 40 bytes @ 0, CorrId 1)
19:33:43.973193380 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Received ApiVersionResponse (v3, 6 bytes, CorrId 1, rtt 0.25ms)
19:33:43.973195444 [Debug ] [RDK] [anonymous] [7] [PROTOERR] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Protocol parse failure for ApiVersion v3 at 3/6 (rd_kafka_handle_ApiVersion:1945) (incorrect broker.version.fallback?)
19:33:43.973196245 [Debug ] [RDK] [anonymous] [7] [PROTOERR] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: ApiArrayCnt -1 out of range
19:33:43.973199451 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: ApiVersionRequest v3 failed due to UNSUPPORTED_VERSION: retrying with v0
19:33:43.973210983 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Sent ApiVersionRequest (v0, 21 bytes @ 0, CorrId 2)
19:33:43.973375056 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Received ApiVersionResponse (v0, 264 bytes, CorrId 2, rtt 0.16ms)
19:33:43.973375968 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Broker API support:
19:33:43.973378623 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey Produce (0) Versions 0..7
19:33:43.973379504 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey Fetch (1) Versions 0..10
19:33:43.973380266 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey Offset (2) Versions 0..4
19:33:43.973381017 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey Metadata (3) Versions 0..7
19:33:43.973381769 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey LeaderAndIsr (4) Versions 0..1
19:33:43.973382530 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey StopReplica (5) Versions 0..0
19:33:43.973383281 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey UpdateMetadata (6) Versions 0..4
19:33:43.973384043 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey ControlledShutdown (7) Versions 0..1
19:33:43.973384784 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey OffsetCommit (8) Versions 0..6
19:33:43.973385516 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey OffsetFetch (9) Versions 0..5
19:33:43.973386297 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey FindCoordinator (10) Versions 0..2
19:33:43.973387049 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey JoinGroup (11) Versions 0..3
19:33:43.973387770 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey Heartbeat (12) Versions 0..2
19:33:43.973388542 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey LeaveGroup (13) Versions 0..2
19:33:43.973389263 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey SyncGroup (14) Versions 0..2
19:33:43.973390004 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey DescribeGroups (15) Versions 0..2
19:33:43.973390726 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey ListGroups (16) Versions 0..2
19:33:43.973391477 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey SaslHandshake (17) Versions 0..1
19:33:43.973392219 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey ApiVersion (18) Versions 0..2
19:33:43.973392950 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey CreateTopics (19) Versions 0..3
19:33:43.973393671 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey DeleteTopics (20) Versions 0..3
19:33:43.973394383 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey DeleteRecords (21) Versions 0..1
19:33:43.973395114 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey InitProducerId (22) Versions 0..1
19:33:43.973395875 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey OffsetForLeaderEpoch (23) Versions 0..2
19:33:43.973396627 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey AddPartitionsToTxn (24) Versions 0..1
19:33:43.973397368 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey AddOffsetsToTxn (25) Versions 0..1
19:33:43.973398100 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey EndTxn (26) Versions 0..1
19:33:43.973398861 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey WriteTxnMarkers (27) Versions 0..0
19:33:43.973399583 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey TxnOffsetCommit (28) Versions 0..2
19:33:43.973400314 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey DescribeAcls (29) Versions 0..1
19:33:43.973401035 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey CreateAcls (30) Versions 0..1
19:33:43.973401767 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey DeleteAcls (31) Versions 0..1
19:33:43.973402488 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey DescribeConfigs (32) Versions 0..2
19:33:43.973403219 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey AlterConfigs (33) Versions 0..1
19:33:43.973403971 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey AlterReplicaLogDirs (34) Versions 0..1
19:33:43.973404702 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey DescribeLogDirs (35) Versions 0..1
19:33:43.973405464 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey SaslAuthenticate (36) Versions 0..0
19:33:43.973406195 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey CreatePartitions (37) Versions 0..1
19:33:43.973406977 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey CreateDelegationToken (38) Versions 0..1
19:33:43.973407728 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey RenewDelegationToken (39) Versions 0..1
19:33:43.973408479 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey ExpireDelegationToken (40) Versions 0..1
19:33:43.973409241 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey DescribeDelegationToken (41) Versions 0..1
19:33:43.973409982 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:   ApiKey DeleteGroups (42) Versions 0..1
19:33:43.973415192 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature MsgVer1: Produce (2..2) supported by broker
19:33:43.973416224 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature MsgVer1: Fetch (2..2) supported by broker
19:33:43.973416996 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Enabling feature MsgVer1
19:33:43.973417927 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature MsgVer2: Produce (3..3) supported by broker
19:33:43.973418799 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature MsgVer2: Fetch (4..4) supported by broker
19:33:43.973419490 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Enabling feature MsgVer2
19:33:43.973420512 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature ApiVersion: ApiVersion (0..0) supported by broker
19:33:43.973421204 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Enabling feature ApiVersion
19:33:43.973422236 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature BrokerGroupCoordinator: FindCoordinator (0..0) supported by broker
19:33:43.973422957 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Enabling feature BrokerGroupCoordinator
19:33:43.973423859 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature BrokerBalancedConsumer: FindCoordinator (0..0) supported by broker
19:33:43.973424851 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature BrokerBalancedConsumer: OffsetCommit (1..2) supported by broker
19:33:43.973425802 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature BrokerBalancedConsumer: OffsetFetch (1..1) supported by broker
19:33:43.973426774 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature BrokerBalancedConsumer: JoinGroup (0..0) supported by broker
19:33:43.973427666 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature BrokerBalancedConsumer: SyncGroup (0..0) supported by broker
19:33:43.973428558 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature BrokerBalancedConsumer: Heartbeat (0..0) supported by broker
19:33:43.973429449 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature BrokerBalancedConsumer: LeaveGroup (0..0) supported by broker
19:33:43.973430161 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Enabling feature BrokerBalancedConsumer
19:33:43.973431153 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature ThrottleTime: Produce (1..2) supported by broker
19:33:43.973432054 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature ThrottleTime: Fetch (1..2) supported by broker
19:33:43.973432816 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Enabling feature ThrottleTime
19:33:43.973433768 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature Sasl: JoinGroup (0..0) supported by broker
19:33:43.973434489 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Enabling feature Sasl
19:33:43.973435531 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature SaslHandshake: SaslHandshake (0..0) supported by broker
19:33:43.973436302 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Enabling feature SaslHandshake
19:33:43.973437224 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature LZ4: FindCoordinator (0..0) supported by broker
19:33:43.973437936 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Enabling feature LZ4
19:33:43.973438897 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature OffsetTime: Offset (1..1) supported by broker
19:33:43.973439599 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Enabling feature OffsetTime
19:33:43.973440751 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature IdempotentProducer: InitProducerId (0..0) supported by broker
19:33:43.973441492 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Enabling feature IdempotentProducer
19:33:43.973442434 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature ZSTD: Produce (7..7) supported by broker
19:33:43.973443326 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature ZSTD: Fetch (10..10) supported by broker
19:33:43.973444007 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Enabling feature ZSTD
19:33:43.973444969 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature SaslAuthReq: SaslHandshake (1..1) supported by broker
19:33:43.973446211 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap:  Feature SaslAuthReq: SaslAuthenticate (0..0) supported by broker
19:33:43.973478593 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Enabling feature SaslAuthReq
19:33:43.973481709 [Debug ] [RDK] [anonymous] [7] [FEATURE] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Updated enabled protocol features to MsgVer1,ApiVersion,BrokerBalancedConsumer,ThrottleTime,Sasl,SaslHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2,IdempotentProducer,ZSTD,SaslAuthReq
19:33:43.973482420 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Broker changed state APIVERSION_QUERY -> UP
19:33:43.973491638 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:kafka-test-cluster:9092/bootstrap]: Broadcasting state change
19:33:43.973493351 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Request metadata for brokers only: connected
19:33:43.973503841 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Sent MetadataRequest (v4, 26 bytes @ 0, CorrId 3)
19:33:43.973781901 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Received MetadataResponse (v4, 112 bytes, CorrId 3, rtt 0.27ms)
19:33:43.973787481 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: kafka-test-cluster:9092/bootstrap: ===== Received metadata: connected =====
19:33:43.973799544 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: kafka-test-cluster:9092/bootstrap: ClusterId: Uz_c76ACSsmTXoZ8R2CI_w, ControllerId: 3
19:33:43.973800366 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: kafka-test-cluster:9092/bootstrap: 3 brokers, 0 topics
19:33:43.973801308 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: kafka-test-cluster:9092/bootstrap:   Broker #0/3: host_002:9092 NodeId 2
19:33:43.973831515 [Debug ] [RDK] [anonymous] [7] [WAKEUPFD] [thrd:main]: host_002:9092/2: Enabled low-latency ops queue wake-ups
19:33:43.973863536 [Debug ] [RDK] [anonymous] [7] [BROKER] [thrd:main]: host_002:9092/2: Added new broker with NodeId 2
19:33:43.973864819 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: kafka-test-cluster:9092/bootstrap:   Broker #1/3: host_003:9092 NodeId 3
19:33:43.973912269 [Debug ] [RDK] [anonymous] [7] [WAKEUPFD] [thrd:main]: host_003:9092/3: Enabled low-latency ops queue wake-ups
19:33:43.973978295 [Debug ] [RDK] [anonymous] [7] [BROKER] [thrd:main]: host_003:9092/3: Added new broker with NodeId 3
19:33:43.973980038 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: kafka-test-cluster:9092/bootstrap:   Broker #2/3: host_001:9092 NodeId 1
19:33:43.974118241 [Debug ] [RDK] [anonymous] [7] [WAKEUPFD] [thrd:main]: host_001:9092/1: Enabled low-latency ops queue wake-ups
19:33:43.974198193 [Debug ] [RDK] [anonymous] [7] [BROKER] [thrd:main]: host_001:9092/1: Added new broker with NodeId 1
19:33:43.974199837 [Debug ] [RDK] [anonymous] [7] [CLUSTERID] [thrd:main]: kafka-test-cluster:9092/bootstrap: ClusterId update "" -> "Uz_c76ACSsmTXoZ8R2CI_w"
19:33:43.974200718 [Debug ] [RDK] [anonymous] [7] [CONTROLLERID] [thrd:main]: kafka-test-cluster:9092/bootstrap: ControllerId update -1 -> 3
19:33:43.974201179 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:main]: Broadcasting state change
19:33:43.974230094 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Sent FindCoordinatorRequest (v2, 45 bytes @ 0, CorrId 4)
19:33:43.974563529 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Received FindCoordinatorResponse (v2, 30 bytes, CorrId 4, rtt 0.33ms)
19:33:43.974571434 [Debug ] [RDK] [anonymous] [7] [TXNCOORD] [thrd:main]: kafka-test-cluster:9092/bootstrap: FindCoordinator response: Transaction coordinator is broker 3 (host_003:9092)
19:33:43.974573428 [Debug ] [RDK] [anonymous] [7] [TXNCOORD] [thrd:main]: Transaction coordinator changed from (none) -> host_003:9092/3: FindCoordinator response
19:33:43.974574660 [Debug ] [RDK] [anonymous] [7] [NODENAME] [thrd:main]: TxnCoordinator: Broker nodename changed from "" to "host_003:9092"
19:33:43.974580552 [Debug ] [RDK] [anonymous] [7] [IDEMPSTATE] [thrd:main]: Idempotent producer state change RequestPID -> WaitTransport
19:33:43.974581574 [Debug ] [RDK] [anonymous] [7] [TXN] [thrd:main]: Starting PID FSM timer: No broker available
19:33:43.974605459 [Debug ] [RDK] [anonymous] [7] [FAIL] [thrd:TxnCoordinator]: TxnCoordinator/3: Closing connection due to nodename change (after 3ms in state TRY_CONNECT) (_TRANSPORT)
19:33:43.974607042 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:TxnCoordinator]: TxnCoordinator: Broker changed state TRY_CONNECT -> DOWN
19:33:43.974607984 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:TxnCoordinator]: Broadcasting state change
19:33:43.974611881 [Debug ] [RDK] [anonymous] [7] [BUFQ] [thrd:TxnCoordinator]: TxnCoordinator/3: Purging bufq with 0 buffers
19:33:43.974612623 [Debug ] [RDK] [anonymous] [7] [BUFQ] [thrd:TxnCoordinator]: TxnCoordinator/3: Purging bufq with 0 buffers
19:33:43.974613424 [Debug ] [RDK] [anonymous] [7] [BUFQ] [thrd:TxnCoordinator]: TxnCoordinator/3: Updating 0 buffers on connection reset
19:33:43.974615468 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:TxnCoordinator]: TxnCoordinator: Broker changed state DOWN -> INIT
19:33:43.974616029 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:TxnCoordinator]: Broadcasting state change
19:33:43.974616951 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:TxnCoordinator]: TxnCoordinator: Broker changed state INIT -> TRY_CONNECT
19:33:43.974617512 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:TxnCoordinator]: Broadcasting state change
19:33:43.974618354 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:TxnCoordinator]: TxnCoordinator/3: broker in state TRY_CONNECT connecting
19:33:43.974619325 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:TxnCoordinator]: TxnCoordinator: Broker changed state TRY_CONNECT -> CONNECT
19:33:43.974619636 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:TxnCoordinator]: Broadcasting state change
19:33:43.973877002 [Debug ] [RDK] [anonymous] [7] [BRKMAIN] [thrd:host_002:9092/2]: host_002:9092/2: Enter main broker thread
19:33:43.974230345 [Debug ] [RDK] [anonymous] [7] [BRKMAIN] [thrd:host_001:9092/1]: host_001:9092/1: Enter main broker thread
19:33:43.975215501 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:TxnCoordinator]: TxnCoordinator/3: Connecting to ipv4#10.76.128.235:9092 (plaintext) with socket 49
19:33:43.974000056 [Debug ] [RDK] [anonymous] [7] [BRKMAIN] [thrd:host_003:9092/3]: host_003:9092/3: Enter main broker thread
19:33:43.975453655 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:TxnCoordinator]: TxnCoordinator/3: Connected to ipv4#10.76.128.235:9092
19:33:43.975455568 [Debug ] [RDK] [anonymous] [7] [CONNECTED] [thrd:TxnCoordinator]: TxnCoordinator/3: Connected (#1)
19:33:43.975463243 [Debug ] [RDK] [anonymous] [7] [FEATURE] [thrd:TxnCoordinator]: TxnCoordinator/3: Updated enabled protocol features +ApiVersion to ApiVersion
19:33:43.975464014 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:TxnCoordinator]: TxnCoordinator: Broker changed state CONNECT -> APIVERSION_QUERY
19:33:43.975464595 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:TxnCoordinator]: Broadcasting state change
19:33:43.975491066 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:TxnCoordinator]: TxnCoordinator/3: Sent ApiVersionRequest (v3, 40 bytes @ 0, CorrId 1)
19:33:43.975987501 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:TxnCoordinator]: TxnCoordinator/3: Received ApiVersionResponse (v3, 6 bytes, CorrId 1, rtt 0.49ms)
19:33:43.975991649 [Debug ] [RDK] [anonymous] [7] [PROTOERR] [thrd:TxnCoordinator]: TxnCoordinator/3: Protocol parse failure for ApiVersion v3 at 3/6 (rd_kafka_handle_ApiVersion:1945) (incorrect broker.version.fallback?)
19:33:43.975993042 [Debug ] [RDK] [anonymous] [7] [PROTOERR] [thrd:TxnCoordinator]: TxnCoordinator/3: ApiArrayCnt -1 out of range
19:33:43.975994735 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: ApiVersionRequest v3 failed due to UNSUPPORTED_VERSION: retrying with v0
19:33:43.976016056 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:TxnCoordinator]: TxnCoordinator/3: Sent ApiVersionRequest (v0, 21 bytes @ 0, CorrId 2)
19:33:43.976198724 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:TxnCoordinator]: TxnCoordinator/3: Received ApiVersionResponse (v0, 264 bytes, CorrId 2, rtt 0.18ms)
19:33:43.976199926 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Broker API support:
19:33:43.976201840 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey Produce (0) Versions 0..7
19:33:43.976202892 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey Fetch (1) Versions 0..10
19:33:43.976203763 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey Offset (2) Versions 0..4
19:33:43.976204475 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey Metadata (3) Versions 0..7
19:33:43.976205306 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey LeaderAndIsr (4) Versions 0..1
19:33:43.976206048 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey StopReplica (5) Versions 0..0
19:33:43.976206769 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey UpdateMetadata (6) Versions 0..4
19:33:43.976207481 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey ControlledShutdown (7) Versions 0..1
19:33:43.976208172 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey OffsetCommit (8) Versions 0..6
19:33:43.976208843 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey OffsetFetch (9) Versions 0..5
19:33:43.976209595 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey FindCoordinator (10) Versions 0..2
19:33:43.976210326 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey JoinGroup (11) Versions 0..3
19:33:43.976210997 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey Heartbeat (12) Versions 0..2
19:33:43.976211709 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey LeaveGroup (13) Versions 0..2
19:33:43.976212380 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey SyncGroup (14) Versions 0..2
19:33:43.976213061 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey DescribeGroups (15) Versions 0..2
19:33:43.976213762 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey ListGroups (16) Versions 0..2
19:33:43.976214484 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey SaslHandshake (17) Versions 0..1
19:33:43.976215155 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey ApiVersion (18) Versions 0..2
19:33:43.976215846 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey CreateTopics (19) Versions 0..3
19:33:43.976216518 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey DeleteTopics (20) Versions 0..3
19:33:43.976217179 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey DeleteRecords (21) Versions 0..1
19:33:43.976217860 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey InitProducerId (22) Versions 0..1
19:33:43.976218592 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey OffsetForLeaderEpoch (23) Versions 0..2
19:33:43.976219313 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey AddPartitionsToTxn (24) Versions 0..1
19:33:43.976220024 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey AddOffsetsToTxn (25) Versions 0..1
19:33:43.976220716 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey EndTxn (26) Versions 0..1
19:33:43.976221407 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey WriteTxnMarkers (27) Versions 0..0
19:33:43.976222078 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey TxnOffsetCommit (28) Versions 0..2
19:33:43.976222750 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey DescribeAcls (29) Versions 0..1
19:33:43.976223421 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey CreateAcls (30) Versions 0..1
19:33:43.976224102 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey DeleteAcls (31) Versions 0..1
19:33:43.976224773 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey DescribeConfigs (32) Versions 0..2
19:33:43.976225435 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey AlterConfigs (33) Versions 0..1
19:33:43.976226146 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey AlterReplicaLogDirs (34) Versions 0..1
19:33:43.976226837 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey DescribeLogDirs (35) Versions 0..1
19:33:43.976227549 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey SaslAuthenticate (36) Versions 0..0
19:33:43.976228230 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey CreatePartitions (37) Versions 0..1
19:33:43.976228981 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey CreateDelegationToken (38) Versions 0..1
19:33:43.976229713 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey RenewDelegationToken (39) Versions 0..1
19:33:43.976230424 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey ExpireDelegationToken (40) Versions 0..1
19:33:43.976231156 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey DescribeDelegationToken (41) Versions 0..1
19:33:43.976231867 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey DeleteGroups (42) Versions 0..1
19:33:43.976237397 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature MsgVer1: Produce (2..2) supported by broker
19:33:43.976238349 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature MsgVer1: Fetch (2..2) supported by broker
19:33:43.976239091 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature MsgVer1
19:33:43.976240133 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature MsgVer2: Produce (3..3) supported by broker
19:33:43.976240944 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature MsgVer2: Fetch (4..4) supported by broker
19:33:43.976241565 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature MsgVer2
19:33:43.976242708 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature ApiVersion: ApiVersion (0..0) supported by broker
19:33:43.976243389 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature ApiVersion
19:33:43.976244621 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature BrokerGroupCoordinator: FindCoordinator (0..0) supported by broker
19:33:43.976245323 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature BrokerGroupCoordinator
19:33:43.976246194 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature BrokerBalancedConsumer: FindCoordinator (0..0) supported by broker
19:33:43.976247156 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature BrokerBalancedConsumer: OffsetCommit (1..2) supported by broker
19:33:43.976248048 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature BrokerBalancedConsumer: OffsetFetch (1..1) supported by broker
19:33:43.976248980 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature BrokerBalancedConsumer: JoinGroup (0..0) supported by broker
19:33:43.976249841 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature BrokerBalancedConsumer: SyncGroup (0..0) supported by broker
19:33:43.976250683 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature BrokerBalancedConsumer: Heartbeat (0..0) supported by broker
19:33:43.976251534 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature BrokerBalancedConsumer: LeaveGroup (0..0) supported by broker
19:33:43.976252216 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature BrokerBalancedConsumer
19:33:43.976253127 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature ThrottleTime: Produce (1..2) supported by broker
19:33:43.976253999 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature ThrottleTime: Fetch (1..2) supported by broker
19:33:43.976254700 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature ThrottleTime
19:33:43.976255622 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature Sasl: JoinGroup (0..0) supported by broker
19:33:43.976256283 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature Sasl
19:33:43.976257255 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature SaslHandshake: SaslHandshake (0..0) supported by broker
19:33:43.976257987 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature SaslHandshake
19:33:43.976258878 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature LZ4: FindCoordinator (0..0) supported by broker
19:33:43.976259560 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature LZ4
19:33:43.976260461 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature OffsetTime: Offset (1..1) supported by broker
19:33:43.976261133 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature OffsetTime
19:33:43.976262105 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature IdempotentProducer: InitProducerId (0..0) supported by broker
19:33:43.976262796 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature IdempotentProducer
19:33:43.976263698 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature ZSTD: Produce (7..7) supported by broker
19:33:43.976264649 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature ZSTD: Fetch (10..10) supported by broker
19:33:43.976265281 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature ZSTD
19:33:43.976266202 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature SaslAuthReq: SaslHandshake (1..1) supported by broker
19:33:43.976267164 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature SaslAuthReq: SaslAuthenticate (0..0) supported by broker
19:33:43.976267835 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature SaslAuthReq
19:33:43.976270621 [Debug ] [RDK] [anonymous] [7] [FEATURE] [thrd:TxnCoordinator]: TxnCoordinator/3: Updated enabled protocol features to MsgVer1,ApiVersion,BrokerBalancedConsumer,ThrottleTime,Sasl,SaslHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2,IdempotentProducer,ZSTD,SaslAuthReq
19:33:43.976271452 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:TxnCoordinator]: TxnCoordinator: Broker changed state APIVERSION_QUERY -> UP
19:33:43.976280369 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:TxnCoordinator]: Broadcasting state change
19:33:43.976284417 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:TxnCoordinator]: TxnCoordinator/3: Request metadata for brokers only: connected
19:33:43.976292072 [Debug ] [RDK] [anonymous] [7] [COORD] [thrd:main]: TxnCoordinator/3: Transaction coordinator is now up
19:33:43.976293705 [Debug ] [RDK] [anonymous] [7] [GETPID] [thrd:main]: TxnCoordinator/3: Acquiring ProducerId
19:33:43.976298905 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:TxnCoordinator]: TxnCoordinator/3: Sent MetadataRequest (v4, 26 bytes @ 0, CorrId 3)
19:33:43.976306359 [Debug ] [RDK] [anonymous] [7] [IDEMPSTATE] [thrd:main]: Idempotent producer state change WaitTransport -> WaitPID
19:33:43.976319103 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:TxnCoordinator]: TxnCoordinator/3: Sent InitProducerIdRequest (v1, 48 bytes @ 0, CorrId 4)
19:33:43.976546657 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:TxnCoordinator]: TxnCoordinator/3: Received MetadataResponse (v4, 112 bytes, CorrId 3, rtt 0.25ms)
19:33:43.976560313 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: TxnCoordinator/3: ===== Received metadata: connected =====
19:33:43.976564701 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: TxnCoordinator/3: ClusterId: Uz_c76ACSsmTXoZ8R2CI_w, ControllerId: 3
19:33:43.976565382 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: TxnCoordinator/3: 3 brokers, 0 topics
19:33:43.976566334 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: TxnCoordinator/3:   Broker #0/3: host_002:9092 NodeId 2
19:33:43.976568128 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: TxnCoordinator/3:   Broker #1/3: host_003:9092 NodeId 3
19:33:43.976569330 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: TxnCoordinator/3:   Broker #2/3: host_001:9092 NodeId 1
19:33:43.986456191 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:TxnCoordinator]: TxnCoordinator/3: Received InitProducerIdResponse (v1, 16 bytes, CorrId 4, rtt 10.13ms)
19:33:43.986486128 [Debug ] [RDK] [anonymous] [7] [GETPID] [thrd:main]: Acquired PID{Id:294012,Epoch:50}
19:33:43.986487370 [Debug ] [RDK] [anonymous] [7] [IDEMPSTATE] [thrd:main]: Idempotent producer state change WaitPID -> Assigned
19:33:43.986488362 [Debug ] [RDK] [anonymous] [7] [TXNSTATE] [thrd:main]: Transaction state change WaitPID -> ReadyNotAcked
19:33:43.986501517 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_001:9092/1: Wake-up
19:33:43.986508370 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_003:9092/3: Wake-up
19:33:43.986513129 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_002:9092/2: Wake-up
19:33:43.986515334 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: kafka-test-cluster:9092/bootstrap: Wake-up
19:33:43.986519932 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: TxnCoordinator/3: Wake-up
19:33:43.986546192 [Debug ] [RDK] [main] [7] [TXNAPI] [thrd:app]: Transactional API called: init_transactions
19:33:43.986578414 [Debug ] [RDK] [anonymous] [7] [TXNSTATE] [thrd:main]: Transaction state change ReadyNotAcked -> Ready
19:33:43.986659037 [Debug ] [RDK] [anonymous] [7] [TXNSTATE] [thrd:main]: Transaction state change Ready -> InTransaction
19:33:43.986669738 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_001:9092/1: Wake-up
19:33:43.986672403 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_003:9092/3: Wake-up
19:33:43.986677252 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_002:9092/2: Wake-up
19:33:43.986679897 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: kafka-test-cluster:9092/bootstrap: Wake-up
19:33:43.986684816 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: TxnCoordinator/3: Wake-up
19:33:43.986803813 [Debug ] [RDK] [main] [7] [TOPIC] [thrd:app]: New local topic: SIMPLE_TOPIC_1
19:33:43.986811808 [Debug ] [RDK] [main] [7] [TOPPARNEW] [thrd:app]: NEW SIMPLE_TOPIC_1 [-1] 0x10e90c0 (at rd_kafka_topic_new0:441)
19:33:43.986821096 [Debug ] [RDK] [main] [7] [METADATA] [thrd:app]: Hinted cache of 1/1 topic(s) being queried
19:33:43.986822318 [Debug ] [RDK] [main] [7] [METADATA] [thrd:app]: Requesting metadata for 1/1 topics: leader query
19:33:43.986830634 [Debug ] [RDK] [main] [7] [METADATA] [thrd:app]: kafka-test-cluster:9092/bootstrap: Request metadata for 1 topic(s): leader query
19:33:43.987055983 [Debug ] [RDK] [main] [7] [TXNAPI] [thrd:app]: Transactional API called: commit_transaction (begin)
19:33:43.987074318 [Debug ] [RDK] [anonymous] [7] [TXNSTATE] [thrd:main]: Transaction state change InTransaction -> BeginCommit
19:33:43.987087022 [Debug ] [RDK] [main] [7] [TXNCOMMIT] [thrd:app]: Flushing 10 outstanding message(s) prior to commit
19:33:43.987175761 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Sent MetadataRequest (v4, 53 bytes @ 0, CorrId 5)
19:33:43.988005802 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Received MetadataResponse (v4, 180 bytes, CorrId 5, rtt 0.83ms)
19:33:43.988029167 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: kafka-test-cluster:9092/bootstrap: ===== Received metadata (for 1 requested topics): leader query =====
19:33:43.988034868 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: kafka-test-cluster:9092/bootstrap: ClusterId: Uz_c76ACSsmTXoZ8R2CI_w, ControllerId: 3
19:33:43.988035589 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: kafka-test-cluster:9092/bootstrap: 3 brokers, 1 topics
19:33:43.988039717 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: kafka-test-cluster:9092/bootstrap:   Broker #0/3: host_002:9092 NodeId 2
19:33:43.988041681 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: kafka-test-cluster:9092/bootstrap:   Broker #1/3: host_003:9092 NodeId 3
19:33:43.988042733 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: kafka-test-cluster:9092/bootstrap:   Broker #2/3: host_001:9092 NodeId 1
19:33:43.988044145 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: kafka-test-cluster:9092/bootstrap:   Topic #0/1: SIMPLE_TOPIC_1 with 1 partitions
19:33:43.988047071 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:main]: Topic SIMPLE_TOPIC_1 changed state unknown -> exists
19:33:43.988048073 [Debug ] [RDK] [anonymous] [7] [PARTCNT] [thrd:main]: Topic SIMPLE_TOPIC_1 partition count changed from 0 to 1
19:33:43.988052040 [Debug ] [RDK] [anonymous] [7] [TOPPARNEW] [thrd:main]: NEW SIMPLE_TOPIC_1 [0] 0x7f8518143ab0 (at rd_kafka_topic_partition_cnt_update:750)
19:33:43.988052902 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic SIMPLE_TOPIC_1 partition 0 Leader 3
19:33:43.988055076 [Debug ] [RDK] [anonymous] [7] [BRKDELGT] [thrd:main]: SIMPLE_TOPIC_1 [0]: delegate to broker host_003:9092/3 (rktp 0x7f8518143ab0, term 0, ref 2)
19:33:43.988056579 [Debug ] [RDK] [anonymous] [7] [BRKDELGT] [thrd:main]: SIMPLE_TOPIC_1 [0]: delegating to broker host_003:9092/3 for partition with 0 messages (0 bytes) queued
19:33:43.988059184 [Debug ] [RDK] [anonymous] [7] [BRKMIGR] [thrd:main]: Migrating topic SIMPLE_TOPIC_1 [0] 0x7f8518143ab0 from (none) to host_003:9092/3 (sending PARTITION_JOIN to host_003:9092/3)
19:33:43.988068462 [Debug ] [RDK] [anonymous] [7] [PARTCNT] [thrd:main]: Partitioning 10 unassigned messages in topic SIMPLE_TOPIC_1 to 1 partitions
19:33:43.988086847 [Debug ] [RDK] [anonymous] [7] [TOPBRK] [thrd:host_003:9092/3]: host_003:9092/3: Topic SIMPLE_TOPIC_1 [0]: joining broker (rktp 0x7f8518143ab0, 3 message(s) queued)
19:33:43.988090814 [Debug ] [RDK] [anonymous] [7] [FETCHADD] [thrd:host_003:9092/3]: host_003:9092/3: Added SIMPLE_TOPIC_1 [0] to active list (1 entries, opv 0, 3 messages queued): joining
19:33:43.988092688 [Debug ] [RDK] [anonymous] [7] [DRAIN] [thrd:host_003:9092/3]: SIMPLE_TOPIC_1 [0] beginning partition drain: wait for outstanding requests to finish before producing to new leader
19:33:43.988100723 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:host_003:9092/3]: Broadcasting state change
19:33:43.988204050 [Debug ] [RDK] [anonymous] [7] [UAS] [thrd:main]: 10/10 messages were partitioned in topic SIMPLE_TOPIC_1
19:33:43.988213648 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: kafka-test-cluster:9092/bootstrap: 1/1 requested topic(s) seen in metadata
19:33:43.988224439 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: SIMPLE_TOPIC_1 [0] all in-flight requests drained from queue
19:33:43.989099283 [Debug ] [RDK] [anonymous] [7] [ADDPARTS] [thrd:main]: TxnCoordinator/3: Adding partitions to transaction
19:33:43.989147364 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:TxnCoordinator]: TxnCoordinator/3: Sent AddPartitionsToTxnRequest (v0, 93 bytes @ 0, CorrId 5)
19:33:43.999825094 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:TxnCoordinator]: TxnCoordinator/3: Received AddPartitionsToTxnResponse (v0, 45 bytes, CorrId 5, rtt 10.68ms)
19:33:43.999875029 [Debug ] [RDK] [anonymous] [7] [ADDPARTS] [thrd:main]: SIMPLE_TOPIC_1 [0] registered with transaction
19:33:43.999885198 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_001:9092/1: Wake-up
19:33:43.999887833 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_003:9092/3: Wake-up
19:33:43.999892342 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_002:9092/2: Wake-up
19:33:43.999898884 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: kafka-test-cluster:9092/bootstrap: Wake-up
19:33:43.999903694 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: TxnCoordinator/3: Wake-up
19:33:43.999922710 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: SIMPLE_TOPIC_1 [0] 10 message(s) in xmit queue (10 added from partition queue)
19:33:43.999926267 [Debug ] [RDK] [anonymous] [7] [NEWPID] [thrd:host_003:9092/3]: SIMPLE_TOPIC_1 [0] changed PID{Invalid} -> PID{Id:294012,Epoch:50} with base MsgId 1
19:33:43.999927850 [Debug ] [RDK] [anonymous] [7] [RESETSEQ] [thrd:host_003:9092/3]: SIMPLE_TOPIC_1 [0] resetting epoch base seq from 0 to 1
19:33:43.999929383 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: SIMPLE_TOPIC_1 [0] 10 message(s) queued but broker not up
19:33:43.999931216 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:host_003:9092/3]: host_003:9092/3: Broker changed state INIT -> TRY_CONNECT
19:33:43.999932198 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:host_003:9092/3]: Broadcasting state change
19:33:43.999934112 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:host_003:9092/3]: host_003:9092/3: broker in state TRY_CONNECT connecting
19:33:43.999935374 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:host_003:9092/3]: host_003:9092/3: Broker changed state TRY_CONNECT -> CONNECT
19:33:43.999936015 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:host_003:9092/3]: Broadcasting state change
19:33:44.000561807 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:host_003:9092/3]: host_003:9092/3: Connecting to ipv4#10.76.128.235:9092 (plaintext) with socket 50
19:33:44.000592295 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: SIMPLE_TOPIC_1 [0] 10 message(s) in xmit queue (0 added from partition queue)
19:33:44.000593517 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: SIMPLE_TOPIC_1 [0] 10 message(s) queued but broker not up
19:33:44.000601493 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: SIMPLE_TOPIC_1 [0] 10 message(s) in xmit queue (0 added from partition queue)
19:33:44.000602495 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: SIMPLE_TOPIC_1 [0] 10 message(s) queued but broker not up
19:33:44.000734115 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:host_003:9092/3]: host_003:9092/3: Connected to ipv4#10.76.128.235:9092
19:33:44.000735848 [Debug ] [RDK] [anonymous] [7] [CONNECTED] [thrd:host_003:9092/3]: host_003:9092/3: Connected (#1)
19:33:44.000738373 [Debug ] [RDK] [anonymous] [7] [FEATURE] [thrd:host_003:9092/3]: host_003:9092/3: Updated enabled protocol features +ApiVersion to ApiVersion
19:33:44.000739115 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:host_003:9092/3]: host_003:9092/3: Broker changed state CONNECT -> APIVERSION_QUERY
19:33:44.000739716 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:host_003:9092/3]: Broadcasting state change
19:33:44.000766677 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:host_003:9092/3]: host_003:9092/3: Sent ApiVersionRequest (v3, 40 bytes @ 0, CorrId 1)
19:33:44.000769713 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: SIMPLE_TOPIC_1 [0] 10 message(s) in xmit queue (0 added from partition queue)
19:33:44.000770845 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: SIMPLE_TOPIC_1 [0] 10 message(s) queued but broker not up
19:33:44.001071157 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:host_003:9092/3]: host_003:9092/3: Received ApiVersionResponse (v3, 6 bytes, CorrId 1, rtt 0.30ms)
19:33:44.001073742 [Debug ] [RDK] [anonymous] [7] [PROTOERR] [thrd:host_003:9092/3]: host_003:9092/3: Protocol parse failure for ApiVersion v3 at 3/6 (rd_kafka_handle_ApiVersion:1945) (incorrect broker.version.fallback?)
19:33:44.001074794 [Debug ] [RDK] [anonymous] [7] [PROTOERR] [thrd:host_003:9092/3]: host_003:9092/3: ApiArrayCnt -1 out of range
19:33:44.001075996 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3: ApiVersionRequest v3 failed due to UNSUPPORTED_VERSION: retrying with v0
19:33:44.001095513 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:host_003:9092/3]: host_003:9092/3: Sent ApiVersionRequest (v0, 21 bytes @ 0, CorrId 2)
19:33:44.001097758 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: SIMPLE_TOPIC_1 [0] 10 message(s) in xmit queue (0 added from partition queue)
19:33:44.001098780 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: SIMPLE_TOPIC_1 [0] 10 message(s) queued but broker not up
19:33:44.001287249 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:host_003:9092/3]: host_003:9092/3: Received ApiVersionResponse (v0, 264 bytes, CorrId 2, rtt 0.17ms)
19:33:44.001289433 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3: Broker API support:
19:33:44.001291236 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey Produce (0) Versions 0..7
19:33:44.001292559 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey Fetch (1) Versions 0..10
19:33:44.001293741 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey Offset (2) Versions 0..4
19:33:44.001295013 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey Metadata (3) Versions 0..7
19:33:44.001296256 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey LeaderAndIsr (4) Versions 0..1
19:33:44.001297488 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey StopReplica (5) Versions 0..0
19:33:44.001298731 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey UpdateMetadata (6) Versions 0..4
19:33:44.001299973 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey ControlledShutdown (7) Versions 0..1
19:33:44.001301175 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey OffsetCommit (8) Versions 0..6
19:33:44.001302428 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey OffsetFetch (9) Versions 0..5
19:33:44.001303620 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey FindCoordinator (10) Versions 0..2
19:33:44.001304872 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey JoinGroup (11) Versions 0..3
19:33:44.001306105 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey Heartbeat (12) Versions 0..2
19:33:44.001307207 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey LeaveGroup (13) Versions 0..2
19:33:44.001308409 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey SyncGroup (14) Versions 0..2
19:33:44.001309611 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey DescribeGroups (15) Versions 0..2
19:33:44.001310783 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey ListGroups (16) Versions 0..2
19:33:44.001312056 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey SaslHandshake (17) Versions 0..1
19:33:44.001313268 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey ApiVersion (18) Versions 0..2
19:33:44.001314440 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey CreateTopics (19) Versions 0..3
19:33:44.001315653 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey DeleteTopics (20) Versions 0..3
19:33:44.001316725 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey DeleteRecords (21) Versions 0..1
19:33:44.001317997 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey InitProducerId (22) Versions 0..1
19:33:44.001319220 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey OffsetForLeaderEpoch (23) Versions 0..2
19:33:44.001320352 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey AddPartitionsToTxn (24) Versions 0..1
19:33:44.001321624 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey AddOffsetsToTxn (25) Versions 0..1
19:33:44.001322756 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey EndTxn (26) Versions 0..1
19:33:44.001323969 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey WriteTxnMarkers (27) Versions 0..0
19:33:44.001325211 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey TxnOffsetCommit (28) Versions 0..2
19:33:44.001326363 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey DescribeAcls (29) Versions 0..1
19:33:44.001327555 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey CreateAcls (30) Versions 0..1
19:33:44.001328728 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey DeleteAcls (31) Versions 0..1
19:33:44.001329860 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey DescribeConfigs (32) Versions 0..2
19:33:44.001331092 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey AlterConfigs (33) Versions 0..1
19:33:44.001332174 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey AlterReplicaLogDirs (34) Versions 0..1
19:33:44.001333096 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey DescribeLogDirs (35) Versions 0..1
19:33:44.001334128 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey SaslAuthenticate (36) Versions 0..0
19:33:44.001335010 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey CreatePartitions (37) Versions 0..1
19:33:44.001335991 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey CreateDelegationToken (38) Versions 0..1
19:33:44.001336993 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey RenewDelegationToken (39) Versions 0..1
19:33:44.001337955 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey ExpireDelegationToken (40) Versions 0..1
19:33:44.001338867 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey DescribeDelegationToken (41) Versions 0..1
19:33:44.001339809 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:   ApiKey DeleteGroups (42) Versions 0..1
19:33:44.001344458 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature MsgVer1: Produce (2..2) supported by broker
19:33:44.001345981 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature MsgVer1: Fetch (2..2) supported by broker
19:33:44.001347173 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3: Enabling feature MsgVer1
19:33:44.001348545 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature MsgVer2: Produce (3..3) supported by broker
19:33:44.001349938 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature MsgVer2: Fetch (4..4) supported by broker
19:33:44.001351030 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3: Enabling feature MsgVer2
19:33:44.001352493 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature ApiVersion: ApiVersion (0..0) supported by broker
19:33:44.001353585 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3: Enabling feature ApiVersion
19:33:44.001355088 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature BrokerGroupCoordinator: FindCoordinator (0..0) supported by broker
19:33:44.001356220 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3: Enabling feature BrokerGroupCoordinator
19:33:44.001357563 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature BrokerBalancedConsumer: FindCoordinator (0..0) supported by broker
19:33:44.001359055 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature BrokerBalancedConsumer: OffsetCommit (1..2) supported by broker
19:33:44.001360588 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature BrokerBalancedConsumer: OffsetFetch (1..1) supported by broker
19:33:44.001362081 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature BrokerBalancedConsumer: JoinGroup (0..0) supported by broker
19:33:44.001363494 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature BrokerBalancedConsumer: SyncGroup (0..0) supported by broker
19:33:44.001364746 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature BrokerBalancedConsumer: Heartbeat (0..0) supported by broker
19:33:44.001365918 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature BrokerBalancedConsumer: LeaveGroup (0..0) supported by broker
19:33:44.001366870 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3: Enabling feature BrokerBalancedConsumer
19:33:44.001368483 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature ThrottleTime: Produce (1..2) supported by broker
19:33:44.001369806 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature ThrottleTime: Fetch (1..2) supported by broker
19:33:44.001370848 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3: Enabling feature ThrottleTime
19:33:44.001372180 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature Sasl: JoinGroup (0..0) supported by broker
19:33:44.001373463 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3: Enabling feature Sasl
19:33:44.001375306 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature SaslHandshake: SaslHandshake (0..0) supported by broker
19:33:44.001376699 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3: Enabling feature SaslHandshake
19:33:44.001378432 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature LZ4: FindCoordinator (0..0) supported by broker
19:33:44.001379625 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3: Enabling feature LZ4
19:33:44.001381428 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature OffsetTime: Offset (1..1) supported by broker
19:33:44.001382720 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3: Enabling feature OffsetTime
19:33:44.001383933 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature IdempotentProducer: InitProducerId (0..0) supported by broker
19:33:44.001384754 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3: Enabling feature IdempotentProducer
19:33:44.001469125 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature ZSTD: Produce (7..7) supported by broker
19:33:44.001471179 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature ZSTD: Fetch (10..10) supported by broker
19:33:44.001472261 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3: Enabling feature ZSTD
19:33:44.001473774 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature SaslAuthReq: SaslHandshake (1..1) supported by broker
19:33:44.001475387 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3:  Feature SaslAuthReq: SaslAuthenticate (0..0) supported by broker
19:33:44.001476529 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_003:9092/3]: host_003:9092/3: Enabling feature SaslAuthReq
19:33:44.001480687 [Debug ] [RDK] [anonymous] [7] [FEATURE] [thrd:host_003:9092/3]: host_003:9092/3: Updated enabled protocol features to MsgVer1,ApiVersion,BrokerBalancedConsumer,ThrottleTime,Sasl,SaslHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2,IdempotentProducer,ZSTD,SaslAuthReq
19:33:44.001482100 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:host_003:9092/3]: host_003:9092/3: Broker changed state APIVERSION_QUERY -> UP
19:33:44.001490275 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:host_003:9092/3]: Broadcasting state change
19:33:44.001495706 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:host_003:9092/3]: Skipping metadata refresh of 1 topic(s): connected: already being requested
19:33:44.001502909 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: SIMPLE_TOPIC_1 [0] 10 message(s) in xmit queue (0 added from partition queue)
19:33:44.037581006 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: SIMPLE_TOPIC_1 [0] 10 message(s) in xmit queue (0 added from partition queue)
19:33:44.037805443 [Debug ] [RDK] [anonymous] [7] [PRODUCE] [thrd:host_003:9092/3]: host_003:9092/3: SIMPLE_TOPIC_1 [0]: Produce MessageSet with 10 message(s) (3393 bytes, ApiVersion 7, MsgVersion 2, MsgId 1, BaseSeq 0, PID{Id:294012,Epoch:50}, snappy)
19:33:44.037849517 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:host_003:9092/3]: host_003:9092/3: Sent ProduceRequest (v7, 3486 bytes @ 0, CorrId 3)
19:33:44.042604955 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:host_003:9092/3]: host_003:9092/3: Received ProduceResponse (v7, 69 bytes, CorrId 3, rtt 4.75ms)
19:33:44.042616256 [Debug ] [RDK] [anonymous] [7] [MSGSET] [thrd:host_003:9092/3]: host_003:9092/3: SIMPLE_TOPIC_1 [0]: MessageSet with 10 message(s) (MsgId 1, BaseSeq 0) delivered
19:33:44.042670790 [Debug ] [RDK] [main] [7] [TXNAPI] [thrd:app]: Transactional API called: commit_transaction
19:33:44.042699064 [Debug ] [RDK] [anonymous] [7] [TXNSTATE] [thrd:main]: Transaction state change BeginCommit -> CommittingTransaction
19:33:44.042745783 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:TxnCoordinator]: TxnCoordinator/3: Sent EndTxnRequest (v1, 55 bytes @ 0, CorrId 6)
19:33:44.050901467 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:TxnCoordinator]: TxnCoordinator/3: Received EndTxnResponse (v1, 6 bytes, CorrId 6, rtt 8.16ms)
19:33:44.050913780 [Debug ] [RDK] [anonymous] [7] [TXNCOMPLETE] [thrd:main]: Transaction successfully committed
19:33:44.050914642 [Debug ] [RDK] [anonymous] [7] [TXNSTATE] [thrd:main]: Transaction state change CommittingTransaction -> Ready
19:33:44.050949268 [Debug ] [RDK] [anonymous] [7] [TXNSTATE] [thrd:main]: Transaction state change Ready -> InTransaction
19:33:44.050955119 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_001:9092/1: Wake-up
19:33:44.050958005 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_003:9092/3: Wake-up
19:33:44.050962653 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_002:9092/2: Wake-up
19:33:44.050967943 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: kafka-test-cluster:9092/bootstrap: Wake-up
19:33:44.050969897 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: TxnCoordinator/3: Wake-up
19:33:44.471625723 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:host_003:9092/3]: host_003:9092/3: Sent FindCoordinatorRequest (v2, 45 bytes @ 0, CorrId 4)
19:33:44.472250262 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:host_003:9092/3]: host_003:9092/3: Received FindCoordinatorResponse (v2, 30 bytes, CorrId 4, rtt 0.62ms)
19:33:44.472274328 [Debug ] [RDK] [anonymous] [7] [TXNCOORD] [thrd:main]: host_003:9092/3: FindCoordinator response: Transaction coordinator is broker 3 (host_003:9092)
19:33:44.993163419 [Debug ] [RDK] [main] [7] [TXNAPI] [thrd:app]: Transactional API called: commit_transaction (begin)
19:33:44.993218263 [Debug ] [RDK] [anonymous] [7] [TXNSTATE] [thrd:main]: Transaction state change InTransaction -> BeginCommit
19:33:44.993245084 [Debug ] [RDK] [main] [7] [TXNCOMMIT] [thrd:app]: Flushing 0 outstanding message(s) prior to commit
19:33:44.993250124 [Debug ] [RDK] [main] [7] [TXNAPI] [thrd:app]: Transactional API called: commit_transaction
19:33:44.993286293 [Debug ] [RDK] [anonymous] [7] [TXNSTATE] [thrd:main]: Transaction state change BeginCommit -> CommittingTransaction
19:33:44.993341197 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:TxnCoordinator]: TxnCoordinator/3: Sent EndTxnRequest (v1, 55 bytes @ 0, CorrId 7)
19:33:44.993666006 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:TxnCoordinator]: TxnCoordinator/3: Received EndTxnResponse (v1, 6 bytes, CorrId 7, rtt 0.32ms)
19:33:44.993714989 [Debug ] [RDK] [anonymous] [7] [TXNCOMPLETE] [thrd:main]: Transaction successfully committed
19:33:44.993716502 [Debug ] [RDK] [anonymous] [7] [TXNSTATE] [thrd:main]: Transaction state change CommittingTransaction -> Ready
19:33:44.993755096 [Debug ] [RDK] [anonymous] [7] [TXNSTATE] [thrd:main]: Transaction state change Ready -> InTransaction
19:33:44.993764293 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_001:9092/1: Wake-up
19:33:44.993769162 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_003:9092/3: Wake-up
19:33:44.993786055 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_002:9092/2: Wake-up
19:33:44.993792998 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: kafka-test-cluster:9092/bootstrap: Wake-up
19:33:44.993794741 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: TxnCoordinator/3: Wake-up
19:33:48.051624471 [Debug ] [RDK] [main] [7] [TOPIC] [thrd:app]: New local topic: AGGREGATE_TOPIC_2
19:33:48.051628659 [Debug ] [RDK] [main] [7] [TOPPARNEW] [thrd:app]: NEW AGGREGATE_TOPIC_2 [-1] 0x14446c0 (at rd_kafka_topic_new0:441)
19:33:48.051635422 [Debug ] [RDK] [main] [7] [METADATA] [thrd:app]: Hinted cache of 1/1 topic(s) being queried
19:33:48.051636454 [Debug ] [RDK] [main] [7] [METADATA] [thrd:app]: Requesting metadata for 1/1 topics: leader query
19:33:48.051640772 [Debug ] [RDK] [main] [7] [METADATA] [thrd:app]: host_003:9092/3: Request metadata for 1 topic(s): leader query
19:33:48.051703421 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:host_003:9092/3]: host_003:9092/3: Sent MetadataRequest (v4, 64 bytes @ 0, CorrId 5)
19:33:48.052254458 [Debug ] [RDK] [main] [7] [TOPIC] [thrd:app]: New local topic: AGGREGATE_TOPIC_1
19:33:48.052257755 [Debug ] [RDK] [main] [7] [TOPPARNEW] [thrd:app]: NEW AGGREGATE_TOPIC_1 [-1] 0x1495c30 (at rd_kafka_topic_new0:441)
19:33:48.052261251 [Debug ] [RDK] [main] [7] [METADATA] [thrd:app]: Hinted cache of 1/1 topic(s) being queried
19:33:48.052261822 [Debug ] [RDK] [main] [7] [METADATA] [thrd:app]: Requesting metadata for 1/1 topics: leader query
19:33:48.052264017 [Debug ] [RDK] [main] [7] [METADATA] [thrd:app]: host_003:9092/3: Request metadata for 1 topic(s): leader query
19:33:48.052298743 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:host_003:9092/3]: host_003:9092/3: Sent MetadataRequest (v4, 62 bytes @ 0, CorrId 6)
19:33:48.052410164 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:host_003:9092/3]: host_003:9092/3: Received MetadataResponse (v4, 191 bytes, CorrId 5, rtt 0.71ms)
19:33:48.052423440 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3: ===== Received metadata (for 1 requested topics): leader query =====
19:33:48.052432417 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3: ClusterId: Uz_c76ACSsmTXoZ8R2CI_w, ControllerId: 3
19:33:48.052433348 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3: 3 brokers, 1 topics
19:33:48.052438939 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3:   Broker #0/3: host_002:9092 NodeId 2
19:33:48.052442616 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3:   Broker #1/3: host_003:9092 NodeId 3
19:33:48.052443778 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3:   Broker #2/3: host_001:9092 NodeId 1
19:33:48.052445481 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3:   Topic #0/1: AGGREGATE_TOPIC_2 with 1 partitions
19:33:48.052450381 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:main]: Topic AGGREGATE_TOPIC_2 changed state unknown -> exists
19:33:48.052451603 [Debug ] [RDK] [anonymous] [7] [PARTCNT] [thrd:main]: Topic AGGREGATE_TOPIC_2 partition count changed from 0 to 1
19:33:48.052456232 [Debug ] [RDK] [anonymous] [7] [TOPPARNEW] [thrd:main]: NEW AGGREGATE_TOPIC_2 [0] 0x7f85181441e0 (at rd_kafka_topic_partition_cnt_update:750)
19:33:48.052457134 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic AGGREGATE_TOPIC_2 partition 0 Leader 3
19:33:48.052459288 [Debug ] [RDK] [anonymous] [7] [BRKDELGT] [thrd:main]: AGGREGATE_TOPIC_2 [0]: delegate to broker host_003:9092/3 (rktp 0x7f85181441e0, term 0, ref 2)
19:33:48.052460871 [Debug ] [RDK] [anonymous] [7] [BRKDELGT] [thrd:main]: AGGREGATE_TOPIC_2 [0]: delegating to broker host_003:9092/3 for partition with 0 messages (0 bytes) queued
19:33:48.052463666 [Debug ] [RDK] [anonymous] [7] [BRKMIGR] [thrd:main]: Migrating topic AGGREGATE_TOPIC_2 [0] 0x7f85181441e0 from (none) to host_003:9092/3 (sending PARTITION_JOIN to host_003:9092/3)
19:33:48.052467363 [Debug ] [RDK] [anonymous] [7] [PARTCNT] [thrd:main]: Partitioning 43 unassigned messages in topic AGGREGATE_TOPIC_2 to 1 partitions
19:33:48.052481901 [Debug ] [RDK] [anonymous] [7] [UAS] [thrd:main]: 43/43 messages were partitioned in topic AGGREGATE_TOPIC_2
19:33:48.052486309 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3: 1/1 requested topic(s) seen in metadata
19:33:48.052498963 [Debug ] [RDK] [anonymous] [7] [TOPBRK] [thrd:host_003:9092/3]: host_003:9092/3: Topic AGGREGATE_TOPIC_2 [0]: joining broker (rktp 0x7f85181441e0, 43 message(s) queued)
19:33:48.052500877 [Debug ] [RDK] [anonymous] [7] [FETCHADD] [thrd:host_003:9092/3]: host_003:9092/3: Added AGGREGATE_TOPIC_2 [0] to active list (2 entries, opv 0, 43 messages queued): joining
19:33:48.052501899 [Debug ] [RDK] [anonymous] [7] [DRAIN] [thrd:host_003:9092/3]: AGGREGATE_TOPIC_2 [0] beginning partition drain: wait for outstanding requests to finish before producing to new leader
19:33:48.052502540 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:host_003:9092/3]: Broadcasting state change
19:33:48.052504484 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: AGGREGATE_TOPIC_2 [0] all in-flight requests drained from queue
19:33:48.053481170 [Debug ] [RDK] [anonymous] [7] [ADDPARTS] [thrd:main]: TxnCoordinator/3: Adding partitions to transaction
19:33:48.053511197 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:TxnCoordinator]: TxnCoordinator/3: Sent AddPartitionsToTxnRequest (v0, 104 bytes @ 0, CorrId 8)
19:33:48.053520254 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:host_003:9092/3]: host_003:9092/3: Received MetadataResponse (v4, 189 bytes, CorrId 6, rtt 1.22ms)
19:33:48.053526536 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3: ===== Received metadata (for 1 requested topics): leader query =====
19:33:48.053529602 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3: ClusterId: Uz_c76ACSsmTXoZ8R2CI_w, ControllerId: 3
19:33:48.053530193 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3: 3 brokers, 1 topics
19:33:48.053532097 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3:   Broker #0/3: host_002:9092 NodeId 2
19:33:48.053533329 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3:   Broker #1/3: host_003:9092 NodeId 3
19:33:48.053534491 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3:   Broker #2/3: host_001:9092 NodeId 1
19:33:48.053535794 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3:   Topic #0/1: AGGREGATE_TOPIC_1 with 1 partitions
19:33:48.053537517 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:main]: Topic AGGREGATE_TOPIC_1 changed state unknown -> exists
19:33:48.053538168 [Debug ] [RDK] [anonymous] [7] [PARTCNT] [thrd:main]: Topic AGGREGATE_TOPIC_1 partition count changed from 0 to 1
19:33:48.053540513 [Debug ] [RDK] [anonymous] [7] [TOPPARNEW] [thrd:main]: NEW AGGREGATE_TOPIC_1 [0] 0x7f8518144900 (at rd_kafka_topic_partition_cnt_update:750)
19:33:48.053541444 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic AGGREGATE_TOPIC_1 partition 0 Leader 3
19:33:48.053542426 [Debug ] [RDK] [anonymous] [7] [BRKDELGT] [thrd:main]: AGGREGATE_TOPIC_1 [0]: delegate to broker host_003:9092/3 (rktp 0x7f8518144900, term 0, ref 2)
19:33:48.053543689 [Debug ] [RDK] [anonymous] [7] [BRKDELGT] [thrd:main]: AGGREGATE_TOPIC_1 [0]: delegating to broker host_003:9092/3 for partition with 0 messages (0 bytes) queued
19:33:48.053545211 [Debug ] [RDK] [anonymous] [7] [BRKMIGR] [thrd:main]: Migrating topic AGGREGATE_TOPIC_1 [0] 0x7f8518144900 from (none) to host_003:9092/3 (sending PARTITION_JOIN to host_003:9092/3)
19:33:48.053547636 [Debug ] [RDK] [anonymous] [7] [PARTCNT] [thrd:main]: Partitioning 72 unassigned messages in topic AGGREGATE_TOPIC_1 to 1 partitions
19:33:48.053571121 [Debug ] [RDK] [anonymous] [7] [UAS] [thrd:main]: 72/72 messages were partitioned in topic AGGREGATE_TOPIC_1
19:33:48.053579146 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3: 1/1 requested topic(s) seen in metadata
19:33:48.054569796 [Debug ] [RDK] [anonymous] [7] [ADDPARTS] [thrd:main]: TxnCoordinator/3: Adding partitions to transaction
19:33:48.054577129 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:TxnCoordinator]: TxnCoordinator/3: Sent AddPartitionsToTxnRequest (v0, 102 bytes @ 0, CorrId 9)
19:33:48.054581307 [Debug ] [RDK] [anonymous] [7] [TOPBRK] [thrd:host_003:9092/3]: host_003:9092/3: Topic AGGREGATE_TOPIC_1 [0]: joining broker (rktp 0x7f8518144900, 122 message(s) queued)
19:33:48.054583431 [Debug ] [RDK] [anonymous] [7] [FETCHADD] [thrd:host_003:9092/3]: host_003:9092/3: Added AGGREGATE_TOPIC_1 [0] to active list (3 entries, opv 0, 122 messages queued): joining
19:33:48.054584413 [Debug ] [RDK] [anonymous] [7] [DRAIN] [thrd:host_003:9092/3]: AGGREGATE_TOPIC_1 [0] beginning partition drain: wait for outstanding requests to finish before producing to new leader
19:33:48.054585095 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:host_003:9092/3]: Broadcasting state change
19:33:48.054586647 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: AGGREGATE_TOPIC_1 [0] all in-flight requests drained from queue
19:33:48.061934088 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:TxnCoordinator]: TxnCoordinator/3: Received AddPartitionsToTxnResponse (v0, 56 bytes, CorrId 8, rtt 8.42ms)
19:33:48.061953264 [Debug ] [RDK] [anonymous] [7] [ADDPARTS] [thrd:main]: AGGREGATE_TOPIC_2 [0] registered with transaction
19:33:48.061966309 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_001:9092/1: Wake-up
19:33:48.061968523 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_003:9092/3: Wake-up
19:33:48.061975486 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_002:9092/2: Wake-up
19:33:48.061980215 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: kafka-test-cluster:9092/bootstrap: Wake-up
19:33:48.061982480 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: TxnCoordinator/3: Wake-up
19:33:48.062001616 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: AGGREGATE_TOPIC_2 [0] 185 message(s) in xmit queue (185 added from partition queue)
19:33:48.062004311 [Debug ] [RDK] [anonymous] [7] [NEWPID] [thrd:host_003:9092/3]: AGGREGATE_TOPIC_2 [0] changed PID{Invalid} -> PID{Id:294012,Epoch:50} with base MsgId 1
19:33:48.062005824 [Debug ] [RDK] [anonymous] [7] [RESETSEQ] [thrd:host_003:9092/3]: AGGREGATE_TOPIC_2 [0] resetting epoch base seq from 0 to 1
19:33:48.063086648 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: AGGREGATE_TOPIC_2 [0] 186 message(s) in xmit queue (1 added from partition queue)
19:33:48.063902389 [Debug ] [RDK] [main] [7] [TOPIC] [thrd:app]: New local topic: AGGREGATE_TOPIC_3
19:33:48.063910354 [Debug ] [RDK] [main] [7] [TOPPARNEW] [thrd:app]: NEW AGGREGATE_TOPIC_3 [-1] 0x1528d20 (at rd_kafka_topic_new0:441)
19:33:48.063919030 [Debug ] [RDK] [main] [7] [METADATA] [thrd:app]: Hinted cache of 1/1 topic(s) being queried
19:33:48.063920453 [Debug ] [RDK] [main] [7] [METADATA] [thrd:app]: Requesting metadata for 1/1 topics: leader query
19:33:48.063924310 [Debug ] [RDK] [main] [7] [METADATA] [thrd:app]: host_003:9092/3: Request metadata for 1 topic(s): leader query
19:33:48.063972422 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:host_003:9092/3]: host_003:9092/3: Sent MetadataRequest (v4, 61 bytes @ 0, CorrId 7)
19:33:48.063975938 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: AGGREGATE_TOPIC_2 [0] 241 message(s) in xmit queue (55 added from partition queue)
19:33:48.064979927 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:host_003:9092/3]: host_003:9092/3: Received MetadataResponse (v4, 188 bytes, CorrId 7, rtt 1.01ms)
19:33:48.064985367 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: AGGREGATE_TOPIC_2 [0] 241 message(s) in xmit queue (0 added from partition queue)
19:33:48.064990717 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3: ===== Received metadata (for 1 requested topics): leader query =====
19:33:48.064996629 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3: ClusterId: Uz_c76ACSsmTXoZ8R2CI_w, ControllerId: 3
19:33:48.064997460 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3: 3 brokers, 1 topics
19:33:48.065001408 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3:   Broker #0/3: host_002:9092 NodeId 2
19:33:48.065003181 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3:   Broker #1/3: host_003:9092 NodeId 3
19:33:48.065004223 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3:   Broker #2/3: host_001:9092 NodeId 1
19:33:48.065005776 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3:   Topic #0/1: AGGREGATE_TOPIC_3 with 1 partitions
19:33:48.065008782 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:main]: Topic AGGREGATE_TOPIC_3 changed state unknown -> exists
19:33:48.065009694 [Debug ] [RDK] [anonymous] [7] [PARTCNT] [thrd:main]: Topic AGGREGATE_TOPIC_3 partition count changed from 0 to 1
19:33:48.065012880 [Debug ] [RDK] [anonymous] [7] [TOPPARNEW] [thrd:main]: NEW AGGREGATE_TOPIC_3 [0] 0x7f8518145500 (at rd_kafka_topic_partition_cnt_update:750)
19:33:48.065013641 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic AGGREGATE_TOPIC_3 partition 0 Leader 2
19:33:48.065015104 [Debug ] [RDK] [anonymous] [7] [BRKDELGT] [thrd:main]: AGGREGATE_TOPIC_3 [0]: delegate to broker host_002:9092/2 (rktp 0x7f8518145500, term 0, ref 2)
19:33:48.065016356 [Debug ] [RDK] [anonymous] [7] [BRKDELGT] [thrd:main]: AGGREGATE_TOPIC_3 [0]: delegating to broker host_002:9092/2 for partition with 0 messages (0 bytes) queued
19:33:48.065018430 [Debug ] [RDK] [anonymous] [7] [BRKMIGR] [thrd:main]: Migrating topic AGGREGATE_TOPIC_3 [0] 0x7f8518145500 from (none) to host_002:9092/2 (sending PARTITION_JOIN to host_002:9092/2)
19:33:48.065027808 [Debug ] [RDK] [anonymous] [7] [PARTCNT] [thrd:main]: Partitioning 21 unassigned messages in topic AGGREGATE_TOPIC_3 to 1 partitions
19:33:48.065038588 [Debug ] [RDK] [anonymous] [7] [UAS] [thrd:main]: 21/21 messages were partitioned in topic AGGREGATE_TOPIC_3
19:33:48.065046644 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_003:9092/3: 1/1 requested topic(s) seen in metadata
19:33:48.065046463 [Debug ] [RDK] [anonymous] [7] [TOPBRK] [thrd:host_002:9092/2]: host_002:9092/2: Topic AGGREGATE_TOPIC_3 [0]: joining broker (rktp 0x7f8518145500, 21 message(s) queued)
19:33:48.065052044 [Debug ] [RDK] [anonymous] [7] [FETCHADD] [thrd:host_002:9092/2]: host_002:9092/2: Added AGGREGATE_TOPIC_3 [0] to active list (1 entries, opv 0, 21 messages queued): joining
19:33:48.065053908 [Debug ] [RDK] [anonymous] [7] [DRAIN] [thrd:host_002:9092/2]: AGGREGATE_TOPIC_3 [0] beginning partition drain: wait for outstanding requests to finish before producing to new leader
19:33:48.065055260 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:host_002:9092/2]: Broadcasting state change
19:33:48.065061552 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_002:9092/2]: host_002:9092/2: AGGREGATE_TOPIC_3 [0] all in-flight requests drained from queue
19:33:48.069606151 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:TxnCoordinator]: TxnCoordinator/3: Received AddPartitionsToTxnResponse (v0, 54 bytes, CorrId 9, rtt 15.02ms)
19:33:48.069623524 [Debug ] [RDK] [anonymous] [7] [ADDPARTS] [thrd:main]: AGGREGATE_TOPIC_1 [0] registered with transaction
19:33:48.069635617 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_001:9092/1: Wake-up
19:33:48.069639023 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_003:9092/3: Wake-up
19:33:48.069644744 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_002:9092/2: Wake-up
19:33:48.069647389 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: kafka-test-cluster:9092/bootstrap: Wake-up
19:33:48.069648932 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: TxnCoordinator/3: Wake-up
19:33:48.069664341 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: AGGREGATE_TOPIC_2 [0] 241 message(s) in xmit queue (0 added from partition queue)
19:33:48.069665544 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: AGGREGATE_TOPIC_1 [0] 549 message(s) in xmit queue (549 added from partition queue)
19:33:48.069667076 [Debug ] [RDK] [anonymous] [7] [NEWPID] [thrd:host_003:9092/3]: AGGREGATE_TOPIC_1 [0] changed PID{Invalid} -> PID{Id:294012,Epoch:50} with base MsgId 1
19:33:48.069667768 [Debug ] [RDK] [anonymous] [7] [RESETSEQ] [thrd:host_003:9092/3]: AGGREGATE_TOPIC_1 [0] resetting epoch base seq from 0 to 1
19:33:48.101747325 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: AGGREGATE_TOPIC_2 [0] 241 message(s) in xmit queue (0 added from partition queue)
19:33:48.102221746 [Debug ] [RDK] [anonymous] [7] [PRODUCE] [thrd:host_003:9092/3]: host_003:9092/3: AGGREGATE_TOPIC_2 [0]: Produce MessageSet with 241 message(s) (10106 bytes, ApiVersion 7, MsgVersion 2, MsgId 1, BaseSeq 0, PID{Id:294012,Epoch:50}, snappy)
19:33:48.102276320 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:host_003:9092/3]: host_003:9092/3: Sent ProduceRequest (v7, 10210 bytes @ 0, CorrId 8)
19:33:48.102279456 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: AGGREGATE_TOPIC_1 [0] 549 message(s) in xmit queue (0 added from partition queue)
19:33:48.103259008 [Debug ] [RDK] [anonymous] [7] [PRODUCE] [thrd:host_003:9092/3]: host_003:9092/3: AGGREGATE_TOPIC_1 [0]: Produce MessageSet with 549 message(s) (30351 bytes, ApiVersion 7, MsgVersion 2, MsgId 1, BaseSeq 0, PID{Id:294012,Epoch:50}, snappy)
19:33:48.103281862 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:host_003:9092/3]: host_003:9092/3: Sent ProduceRequest (v7, 30453 bytes @ 0, CorrId 9)
19:33:48.109370455 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:host_003:9092/3]: host_003:9092/3: Received ProduceResponse (v7, 80 bytes, CorrId 8, rtt 7.07ms)
19:33:48.109375925 [Debug ] [RDK] [anonymous] [7] [MSGSET] [thrd:host_003:9092/3]: host_003:9092/3: AGGREGATE_TOPIC_2 [0]: MessageSet with 241 message(s) (MsgId 1, BaseSeq 0) delivered
19:33:48.116594647 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:host_003:9092/3]: host_003:9092/3: Received ProduceResponse (v7, 78 bytes, CorrId 9, rtt 13.31ms)
19:33:48.116599326 [Debug ] [RDK] [anonymous] [7] [MSGSET] [thrd:host_003:9092/3]: host_003:9092/3: AGGREGATE_TOPIC_1 [0]: MessageSet with 549 message(s) (MsgId 1, BaseSeq 0) delivered
19:33:48.164023000 [Debug ] [RDK] [main] [7] [TXNAPI] [thrd:app]: Transactional API called: send_offsets_to_transaction
19:33:48.164161964 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:TxnCoordinator]: TxnCoordinator/3: Sent AddOffsetsToTxnRequest (v0, 77 bytes @ 0, CorrId 10)
19:33:48.175809273 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:TxnCoordinator]: TxnCoordinator/3: Received AddOffsetsToTxnResponse (v0, 6 bytes, CorrId 10, rtt 11.64ms)
19:33:48.175887562 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:host_003:9092/3]: host_003:9092/3: Sent FindCoordinatorRequest (v2, 45 bytes @ 0, CorrId 10)
19:33:48.176253858 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:host_003:9092/3]: host_003:9092/3: Received FindCoordinatorResponse (v2, 30 bytes, CorrId 10, rtt 0.36ms)
19:33:48.176330323 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:host_001:9092/1]: host_001:9092/1: Received CONNECT op
19:33:48.176333890 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:host_001:9092/1]: host_001:9092/1: Broker changed state INIT -> TRY_CONNECT
19:33:48.176335744 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:host_001:9092/1]: Broadcasting state change
19:33:48.176341655 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:host_001:9092/1]: host_001:9092/1: broker in state TRY_CONNECT connecting
19:33:48.176342707 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:host_001:9092/1]: host_001:9092/1: Broker changed state TRY_CONNECT -> CONNECT
19:33:48.176350311 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:host_001:9092/1]: Broadcasting state change
19:33:48.176951294 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:host_001:9092/1]: host_001:9092/1: Connecting to ipv4#10.76.128.121:9092 (plaintext) with socket 54
19:33:48.177111088 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:host_001:9092/1]: host_001:9092/1: Connected to ipv4#10.76.128.121:9092
19:33:48.177113162 [Debug ] [RDK] [anonymous] [7] [CONNECTED] [thrd:host_001:9092/1]: host_001:9092/1: Connected (#1)
19:33:48.177116077 [Debug ] [RDK] [anonymous] [7] [FEATURE] [thrd:host_001:9092/1]: host_001:9092/1: Updated enabled protocol features +ApiVersion to ApiVersion
19:33:48.177116638 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:host_001:9092/1]: host_001:9092/1: Broker changed state CONNECT -> APIVERSION_QUERY
19:33:48.177117210 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:host_001:9092/1]: Broadcasting state change
19:33:48.177149321 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:host_001:9092/1]: host_001:9092/1: Sent ApiVersionRequest (v3, 40 bytes @ 0, CorrId 1)
19:33:48.177426848 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:host_001:9092/1]: host_001:9092/1: Received ApiVersionResponse (v3, 6 bytes, CorrId 1, rtt 0.28ms)
19:33:48.177430485 [Debug ] [RDK] [anonymous] [7] [PROTOERR] [thrd:host_001:9092/1]: host_001:9092/1: Protocol parse failure for ApiVersion v3 at 3/6 (rd_kafka_handle_ApiVersion:1945) (incorrect broker.version.fallback?)
19:33:48.177431287 [Debug ] [RDK] [anonymous] [7] [PROTOERR] [thrd:host_001:9092/1]: host_001:9092/1: ApiArrayCnt -1 out of range
19:33:48.177432619 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1: ApiVersionRequest v3 failed due to UNSUPPORTED_VERSION: retrying with v0
19:33:48.177446485 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:host_001:9092/1]: host_001:9092/1: Sent ApiVersionRequest (v0, 21 bytes @ 0, CorrId 2)
19:33:48.177623021 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:host_001:9092/1]: host_001:9092/1: Received ApiVersionResponse (v0, 264 bytes, CorrId 2, rtt 0.17ms)
19:33:48.177624604 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1: Broker API support:
19:33:48.177626518 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey Produce (0) Versions 0..7
19:33:48.177627359 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey Fetch (1) Versions 0..10
19:33:48.177628060 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey Offset (2) Versions 0..4
19:33:48.177628742 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey Metadata (3) Versions 0..7
19:33:48.177629734 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey LeaderAndIsr (4) Versions 0..1
19:33:48.177630445 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey StopReplica (5) Versions 0..0
19:33:48.177631146 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey UpdateMetadata (6) Versions 0..4
19:33:48.177631858 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey ControlledShutdown (7) Versions 0..1
19:33:48.177632559 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey OffsetCommit (8) Versions 0..6
19:33:48.177633240 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey OffsetFetch (9) Versions 0..5
19:33:48.177633992 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey FindCoordinator (10) Versions 0..2
19:33:48.177634713 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey JoinGroup (11) Versions 0..3
19:33:48.177635394 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey Heartbeat (12) Versions 0..2
19:33:48.177636096 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey LeaveGroup (13) Versions 0..2
19:33:48.177636787 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey SyncGroup (14) Versions 0..2
19:33:48.177637468 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey DescribeGroups (15) Versions 0..2
19:33:48.177638170 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey ListGroups (16) Versions 0..2
19:33:48.177638871 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey SaslHandshake (17) Versions 0..1
19:33:48.177639542 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey ApiVersion (18) Versions 0..2
19:33:48.177640234 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey CreateTopics (19) Versions 0..3
19:33:48.177640925 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey DeleteTopics (20) Versions 0..3
19:33:48.177641576 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey DeleteRecords (21) Versions 0..1
19:33:48.177642288 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey InitProducerId (22) Versions 0..1
19:33:48.177643019 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey OffsetForLeaderEpoch (23) Versions 0..2
19:33:48.177643740 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey AddPartitionsToTxn (24) Versions 0..1
19:33:48.177644432 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey AddOffsetsToTxn (25) Versions 0..1
19:33:48.177645123 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey EndTxn (26) Versions 0..1
19:33:48.177645824 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey WriteTxnMarkers (27) Versions 0..0
19:33:48.177646506 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey TxnOffsetCommit (28) Versions 0..2
19:33:48.177647197 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey DescribeAcls (29) Versions 0..1
19:33:48.177647868 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey CreateAcls (30) Versions 0..1
19:33:48.177648539 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey DeleteAcls (31) Versions 0..1
19:33:48.177649221 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey DescribeConfigs (32) Versions 0..2
19:33:48.177649892 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey AlterConfigs (33) Versions 0..1
19:33:48.177650603 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey AlterReplicaLogDirs (34) Versions 0..1
19:33:48.177651295 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey DescribeLogDirs (35) Versions 0..1
19:33:48.177652016 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey SaslAuthenticate (36) Versions 0..0
19:33:48.177652717 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey CreatePartitions (37) Versions 0..1
19:33:48.177653439 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey CreateDelegationToken (38) Versions 0..1
19:33:48.177654150 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey RenewDelegationToken (39) Versions 0..1
19:33:48.177654841 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey ExpireDelegationToken (40) Versions 0..1
19:33:48.177655553 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey DescribeDelegationToken (41) Versions 0..1
19:33:48.177656244 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:   ApiKey DeleteGroups (42) Versions 0..1
19:33:48.177661264 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature MsgVer1: Produce (2..2) supported by broker
19:33:48.177662225 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature MsgVer1: Fetch (2..2) supported by broker
19:33:48.177662977 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1: Enabling feature MsgVer1
19:33:48.177663909 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature MsgVer2: Produce (3..3) supported by broker
19:33:48.177664710 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature MsgVer2: Fetch (4..4) supported by broker
19:33:48.177665351 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1: Enabling feature MsgVer2
19:33:48.177666443 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature ApiVersion: ApiVersion (0..0) supported by broker
19:33:48.177667145 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1: Enabling feature ApiVersion
19:33:48.177668227 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature BrokerGroupCoordinator: FindCoordinator (0..0) supported by broker
19:33:48.177668918 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1: Enabling feature BrokerGroupCoordinator
19:33:48.177669780 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature BrokerBalancedConsumer: FindCoordinator (0..0) supported by broker
19:33:48.177670712 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature BrokerBalancedConsumer: OffsetCommit (1..2) supported by broker
19:33:48.177671633 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature BrokerBalancedConsumer: OffsetFetch (1..1) supported by broker
19:33:48.177672545 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature BrokerBalancedConsumer: JoinGroup (0..0) supported by broker
19:33:48.177673407 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature BrokerBalancedConsumer: SyncGroup (0..0) supported by broker
19:33:48.177674248 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature BrokerBalancedConsumer: Heartbeat (0..0) supported by broker
19:33:48.177675080 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature BrokerBalancedConsumer: LeaveGroup (0..0) supported by broker
19:33:48.177675751 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1: Enabling feature BrokerBalancedConsumer
19:33:48.177676943 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature ThrottleTime: Produce (1..2) supported by broker
19:33:48.177677795 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature ThrottleTime: Fetch (1..2) supported by broker
19:33:48.177678476 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1: Enabling feature ThrottleTime
19:33:48.177679378 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature Sasl: JoinGroup (0..0) supported by broker
19:33:48.177680009 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1: Enabling feature Sasl
19:33:48.177680981 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature SaslHandshake: SaslHandshake (0..0) supported by broker
19:33:48.177681662 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1: Enabling feature SaslHandshake
19:33:48.177682514 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature LZ4: FindCoordinator (0..0) supported by broker
19:33:48.177683195 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1: Enabling feature LZ4
19:33:48.177684097 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature OffsetTime: Offset (1..1) supported by broker
19:33:48.177684748 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1: Enabling feature OffsetTime
19:33:48.177685790 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature IdempotentProducer: InitProducerId (0..0) supported by broker
19:33:48.177686461 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1: Enabling feature IdempotentProducer
19:33:48.177687503 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature ZSTD: Produce (7..7) supported by broker
19:33:48.177688355 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature ZSTD: Fetch (10..10) supported by broker
19:33:48.177688986 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1: Enabling feature ZSTD
19:33:48.177689908 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature SaslAuthReq: SaslHandshake (1..1) supported by broker
19:33:48.177690960 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1:  Feature SaslAuthReq: SaslAuthenticate (0..0) supported by broker
19:33:48.177691611 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:host_001:9092/1]: host_001:9092/1: Enabling feature SaslAuthReq
19:33:48.177694336 [Debug ] [RDK] [anonymous] [7] [FEATURE] [thrd:host_001:9092/1]: host_001:9092/1: Updated enabled protocol features to MsgVer1,ApiVersion,BrokerBalancedConsumer,ThrottleTime,Sasl,SaslHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2,IdempotentProducer,ZSTD,SaslAuthReq
19:33:48.177695148 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:host_001:9092/1]: host_001:9092/1: Broker changed state APIVERSION_QUERY -> UP
19:33:48.177704506 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:host_001:9092/1]: Broadcasting state change
19:33:48.177711559 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:host_001:9092/1]: Skipping metadata refresh of 4 topic(s): connected: already being requested
19:33:48.177767315 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:host_001:9092/1]: host_001:9092/1: Sent TxnOffsetCommitRequest (v0, 722 bytes @ 0, CorrId 3)
19:33:48.188393193 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:host_001:9092/1]: host_001:9092/1: Received TxnOffsetCommitResponse (v0, 545 bytes, CorrId 3, rtt 10.62ms)
19:33:48.188532227 [Debug ] [RDK] [main] [7] [TXNAPI] [thrd:app]: Transactional API called: commit_transaction (begin)
19:33:48.188556123 [Debug ] [RDK] [anonymous] [7] [TXNSTATE] [thrd:main]: Transaction state change InTransaction -> BeginCommit
19:33:48.188576982 [Debug ] [RDK] [main] [7] [TXNCOMMIT] [thrd:app]: Flushing 1210 outstanding message(s) prior to commit
19:43:25.362187640 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: Requesting metadata for 4/4 topics: periodic topic and broker list refresh
19:43:25.362195666 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1: Request metadata for 4 topic(s): periodic topic and broker list refresh
19:43:25.362416634 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:host_001:9092/1]: host_001:9092/1: Sent MetadataRequest (v4, 162 bytes @ 0, CorrId 4)
19:43:25.363149564 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:host_001:9092/1]: host_001:9092/1: Received MetadataResponse (v4, 412 bytes, CorrId 4, rtt 0.73ms)
19:43:25.363160695 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1: ===== Received metadata (for 4 requested topics): periodic topic and broker list refresh =====
19:43:25.363169552 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1: ClusterId: Uz_c76ACSsmTXoZ8R2CI_w, ControllerId: 3
19:43:25.363170283 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1: 3 brokers, 4 topics
19:43:25.363178108 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Broker #0/3: host_002:9092 NodeId 2
19:43:25.363182567 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Broker #1/3: host_003:9092 NodeId 3
19:43:25.363183619 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Broker #2/3: host_001:9092 NodeId 1
19:43:25.363184901 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Topic #0/4: SIMPLE_TOPIC_1 with 1 partitions
19:43:25.363187717 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic SIMPLE_TOPIC_1 partition 0 Leader 3
19:43:25.363191754 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Topic #1/4: AGGREGATE_TOPIC_2 with 1 partitions
19:43:25.363192786 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic AGGREGATE_TOPIC_2 partition 0 Leader 3
19:43:25.363194449 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Topic #2/4: AGGREGATE_TOPIC_1 with 1 partitions
19:43:25.363195261 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic AGGREGATE_TOPIC_1 partition 0 Leader 3
19:43:25.363196654 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Topic #3/4: AGGREGATE_TOPIC_3 with 1 partitions
19:43:25.363197656 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic AGGREGATE_TOPIC_3 partition 0 Leader 2
19:43:25.363199138 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1: 4/4 requested topic(s) seen in metadata
19:43:43.997314982 [Debug ] [RDK] [anonymous] [7] [FAIL] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Disconnected (after 600023ms in state UP) (_TRANSPORT)
19:43:43.997317536 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Broker changed state UP -> DOWN
19:43:43.997327545 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:kafka-test-cluster:9092/bootstrap]: Broadcasting state change
19:43:43.997329058 [Debug ] [RDK] [anonymous] [7] [BUFQ] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Purging bufq with 0 buffers
19:43:43.997329589 [Debug ] [RDK] [anonymous] [7] [BUFQ] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Purging bufq with 0 buffers
19:43:43.997330271 [Debug ] [RDK] [anonymous] [7] [BUFQ] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Updating 0 buffers on connection reset
19:43:43.997339889 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:kafka-test-cluster:9092/bootstrap]: Requesting metadata for 4/4 topics: broker down
19:43:43.997345009 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:kafka-test-cluster:9092/bootstrap]: host_001:9092/1: Request metadata for 4 topic(s): broker down
19:43:43.997356571 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Broker changed state DOWN -> INIT
19:43:43.997357002 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:kafka-test-cluster:9092/bootstrap]: Broadcasting state change
19:43:43.997389664 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:host_001:9092/1]: host_001:9092/1: Sent MetadataRequest (v4, 162 bytes @ 0, CorrId 5)
19:43:43.998623332 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:host_001:9092/1]: host_001:9092/1: Received MetadataResponse (v4, 412 bytes, CorrId 5, rtt 1.23ms)
19:43:43.998656726 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1: ===== Received metadata (for 4 requested topics): broker down =====
19:43:43.998675992 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1: ClusterId: Uz_c76ACSsmTXoZ8R2CI_w, ControllerId: 3
19:43:43.998677485 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1: 3 brokers, 4 topics
19:43:43.998690460 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Broker #0/3: host_002:9092 NodeId 2
19:43:43.998696742 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Broker #1/3: host_003:9092 NodeId 3
19:43:43.998698555 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Broker #2/3: host_001:9092 NodeId 1
19:43:43.998700860 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Topic #0/4: SIMPLE_TOPIC_1 with 1 partitions
19:43:43.998706681 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic SIMPLE_TOPIC_1 partition 0 Leader 3
19:43:43.998712372 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Topic #1/4: AGGREGATE_TOPIC_2 with 1 partitions
19:43:43.998714185 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic AGGREGATE_TOPIC_2 partition 0 Leader 3
19:43:43.998715978 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Topic #2/4: AGGREGATE_TOPIC_1 with 1 partitions
19:43:43.998717852 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic AGGREGATE_TOPIC_1 partition 0 Leader 3
19:43:43.998720677 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Topic #3/4: AGGREGATE_TOPIC_3 with 1 partitions
19:43:43.998722441 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic AGGREGATE_TOPIC_3 partition 0 Leader 2
19:43:43.998725196 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1: 4/4 requested topic(s) seen in metadata
19:43:48.064064716 [Debug ] [RDK] [anonymous] [7] [TIMEOUT] [thrd:host_002:9092/2]: host_002:9092/2: AGGREGATE_TOPIC_3 [0]: timed out 0+2 message(s) (MsgId 1..2): message.timeout.ms exceeded
19:43:48.064079383 [Debug ] [RDK] [anonymous] [7] [DRAIN] [thrd:host_002:9092/2]: Beginning partition drain for PID{Id:294012,Epoch:50} reset for 0 partition(s) with in-flight requests: 2 message(s) timed out on AGGREGATE_TOPIC_3 [0]
19:43:48.064081427 [Debug ] [RDK] [anonymous] [7] [IDEMPSTATE] [thrd:host_002:9092/2]: Idempotent producer state change Assigned -> DrainReset
19:43:48.064088250 [Debug ] [RDK] [anonymous] [7] [DRAIN] [thrd:host_002:9092/2]: All partitions drained
19:43:48.064089302 [Debug ] [RDK] [anonymous] [7] [IDEMPSTATE] [thrd:host_002:9092/2]: Idempotent producer state change DrainReset -> RequestPID
19:43:48.064089974 [Debug ] [RDK] [anonymous] [7] [TXN] [thrd:host_002:9092/2]: Starting PID FSM timer (fire immediately): Drain done
19:43:48.179764407 [Debug ] [RDK] [anonymous] [7] [FAIL] [thrd:TxnCoordinator]: TxnCoordinator/3: Disconnected (after 604203ms in state UP) (_TRANSPORT)
19:43:48.179767964 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:TxnCoordinator]: TxnCoordinator: Broker changed state UP -> DOWN
19:43:48.179790146 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:TxnCoordinator]: Broadcasting state change
19:43:48.179792220 [Debug ] [RDK] [anonymous] [7] [BUFQ] [thrd:TxnCoordinator]: TxnCoordinator/3: Purging bufq with 0 buffers
19:43:48.179792711 [Debug ] [RDK] [anonymous] [7] [BUFQ] [thrd:TxnCoordinator]: TxnCoordinator/3: Purging bufq with 0 buffers
19:43:48.179793262 [Debug ] [RDK] [anonymous] [7] [BUFQ] [thrd:TxnCoordinator]: TxnCoordinator/3: Updating 0 buffers on connection reset
19:43:48.179803291 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:TxnCoordinator]: Requesting metadata for 4/4 topics: broker down
19:43:48.179810324 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:TxnCoordinator]: host_001:9092/1: Request metadata for 4 topic(s): broker down
19:43:48.179817448 [Debug ] [RDK] [anonymous] [7] [COORD] [thrd:main]: TxnCoordinator/3: Transaction coordinator is now down
19:43:48.179823740 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:TxnCoordinator]: TxnCoordinator: Broker changed state DOWN -> INIT
19:43:48.179824161 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:TxnCoordinator]: Broadcasting state change
19:43:48.179825062 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:TxnCoordinator]: TxnCoordinator: Broker changed state INIT -> TRY_CONNECT
19:43:48.179825373 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:TxnCoordinator]: Broadcasting state change
19:43:48.179826505 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:TxnCoordinator]: TxnCoordinator/3: broker in state TRY_CONNECT connecting
19:43:48.179827046 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:TxnCoordinator]: TxnCoordinator: Broker changed state TRY_CONNECT -> CONNECT
19:43:48.179827337 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:TxnCoordinator]: Broadcasting state change
19:43:48.179839219 [Debug ] [RDK] [anonymous] [7] [IDEMPSTATE] [thrd:main]: Idempotent producer state change RequestPID -> WaitTransport
19:43:48.179841003 [Debug ] [RDK] [anonymous] [7] [TXN] [thrd:main]: Starting PID FSM timer: No broker available
19:43:48.180019472 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:host_001:9092/1]: host_001:9092/1: Sent MetadataRequest (v4, 162 bytes @ 0, CorrId 6)
19:43:48.180368005 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:TxnCoordinator]: TxnCoordinator/3: Connecting to ipv4#10.76.128.235:9092 (plaintext) with socket 11
19:43:48.180553869 [Debug ] [RDK] [anonymous] [7] [CONNECT] [thrd:TxnCoordinator]: TxnCoordinator/3: Connected to ipv4#10.76.128.235:9092
19:43:48.180555813 [Debug ] [RDK] [anonymous] [7] [CONNECTED] [thrd:TxnCoordinator]: TxnCoordinator/3: Connected (#2)
19:43:48.180556965 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:TxnCoordinator]: TxnCoordinator: Broker changed state CONNECT -> APIVERSION_QUERY
19:43:48.180557496 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:TxnCoordinator]: Broadcasting state change
19:43:48.180583345 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:TxnCoordinator]: TxnCoordinator/3: Sent ApiVersionRequest (v3, 40 bytes @ 0, CorrId 11)
19:43:48.180721598 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:host_001:9092/1]: host_001:9092/1: Received MetadataResponse (v4, 412 bytes, CorrId 6, rtt 0.71ms)
19:43:48.180754902 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1: ===== Received metadata (for 4 requested topics): broker down =====
19:43:48.180770882 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1: ClusterId: Uz_c76ACSsmTXoZ8R2CI_w, ControllerId: 3
19:43:48.180771744 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1: 3 brokers, 4 topics
19:43:48.180790810 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Broker #0/3: host_002:9092 NodeId 2
19:43:48.180795629 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Broker #1/3: host_003:9092 NodeId 3
19:43:48.180796922 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Broker #2/3: host_001:9092 NodeId 1
19:43:48.180798264 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Topic #0/4: SIMPLE_TOPIC_1 with 1 partitions
19:43:48.180803995 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic SIMPLE_TOPIC_1 partition 0 Leader 3
19:43:48.180810888 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Topic #1/4: AGGREGATE_TOPIC_2 with 1 partitions
19:43:48.180812712 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic AGGREGATE_TOPIC_2 partition 0 Leader 3
19:43:48.180814896 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Topic #2/4: AGGREGATE_TOPIC_1 with 1 partitions
19:43:48.180816088 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic AGGREGATE_TOPIC_1 partition 0 Leader 3
19:43:48.180817561 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Topic #3/4: AGGREGATE_TOPIC_3 with 1 partitions
19:43:48.180818923 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic AGGREGATE_TOPIC_3 partition 0 Leader 2
19:43:48.180820917 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1: 4/4 requested topic(s) seen in metadata
19:43:48.180823682 [Debug ] [RDK] [anonymous] [7] [TXN] [thrd:main]: Starting PID FSM timer: No broker available
19:43:48.181010298 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:TxnCoordinator]: TxnCoordinator/3: Received ApiVersionResponse (v3, 6 bytes, CorrId 11, rtt 0.42ms)
19:43:48.181013894 [Debug ] [RDK] [anonymous] [7] [PROTOERR] [thrd:TxnCoordinator]: TxnCoordinator/3: Protocol parse failure for ApiVersion v3 at 3/6 (rd_kafka_handle_ApiVersion:1945) (incorrect broker.version.fallback?)
19:43:48.181014686 [Debug ] [RDK] [anonymous] [7] [PROTOERR] [thrd:TxnCoordinator]: TxnCoordinator/3: ApiArrayCnt -1 out of range
19:43:48.181016129 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: ApiVersionRequest v3 failed due to UNSUPPORTED_VERSION: retrying with v0
19:43:48.181046727 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:TxnCoordinator]: TxnCoordinator/3: Sent ApiVersionRequest (v0, 21 bytes @ 0, CorrId 12)
19:43:48.181251046 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:TxnCoordinator]: TxnCoordinator/3: Received ApiVersionResponse (v0, 264 bytes, CorrId 12, rtt 0.20ms)
19:43:48.181252498 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Broker API support:
19:43:48.181254091 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey Produce (0) Versions 0..7
19:43:48.181254933 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey Fetch (1) Versions 0..10
19:43:48.181255674 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey Offset (2) Versions 0..4
19:43:48.181256396 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey Metadata (3) Versions 0..7
19:43:48.181257127 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey LeaderAndIsr (4) Versions 0..1
19:43:48.181257889 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey StopReplica (5) Versions 0..0
19:43:48.181258600 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey UpdateMetadata (6) Versions 0..4
19:43:48.181259341 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey ControlledShutdown (7) Versions 0..1
19:43:48.181260063 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey OffsetCommit (8) Versions 0..6
19:43:48.181260754 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey OffsetFetch (9) Versions 0..5
19:43:48.181261516 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey FindCoordinator (10) Versions 0..2
19:43:48.181262237 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey JoinGroup (11) Versions 0..3
19:43:48.181262918 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey Heartbeat (12) Versions 0..2
19:43:48.181263650 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey LeaveGroup (13) Versions 0..2
19:43:48.181264341 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey SyncGroup (14) Versions 0..2
19:43:48.181265052 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey DescribeGroups (15) Versions 0..2
19:43:48.181265754 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey ListGroups (16) Versions 0..2
19:43:48.181266485 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey SaslHandshake (17) Versions 0..1
19:43:48.181267176 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey ApiVersion (18) Versions 0..2
19:43:48.181267888 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey CreateTopics (19) Versions 0..3
19:43:48.181268589 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey DeleteTopics (20) Versions 0..3
19:43:48.181269270 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey DeleteRecords (21) Versions 0..1
19:43:48.181269982 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey InitProducerId (22) Versions 0..1
19:43:48.181270733 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey OffsetForLeaderEpoch (23) Versions 0..2
19:43:48.181271474 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey AddPartitionsToTxn (24) Versions 0..1
19:43:48.181272206 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey AddOffsetsToTxn (25) Versions 0..1
19:43:48.181272927 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey EndTxn (26) Versions 0..1
19:43:48.181273639 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey WriteTxnMarkers (27) Versions 0..0
19:43:48.181274330 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey TxnOffsetCommit (28) Versions 0..2
19:43:48.181275011 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey DescribeAcls (29) Versions 0..1
19:43:48.181275713 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey CreateAcls (30) Versions 0..1
19:43:48.181276414 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey DeleteAcls (31) Versions 0..1
19:43:48.181277115 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey DescribeConfigs (32) Versions 0..2
19:43:48.181277807 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey AlterConfigs (33) Versions 0..1
19:43:48.181278528 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey AlterReplicaLogDirs (34) Versions 0..1
19:43:48.181279239 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey DescribeLogDirs (35) Versions 0..1
19:43:48.181279971 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey SaslAuthenticate (36) Versions 0..0
19:43:48.181280672 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey CreatePartitions (37) Versions 0..1
19:43:48.181281443 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey CreateDelegationToken (38) Versions 0..1
19:43:48.181282205 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey RenewDelegationToken (39) Versions 0..1
19:43:48.181282926 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey ExpireDelegationToken (40) Versions 0..1
19:43:48.181283648 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey DescribeDelegationToken (41) Versions 0..1
19:43:48.181284379 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:   ApiKey DeleteGroups (42) Versions 0..1
19:43:48.181296843 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature MsgVer1: Produce (2..2) supported by broker
19:43:48.181297895 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature MsgVer1: Fetch (2..2) supported by broker
19:43:48.181298716 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature MsgVer1
19:43:48.181299608 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature MsgVer2: Produce (3..3) supported by broker
19:43:48.181300430 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature MsgVer2: Fetch (4..4) supported by broker
19:43:48.181301071 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature MsgVer2
19:43:48.181302063 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature ApiVersion: ApiVersion (0..0) supported by broker
19:43:48.181302724 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature ApiVersion
19:43:48.181303636 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature BrokerGroupCoordinator: FindCoordinator (0..0) supported by broker
19:43:48.181304317 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature BrokerGroupCoordinator
19:43:48.181305149 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature BrokerBalancedConsumer: FindCoordinator (0..0) supported by broker
19:43:48.181306070 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature BrokerBalancedConsumer: OffsetCommit (1..2) supported by broker
19:43:48.181306972 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature BrokerBalancedConsumer: OffsetFetch (1..1) supported by broker
19:43:48.181307864 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature BrokerBalancedConsumer: JoinGroup (0..0) supported by broker
19:43:48.181308725 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature BrokerBalancedConsumer: SyncGroup (0..0) supported by broker
19:43:48.181309557 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature BrokerBalancedConsumer: Heartbeat (0..0) supported by broker
19:43:48.181310379 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature BrokerBalancedConsumer: LeaveGroup (0..0) supported by broker
19:43:48.181311040 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature BrokerBalancedConsumer
19:43:48.181311941 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature ThrottleTime: Produce (1..2) supported by broker
19:43:48.181312783 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature ThrottleTime: Fetch (1..2) supported by broker
19:43:48.181313494 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature ThrottleTime
19:43:48.181314356 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature Sasl: JoinGroup (0..0) supported by broker
19:43:48.181315027 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature Sasl
19:43:48.181315999 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature SaslHandshake: SaslHandshake (0..0) supported by broker
19:43:48.181316711 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature SaslHandshake
19:43:48.181317582 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature LZ4: FindCoordinator (0..0) supported by broker
19:43:48.181318264 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature LZ4
19:43:48.181319165 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature OffsetTime: Offset (1..1) supported by broker
19:43:48.181319826 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature OffsetTime
19:43:48.181320818 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature IdempotentProducer: InitProducerId (0..0) supported by broker
19:43:48.181321490 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature IdempotentProducer
19:43:48.181322371 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature ZSTD: Produce (7..7) supported by broker
19:43:48.181323273 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature ZSTD: Fetch (10..10) supported by broker
19:43:48.181323904 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature ZSTD
19:43:48.181324826 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature SaslAuthReq: SaslHandshake (1..1) supported by broker
19:43:48.181325788 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3:  Feature SaslAuthReq: SaslAuthenticate (0..0) supported by broker
19:43:48.181326439 [Debug ] [RDK] [anonymous] [7] [APIVERSION] [thrd:TxnCoordinator]: TxnCoordinator/3: Enabling feature SaslAuthReq
19:43:48.181329595 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:TxnCoordinator]: TxnCoordinator: Broker changed state APIVERSION_QUERY -> UP
19:43:48.181337470 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:TxnCoordinator]: Broadcasting state change
19:43:48.181344453 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:TxnCoordinator]: Skipping metadata refresh of 4 topic(s): connected: already being requested
19:43:48.181352819 [Debug ] [RDK] [anonymous] [7] [COORD] [thrd:main]: TxnCoordinator/3: Transaction coordinator is now up
19:43:48.181354522 [Debug ] [RDK] [anonymous] [7] [GETPID] [thrd:main]: TxnCoordinator/3: Acquiring ProducerId
19:43:48.181414937 [Debug ] [RDK] [anonymous] [7] [IDEMPSTATE] [thrd:main]: Idempotent producer state change WaitTransport -> WaitPID
19:43:48.181446778 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:TxnCoordinator]: TxnCoordinator/3: Sent InitProducerIdRequest (v1, 48 bytes @ 0, CorrId 13)
19:43:48.188553228 [Error ] [RDK] [anonymous] [3] [TXNERR] [thrd:main]: Current transaction failed: Transactional operation timed out (_TIMED_OUT)
19:43:48.188557245 [Debug ] [RDK] [anonymous] [7] [TXNSTATE] [thrd:main]: Transaction state change BeginCommit -> AbortableError
19:43:48.188617841 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:main]: Purged 0 message(s) from 0 UA-partition(s)
19:43:48.188614434 [Debug ] [RDK] [anonymous] [7] [PURGE] [thrd:host_002:9092/2]: host_002:9092/2: Purging queues with flags queue,non-blocking
19:43:48.188620035 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:host_002:9092/2]: host_002:9092/2: Purged 0 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
19:43:48.188624513 [Debug ] [RDK] [anonymous] [7] [ADVBASE] [thrd:host_002:9092/2]: AGGREGATE_TOPIC_3 [0] advancing epoch base msgid to 1208 due to 1208 message(s) in aborted transaction
19:43:48.188628320 [Debug ] [RDK] [anonymous] [7] [PURGE] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Purging queues with flags queue,non-blocking
19:43:48.188630264 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Purged 0 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
19:43:48.188631056 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Purged 0 message(s) from 0 partition(s)
19:43:48.188642347 [Debug ] [RDK] [anonymous] [7] [PURGE] [thrd::0/internal]: :0/internal: Purging queues with flags queue,non-blocking
19:43:48.188643439 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd::0/internal]: :0/internal: Purged 0 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
19:43:48.188644111 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd::0/internal]: :0/internal: Purged 0 message(s) from 0 partition(s)
19:43:48.188652827 [Debug ] [RDK] [anonymous] [7] [PURGE] [thrd:TxnCoordinator]: TxnCoordinator/3: Purging queues with flags queue,non-blocking
19:43:48.188653569 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:TxnCoordinator]: TxnCoordinator/3: Purged 0 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
19:43:48.188654079 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:TxnCoordinator]: TxnCoordinator/3: Purged 0 message(s) from 0 partition(s)
19:43:48.188653939 [Debug ] [RDK] [anonymous] [7] [PURGE] [thrd:host_003:9092/3]: host_003:9092/3: Purging queues with flags queue,non-blocking
19:43:48.188657376 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:host_003:9092/3]: host_003:9092/3: Purged 0 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
19:43:48.188660562 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:host_003:9092/3]: host_003:9092/3: Purged 0 message(s) from 0 partition(s)
19:43:48.188678666 [Debug ] [RDK] [anonymous] [7] [PURGE] [thrd:host_001:9092/1]: host_001:9092/1: Purging queues with flags queue,non-blocking
19:43:48.188680349 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:host_001:9092/1]: host_001:9092/1: Purged 0 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
19:43:48.188681411 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:host_001:9092/1]: host_001:9092/1: Purged 0 message(s) from 0 partition(s)
19:43:48.188810176 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:host_002:9092/2]: host_002:9092/2: Purged 1208 message(s) from 1 partition(s)
19:43:48.189092043 [Debug ] [RDK] [main] [7] [TXNAPI] [thrd:app]: Transactional API called: commit_transaction
19:43:48.189681133 [Debug ] [RDK] [main] [7] [TXNAPI] [thrd:app]: Transactional API called: abort_transaction (begin)
19:43:48.189702775 [Debug ] [RDK] [anonymous] [7] [TXNSTATE] [thrd:main]: Transaction state change AbortableError -> AbortingTransaction
19:43:48.189720148 [Debug ] [RDK] [main] [7] [TXNABORT] [thrd:app]: Purging and flushing 0 outstanding message(s) prior to abort
19:43:48.189759613 [Debug ] [RDK] [anonymous] [7] [PURGE] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Purging queues with flags queue
19:43:48.189760815 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Purged 0 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
19:43:48.189761597 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:kafka-test-cluster:9092/bootstrap]: kafka-test-cluster:9092/bootstrap: Purged 0 message(s) from 0 partition(s)
19:43:48.189765233 [Debug ] [RDK] [anonymous] [7] [PURGE] [thrd:host_003:9092/3]: host_003:9092/3: Purging queues with flags queue
19:43:48.189766456 [Debug ] [RDK] [anonymous] [7] [PURGE] [thrd:host_001:9092/1]: host_001:9092/1: Purging queues with flags queue
19:43:48.189768931 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:host_001:9092/1]: host_001:9092/1: Purged 0 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
19:43:48.189770103 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:host_001:9092/1]: host_001:9092/1: Purged 0 message(s) from 0 partition(s)
19:43:48.189770784 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:host_003:9092/3]: host_003:9092/3: Purged 0 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
19:43:48.189782015 [Debug ] [RDK] [anonymous] [7] [PURGE] [thrd::0/internal]: :0/internal: Purging queues with flags queue
19:43:48.189782767 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd::0/internal]: :0/internal: Purged 0 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
19:43:48.189783238 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd::0/internal]: :0/internal: Purged 0 message(s) from 0 partition(s)
19:43:48.189773169 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:host_003:9092/3]: host_003:9092/3: Purged 0 message(s) from 0 partition(s)
19:43:48.189793607 [Debug ] [RDK] [anonymous] [7] [PURGE] [thrd:TxnCoordinator]: TxnCoordinator/3: Purging queues with flags queue
19:43:48.189794299 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:TxnCoordinator]: TxnCoordinator/3: Purged 0 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
19:43:48.189794800 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:TxnCoordinator]: TxnCoordinator/3: Purged 0 message(s) from 0 partition(s)
19:43:48.189794569 [Debug ] [RDK] [anonymous] [7] [PURGE] [thrd:host_002:9092/2]: host_002:9092/2: Purging queues with flags queue
19:43:48.189795842 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:host_002:9092/2]: host_002:9092/2: Purged 0 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
19:43:48.189796924 [Debug ] [RDK] [anonymous] [7] [PURGEQ] [thrd:host_002:9092/2]: host_002:9092/2: Purged 0 message(s) from 0 partition(s)
19:43:48.189805450 [Debug ] [RDK] [main] [7] [PURGEQ] [thrd:app]: Purged 0 message(s) from 0 UA-partition(s)
19:43:48.189806903 [Debug ] [RDK] [main] [7] [TXNAPI] [thrd:app]: Transactional API called: abort_transaction
19:43:48.189947140 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:TxnCoordinator]: TxnCoordinator/3: Received InitProducerIdResponse (v1, 16 bytes, CorrId 13, rtt 8.50ms)
19:43:48.189981966 [Debug ] [RDK] [anonymous] [7] [GETPID] [thrd:main]: TxnCoordinator/3: Failed to acquire PID: Broker: Producer attempted to update a transaction while another concurrent operation on the same transaction was ongoing
19:43:48.189986184 [Debug ] [RDK] [anonymous] [7] [IDEMPSTATE] [thrd:main]: Idempotent producer state change WaitPID -> RequestPID
19:43:48.189987416 [Debug ] [RDK] [anonymous] [7] [TXN] [thrd:main]: Starting PID FSM timer: Failed to acquire PID from broker TxnCoordinator/3: Broker: Producer attempted to update a transaction while another concurrent operation on the same transaction was ongoing
19:43:48.190135798 [Debug ] [RDK] [anonymous] [7] [FAIL] [thrd:host_003:9092/3]: host_003:9092/3: Disconnected (after 604188ms in state UP) (_TRANSPORT)
19:43:48.190137612 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:host_003:9092/3]: host_003:9092/3: Broker changed state UP -> DOWN
19:43:48.190145307 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:host_003:9092/3]: Broadcasting state change
19:43:48.190146970 [Debug ] [RDK] [anonymous] [7] [BUFQ] [thrd:host_003:9092/3]: host_003:9092/3: Purging bufq with 0 buffers
19:43:48.190147441 [Debug ] [RDK] [anonymous] [7] [BUFQ] [thrd:host_003:9092/3]: host_003:9092/3: Purging bufq with 0 buffers
19:43:48.190148002 [Debug ] [RDK] [anonymous] [7] [BUFQ] [thrd:host_003:9092/3]: host_003:9092/3: Updating 0 buffers on connection reset
19:43:48.190160325 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:host_003:9092/3]: Requesting metadata for 4/4 topics: broker down
19:43:48.190165315 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:host_003:9092/3]: host_001:9092/1: Request metadata for 4 topic(s): broker down
19:43:48.190177808 [Debug ] [RDK] [anonymous] [7] [STATE] [thrd:host_003:9092/3]: host_003:9092/3: Broker changed state DOWN -> INIT
19:43:48.190178219 [Debug ] [RDK] [anonymous] [7] [BROADCAST] [thrd:host_003:9092/3]: Broadcasting state change
19:43:48.190265976 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:host_001:9092/1]: host_001:9092/1: Sent MetadataRequest (v4, 162 bytes @ 0, CorrId 7)
19:43:48.191376679 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:host_001:9092/1]: host_001:9092/1: Received MetadataResponse (v4, 412 bytes, CorrId 7, rtt 1.11ms)
19:43:48.191403661 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1: ===== Received metadata (for 4 requested topics): broker down =====
19:43:48.191425632 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1: ClusterId: Uz_c76ACSsmTXoZ8R2CI_w, ControllerId: 3
19:43:48.191426614 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1: 3 brokers, 4 topics
19:43:48.191435060 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Broker #0/3: host_002:9092 NodeId 2
19:43:48.191439529 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Broker #1/3: host_003:9092 NodeId 3
19:43:48.191440861 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Broker #2/3: host_001:9092 NodeId 1
19:43:48.191442444 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Topic #0/4: SIMPLE_TOPIC_1 with 1 partitions
19:43:48.191447534 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic SIMPLE_TOPIC_1 partition 0 Leader 3
19:43:48.191453776 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Topic #1/4: AGGREGATE_TOPIC_2 with 1 partitions
19:43:48.191455509 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic AGGREGATE_TOPIC_2 partition 0 Leader 3
19:43:48.191457713 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Topic #2/4: AGGREGATE_TOPIC_1 with 1 partitions
19:43:48.191458956 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic AGGREGATE_TOPIC_1 partition 0 Leader 3
19:43:48.191461310 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1:   Topic #3/4: AGGREGATE_TOPIC_3 with 1 partitions
19:43:48.191462873 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]:   Topic AGGREGATE_TOPIC_3 partition 0 Leader 2
19:43:48.191465408 [Debug ] [RDK] [anonymous] [7] [METADATA] [thrd:main]: host_001:9092/1: 4/4 requested topic(s) seen in metadata
19:43:48.191468213 [Debug ] [RDK] [anonymous] [7] [IDEMPSTATE] [thrd:main]: Idempotent producer state change RequestPID -> WaitTransport
19:43:48.191469546 [Debug ] [RDK] [anonymous] [7] [GETPID] [thrd:main]: TxnCoordinator/3: Acquiring ProducerId
19:43:48.191484194 [Debug ] [RDK] [anonymous] [7] [IDEMPSTATE] [thrd:main]: Idempotent producer state change WaitTransport -> WaitPID
19:43:48.191511055 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:TxnCoordinator]: TxnCoordinator/3: Sent InitProducerIdRequest (v1, 48 bytes @ 0, CorrId 14)
19:43:48.191879466 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:TxnCoordinator]: TxnCoordinator/3: Received InitProducerIdResponse (v1, 16 bytes, CorrId 14, rtt 0.37ms)
19:43:48.191902670 [Debug ] [RDK] [anonymous] [7] [GETPID] [thrd:main]: TxnCoordinator/3: Failed to acquire PID: Broker: Producer attempted to update a transaction while another concurrent operation on the same transaction was ongoing
19:43:48.191905626 [Debug ] [RDK] [anonymous] [7] [IDEMPSTATE] [thrd:main]: Idempotent producer state change WaitPID -> RequestPID
19:43:48.191906748 [Debug ] [RDK] [anonymous] [7] [TXN] [thrd:main]: Starting PID FSM timer: Failed to acquire PID from broker TxnCoordinator/3: Broker: Producer attempted to update a transaction while another concurrent operation on the same transaction was ongoing
19:43:48.679989789 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:host_001:9092/1]: host_001:9092/1: Sent FindCoordinatorRequest (v2, 45 bytes @ 0, CorrId 8)
19:43:48.680625047 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:host_001:9092/1]: host_001:9092/1: Received FindCoordinatorResponse (v2, 30 bytes, CorrId 8, rtt 0.63ms)
19:43:48.680667869 [Debug ] [RDK] [anonymous] [7] [TXNCOORD] [thrd:main]: host_001:9092/1: FindCoordinator response: Transaction coordinator is broker 3 (host_003:9092)
19:43:48.691916711 [Debug ] [RDK] [anonymous] [7] [IDEMPSTATE] [thrd:main]: Idempotent producer state change RequestPID -> WaitTransport
19:43:48.691923113 [Debug ] [RDK] [anonymous] [7] [GETPID] [thrd:main]: TxnCoordinator/3: Acquiring ProducerId
19:43:48.691952839 [Debug ] [RDK] [anonymous] [7] [IDEMPSTATE] [thrd:main]: Idempotent producer state change WaitTransport -> WaitPID
19:43:48.692065454 [Debug ] [RDK] [anonymous] [7] [SEND] [thrd:TxnCoordinator]: TxnCoordinator/3: Sent InitProducerIdRequest (v1, 48 bytes @ 0, CorrId 15)
19:43:48.700962850 [Debug ] [RDK] [anonymous] [7] [RECV] [thrd:TxnCoordinator]: TxnCoordinator/3: Received InitProducerIdResponse (v1, 16 bytes, CorrId 15, rtt 8.90ms)
19:43:48.701009359 [Debug ] [RDK] [anonymous] [7] [GETPID] [thrd:main]: Acquired PID{Id:294012,Epoch:52} (previous PID{Id:294012,Epoch:50})
19:43:48.701013667 [Debug ] [RDK] [anonymous] [7] [IDEMPSTATE] [thrd:main]: Idempotent producer state change WaitPID -> Assigned
19:43:48.701034427 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_001:9092/1: Wake-up
19:43:48.701044305 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_003:9092/3: Wake-up
19:43:48.701049135 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: host_002:9092/2: Wake-up
19:43:48.701056990 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: kafka-test-cluster:9092/bootstrap: Wake-up
19:43:48.701062891 [Debug ] [RDK] [anonymous] [7] [WAKEUP] [thrd:main]: TxnCoordinator/3: Wake-up
19:43:48.701087207 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: AGGREGATE_TOPIC_1 [0] PID has changed: must drain requests for all partitions before resuming reset of PID
19:43:48.701090513 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: SIMPLE_TOPIC_1 [0] PID has changed: must drain requests for all partitions before resuming reset of PID
19:43:48.701092387 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: AGGREGATE_TOPIC_2 [0] PID has changed: must drain requests for all partitions before resuming reset of PID
19:43:49.190269682 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: SIMPLE_TOPIC_1 [0] PID has changed: must drain requests for all partitions before resuming reset of PID
19:43:49.190273990 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: AGGREGATE_TOPIC_2 [0] PID has changed: must drain requests for all partitions before resuming reset of PID
19:43:49.190275964 [Debug ] [RDK] [anonymous] [7] [TOPPAR] [thrd:host_003:9092/3]: host_003:9092/3: AGGREGATE_TOPIC_1 [0] PID has changed: must drain requests for all partitions before resuming reset of PID

@sanjay24
Copy link
Contributor Author

sanjay24 commented Aug 26, 2020

hi @edenhill, did you get a chance to see this issue? I've seen multiple issues coming due to this, even with just enabling idempotent (without transactions). There's nothing in the broker logs that could suggest something useful.

@sanjay24
Copy link
Contributor Author

sanjay24 commented Sep 3, 2020

I could capture some more details about the issue, this time while attempting to Abort the transaction. Application hangs while doing a "CommitAndStartNewTransaction()" operation. Actual problem is in flushing the messages. Below is the stackstrace

(gdb) thread apply all bt


Thread 22 (Thread 0x7f854316d700 (LWP 27058)):
#0  0x00007f8545170bed in poll () from /lib64/libc.so.6
#1  0x00000000006ea4be in rd_kafka_transport_poll ()
#2  0x00000000006e9cd7 in rd_kafka_transport_io_serve ()
#3  0x00000000006bf7a3 in ?? ()
#4  0x00000000006c7fef in ?? ()
#5  0x00000000006c8189 in ?? ()
#6  0x00000000006c86a2 in ?? ()
#7  0x000000000073ab55 in ?? ()
#8  0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 21 (Thread 0x7f854296c700 (LWP 27060)):
#0  0x00007f85460b7da2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x000000000073aaed in cnd_timedwait ()
#2  0x000000000073b0f2 in cnd_timedwait_abs ()
#3  0x00000000006f08e9 in rd_kafka_q_serve ()
#4  0x00000000006a9229 in ?? ()
#5  0x000000000073ab55 in ?? ()
#6  0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#7  0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 20 (Thread 0x7f854216b700 (LWP 27061)):
#0  0x00007f85460b7da2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x000000000073aaed in cnd_timedwait ()
#2  0x000000000073b0f2 in cnd_timedwait_abs ()
#3  0x00000000006f070e in rd_kafka_q_pop_serve ()
#4  0x00000000006f07ac in rd_kafka_q_pop ()
#5  0x00000000006bf6b6 in ?? ()
#6  0x00000000006bf7cd in ?? ()
#7  0x00000000006bfcfe in ?? ()
#8  0x00000000006c8134 in ?? ()
#9  0x00000000006c83a0 in ?? ()
#10 0x000000000073ab55 in ?? ()
#11 0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#12 0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 19 (Thread 0x7f854196a700 (LWP 27062)):
#0  0x00007f8545170bed in poll () from /lib64/libc.so.6
#1  0x00000000006ea4be in rd_kafka_transport_poll ()
#2  0x00000000006e9cd7 in rd_kafka_transport_io_serve ()
#3  0x00000000006bf7a3 in ?? ()
#4  0x00000000006c7fef in ?? ()
#5  0x00000000006c8189 in ?? ()
#6  0x00000000006c86a2 in ?? ()
#7  0x000000000073ab55 in ?? ()
#8  0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 18 (Thread 0x7f8540d4f700 (LWP 27063)):
#0  0x00007f8545170bed in poll () from /lib64/libc.so.6
#1  0x00000000006ea4be in rd_kafka_transport_poll ()
#2  0x00000000006e9cd7 in rd_kafka_transport_io_serve ()
#3  0x00000000006bf7a3 in ?? ()
#4  0x00000000006c7fef in ?? ()
#5  0x00000000006c8189 in ?? ()
#6  0x00000000006c86a2 in ?? ()
#7  0x000000000073ab55 in ?? ()
#8  0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 17 (Thread 0x7f8533fff700 (LWP 27064)):
#0  0x00007f8545170bed in poll () from /lib64/libc.so.6
#1  0x00000000006ea4be in rd_kafka_transport_poll ()
#2  0x00000000006e9cd7 in rd_kafka_transport_io_serve ()
#3  0x00000000006bf7a3 in ?? ()
#4  0x00000000006c7fef in ?? ()
#5  0x00000000006c8189 in ?? ()
#6  0x00000000006c86a2 in ?? ()
#7  0x000000000073ab55 in ?? ()
#8  0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 16 (Thread 0x7f85337fe700 (LWP 27065)):
#0  0x00007f8545170bed in poll () from /lib64/libc.so.6
#1  0x00000000006ea4be in rd_kafka_transport_poll ()
#2  0x00000000006e9cd7 in rd_kafka_transport_io_serve ()
#3  0x00000000006bf7a3 in ?? ()
#4  0x00000000006c7fef in ?? ()
#5  0x00000000006c8189 in ?? ()
#6  0x00000000006c86a2 in ?? ()
#7  0x000000000073ab55 in ?? ()
#8  0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 15 (Thread 0x7f8532ffd700 (LWP 27099)):
#0  0x00007f8545170bed in poll () from /lib64/libc.so.6
#1  0x00000000006ea4be in rd_kafka_transport_poll ()
#2  0x00000000006e9cd7 in rd_kafka_transport_io_serve ()
#3  0x00000000006bf7a3 in ?? ()
#4  0x00000000006c7fef in ?? ()
#5  0x00000000006c8189 in ?? ()
#6  0x00000000006c86a2 in ?? ()
#7  0x000000000073ab55 in ?? ()
#8  0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 14 (Thread 0x7f85327fc700 (LWP 27100)):
#0  0x00007f85460b7da2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x000000000073aaed in cnd_timedwait ()
#2  0x000000000073b0f2 in cnd_timedwait_abs ()
#3  0x00000000006f08e9 in rd_kafka_q_serve ()
#4  0x00000000006a9229 in ?? ()
#5  0x000000000073ab55 in ?? ()
#6  0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#7  0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 13 (Thread 0x7f8531ffb700 (LWP 27101)):
#0  0x00007f85460b7da2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x000000000073aaed in cnd_timedwait ()
#2  0x000000000073b0f2 in cnd_timedwait_abs ()
#3  0x00000000006f070e in rd_kafka_q_pop_serve ()
#4  0x00000000006f07ac in rd_kafka_q_pop ()
#5  0x00000000006bf6b6 in ?? ()
#6  0x00000000006bf7cd in ?? ()
#7  0x00000000006bfcfe in ?? ()
#8  0x00000000006c8134 in ?? ()
#9  0x00000000006c83a0 in ?? ()
#10 0x000000000073ab55 in ?? ()
#11 0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#12 0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 12 (Thread 0x7f85317fa700 (LWP 27102)):
#0  0x00007f8545170bed in poll () from /lib64/libc.so.6
#1  0x00000000006ea4be in rd_kafka_transport_poll ()
#2  0x00000000006e9cd7 in rd_kafka_transport_io_serve ()
#3  0x00000000006bf7a3 in ?? ()
#4  0x00000000006c7fef in ?? ()
#5  0x00000000006c8189 in ?? ()
#6  0x00000000006c86a2 in ?? ()
#7  0x000000000073ab55 in ?? ()
#8  0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 11 (Thread 0x7f8530ff9700 (LWP 27103)):
#0  0x00007f85460b7da2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x000000000073aaed in cnd_timedwait ()
#2  0x000000000073b0f2 in cnd_timedwait_abs ()
#3  0x00000000006f08e9 in rd_kafka_q_serve ()
#4  0x00000000006a9229 in ?? ()
#5  0x000000000073ab55 in ?? ()
#6  0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#7  0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 10 (Thread 0x7f8513fff700 (LWP 27104)):
#0  0x00007f85460b7da2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x000000000073aaed in cnd_timedwait ()
#2  0x000000000073b0f2 in cnd_timedwait_abs ()
#3  0x00000000006f070e in rd_kafka_q_pop_serve ()
#4  0x00000000006f07ac in rd_kafka_q_pop ()
#5  0x00000000006bf6b6 in ?? ()
#6  0x00000000006bf7cd in ?? ()
#7  0x00000000006bfd99 in ?? ()
#8  0x00000000006c8134 in ?? ()
#9  0x00000000006c83a0 in ?? ()
#10 0x000000000073ab55 in ?? ()
#11 0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#12 0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 9 (Thread 0x7f85137fe700 (LWP 27105)):
#0  0x00007f8545170bed in poll () from /lib64/libc.so.6
#1  0x00000000006ea4be in rd_kafka_transport_poll ()
#2  0x00000000006e9cd7 in rd_kafka_transport_io_serve ()
#3  0x00000000006bf7a3 in ?? ()
#4  0x00000000006c0dd7 in ?? ()
#5  0x00000000006c815e in ?? ()
#6  0x00000000006c86a2 in ?? ()
#7  0x000000000073ab55 in ?? ()
#8  0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 8 (Thread 0x7f8512ffd700 (LWP 27106)):
#0  0x00007f8545170bed in poll () from /lib64/libc.so.6
#1  0x00000000006ea4be in rd_kafka_transport_poll ()
#2  0x00000000006e9cd7 in rd_kafka_transport_io_serve ()
#3  0x00000000006bf7a3 in ?? ()
#4  0x00000000006c0dd7 in ?? ()
#5  0x00000000006c815e in ?? ()
#6  0x00000000006c86a2 in ?? ()
#7  0x000000000073ab55 in ?? ()
#8  0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 7 (Thread 0x7f85127fc700 (LWP 27107)):
#0  0x00007f8545170bed in poll () from /lib64/libc.so.6
#1  0x00000000006ea4be in rd_kafka_transport_poll ()
#2  0x00000000006e9cd7 in rd_kafka_transport_io_serve ()
#3  0x00000000006bf7a3 in ?? ()
#4  0x00000000006c7fef in ?? ()
#5  0x00000000006c8189 in ?? ()
#6  0x00000000006c86a2 in ?? ()
#7  0x000000000073ab55 in ?? ()
#8  0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 6 (Thread 0x7f8511ffb700 (LWP 27108)):
#0  0x00007f8545170bed in poll () from /lib64/libc.so.6
#1  0x00000000006ea4be in rd_kafka_transport_poll ()
#2  0x00000000006e9cd7 in rd_kafka_transport_io_serve ()
#3  0x00000000006bf7a3 in ?? ()
#4  0x00000000006c7fef in ?? ()
#5  0x00000000006c8189 in ?? ()
#6  0x00000000006c86a2 in ?? ()
#7  0x000000000073ab55 in ?? ()
#8  0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 5 (Thread 0x7f85117fa700 (LWP 27109)):
#0  0x00007f8545170bed in poll () from /lib64/libc.so.6
#1  0x00000000006ea4be in rd_kafka_transport_poll ()
#2  0x00000000006e9cd7 in rd_kafka_transport_io_serve ()
#3  0x00000000006bf7a3 in ?? ()
#4  0x00000000006c7fef in ?? ()
#5  0x00000000006c8189 in ?? ()
#6  0x00000000006c86a2 in ?? ()
#7  0x000000000073ab55 in ?? ()
#8  0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 4 (Thread 0x7f8510ff9700 (LWP 27110)):
#0  0x00007f85460b7da2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x000000000073aaed in cnd_timedwait ()
#2  0x000000000073b0f2 in cnd_timedwait_abs ()
#3  0x00000000006f070e in rd_kafka_q_pop_serve ()
#4  0x00000000006f07ac in rd_kafka_q_pop ()
#5  0x00000000006bf6b6 in ?? ()
#6  0x00000000006bf7cd in ?? ()
#7  0x00000000006c0dd7 in ?? ()
#8  0x00000000006c815e in ?? ()
#9  0x00000000006c83a0 in ?? ()
#10 0x000000000073ab55 in ?? ()
#11 0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#12 0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 3 (Thread 0x7f84fbfff700 (LWP 27111)):
#0  0x00007f8545170bed in poll () from /lib64/libc.so.6
#1  0x00000000006ea4be in rd_kafka_transport_poll ()
#2  0x00000000006e9cd7 in rd_kafka_transport_io_serve ()
#3  0x00000000006bf7a3 in ?? ()
#4  0x00000000006c0dd7 in ?? ()
#5  0x00000000006c815e in ?? ()
#6  0x00000000006c86a2 in ?? ()
#7  0x000000000073ab55 in ?? ()
#8  0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 2 (Thread 0x7f84fb7fe700 (LWP 27112)):
#0  0x00007f8545170bed in poll () from /lib64/libc.so.6
#1  0x00000000006ea4be in rd_kafka_transport_poll ()
#2  0x00000000006e9cd7 in rd_kafka_transport_io_serve ()
#3  0x00000000006bf7a3 in ?? ()
#4  0x00000000006c0dd7 in ?? ()
#5  0x00000000006c815e in ?? ()
#6  0x00000000006c86a2 in ?? ()
#7  0x000000000073ab55 in ?? ()
#8  0x00007f85460b3e65 in start_thread () from /lib64/libpthread.so.0
#9  0x00007f854517b88d in clone () from /lib64/libc.so.6

Thread 1 (Thread 0x7f8546fbea40 (LWP 27047)):
#0  0x00007f85460b7da2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x000000000073aaed in cnd_timedwait ()
#2  0x000000000073b0f2 in cnd_timedwait_abs ()
#3  0x00000000006f08e9 in rd_kafka_q_serve ()
#4  0x00000000006ac963 in rd_kafka_poll ()
#5  0x00000000006ad741 in rd_kafka_flush ()
#6  0x0000000000772975 in rd_kafka_commit_transaction ()
#7  0x000000000068d86d in MyPublisher::CommitTransactionsAndStartNew() ()
#8  0x000000000068d6f7 in MyPublisher::CommitTransaction(bool) ()
#9  0x00000000007d6959 in MyApp::EventLoop() ()
#10 0x0000000000585157 in MyApp::Run(int, char**) ()
#11 0x0000000000579cee in main ()

Problem: based on above stack trace it looks like producer is waiting for acks for enqueued messages

         /* snip from rdkafka_queue.c */

         /* Wait for op */
        while (!(rko = TAILQ_FIRST(&rkq->rkq_q)) &&
               !rd_kafka_q_check_yield(rkq) &&
               cnd_timedwait_abs(&rkq->rkq_cond, &rkq->rkq_lock,
                                 &timeout_tspec) == thrd_success)
                ;

But, it never gets signaled on the rkq_cond. Could you think of any reasons why it would fail to get signaled? I checked the broker logs, but, I couldn't see any errors on any of the brokers.

Now that main thread is stuck above, I see the following issues:

  1. It gets a message timeout expiry (after 10 minutes), and idempotent producer's internal idempotent FSM starts changing states (Assign-> DrainReset -> RequestPID -> WaitTransport -> WaitPID). But, it fails with the following error
[GETPID] [thrd:main]: TxnCoordinator/3: Failed to acquire PID: Broker: Producer attempted to update a transaction while another concurrent operation on the same transaction was ongoing

At this time the internal PID has become invalid.

  1. Soon, after that it gets a transaction timeout (due to inactivity on the transaction status update) (BeginCommit -> AbortableError ). On getting an Abortable error my application tries to abort the transaction as below
	rd_kafka_error_t* error = rd_kafka_commit_transaction(mProducer, -1);
	if (error) {
		LOG(LL_WARN, "commit transaction failed with error=%s", rd_kafka_error_string(error));

		if (rd_kafka_error_txn_requires_abort(error)) {
			LOG(LL_ERROR, "aborting current transaction!");
			rd_kafka_error_destroy(error);
			AbortTransactionAndRewind();
			return false;
		}
		else if (rd_kafka_error_is_fatal(error))
		{
			FatalError(Common::Format("commit transaction encountered fatal error, exiting!"), error);
		}
		else
		{
			LOG( LL_DEBUG, "successfully committed transaction. Beginning new transaction");
		}	
	} 

But, due to idempotent producer FSM already invalidating PID, an attempt to call abort transaction results in the following error:

Aborting with uncaught exception: abort transaction failed error=No PID available (idempotence state RequestPID)

So, now I can understand why I'm seeing "No PID available", but, there are still few questions that I would like to understand & get your help on

  1. Though I'm calling rd_kafka_commit_transaction(mProducer, -1) with timeout specified as INFINITE, I don't expect rd_kafka_flush to be stuck for the whole duration of message/transaction timeout (which is 600*1000 ms). Could you help me understand any condition (apart from broker/network going bad, which is not the case here) that would result in rd_kafka_flush() getting stuck like above?
  2. Do, you think as a workaround I should put a timeout value to rd_kafka_commit_transaction()? Is that a good practice? In such a case should it be a retriable error?
  3. I'm using a single producer for close to 750 topic partitions. In this case, I saw that rd_kafka_flush got stuck flushing out close to 2000 messages, however, at all other times it was able to flush out close to 80k messages without any problem.

Look forward to hear back from you

@sanjay24
Copy link
Contributor Author

sanjay24 commented Sep 10, 2020

Hi @edenhill ,
I further analyzed the issue by introducing some debug logs in the code, (I'm not too familiar with the way internal queues are used, but, these logs do give some clear picture that rd_kafka_flush() fails to PRODUCE randomly.

Code that I changed on 1.5.0

                /*  -------- rdkafka.c -----------*/
                do {
                         // print the message count here
                        rd_kafka_dbg(rk, ALL, "MY_DEBUG", "queue count = %d, msg_cnt = %d, tmout=%d, tsend=%ld", 
                        qlen, msg_cnt, tmout, ts_end);
                        rd_kafka_poll(rk, tmout);
                } while (((qlen = rd_kafka_q_len(rk->rk_rep)) > 0 ||
                          (msg_cnt = rd_kafka_curr_msgs_cnt(rk)) > 0) &&
                         !rd_kafka_yield_thread &&
                         (tmout = rd_timeout_remains_limit(ts_end, 10)) !=
                         RD_POLL_NOWAIT);

Logs corresponding to this random occurrence:

21:34:45.111349179 [Debug ] [KAFKA_PRODUCER] [main] [7] [TXNCOMMIT] [thrd:app]: Flushing 233922 outstanding message(s) prior to commit
21:34:45.111351098 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 0, tmout=0
21:34:45.111452272 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [PRODUCE] [thrd:host1168:9092/3]: host1168:9092/3:transactions_topic_1 [0]: No more space in current MessageSet (2375 message(s), 999843 bytes)
21:34:45.111966843 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 229170, tmout=10
21:34:45.119146928 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [PRODUCE] [thrd:host1168:9092/3]: host1168:9092/3:transactions_topic_1 [0]: Produce MessageSet with 2375 message(s) (50196 bytes, ApiVersion 7, MsgVersion 2, MsgId 251639, BaseSeq 251638, PID{Id:165217,Epoch:38}, gzip)
21:34:45.119285873 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [SEND] [thrd:host1168:9092/3]: host1168:9092/3: Sent ProduceRequest (v7, 50288 bytes @ 0, CorrId 116)
21:34:45.122153084 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 229170, tmout=10
21:34:45.132259884 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 229170, tmout=10
21:34:45.136198162 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [RECV] [thrd:host1168:9092/3]: host1168:9092/3: Received ProduceResponse (v7, 71 bytes, CorrId 116, rtt 16.91ms)
21:34:45.136202516 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [MSGSET] [thrd:host1168:9092/3]: host1168:9092/3:transactions_topic_1 [0]: MessageSet with 2375 message(s) (MsgId 251639, BaseSeq 251638) delivered
21:34:45.136767506 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 226795, tmout=10
21:34:45.137642245 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [TOPPAR] [thrd:host1168:9092/3]: host1168:9092/3:transactions_topic_1 [0] 29425 message(s) in xmit queue (0 added from partition queue)
21:34:45.138724780 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [PRODUCE] [thrd:host1168:9092/3]: host1168:9092/3:transactions_topic_1 [0]: No more space in current MessageSet (2376 message(s), 999912 bytes)
21:34:45.145924617 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [PRODUCE] [thrd:host1168:9092/3]: host1168:9092/3:transactions_topic_1 [0]: Produce MessageSet with 2376 message(s) (50738 bytes, ApiVersion 7, MsgVersion 2, MsgId 254014, BaseSeq 254013, PID{Id:165217,Epoch:38}, gzip)
21:34:45.146094317 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [SEND] [thrd:host1168:9092/3]: host1168:9092/3: Sent ProduceRequest (v7, 50830 bytes @ 0, CorrId 117)
21:34:45.146883478 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 226795, tmout=10
21:34:45.153058770 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [`] [thrd:host1045:9092/2]: host1045:9092/2: routing.tj [0] 1 message(s) in xmit queue (0 added from partition queue)
21:34:45.153106539 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [PRODUCE] [thrd:host1045:9092/2]: host1045:9092/2: routing.tj [0]: Produce MessageSet with 1 message(s) (137 bytes, ApiVersion 7, MsgVersion 2, MsgId 52, BaseSeq 51, PID{Id:165217,Epoch:38}, uncompressed)
21:34:45.153137989 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [SEND] [thrd:host1045:9092/2]: host1045:9092/2: Sent ProduceRequest (v7, 212 bytes @ 0, CorrId 50)
21:34:45.153142656 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [TOPPAR] [thrd:host1045:9092/2]: host1045:9092/2: transactions_topic_2 [0] 24 message(s) in xmit queue (0 added from partition queue)
21:34:45.154261549 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [TOPPAR] [thrd:host1045:9092/2]: host1045:9092/2: transactions_topic_2 [0] 24 message(s) in xmit queue (0 added from partition queue)
21:34:45.154379681 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [PRODUCE] [thrd:host1045:9092/2]: host1045:9092/2: transactions_topic_2 [0]: Produce MessageSet with 24 message(s) (1082 bytes, ApiVersion 7, MsgVersion 2, MsgId 35853, BaseSeq 35852, PID{Id:165217,Epoch:38}, gzip)
21:34:45.154396876 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [SEND] [thrd:host1045:9092/2]: host1045:9092/2: Sent ProduceRequest (v7, 1174 bytes @ 0, CorrId 51)
21:34:45.157097396 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 226795, tmout=10
21:34:45.529369855 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [PRODUCE] [thrd:host1168:9092/3]: host1168:9092/3:transactions_topic_1 [0]: Produce MessageSet with 921 message(s) (20560 bytes, ApiVersion 7, MsgVersion 2, MsgId 282518, BaseSeq 282517, PID{Id:165217,Epoch:38}, gzip)
21:34:45.529423780 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [SEND] [thrd:host1168:9092/3]: host1168:9092/3: Sent ProduceRequest (v7, 20652 bytes @ 0, CorrId 129)
21:34:45.536822639 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 198266, tmout=10
21:34:45.543460792 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [RECV] [thrd:host1168:9092/3]: host1168:9092/3: Received ProduceResponse (v7, 71 bytes, CorrId 129, rtt 14.03ms)
21:34:45.543467698 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [MSGSET] [thrd:host1168:9092/3]: host1168:9092/3:transactions_topic_1 [0]: MessageSet with 921 message(s) (MsgId 282518, BaseSeq 282517) delivered
21:34:45.543749182 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 197345, tmout=10
21:34:45.553894886 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 197345, tmout=10
21:34:45.563976535 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 197345, tmout=10
21:34:45.574101480 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 197345, tmout=10
21:34:45.584185623 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 197345, tmout=10
21:34:45.594310202 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 197345, tmout=10
21:34:45.607345307 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 197345, tmout=10
21:34:45.626441208 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 197345, tmout=10
21:34:45.643414689 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 197345, tmout=10
21:34:45.653558133 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 197345, tmout=10
21:34:45.663673046 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 197345, tmout=10
21:34:45.673807440 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 197345, tmout=10
21:34:45.683932938 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 197345, tmout=10
21:34:45.694048281 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 197345, tmout=10
...........
...........
21:37:41.098129400 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 197345, tmout=10
21:37:41.108279497 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 197345, tmout=10
21:37:41.118364616 [Debug ] [KAFKA_PRODUCER] [main] [7] [MY_DEBUG] [thrd:app]: queue count = 0, msg_cnt = 197345, tmout=10
.....
21:37:43.538912495 [Debug ] [KAFKA_PRODUCER] [anonymous] [7] [TIMEOUT] [thrd:host1168:9092/3]: host1168:9092/3: transactions_topic_1 [0]: timed out 0+11 message(s) (MsgId 14500..14510): message.timeout.ms exceeded
....
21:37:45.111214321 [Error ] [KAFKA_PRODUCER] [anonymous] [3] [TXNERR] [thrd:main]: Current transaction failed: Transactional operation timed out (_TIMED_OUT)

Message and transaction timeout is set to 3 mins above
It appears that, rd_kafka_broker_producer_serve or some API on that flow is preventing the serve in the queue.

One peculiarity in my application is that the librdkafka archive library is built using gcc 4.8.5, but my , application is built using clang 5.0.1.

Based on this info could you suggest pointers as to what might be going wrong here?

@sanjay24
Copy link
Contributor Author

sanjay24 commented Sep 17, 2020

hey @edenhill

I further narrowed the problem to this block of code

       /* code from rdkafka_broker.c */

        } else if (unlikely(rd_kafka_is_transactional(rkb->rkb_rk) &&
                            !rd_kafka_txn_toppar_may_send_msg(rktp))) { // rktp is still in RD_KAFKA_TOPPAR_F_PEND_TXN
                /* Partition not registered in transaction yet */
                max_requests = 0;
        } else if (max_requests > 0) {

In my case rd_kafka_txn_add_partition gets called from rd_kafka_msg_partitioner but randomly for some topic-partitions, it doesn't schedule rd_kafka_txn_schedule_register_partitions as a result of which this rktp never gets added to the transaction, and eventually it leads to message/transaction timeout leading to abortable error on the transaction.

I couldn't understand why the rktp registration would be scheduled only when rk->rk_eos.txn_pending_rktps is empty? Why can't we schedule it every time there's new rktp available for registration as there's check that prevents rktp already added/registered.

       /* snip from from rdkafka_txnmgr.h */
       /* Already added or registered */
        if (likely(rktp->rktp_flags &
                   (RD_KAFKA_TOPPAR_F_PEND_TXN | RD_KAFKA_TOPPAR_F_IN_TXN))) {
                rd_kafka_toppar_unlock(rktp);
                return;
        }
        ....
        ....
       schedule = TAILQ_EMPTY(&rk->rk_eos.txn_pending_rktps);    // why schedule on TAILQ_EMPTY??

        /* List is sorted by topic name since AddPartitionsToTxnRequest()
         * requires it. */
        TAILQ_INSERT_SORTED(&rk->rk_eos.txn_pending_rktps, rktp,
                            rd_kafka_toppar_t *, rktp_txnlink,
                            rd_kafka_toppar_topic_cmp);
        rd_kafka_toppar_keep(rktp);
        mtx_unlock(&rk->rk_eos.txn_pending_lock);

        /* Schedule registration of partitions by the rdkafka main thread */
        if (unlikely(schedule))
                rd_kafka_txn_schedule_register_partitions(
                        rk, rd_true/*immediate*/);

@edenhill
Copy link
Contributor

To answer your questions in #3041 (comment)

  1. Though I'm calling rd_kafka_commit_transaction(mProducer, -1) with timeout specified as INFINITE, I don't expect rd_kafka_flush to be stuck for the whole duration of message/transaction timeout (which is 600*1000 ms). Could you help me understand any condition (apart from broker/network going bad, which is not the case here) that would result in rd_kafka_flush() getting stuck like above?

If you pass an infinite timeout it will be used in two different ways; the infinite timeout will be used for the internal call to flush() (since the flush happens first), while the internal API timeout will be adjusted to your transaction.timeout.ms.

It will block on the flush() until all the messages have been delivered or failed, or the timeout hits, whichever comes first. In the case of the timeout a retriable error will be returned and it is okay to call commit_transaction() again.

I managed to reproduce this by setting the partition leaders to an unavailable broker (making the messages wait in queue) and then making the transaction coordinator unavailable just prior to calling commit_transaction(), this resulted in a myriad of timeouts that eventually bubbled up to the application.

One of the issues I found during this test was that messages that failed in the transmission queue, rather than on the request level, did not really flag the transaction as failed, and a transaction_commit() would have succeeded if the app did not take action in the delivery report (which it shouldnt need to do).

The second issue found was that an EndTxnRequest that would fail (for broker or local reasons) could get stuck in endless retries. The fix is to only retry if the state (aborting|committing) allows it.
With this fix in the commit_transaction() fails with an abortable error and the transaction can be restarted.

  1. Do, you think as a workaround I should put a timeout value to rd_kafka_commit_transaction()? Is that a good practice? In such a case should it be a retriable error?

I think it should be fine with passing -1 to commit_transaction().

  1. I'm using a single producer for close to 750 topic partitions. In this case, I saw that rd_kafka_flush got stuck flushing out close to 2000 messages, however, at all other times it was able to flush out close to 80k messages without any problem.

This is not an issue I've been able to reproduce.
The messages may linger in the queues until message.timeout.ms (which is capped by transaction.timeout.ms).

edenhill added a commit that referenced this issue Sep 23, 2020
…tes (#3041)

Previously the transaction could hang on commit_transaction() if an abortable
error was hit and the EndTxnRequest was to be retried.
edenhill added a commit that referenced this issue Sep 29, 2020
…tes (#3041)

Previously the transaction could hang on commit_transaction() if an abortable
error was hit and the EndTxnRequest was to be retried.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants