Connection to node could not be established

deywillan · 22 February 2024 09:47

Hello!

I’m testing the Kafka cluster implementation on virtual machines using the Confluent Platform Community. I followed the instructions, but when starting the Kafka service, the VMs do not boot up. I ran ping tests between the VMs and telnet to the ports, and everything seems normal.

[2024-02-21 18:21:13,627] INFO Registered kafka:type=kafka.Log4jController MBean (kafka.utils.Log4jControllerRegistration$)
[2024-02-21 18:21:13,799] INFO Setting -D jdk.tls.rejectClientInitiatedRenegotiation=true to disable client-initiated TLS renegotiation (org.apache.zookeeper.common.X509Util)
[2024-02-21 18:21:13,883] INFO Registered signal handlers for TERM, INT, HUP (org.apache.kafka.common.utils.LoggingSignalHandler)
[2024-02-21 18:21:13,892] INFO [ControllerServer id=1] Starting controller (kafka.server.ControllerServer)
[2024-02-21 18:21:14,121] INFO Updated connection-accept-rate max connection creation rate to 2147483647 (kafka.network.ConnectionQuotas)
[2024-02-21 18:21:14,146] INFO [SocketServer listenerType=CONTROLLER, nodeId=1] Created data-plane acceptor and processors for endpoint : ListenerName(CONTROLLER) (kafka.network.SocketServer)
[2024-02-21 18:21:14,153] INFO [SharedServer id=1] Starting SharedServer (kafka.server.SharedServer)
[2024-02-21 18:21:14,183] INFO [LogLoader partition=__cluster_metadata-0, dir=/opt/confluent-platform/data/kafka] Recovering unflushed segment 0. 0/1 recovered for __cluster_metadata-0. (kafka.log.LogLoader)
[2024-02-21 18:21:14,184] INFO [LogLoader partition=__cluster_metadata-0, dir=/opt/confluent-platform/data/kafka] Loading producer state till offset 0 with message format version 2 (kafka.log.UnifiedLog$)
[2024-02-21 18:21:14,185] INFO [LogLoader partition=__cluster_metadata-0, dir=/opt/confluent-platform/data/kafka] Reloading from producer snapshot and rebuilding producer state from offset 0 (kafka.log.UnifiedLog$)
[2024-02-21 18:21:14,185] INFO [LogLoader partition=__cluster_metadata-0, dir=/opt/confluent-platform/data/kafka] Producer state recovery took 0ms for snapshot load and 0ms for segment recovery from offset 0 (kafka.log.UnifiedLog$)
[2024-02-21 18:21:14,191] INFO [LogLoader partition=__cluster_metadata-0, dir=/opt/confluent-platform/data/kafka] Loading producer state till offset 0 with message format version 2 (kafka.log.UnifiedLog$)
[2024-02-21 18:21:14,192] INFO [LogLoader partition=__cluster_metadata-0, dir=/opt/confluent-platform/data/kafka] Reloading from producer snapshot and rebuilding producer state from offset 0 (kafka.log.UnifiedLog$)
[2024-02-21 18:21:14,192] INFO [LogLoader partition=__cluster_metadata-0, dir=/opt/confluent-platform/data/kafka] Producer state recovery took 0ms for snapshot load and 0ms for segment recovery from offset 0 (kafka.log.UnifiedLog$)
[2024-02-21 18:21:14,213] INFO Initialized snapshots with IDs SortedSet() from /opt/confluent-platform/data/kafka/__cluster_metadata-0 (kafka.raft.KafkaMetadataLog$)
[2024-02-21 18:21:14,223] INFO [raft-expiration-reaper]: Starting (kafka.raft.TimingWheelExpirationService$ExpiredOperationReaper)
[2024-02-21 18:21:14,317] INFO [RaftManager id=1] Completed transition to CandidateState(localId=1, epoch=2970, retries=1, voteStates={1=GRANTED, 2=UNRECORDED, 3=UNRECORDED}, highWatermark=Optional.empty, electionTimeoutMs=1190) from null (org.apache.kafka.raft.QuorumState)
[2024-02-21 18:21:14,320] INFO [kafka-1-raft-outbound-request-thread]: Starting (kafka.raft.RaftSendThread)
[2024-02-21 18:21:14,321] INFO [kafka-1-raft-io-thread]: Starting (kafka.raft.KafkaRaftManager$RaftIoThread)
[2024-02-21 18:21:14,339] INFO [ControllerServer id=1] Waiting for controller quorum voters future (kafka.server.ControllerServer)
[2024-02-21 18:21:14,339] INFO [ControllerServer id=1] Finished waiting for controller quorum voters future (kafka.server.ControllerServer)
[2024-02-21 18:21:14,342] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:14,358] INFO [RaftManager id=1] Registered the listener org.apache.kafka.image.loader.MetadataLoader@1637960569 (org.apache.kafka.raft.KafkaRaftClient)
[2024-02-21 18:21:14,374] INFO [RaftManager id=1] Node 2 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:14,375] WARN [RaftManager id=1] Connection to node 2 (/192.168.28.111:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:14,378] INFO [RaftManager id=1] Node 3 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:14,378] WARN [RaftManager id=1] Connection to node 3 (/192.168.28.112:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:14,442] INFO [RaftManager id=1] Node 3 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:14,442] WARN [RaftManager id=1] Connection to node 3 (/192.168.28.112:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:14,444] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:14,453] INFO [RaftManager id=1] Node 2 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:14,453] WARN [RaftManager id=1] Connection to node 2 (/192.168.28.111:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:14,538] INFO [RaftManager id=1] Node 3 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:14,538] WARN [RaftManager id=1] Connection to node 3 (/192.168.28.112:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:14,544] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:14,562] INFO [RaftManager id=1] Node 2 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:14,562] WARN [RaftManager id=1] Connection to node 2 (/192.168.28.111:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:14,644] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:14,681] INFO [RaftManager id=1] Registered the listener org.apache.kafka.controller.QuorumController$QuorumMetaLogListener@553834878 (org.apache.kafka.raft.KafkaRaftClient)
[2024-02-21 18:21:14,688] INFO [controller-1-ThrottledChannelReaper-Fetch]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
[2024-02-21 18:21:14,690] INFO [controller-1-ThrottledChannelReaper-Produce]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
[2024-02-21 18:21:14,691] INFO [controller-1-ThrottledChannelReaper-Request]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
[2024-02-21 18:21:14,693] INFO [controller-1-ThrottledChannelReaper-ControllerMutation]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
[2024-02-21 18:21:14,713] INFO [ExpirationReaper-1-AlterAcls]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)
[2024-02-21 18:21:14,716] INFO [SocketServer listenerType=CONTROLLER, nodeId=1] Enabling request processing. (kafka.network.SocketServer)
[2024-02-21 18:21:14,723] INFO Awaiting socket connections on 192.168.28.110:9093. (kafka.network.DataPlaneAcceptor)
[2024-02-21 18:21:14,725] INFO [ControllerServer id=1] Waiting for all of the authorizer futures to be completed (kafka.server.ControllerServer)
[2024-02-21 18:21:14,725] INFO [ControllerServer id=1] Finished waiting for all of the authorizer futures to be completed (kafka.server.ControllerServer)
[2024-02-21 18:21:14,725] INFO [ControllerServer id=1] Waiting for all of the SocketServer Acceptors to be started (kafka.server.ControllerServer)
[2024-02-21 18:21:14,726] INFO [ControllerServer id=1] Finished waiting for all of the SocketServer Acceptors to be started (kafka.server.ControllerServer)
[2024-02-21 18:21:14,729] INFO [ControllerServer id=1] Waiting for the controller metadata publishers to be installed (kafka.server.ControllerServer)
[2024-02-21 18:21:14,729] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:14,729] INFO [ControllerServer id=1] Finished waiting for the controller metadata publishers to be installed (kafka.server.ControllerServer)
[2024-02-21 18:21:14,730] INFO [BrokerServer id=1] Transition from SHUTDOWN to STARTING (kafka.server.BrokerServer)
[2024-02-21 18:21:14,730] INFO [BrokerServer id=1] Starting broker (kafka.server.BrokerServer)
[2024-02-21 18:21:14,747] INFO [broker-1-ThrottledChannelReaper-Fetch]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
[2024-02-21 18:21:14,747] INFO [broker-1-ThrottledChannelReaper-Request]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
[2024-02-21 18:21:14,747] INFO [broker-1-ThrottledChannelReaper-ControllerMutation]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
[2024-02-21 18:21:14,749] INFO [broker-1-ThrottledChannelReaper-Produce]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
[2024-02-21 18:21:14,759] INFO [RaftManager id=1] Node 2 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:14,762] WARN [RaftManager id=1] Connection to node 2 (/192.168.28.111:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:14,762] INFO [RaftManager id=1] Node 3 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:14,762] WARN [RaftManager id=1] Connection to node 3 (/192.168.28.112:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:14,766] INFO [BrokerServer id=1] Waiting for controller quorum voters future (kafka.server.BrokerServer)
[2024-02-21 18:21:14,767] INFO [BrokerServer id=1] Finished waiting for controller quorum voters future (kafka.server.BrokerServer)
[2024-02-21 18:21:14,776] INFO [broker-1-to-controller-forwarding-channel-manager]: Starting (kafka.server.BrokerToControllerRequestThread)
[2024-02-21 18:21:14,817] INFO Updated connection-accept-rate max connection creation rate to 2147483647 (kafka.network.ConnectionQuotas)
[2024-02-21 18:21:14,824] INFO [SocketServer listenerType=BROKER, nodeId=1] Created data-plane acceptor and processors for endpoint : ListenerName(PLAINTEXT) (kafka.network.SocketServer)
[2024-02-21 18:21:14,829] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:14,838] INFO [broker-1-to-controller-alter-partition-channel-manager]: Starting (kafka.server.BrokerToControllerRequestThread)
[2024-02-21 18:21:14,847] INFO [ExpirationReaper-1-Produce]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)
[2024-02-21 18:21:14,848] INFO [ExpirationReaper-1-Fetch]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)
[2024-02-21 18:21:14,849] INFO [ExpirationReaper-1-DeleteRecords]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)
[2024-02-21 18:21:14,850] INFO [ExpirationReaper-1-ElectLeader]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)
[2024-02-21 18:21:14,864] INFO [ExpirationReaper-1-Heartbeat]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)
[2024-02-21 18:21:14,871] INFO [ExpirationReaper-1-Rebalance]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)
[2024-02-21 18:21:14,900] INFO [broker-1-to-controller-heartbeat-channel-manager]: Starting (kafka.server.BrokerToControllerRequestThread)
[2024-02-21 18:21:14,902] INFO [BrokerLifecycleManager id=1] Incarnation iSWHBvj4S8S6m4DvQmuMDQ of broker 1 in cluster kwwm930QRqaLaJvBmVTRRQ is now STARTING. (kafka.server.BrokerLifecycleManager)
[2024-02-21 18:21:14,919] INFO [ExpirationReaper-1-AlterAcls]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)
[2024-02-21 18:21:14,931] INFO [BrokerServer id=1] Waiting for the broker metadata publishers to be installed (kafka.server.BrokerServer)
[2024-02-21 18:21:14,931] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:14,932] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:14,932] INFO [BrokerServer id=1] Finished waiting for the broker metadata publishers to be installed (kafka.server.BrokerServer)
[2024-02-21 18:21:14,932] INFO [BrokerServer id=1] Waiting for the controller to acknowledge that we are caught up (kafka.server.BrokerServer)
[2024-02-21 18:21:15,032] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:15,109] INFO [RaftManager id=1] Node 2 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:15,109] WARN [RaftManager id=1] Connection to node 2 (/192.168.28.111:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:15,132] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:15,212] INFO [RaftManager id=1] Node 3 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:15,212] WARN [RaftManager id=1] Connection to node 3 (/192.168.28.112:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:15,232] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:15,333] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:15,433] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:15,491] INFO [RaftManager id=1] Election has timed out, backing off for 0ms before becoming a candidate again (org.apache.kafka.raft.KafkaRaftClient)
[2024-02-21 18:21:15,491] INFO [RaftManager id=1] Re-elect as candidate after election backoff has completed (org.apache.kafka.raft.KafkaRaftClient)
[2024-02-21 18:21:15,506] INFO [RaftManager id=1] Completed transition to CandidateState(localId=1, epoch=2971, retries=2, voteStates={1=GRANTED, 2=UNRECORDED, 3=UNRECORDED}, highWatermark=Optional.empty, electionTimeoutMs=1800) from CandidateState(localId=1, epoch=2970, retries=1, voteStates={1=GRANTED, 2=UNRECORDED, 3=UNRECORDED}, highWatermark=Optional.empty, electionTimeoutMs=1190) (org.apache.kafka.raft.QuorumState)
[2024-02-21 18:21:15,533] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:15,545] INFO [RaftManager id=1] Node 2 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:15,545] WARN [RaftManager id=1] Connection to node 2 (/192.168.28.111:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:15,633] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:15,733] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:15,788] INFO [RaftManager id=1] Node 3 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:15,788] WARN [RaftManager id=1] Connection to node 3 (/192.168.28.112:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:15,834] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:15,934] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:16,034] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:16,040] INFO [RaftManager id=1] Node 2 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:16,040] WARN [RaftManager id=1] Connection to node 2 (/192.168.28.111:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:16,135] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:16,229] INFO [RaftManager id=1] Node 3 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:16,229] WARN [RaftManager id=1] Connection to node 3 (/192.168.28.112:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:16,235] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:16,339] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:16,439] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:16,540] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:16,618] INFO [RaftManager id=1] Node 2 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:16,618] WARN [RaftManager id=1] Connection to node 2 (/192.168.28.111:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:16,640] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:16,683] INFO [RaftManager id=1] Node 3 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:16,683] WARN [RaftManager id=1] Connection to node 3 (/192.168.28.112:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:16,741] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:16,844] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:16,945] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:17,046] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:17,052] INFO [RaftManager id=1] Node 2 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:17,052] WARN [RaftManager id=1] Connection to node 2 (/192.168.28.111:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:17,147] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:17,222] INFO [RaftManager id=1] Node 3 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:17,223] WARN [RaftManager id=1] Connection to node 3 (/192.168.28.112:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:17,247] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:17,291] INFO [RaftManager id=1] Election has timed out, backing off for 100ms before becoming a candidate again (org.apache.kafka.raft.KafkaRaftClient)
[2024-02-21 18:21:17,348] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:17,392] INFO [RaftManager id=1] Re-elect as candidate after election backoff has completed (org.apache.kafka.raft.KafkaRaftClient)
[2024-02-21 18:21:17,401] INFO [RaftManager id=1] Completed transition to CandidateState(localId=1, epoch=2972, retries=3, voteStates={1=GRANTED, 2=UNRECORDED, 3=UNRECORDED}, highWatermark=Optional.empty, electionTimeoutMs=1133) from CandidateState(localId=1, epoch=2971, retries=2, voteStates={1=GRANTED, 2=UNRECORDED, 3=UNRECORDED}, highWatermark=Optional.empty, electionTimeoutMs=1800) (org.apache.kafka.raft.QuorumState)
[2024-02-21 18:21:17,449] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:17,550] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:17,620] INFO [RaftManager id=1] Node 2 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:17,621] WARN [RaftManager id=1] Connection to node 2 (/192.168.28.111:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:17,653] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:17,754] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:17,826] INFO [RaftManager id=1] Node 3 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:17,827] WARN [RaftManager id=1] Connection to node 3 (/192.168.28.112:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:17,855] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:17,956] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:18,057] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:18,090] INFO [RaftManager id=1] Node 2 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:18,091] WARN [RaftManager id=1] Connection to node 2 (/192.168.28.111:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:18,157] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:18,257] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:18,357] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:18,396] INFO [RaftManager id=1] Node 3 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:18,396] WARN [RaftManager id=1] Connection to node 3 (/192.168.28.112:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:18,458] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:18,528] INFO [RaftManager id=1] Election has timed out, backing off for 500ms before becoming a candidate again (org.apache.kafka.raft.KafkaRaftClient)
[2024-02-21 18:21:18,558] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:18,658] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:18,759] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:18,860] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:18,960] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:19,028] INFO [RaftManager id=1] Re-elect as candidate after election backoff has completed (org.apache.kafka.raft.KafkaRaftClient)
[2024-02-21 18:21:19,039] INFO [RaftManager id=1] Completed transition to CandidateState(localId=1, epoch=2973, retries=4, voteStates={1=GRANTED, 2=UNRECORDED, 3=UNRECORDED}, highWatermark=Optional.empty, electionTimeoutMs=1218) from CandidateState(localId=1, epoch=2972, retries=3, voteStates={1=GRANTED, 2=UNRECORDED, 3=UNRECORDED}, highWatermark=Optional.empty, electionTimeoutMs=1133) (org.apache.kafka.raft.QuorumState)
[2024-02-21 18:21:19,040] INFO [RaftManager id=1] Node 2 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:19,040] WARN [RaftManager id=1] Connection to node 2 (/192.168.28.111:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:19,041] INFO [RaftManager id=1] Node 3 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:19,041] WARN [RaftManager id=1] Connection to node 3 (/192.168.28.112:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:19,060] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:19,161] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:19,261] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:19,361] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:19,416] INFO [BrokerLifecycleManager id=1] Unable to register the broker because the RPC got timed out before it could be sent. (kafka.server.BrokerLifecycleManager)
[2024-02-21 18:21:19,461] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:19,524] INFO [RaftManager id=1] Node 2 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:19,525] WARN [RaftManager id=1] Connection to node 2 (/192.168.28.111:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:19,562] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:19,603] INFO [RaftManager id=1] Node 3 disconnected. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:19,603] WARN [RaftManager id=1] Connection to node 3 (/192.168.28.112:9093) could not be established. Broker may not be available. (org.apache.kafka.clients.NetworkClient)
[2024-02-21 18:21:19,662] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:19,762] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:19,863] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:19,963] INFO [MetadataLoader id=1] initializeNewPublishers: the loader is still catching up because we still don’t know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
[2024-02-21 18:21:20,024] INFO [RaftManager id=1] Node 2 disconnected. (org.apache.kafka.clients.NetworkClient)

