Kafka CRD Going into NotReady state after sometime with "io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod apps-kafka-2 cannot be updated right now." Error

[navnitkum]

We have strimzi kafka cluster running with 3 brokers , the kafka CR is suddenly going into Not Ready state after being healthy for sometime , the status in CR says io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod apps-kafka-2 cannot be updated right now.

Below is the kafka logs for the apps-kafka-2

,896 INFO [Partition __consumer_offsets-4 broker=2] ISR updated to 0,2,1 and version updated to 3341 (kafka.cluster.Partition) [zk-broker-2-to-controller-alter-partition-channel-manager] 2024-10-08 06:36:35,897 INFO [Partition __consumer_offsets-33 broker=2] ISR updated to 0,2,1 and version updated to 3347 (kafka.cluster.Partition) [zk-broker-2-to-controller-alter-partition-channel-manager] 2024-10-08 06:36:35,897 INFO [Partition dbm-changes-mongodb.risk_orchestrator_riskdata.multi_platform_detection_advanceai_aggregate-0 broker=2] ISR updated to 0,2,1 and version updated to 240 (kafka.cluster.Partition) [zk-broker-2-to-controller-alter-partition-channel-manager] 2024-10-08 06:36:36,301 DEBUG [Controller id=2] Updating ISRs for partitions: Set(__consumer_offsets-46). (kafka.controller.KafkaController) [controller-event-thread] 2024-10-08 06:36:36,307 DEBUG [Controller id=2] ISR for partition __consumer_offsets-46 updated to LeaderAndIsr(leader=2, leaderEpoch=2030, isrWithBrokerEpoch=List(BrokerState(brokerId=0, brokerEpoch=-1), BrokerState(brokerId=2, brokerEpoch=-1), BrokerState(brokerId=1, brokerEpoch=-1)), leaderRecoveryState=RECOVERED, partitionEpoch=3341). (kafka.controller.KafkaController) [controller-event-thread] 2024-10-08 06:36:36,313 INFO [Controller id=2 epoch=812] Sending UpdateMetadata request to brokers HashSet(0, 1, 2) for 1 partitions (state.change.logger) [controller-event-thread] 2024-10-08 06:36:36,315 TRACE [Broker id=2] Cached leader info UpdateMetadataPartitionState(topicName='__consumer_offsets', partitionIndex=46, controllerEpoch=812, leader=2, leaderEpoch=2030, isr=[0, 2, 1], zkVersion=3341, replicas=[1, 2, 0], offlineReplicas=[]) for partition __consumer_offsets-46 in response to UpdateMetadata request sent by controller 2 epoch 812 with correlation id 12 (state.change.logger) [control-plane-kafka-request-handler-0] 2024-10-08 06:36:36,316 INFO [Broker id=2] Add 1 partitions and deleted 0 partitions from metadata cache in response to UpdateMetadata request sent by controller 2 epoch 812 with correlation id 12 (state.change.logger) [control-plane-kafka-request-handler-0] 2024-10-08 06:36:36,317 TRACE [Controller id=2 epoch=812] Received response UpdateMetadataResponseData(errorCode=0) for request UPDATE_METADATA with correlation id 12 sent to broker apps-kafka-2.apps-kafka-brokers.kafka.svc:9090 (id: 2 rack: null) (state.change.logger) [Controller-2-to-broker-2-send-thread] 2024-10-08 06:36:36,316 INFO [Partition __consumer_offsets-46 broker=2] ISR updated to 0,2,1 and version updated to 3341 (kafka.cluster.Partition) [zk-broker-2-to-controller-alter-partition-channel-manager] 2024-10-08 06:36:36,323 TRACE [Controller id=2 epoch=812] Received response UpdateMetadataResponseData(errorCode=0) for request UPDATE_METADATA with correlation id 12 sent to broker apps-kafka-0.apps-kafka-brokers.kafka.svc:9090 (id: 0 rack: null) (state.change.logger) [Controller-2-to-broker-0-send-thread] 2024-10-08 06:36:36,380 TRACE [Controller id=2 epoch=812] Received response UpdateMetadataResponseData(errorCode=0) for request UPDATE_METADATA with correlation id 9 sent to broker apps-kafka-1.apps-kafka-brokers.kafka.svc:9090 (id: 1 rack: null) (state.change.logger) [Controller-2-to-broker-1-send-thread] 2024-10-08 06:36:36,407 DEBUG [Controller id=2] Updating ISRs for partitions: Set(__consumer_offsets-28). (kafka.controller.KafkaController) [controller-event-thread] 2024-10-08 06:36:36,414 DEBUG [Controller id=2] ISR for partition __consumer_offsets-28 updated to LeaderAndIsr(leader=2, leaderEpoch=2030, isrWithBrokerEpoch=List(BrokerState(brokerId=0, brokerEpoch=-1), BrokerState(brokerId=2, brokerEpoch=-1), BrokerState(brokerId=1, brokerEpoch=-1)), leaderRecoveryState=RECOVERED, partitionEpoch=3341). (kafka.controller.KafkaController) [controller-event-thread] 2024-10-08 06:36:36,417 INFO [Controller id=2 epoch=812] Sending UpdateMetadata request to brokers HashSet(0, 1, 2) for 1 partitions (state.change.logger) [controller-event-thread] 2024-10-08 06:36:36,420 TRACE [Broker id=2] Cached leader info UpdateMetadataPartitionState(topicName='__consumer_offsets', partitionIndex=28, controllerEpoch=812, leader=2, leaderEpoch=2030, isr=[0, 2, 1], zkVersion=3341, replicas=[1, 2, 0], offlineReplicas=[]) for partition __consumer_offsets-28 in response to UpdateMetadata request sent by controller 2 epoch 812 with correlation id 13 (state.change.logger) [control-plane-kafka-request-handler-0]

