Startup probe failed,Attempting reconnect except it is a SessionExpiredException #6706

fanux · 2022-04-19T09:06:02Z

fanux
Apr 19, 2022

Describe the bug
The my-cluster-entity-operator can't start, one container start failed:

[root@iZ2zeaxzynknewlf0dkin9Z ~]# kubectl get pod -n kafka -owide
NAME                                          READY   STATUS    RESTARTS      AGE   IP               NODE                      NOMINATED NODE   READINESS GATES
my-cluster-entity-operator-67cbb8f86f-vhkl8   2/3     Running   8 (81s ago)   21m   100.84.137.8     iz2zeaxzynknewlf0dkinbz   <none>           <none>
my-cluster-kafka-0                            1/1     Running   0             32m   100.73.225.10    iz2zeaxzynknewlf0dkindz   <none>           <none>
my-cluster-kafka-1                            1/1     Running   0             32m   100.121.221.73   iz2zeaxzynknewlf0dkincz   <none>           <none>
my-cluster-kafka-2                            1/1     Running   0             32m   100.84.137.7     iz2zeaxzynknewlf0dkinbz   <none>           <none>
my-cluster-zookeeper-0                        1/1     Running   0             34m   100.121.221.71   iz2zeaxzynknewlf0dkincz   <none>           <none>
my-cluster-zookeeper-1                        1/1     Running   1 (34m ago)   34m   100.73.225.9     iz2zeaxzynknewlf0dkindz   <none>           <none>
my-cluster-zookeeper-2                        1/1     Running   0             34m   100.84.137.5     iz2zeaxzynknewlf0dkinbz   <none>           <none>
strimzi-cluster-operator-7599bc57cb-2dt5m     1/1     Running   0             63m   100.84.137.3     iz2zeaxzynknewlf0dkinbz   <none>           <none>

Describe the pod:

  Type     Reason     Age                 From               Message
  ----     ------     ----                ----               -------
  Normal   Scheduled  20m                 default-scheduler  Successfully assigned kafka/my-cluster-entity-operator-67cbb8f86f-vhkl8 to iz2zeaxzynknewlf0dkinbz
  Normal   Pulled     20m                 kubelet            Container image "quay.io/strimzi/kafka:0.28.0-kafka-3.1.0" already present on machine
  Normal   Created    20m                 kubelet            Created container tls-sidecar
  Normal   Started    20m                 kubelet            Started container tls-sidecar
  Normal   Pulled     20m                 kubelet            Container image "quay.io/strimzi/operator:0.28.0" already present on machine
  Normal   Created    20m                 kubelet            Created container user-operator
  Normal   Started    20m                 kubelet            Started container user-operator
  Normal   Killing    18m                 kubelet            Container topic-operator failed startup probe, will be restarted
  Normal   Pulled     18m (x2 over 20m)   kubelet            Container image "quay.io/strimzi/operator:0.28.0" already present on machine
  Normal   Created    18m (x2 over 20m)   kubelet            Created container topic-operator
  Normal   Started    18m (x2 over 20m)   kubelet            Started container topic-operator
  Warning  Unhealthy  37s (x96 over 20m)  kubelet            Startup probe failed: Get "http://100.84.137.8:8080/healthy": dial tcp 100.84.137.8:8080: connect: connection refused

The container log:

kubectl logs -n kafka my-cluster-entity-operator-67cbb8f86f-vhkl8 -c topic-operator

2022-04-19 08:54:59,78134 INFO  [vert.x-worker-thread-0] ZkClient:936 - Waiting for keeper state SyncConnected
2022-04-19 08:54:59,78536 INFO  [vert.x-worker-thread-0-SendThread(localhost:2181)] ClientCnxn:1181 - Opening socket connection to server localhost/0:0:0:0:0:0:0:1:2181.
2022-04-19 08:54:59,78562 INFO  [vert.x-worker-thread-0-SendThread(localhost:2181)] ClientCnxn:1183 - SASL config status: Will not attempt to authenticate using SASL (unknown error)
2022-04-19 08:54:59,78615 WARN  [vert.x-worker-thread-0-SendThread(localhost:2181)] ClientCnxn:1300 - Session 0x0 for sever localhost/0:0:0:0:0:0:0:1:2181, Closing socket connection. Attempting reconnect except it is a SessionExpiredException.
java.net.ConnectException: Connection refused
	at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) ~[?:?]
	at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:777) ~[?:?]
	at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:344) ~[org.apache.zookeeper.zookeeper-3.6.3.jar:3.6.3]
	at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1290) [org.apache.zookeeper.zookeeper-3.6.3.jar:3.6.3]
2022-04-19 08:55:00,89244 INFO  [vert.x-worker-thread-0-SendThread(localhost:2181)] ClientCnxn:1181 - Opening socket connection to server localhost/0:0:0:0:0:0:0:1:2181.
2022-04-19 08:55:00,89265 INFO  [vert.x-worker-thread-0-SendThread(localhost:2181)] ClientCnxn:1183 - SASL config status: Will not attempt to authenticate using SASL (unknown error)
2022-04-19 08:55:00,89318 WARN  [vert.x-worker-thread-0-SendThread(localhost:2181)] ClientCnxn:1300 - Session 0x0 for sever localhost/0:0:0:0:0:0:0:1:2181, Closing socket connection. Attempting reconnect except it is a SessionExpiredException.
java.net.ConnectException: Connection refused
	at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) ~[?:?]
	at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:777) ~[?:?]
	at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:344) ~[org.apache.zookeeper.zookeeper-3.6.3.jar:3.6.3]
	at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1290) [org.apache.zookeeper.zookeeper-3.6.3.jar:3.6.3]