dtroiano · 22 February 2024 14:29

What do your broker properties look like for the 3 nodes?

deywillan · 22 February 2024 15:07

Below are the details from the server.properties file. This example is from computer 1, but these settings are the same for the other computers.

process.roles=broker,controller
node.id=1
controller.quorum.voters=1@192.168.28.110:9093,2@192.168.28.111:9093,3@192.168.28.112:9093
listeners=PLAINTEXT://192.168.28.110:9092,CONTROLLER://192.168.28.110:9093
inter.broker.listener.name=PLAINTEXT
advertised.listeners=PLAINTEXT://192.168.28.110:9092
controller.listener.names=CONTROLLER
listener.security.protocol.map=CONTROLLER:PLAINTEXT,PLAINTEXT:PLAINTEXT,SSL:SSL,SASL_PLAINTEXT:SASL_PLAINTEXT,SASL_SSL:SASL_SSL
num.network.threads=3
num.io.threads=8
socket.send.buffer.bytes=102400
socket.receive.buffer.bytes=102400
socket.request.max.bytes=104857600
log.dirs=/opt/confluent-platform/data/kafka
num.partitions=1
num.recovery.threads.per.data.dir=1
offsets.topic.replication.factor=1
transaction.state.log.replication.factor=1
transaction.state.log.min.isr=1
log.segment.bytes=1073741824
log.retention.check.interval.ms=300000
group.initial.rebalance.delay.ms=0
confluent.license.topic.replication.factor=1
confluent.metadata.topic.replication.factor=1
confluent.security.event.logger.exporter.kafka.topic.replicas=1
confluent.balancer.enable=true
confluent.balancer.topic.replication.factor=1

