Kafka restarts repeatedly #5723

lanzhiwang · 2021-10-15T10:32:48Z

lanzhiwang
Oct 15, 2021

Kafka restart times

$ kubectl -n jinhu get pods -o wide
I1015 18:29:17.524224 1313666 request.go:668] Waited for 1.177879891s due to client-side throttling, not priority and fairness, request: GET:https://192.168.31.160:6443/apis/clusterregistry.k8s.io/v1alpha1?timeout=32s
NAME                                        READY   STATUS    RESTARTS   AGE   IP           NODE             NOMINATED NODE   READINESS GATES
kafka250-entity-operator-65b646c959-6ldcb   3/3     Running   0          49m   10.3.2.163   192.168.31.162   <none>           <none>
kafka250-kafka-0                            2/2     Running   6          50m   10.3.2.157   192.168.31.162   <none>           <none>
kafka250-kafka-1                            2/2     Running   6          50m   10.3.2.158   192.168.31.161   <none>           <none>
kafka250-kafka-2                            2/2     Running   6          50m   10.3.2.159   192.168.31.163   <none>           <none>
kafka250-kafka-exporter-7b5c6cbcd-4pcz5     1/1     Running   0          49m   10.3.2.164   192.168.31.162   <none>           <none>
kafka250-zookeeper-0                        1/1     Running   0          51m   10.3.2.151   192.168.31.162   <none>           <none>
kafka250-zookeeper-1                        1/1     Running   0          51m   10.3.2.152   192.168.31.161   <none>           <none>
kafka250-zookeeper-2                        1/1     Running   3          51m   10.3.2.153   192.168.31.163   <none>           <none>

kafka log

2021-10-15 10:14:38,820 INFO Creating /brokers/ids/0 (is it secure? false) (kafka.zk.KafkaZkClient) [main]
2021-10-15 10:14:38,871 ERROR Error while creating ephemeral at /brokers/ids/0, node already exists and owner '72068984231165968' does not match current session '216184171116625930' (kafka.zk.KafkaZkClient$CheckedEphemeral) [main]
2021-10-15 10:14:38,881 ERROR [KafkaServer id=0] Fatal error during KafkaServer startup. Prepare to shutdown (kafka.server.KafkaServer) [main]
org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists
	at org.apache.zookeeper.KeeperException.create(KeeperException.java:126)
	at kafka.zk.KafkaZkClient$CheckedEphemeral.getAfterNodeExists(KafkaZkClient.scala:1819)
	at kafka.zk.KafkaZkClient$CheckedEphemeral.create(KafkaZkClient.scala:1757)
	at kafka.zk.KafkaZkClient.checkedEphemeralCreate(KafkaZkClient.scala:1724)
	at kafka.zk.KafkaZkClient.registerBroker(KafkaZkClient.scala:95)
	at kafka.server.KafkaServer.startup(KafkaServer.scala:273)
	at kafka.server.KafkaServerStartable.startup(KafkaServerStartable.scala:44)
	at kafka.Kafka$.main(Kafka.scala:82)
	at kafka.Kafka.main(Kafka.scala)
2021-10-15 10:14:38,884 INFO [KafkaServer id=0] shutting down (kafka.server.KafkaServer) [main]
2021-10-15 10:14:38,886 INFO [SocketServer brokerId=0] Stopping socket server request processors (kafka.network.SocketServer) [main]

What is the reason for this and how to troubleshoot ？

scholzj · 2021-10-15T10:34:45Z

scholzj
Oct 15, 2021
Maintainer

That is weird. That looks like it suggests another broker with the same ID is already running. Maybe some ZooKeeper glitch?

@tombentley You ever saw this?

4 replies

robertc11 May 28, 2024

@scholzj @tombentley Any update on this discussion? I am also receiving similar error, see logs below.

2024-05-28 01:16:52,007 ERROR Error while creating ephemeral at /brokers/ids/2, node already exists and owner '0x200107257ac0ea2' does not match current session '0x1001059a1ec0e88' (kafka.zk.KafkaZkClient$CheckedEphemeral) [main]
2024-05-28 01:16:52,012 ERROR [KafkaServer id=2] Fatal error during KafkaServer startup. Prepare to shutdown (kafka.server.KafkaServer) [main]
org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists
	at org.apache.zookeeper.KeeperException.create(KeeperException.java:126)
	at kafka.zk.KafkaZkClient$CheckedEphemeral.getAfterNodeExists(KafkaZkClient.scala:2189)
	at kafka.zk.KafkaZkClient$CheckedEphemeral.create(KafkaZkClient.scala:2127)
	at kafka.zk.KafkaZkClient.checkedEphemeralCreate(KafkaZkClient.scala:2094)
	at kafka.zk.KafkaZkClient.registerBroker(KafkaZkClient.scala:106)
	at kafka.server.KafkaServer.startup(KafkaServer.scala:404)
	at kafka.Kafka$.main(Kafka.scala:112)
	at kafka.Kafka.main(Kafka.scala)