The zookeeper dns is fine:

bash-5.1# nslookup my-cluster-zookeeper-nodes.kafka.svc.cluster.local
Server:		10.96.0.10
Address:	10.96.0.10#53

Name:	my-cluster-zookeeper-nodes.kafka.svc.cluster.local
Address: 100.73.225.9
Name:	my-cluster-zookeeper-nodes.kafka.svc.cluster.local
Address: 100.84.137.5
Name:	my-cluster-zookeeper-nodes.kafka.svc.cluster.local
Address: 100.121.221.71

To Reproduce

[root@iZ2zeaxzynknewlf0dkin9Z ~]# cat kafka-instance.yaml 
apiVersion: kafka.strimzi.io/v1beta2
kind: Kafka
metadata:
  name: my-cluster
  namespace: kafka
spec:
  kafka:
    version: 3.1.0
    replicas: 3
    listeners:
      - name: plain
        port: 9092
        type: internal
        tls: false
      - name: tls
        port: 9093
        type: internal
        tls: true
    config:
      offsets.topic.replication.factor: 3
      transaction.state.log.replication.factor: 3
      transaction.state.log.min.isr: 2
      default.replication.factor: 3
      min.insync.replicas: 2
      inter.broker.protocol.version: "3.1"
    storage:
      type: jbod
      volumes:
      - id: 0
        type: persistent-claim
        size: 10Gi
        deleteClaim: false
  zookeeper:
    replicas: 3
    storage:
      type:  persistent-claim
      size: 10Gi
      deleteClaim: false
  entityOperator:
    topicOperator: {}
    userOperator: {}

Just apply it.

Environment (please complete the following information):

Strimzi version: [e.g. main, 0.28.0]
Installation method: yaml
Kubernetes cluster: 1.23.5
Infrastructure: alicloud

scholzj · 2022-04-19T09:08:03Z

scholzj
Apr 19, 2022
Maintainer

That is not startup probe failure. If it cannot connect to ZooKeeper, it is not running and restarts. So you have to investigate why it cannot conennct to ZooKeeper.

0 replies

fanux · 2022-04-19T09:09:26Z

fanux
Apr 19, 2022
Author

It seems the zookeeper worked fine, I can resolve the zookeeper DNS.

0 replies

fanux · 2022-04-19T09:09:53Z

fanux
Apr 19, 2022
Author

Session 0x0 for sever localhost/0:0:0:0:0:0:0:1:2181, Closing socket connection. Attempting reconnect except it is a SessionExpiredException.
java.net.ConnectException: Connection refused

0 replies

scholzj · 2022-04-19T09:10:03Z

scholzj
Apr 19, 2022
Maintainer

But resolving DNS doesn't say anything about ZooKeeper working or not. The error is not complaining about resolving ZooKeeper DNS.

0 replies

fanux · 2022-04-19T09:15:49Z

fanux
Apr 19, 2022
Author

OH, it seems I can't ping the zookeeper IP...

0 replies

scholzj · 2022-04-19T11:56:32Z

scholzj
Apr 19, 2022
Maintainer

Not sure the ping is expected to work in Kubernetes. But maybe you can start by:

Checking the ZooKeeper logs
Checking the TLS sidecar in the EO pod which is where the Topic Operator connects and which connects to ZooKeeper
See if you can connect manually

0 replies

fanux · 2022-04-19T13:19:50Z

fanux
Apr 19, 2022
Author

It seems cause by the network policy:

[root@iZ2zeaxzynknewlf0dkin9Z ~]# kubectl get networkpolicy -A -owide
NAMESPACE   NAME                                  POD-SELECTOR                           AGE
kafka       my-cluster-network-policy-kafka       strimzi.io/name=my-cluster-kafka       11s
kafka       my-cluster-network-policy-zookeeper   strimzi.io/name=my-cluster-zookeeper   12s

How can I delete those policy, the operator will recreate it when I delete it?

0 replies

fanux · 2022-04-19T13:53:52Z

fanux
Apr 19, 2022
Author

zookeeper logs:

2022-04-19 13:30:54,445 INFO The list of known four letter word commands is : [{1936881266=srvr, 1937006964=stat, 2003003491=wchc, 1685417328=dump, 1668445044=crst, 1936880500=srst, 1701738089=envi, 1668247142=conf, -720899=telnet close, 1751217000=hash, 2003003507=wchs, 2003003504=wchp, 1684632179=dirs, 1668247155=cons, 1835955314=mntr, 1769173615=isro, 1920298859=ruok, 1735683435=gtmk, 1937010027=stmk}] (org.apache.zookeeper.server.command.FourLetterCommands) [nioEventLoopGroup-4-2]
2022-04-19 13:30:54,445 INFO The list of enabled four letter word commands is : [[wchs, stat, wchp, dirs, stmk, conf, ruok, mntr, srvr, wchc, envi, srst, isro, dump, gtmk, telnet close, crst, hash, cons]] (org.apache.zookeeper.server.command.FourLetterCommands) [nioEventLoopGroup-4-2]
2022-04-19 13:30:54,445 INFO Processing ruok command from /127.0.0.1:53654 (org.apache.zookeeper.server.NettyServerCnxn) [nioEventLoopGroup-4-2]
2022-04-19 13:30:54,446 INFO Processing ruok command from /127.0.0.1:53652 (org.apache.zookeeper.server.NettyServerCnxn) [nioEventLoopGroup-4-1]

