Strimzi entity operator not starting; vertx-blocked-thread-checker shows a blocked thread #9327

stevpier · 2023-11-06T14:59:09Z

stevpier
Nov 6, 2023

When I restart the strimzi entity operator, it starts up and within a few minutes, I see this message repeated:

2023-11-06 14:51:30,68589 WARN [vertx-blocked-thread-checker] BlockedThreadChecker: - Thread Thread[blocking-startup-ops-0,5,main] has been blocked for 60580 ms, time limit is 60000 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.strimzi.operator.topic.Session.createTopicStore(Session.java:324) ~[io.strimzi.topic-operator-0.30.0.jar:0.30.0]
at io.strimzi.operator.topic.Session$$Lambda$226/0x00000008402e0c40.apply(Unknown Source) ~[?:?]
at io.strimzi.operator.topic.Session.lambda$createTopicStoreAsync$15(Session.java:254) ~[io.strimzi.topic-operator-0.30.0.jar:0.30.0]
at io.strimzi.operator.topic.Session$$Lambda$467/0x00000008404ad840.handle(Unknown Source) ~[?:?]
at io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159) ~[io.vertx.vertx-core-4.2.4.jar:4.2.4]
at io.vertx.core.impl.ContextImpl$$Lambda$318/0x00000008403ce840.handle(Unknown Source) ~[?:?]
at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100) ~[io.vertx.vertx-core-4.2.4.jar:4.2.4]
at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157) ~[io.vertx.vertx-core-4.2.4.jar:4.2.4]
at io.vertx.core.impl.ContextImpl$$Lambda$315/0x00000008403cf840.run(Unknown Source) ~[?:?]
at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76) ~[io.vertx.vertx-core-4.2.4.jar:4.2.4]
at io.vertx.core.impl.TaskQueue$$Lambda$234/0x00000008402e7040.run(Unknown Source) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[io.netty.netty-common-4.1.77.Final.jar:4.1.77.Final]

I suspect this has something to do with the Kafka Streams store of topic information. I suspect that the stream is corrupted on my cluster. This cluster is in production, and I'd love to reinitialize whatever's broken.

How can I fix the entity operator?

Thanks,

Steve

Startup log:

Preparing trust store certificates for internal communication
Adding /etc/tls-sidecar/cluster-ca-certs/ca.crt to truststore /tmp/topic-operator/replication.truststore.p12 with alias ca
Certificate was added to keystore
Preparing trust store certificates for internal communication is completed
Preparing key store certificates for internal communication
Preparing key store certificates for internal communication is completed

