Reconcilation Failure on Zookeeper pods.

[vperi1730]

Hi Scholzj,

I found a scenario today while performing compatibility/behavior tests on Kafka. Let me clearly tell you what I have done.

1. On my Kubernetes cluster I have installed all the CRD's/ClusterRoles/ClusterRoleBindings of Operator version 20.
2. I have launched Kafka (17+2.4.0) - It has come up properly, no issues seen.
3. Now I have installed the 19 deployment operators which have come up well.
4. Now the Zookeeper pods started container re-creating. In this step, I have noticed that the reconciliation is continuously failing due to which the zookeeper pod is going to crashloopbackoff.

pod/my-cluster-kafka-0                            2/2     Running            0          37m
pod/my-cluster-kafka-1                            2/2     Running            0          37m
pod/my-cluster-kafka-2                            2/2     Running            0          37m
pod/my-cluster-kafka-exporter-596bc54fc8-s67pb    1/1     Running            0          35m
pod/my-cluster-zookeeper-0                        0/1     CrashLoopBackOff   6          6m46s
pod/my-cluster-zookeeper-1                        2/2     Running            0          37m
pod/my-cluster-zookeeper-2                        2/2     Running            0          37m
pod/strimzi-operator-57ddf969bc-lg4rw             1/1     Running            0          12m

Here is the error message.

2021-01-07 11:22:59 INFO  ClusterOperator:125 - Triggering periodic reconciliation for namespace kup20...
2021-01-07 11:23:09 WARN  AbstractOperator:247 - Reconciliation #2(timer) Kafka(kup20/my-cluster): Failed to acquire lock lock::kup20::Kafka::my-cluster within 10000ms.
2021-01-07 11:24:22 ERROR Util:120 - Exceeded timeout of 300000ms while waiting for Pods resource my-cluster-zookeeper-0 in namespace kup20 to be ready
2021-01-07 11:24:22 INFO  OperatorWatcher:40 - Reconciliation #3(watch) Kafka(kup20/my-cluster): Kafka my-cluster in namespace kup20 was MODIFIED
2021-01-07 11:24:22 ERROR AbstractOperator:175 - Reconciliation #0(watch) Kafka(kup20/my-cluster): createOrUpdate failed
io.strimzi.operator.common.operator.resource.TimeoutException: Exceeded timeout of 300000ms while waiting for Pods resource my-cluster-zookeeper-0 in namespace kup20 to be ready
        at io.strimzi.operator.common.Util$1.lambda$handle$1(Util.java:121) ~[io.strimzi.operator-common-0.19.0.jar:0.19.0]
        at io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:327) ~[io.vertx.vertx-core-3.9.1.jar:3.9.1]
        at io.vertx.core.impl.ContextImpl.executeTask(ContextImpl.java:366) ~[io.vertx.vertx-core-3.9.1.jar:3.9.1]
        at io.vertx.core.impl.EventLoopContext.lambda$executeAsync$0(EventLoopContext.java:38) ~[io.vertx.vertx-core-3.9.1.jar:3.9.1]
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) [io.netty.netty-common-4.1.50.Final.jar:4.1.50.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472) [io.netty.netty-common-4.1.50.Final.jar:4.1.50.Final]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500) [io.netty.netty-transport-4.1.50.Final.jar:4.1.50.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) [io.netty.netty-common-4.1.50.Final.jar:4.1.50.Final]
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [io.netty.netty-common-4.1.50.Final.jar:4.1.50.Final]
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty.netty-common-4.1.50.Final.jar:4.1.50.Final]
        at java.lang.Thread.run(Thread.java:834) [?:?]
2021-01-07 11:24:22 WARN  AbstractOperator:330 - Reconciliation #0(watch) Kafka(kup20/my-cluster): Failed to reconcile
io.strimzi.operator.common.operator.resource.TimeoutException: Exceeded timeout of 300000ms while waiting for Pods resource my-cluster-zookeeper-0 in namespace kup20 to be ready

Is there any restriction that the reconciliation happens successfully only when the CRD's version matches with the installed deployment operator, in my case it is 20 & 19 respectively.

Please throw some light on this.

[tomncooper]

Why are you using 0.20 CRDs etc with the 0.19 Operator?

[vperi1730]

I would like to check if the backward compatibility of something like this still works. So does it mean both the versions should always be the same?. If there is any other explanation behind this, would like to listen from you.

[scholzj]

I'm not really sire I understand what are you doing. Neither Strimzi 0.19 or 0.20 has Zookeeper with TLS sidecars anymore. So I'm not sure where do the odl pods come from. But I doubt it has any relation to the CRD. You will need to check the logs of the pods to see what the problem is.

[vperi1730]

Ok, so from my above-shown list of pods, my-cluster-zookeeper-0 is something which I am referring to (rest can be ignored for now) and there is a reconciliation error on this pod with a timeout issue. Would like to understand the reason behind this behavior?