Strimzi-operator logs
2024-10-08 06:47:01 WARN AbstractOperator:556 - Reconciliation #1909(timer) Kafka(kafka/apps): Failed to reconcile io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod apps-kafka-2 cannot be updated right now. at io.strimzi.operator.cluster.operator.resource.KafkaRoller.restartIfNecessary(KafkaRoller.java:477) ~[io.strimzi.cluster-operator-0.42.0.jar:0.42.0] at io.strimzi.operator.cluster.operator.resource.KafkaRoller.lambda$schedule$7(KafkaRoller.java:376) ~[io.strimzi.cluster-operator-0.42.0.jar:0.42.0] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?] at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?] at java.lang.Thread.run(Thread.java:840) ~[?:?]

[scholzj]

You would have to share the full logs from the operator and Kafka nodes and the configurations for anyone to be able to understand what exactly the problem is.

[navnitkum]

kafka CRD yaml

`apiVersion: kafka.strimzi.io/v1beta2
kind: Kafka
metadata:
name: apps
spec:
kafka:
version: 3.7.1
replicas: 3
listeners:
- name: plain
port: 9092
type: internal
tls: false
- name: tls
port: 9093
type: internal
tls: true
template:
pod:
tolerations:
- effect: NoSchedule
key: on-demand
operator: Exists
affinity:
nodeAffinity:
requiredDuringSchedulingIgnoredDuringExecution:
nodeSelectorTerms:
- matchExpressions:
- key: app
operator: In
values:
- common
resources:
requests:
memory: "3Gi"
cpu: "1"
limits:
memory: "3Gi"
cpu: "1"
jvmOptions:
-Xms: "1024m"
-Xmx: "2048m"
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.7"
storage:
type: jbod
volumes:
- id: 0
type: persistent-claim
size: 100Gi
deleteClaim: false
class: "standard-rwo"
metricsConfig:
type: jmxPrometheusExporter
valueFrom:
configMapKeyRef:
name: kafka-metrics
key: kafka-metrics-config.yml
template:
pod:
metadata:
annotations:
prometheus.io/scrape: "true"
prometheus.io/port: "9404" # Replace with the correct port if different
prometheus.io/path: "/metrics"
zookeeper:
replicas: 3
storage:
type: persistent-claim
size: 100Gi
deleteClaim: false
class: "standard-rwo"
resources:
requests:
memory: "1Gi"
cpu: "0.5"
limits:
memory: "1Gi"
cpu: "1"
jvmOptions:
javaSystemProperties:
- name: zookeeper.ssl.hostnameVerification
value: "false"
- name: zookeeper.ssl.quorum.hostnameVerification
value: "false"
-Xms: "1024m"
-Xmx: "2048m"
metricsConfig:
type: jmxPrometheusExporter
valueFrom:
configMapKeyRef:
name: kafka-metrics
key: zookeeper-metrics-config.yml
template:
pod:
metadata:
annotations:
prometheus.io/scrape: "true"
prometheus.io/port: "9404" # Replace with the correct port if different
prometheus.io/path: "/metrics"
entityOperator:
topicOperator:
resources:
requests:
memory: "256Mi"
cpu: "0.2"
limits:
memory: "256Mi"
cpu: "0.5"
userOperator:
requests:
memory: "256Mi"
cpu: "0.3"
limits:
memory: "256Mi"
cpu: "0.6"

Source: kafka-resources/templates/kafka-resources.yaml

apiVersion: kafka.strimzi.io/v1beta2
kind: KafkaConnect
metadata:
name: apps-connect
annotations:
strimzi.io/use-connector-resources: "true"
spec:
version: 3.7.1
replicas: 1
bootstrapServers: apps-kafka-bootstrap:9092
config:
config.providers: secrets
config.providers.secrets.class: io.strimzi.kafka.KubernetesSecretConfigProvider
group.id: apps-group
config.storage.replication.factor: 1
offset.storage.replication.factor: 1
status.storage.replication.factor: 1
build:
output:
type: docker
image: mehulflip/debezium-pg-connector:latest
pushSecret: dhcred
plugins:
- name: debezium-pg-connector
artifacts:
- type: tgz
url: https://repo1.maven.org/maven2/io/debezium/debezium-connector-postgres/2.7.0.Final/debezium-connector-postgres-2.7.0.Final-plugin.tar.gz
- name: debezium-mongo-connector
artifacts:
- type: tgz
url: https://repo1.maven.org/maven2/io/debezium/debezium-connector-mongodb/2.7.0.Final/debezium-connector-mongodb-2.7.0.Final-plugin.tar.gz
template:
buildServiceAccount:
metadata:
annotations:
iam.gke.io/gcp-service-account: lip-prod-kafka-build@lip-prod-common-d4d7.iam.gserviceaccount.com
pod:
imagePullSecrets:
- name: dhcred
tolerations:
- effect: NoSchedule
key: on-demand
operator: Exists
affinity:
nodeAffinity:
requiredDuringSchedulingIgnoredDuringExecution:
nodeSelectorTerms:
- matchExpressions:
- key: app
operator: In
values:
- common`

Strimzi-operator logs

strimzi-cluster-operator.txt

kafka logs
kafka (1).txt
rator.txt)

[scholzj]

The config is unreadable and the log on the DEBUG level is pretty huge. So when exactly did it happen? What should I look for?

[navnitkum]

Could not verify pod apps-kafka-2/2 is up-to-date, giving up after 10 attempts. Total delay between attempts 127750ms
io.strimzi.operator.cluster.operator.resource.KafkaRoller$UnforceableProblem: Pod apps-kafka-2 cannot be updated right now.
at io.strimzi.operator.cluster.operator.resource.KafkaRoller.restartIfNecessary(KafkaRoller.java:477) ~[io.strimzi.cluster-operator-0.42.0.jar:0.42.0]

this is the exact logs of operator after certain number of times

[scholzj]

Well, if you check the logs, the reason for this seems to be quite clear:

2024-10-08 10:33:34 INFO  KafkaAvailability:135 - Reconciliation #49(timer) Kafka(kafka/apps): __consumer_offsets/0 will be under-replicated (ISR={2}, replicas=[2,1,0], min.insync.replicas=1) if broker 2 is restarted.

You have topics / partitions with only one in-sync replica. This does not seem like a properly ocnfigured cluster.