exec /usr/bin/tini -w -e 143 -- java -Dlog4j2.configurationFile=file:/opt/topic-operator/custom-config/log4j2.properties -Dvertx.cacheDirBase=/tmp/vertx-cache -Djava.security.egd=file:/dev/./urandom --illegal-access=deny -XX:+ExitOnOutOfMemoryError -XX:MinRAMPercentage=10 -XX:MaxRAMPercentage=20 -XX:InitialRAMPercentage=10 -classpath lib/io.strimzi.topic-operator-0.30.0.jar:lib/io.fabric8.kubernetes-model-discovery-5.12.2.jar:lib/io.prometheus.simpleclient_common-0.7.0.jar:lib/io.apicurio.apicurio-registry-utils-streams-1.3.2.Final.jar:lib/io.netty.netty-transport-4.1.77.Final.jar:lib/io.netty.netty-codec-socks-4.1.77.Final.jar:lib/io.fabric8.kubernetes-model-events-5.12.2.jar:lib/com.fasterxml.jackson.datatype.jackson-datatype-jsr310-2.13.1.jar:lib/io.netty.netty-transport-native-epoll-4.1.77.Final.jar:lib/com.101tec.zkclient-0.11.jar:lib/org.lz4.lz4-java-1.8.0.jar:lib/io.vertx.vertx-core-4.2.4.jar:lib/com.squareup.okio.okio-1.15.0.jar:lib/io.apicurio.apicurio-registry-utils-kafka-1.3.2.Final.jar:lib/org.xerial.snappy.snappy-java-1.1.8.4.jar:lib/io.netty.netty-handler-proxy-4.1.77.Final.jar:lib/org.slf4j.slf4j-api-1.7.36.jar:lib/org.apache.kafka.kafka-streams-3.2.0.jar:lib/io.fabric8.kubernetes-model-common-5.12.2.jar:lib/io.fabric8.kubernetes-model-autoscaling-5.12.2.jar:lib/jakarta.annotation.jakarta.annotation-api-1.3.5.jar:lib/org.hdrhistogram.HdrHistogram-2.1.11.jar:lib/com.fasterxml.jackson.dataformat.jackson-dataformat-yaml-2.12.6.jar:lib/io.strimzi.crd-annotations-0.30.0.jar:lib/io.fabric8.kubernetes-model-apiextensions-5.12.2.jar:lib/io.fabric8.openshift-client-5.12.2.jar:lib/io.fabric8.openshift-model-whereabouts-5.12.2.jar:lib/io.prometheus.simpleclient-0.7.0.jar:lib/com.fasterxml.jackson.core.jackson-databind-2.12.6.1.jar:lib/com.squareup.okhttp3.logging-interceptor-3.12.12.jar:lib/org.apache.yetus.audience-annotations-0.5.0.jar:lib/io.netty.netty-codec-4.1.77.Final.jar:lib/io.fabric8.openshift-model-machineconfig-5.12.2.jar:lib/io.fabric8.openshift-model-storageversionmigrator-5.12.2.jar:lib/io.fabric8.kubernetes-model-networking-5.12.2.jar:lib/org.apache.zookeeper.zookeeper-jute-3.6.3.jar:lib/io.micrometer.micrometer-core-1.3.1.jar:lib/org.apache.zookeeper.zookeeper-3.6.3.jar:lib/io.netty.netty-resolver-dns-4.1.77.Final.jar:lib/io.netty.netty-handler-4.1.77.Final.jar:lib/io.strimzi.operator-common-0.30.0.jar:lib/io.fabric8.openshift-model-monitoring-5.12.2.jar:lib/com.fasterxml.jackson.core.jackson-core-2.12.6.jar:lib/io.fabric8.kubernetes-client-5.12.2.jar:lib/com.squareup.okhttp3.okhttp-3.12.12.jar:lib/com.github.mifmif.generex-1.0.2.jar:lib/org.apache.logging.log4j.log4j-api-2.17.2.jar:lib/org.apache.logging.log4j.log4j-slf4j-impl-2.17.2.jar:lib/io.fabric8.kubernetes-model-certificates-5.12.2.jar:lib/io.fabric8.openshift-model-console-5.12.2.jar:lib/io.strimzi.certificate-manager-0.30.0.jar:lib/io.netty.netty-codec-http-4.1.77.Final.jar:lib/org.apache.kafka.kafka-clients-3.2.0.jar:lib/io.netty.netty-buffer-4.1.77.Final.jar:lib/io.apicurio.apicurio-registry-common-1.3.2.Final.jar:lib/io.fabric8.kubernetes-model-metrics-5.12.2.jar:lib/org.apache.logging.log4j.log4j-core-2.17.2.jar:lib/io.fabric8.openshift-model-installer-5.12.2.jar:lib/io.fabric8.kubernetes-model-flowcontrol-5.12.2.jar:lib/io.fabric8.openshift-model-hive-5.12.2.jar:lib/dk.brics.automaton.automaton-1.11-8.jar:lib/org.eclipse.microprofile.config.microprofile-config-api-1.4.jar:lib/io.fabric8.openshift-model-miscellaneous-5.12.2.jar:lib/io.fabric8.kubernetes-model-apps-5.12.2.jar:lib/io.fabric8.kubernetes-model-storageclass-5.12.2.jar:lib/io.netty.netty-codec-http2-4.1.77.Final.jar:lib/io.fabric8.kubernetes-model-node-5.12.2.jar:lib/com.github.luben.zstd-jni-1.5.2-1.jar:lib/io.fabric8.openshift-model-operator-5.12.2.jar:lib/io.fabric8.openshift-model-machine-5.12.2.jar:lib/io.fabric8.zjsonpatch-0.3.0.jar:lib/org.jboss.spec.javax.ws.rs.jboss-jaxrs-api_2.1_spec-2.0.1.Final.jar:lib/io.fabric8.openshift-model-clusterautoscaling-5.12.2.jar:lib/org.yaml.snakeyaml-1.27.jar:lib/io.netty.netty-codec-dns-4.1.77.Final.jar:lib/io.fabric8.openshift-model-5.12.2.jar:lib/io.netty.netty-resolver-4.1.77.Final.jar:lib/org.rocksdb.rocksdbjni-6.29.4.1.jar:lib/io.fabric8.kubernetes-model-core-5.12.2.jar:lib/io.netty.netty-transport-classes-epoll-4.1.77.Final.jar:lib/io.fabric8.kubernetes-model-rbac-5.12.2.jar:lib/io.fabric8.kubernetes-model-policy-5.12.2.jar:lib/org.latencyutils.LatencyUtils-2.0.3.jar:lib/io.strimzi.api-0.30.0.jar:lib/io.fabric8.kubernetes-model-admissionregistration-5.12.2.jar:lib/io.fabric8.openshift-model-tuned-5.12.2.jar:lib/io.vertx.vertx-micrometer-metrics-4.2.4.jar:lib/io.fabric8.kubernetes-model-scheduling-5.12.2.jar:lib/io.fabric8.openshift-model-operatorhub-5.12.2.jar:lib/com.fasterxml.jackson.core.jackson-annotations-2.12.6.jar:lib/io.netty.netty-transport-native-unix-common-4.1.77.Final.jar:lib/io.fabric8.kubernetes-model-batch-5.12.2.jar:lib/io.fabric8.kubernetes-model-coordination-5.12.2.jar:lib/io.micrometer.micrometer-registry-prometheus-1.3.1.jar:lib/io.fabric8.kubernetes-model-extensions-5.12.2.jar:lib/io.netty.netty-common-4.1.77.Final.jar:lib/org.quartz-scheduler.quartz-2.3.2.jar io.strimzi.operator.topic.Main
2023-11-06 14:50:22,71181 INFO [main] Main:29 - TopicOperator 0.30.0 is starting
2023-11-06 14:50:25,07439 INFO [main] Session:116 - Using config:
STRIMZI_TRUSTSTORE_LOCATION: /tmp/topic-operator/replication.truststore.p12
STRIMZI_RESOURCE_LABELS: strimzi.io/cluster=bes
STRIMZI_SASL_MECHANISM:
STRIMZI_SASL_USERNAME:
STRIMZI_FULL_RECONCILIATION_INTERVAL_MS: 120000
STRIMZI_CLIENT_ID: strimzi-topic-operator-dbc7c481-a726-4f91-a2ec-3c38cab6c2e5
STRIMZI_SECURITY_PROTOCOL: SSL
STRIMZI_STALE_RESULT_TIMEOUT_MS: 5000
STRIMZI_TOPIC_METADATA_MAX_ATTEMPTS: 6
STRIMZI_KEYSTORE_LOCATION: /tmp/topic-operator/replication.keystore.p12
STRIMZI_REASSIGN_THROTTLE: 9223372036854775807
STRIMZI_USE_ZOOKEEPER_TOPIC_STORE: false
STRIMZI_SASL_PASSWORD: ********
STRIMZI_KAFKA_BOOTSTRAP_SERVERS: bes-kafka-bootstrap:9091
STRIMZI_SASL_ENABLED: false
STRIMZI_SSL_ENDPOINT_IDENTIFICATION_ALGORITHM: HTTPS
STRIMZI_NAMESPACE: bes
STRIMZI_APPLICATION_ID: __strimzi-topic-operator-kstreams
STRIMZI_ZOOKEEPER_SESSION_TIMEOUT_MS: 18000
STRIMZI_TOPICS_PATH: /strimzi/topics
STRIMZI_ZOOKEEPER_CONNECT: localhost:2181
STRIMZI_TLS_ENABLED: true
STRIMZI_KEYSTORE_PASSWORD: ********
STRIMZI_STORE_NAME: topic-store
STRIMZI_REASSIGN_VERIFY_INTERVAL_MS: 120000
TC_ZK_CONNECTION_TIMEOUT_MS: 18000
STRIMZI_TRUSTSTORE_PASSWORD: ********
STRIMZI_STORE_TOPIC: __strimzi_store_topic

