Saw issue with Zookeeper on initial creation

[TimothySutton81]

I followed the https://strimzi.io/quickstarts/ for kubernetes kind with a k3s cluster, and it looked like the zookeeper on initial pod creation got stuck in the endless loop of having an bind issue with the unresolved address. Below is the log, I saw a few discussions which were saying it was a coredns issue but even after adding a NetworkPolicy to allow all connections to the zookeeper I saw no change. I then just deleted the pod and on recreation of the pod everything worked, and my cluster finished creating. I then deleted the NetworkPolicy I added, and deleted kafka deployment and strimzi operator to start from scratch. When I redeployed the zookeeper didnt get stuck in this same loop, and I tried on another k3s cluster and didnt see it stuck in this loop. Unfortunately I dont have a way to recreate this issue, but it does worry me that its a possibility to get stuck here again in the future. Any suggestions?

2024-04-02 12:07:22,165 INFO Peer state changed: looking (org.apache.zookeeper.server.quorum.QuorumPeer) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:0]:2181)]
2024-04-02 12:07:22,165 WARN PeerState set to LOOKING (org.apache.zookeeper.server.quorum.QuorumPeer) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:0]:2181)]
2024-04-02 12:07:22,165 INFO LOOKING (org.apache.zookeeper.server.quorum.QuorumPeer) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:0]:2181)]
2024-04-02 12:07:22,165 INFO New election. My id = 1, proposed zxid=0x0 (org.apache.zookeeper.server.quorum.FastLeaderElection) [QuorumPeermyid=1(secure=[0:
2024-04-02 12:07:22,165 INFO Notification: my state:LOOKING; n.sid:1, n.state:LOOKING, n.leader:1, n.round:0x44839, n.peerEpoch:0x0, n.zxid:0x0, message format version:0x2, n.config
2024-04-02 12:07:22,365 INFO Peer state changed: leading (org.apache.zookeeper.server.quorum.QuorumPeer) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:0]:2181)]
2024-04-02 12:07:22,366 INFO LEADING (org.apache.zookeeper.server.quorum.QuorumPeer) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:0]:2181)]
2024-04-02 12:07:22,366 INFO minSessionTimeout set to 4000 ms (org.apache.zookeeper.server.ZooKeeperServer) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:0]:2181)
2024-04-02 12:07:22,366 INFO maxSessionTimeout set to 40000 ms (org.apache.zookeeper.server.ZooKeeperServer) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:0]:2181
2024-04-02 12:07:22,366 INFO getData response cache size is initialized with value 400. (org.apache.zookeeper.server.ResponseCache) [QuorumPeermyid=1(secure
2024-04-02 12:07:22,366 INFO getChildren response cache size is initialized with value 400. (org.apache.zookeeper.server.ResponseCache) [QuorumPeermyid=1(se
2024-04-02 12:07:22,366 INFO zookeeper.pathStats.slotCapacity = 60 (org.apache.zookeeper.server.util.RequestPathMetricsCollector) [QuorumPeermyid=1(secure=[
2024-04-02 12:07:22,366 INFO zookeeper.pathStats.slotDuration = 15 (org.apache.zookeeper.server.util.RequestPathMetricsCollector) [QuorumPeermyid=1(secure=[
2024-04-02 12:07:22,366 INFO zookeeper.pathStats.maxDepth = 6 (org.apache.zookeeper.server.util.RequestPathMetricsCollector) [QuorumPeermyid=1(secure=[0:0:0
2024-04-02 12:07:22,366 INFO zookeeper.pathStats.initialDelay = 5 (org.apache.zookeeper.server.util.RequestPathMetricsCollector) [QuorumPeermyid=1(secure=[0
2024-04-02 12:07:22,366 INFO zookeeper.pathStats.delay = 5 (org.apache.zookeeper.server.util.RequestPathMetricsCollector) [QuorumPeermyid=1(secure=[0:0:0:0:
2024-04-02 12:07:22,366 INFO zookeeper.pathStats.enabled = false (org.apache.zookeeper.server.util.RequestPathMetricsCollector) [QuorumPeermyid=1(secure=[0:
2024-04-02 12:07:22,366 INFO The max bytes for all large requests are set to 104857600 (org.apache.zookeeper.server.ZooKeeperServer) [QuorumPeermyid=1(secur
2024-04-02 12:07:22,366 INFO The large request threshold is set to -1 (org.apache.zookeeper.server.ZooKeeperServer) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:
2024-04-02 12:07:22,366 INFO zookeeper.enforce.auth.enabled = false (org.apache.zookeeper.server.AuthenticationHelper) [QuorumPeermyid=1(secure=[0:0:0:0:0:0
2024-04-02 12:07:22,366 INFO zookeeper.enforce.auth.schemes = [] (org.apache.zookeeper.server.AuthenticationHelper) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:
2024-04-02 12:07:22,366 INFO Created server with tickTime 2000 ms minSessionTimeout 4000 ms maxSessionTimeout 40000 ms clientPortListenBacklog -1 datadir /var/lib/zookeeper/data/ver:0]:2181)]
2024-04-02 12:07:22,366 ERROR Couldn't bind to my-cluster-zookeeper-0.my-cluster-zookeeper-nodes.kafka.svc/:2888 (org.apache.zookeeper.server.quorum.Leader) [QuorumPeer[
java.net.SocketException: Unresolved address
at java.base/java.net.ServerSocket.bind(ServerSocket.java:380)
at java.base/java.net.ServerSocket.bind(ServerSocket.java:342)
at org.apache.zookeeper.server.quorum.Leader.createServerSocket(Leader.java:322)
at org.apache.zookeeper.server.quorum.Leader.lambda$new$0(Leader.java:301)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197)
at java.base/java.util.concurrent.ConcurrentHashMap$KeySpliterator.forEachRemaining(ConcurrentHashMap.java:3573)
at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509)
at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499)
at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596)
at org.apache.zookeeper.server.quorum.Leader.(Leader.java:304)
at org.apache.zookeeper.server.quorum.QuorumPeer.makeLeader(QuorumPeer.java:1340)
at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1551)
2024-04-02 12:07:22,366 WARN Unexpected exception (org.apache.zookeeper.server.quorum.QuorumPeer) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:0]:2181)]
java.io.IOException: Leader failed to initialize any of the following sockets: [my-cluster-zookeeper-0.my-cluster-zookeeper-nodes.kafka.svc/:2888]
at org.apache.zookeeper.server.quorum.Leader.(Leader.java:307)
at org.apache.zookeeper.server.quorum.QuorumPeer.makeLeader(QuorumPeer.java:1340)
at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1551)
2024-04-02 12:07:22,366 INFO Peer state changed: looking (org.apache.zookeeper.server.quorum.QuorumPeer) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:0]:2181)]
2024-04-02 12:07:22,366 WARN PeerState set to LOOKING (org.apache.zookeeper.server.quorum.QuorumPeer) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:0]:2181)]
2024-04-02 12:07:22,366 INFO LOOKING (org.apache.zookeeper.server.quorum.QuorumPeer) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:0]:2181)]
2024-04-02 12:07:22,366 INFO New election. My id = 1, proposed zxid=0x0 (org.apache.zookeeper.server.quorum.FastLeaderElection) [QuorumPeermyid=1(secure=[0:
2024-04-02 12:07:22,366 INFO Notification: my state:LOOKING; n.sid:1, n.state:LOOKING, n.leader:1, n.round:0x4483a, n.peerEpoch:0x0, n.zxid:0x0, message format version:0x2, n.config
2024-04-02 12:07:22,566 INFO Peer state changed: leading (org.apache.zookeeper.server.quorum.QuorumPeer) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:0]:2181)]
2024-04-02 12:07:22,566 INFO LEADING (org.apache.zookeeper.server.quorum.QuorumPeer) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:0]:2181)]
2024-04-02 12:07:22,566 INFO minSessionTimeout set to 4000 ms (org.apache.zookeeper.server.ZooKeeperServer) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:0]:2181)
2024-04-02 12:07:22,566 INFO maxSessionTimeout set to 40000 ms (org.apache.zookeeper.server.ZooKeeperServer) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:0]:2181
2024-04-02 12:07:22,566 INFO getData response cache size is initialized with value 400. (org.apache.zookeeper.server.ResponseCache) [QuorumPeermyid=1(secure
2024-04-02 12:07:22,566 INFO getChildren response cache size is initialized with value 400. (org.apache.zookeeper.server.ResponseCache) [QuorumPeermyid=1(se
2024-04-02 12:07:22,566 INFO zookeeper.pathStats.slotCapacity = 60 (org.apache.zookeeper.server.util.RequestPathMetricsCollector) [QuorumPeermyid=1(secure=[
2024-04-02 12:07:22,566 INFO zookeeper.pathStats.slotDuration = 15 (org.apache.zookeeper.server.util.RequestPathMetricsCollector) [QuorumPeermyid=1(secure=[
2024-04-02 12:07:22,566 INFO zookeeper.pathStats.maxDepth = 6 (org.apache.zookeeper.server.util.RequestPathMetricsCollector) [QuorumPeermyid=1(secure=[0:0:0
2024-04-02 12:07:22,566 INFO zookeeper.pathStats.initialDelay = 5 (org.apache.zookeeper.server.util.RequestPathMetricsCollector) [QuorumPeermyid=1(secure=[0
2024-04-02 12:07:22,566 INFO zookeeper.pathStats.delay = 5 (org.apache.zookeeper.server.util.RequestPathMetricsCollector) [QuorumPeermyid=1(secure=[0:0:0:0:
2024-04-02 12:07:22,566 INFO zookeeper.pathStats.enabled = false (org.apache.zookeeper.server.util.RequestPathMetricsCollector) [QuorumPeermyid=1(secure=[0:
2024-04-02 12:07:22,566 INFO The max bytes for all large requests are set to 104857600 (org.apache.zookeeper.server.ZooKeeperServer) [QuorumPeermyid=1(secur
2024-04-02 12:07:22,566 INFO The large request threshold is set to -1 (org.apache.zookeeper.server.ZooKeeperServer) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:
2024-04-02 12:07:22,566 INFO zookeeper.enforce.auth.enabled = false (org.apache.zookeeper.server.AuthenticationHelper) [QuorumPeermyid=1(secure=[0:0:0:0:0:0
2024-04-02 12:07:22,566 INFO zookeeper.enforce.auth.schemes = [] (org.apache.zookeeper.server.AuthenticationHelper) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:
2024-04-02 12:07:22,566 INFO Created server with tickTime 2000 ms minSessionTimeout 4000 ms maxSessionTimeout 40000 ms clientPortListenBacklog -1 datadir /var/lib/zookeeper/data/ver:0]:2181)]
2024-04-02 12:07:22,566 ERROR Couldn't bind to my-cluster-zookeeper-0.my-cluster-zookeeper-nodes.kafka.svc/:2888 (org.apache.zookeeper.server.quorum.Leader) [QuorumPeer[
java.net.SocketException: Unresolved address
at java.base/java.net.ServerSocket.bind(ServerSocket.java:380)
at java.base/java.net.ServerSocket.bind(ServerSocket.java:342)
at org.apache.zookeeper.server.quorum.Leader.createServerSocket(Leader.java:322)
at org.apache.zookeeper.server.quorum.Leader.lambda$new$0(Leader.java:301)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197)
at java.base/java.util.concurrent.ConcurrentHashMap$KeySpliterator.forEachRemaining(ConcurrentHashMap.java:3573)
at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509)
at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499)
at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596)
at org.apache.zookeeper.server.quorum.Leader.(Leader.java:304)
at org.apache.zookeeper.server.quorum.QuorumPeer.makeLeader(QuorumPeer.java:1340)
at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1551)
2024-04-02 12:07:22,567 WARN Unexpected exception (org.apache.zookeeper.server.quorum.QuorumPeer) [QuorumPeermyid=1(secure=[0:0:0:0:0:0:0:0]:2181)]
java.io.IOException: Leader failed to initialize any of the following sockets: [my-cluster-zookeeper-0.my-cluster-zookeeper-nodes.kafka.svc/:2888]
at org.apache.zookeeper.server.quorum.Leader.(Leader.java:307)
at org.apache.zookeeper.server.quorum.QuorumPeer.makeLeader(QuorumPeer.java:1340)
at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1551)

[scholzj]

That suggests some issues with slow or broken DNS in your cluster. Unfortunately, ZooKeeper is quite sensitive to them. If you use the latest Strimzi release (0.40), you can maybe try ZooKeeper-less Kafka with one of these examples: https://github.com/strimzi/strimzi-kafka-operator/tree/main/examples/kafka/kraft

[TimothySutton81]

If deleting the pod fixed it confuses me that DNS would be broken. Maybe slow is the answer, but just surprised that slow would result in it stuck forever that way.

[scholzj]

Right. If deletion helps, it is likely the speed of the DNS.

The problem is that ZooKeeper does not re-resolve it again. So if it fails to resolve it right away, it is happy to live with it forever :-(. There are some older discussions and issues about this in Strimzi that have links to some issues in ZooKeeper.

[TimothySutton81]

Is there any headway on trying to improve the re-resolution or is trying to go forward without the zookeeper really the best bet? I am a little worried that even if I figured out why the dns had an issue this could happen again making start up of kafka failed with out human intervention.

[see-quick]

I think there is an open issue, which should solve such a problem [1]. However, the community around ZooKeeper is kinda slow :/

[1] - apache/zookeeper#2041