Strimzi-kafka-operator: Broker cannot connect to Zookeeper

[lluzza]

Hi,

We had a working cluster with 3 brokers and 3 zookeepers but all of a sudden 2 brokers won't go online and keep in CrashLoopBackOff state with these error messages:

kafka.zookeeper.ZooKeeperClientTimeoutException: Timed out waiting for connection while in state: CONNECTING
at kafka.zookeeper.ZooKeeperClient.$anonfun$waitUntilConnected$3(ZooKeeperClient.scala:259)
at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
at kafka.utils.CoreUtils$.inLock(CoreUtils.scala:253)
at kafka.zookeeper.ZooKeeperClient.waitUntilConnected(ZooKeeperClient.scala:255)
at kafka.zookeeper.ZooKeeperClient.(ZooKeeperClient.scala:113)
at kafka.zk.KafkaZkClient$.apply(KafkaZkClient.scala:1858)
at kafka.server.KafkaServer.createZkClient$1(KafkaServer.scala:375)
at kafka.server.KafkaServer.initZkClient(KafkaServer.scala:399)
at kafka.server.KafkaServer.startup(KafkaServer.scala:207)
at kafka.server.KafkaServerStartable.startup(KafkaServerStartable.scala:44)
at kafka.Kafka$.main(Kafka.scala:84)
at kafka.Kafka.main(Kafka.scala)
2020-05-28 03:45:19,986 INFO shutting down (kafka.server.KafkaServer) [main]
2020-05-28 03:45:19,990 INFO shut down completed (kafka.server.KafkaServer) [main]
2020-05-28 03:45:19,990 ERROR Exiting Kafka. (kafka.server.KafkaServerStartable) [main]
2020-05-28 03:45:19,992 INFO shutting down (kafka.server.KafkaServer) [kafka-shutdown-hook]

Zookeeper pods are up and DNS seems to be working fine.

Thanks in advance,
Lucho.

[scholzj]

The reason why your Kafka cluster cannot connect to the Zookeeper is that the Zookeeper cluster cannot bootstrap. The reason why it failed to bootstrap is following:

2020-05-28 03:35:09,670 INFO Received connection request 10.125.120.3:52994 (org.apache.zookeeper.server.quorum.QuorumCnxManager) [xichlo-kafka-prod-zookeeper-0.xichlo-kafka-prod-zookeeper-nodes.kafka-prod.svc/10.127.104.4:3888]
2020-05-28 03:35:09,689 ERROR Failed to verify host address: 10.125.120.3 (org.apache.zookeeper.common.ZKTrustManager) [xichlo-kafka-prod-zookeeper-0.xichlo-kafka-prod-zookeeper-nodes.kafka-prod.svc/10.127.104.4:3888]
javax.net.ssl.SSLPeerUnverifiedException: Certificate for <10.125.120.3> doesn't match any of the subject alternative names: [xichlo-kafka-prod-zookeeper-2.xichlo-kafka-prod-zookeeper-nodes.kafka-prod.svc.cluster.local, xichlo-kafka-prod-zookeeper-2.xichlo-kafka-prod-zookeeper-nodes.kafka-prod.svc, xichlo-kafka-prod-zookeeper-client.kafka-prod.svc, xichlo-kafka-prod-zookeeper-client.kafka-prod.svc.cluster.local, xichlo-kafka-prod-zookeeper-client, xichlo-kafka-prod-zookeeper-client.kafka-prod]
    at org.apache.zookeeper.common.ZKHostnameVerifier.matchIPAddress(ZKHostnameVerifier.java:194)
    at org.apache.zookeeper.common.ZKHostnameVerifier.verify(ZKHostnameVerifier.java:164)
    at org.apache.zookeeper.common.ZKTrustManager.performHostVerification(ZKTrustManager.java:135)
    at org.apache.zookeeper.common.ZKTrustManager.checkClientTrusted(ZKTrustManager.java:74)
    at sun.security.ssl.ServerHandshaker.clientCertificate(ServerHandshaker.java:2037)
    at sun.security.ssl.ServerHandshaker.processMessage(ServerHandshaker.java:233)
    at sun.security.ssl.Handshaker.processLoop(Handshaker.java:1082)
    at sun.security.ssl.Handshaker.process_record(Handshaker.java:1010)
    at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1079)
    at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1388)
    at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1416)
    at sun.security.ssl.SSLSocketImpl.getSession(SSLSocketImpl.java:2309)
    at org.apache.zookeeper.server.quorum.UnifiedServerSocket$UnifiedSocket.detectMode(UnifiedServerSocket.java:273)
    at org.apache.zookeeper.server.quorum.UnifiedServerSocket$UnifiedSocket.getSocket(UnifiedServerSocket.java:301)
    at org.apache.zookeeper.server.quorum.UnifiedServerSocket$UnifiedSocket.access$400(UnifiedServerSocket.java:180)
    at org.apache.zookeeper.server.quorum.UnifiedServerSocket$UnifiedInputStream.getRealInputStream(UnifiedServerSocket.java:700)
    at org.apache.zookeeper.server.quorum.UnifiedServerSocket$UnifiedInputStream.read(UnifiedServerSocket.java:694)
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
    at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
    at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
    at java.io.DataInputStream.readFully(DataInputStream.java:195)
    at java.io.DataInputStream.readLong(DataInputStream.java:416)
    at org.apache.zookeeper.server.quorum.QuorumCnxManager.handleConnection(QuorumCnxManager.java:518)
    at org.apache.zookeeper.server.quorum.QuorumCnxManager.receiveConnection(QuorumCnxManager.java:472)
    at org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener.run(QuorumCnxManager.java:928)