2023-11-06 14:50:25,12793 INFO [vert.x-eventloop-thread-0] Session:200 - Starting
2023-11-06 14:50:25,68331 INFO [vert.x-eventloop-thread-0] AppInfoParser:119 - Kafka version: 3.2.0
2023-11-06 14:50:25,68367 INFO [vert.x-eventloop-thread-0] AppInfoParser:120 - Kafka commitId: 38103ffaa962ef50
2023-11-06 14:50:25,68386 INFO [vert.x-eventloop-thread-0] AppInfoParser:121 - Kafka startTimeMs: 1699282225666
2023-11-06 14:50:26,52184 INFO [ZkClient-EventThread-20-localhost:2181] ZkEventThread:65 - Starting ZkClient event thread.
2023-11-06 14:50:26,54342 INFO [vert.x-worker-thread-0] ZooKeeper:98 - Client environment:zookeeper.version=3.6.3--6401e4ad2087061bc6b9f80dec2d69f2e3c8660a, built on 04/08/2021 16:35 GMT
2023-11-06 14:50:26,54442 INFO [vert.x-worker-thread-0] ZooKeeper:98 - Client environment:host.name=bes-entity-operator-9f59889d-l8pwm
2023-11-06 14:50:26,54468 INFO [vert.x-worker-thread-0] ZooKeeper:98 - Client environment:java.version=11.0.15
2023-11-06 14:50:26,54486 INFO [vert.x-worker-thread-0] ZooKeeper:98 - Client environment:java.vendor=Red Hat, Inc.
2023-11-06 14:50:26,54503 INFO [vert.x-worker-thread-0] ZooKeeper:98 - Client environment:java.home=/usr/lib/jvm/java-11-openjdk-11.0.15.0.10-2.el8_6.x86_64
2023-11-06 14:50:26,54558 INFO [vert.x-worker-thread-0] ZooKeeper:98 - Client environment:java.class.path=lib/io.strimzi.topic-operator-0.30.0.jar:lib/io.fabric8.kubernetes-model-discovery-5.12.2.jar:lib/io.prometheus.simpleclient_common-0.7.0.jar:lib/io.apicurio.apicurio-registry-utils-streams-1.3.2.Final.jar:lib/io.netty.netty-transport-4.1.77.Final.jar:lib/io.netty.netty-codec-socks-4.1.77.Final.jar:lib/io.fabric8.kubernetes-model-events-5.12.2.jar:lib/com.fasterxml.jackson.datatype.jackson-datatype-jsr310-2.13.1.jar:lib/io.netty.netty-transport-native-epoll-4.1.77.Final.jar:lib/com.101tec.zkclient-0.11.jar:lib/org.lz4.lz4-java-1.8.0.jar:lib/io.vertx.vertx-core-4.2.4.jar:lib/com.squareup.okio.okio-1.15.0.jar:lib/io.apicurio.apicurio-registry-utils-kafka-1.3.2.Final.jar:lib/org.xerial.snappy.snappy-java-1.1.8.4.jar:lib/io.netty.netty-handler-proxy-4.1.77.Final.jar:lib/org.slf4j.slf4j-api-1.7.36.jar:lib/org.apache.kafka.kafka-streams-3.2.0.jar:lib/io.fabric8.kubernetes-model-common-5.12.2.jar:lib/io.fabric8.kubernetes-model-autoscaling-5.12.2.jar:lib/jakarta.annotation.jakarta.annotation-api-1.3.5.jar:lib/org.hdrhistogram.HdrHistogram-2.1.11.jar:lib/com.fasterxml.jackson.dataformat.jackson-dataformat-yaml-2.12.6.jar:lib/io.strimzi.crd-annotations-0.30.0.jar:lib/io.fabric8.kubernetes-model-apiextensions-5.12.2.jar:lib/io.fabric8.openshift-client-5.12.2.jar:lib/io.fabric8.openshift-model-whereabouts-5.12.2.jar:lib/io.prometheus.simpleclient-0.7.0.jar:lib/com.fasterxml.jackson.core.jackson-databind-2.12.6.1.jar:lib/com.squareup.okhttp3.logging-interceptor-3.12.12.jar:lib/org.apache.yetus.audience-annotations-0.5.0.jar:lib/io.netty.netty-codec-4.1.77.Final.jar:lib/io.fabric8.openshift-model-machineconfig-5.12.2.jar:lib/io.fabric8.openshift-model-storageversionmigrator-5.12.2.jar:lib/io.fabric8.kubernetes-model-networking-5.12.2.jar:lib/org.apache.zookeeper.zookeeper-jute-3.6.3.jar:lib/io.micrometer.micrometer-core-1.3.1.jar:lib/org.apache.zookeeper.zookeeper-3.6.3.jar:lib/io.netty.netty-resolver-dns-4.1.77.Final.jar:lib/io.netty.netty-handler-4.1.77.Final.jar:lib/io.strimzi.operator-common-0.30.0.jar:lib/io.fabric8.openshift-model-monitoring-5.12.2.jar:lib/com.fasterxml.jackson.core.jackson-core-2.12.6.jar:lib/io.fabric8.kubernetes-client-5.12.2.jar:lib/com.squareup.okhttp3.okhttp-3.12.12.jar:lib/com.github.mifmif.generex-1.0.2.jar:lib/org.apache.logging.log4j.log4j-api-2.17.2.jar:lib/org.apache.logging.log4j.log4j-slf4j-impl-2.17.2.jar:lib/io.fabric8.kubernetes-model-certificates-5.12.2.jar:lib/io.fabric8.openshift-model-console-5.12.2.jar:lib/io.strimzi.certificate-manager-0.30.0.jar:lib/io.netty.netty-codec-http-4.1.77.Final.jar:lib/org.apache.kafka.kafka-clients-3.2.0.jar:lib/io.netty.netty-buffer-4.1.77.Final.jar:lib/io.apicurio.apicurio-registry-common-1.3.2.Final.jar:lib/io.fabric8.kubernetes-model-metrics-5.12.2.jar:lib/org.apache.logging.log4j.log4j-core-2.17.2.jar:lib/io.fabric8.openshift-model-installer-5.12.2.jar:lib/io.fabric8.kubernetes-model-flowcontrol-5.12.2.jar:lib/io.fabric8.openshift-model-hive-5.12.2.jar:lib/dk.brics.automaton.automaton-1.11-8.jar:lib/org.eclipse.microprofile.config.microprofile-config-api-1.4.jar:lib/io.fabric8.openshift-model-miscellaneous-5.12.2.jar:lib/io.fabric8.kubernetes-model-apps-5.12.2.jar:lib/io.fabric8.kubernetes-model-storageclass-5.12.2.jar:lib/io.netty.netty-codec-http2-4.1.77.Final.jar:lib/io.fabric8.kubernetes-model-node-5.12.2.jar:lib/com.github.luben.zstd-jni-1.5.2-1.jar:lib/io.fabric8.openshift-model-operator-5.12.2.jar:lib/io.fabric8.openshift-model-machine-5.12.2.jar:lib/io.fabric8.zjsonpatch-0.3.0.jar:lib/org.jboss.spec.javax.ws.rs.jboss-jaxrs-api_2.1_spec-2.0.1.Final.jar:lib/io.fabric8.openshift-model-clusterautoscaling-5.12.2.jar:lib/org.yaml.snakeyaml-1.27.jar:lib/io.netty.netty-codec-dns-4.1.77.Final.jar:lib/io.fabric8.openshift-model-5.12.2.jar:lib/io.netty.netty-resolver-4.1.77.Final.jar:lib/org.rocksdb.rocksdbjni-6.29.4.1.jar:lib/io.fabric8.kubernetes-model-core-5.12.2.jar:lib/io.netty.netty-transport-classes-epoll-4.1.77.Final.jar:lib/io.fabric8.kubernetes-model-rbac-5.12.2.jar:lib/io.fabric8.kubernetes-model-policy-5.12.2.jar:lib/org.latencyutils.LatencyUtils-2.0.3.jar:lib/io.strimzi.api-0.30.0.jar:lib/io.fabric8.kubernetes-model-admissionregistration-5.12.2.jar:lib/io.fabric8.openshift-model-tuned-5.12.2.jar:lib/io.vertx.vertx-micrometer-metrics-4.2.4.jar:lib/io.fabric8.kubernetes-model-scheduling-5.12.2.jar:lib/io.fabric8.openshift-model-operatorhub-5.12.2.jar:lib/com.fasterxml.jackson.core.jackson-annotations-2.12.6.jar:lib/io.netty.netty-transport-native-unix-common-4.1.77.Final.jar:lib/io.fabric8.kubernetes-model-batch-5.12.2.jar:lib/io.fabric8.kubernetes-model-coordination-5.12.2.jar:lib/io.micrometer.micrometer-registry-prometheus-1.3.1.jar:lib/io.fabric8.kubernetes-model-extensions-5.12.2.jar:lib/io.netty.netty-common-4.1.77.Final.jar:lib/org.quartz-scheduler.quartz-2.3.2.jar
2023-11-06 14:50:26,54600 INFO [vert.x-worker-thread-0] ZooKeeper:98 - Client environment:java.library.path=/usr/java/packages/lib:/usr/lib64:/lib64:/lib:/usr/lib
2023-11-06 14:50:26,54641 INFO [vert.x-worker-thread-0] ZooKeeper:98 - Client environment:java.io.tmpdir=/tmp
2023-11-06 14:50:26,54661 INFO [vert.x-worker-thread-0] ZooKeeper:98 - Client environment:java.compiler=
2023-11-06 14:50:26,54677 INFO [vert.x-worker-thread-0] ZooKeeper:98 - Client environment:os.name=Linux
2023-11-06 14:50:26,54692 INFO [vert.x-worker-thread-0] ZooKeeper:98 - Client environment:os.arch=amd64
2023-11-06 14:50:26,54720 INFO [vert.x-worker-thread-0] ZooKeeper:98 - Client environment:os.version=4.18.0-372.19.1.el8_6.x86_64
2023-11-06 14:50:26,54737 INFO [vert.x-worker-thread-0] ZooKeeper:98 - Client environment:user.name=strimzi
2023-11-06 14:50:26,54838 INFO [vert.x-worker-thread-0] ZooKeeper:98 - Client environment:user.home=/home/strimzi
2023-11-06 14:50:26,54867 INFO [vert.x-worker-thread-0] ZooKeeper:98 - Client environment:user.dir=/opt/strimzi
2023-11-06 14:50:26,54885 INFO [vert.x-worker-thread-0] ZooKeeper:98 - Client environment:os.memory.free=2588MB
2023-11-06 14:50:26,54899 INFO [vert.x-worker-thread-0] ZooKeeper:98 - Client environment:os.memory.max=5428MB
2023-11-06 14:50:26,54915 INFO [vert.x-worker-thread-0] ZooKeeper:98 - Client environment:os.memory.total=2714MB
2023-11-06 14:50:26,56070 INFO [vert.x-worker-thread-0] ZooKeeper:1006 - Initiating client connection, connectString=localhost:2181 sessionTimeout=18000 watcher=org.I0Itec.zkclient.ZkClient@6f1f6efa
2023-11-06 14:50:26,57454 INFO [vert.x-worker-thread-0] X509Util:77 - Setting -D jdk.tls.rejectClientInitiatedRenegotiation=true to disable client-initiated TLS renegotiation
2023-11-06 14:50:26,60038 INFO [vert.x-worker-thread-0] ClientCnxnSocket:239 - jute.maxbuffer value is 1048575 Bytes
2023-11-06 14:50:26,63907 INFO [vert.x-worker-thread-0] ClientCnxn:1736 - zookeeper.request.timeout value is 0. feature enabled=false
2023-11-06 14:50:26,64350 INFO [vert.x-worker-thread-0] ZkClient:936 - Waiting for keeper state SyncConnected
2023-11-06 14:50:26,65546 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.
2023-11-06 14:50:26,65623 INFO [vert.x-worker-thread-0-SendThread(localhost:2181)] ClientCnxn:1183 - SASL config status: Will not attempt to authenticate using SASL (unknown error)
2023-11-06 14:50:26,65749 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]
2023-11-06 14:50:27,78115 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.
2023-11-06 14:50:27,78150 INFO [vert.x-worker-thread-0-SendThread(localhost:2181)] ClientCnxn:1183 - SASL config status: Will not attempt to authenticate using SASL (unknown error)
2023-11-06 14:50:27,78250 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.
2023-11-06 14:51:30,68589 WARN [vertx-blocked-thread-checker] BlockedThreadChecker: - Thread Thread[blocking-startup-ops-0,5,main] has been blocked for 60580 ms, time limit is 60000 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.strimzi.operator.topic.Session.createTopicStore(Session.java:324) ~[io.strimzi.topic-operator-0.30.0.jar:0.30.0]
at io.strimzi.operator.topic.Session$$Lambda$226/0x00000008402e0c40.apply(Unknown Source) ~[?:?]
at io.strimzi.operator.topic.Session.lambda$createTopicStoreAsync$15(Session.java:254) ~[io.strimzi.topic-operator-0.30.0.jar:0.30.0]
at io.strimzi.operator.topic.Session$$Lambda$467/0x00000008404ad840.handle(Unknown Source) ~[?:?]
at io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159) ~[io.vertx.vertx-core-4.2.4.jar:4.2.4]
at io.vertx.core.impl.ContextImpl$$Lambda$318/0x00000008403ce840.handle(Unknown Source) ~[?:?]
at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100) ~[io.vertx.vertx-core-4.2.4.jar:4.2.4]
at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157) ~[io.vertx.vertx-core-4.2.4.jar:4.2.4]
at io.vertx.core.impl.ContextImpl$$Lambda$315/0x00000008403cf840.run(Unknown Source) ~[?:?]
at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76) ~[io.vertx.vertx-core-4.2.4.jar:4.2.4]
at io.vertx.core.impl.TaskQueue$$Lambda$234/0x00000008402e7040.run(Unknown Source) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[io.netty.netty-common-4.1.77.Final.jar:4.1.77.Final]