dtroiano · 23 February 2024 15:23

Nothing is jumping out at me. A few things to sanity check:

node.id is 2 / 3 on the other nodes, right?
Did you use the same cluster ID on all nodes when formatting storage?
How did you test with telnet? nc -l 9093 on one and telnet <ip> 9093 on the other? Do that with ports 9093 (and 9092) among all three nodes if you haven’t already.
Anything different in the other broker logs or is it the same as node 1’s log?

deywillan · 23 February 2024 18:59

Hello @dtroiano !

Yes!

image1274×377 73.7 KB

No!

image739×135 18 KB

Test with telnet. Actually port 9092 is not listening. But no firewall on the system. It is disabled.

dtroiano · 23 February 2024 20:11

You’ll want to use the same cluster ID for all three.

For the telnet test, try using nc to listen. I’m not sure if this is what you did or if you’re using Kafka – nc is the safer networking test since Kafka isn’t starting successfully. The nc command will either be available or depending on your OS you can install it (eg., yum install -y nc). You just want to make sure that once the broker is listening on 9092 and 9093 that there won’t be an issue. With Kafka stopped on all nodes:

run nc -l 9092 in one shell, and nc -l 9093 on another. Do this on all three
From each of the three nodes, run telnet <IP> 9092 and telnet <IP> 9093 for each of the other 2 nodes. ensure that you see Connected to <IP>. Escape character is '^]'. for all 6 telnet commands.