Zookeeper logs show this.

kubectl logs -f my-cluster-zookeeper-0 -n kup20
Detected Zookeeper ID 1
Starting Zookeeper with configuration:
# the directory where the snapshot is stored.
dataDir=/var/lib/zookeeper/data
4lw.commands.whitelist=*
standaloneEnabled=false
reconfigEnabled=true

# Provided configuration
tickTime=2000
initLimit=5
syncLimit=2
autopurge.purgeInterval=1

# Zookeeper nodes configuration

2021-01-07 12:01:35,723 INFO Reading configuration from: /tmp/zookeeper.properties (org.apache.zookeeper.server.quorum.QuorumPeerConfig) [main]
2021-01-07 12:01:35,725 INFO clientPort is not set (org.apache.zookeeper.server.quorum.QuorumPeerConfig) [main]
2021-01-07 12:01:35,725 INFO secureClientPort is not set (org.apache.zookeeper.server.quorum.QuorumPeerConfig) [main]
2021-01-07 12:01:35,729 ERROR Invalid config, exiting abnormally (org.apache.zookeeper.server.quorum.QuorumPeerMain) [main]
org.apache.zookeeper.server.quorum.QuorumPeerConfig$ConfigException: Error processing /tmp/zookeeper.properties
        at org.apache.zookeeper.server.quorum.QuorumPeerConfig.parse(QuorumPeerConfig.java:154)
        at org.apache.zookeeper.server.quorum.QuorumPeerMain.initializeAndRun(QuorumPeerMain.java:113)
        at org.apache.zookeeper.server.quorum.QuorumPeerMain.main(QuorumPeerMain.java:82)
Caused by: java.lang.IllegalArgumentException: standaloneEnabled = false then number of participants should be >0
        at org.apache.zookeeper.server.quorum.QuorumPeerConfig.parseDynamicConfig(QuorumPeerConfig.java:634)
        at org.apache.zookeeper.server.quorum.QuorumPeerConfig.setupQuorumPeerConfig(QuorumPeerConfig.java:601)
        at org.apache.zookeeper.server.quorum.QuorumPeerConfig.parseProperties(QuorumPeerConfig.java:420)
        at org.apache.zookeeper.server.quorum.QuorumPeerConfig.parse(QuorumPeerConfig.java:150)
        ... 2 more
Invalid config, exiting abnormally

[scholzj]

Everything needs a timeout -> the operator cannot wait forever. When it does not happen, the operator could be waiting forever. I do not think the other pods cannot be ignored. They are from the same cluster. So they have to be related to the problem and understanding what is the exact state of your cluster and what steps led to the current situation is probably important to understand the issue.

[scholzj]

Are the old pods from some old Strimzi version or something like that?

[vperi1730]

Ok, this is how the state of the pods is inside my cluster.

1. Kafka 17+2.4.0(In this case the resources are running well)

pod/my-cluster-kafka-0                            2/2     Running            0          37m
pod/my-cluster-kafka-1                            2/2     Running            0          37m
pod/my-cluster-kafka-2                            2/2     Running            0          37m
pod/my-cluster-kafka-exporter-596bc54fc8-s67pb    1/1     Running            0          35m
pod/my-cluster-zookeeper-0                        1/1     Running            0          6m46s
pod/my-cluster-zookeeper-1                        2/2     Running            0          37m
pod/my-cluster-zookeeper-2                        2/2     Running            0          37m
pod/strimzi-operator-57ddf969bc-lg4rw             1/1     Running            0          12m

2. The last pod i.e. strimzi-operator has been re-created with the 19 version which kind of started re-conciliation on the zk/kafka pods. While it is doing for the 0th zk pod it has timed out with the above logs.

So to answer your question, the ones which are seen in running state are still on the 17 version as the reconciliation hasn't started for those yet.

pod/my-cluster-kafka-0                            2/2     Running            0          37m
pod/my-cluster-kafka-1                            2/2     Running            0          37m
pod/my-cluster-kafka-2                            2/2     Running            0          37m
pod/my-cluster-kafka-exporter-596bc54fc8-s67pb    1/1     Running            0          35m
pod/my-cluster-zookeeper-0                        0/1     CrashLoopBackOff   6          6m46s
pod/my-cluster-zookeeper-1                        2/2     Running            0          37m
pod/my-cluster-zookeeper-2                        2/2     Running            0          37m
pod/strimzi-operator-57ddf969bc-lg4rw             1/1     Running            0          12m

[scholzj]

But already in the first step it has to be broken. You have Zookeepers 1+2 with TLS sidecars. But 0 is without the sidecar. So that could not be Strimzi 0.17. Also, the sidecar was removed in 0.18. So not sure how does upgrade from 0.17 -> 0.19 work.

[vperi1730]

Closing this for now. The answer helps us, thanks Scholzj.