Connection to node could not be established

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)

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

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

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

  1. node.id is 2 / 3 on the other nodes, right?
  2. Did you use the same cluster ID on all nodes when formatting storage?
  3. 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.
  4. Anything different in the other broker logs or is it the same as node 1’s log?

Hello @dtroiano !

  1. Yes!

  1. No!

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

image

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:

  1. run nc -l 9092 in one shell, and nc -l 9093 on another. Do this on all three
  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.

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”.

image

image

image


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”.

image

image

image

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.

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)

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

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.

1 Like