deywillan · 25 February 2024 23:59

Dear @dtroiano,

I hope this message finds you well. I wanted to express my heartfelt gratitude for your prompt and valuable assistance. Your support has been immensely helpful, and I truly appreciate the time and effort you have dedicated to helping me.

You’ll want to use the same cluster ID for all three.

I didn’t understand this part. For the three nodes, 3 IDs were generated using the command kafka-storage.sh random-uuid. And for each node, in the server.properties file, under the “node.id” field, a different ID was assigned for each of the 3 nodes.

1. run nc -l 9092 in one shell, and nc -l 9093 on another. Do this on all three

As suggested, the commands nc -l 9092 and nc -l 9093 were executed on all 3 nodes. For the test on port 9092, on all 3 nodes, the command returned no result. For the test on port 9093, on node 1, the output was “nc: Address already in use”, and for the other nodes, the response was “raft-client-1apache-kafka-java”.

2. From each of the three nodes, run telnet <IP> 9092 and telnet <IP> 9093 for each of the other 2 nodes. ensure that you see Connected to <IP>. Escape character is '^]'. for all 6 telnet commands.

With the Kafka service stopped, I executed the telnet command for ports 9092 and 9093, and the response was “telnet: Unable to connect to remote host: Connection refused”.

dtroiano · 26 February 2024 15:56