The TLS sidecar:

2022.04.19 13:30:50 LOG5[68]: Service [zookeeper-2181] accepted connection from 127.0.0.1:48660
2022.04.19 13:30:50 LOG5[68]: s_connect: connected 10.100.244.194:2181
2022.04.19 13:30:50 LOG5[68]: Service [zookeeper-2181] connected remote server from 100.84.137.8:37512
2022.04.19 13:30:50 LOG5[68]: Certificate accepted at depth=0: O=io.strimzi, CN=my-cluster-zookeeper
2022.04.19 13:31:40 LOG3[66]: transfer: s_poll_wait: TIMEOUTclose exceeded: closing
2022.04.19 13:31:40 LOG5[66]: Connection closed: 309 byte(s) sent to TLS, 421 byte(s) sent to socket
2022.04.19 13:32:57 LOG5[68]: Connection closed: 333 byte(s) sent to TLS, 481 byte(s) sent to socket

0 replies

scholzj · 2022-04-19T15:32:30Z

scholzj
Apr 19, 2022
Maintainer

But the network policy allows the connection. Plus the TLS sidecar seems to connect and then disconnect. So I think this is more some general networking issue rather than network policy.

0 replies

fanux · 2022-04-20T02:03:54Z

fanux
Apr 20, 2022
Author

So how can I solve this issue or how to trouble shouting it ?

0 replies

fanux · 2022-04-20T03:17:20Z

fanux
Apr 20, 2022
Author

I delete the pod, now the TLS sidecar seems work now:

2022.04.20 03:07:39 LOG5[1]: Service [zookeeper-2181] accepted connection from 127.0.0.1:48714
2022.04.20 03:07:39 LOG5[1]: s_connect: connected 10.100.244.194:2181
2022.04.20 03:07:39 LOG5[1]: Service [zookeeper-2181] connected remote server from 100.121.221.78:37684
2022.04.20 03:07:39 LOG5[1]: Certificate accepted at depth=0: O=io.strimzi, CN=my-cluster-zookeeper
2022.04.20 03:09:46 LOG5[1]: Connection closed: 333 byte(s) sent to TLS, 481 byte(s) sent to socket
2022.04.20 03:09:49 LOG5[2]: Service [zookeeper-2181] accepted connection from 127.0.0.1:51034
2022.04.20 03:09:49 LOG5[2]: s_connect: connected 10.100.244.194:2181
2022.04.20 03:09:49 LOG5[2]: Service [zookeeper-2181] connected remote server from 100.121.221.78:40004
2022.04.20 03:09:49 LOG5[2]: Certificate accepted at depth=0: O=io.strimzi, CN=my-cluster-zookeeper
2022.04.20 03:11:56 LOG5[2]: Connection closed: 333 byte(s) sent to TLS, 481 byte(s) sent to socket
2022.04.20 03:11:58 LOG5[3]: Service [zookeeper-2181] accepted connection from 127.0.0.1:53352
2022.04.20 03:11:58 LOG5[3]: s_connect: connected 10.100.244.194:2181
2022.04.20 03:11:58 LOG5[3]: Service [zookeeper-2181] connected remote server from 100.121.221.78:42322
2022.04.20 03:11:58 LOG5[3]: Certificate accepted at depth=0: O=io.strimzi, CN=my-cluster-zookeeper

But the topic operator still can't start:

2022-04-20 03:14:08,64883 WARN  [vert.x-worker-thread-0-SendThread(localhost:2181)] ClientCnxn:1300 - Session 0x0 for sever localhost/0:0:0:0:0:0:0:1:2181, Closing socket connection. Attempting reconnect except it is a SessionExpiredException.
java.net.ConnectException: Connection refused
	at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) ~[?:?]
	at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:777) ~[?:?]
	at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:344) ~[org.apache.zookeeper.zookeeper-3.6.3.jar:3.6.3]
	at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1290) [org.apache.zookeeper.zookeeper-3.6.3.jar:3.6.3]

2022-04-20 03:14:09,88219 WARN  [kafka-admin-client-thread | adminclient-2] KafkaStreamsTopicStoreService:152 - Durability of the topic [__strimzi_store_topic] is not sufficient for production use - replicationFactor: 1, min.insync.replicas: 1. Increase the replication factor to at least 3 and configure the min.insync.replicas to 1.