2020-05-28 03:35:09,689 ERROR Failed to verify hostname: ip-10-125-120-3.ec2.internal (org.apache.zookeeper.common.ZKTrustManager) [xichlo-kafka-prod-zookeeper-0.xichlo-kafka-prod-zookeeper-nodes.kafka-prod.svc/10.127.104.4:3888]
javax.net.ssl.SSLPeerUnverifiedException: Certificate for <ip-10-125-120-3.ec2.internal> doesn't match any of the subject alternative names: [xichlo-kafka-prod-zookeeper-2.xichlo-kafka-prod-zookeeper-nodes.kafka-prod.svc.cluster.local, xichlo-kafka-prod-zookeeper-2.xichlo-kafka-prod-zookeeper-nodes.kafka-prod.svc, xichlo-kafka-prod-zookeeper-client.kafka-prod.svc, xichlo-kafka-prod-zookeeper-client.kafka-prod.svc.cluster.local, xichlo-kafka-prod-zookeeper-client, xichlo-kafka-prod-zookeeper-client.kafka-prod]
    at org.apache.zookeeper.common.ZKHostnameVerifier.matchDNSName(ZKHostnameVerifier.java:224)
    at org.apache.zookeeper.common.ZKHostnameVerifier.verify(ZKHostnameVerifier.java:170)
    at org.apache.zookeeper.common.ZKTrustManager.performHostVerification(ZKTrustManager.java:141)
    at org.apache.zookeeper.common.ZKTrustManager.checkClientTrusted(ZKTrustManager.java:74)
    at sun.security.ssl.ServerHandshaker.clientCertificate(ServerHandshaker.java:2037)
    at sun.security.ssl.ServerHandshaker.processMessage(ServerHandshaker.java:233)
    at sun.security.ssl.Handshaker.processLoop(Handshaker.java:1082)
    at sun.security.ssl.Handshaker.process_record(Handshaker.java:1010)
    at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1079)
    at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1388)
    at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1416)
    at sun.security.ssl.SSLSocketImpl.getSession(SSLSocketImpl.java:2309)
    at org.apache.zookeeper.server.quorum.UnifiedServerSocket$UnifiedSocket.detectMode(UnifiedServerSocket.java:273)
    at org.apache.zookeeper.server.quorum.UnifiedServerSocket$UnifiedSocket.getSocket(UnifiedServerSocket.java:301)
    at org.apache.zookeeper.server.quorum.UnifiedServerSocket$UnifiedSocket.access$400(UnifiedServerSocket.java:180)
    at org.apache.zookeeper.server.quorum.UnifiedServerSocket$UnifiedInputStream.getRealInputStream(UnifiedServerSocket.java:700)
    at org.apache.zookeeper.server.quorum.UnifiedServerSocket$UnifiedInputStream.read(UnifiedServerSocket.java:694)
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
    at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
    at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
    at java.io.DataInputStream.readFully(DataInputStream.java:195)
    at java.io.DataInputStream.readLong(DataInputStream.java:416)
    at org.apache.zookeeper.server.quorum.QuorumCnxManager.handleConnection(QuorumCnxManager.java:518)
    at org.apache.zookeeper.server.quorum.QuorumCnxManager.receiveConnection(QuorumCnxManager.java:472)
    at org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener.run(QuorumCnxManager.java:928)
