We currently have an "UnwritableMetadataException" error starting Kafka in
our test environment. Unfortunately, I don’t know whether it is due to an
incorrect configuration or something similar. Kafka is running in a Docker
Container, but I don’t think that’s the cause. When I searched this error, I
unfortunately don’t find any results.
We are currently using Kafka Kraft Version 3.7.0. If you need additional Infos about our config let me know.
Does anyone have any tips or did anyone experience this error before? The
following is a log excerpt:
kafka | kafka 06:17:49.01 INFO ==>
kafka | kafka 06:17:49.02 INFO ==> Welcome to the Bitnami kafka container
kafka | kafka 06:17:49.02 INFO ==> Subscribe to project updates by watching https://github.com/bitnami/containers
kafka | kafka 06:17:49.02 INFO ==> Submit issues and feature requests at https://github.com/bitnami/containers/issues
kafka | kafka 06:17:49.02 INFO ==> Upgrade to Tanzu Application Catalog for production environments to access custom-configured and pre-packaged software components. Gain enhanced features, including Software Bill of Materials (SBOM), CVE scan result reports, and VEX documents. To learn more, visit https://bitnami.com/enterprise
kafka | kafka 06:17:49.02 INFO ==>
kafka | kafka 06:17:49.03 INFO ==> ** Starting Kafka setup **
kafka | kafka 06:17:50.68 INFO ==> Initializing Kafka...
kafka | kafka 06:17:50.69 INFO ==> No injected configuration files found, creating default config files
kafka | kafka 06:17:51.24 INFO ==> Initializing KRaft storage metadata
kafka | kafka 06:17:51.25 INFO ==> Formatting storage directories to add metadata...
kafka | metaPropertiesEnsemble=MetaPropertiesEnsemble(metadataLogDir=Optional.empty, dirs={/bitnami/kafka/data: MetaProperties(version=1, clusterId=<cluster_id>, nodeId=2, directoryId=85zdFJUTcbfYz0NwP8U3iA)})
kafka | All of the log directories are already formatted.
kafka | kafka 06:17:53.21 INFO ==> ** Kafka setup finished! **
kafka |
kafka | kafka 06:17:53.23 INFO ==> ** Starting Kafka **
kafka | [2024-04-16 06:17:54,210] INFO Registered kafka:type=kafka.Log4jController MBean (kafka.utils.Log4jControllerRegistration$)
kafka | [2024-04-16 06:17:54,607] INFO Setting -D jdk.tls.rejectClientInitiatedRenegotiation=true to disable client-initiated TLS renegotiation (org.apache.zookeeper.common.X509Util)
kafka | [2024-04-16 06:17:54,815] INFO Registered signal handlers for TERM, INT, HUP (org.apache.kafka.common.utils.LoggingSignalHandler)
kafka | [2024-04-16 06:17:54,819] INFO [ControllerServer id=2] Starting controller (kafka.server.ControllerServer)
kafka | [2024-04-16 06:17:55,465] INFO Updated connection-accept-rate max connection creation rate to 2147483647 (kafka.network.ConnectionQuotas)
kafka | [2024-04-16 06:17:56,298] INFO [SocketServer listenerType=CONTROLLER, nodeId=2] Created data-plane acceptor and processors for endpoint : ListenerName(CONTROLLER) (kafka.network.SocketServer)
kafka | [2024-04-16 06:17:56,302] INFO CONTROLLER: resolved wildcard host to kafka (org.apache.kafka.metadata.ListenerInfo)
kafka | [2024-04-16 06:17:56,312] INFO authorizerStart completed for endpoint CONTROLLER. Endpoint is now READY. (org.apache.kafka.server.network.EndpointReadyFutures)
kafka | [2024-04-16 06:17:56,312] INFO [SharedServer id=2] Starting SharedServer (kafka.server.SharedServer)
kafka | [2024-04-16 06:17:56,405] INFO [LogLoader partition=__cluster_metadata-0, dir=/bitnami/kafka/data] Recovering unflushed segment 2639301. 0/3 recovered for __cluster_metadata-0. (kafka.log.LogLoader)
kafka | [2024-04-16 06:17:56,408] INFO [LogLoader partition=__cluster_metadata-0, dir=/bitnami/kafka/data] Loading producer state till offset 2639301 with message format version 2 (kafka.log.UnifiedLog$)
kafka | [2024-04-16 06:17:56,409] INFO [LogLoader partition=__cluster_metadata-0, dir=/bitnami/kafka/data] Reloading from producer snapshot and rebuilding producer state from offset 2639301 (kafka.log.UnifiedLog$)
kafka | [2024-04-16 06:17:56,410] INFO Deleted producer state snapshot /bitnami/kafka/data/__cluster_metadata-0/00000000000003954853.snapshot (org.apache.kafka.storage.internals.log.SnapshotFile)
kafka | [2024-04-16 06:17:56,410] INFO Deleted producer state snapshot /bitnami/kafka/data/__cluster_metadata-0/00000000000005164322.snapshot (org.apache.kafka.storage.internals.log.SnapshotFile)
kafka | [2024-04-16 06:17:56,411] INFO Deleted producer state snapshot /bitnami/kafka/data/__cluster_metadata-0/00000000000006183812.snapshot (org.apache.kafka.storage.internals.log.SnapshotFile)
kafka | [2024-04-16 06:17:56,420] INFO [ProducerStateManager partition=__cluster_metadata-0] Wrote producer snapshot at offset 2639301 with 0 producer ids in 7 ms. (org.apache.kafka.storage.internals.log.ProducerStateManager)
kafka | [2024-04-16 06:17:56,420] INFO [LogLoader partition=__cluster_metadata-0, dir=/bitnami/kafka/data] Producer state recovery took 1ms for snapshot load and 9ms for segment recovery from offset 2639301 (kafka.log.UnifiedLog$)
kafka | [2024-04-16 06:18:01,061] INFO [ProducerStateManager partition=__cluster_metadata-0] Wrote producer snapshot at offset 3954853 with 0 producer ids in 1 ms. (org.apache.kafka.storage.internals.log.ProducerStateManager)
kafka | [2024-04-16 06:18:01,061] INFO [LogLoader partition=__cluster_metadata-0, dir=/bitnami/kafka/data] Recovering unflushed segment 3954853. 1/3 recovered for __cluster_metadata-0. (kafka.log.LogLoader)
kafka | [2024-04-16 06:18:01,063] INFO [LogLoader partition=__cluster_metadata-0, dir=/bitnami/kafka/data] Loading producer state till offset 3954853 with message format version 2 (kafka.log.UnifiedLog$)
kafka | [2024-04-16 06:18:01,063] INFO [LogLoader partition=__cluster_metadata-0, dir=/bitnami/kafka/data] Reloading from producer snapshot and rebuilding producer state from offset 3954853 (kafka.log.UnifiedLog$)
kafka | [2024-04-16 06:18:01,063] INFO [ProducerStateManager partition=__cluster_metadata-0] Loading producer state from snapshot file 'SnapshotFile(offset=3954853, file=/bitnami/kafka/data/__cluster_metadata-0/00000000000003954853.snapshot)' (org.apache.kafka.storage.internals.log.ProducerStateManager)
kafka | [2024-04-16 06:18:01,066] INFO [LogLoader partition=__cluster_metadata-0, dir=/bitnami/kafka/data] Producer state recovery took 3ms for snapshot load and 0ms for segment recovery from offset 3954853 (kafka.log.UnifiedLog$)
kafka | [2024-04-16 06:18:05,185] INFO [ProducerStateManager partition=__cluster_metadata-0] Wrote producer snapshot at offset 5164322 with 0 producer ids in 1 ms. (org.apache.kafka.storage.internals.log.ProducerStateManager)
kafka | [2024-04-16 06:18:05,186] INFO [LogLoader partition=__cluster_metadata-0, dir=/bitnami/kafka/data] Recovering unflushed segment 5164322. 2/3 recovered for __cluster_metadata-0. (kafka.log.LogLoader)
kafka | [2024-04-16 06:18:05,187] INFO [LogLoader partition=__cluster_metadata-0, dir=/bitnami/kafka/data] Loading producer state till offset 5164322 with message format version 2 (kafka.log.UnifiedLog$)
kafka | [2024-04-16 06:18:05,187] INFO [LogLoader partition=__cluster_metadata-0, dir=/bitnami/kafka/data] Reloading from producer snapshot and rebuilding producer state from offset 5164322 (kafka.log.UnifiedLog$)
kafka | [2024-04-16 06:18:05,187] INFO [ProducerStateManager partition=__cluster_metadata-0] Loading producer state from snapshot file 'SnapshotFile(offset=5164322, file=/bitnami/kafka/data/__cluster_metadata-0/00000000000005164322.snapshot)' (org.apache.kafka.storage.internals.log.ProducerStateManager)
kafka | [2024-04-16 06:18:05,188] INFO [LogLoader partition=__cluster_metadata-0, dir=/bitnami/kafka/data] Producer state recovery took 1ms for snapshot load and 0ms for segment recovery from offset 5164322 (kafka.log.UnifiedLog$)
kafka | [2024-04-16 06:18:08,466] INFO [ProducerStateManager partition=__cluster_metadata-0] Wrote producer snapshot at offset 6183828 with 0 producer ids in 1 ms. (org.apache.kafka.storage.internals.log.ProducerStateManager)
kafka | [2024-04-16 06:18:08,480] INFO [LogLoader partition=__cluster_metadata-0, dir=/bitnami/kafka/data] Loading producer state till offset 6183828 with message format version 2 (kafka.log.UnifiedLog$)
kafka | [2024-04-16 06:18:08,480] INFO [LogLoader partition=__cluster_metadata-0, dir=/bitnami/kafka/data] Reloading from producer snapshot and rebuilding producer state from offset 6183828 (kafka.log.UnifiedLog$)
kafka | [2024-04-16 06:18:08,480] INFO Deleted producer state snapshot /bitnami/kafka/data/__cluster_metadata-0/00000000000002639301.snapshot (org.apache.kafka.storage.internals.log.SnapshotFile)
kafka | [2024-04-16 06:18:08,480] INFO [ProducerStateManager partition=__cluster_metadata-0] Loading producer state from snapshot file 'SnapshotFile(offset=6183828, file=/bitnami/kafka/data/__cluster_metadata-0/00000000000006183828.snapshot)' (org.apache.kafka.storage.internals.log.ProducerStateManager)
kafka | [2024-04-16 06:18:08,480] INFO [LogLoader partition=__cluster_metadata-0, dir=/bitnami/kafka/data] Producer state recovery took 0ms for snapshot load and 0ms for segment recovery from offset 6183828 (kafka.log.UnifiedLog$)
kafka | [2024-04-16 06:18:08,520] INFO Initialized snapshots with IDs Set(OffsetAndEpoch(offset=2639301, epoch=235)) from /bitnami/kafka/data/__cluster_metadata-0 (kafka.raft.KafkaMetadataLog$)
kafka | [2024-04-16 06:18:08,692] INFO [raft-expiration-reaper]: Starting (kafka.raft.TimingWheelExpirationService$ExpiredOperationReaper)
kafka | [2024-04-16 06:18:08,912] INFO [RaftManager id=2] Completed transition to FollowerState(fetchTimeoutMs=2000, epoch=2327, leaderId=1, voters=[1, 2], highWatermark=Optional.empty, fetchingSnapshot=Optional.empty) from null (org.apache.kafka.raft.QuorumState)
kafka | [2024-04-16 06:18:08,916] INFO [kafka-2-raft-outbound-request-thread]: Starting (org.apache.kafka.raft.KafkaNetworkChannel$SendThread)
kafka | [2024-04-16 06:18:08,917] INFO [kafka-2-raft-io-thread]: Starting (kafka.raft.KafkaRaftManager$RaftIoThread)
kafka | [2024-04-16 06:18:08,939] INFO [MetadataLoader id=2] initializeNewPublishers: the loader is still catching up because we still don't know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
kafka | [2024-04-16 06:18:08,941] INFO [ControllerServer id=2] Waiting for controller quorum voters future (kafka.server.ControllerServer)
kafka | [2024-04-16 06:18:08,942] INFO [RaftManager id=2] Registered the listener org.apache.kafka.image.loader.MetadataLoader@1969093581 (org.apache.kafka.raft.KafkaRaftClient)
kafka | [2024-04-16 06:18:08,942] INFO [ControllerServer id=2] Finished waiting for controller quorum voters future (kafka.server.ControllerServer)
kafka | [2024-04-16 06:18:09,031] INFO [QuorumController id=2] Creating new QuorumController with clusterId <cluster_id>. (org.apache.kafka.controller.QuorumController)
kafka | [2024-04-16 06:18:09,032] INFO [RaftManager id=2] Registered the listener org.apache.kafka.controller.QuorumController$QuorumMetaLogListener@635384855 (org.apache.kafka.raft.KafkaRaftClient)
kafka | [2024-04-16 06:18:09,040] INFO [MetadataLoader id=2] initializeNewPublishers: the loader is still catching up because we still don't know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
kafka | [2024-04-16 06:18:09,040] INFO [controller-2-ThrottledChannelReaper-Fetch]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
kafka | [2024-04-16 06:18:09,041] INFO [controller-2-ThrottledChannelReaper-Produce]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
kafka | [2024-04-16 06:18:09,042] INFO [controller-2-ThrottledChannelReaper-Request]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
kafka | [2024-04-16 06:18:09,045] INFO [controller-2-ThrottledChannelReaper-ControllerMutation]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
kafka | [2024-04-16 06:18:09,077] INFO [ExpirationReaper-2-AlterAcls]: Starting (kafka.server.DelayedOperationPurgatory$ExpiredOperationReaper)
kafka | [2024-04-16 06:18:09,108] INFO [ControllerServer id=2] Waiting for the controller metadata publishers to be installed (kafka.server.ControllerServer)
kafka | [2024-04-16 06:18:09,108] INFO [MetadataLoader id=2] initializeNewPublishers: the loader is still catching up because we still don't know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
kafka | [2024-04-16 06:18:09,109] INFO [ControllerServer id=2] Finished waiting for the controller metadata publishers to be installed (kafka.server.ControllerServer)
kafka | [2024-04-16 06:18:09,112] INFO [SocketServer listenerType=CONTROLLER, nodeId=2] Enabling request processing. (kafka.network.SocketServer)
kafka | [2024-04-16 06:18:09,117] INFO Awaiting socket connections on 0.0.0.0:9091. (kafka.network.DataPlaneAcceptor)
kafka | [2024-04-16 06:18:09,198] INFO [RaftManager id=2] Completed transition to Unattached(epoch=138222, voters=[1, 2], electionTimeoutMs=1496) from FollowerState(fetchTimeoutMs=2000, epoch=2327, leaderId=1, voters=[1, 2], highWatermark=Optional.empty, fetchingSnapshot=Optional.empty) (org.apache.kafka.raft.QuorumState)
kafka | [2024-04-16 06:18:09,201] INFO [QuorumController id=2] In the new epoch 138222, the leader is (none). (org.apache.kafka.controller.QuorumController)
kafka | [2024-04-16 06:18:09,209] INFO [MetadataLoader id=2] initializeNewPublishers: the loader is still catching up because we still don't know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
kafka | [2024-04-16 06:18:09,300] INFO [RaftManager id=2] Completed transition to Voted(epoch=138222, votedId=1, voters=[1, 2], electionTimeoutMs=1449) from Unattached(epoch=138222, voters=[1, 2], electionTimeoutMs=1496) (org.apache.kafka.raft.QuorumState)
kafka | [2024-04-16 06:18:09,301] INFO [RaftManager id=2] Vote request VoteRequestData(clusterId='<cluster_id>', topics=[TopicData(topicName='__cluster_metadata', partitions=[PartitionData(partitionIndex=0, candidateEpoch=138222, candidateId=1, lastOffsetEpoch=2327, lastOffset=6183834)])]) with epoch 138222 is granted (org.apache.kafka.raft.KafkaRaftClient)
kafka | [2024-04-16 06:18:09,310] INFO [MetadataLoader id=2] initializeNewPublishers: the loader is still catching up because we still don't know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
kafka | [2024-04-16 06:18:09,319] INFO [RaftManager id=2] Completed transition to FollowerState(fetchTimeoutMs=2000, epoch=138222, leaderId=1, voters=[1, 2], highWatermark=Optional.empty, fetchingSnapshot=Optional.empty) from Voted(epoch=138222, votedId=1, voters=[1, 2], electionTimeoutMs=1449) (org.apache.kafka.raft.QuorumState)
kafka | [2024-04-16 06:18:09,320] INFO [QuorumController id=2] In the new epoch 138222, the leader is 1. (org.apache.kafka.controller.QuorumController)
kafka | [2024-04-16 06:18:09,340] INFO [controller-2-to-controller-registration-channel-manager]: Starting (kafka.server.NodeToControllerRequestThread)
kafka | [2024-04-16 06:18:09,341] INFO [ControllerServer id=2] Waiting for all of the authorizer futures to be completed (kafka.server.ControllerServer)
kafka | [2024-04-16 06:18:09,341] INFO [ControllerServer id=2] Finished waiting for all of the authorizer futures to be completed (kafka.server.ControllerServer)
kafka | [2024-04-16 06:18:09,341] INFO [ControllerServer id=2] Waiting for all of the SocketServer Acceptors to be started (kafka.server.ControllerServer)
kafka | [2024-04-16 06:18:09,341] INFO [ControllerServer id=2] Finished waiting for all of the SocketServer Acceptors to be started (kafka.server.ControllerServer)
kafka | [2024-04-16 06:18:09,342] INFO [ControllerRegistrationManager id=2 incarnation=UKrUxI-6ROCM4xnCzRTr8Q] initialized channel manager. (kafka.server.ControllerRegistrationManager)
kafka | [2024-04-16 06:18:09,342] INFO [BrokerServer id=2] Transition from SHUTDOWN to STARTING (kafka.server.BrokerServer)
kafka | [2024-04-16 06:18:09,342] INFO [controller-2-to-controller-registration-channel-manager]: Recorded new controller, from now on will use node <node_1_id>:9091 (id: 1 rack: null) (kafka.server.NodeToControllerRequestThread)
kafka | [2024-04-16 06:18:09,344] INFO [BrokerServer id=2] Starting broker (kafka.server.BrokerServer)
kafka | [2024-04-16 06:18:09,344] INFO [ControllerRegistrationManager id=2 incarnation=UKrUxI-6ROCM4xnCzRTr8Q] maybeSendControllerRegistration: cannot register yet because the metadata version is still 3.0-IV1, which does not support KIP-919 controller registration. (kafka.server.ControllerRegistrationManager)
kafka | [2024-04-16 06:18:09,355] INFO [broker-2-ThrottledChannelReaper-Fetch]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
kafka | [2024-04-16 06:18:09,355] INFO [broker-2-ThrottledChannelReaper-Produce]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
kafka | [2024-04-16 06:18:09,355] INFO [broker-2-ThrottledChannelReaper-Request]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
kafka | [2024-04-16 06:18:09,356] INFO [broker-2-ThrottledChannelReaper-ControllerMutation]: Starting (kafka.server.ClientQuotaManager$ThrottledChannelReaper)
kafka | [2024-04-16 06:18:09,365] INFO [LocalLog partition=__cluster_metadata-0, dir=/bitnami/kafka/data] Rolled new log segment at offset 6183834 in 4 ms. (kafka.log.LocalLog)
kafka | [2024-04-16 06:18:09,366] INFO [ProducerStateManager partition=__cluster_metadata-0] Wrote producer snapshot at offset 6183834 with 0 producer ids in 1 ms. (org.apache.kafka.storage.internals.log.ProducerStateManager)
kafka | [2024-04-16 06:18:09,387] INFO [BrokerServer id=2] Waiting for controller quorum voters future (kafka.server.BrokerServer)
kafka | [2024-04-16 06:18:09,387] INFO [BrokerServer id=2] Finished waiting for controller quorum voters future (kafka.server.BrokerServer)
kafka | [2024-04-16 06:18:09,410] INFO [MetadataLoader id=2] initializeNewPublishers: the loader is still catching up because we still don't know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
kafka | [2024-04-16 06:18:09,510] INFO [MetadataLoader id=2] initializeNewPublishers: the loader is still catching up because we still don't know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
kafka | [2024-04-16 06:18:09,541] INFO [broker-2-to-controller-forwarding-channel-manager]: Starting (kafka.server.NodeToControllerRequestThread)
kafka | [2024-04-16 06:18:09,541] INFO [broker-2-to-controller-forwarding-channel-manager]: Recorded new controller, from now on will use node <node_1_id>:9091 (id: 1 rack: null) (kafka.server.NodeToControllerRequestThread)
kafka | [2024-04-16 06:18:09,611] INFO [MetadataLoader id=2] initializeNewPublishers: the loader is still catching up because we still don't know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
kafka | [2024-04-16 06:18:09,627] INFO Updated connection-accept-rate max connection creation rate to 2147483647 (kafka.network.ConnectionQuotas)
kafka | [2024-04-16 06:18:09,711] INFO [MetadataLoader id=2] initializeNewPublishers: the loader is still catching up because we still don't know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
kafka | [2024-04-16 06:18:09,812] INFO [MetadataLoader id=2] initializeNewPublishers: the loader is still catching up because we still don't know the high water mark yet. (org.apache.kafka.image.loader.MetadataLoader)
kafka | [2024-04-16 06:18:09,878] INFO [RaftManager id=2] High watermark set to Optional[LogOffsetMetadata(offset=6183835, metadata=Optional.empty)] for the first time for epoch 138222 (org.apache.kafka.raft.FollowerState)
kafka | [2024-04-16 06:18:09,886] INFO [MetadataLoader id=2] handleLoadSnapshot(00000000000002639301-0000000235): incrementing HandleLoadSnapshotCount to 1. (org.apache.kafka.image.loader.MetadataLoader)
kafka | [2024-04-16 06:18:09,892] INFO [QuorumController id=2] Starting to load snapshot 00000000000002639301-0000000235. Previous lastCommittedOffset was -1. Previous transactionStartOffset was -1. (org.apache.kafka.controller.OffsetControlManager)
kafka | [2024-04-16 06:18:09,935] INFO [QuorumController id=2] Replayed a FeatureLevelRecord setting metadata version to 3.5-IV2 (org.apache.kafka.controller.FeatureControlManager)
kafka | [2024-04-16 06:18:09,940] INFO [QuorumController id=2] Replayed initial RegisterBrokerRecord for broker 1: RegisterBrokerRecord(brokerId=1, isMigratingZkBroker=false, incarnationId=reiuYG1aT3K2b9l0OBEKUw, brokerEpoch=2601314, endPoints=[BrokerEndpoint(name='BROKER', host='<node_1_id>', port=9092, securityProtocol=1)], features=[BrokerFeature(name='metadata.version', minSupportedVersion=1, maxSupportedVersion=19)], rack='rack1', fenced=false, inControlledShutdown=false, logDirs=[]) (org.apache.kafka.controller.ClusterControlManager)
kafka | [2024-04-16 06:18:09,940] INFO [QuorumController id=2] Replayed initial RegisterBrokerRecord for broker 2: RegisterBrokerRecord(brokerId=2, isMigratingZkBroker=false, incarnationId=U-yYc2WoQsG4aBo4JL6oLg, brokerEpoch=2597822, endPoints=[BrokerEndpoint(name='BROKER', host='<node_2_id>', port=9092, securityProtocol=1)], features=[BrokerFeature(name='metadata.version', minSupportedVersion=1, maxSupportedVersion=19)], rack='rack1', fenced=false, inControlledShutdown=false, logDirs=[]) (org.apache.kafka.controller.ClusterControlManager)
kafka | [2024-04-16 06:18:09,941] INFO [QuorumController id=2] Replayed TopicRecord for ....
kafka | [2024-04-16 06:18:09,946] INFO [QuorumController id=2] Replayed PartitionRecord .....
...
kafka | [2024-04-16 06:18:13,702] INFO [MetadataLoader id=2] maybePublishMetadata(LOG_DELTA): The loader finished catching up to the current high water mark of 6183843 (org.apache.kafka.image.loader.MetadataLoader)
kafka | [2024-04-16 06:18:13,706] INFO [BrokerLifecycleManager id=2] The broker has caught up. Transitioning from STARTING to RECOVERY. (kafka.server.BrokerLifecycleManager)
kafka | [2024-04-16 06:18:13,706] INFO [BrokerServer id=2] Finished waiting for the controller to acknowledge that we are caught up (kafka.server.BrokerServer)
kafka | [2024-04-16 06:18:13,706] INFO [BrokerServer id=2] Waiting for the initial broker metadata update to be published (kafka.server.BrokerServer)
kafka | [2024-04-16 06:18:13,707] ERROR Encountered fatal fault: Unhandled error initializing new publishers (org.apache.kafka.server.fault.ProcessTerminatingFaultHandler)
kafka | org.apache.kafka.image.writer.UnwritableMetadataException: Metadata has been lost because the following could not be represented in metadata version 3.5-IV2: the directory assignment state of one or more replicas
kafka | at org.apache.kafka.image.writer.ImageWriterOptions.handleLoss(ImageWriterOptions.java:94)
kafka | at org.apache.kafka.metadata.PartitionRegistration.toRecord(PartitionRegistration.java:391)
kafka | at org.apache.kafka.image.TopicImage.write(TopicImage.java:71)
kafka | at org.apache.kafka.image.TopicsImage.write(TopicsImage.java:84)
kafka | at org.apache.kafka.image.MetadataImage.write(MetadataImage.java:155)
kafka | at org.apache.kafka.image.loader.MetadataLoader.initializeNewPublishers(MetadataLoader.java:295)
kafka | at org.apache.kafka.image.loader.MetadataLoader.lambda$scheduleInitializeNewPublishers$0(MetadataLoader.java:266)
kafka | at org.apache.kafka.queue.KafkaEventQueue$EventContext.run(KafkaEventQueue.java:127)
kafka | at org.apache.kafka.queue.KafkaEventQueue$EventHandler.handleEvents(KafkaEventQueue.java:210)
kafka | at org.apache.kafka.queue.KafkaEventQueue$EventHandler.run(KafkaEventQueue.java:181)
kafka | at java.base/java.lang.Thread.run(Thread.java:840)
kafka exited with code 0
The problem occurred after restarting the Kafka Docker container. The other node in the cluster is still running as usual. Everything worked prior to the restart.
2
Answers
This is an actual Kafka Bug, tracked in https://issues.apache.org/jira/browse/KAFKA-16662. It was resolved recently from the Apache Team. The fix will be included in v3.7.1 and v3.8.0.
I’ve run into the same problem with Kafka 3.7, though in my case the message is (likely because this cluster was originally created with 3.4 and later upgraded to 3.5, 3.6, and finally 3.7).
Was anyone able to understand and/or resolve this issue?