Answered by stevpier

Nov 9, 2023

I added this to the kafka cluster definition:

  entityOperator:
    template:
      topicOperatorContainer:
        env:
        - name: STRIMZI_USE_ZOOKEEPER_TOPIC_STORE
          value: "true"

The entity operator pod needed to be deleted, and the new pod, once started, came up.

View full answer

scholzj · 2023-11-06T15:32:59Z

scholzj
Nov 6, 2023
Maintainer

Can you please format the log to make it readable?

0 replies

stevpier · 2023-11-07T03:15:39Z

stevpier
Nov 7, 2023
Author

log.txt
Log file attached. Not sure exactly how to format it better, so here's the actual output, without any formatting at all.

1 reply

scholzj Nov 7, 2023
Maintainer

@tombentley @fvaleri Any ideas?

stevpier · 2023-11-07T14:48:26Z

stevpier
Nov 7, 2023
Author

If it helps, I had this problem on a dev cluster. I changed the number of partitions on the __strimzi_store_topic topic, and shortly after the entity operator had this same problem. I had to rebuild the entire kafka cluster to fix the entity operator. I wasn't able to figure out another way to solve the problem. Since this cluster is production, that solution won't work. I did not try to reproduce the failure, so I don't know if it was the cause, or just a coincidence.

Also, I asked the team, and they did not change the topic partition count for the production cluster.