2020-05-28 03:35:09,690 INFO Accepted TLS connection from ip-10-125-120-3.ec2.internal/10.125.120.3:52994 - NONE - SSL_NULL_WITH_NULL_NULL (org.apache.zookeeper.server.quorum.UnifiedServerSocket) [xichlo-kafka-prod-zookeeper-0.xichlo-kafka-prod-zookeeper-nodes.kafka-prod.svc/10.127.104.4:3888]
2020-05-28 03:35:09,690 WARN Exception reading or writing challenge: {} (org.apache.zookeeper.server.quorum.QuorumCnxManager) [xichlo-kafka-prod-zookeeper-0.xichlo-kafka-prod-zookeeper-nodes.kafka-prod.svc/10.127.104.4:3888]
javax.net.ssl.SSLException: Connection has been shutdown: javax.net.ssl.SSLHandshakeException: java.security.cert.CertificateException: Failed to verify both host address and host name
    at sun.security.ssl.SSLSocketImpl.checkEOF(SSLSocketImpl.java:1554)
    at sun.security.ssl.AppInputStream.read(AppInputStream.java:95)
    at org.apache.zookeeper.server.quorum.UnifiedServerSocket$UnifiedInputStream.read(UnifiedServerSocket.java:694)
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
    at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
    at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
    at java.io.DataInputStream.readFully(DataInputStream.java:195)
    at java.io.DataInputStream.readLong(DataInputStream.java:416)
    at org.apache.zookeeper.server.quorum.QuorumCnxManager.handleConnection(QuorumCnxManager.java:518)
    at org.apache.zookeeper.server.quorum.QuorumCnxManager.receiveConnection(QuorumCnxManager.java:472)
    at org.apache.zookeeper.server.quorum.QuorumCnxManager$Listener.run(QuorumCnxManager.java:928)
Caused by: javax.net.ssl.SSLHandshakeException: java.security.cert.CertificateException: Failed to verify both host address and host name
    at sun.security.ssl.Alerts.getSSLException(Alerts.java:198)
    at sun.security.ssl.SSLSocketImpl.fatal(SSLSocketImpl.java:1967)
    at sun.security.ssl.Handshaker.fatalSE(Handshaker.java:331)
    at sun.security.ssl.Handshaker.fatalSE(Handshaker.java:325)
    at sun.security.ssl.ServerHandshaker.clientCertificate(ServerHandshaker.java:2055)
    at sun.security.ssl.ServerHandshaker.processMessage(ServerHandshaker.java:233)
    at sun.security.ssl.Handshaker.processLoop(Handshaker.java:1082)
    at sun.security.ssl.Handshaker.process_record(Handshaker.java:1010)
    at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1079)
    at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1388)
    at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1416)
    at sun.security.ssl.SSLSocketImpl.getSession(SSLSocketImpl.java:2309)
    at org.apache.zookeeper.server.quorum.UnifiedServerSocket$UnifiedSocket.detectMode(UnifiedServerSocket.java:273)
    at org.apache.zookeeper.server.quorum.UnifiedServerSocket$UnifiedSocket.getSocket(UnifiedServerSocket.java:301)
    at org.apache.zookeeper.server.quorum.UnifiedServerSocket$UnifiedSocket.access$400(UnifiedServerSocket.java:180)
    at org.apache.zookeeper.server.quorum.UnifiedServerSocket$UnifiedInputStream.getRealInputStream(UnifiedServerSocket.java:700)
    ... 9 more
Caused by: java.security.cert.CertificateException: Failed to verify both host address and host name
    at org.apache.zookeeper.common.ZKTrustManager.performHostVerification(ZKTrustManager.java:145)
    at org.apache.zookeeper.common.ZKTrustManager.checkClientTrusted(ZKTrustManager.java:74)
    at sun.security.ssl.ServerHandshaker.clientCertificate(ServerHandshaker.java:2037)
    ... 20 more