You should run kafka-storage random-uuid only once to get an ID, and then use that same ID when formatting storage on the three nodes (see here).

The port being in use is problematic for the network connectivity test and for starting Kafka so you should kill the process listening on port 9093. You can find the process listening on 9093 either with lsof or netstat. E.g., on most Linux distributions netstat -anp | grep 9093 will show you the process ID listening on 9093 in the last column.

Also, you should leave the 6 nc commands running, not Ctrl-C out of them as in the screenshots. These are the listeners simulating the Kafka listeners so they should be running when you run the telnet commands.

deywillan · 27 February 2024 02:48

Alright!

I changed the cluster id for the 3 nodes. Now it is the same for the 3 nodes.

I also updated the server.properties file:

I tried starting again. Now a new log is being shown.

[2024-02-27 02:46:19,707] INFO Registered kafka:type=kafka.Log4jController MBean (kafka.utils.Log4jControllerRegistration$)
[2024-02-27 02:46:19,891] INFO Setting -D jdk.tls.rejectClientInitiatedRenegotiation=true to disable client-initiated TLS renegotiation (org.apache.zookeeper.common.X509Util)
[2024-02-27 02:46:19,980] INFO Registered signal handlers for TERM, INT, HUP (org.apache.kafka.common.utils.LoggingSignalHandler)
[2024-02-27 02:46:19,989] INFO [ControllerServer id=1] Starting controller (kafka.server.ControllerServer)
[2024-02-27 02:46:20,222] INFO Updated connection-accept-rate max connection creation rate to 2147483647 (kafka.network.ConnectionQuotas)
[2024-02-27 02:46:20,248] INFO [SocketServer listenerType=CONTROLLER, nodeId=1] Created data-plane acceptor and processors for endpoint : ListenerName(CONTROLLER) (kafka.network.SocketServer)
[2024-02-27 02:46:20,249] INFO [SharedServer id=1] Starting SharedServer (kafka.server.SharedServer)
[2024-02-27 02:46:20,261] ERROR [SharedServer id=1] Got exception while starting SharedServer (kafka.server.SharedServer)
java.nio.file.AccessDeniedException: /opt/confluent-platform/data/kraft/kraft-combined-logs/__cluster_metadata-0
	at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:90)
	at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111)
	at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:116)
	at java.base/sun.nio.fs.UnixFileSystemProvider.createDirectory(UnixFileSystemProvider.java:389)
	at java.base/java.nio.file.Files.createDirectory(Files.java:690)
	at java.base/java.nio.file.Files.createAndCheckIsDirectory(Files.java:797)
	at java.base/java.nio.file.Files.createDirectories(Files.java:783)
	at kafka.raft.KafkaRaftManager$.kafka$raft$KafkaRaftManager$$createLogDirectory(RaftManager.scala:94)
	at kafka.raft.KafkaRaftManager.createDataDir(RaftManager.scala:259)
	at kafka.raft.KafkaRaftManager.<init>(RaftManager.scala:152)
	at kafka.server.SharedServer.start(SharedServer.scala:247)
	at kafka.server.SharedServer.startForController(SharedServer.scala:129)
	at kafka.server.ControllerServer.startup(ControllerServer.scala:197)
	at kafka.server.KafkaRaftServer.$anonfun$startup$1(KafkaRaftServer.scala:95)
	at kafka.server.KafkaRaftServer.$anonfun$startup$1$adapted(KafkaRaftServer.scala:95)
	at scala.Option.foreach(Option.scala:437)
	at kafka.server.KafkaRaftServer.startup(KafkaRaftServer.scala:95)
	at kafka.Kafka$.main(Kafka.scala:113)
	at kafka.Kafka.main(Kafka.scala)