0 replies

stevpier · 2023-11-07T14:50:14Z

stevpier
Nov 7, 2023
Author

I also checked the user operator, and it's running fine. It's just the topic operator that's not working.

FYI: I'm running 0.30. I'm working on upgrading, to see if that helps.

2 replies

scholzj Nov 7, 2023
Maintainer

I don't think there were any changes to the old Topic Operator in the latest releases. So I would not expect the upgrade to help. In the next version (0.39) the new Unidirectional Topic Operator will be used. The User Operator is independent on this, so it has nothing to do with it, so it would be expected that it is not affected.

stevpier Nov 7, 2023
Author

I'm scheduling our upgrade for sometime this week.

fvaleri · 2023-11-08T15:00:04Z

fvaleri
Nov 8, 2023
Collaborator

It looks like the TO is waiting for the Kafka Streams state-store to become ready (state=RUNNING), and this never happens.

2023-11-07 03:13:39,43741 INFO  [kafka-admin-client-thread | adminclient-2] KafkaStreamsTopicStoreService:97 - Creating Kafka Streams, store name: topic-store

Do you have any error log and/or topic failing the reconciliation with InvalidStateStoreException? In that case, check this thread for a possible workaround.

Then, if you are upgrading, consider enabling the new Unidirectional Topic Operator.