2024-05-28 01:16:52,016 INFO [KafkaServer id=2] shutting down (kafka.server.KafkaServer) [main]
2024-05-28 01:16:52,018 INFO [SocketServer listenerType=ZK_BROKER, nodeId=2] Stopping socket server request processors (kafka.network.SocketServer) [main]
2024-05-28 01:16:52,025 INFO [SocketServer listenerType=ZK_BROKER, nodeId=2] Stopped socket server request processors (kafka.network.SocketServer) [main]
2024-05-28 01:16:52,031 INFO [ReplicaManager broker=2] Shutting down (kafka.server.ReplicaManager) [main]
2024-05-28 01:16:52,032 INFO [LogDirFailureHandler]: Shutting down (kafka.server.ReplicaManager$LogDirFailureHandler) [main]
2024-05-28 01:16:52,032 INFO [LogDirFailureHandler]: Stopped (kafka.server.ReplicaManager$LogDirFailureHandler) [LogDirFailureHandler]
2024-05-28 01:16:52,033 INFO [LogDirFailureHandler]: Shutdown completed (kafka.server.ReplicaManager$LogDirFailureHandler) [main]
2024-05-28 01:16:52,033 INFO [ReplicaFetcherManager on broker 2] shutting down (kafka.server.ReplicaFetcherManager) [main]
2024-05-28 01:16:52,034 INFO [ReplicaFetcherManager on broker 2] shutdown completed (kafka.server.ReplicaFetcherManager) [main]
2024-05-28 01:16:52,035 INFO [ReplicaAlterLogDirsManager on broker 2] shutting down (kafka.server.ReplicaAlterLogDirsManager) [main]
2024-05-28 01:16:52,035 INFO [ReplicaAlterLogDirsManager on broker 2] shutdown completed (kafka.server.ReplicaAlterLogDirsManager) [main]
2024-05-28 01:16:52,035 INFO [ExpirationReaper-2-Fetch]: Shutting down (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,036 INFO [ExpirationReaper-2-Fetch]: Shutdown completed (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,036 INFO [ExpirationReaper-2-Fetch]: Stopped (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [ExpirationReaper-2-Fetch]
2024-05-28 01:16:52,036 INFO [ExpirationReaper-2-RemoteFetch]: Shutting down (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,046 INFO [ExpirationReaper-2-RemoteFetch]: Stopped (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [ExpirationReaper-2-RemoteFetch]
2024-05-28 01:16:52,047 INFO [ExpirationReaper-2-RemoteFetch]: Shutdown completed (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,047 INFO [ExpirationReaper-2-Produce]: Shutting down (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,047 INFO [ExpirationReaper-2-Produce]: Stopped (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [ExpirationReaper-2-Produce]
2024-05-28 01:16:52,047 INFO [ExpirationReaper-2-Produce]: Shutdown completed (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,048 INFO [ExpirationReaper-2-DeleteRecords]: Shutting down (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,048 INFO [ExpirationReaper-2-DeleteRecords]: Stopped (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [ExpirationReaper-2-DeleteRecords]
2024-05-28 01:16:52,048 INFO [ExpirationReaper-2-DeleteRecords]: Shutdown completed (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,049 INFO [ExpirationReaper-2-ElectLeader]: Shutting down (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,049 INFO [ExpirationReaper-2-ElectLeader]: Stopped (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [ExpirationReaper-2-ElectLeader]
2024-05-28 01:16:52,049 INFO [ExpirationReaper-2-ElectLeader]: Shutdown completed (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,056 INFO [AddPartitionsToTxnSenderThread-2]: Shutting down (kafka.server.AddPartitionsToTxnManager) [main]
2024-05-28 01:16:52,057 INFO [AddPartitionsToTxnSenderThread-2]: Stopped (kafka.server.AddPartitionsToTxnManager) [AddPartitionsToTxnSenderThread-2]
2024-05-28 01:16:52,057 INFO [AddPartitionsToTxnSenderThread-2]: Shutdown completed (kafka.server.AddPartitionsToTxnManager) [main]
2024-05-28 01:16:52,058 INFO [ReplicaManager broker=2] Shut down completely (kafka.server.ReplicaManager) [main]
2024-05-28 01:16:52,059 INFO [zk-broker-2-to-controller-alter-partition-channel-manager]: Shutting down (kafka.server.NodeToControllerRequestThread) [main]
2024-05-28 01:16:52,059 INFO [zk-broker-2-to-controller-alter-partition-channel-manager]: Stopped (kafka.server.NodeToControllerRequestThread) [zk-broker-2-to-controller-alter-partition-channel-manager]
2024-05-28 01:16:52,059 INFO [zk-broker-2-to-controller-alter-partition-channel-manager]: Shutdown completed (kafka.server.NodeToControllerRequestThread) [main]
2024-05-28 01:16:52,060 INFO Node to controller channel manager for alter-partition shutdown (kafka.server.NodeToControllerChannelManagerImpl) [main]
2024-05-28 01:16:52,060 INFO [zk-broker-2-to-controller-forwarding-channel-manager]: Shutting down (kafka.server.NodeToControllerRequestThread) [main]
2024-05-28 01:16:52,061 INFO [zk-broker-2-to-controller-forwarding-channel-manager]: Stopped (kafka.server.NodeToControllerRequestThread) [zk-broker-2-to-controller-forwarding-channel-manager]
2024-05-28 01:16:52,061 INFO [zk-broker-2-to-controller-forwarding-channel-manager]: Shutdown completed (kafka.server.NodeToControllerRequestThread) [main]
2024-05-28 01:16:52,061 INFO Node to controller channel manager for forwarding shutdown (kafka.server.NodeToControllerChannelManagerImpl) [main]
2024-05-28 01:16:52,062 INFO Shutting down. (kafka.log.LogManager) [main]
2024-05-28 01:16:52,063 INFO Shutting down the log cleaner. (kafka.log.LogCleaner) [main]
2024-05-28 01:16:52,063 INFO [kafka-log-cleaner-thread-0]: Shutting down (kafka.log.LogCleaner$CleanerThread) [main]
2024-05-28 01:16:52,064 INFO [kafka-log-cleaner-thread-0]: Stopped (kafka.log.LogCleaner$CleanerThread) [kafka-log-cleaner-thread-0]
2024-05-28 01:16:52,064 INFO [kafka-log-cleaner-thread-0]: Shutdown completed (kafka.log.LogCleaner$CleanerThread) [main]
2024-05-28 01:16:52,304 INFO Shutdown complete. (kafka.log.LogManager) [main]
2024-05-28 01:16:52,309 INFO [feature-zk-node-event-process-thread]: Shutting down (kafka.server.FinalizedFeatureChangeListener$ChangeNotificationProcessorThread) [main]
2024-05-28 01:16:52,309 INFO [feature-zk-node-event-process-thread]: Stopped (kafka.server.FinalizedFeatureChangeListener$ChangeNotificationProcessorThread) [feature-zk-node-event-process-thread]
2024-05-28 01:16:52,309 INFO [feature-zk-node-event-process-thread]: Shutdown completed (kafka.server.FinalizedFeatureChangeListener$ChangeNotificationProcessorThread) [main]
2024-05-28 01:16:52,311 INFO [ZooKeeperClient Kafka server] Closing. (kafka.zookeeper.ZooKeeperClient) [main]
2024-05-28 01:16:52,317 INFO channel is told closing (org.apache.zookeeper.ClientCnxnSocketNetty) [main]
2024-05-28 01:16:52,323 INFO channel is disconnected: [id: 0x3c20e983, L:/192.168.85.220:37276 ! R:kafka-cluster-zookeeper-client/10.100.91.91:2181] (org.apache.zookeeper.ClientCnxnSocketNetty) [nioEventLoopGroup-2-1]
2024-05-28 01:16:52,323 INFO channel is told closing (org.apache.zookeeper.ClientCnxnSocketNetty) [nioEventLoopGroup-2-1]
2024-05-28 01:16:52,323 INFO Session: 0x1001059a1ec0e88 closed (org.apache.zookeeper.ZooKeeper) [main]
2024-05-28 01:16:52,323 INFO EventThread shut down for session: 0x1001059a1ec0e88 (org.apache.zookeeper.ClientCnxn) [main-EventThread]
2024-05-28 01:16:52,324 INFO [ZooKeeperClient Kafka server] Closed. (kafka.zookeeper.ZooKeeperClient) [main]
2024-05-28 01:16:52,325 INFO [ThrottledChannelReaper-Fetch]: Shutting down (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [main]
2024-05-28 01:16:52,326 INFO [ThrottledChannelReaper-Fetch]: Stopped (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [ThrottledChannelReaper-Fetch]
2024-05-28 01:16:52,326 INFO [ThrottledChannelReaper-Fetch]: Shutdown completed (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [main]
2024-05-28 01:16:52,326 INFO [ThrottledChannelReaper-Produce]: Shutting down (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [main]
2024-05-28 01:16:52,327 INFO [ThrottledChannelReaper-Produce]: Shutdown completed (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [main]
2024-05-28 01:16:52,327 INFO [ThrottledChannelReaper-Request]: Shutting down (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [main]
2024-05-28 01:16:52,327 INFO [ThrottledChannelReaper-Request]: Stopped (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [ThrottledChannelReaper-Request]
2024-05-28 01:16:52,327 INFO [ThrottledChannelReaper-Produce]: Stopped (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [ThrottledChannelReaper-Produce]
2024-05-28 01:16:52,327 INFO [ThrottledChannelReaper-Request]: Shutdown completed (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [main]
2024-05-28 01:16:52,334 INFO [ThrottledChannelReaper-ControllerMutation]: Shutting down (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [main]
2024-05-28 01:16:52,335 INFO [ThrottledChannelReaper-ControllerMutation]: Stopped (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [ThrottledChannelReaper-ControllerMutation]
2024-05-28 01:16:52,335 INFO [ThrottledChannelReaper-ControllerMutation]: Shutdown completed (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [main]
2024-05-28 01:16:52,337 INFO [SocketServer listenerType=ZK_BROKER, nodeId=2] Shutting down socket server (kafka.network.SocketServer) [main]
2024-05-28 01:16:52,395 INFO [SocketServer listenerType=ZK_BROKER, nodeId=2] Shutdown completed (kafka.network.SocketServer) [main]
2024-05-28 01:16:52,397 INFO Metrics scheduler closed (org.apache.kafka.common.metrics.Metrics) [main]
2024-05-28 01:16:52,397 INFO Metrics reporters closed (org.apache.kafka.common.metrics.Metrics) [main]
2024-05-28 01:16:52,400 INFO Broker and topic stats closed (kafka.server.BrokerTopicStats) [main]
2024-05-28 01:16:52,402 INFO App info kafka.server for 2 unregistered (org.apache.kafka.common.utils.AppInfoParser) [main]
2024-05-28 01:16:52,403 INFO [KafkaServer id=2] shut down completed (kafka.server.KafkaServer) [main]
2024-05-28 01:16:52,403 ERROR Exiting Kafka due to fatal exception during startup. (kafka.Kafka$) [main]
org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists
	at org.apache.zookeeper.KeeperException.create(KeeperException.java:126)
	at kafka.zk.KafkaZkClient$CheckedEphemeral.getAfterNodeExists(KafkaZkClient.scala:2189)
	at kafka.zk.KafkaZkClient$CheckedEphemeral.create(KafkaZkClient.scala:2127)
	at kafka.zk.KafkaZkClient.checkedEphemeralCreate(KafkaZkClient.scala:2094)
	at kafka.zk.KafkaZkClient.registerBroker(KafkaZkClient.scala:106)
	at kafka.server.KafkaServer.startup(KafkaServer.scala:404)
	at kafka.Kafka$.main(Kafka.scala:112)
	at kafka.Kafka.main(Kafka.scala)
2024-05-28 01:16:52,414 INFO [KafkaServer id=2] shutting down (kafka.server.KafkaServer) [kafka-shutdown-hook]
2024-05-28 01:16:52,424 INFO Stopped ServerConnector@2bbf4b8b{SSL, (ssl, http/1.1)}{0.0.0.0:8443} (org.eclipse.jetty.server.AbstractConnector) [JettyShutdownThread]
2024-05-28 01:16:52,425 INFO Stopped ServerConnector@612679d6{HTTP/1.1, (http/1.1)}{0.0.0.0:8080} (org.eclipse.jetty.server.AbstractConnector) [JettyShutdownThread]
2024-05-28 01:16:52,426 INFO Stopped o.e.j.s.h.ContextHandler@74a10858{/v1/kraft-migration,null,STOPPED} (org.eclipse.jetty.server.handler.ContextHandler) [JettyShutdownThread]
2024-05-28 01:16:52,428 INFO Stopped o.e.j.s.h.ContextHandler@cb0ed20{/v1/ready,null,STOPPED} (org.eclipse.jetty.server.handler.ContextHandler) [JettyShutdownThread]
2024-05-28 01:16:52,428 INFO Stopped o.e.j.s.h.ContextHandler@8e24743{/v1/broker-state,null,STOPPED} (org.eclipse.jetty.server.handler.ContextHandler) [JettyShutdownThread]

robertc11 May 28, 2024

Adding more context.

I have included the --previous logs for strimzi operator and broker 2 below.

I understand the heap err from the operator and can adjust heap in yaml. The broker 2 err is the one described in this discussion, the logs can be found in comment above.

When this broker 2 err happened my listener service threw the below in-sync replica err. I believe I can reduce the required in-sync replicas for the topic to prevent this err or implement retry logic.

NAME                                                READY   STATUS    RESTARTS      AGE
pod/kafka-cluster-entity-operator-7d57f58f6-hn7s4   2/2     Running   0             15h
pod/kafka-cluster-kafka-0                           0/1     Running   0             5m26s
pod/kafka-cluster-kafka-1                           1/1     Running   0             13h
pod/kafka-cluster-kafka-2                           1/1     Running   1 (12h ago)   12h
pod/kafka-cluster-zookeeper-0                       1/1     Running   0             3d23h
pod/kafka-cluster-zookeeper-1                       1/1     Running   0             3d23h
pod/kafka-cluster-zookeeper-2                       1/1     Running   0             12h
pod/strimzi-cluster-operator-77fddb4d5c-xpvfz       1/1     Running   1 (28h ago)   4d16h

NAME                                     TYPE        CLUSTER-IP     EXTERNAL-IP   PORT(S)                                        AGE
service/kafka-cluster-kafka-bootstrap    ClusterIP   <anonymized>   <none>        9091/TCP,9092/TCP,9093/TCP                     5d15h
service/kafka-cluster-kafka-brokers      ClusterIP   None           <none>        9090/TCP,9091/TCP,8443/TCP,9092/TCP,9093/TCP   5d15h
service/kafka-cluster-zookeeper-client   ClusterIP   <anonymized>   <none>        2181/TCP                                       5d15h
service/kafka-cluster-zookeeper-nodes    ClusterIP   None           <none>        2181/TCP,2888/TCP,3888/TCP                     5d15h
service/kubernetes                       ClusterIP   <anonymized>   443/TCP                                        514d

NAME                                            READY   UP-TO-DATE   AVAILABLE   AGE
deployment.apps/kafka-cluster-entity-operator   1/1     1            1           5d15h
deployment.apps/strimzi-cluster-operator        1/1     1            1           5d16h

NAME                                                      DESIRED   CURRENT   READY   AGE
replicaset.apps/kafka-cluster-entity-operator-7d57f58f6   1         1         1       3d23h
replicaset.apps/kafka-cluster-entity-operator-96fdcf777   0         0         0       5d15h
replicaset.apps/strimzi-cluster-operator-77fddb4d5c       1         1         1       4d16h

apiVersion: kafka.strimzi.io/v1beta2
kind: Kafka
metadata:
  name: kafka-cluster
spec:
  kafka:
    version: 3.7.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.7"
      log.message.format.version: "3.7"
      log.segment.bytes: 536870912 # 512MB
      log.retention.bytes: 2147483648 # 2GB
      log.cleanup.policy: "delete" # Deletes old logs
    storage:
      type: jbod
      volumes:
        - id: 0
          type: persistent-claim
          size: 20Gi
          deleteClaim: false
    jvmOptions:
      -Xms: "1G" # Correctly formatted within an object
      -Xmx: "3G"
  zookeeper:
    replicas: 3
    storage:
      type: persistent-claim
      size: 10Gi # Corrected size format
      deleteClaim: false
    jvmOptions:
      -Xms: "1G" # Correctly formatted within an object
      -Xmx: "3G"
  entityOperator:
    topicOperator: {}
    userOperator: {}

KafkaJSNonRetriableError
  Caused by: KafkaJSProtocolError: Messages are rejected since there are fewer in-sync replicas than required
    at createErrorFromCode (/development/docker/nestbe/node_modules/kafkajs/src/protocol/error.js:581:10)
    ... 8 lines matching cause stack trace ...
    at async sendBatch (/development/docker/nestbe/node_modules/kafkajs/src/producer/messageProducer.js:95:12) {
  name: 'KafkaJSNumberOfRetriesExceeded',
  retriable: false,
  helpUrl: undefined,
  retryCount: 5,
  retryTime: 6772,
  [cause]: KafkaJSProtocolError: Messages are rejected since there are fewer in-sync replicas than required
      at createErrorFromCode (/development/docker/nestbe/node_modules/kafkajs/src/protocol/error.js:581:10)
      at Object.parse (/development/docker/nestbe/node_modules/kafkajs/src/protocol/requests/produce/v3/response.js:45:11)
      at Connection.send (/development/docker/nestbe/node_modules/kafkajs/src/network/connection.js:433:35)
      at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
      at async [private:Broker:sendRequest] (/development/docker/nestbe/node_modules/kafkajs/src/broker/index.js:904:14)
      at async Broker.produce (/development/docker/nestbe/node_modules/kafkajs/src/broker/index.js:241:12)
      at async /development/docker/nestbe/node_modules/kafkajs/src/producer/sendMessages.js:94:24
      at async Promise.all (index 0)
      at async /development/docker/nestbe/node_modules/kafkajs/src/producer/sendMessages.js:133:9
      at async sendBatch (/development/docker/nestbe/node_modules/kafkajs/src/producer/messageProducer.js:95:12) {
    retriable: true,
    helpUrl: undefined,
    type: 'NOT_ENOUGH_REPLICAS',
    code: 19,
    [cause]: undefined
  }
}

2024-05-27 09:11:20 DEBUG StrimziPodSetController:479 - Reconciliation #36103(watch) StrimziPodSet(default/kafka-cluster-kafka): Pod kafka-cluster-kafka-0 in namespace default already exists => nothing to do right now
2024-05-27 09:11:20 TRACE KafkaBrokerConfigurationDiff:201 - Reconciliation #36100(watch) Kafka(default/kafka-cluster): Kafka Broker 2 Config Differs : {"op":"remove","path":"/alter.log.dirs.replication.quota.window.size.seconds"}
2024-05-27 09:11:19 WARN  BlockedThreadChecker: - Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 2797 ms, time limit is 2000 ms
2024-05-27 09:11:21 DEBUG StrimziPodSetController:479 - Reconciliation #36103(watch) StrimziPodSet(default/kafka-cluster-kafka): Pod kafka-cluster-kafka-1 in namespace default already exists => nothing to do right now
2024-05-27 09:11:22 DEBUG StrimziPodSetController:479 - Reconciliation #36103(watch) StrimziPodSet(default/kafka-cluster-kafka): Pod kafka-cluster-kafka-2 in namespace default already exists => nothing to do right now
2024-05-27 09:11:22 TRACE KafkaBrokerConfigurationDiff:202 - Reconciliation #36100(watch) Kafka(default/kafka-cluster): Current Kafka Broker Config path alter.log.dirs.replication.quota.window.size.seconds has value "1"
2024-05-27 09:11:23 DEBUG CustomResource:184 - Calling CustomResource#setApiVersion doesn't do anything because the API version is computed and shouldn't be changed
2024-05-27 09:11:24 DEBUG CustomResource:195 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2024-05-27 09:11:24 INFO  StrimziPodSetController:414 - Reconciliation #36103(watch) StrimziPodSet(default/kafka-cluster-kafka): reconciled
2024-05-27 09:11:25 TRACE KafkaBrokerConfigurationDiff:203 - Reconciliation #36100(watch) Kafka(default/kafka-cluster): Desired Kafka Broker Config path alter.log.dirs.replication.quota.window.size.seconds has value 
2024-05-27 09:11:25 DEBUG StrimziPodSetController:564 - Waiting for next event from work queue
2024-05-27 09:11:26 TRACE KafkaBrokerConfigurationDiff:236 - Reconciliation #36100(watch) Kafka(default/kafka-cluster): authorizer.class.name not set in desired, using default value
2024-05-27 09:11:27 INFO  StrimziPodSetController:378 - Reconciliation #36104(watch) StrimziPodSet(default/kafka-cluster-zookeeper): StrimziPodSet will be reconciled
2024-05-27 09:11:28 TRACE KafkaBrokerConfigurationDiff:201 - Reconciliation #36100(watch) Kafka(default/kafka-cluster): Kafka Broker 2 Config Differs : {"op":"remove","path":"/authorizer.class.name"}
Terminating due to java.lang.OutOfMemoryError: Java heap space

2024-05-28 01:16:52,007 ERROR Error while creating ephemeral at /brokers/ids/2, node already exists and owner '0x200107257ac0ea2' does not match current session '0x1001059a1ec0e88' (kafka.zk.KafkaZkClient$CheckedEphemeral) [main]
2024-05-28 01:16:52,012 ERROR [KafkaServer id=2] Fatal error during KafkaServer startup. Prepare to shutdown (kafka.server.KafkaServer) [main]
org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists
	at org.apache.zookeeper.KeeperException.create(KeeperException.java:126)
	at kafka.zk.KafkaZkClient$CheckedEphemeral.getAfterNodeExists(KafkaZkClient.scala:2189)
	at kafka.zk.KafkaZkClient$CheckedEphemeral.create(KafkaZkClient.scala:2127)
	at kafka.zk.KafkaZkClient.checkedEphemeralCreate(KafkaZkClient.scala:2094)
	at kafka.zk.KafkaZkClient.registerBroker(KafkaZkClient.scala:106)
	at kafka.server.KafkaServer.startup(KafkaServer.scala:404)
	at kafka.Kafka$.main(Kafka.scala:112)
	at kafka.Kafka.main(Kafka.scala)
2024-05-28 01:16:52,016 INFO [KafkaServer id=2] shutting down (kafka.server.KafkaServer) [main]
2024-05-28 01:16:52,018 INFO [SocketServer listenerType=ZK_BROKER, nodeId=2] Stopping socket server request processors (kafka.network.SocketServer) [main]
2024-05-28 01:16:52,025 INFO [SocketServer listenerType=ZK_BROKER, nodeId=2] Stopped socket server request processors (kafka.network.SocketServer) [main]
2024-05-28 01:16:52,031 INFO [ReplicaManager broker=2] Shutting down (kafka.server.ReplicaManager) [main]
2024-05-28 01:16:52,032 INFO [LogDirFailureHandler]: Shutting down (kafka.server.ReplicaManager$LogDirFailureHandler) [main]
2024-05-28 01:16:52,032 INFO [LogDirFailureHandler]: Stopped (kafka.server.ReplicaManager$LogDirFailureHandler) [LogDirFailureHandler]
2024-05-28 01:16:52,033 INFO [LogDirFailureHandler]: Shutdown completed (kafka.server.ReplicaManager$LogDirFailureHandler) [main]
2024-05-28 01:16:52,033 INFO [ReplicaFetcherManager on broker 2] shutting down (kafka.server.ReplicaFetcherManager) [main]
2024-05-28 01:16:52,034 INFO [ReplicaFetcherManager on broker 2] shutdown completed (kafka.server.ReplicaFetcherManager) [main]
2024-05-28 01:16:52,035 INFO [ReplicaAlterLogDirsManager on broker 2] shutting down (kafka.server.ReplicaAlterLogDirsManager) [main]
2024-05-28 01:16:52,035 INFO [ReplicaAlterLogDirsManager on broker 2] shutdown completed (kafka.server.ReplicaAlterLogDirsManager) [main]
2024-05-28 01:16:52,035 INFO [ExpirationReaper-2-Fetch]: Shutting down (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,036 INFO [ExpirationReaper-2-Fetch]: Shutdown completed (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,036 INFO [ExpirationReaper-2-Fetch]: Stopped (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [ExpirationReaper-2-Fetch]
2024-05-28 01:16:52,036 INFO [ExpirationReaper-2-RemoteFetch]: Shutting down (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,046 INFO [ExpirationReaper-2-RemoteFetch]: Stopped (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [ExpirationReaper-2-RemoteFetch]
2024-05-28 01:16:52,047 INFO [ExpirationReaper-2-RemoteFetch]: Shutdown completed (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,047 INFO [ExpirationReaper-2-Produce]: Shutting down (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,047 INFO [ExpirationReaper-2-Produce]: Stopped (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [ExpirationReaper-2-Produce]
2024-05-28 01:16:52,047 INFO [ExpirationReaper-2-Produce]: Shutdown completed (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,048 INFO [ExpirationReaper-2-DeleteRecords]: Shutting down (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,048 INFO [ExpirationReaper-2-DeleteRecords]: Stopped (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [ExpirationReaper-2-DeleteRecords]
2024-05-28 01:16:52,048 INFO [ExpirationReaper-2-DeleteRecords]: Shutdown completed (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,049 INFO [ExpirationReaper-2-ElectLeader]: Shutting down (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,049 INFO [ExpirationReaper-2-ElectLeader]: Stopped (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [ExpirationReaper-2-ElectLeader]
2024-05-28 01:16:52,049 INFO [ExpirationReaper-2-ElectLeader]: Shutdown completed (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper) [main]
2024-05-28 01:16:52,056 INFO [AddPartitionsToTxnSenderThread-2]: Shutting down (kafka.server.AddPartitionsToTxnManager) [main]
2024-05-28 01:16:52,057 INFO [AddPartitionsToTxnSenderThread-2]: Stopped (kafka.server.AddPartitionsToTxnManager) [AddPartitionsToTxnSenderThread-2]
2024-05-28 01:16:52,057 INFO [AddPartitionsToTxnSenderThread-2]: Shutdown completed (kafka.server.AddPartitionsToTxnManager) [main]
2024-05-28 01:16:52,058 INFO [ReplicaManager broker=2] Shut down completely (kafka.server.ReplicaManager) [main]
2024-05-28 01:16:52,059 INFO [zk-broker-2-to-controller-alter-partition-channel-manager]: Shutting down (kafka.server.NodeToControllerRequestThread) [main]
2024-05-28 01:16:52,059 INFO [zk-broker-2-to-controller-alter-partition-channel-manager]: Stopped (kafka.server.NodeToControllerRequestThread) [zk-broker-2-to-controller-alter-partition-channel-manager]
2024-05-28 01:16:52,059 INFO [zk-broker-2-to-controller-alter-partition-channel-manager]: Shutdown completed (kafka.server.NodeToControllerRequestThread) [main]
2024-05-28 01:16:52,060 INFO Node to controller channel manager for alter-partition shutdown (kafka.server.NodeToControllerChannelManagerImpl) [main]
2024-05-28 01:16:52,060 INFO [zk-broker-2-to-controller-forwarding-channel-manager]: Shutting down (kafka.server.NodeToControllerRequestThread) [main]
2024-05-28 01:16:52,061 INFO [zk-broker-2-to-controller-forwarding-channel-manager]: Stopped (kafka.server.NodeToControllerRequestThread) [zk-broker-2-to-controller-forwarding-channel-manager]
2024-05-28 01:16:52,061 INFO [zk-broker-2-to-controller-forwarding-channel-manager]: Shutdown completed (kafka.server.NodeToControllerRequestThread) [main]
2024-05-28 01:16:52,061 INFO Node to controller channel manager for forwarding shutdown (kafka.server.NodeToControllerChannelManagerImpl) [main]
2024-05-28 01:16:52,062 INFO Shutting down. (kafka.log.LogManager) [main]
2024-05-28 01:16:52,063 INFO Shutting down the log cleaner. (kafka.log.LogCleaner) [main]
2024-05-28 01:16:52,063 INFO [kafka-log-cleaner-thread-0]: Shutting down (kafka.log.LogCleaner$CleanerThread) [main]
2024-05-28 01:16:52,064 INFO [kafka-log-cleaner-thread-0]: Stopped (kafka.log.LogCleaner$CleanerThread) [kafka-log-cleaner-thread-0]
2024-05-28 01:16:52,064 INFO [kafka-log-cleaner-thread-0]: Shutdown completed (kafka.log.LogCleaner$CleanerThread) [main]
2024-05-28 01:16:52,304 INFO Shutdown complete. (kafka.log.LogManager) [main]
2024-05-28 01:16:52,309 INFO [feature-zk-node-event-process-thread]: Shutting down (kafka.server.FinalizedFeatureChangeListener$ChangeNotificationProcessorThread) [main]
2024-05-28 01:16:52,309 INFO [feature-zk-node-event-process-thread]: Stopped (kafka.server.FinalizedFeatureChangeListener$ChangeNotificationProcessorThread) [feature-zk-node-event-process-thread]
2024-05-28 01:16:52,309 INFO [feature-zk-node-event-process-thread]: Shutdown completed (kafka.server.FinalizedFeatureChangeListener$ChangeNotificationProcessorThread) [main]
2024-05-28 01:16:52,311 INFO [ZooKeeperClient Kafka server] Closing. (kafka.zookeeper.ZooKeeperClient) [main]
2024-05-28 01:16:52,317 INFO channel is told closing (org.apache.zookeeper.ClientCnxnSocketNetty) [main]
2024-05-28 01:16:52,323 INFO channel is disconnected: [id: 0x3c20e983, L:/192.168.85.220:37276 ! R:kafka-cluster-zookeeper-client/10.100.91.91:2181] (org.apache.zookeeper.ClientCnxnSocketNetty) [nioEventLoopGroup-2-1]
2024-05-28 01:16:52,323 INFO channel is told closing (org.apache.zookeeper.ClientCnxnSocketNetty) [nioEventLoopGroup-2-1]
2024-05-28 01:16:52,323 INFO Session: 0x1001059a1ec0e88 closed (org.apache.zookeeper.ZooKeeper) [main]
2024-05-28 01:16:52,323 INFO EventThread shut down for session: 0x1001059a1ec0e88 (org.apache.zookeeper.ClientCnxn) [main-EventThread]
2024-05-28 01:16:52,324 INFO [ZooKeeperClient Kafka server] Closed. (kafka.zookeeper.ZooKeeperClient) [main]
2024-05-28 01:16:52,325 INFO [ThrottledChannelReaper-Fetch]: Shutting down (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [main]
2024-05-28 01:16:52,326 INFO [ThrottledChannelReaper-Fetch]: Stopped (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [ThrottledChannelReaper-Fetch]
2024-05-28 01:16:52,326 INFO [ThrottledChannelReaper-Fetch]: Shutdown completed (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [main]
2024-05-28 01:16:52,326 INFO [ThrottledChannelReaper-Produce]: Shutting down (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [main]
2024-05-28 01:16:52,327 INFO [ThrottledChannelReaper-Produce]: Shutdown completed (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [main]
2024-05-28 01:16:52,327 INFO [ThrottledChannelReaper-Request]: Shutting down (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [main]
2024-05-28 01:16:52,327 INFO [ThrottledChannelReaper-Request]: Stopped (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [ThrottledChannelReaper-Request]
2024-05-28 01:16:52,327 INFO [ThrottledChannelReaper-Produce]: Stopped (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [ThrottledChannelReaper-Produce]
2024-05-28 01:16:52,327 INFO [ThrottledChannelReaper-Request]: Shutdown completed (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [main]
2024-05-28 01:16:52,334 INFO [ThrottledChannelReaper-ControllerMutation]: Shutting down (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [main]
2024-05-28 01:16:52,335 INFO [ThrottledChannelReaper-ControllerMutation]: Stopped (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [ThrottledChannelReaper-ControllerMutation]
2024-05-28 01:16:52,335 INFO [ThrottledChannelReaper-ControllerMutation]: Shutdown completed (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [main]
2024-05-28 01:16:52,337 INFO [SocketServer listenerType=ZK_BROKER, nodeId=2] Shutting down socket server (kafka.network.SocketServer) [main]
2024-05-28 01:16:52,395 INFO [SocketServer listenerType=ZK_BROKER, nodeId=2] Shutdown completed (kafka.network.SocketServer) [main]
2024-05-28 01:16:52,397 INFO Metrics scheduler closed (org.apache.kafka.common.metrics.Metrics) [main]
2024-05-28 01:16:52,397 INFO Metrics reporters closed (org.apache.kafka.common.metrics.Metrics) [main]
2024-05-28 01:16:52,400 INFO Broker and topic stats closed (kafka.server.BrokerTopicStats) [main]
2024-05-28 01:16:52,402 INFO App info kafka.server for 2 unregistered (org.apache.kafka.common.utils.AppInfoParser) [main]
2024-05-28 01:16:52,403 INFO [KafkaServer id=2] shut down completed (kafka.server.KafkaServer) [main]
2024-05-28 01:16:52,403 ERROR Exiting Kafka due to fatal exception during startup. (kafka.Kafka$) [main]
org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists
	at org.apache.zookeeper.KeeperException.create(KeeperException.java:126)
	at kafka.zk.KafkaZkClient$CheckedEphemeral.getAfterNodeExists(KafkaZkClient.scala:2189)
	at kafka.zk.KafkaZkClient$CheckedEphemeral.create(KafkaZkClient.scala:2127)
	at kafka.zk.KafkaZkClient.checkedEphemeralCreate(KafkaZkClient.scala:2094)
	at kafka.zk.KafkaZkClient.registerBroker(KafkaZkClient.scala:106)
	at kafka.server.KafkaServer.startup(KafkaServer.scala:404)
	at kafka.Kafka$.main(Kafka.scala:112)
	at kafka.Kafka.main(Kafka.scala)
2024-05-28 01:16:52,414 INFO [KafkaServer id=2] shutting down (kafka.server.KafkaServer) [kafka-shutdown-hook]
2024-05-28 01:16:52,424 INFO Stopped ServerConnector@2bbf4b8b{SSL, (ssl, http/1.1)}{0.0.0.0:8443} (org.eclipse.jetty.server.AbstractConnector) [JettyShutdownThread]
2024-05-28 01:16:52,425 INFO Stopped ServerConnector@612679d6{HTTP/1.1, (http/1.1)}{0.0.0.0:8080} (org.eclipse.jetty.server.AbstractConnector) [JettyShutdownThread]
2024-05-28 01:16:52,426 INFO Stopped o.e.j.s.h.ContextHandler@74a10858{/v1/kraft-migration,null,STOPPED} (org.eclipse.jetty.server.handler.ContextHandler) [JettyShutdownThread]
2024-05-28 01:16:52,428 INFO Stopped o.e.j.s.h.ContextHandler@cb0ed20{/v1/ready,null,STOPPED} (org.eclipse.jetty.server.handler.ContextHandler) [JettyShutdownThread]
2024-05-28 01:16:52,428 INFO Stopped o.e.j.s.h.ContextHandler@8e24743{/v1/broker-state,null,STOPPED} (org.eclipse.jetty.server.handler.ContextHandler) [JettyShutdownThread]

kholisrag Jun 4, 2024

Hi @robertc11 @lanzhiwang @scholzj any of you can share how to solve this issue?
got same issue

2024-06-04 03:14:12,927 INFO Creating /brokers/ids/1 (is it secure? false) (kafka.zk.KafkaZkClient) [main]
2024-06-04 03:14:12,971 ERROR Error while creating ephemeral at /brokers/ids/1, node already exists and owner '0x200000266ab0001' does not match current session '0x1000005953e0000' (kafka.zk.KafkaZkClient$CheckedEphemeral) [main]
2024-06-04 03:14:12,980 ERROR [KafkaServer id=1] Fatal error during KafkaServer startup. Prepare to shutdown (kafka.server.KafkaServer) [main]
org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists
	at org.apache.zookeeper.KeeperException.create(KeeperException.java:126)
	at kafka.zk.KafkaZkClient$CheckedEphemeral.getAfterNodeExists(KafkaZkClient.scala:2189)
	at kafka.zk.KafkaZkClient$CheckedEphemeral.create(KafkaZkClient.scala:2127)
	at kafka.zk.KafkaZkClient.checkedEphemeralCreate(KafkaZkClient.scala:2094)
	at kafka.zk.KafkaZkClient.registerBroker(KafkaZkClient.scala:106)
	at kafka.server.KafkaServer.startup(KafkaServer.scala:404)
	at kafka.Kafka$.main(Kafka.scala:112)
	at kafka.Kafka.main(Kafka.scala)
2024-06-04 03:14:12,981 INFO [KafkaServer id=1] shutting down (kafka.server.KafkaServer) [main]

scholzj Jun 5, 2024
Maintainer

Sorry, I don't know anything about this problem. Looks like there is something wrong with your ZooKeeper 🤷. Is this a new cluster? Existing cluster? Can you share full logs? Is this problem in all brokers? Or only one of them?

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Strimzi

Kafka restarts repeatedly #5723

{{title}}

Replies: 1 comment 4 replies

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

Select a reply

Strimzi

Kafka restarts repeatedly #5723

lanzhiwang Oct 15, 2021

Replies: 1 comment · 4 replies

scholzj Oct 15, 2021 Maintainer

robertc11 May 28, 2024

robertc11 May 28, 2024

kholisrag Jun 4, 2024

scholzj Jun 5, 2024 Maintainer

lanzhiwang
Oct 15, 2021

Replies: 1 comment 4 replies

scholzj
Oct 15, 2021
Maintainer

scholzj Jun 5, 2024
Maintainer