[2024-02-27 02:46:20,262] INFO [ControllerServer id=1] Waiting for controller quorum voters future (kafka.server.ControllerServer)
[2024-02-27 02:46:20,263] INFO [ControllerServer id=1] Finished waiting for controller quorum voters future (kafka.server.ControllerServer)
[2024-02-27 02:46:20,263] ERROR Encountered fatal fault: caught exception (org.apache.kafka.server.fault.ProcessTerminatingFaultHandler)
java.lang.NullPointerException
	at kafka.server.ControllerServer.startup(ControllerServer.scala:210)
	at kafka.server.KafkaRaftServer.$anonfun$startup$1(KafkaRaftServer.scala:95)
	at kafka.server.KafkaRaftServer.$anonfun$startup$1$adapted(KafkaRaftServer.scala:95)
	at scala.Option.foreach(Option.scala:437)
	at kafka.server.KafkaRaftServer.startup(KafkaRaftServer.scala:95)
	at kafka.Kafka$.main(Kafka.scala:113)
	at kafka.Kafka.main(Kafka.scala)

dtroiano · 27 February 2024 14:40

The user that you’re starting services as doesn’t have permission to write to log.dirs:

java.nio.file.AccessDeniedException: /opt/confluent-platform/data/kraft/kraft-combined-logs/__cluster_metadata-0