12 replies

stevpier Nov 9, 2023
Author

No. It may be that logs rolled, so you can only recover them if you have a log aggregation stack in your Kubernetes cluster with enough retention time. Occasionally, I've also seen this exception in KafkaTopic status.

I'll restart the topic operator, wait for ten minutes and check again.

stevpier Nov 9, 2023
Author

Log file is log.txt

stevpier@STEVPIER-M-9RVX ~ % kubectl logs bes-entity-operator-9f59889d-5nskb -c topic-operator> ~/Downloads/log.txt
stevpier@STEVPIER-M-9RVX ~ % grep Invalid ~/Downloads/log.txt
stevpier@STEVPIER-M-9RVX ~ %

scholzj Nov 9, 2023
Maintainer

Seems like it's extra-beta in 0.38, and regular beta in 0.39 (planned).

Maybe the terminology we use there is not the best. But actually, in 0.39 it will be enabled by default for everyone => that means we see it as stable and GA quality code and just leaving people the option to postpone it by disabling the feature gate if they for example need to adjust their tooling for the changes in the Topic OPerator behavior. I think there are some minor bugs reported in 0.38, but nothing major.

stevpier Nov 9, 2023
Author

But actually, in 0.39 it will be enabled by default for everyone => that means we see it as stable and GA quality code and just leaving people the option to postpone it by disabling the feature gate