Caused by: javax.net.ssl.SSLPeerUnverifiedException: Certificate for <ip-10-125-120-3.ec2.internal> doesn't match any of the subject alternative names: [xichlo-kafka-prod-zookeeper-2.xichlo-kafka-prod-zookeeper-nodes.kafka-prod.svc.cluster.local, xichlo-kafka-prod-zookeeper-2.xichlo-kafka-prod-zookeeper-nodes.kafka-prod.svc, xichlo-kafka-prod-zookeeper-client.kafka-prod.svc, xichlo-kafka-prod-zookeeper-client.kafka-prod.svc.cluster.local, xichlo-kafka-prod-zookeeper-client, xichlo-kafka-prod-zookeeper-client.kafka-prod]
    at org.apache.zookeeper.common.ZKHostnameVerifier.matchDNSName(ZKHostnameVerifier.java:224)
    at org.apache.zookeeper.common.ZKHostnameVerifier.verify(ZKHostnameVerifier.java:170)
    at org.apache.zookeeper.common.ZKTrustManager.performHostVerification(ZKTrustManager.java:141)
    ... 22 more

The Zookeeper nodes are trying to connect to each other but they fail to verify the hostnames. There seems to be soemthing weird on a cluster level: The Zookeeper node 0 tries for example to connect to 10.125.120.3 which is the pod xichlo-kafka-prod-zookeeper-2. But it looks like the IP address mixes up with the same IP address used by an AWS EC2 node ip-10-125-120-3.ec2.internal and that causes the issue.

What environment are you running in? Could it be some misconfiguration that you have overlapping sets of private IPs in the same network where the same IP address exists multiple times for both Kubernetes pod and for EC2 host? Or it can be some weird DNS setting or something which mixes them up together.

[lluzza]

We seem to be hitting the same problem as in #3099. Our Strimzi cluster was automatically upgraded last Monday morning and we are experiencing these issues since then. As a workaround we are trying to downgrade to version 0.17 but we were not able to do it.

Could you please let us know how we can perform a downgrade of Strimzi Operator?

Thanks!

[scholzj]

While there are some similar symptoms, the #3099 does not seem to have the same errors. Did you had a look at the IP addresses and networking as I suggested?

[jbuse]

yes we checked, but no is not mixing IPs, we have an internal network managed by Weave with different IPs than the aws instances. We want to downgrade to 0.17 but we have had no luck. Can you share the procedure to downgrade Strimzi Operator? thanks in advance

[scholzj]

So you have no EC2 instace with 10.125.120.3? Have you checked the DNS as well? Because the Zookeeper needs to find the ip-10-125-120-3.ec2.internal it doesn't make it up.

I don't think there is any special downgrade procedure. You just get the YAML files and install them back over instead of the new version of the operator. If you installed it from OperatorHub, I'm not sure it allows to pick a specific version.

[jbuse]

pretty sure we are using other IP range
xichlo-kafka-prod-zookeeper-0 1/1 Running 1 20h 10.127.104.4 ip-10-202-4-164.ec2.internal
xichlo-kafka-prod-zookeeper-1 1/1 Running 0 4h26m 10.120.170.3 ip-10-202-5-238.ec2.internal
xichlo-kafka-prod-zookeeper-2 1/1 Running 0 4h30m 10.120.178.3 ip-10-202-6-77.ec2.internal

[lluzza]

After the automatic upgrade we started receiving these error messages:

Failed to verify hostname: ip-10-127-108-3.ec2.internal (org.apache.zookeeper.common.ZKTrustManager) [xichlo-kafka-prod-zookeeper-1.xichlo-kafka-prod-zookeeper-nodes.kafka-prod.svc/10.122.92.3:3888]

For some reason it's trying to connect to a pod internal IP address instead of using the right alternatives for which the certificate works, so I guess that's why we are seeing these error messages: javax.net.ssl.SSLPeerUnverifiedException: Certificate for <ip-10-127-108-3.ec2.internal> doesn't match any of the subject alternative names: [xichlo-kafka-prod-zookeeper-2.xichlo-kafka-prod-zookeeper-nodes.kafka-prod.svc.cluster.local, xichlo-kafka-prod-zookeeper-2.xichlo-kafka-prod-zookeeper-nodes.kafka-prod.svc, xichlo-kafka-prod-zookeeper-client.kafka-prod.svc, xichlo-kafka-prod-zookeeper-client.kafka-prod.svc.cluster.local, xichlo-kafka-prod-zookeeper-client, xichlo-kafka-prod-zookeeper-client.kafka-prod]