You’ll need to change ownership and / or permissions of /opt/confluent-platform/data/kraft/kraft-combined-logs. Since it doesn’t seem that you’ve gotten the broker to start successfully yet, I’d recommend starting over from scratch with kafka owning that directory (assuming that’s the user running the broker):

rm -rf /opt/confluent-platform/data/kraft/kraft-combined-logs/*
chown kafka /opt/confluent-platform/data/kraft/kraft-combined-logs
chmod 755 /opt/confluent-platform/data/kraft/kraft-combined-logs

deywillan · 28 February 2024 19:31

Hello @dtroiano !

Thank you for the guidance. I reviewed the entire configuration process along with your instructions and was able to start the cluster with the 3 nodes.

yuksel · 23 April 2024 02:55

Hi @deywillan If it is possible could you share your yaml file so I can review.

Kafka Pods Failing with AuthorizerNotReadyException after Enabling ACLs (Bitnami Helm Chart - 3.6.1)

I’m encountering issues with Kafka pods failing after enabling Access Control Lists (ACLs) in a Bitnami Kafka deployment (version 3.6.1 on Debian 12) managed with Helm. Here’s the process I followed:

Cloned Bitnami Kafka Helm Chart: I cloned the Bitnami Kafka Helm chart from the official repository:git clone https://github.com/bitnami/containers/tree/main/bitnami/kafka/3.6/debian-12
Generated Deployment YAML: I used the helm template command to generate a deployment YAML file (output.yaml) from the Helm chart, overriding values with a custom values.yaml file:helm template . -f values.yaml > output.yaml
Enabled SASL: Prior to enabling ACLs, I successfully configured SASL (Security and Authentication Layer) within the generated output.yaml file.
Enabled ACLs and Encountered Error: When I attempted to enable ACLs by setting authorizer.class.name=org.apache.kafka.metadata.authorizer.StandardAuthorizer (reference: Authorization in Confluent Platform using ACLs | Confluent Documentation), my Kafka pods started failing with the following error:[2024-04-22...] ERROR [ControllerApis nodeId=0] Unexpected error handling request ... (kafka.server.ControllerApis) org.apache.kafka.common.errors.AuthorizerNotReadyException This error suggests there might be connectivity issues between Kafka broker nodes.
- I’ve already deployed the Kafka cluster using the generated output.yaml file.

I’m also experiencing connection issues (separate from the ACL error), but haven’t included those details here for clarity.

Question

Has anyone encountered a similar AuthorizerNotReadyException related to ACL implementation in a Bitnami Kafka deployment? Any insights or suggestions on troubleshooting this issue would be greatly appreciated.

Topic		Replies	Views
Unable to connect to Kafka - Confluent Cloud Confluent Cloud	1	2980	25 August 2022
Diagnose failed authentication Ops	9	6983	21 October 2022
Problem with the activate SSL security Lounge	10	4631	12 November 2021
Can't connect to broker in Confluent Cloud Confluent Cloud	4	3285	7 December 2022
Connection to node -1 (localhost/127.0.0.1:9092) could not be established. Broker may not be available Clients	3	14540	30 March 2022

Connection to node could not be established

Related Topics