I'll be holding off on the UTO until at least 0.39; maybe one more release after; the zookeeper store is working fine for me.

scholzj Nov 10, 2023
Maintainer

That is completely up to you. Just keep in mind that the ZooKeeper store is not part of any system tests and has not been used for a long time. So be careful, especially during upgrades.

stevpier · 2023-11-09T19:23:56Z

stevpier
Nov 9, 2023
Author

I added this to the kafka cluster definition:

  entityOperator:
    template:
      topicOperatorContainer:
        env:
        - name: STRIMZI_USE_ZOOKEEPER_TOPIC_STORE
          value: "true"

The entity operator pod needed to be deleted, and the new pod, once started, came up.

0 replies

Strimzi

Strimzi entity operator not starting; vertx-blocked-thread-checker shows a blocked thread #9327

Uh oh!

Uh oh!

stevpier Nov 6, 2023

Replies: 6 comments · 15 replies

Uh oh!

Uh oh!

scholzj Nov 6, 2023 Maintainer

Uh oh!

stevpier Nov 7, 2023 Author

Uh oh!

scholzj Nov 7, 2023 Maintainer

Uh oh!

Uh oh!

stevpier Nov 7, 2023 Author

Uh oh!

stevpier Nov 7, 2023 Author

Uh oh!

scholzj Nov 7, 2023 Maintainer

Uh oh!

stevpier Nov 7, 2023 Author

Uh oh!

Uh oh!

fvaleri Nov 8, 2023 Collaborator

Uh oh!

stevpier Nov 9, 2023 Author

Uh oh!

stevpier Nov 9, 2023 Author

Uh oh!

scholzj Nov 9, 2023 Maintainer

Uh oh!

stevpier Nov 9, 2023 Author

Uh oh!

scholzj Nov 10, 2023 Maintainer

Uh oh!

stevpier Nov 9, 2023 Author

stevpier
Nov 6, 2023

Replies: 6 comments 15 replies

scholzj
Nov 6, 2023
Maintainer

stevpier
Nov 7, 2023
Author

scholzj Nov 7, 2023
Maintainer

stevpier
Nov 7, 2023
Author

stevpier
Nov 7, 2023
Author

scholzj Nov 7, 2023
Maintainer

stevpier Nov 7, 2023
Author

fvaleri
Nov 8, 2023
Collaborator

stevpier Nov 9, 2023
Author

stevpier Nov 9, 2023
Author

scholzj Nov 9, 2023
Maintainer

stevpier Nov 9, 2023
Author

scholzj Nov 10, 2023
Maintainer

stevpier
Nov 9, 2023
Author