2022-04-20 03:14:12,34335 WARN  [vertx-blocked-thread-checker] BlockedThreadChecker: - Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 2574 ms, time limit is 2000 ms
2022-04-20 03:14:13,34395 WARN  [vertx-blocked-thread-checker] BlockedThreadChecker: - Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 3575 ms, time limit is 2000 ms
2022-04-20 03:14:14,34337 WARN  [vertx-blocked-thread-checker] BlockedThreadChecker: - Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 4574 ms, time limit is 2000 ms
2022-04-20 03:14:15,34410 WARN  [vertx-blocked-thread-checker] BlockedThreadChecker: - Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 5574 ms, time limit is 2000 ms
io.vertx.core.VertxException: Thread blocked
	at jdk.internal.misc.Unsafe.park(Native Method) ~[?:?]
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:194) ~[?:?]
	at java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1796) ~[?:?]
	at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3128) ~[?:?]
	at java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1823) ~[?:?]
	at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1998) ~[?:?]
	at io.apicurio.registry.utils.ConcurrentUtil.get(ConcurrentUtil.java:35) ~[io.apicurio.apicurio-registry-common-1.3.2.Final.jar:?]
	at io.apicurio.registry.utils.ConcurrentUtil.get(ConcurrentUtil.java:27) ~[io.apicurio.apicurio-registry-common-1.3.2.Final.jar:?]
	at io.apicurio.registry.utils.ConcurrentUtil.result(ConcurrentUtil.java:54) ~[io.apicurio.apicurio-registry-common-1.3.2.Final.jar:?]
	at io.strimzi.operator.topic.Session.lambda$start$9(Session.java:198) ~[io.strimzi.topic-operator-0.28.0.jar:0.28.0]
	at io.strimzi.operator.topic.Session$$Lambda$278/0x0000000840327040.handle(Unknown Source) ~[?:?]
	at io.vertx.core.impl.future.FutureImpl$3.onSuccess(FutureImpl.java:141) ~[io.vertx.vertx-core-4.2.4.jar:4.2.4]
	at io.vertx.core.impl.future.FutureBase.lambda$emitSuccess$0(FutureBase.java:54) ~[io.vertx.vertx-core-4.2.4.jar:4.2.4]
	at io.vertx.core.impl.future.FutureBase$$Lambda$424/0x0000000840433040.run(Unknown Source) ~[?:?]
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) ~[io.netty.netty-common-4.1.71.Final.jar:4.1.71.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469) ~[io.netty.netty-common-4.1.71.Final.jar:4.1.71.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:503) ~[io.netty.netty-transport-4.1.71.Final.jar:4.1.71.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) ~[io.netty.netty-common-4.1.71.Final.jar:4.1.71.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[io.netty.netty-common-4.1.71.Final.jar:4.1.71.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[io.netty.netty-common-4.1.71.Final.jar:4.1.71.Final]
	at java.lang.Thread.run(Thread.java:829) ~[?:?]

Life is hard...

  Normal   Scheduled  81s   default-scheduler  Successfully assigned kafka/my-cluster-entity-operator-5c4f7c8df4-dzvgz to iz2zeaxzynknewlf0dkincz
  Normal   Pulled     81s   kubelet            Container image "quay.io/strimzi/operator:0.28.0" already present on machine
  Normal   Created    81s   kubelet            Created container topic-operator
  Normal   Started    81s   kubelet            Started container topic-operator
  Normal   Pulled     81s   kubelet            Container image "quay.io/strimzi/operator:0.28.0" already present on machine
  Normal   Created    81s   kubelet            Created container user-operator
  Normal   Started    81s   kubelet            Started container user-operator
  Normal   Pulled     81s   kubelet            Container image "quay.io/strimzi/kafka:0.28.0-kafka-3.1.0" already present on machine
  Normal   Created    81s   kubelet            Created container tls-sidecar
  Normal   Started    81s   kubelet            Started container tls-sidecar
  Warning  Unhealthy  22s   kubelet            Startup probe failed: Get "http://100.121.221.79:8080/healthy": dial tcp 100.121.221.79:8080: connect: connection refused

0 replies

scholzj · 2022-04-20T06:18:22Z

scholzj
Apr 20, 2022
Maintainer

Once again, you would need to share the full logs in order to get any help. Not just some snippets you find interesting.

0 replies

rudramaniteja · 2022-07-21T01:02:21Z

rudramaniteja
Jul 21, 2022

Got the similar kind of Issue, Tried removing the network policies even but no luck. Any solutions for this Issue?

0 replies

akikoogawa7 · 2022-09-20T01:30:04Z

akikoogawa7
Sep 20, 2022

Hi, I am experiencing the same thing. Has anyone found a solution for this?
And could someone help be my spare pair of eyes?

My zookeeper logs:

ZooKeeper JMX enabled by default
Using config: /conf/zoo.cfg
2022-09-20 01:23:23,813 [myid:] - INFO  [main:o.a.z.s.q.QuorumPeerConfig@177] - Reading configuration from: /conf/zoo.cfg
2022-09-20 01:23:23,823 [myid:] - INFO  [main:o.a.z.s.q.QuorumPeerConfig@431] - clientPort is not set
2022-09-20 01:23:23,823 [myid:] - INFO  [main:o.a.z.s.q.QuorumPeerConfig@444] - secureClientPort is not set
2022-09-20 01:23:23,824 [myid:] - INFO  [main:o.a.z.s.q.QuorumPeerConfig@460] - observerMasterPort is not set
2022-09-20 01:23:23,824 [myid:] - INFO  [main:o.a.z.s.q.QuorumPeerConfig@477] - metricsProvider.className is org.apache.zookeeper.metrics.impl.DefaultMetricsProvider
2022-09-20 01:23:23,827 [myid:] - ERROR [main:o.a.z.s.q.QuorumPeerConfig@702] - Invalid configuration, only one server specified (ignoring)
2022-09-20 01:23:23,832 [myid:1] - INFO  [main:o.a.z.s.DatadirCleanupManager@78] - autopurge.snapRetainCount set to 3
2022-09-20 01:23:23,833 [myid:1] - INFO  [main:o.a.z.s.DatadirCleanupManager@79] - autopurge.purgeInterval set to 0
2022-09-20 01:23:23,833 [myid:1] - INFO  [main:o.a.z.s.DatadirCleanupManager@101] - Purge task is not scheduled.
2022-09-20 01:23:23,833 [myid:1] - WARN  [main:o.a.z.s.q.QuorumPeerMain@139] - Either no config or no quorum defined in config, running in standalone mode
2022-09-20 01:23:23,834 [myid:1] - INFO  [main:o.a.z.j.ManagedUtil@46] - Log4j 1.2 jmx support not found; jmx disabled.
2022-09-20 01:23:23,834 [myid:1] - INFO  [main:o.a.z.s.q.QuorumPeerConfig@177] - Reading configuration from: /conf/zoo.cfg
2022-09-20 01:23:23,834 [myid:1] - INFO  [main:o.a.z.s.q.QuorumPeerConfig@431] - clientPort is not set
2022-09-20 01:23:23,834 [myid:1] - INFO  [main:o.a.z.s.q.QuorumPeerConfig@444] - secureClientPort is not set
2022-09-20 01:23:23,834 [myid:1] - INFO  [main:o.a.z.s.q.QuorumPeerConfig@460] - observerMasterPort is not set
2022-09-20 01:23:23,834 [myid:1] - INFO  [main:o.a.z.s.q.QuorumPeerConfig@477] - metricsProvider.className is org.apache.zookeeper.metrics.impl.DefaultMetricsProvider
2022-09-20 01:23:23,834 [myid:1] - ERROR [main:o.a.z.s.q.QuorumPeerConfig@702] - Invalid configuration, only one server specified (ignoring)
2022-09-20 01:23:23,836 [myid:1] - INFO  [main:o.a.z.s.ZooKeeperServerMain@123] - Starting server
2022-09-20 01:23:23,841 [myid:1] - INFO  [main:o.a.z.s.ServerMetrics@64] - ServerMetrics initialized with provider org.apache.zookeeper.metrics.impl.DefaultMetricsProvider@2a65fe7c
2022-09-20 01:23:23,842 [myid:1] - INFO  [main:o.a.z.s.a.DigestAuthenticationProvider@47] - ACL digest algorithm is: SHA1
2022-09-20 01:23:23,843 [myid:1] - INFO  [main:o.a.z.s.a.DigestAuthenticationProvider@61] - zookeeper.DigestAuthenticationProvider.enabled = true
2022-09-20 01:23:23,844 [myid:1] - INFO  [main:o.a.z.s.p.FileTxnSnapLog@124] - zookeeper.snapshot.trust.empty : false
2022-09-20 01:23:23,849 [myid:1] - INFO  [main:o.a.z.ZookeeperBanner@42] - 
2022-09-20 01:23:23,849 [myid:1] - INFO  [main:o.a.z.ZookeeperBanner@42] -   ______                  _                                          
2022-09-20 01:23:23,849 [myid:1] - INFO  [main:o.a.z.ZookeeperBanner@42] -  |___  /                 | |                                         
2022-09-20 01:23:23,849 [myid:1] - INFO  [main:o.a.z.ZookeeperBanner@42] -     / /    ___     ___   | | __   ___    ___   _ __     ___   _ __   
2022-09-20 01:23:23,849 [myid:1] - INFO  [main:o.a.z.ZookeeperBanner@42] -    / /    / _ \   / _ \  | |/ /  / _ \  / _ \ | '_ \   / _ \ | '__|
2022-09-20 01:23:23,849 [myid:1] - INFO  [main:o.a.z.ZookeeperBanner@42] -   / /__  | (_) | | (_) | |   <  |  __/ |  __/ | |_) | |  __/ | |    
2022-09-20 01:23:23,849 [myid:1] - INFO  [main:o.a.z.ZookeeperBanner@42] -  /_____|  \___/   \___/  |_|\_\  \___|  \___| | .__/   \___| |_|
2022-09-20 01:23:23,849 [myid:1] - INFO  [main:o.a.z.ZookeeperBanner@42] -                                               | |                     
2022-09-20 01:23:23,849 [myid:1] - INFO  [main:o.a.z.ZookeeperBanner@42] -                                               |_|                     
2022-09-20 01:23:23,850 [myid:1] - INFO  [main:o.a.z.ZookeeperBanner@42] - 
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.Environment@98] - Server environment:zookeeper.version=3.8.0-5a02a05eddb59aee6ac762f7ea82e92a68eb9c0f, built on 2022-02-25 08:49 UTC
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.Environment@98] - Server environment:host.name=zookeeper
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.Environment@98] - Server environment:java.version=11.0.16
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.Environment@98] - Server environment:java.vendor=Oracle Corporation
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.Environment@98] - Server environment:java.home=/usr/local/openjdk-11
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.Environment@98] - Server environment:java.class.path=/apache-zookeeper-3.8.0-bin/bin/../zookeeper-server/target/classes:/apache-zookeeper-3.8.0-bin/bin/../build/classes:/apache-zookeeper-3.8.0-bin/bin/../zookeeper-server/target/lib/*.jar:/apache-zookeeper-3.8.0-bin/bin/../build/lib/*.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/zookeeper-prometheus-metrics-3.8.0.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/zookeeper-jute-3.8.0.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/zookeeper-3.8.0.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/snappy-java-1.1.7.7.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/slf4j-api-1.7.30.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/simpleclient_servlet-0.9.0.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/simpleclient_hotspot-0.9.0.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/simpleclient_common-0.9.0.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/simpleclient-0.9.0.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/netty-transport-native-unix-common-4.1.73.Final.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/netty-transport-native-epoll-4.1.73.Final.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/netty-transport-classes-epoll-4.1.73.Final.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/netty-transport-4.1.73.Final.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/netty-tcnative-classes-2.0.48.Final.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/netty-tcnative-2.0.48.Final.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/netty-resolver-4.1.73.Final.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/netty-handler-4.1.73.Final.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/netty-common-4.1.73.Final.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/netty-codec-4.1.73.Final.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/netty-buffer-4.1.73.Final.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/metrics-core-4.1.12.1.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/logback-core-1.2.10.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/logback-classic-1.2.10.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/jline-2.14.6.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/jetty-util-ajax-9.4.43.v20210629.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/jetty-util-9.4.43.v20210629.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/jetty-servlet-9.4.43.v20210629.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/jetty-server-9.4.43.v20210629.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/jetty-security-9.4.43.v20210629.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/jetty-io-9.4.43.v20210629.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/jetty-http-9.4.43.v20210629.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/javax.servlet-api-3.1.0.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/jackson-databind-2.13.1.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/jackson-core-2.13.1.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/jackson-annotations-2.13.1.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/commons-io-2.11.0.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/commons-cli-1.4.jar:/apache-zookeeper-3.8.0-bin/bin/../lib/audience-annotations-0.12.0.jar:/apache-zookeeper-3.8.0-bin/bin/../zookeeper-*.jar:/apache-zookeeper-3.8.0-bin/bin/../zookeeper-server/src/main/resources/lib/*.jar:/conf:
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.Environment@98] - Server environment:java.library.path=/usr/java/packages/lib:/lib:/usr/lib:/usr/lib64:/lib64
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.Environment@98] - Server environment:java.io.tmpdir=/tmp
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.Environment@98] - Server environment:java.compiler=<NA>
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.Environment@98] - Server environment:os.name=Linux
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.Environment@98] - Server environment:os.arch=aarch64
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.Environment@98] - Server environment:os.version=5.10.104-linuxkit
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.Environment@98] - Server environment:user.name=zookeeper
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.Environment@98] - Server environment:user.home=/home/zookeeper
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.Environment@98] - Server environment:user.dir=/apache-zookeeper-3.8.0-bin
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.Environment@98] - Server environment:os.memory.free=120MB
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.Environment@98] - Server environment:os.memory.max=1000MB
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.Environment@98] - Server environment:os.memory.total=128MB
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.s.ZooKeeperServer@140] - zookeeper.enableEagerACLCheck = false
2022-09-20 01:23:23,851 [myid:1] - INFO  [main:o.a.z.s.ZooKeeperServer@153] - zookeeper.digest.enabled = true
2022-09-20 01:23:23,852 [myid:1] - INFO  [main:o.a.z.s.ZooKeeperServer@157] - zookeeper.closeSessionTxn.enabled = true
2022-09-20 01:23:23,852 [myid:1] - INFO  [main:o.a.z.s.ZooKeeperServer@1496] - zookeeper.flushDelay = 0 ms
2022-09-20 01:23:23,852 [myid:1] - INFO  [main:o.a.z.s.ZooKeeperServer@1505] - zookeeper.maxWriteQueuePollTime = 0 ms
2022-09-20 01:23:23,852 [myid:1] - INFO  [main:o.a.z.s.ZooKeeperServer@1514] - zookeeper.maxBatchSize=1000
2022-09-20 01:23:23,852 [myid:1] - INFO  [main:o.a.z.s.ZooKeeperServer@264] - zookeeper.intBufferStartingSizeBytes = 1024
2022-09-20 01:23:23,852 [myid:1] - INFO  [main:o.a.z.s.BlueThrottle@141] - Weighed connection throttling is disabled
2022-09-20 01:23:23,853 [myid:1] - INFO  [main:o.a.z.s.ZooKeeperServer@1297] - minSessionTimeout set to 4000 ms
2022-09-20 01:23:23,853 [myid:1] - INFO  [main:o.a.z.s.ZooKeeperServer@1306] - maxSessionTimeout set to 40000 ms
2022-09-20 01:23:23,853 [myid:1] - INFO  [main:o.a.z.s.ResponseCache@45] - getData response cache size is initialized with value 400.
2022-09-20 01:23:23,853 [myid:1] - INFO  [main:o.a.z.s.ResponseCache@45] - getChildren response cache size is initialized with value 400.
2022-09-20 01:23:23,854 [myid:1] - INFO  [main:o.a.z.s.u.RequestPathMetricsCollector@109] - zookeeper.pathStats.slotCapacity = 60
2022-09-20 01:23:23,854 [myid:1] - INFO  [main:o.a.z.s.u.RequestPathMetricsCollector@110] - zookeeper.pathStats.slotDuration = 15
2022-09-20 01:23:23,854 [myid:1] - INFO  [main:o.a.z.s.u.RequestPathMetricsCollector@111] - zookeeper.pathStats.maxDepth = 6
2022-09-20 01:23:23,854 [myid:1] - INFO  [main:o.a.z.s.u.RequestPathMetricsCollector@112] - zookeeper.pathStats.initialDelay = 5
2022-09-20 01:23:23,854 [myid:1] - INFO  [main:o.a.z.s.u.RequestPathMetricsCollector@113] - zookeeper.pathStats.delay = 5
2022-09-20 01:23:23,854 [myid:1] - INFO  [main:o.a.z.s.u.RequestPathMetricsCollector@114] - zookeeper.pathStats.enabled = false
2022-09-20 01:23:23,855 [myid:1] - INFO  [main:o.a.z.s.ZooKeeperServer@1533] - The max bytes for all large requests are set to 104857600
2022-09-20 01:23:23,855 [myid:1] - INFO  [main:o.a.z.s.ZooKeeperServer@1547] - The large request threshold is set to -1
2022-09-20 01:23:23,856 [myid:1] - INFO  [main:o.a.z.s.AuthenticationHelper@66] - zookeeper.enforce.auth.enabled = false
2022-09-20 01:23:23,856 [myid:1] - INFO  [main:o.a.z.s.AuthenticationHelper@67] - zookeeper.enforce.auth.schemes = []
2022-09-20 01:23:23,856 [myid:1] - INFO  [main:o.a.z.s.ZooKeeperServer@365] - Created server with tickTime 2000 ms minSessionTimeout 4000 ms maxSessionTimeout 40000 ms clientPortListenBacklog -1 datadir /datalog/version-2 snapdir /data/version-2
2022-09-20 01:23:23,871 [myid:1] - INFO  [main:o.e.j.u.l.Log@170] - Logging initialized @367ms to org.eclipse.jetty.util.log.Slf4jLog
2022-09-20 01:23:23,919 [myid:1] - WARN  [main:o.e.j.s.h.ContextHandler@1656] - o.e.j.s.ServletContextHandler@437da279{/,null,STOPPED} contextPath ends with /*
2022-09-20 01:23:23,919 [myid:1] - WARN  [main:o.e.j.s.h.ContextHandler@1667] - Empty contextPath
2022-09-20 01:23:23,932 [myid:1] - INFO  [main:o.e.j.s.Server@375] - jetty-9.4.43.v20210629; built: 2021-06-30T11:07:22.254Z; git: 526006ecfa3af7f1a27ef3a288e2bef7ea9dd7e8; jvm 11.0.16+8
2022-09-20 01:23:23,953 [myid:1] - INFO  [main:o.e.j.s.s.DefaultSessionIdManager@334] - DefaultSessionIdManager workerName=node0
2022-09-20 01:23:23,953 [myid:1] - INFO  [main:o.e.j.s.s.DefaultSessionIdManager@339] - No SessionScavenger set, using defaults
2022-09-20 01:23:23,954 [myid:1] - INFO  [main:o.e.j.s.s.HouseKeeper@132] - node0 Scavenging every 660000ms
2022-09-20 01:23:23,956 [myid:1] - WARN  [main:o.e.j.s.ConstraintSecurityHandler@759] - [email protected]@437da279{/,null,STARTING} has uncovered http methods for path: /*
2022-09-20 01:23:23,961 [myid:1] - INFO  [main:o.e.j.s.h.ContextHandler@915] - Started o.e.j.s.ServletContextHandler@437da279{/,null,AVAILABLE}
2022-09-20 01:23:23,968 [myid:1] - INFO  [main:o.e.j.s.AbstractConnector@331] - Started ServerConnector@932bc4a{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}
2022-09-20 01:23:23,969 [myid:1] - INFO  [main:o.e.j.s.Server@415] - Started @465ms
2022-09-20 01:23:23,969 [myid:1] - INFO  [main:o.a.z.s.a.JettyAdminServer@196] - Started AdminServer on address 0.0.0.0, port 8080 and command URL /commands
2022-09-20 01:23:23,982 [myid:1] - INFO  [main:o.a.z.s.ContainerManager@84] - Using checkIntervalMs=60000 maxPerMinute=10000 maxNeverUsedIntervalMs=0
2022-09-20 01:23:23,988 [myid:1] - INFO  [main:o.a.z.a.ZKAuditProvider@42] - ZooKeeper audit is disabled.
2022-09-20 01:24:24,003 [myid:] - ERROR [ContainerManagerTask:o.a.z.s.ContainerManager$1@103] - Error checking containers
java.lang.NullPointerException: null
        at org.apache.zookeeper.server.ContainerManager.getCandidates(ContainerManager.java:162)
        at org.apache.zookeeper.server.ContainerManager.checkContainers(ContainerManager.java:129)
        at org.apache.zookeeper.server.ContainerManager$1.run(ContainerManager.java:97)
        at java.base/java.util.TimerThread.mainLoop(Unknown Source)
        at java.base/java.util.TimerThread.run(Unknown Source)

My kafka broker logs:

[main] INFO org.apache.zookeeper.ZooKeeper - Client environment:java.library.path=/usr/java/packages/lib:/lib:/usr/lib:/usr/lib64:/lib64
[main] INFO org.apache.zookeeper.ZooKeeper - Client environment:java.io.tmpdir=/tmp
[main] INFO org.apache.zookeeper.ZooKeeper - Client environment:java.compiler=<NA>
[main] INFO org.apache.zookeeper.ZooKeeper - Client environment:os.name=Linux
[main] INFO org.apache.zookeeper.ZooKeeper - Client environment:os.arch=aarch64
[main] INFO org.apache.zookeeper.ZooKeeper - Client environment:os.version=5.10.104-linuxkit
[main] INFO org.apache.zookeeper.ZooKeeper - Client environment:user.name=appuser
[main] INFO org.apache.zookeeper.ZooKeeper - Client environment:user.home=/home/appuser
[main] INFO org.apache.zookeeper.ZooKeeper - Client environment:user.dir=/home/appuser
[main] INFO org.apache.zookeeper.ZooKeeper - Client environment:os.memory.free=119MB
[main] INFO org.apache.zookeeper.ZooKeeper - Client environment:os.memory.max=1988MB
[main] INFO org.apache.zookeeper.ZooKeeper - Client environment:os.memory.total=126MB
[main] INFO org.apache.zookeeper.ZooKeeper - Initiating client connection, connectString=zookeeper:2181 sessionTimeout=40000 watcher=io.confluent.admin.utils.ZookeeperConnectionWatcher@1fc2b765
[main] INFO org.apache.zookeeper.common.X509Util - Setting -D jdk.tls.rejectClientInitiatedRenegotiation=true to disable client-initiated TLS renegotiation
[main] INFO org.apache.zookeeper.ClientCnxnSocket - jute.maxbuffer value is 1048575 Bytes
[main] INFO org.apache.zookeeper.ClientCnxn - zookeeper.request.timeout value is 0. feature enabled=false
[main-SendThread(zookeeper:2181)] INFO org.apache.zookeeper.ClientCnxn - Opening socket connection to server zookeeper/172.26.0.3:2181.
[main-SendThread(zookeeper:2181)] INFO org.apache.zookeeper.ClientCnxn - SASL config status: Will not attempt to authenticate using SASL (unknown error)
[main-SendThread(zookeeper:2181)] WARN org.apache.zookeeper.ClientCnxn - Session 0x0 for sever zookeeper/172.26.0.3:2181, Closing socket connection. Attempting reconnect except it is a SessionExpiredException.
java.net.ConnectException: Connection refused
        at java.base/sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
        at java.base/sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:777)
        at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:344)
        at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1290)
[main-SendThread(zookeeper:2181)] INFO org.apache.zookeeper.ClientCnxn - Opening socket connection to server zookeeper/172.26.0.3:2181.
[main-SendThread(zookeeper:2181)] INFO org.apache.zookeeper.ClientCnxn - SASL config status: Will not attempt to authenticate using SASL (unknown error)
[main-SendThread(zookeeper:2181)] WARN org.apache.zookeeper.ClientCnxn - Session 0x0 for sever zookeeper/172.26.0.3:2181, Closing socket connection. Attempting reconnect except it is a SessionExpiredException.
java.net.ConnectException: Connection refused
        at java.base/sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
        at java.base/sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:777)
        at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:344)
        at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1290)
[main-SendThread(zookeeper:2181)] INFO org.apache.zookeeper.ClientCnxn - Opening socket connection to server zookeeper/172.26.0.3:2181.
[main-SendThread(zookeeper:2181)] INFO org.apache.zookeeper.ClientCnxn - SASL config status: Will not attempt to authenticate using SASL (unknown error)

1 reply

scholzj Sep 20, 2022
Maintainer

I don't think the ZooKeeper and Kafka logs are coming from Strimzi since we use completely different versions and different configurations.

pocockn · 2023-01-10T14:33:21Z

pocockn
Jan 10, 2023

I'm also having this issue attempting to run Strimzi on Minikube, did you solve this @akikoogawa7 / @fanux

2 replies

fanux Jan 30, 2023
Author

NO, I having this issue on sealos

jerry1122 Jun 24, 2023

@fanux did you fix this , or still facing it

Strimzi

Startup probe failed,Attempting reconnect except it is a SessionExpiredException #6706

Uh oh!

fanux Apr 19, 2022

Replies: 15 comments · 3 replies

Uh oh!

scholzj Apr 19, 2022 Maintainer

Uh oh!

fanux Apr 19, 2022 Author

Uh oh!

fanux Apr 19, 2022 Author

Uh oh!

scholzj Apr 19, 2022 Maintainer

Uh oh!

fanux Apr 19, 2022 Author

Uh oh!

scholzj Apr 19, 2022 Maintainer

Uh oh!

fanux Apr 19, 2022 Author

Uh oh!

fanux Apr 19, 2022 Author

Uh oh!

scholzj Apr 19, 2022 Maintainer

Uh oh!

fanux Apr 20, 2022 Author

Uh oh!

Uh oh!

fanux Apr 20, 2022 Author

Uh oh!

scholzj Apr 20, 2022 Maintainer

Uh oh!

rudramaniteja Jul 21, 2022

Uh oh!

Uh oh!

akikoogawa7 Sep 20, 2022

Uh oh!

scholzj Sep 20, 2022 Maintainer

Uh oh!

Uh oh!

pocockn Jan 10, 2023

Uh oh!

fanux Jan 30, 2023 Author

Uh oh!

jerry1122 Jun 24, 2023

fanux
Apr 19, 2022

Replies: 15 comments 3 replies

scholzj
Apr 19, 2022
Maintainer

fanux
Apr 19, 2022
Author

fanux
Apr 19, 2022
Author

scholzj
Apr 19, 2022
Maintainer

fanux
Apr 19, 2022
Author

scholzj
Apr 19, 2022
Maintainer

fanux
Apr 19, 2022
Author

fanux
Apr 19, 2022
Author

scholzj
Apr 19, 2022
Maintainer

fanux
Apr 20, 2022
Author

fanux
Apr 20, 2022
Author

scholzj
Apr 20, 2022
Maintainer

rudramaniteja
Jul 21, 2022

akikoogawa7
Sep 20, 2022

scholzj Sep 20, 2022
Maintainer

pocockn
Jan 10, 2023

fanux Jan 30, 2023
Author