We don't know why Zookeeper turns the pod IP into a a hostname adding .ec2.internal at the end. That IP does not belong to any EC2 instance.

[lluzza]

I think it's what you said in #3099

The Upgrade from 0.17 to 0.18 includes the removal of the Zookeeper sidecar which was used for TLS. It is now using the Zookeeper native TLS support. Sometimes during the first rolling update, in one of the intermediate steps of the removal some TLS errors popout.
The native Zookeeper support has this weird thing where it first tries to verify the identity of the other servers using IP address which failes (in Kubernetes, the pod IPs are dynamic and are not part of the certificate) and only then moves to the hostname whihc passes.

Is there any other workaround available besides downgrading to 0.17?

[scholzj]

I checked the Zookeeper code and I think this is in one way or another some kind of issue in your DNS setup. What it does is it tries to connect to xichlo-kafka-prod-zookeeper-2.kafka-prod.svc. That resolves to 10.125.120.3 which seems to be correct because it is listed as the podIP in the ZIP file with YAMLs.

Now they way Zookeeper implements the hostname verification, it for whatever reason first compares the IP address against the certificate. But the pod IP address is dynamic and is not in the certificate since we would need to generate a new one all the time. So what it does is it does reverse lookup and the DNS server tells it that this IP address belongs to ip-10-125-120-3.ec2.internal instead of something like xichlo-kafka-prod-zookeeper-2.kafka-prod.svc.

TBH, I find this implementation in Zookeeper a bit strange, but it is not the first time I saw it. I assume it might be more secure by doublechecking the name from the DNS and not from the original address? Not sure.

Either way I cannot do much about it. I can find out if the hostname verification can be disabled in Zookeeper and make that a configurable option.

The Upgrade from 0.17 to 0.18 includes the removal of the Zookeeper sidecar which was used for TLS. It is now using the Zookeeper native TLS support. Sometimes during the first rolling update, in one of the intermediate steps of the removal some TLS errors popout.
The native Zookeeper support has this weird thing where it first tries to verify the identity of the other servers using IP address which failes (in Kubernetes, the pod IPs are dynamic and are not part of the certificate) and only then moves to the hostname whihc passes.

I ws refering here to a bit different message where the Zookeeper tells you that it didn't validate the IP but it does validate the hostname afterwards - this message happens because of the order in which these two validations are done. But in your case the second part fails because the DNS returns the AWS EC2 host.

[scholzj]

FYI: This the Zookeeper part which does the hostname verification: https://github.com/apache/zookeeper/blob/0f182ab88dac2fda7f5821b7003092428b859164/zookeeper-server/src/main/java/org/apache/zookeeper/common/ZKTrustManager.java#L143

[scholzj]

Actually, I might have a possible workaround for your case. From the ZK docs:

ssl.hostnameVerification and ssl.quorum.hostnameVerification : (Java system properties: zookeeper.ssl.hostnameVerification and zookeeper.ssl.quorum.hostnameVerification) New in 3.5.5: Specifies whether the hostname verification is enabled in client and quorum TLS negotiation process. Disabling it only recommended for testing purposes. Default: true

So, maybe you can try to set the system properties zookeeper.ssl.hostnameVerification=false and zookeeper.ssl.quorum.hostnameVerification=false. You should be able to set them in the Kafka.spec.zookeeper.jvmOptions section of the Kafka CR: https://strimzi.io/docs/operators/latest/full/using.html#type-SystemProperty-reference

[lluzza]

Thanks for your help Jakub!!!

JVM options didn't work but we finally fixed it by changing this line in coredns configmap:

Before:

        ready
        kubernetes cluster.local 10.3.0.0/24 {
          fallthrough in-addr.arpa ip6.arpa
        }

After:

        ready
        kubernetes cluster.local in-addr.arpa ip6.arpa {
          fallthrough in-addr.arpa ip6.arpa
        }

So reverse lookup output will be 10-125-64-3.kube-dns.kube-system.svc.cluster.local. instead of 10-125-64-3.ec2.internal.

Now Zookeeper is able to find the hosts. We didn't have any issues with our previous coredns configuration while running 0.17 Strimzi version.

[scholzj]

In 0.17.0, we didn't yet used the Zookeeper TLS implementation but used a sidecar instead. And the sidecar did the hostname verification stuff differently - so it seems ti did not had problem with this.

Anyway, glad this got resolved. I will close the issue - feel free to re-open it or open a new one if you have something else.