You are viewing a plain text version of this content. The canonical link for it is here.
Posted to jira@kafka.apache.org by "sanghyeok An (Jira)" <ji...@apache.org> on 2024/05/12 02:01:00 UTC
[jira] [Comment Edited] (KAFKA-15648) QuorumControllerTest#testBootstrapZkMigrationRecord is flaky
[ https://issues.apache.org/jira/browse/KAFKA-15648?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17845658#comment-17845658 ]
sanghyeok An edited comment on KAFKA-15648 at 5/12/24 2:00 AM:
---------------------------------------------------------------
Hey, [~davidarthur] !
How did you test it locally?
In my case, I execute test code repeatly, but the error which you encounter on your local never occurs.
this is command lists which i executed.
# gradle --parallel test
# gradle --parallel metadata:test
# gradle metadata:test
was (Author: JIRAUSER303328):
Hey, [~davidarthur] !
How did you test it locally? I execute test code repeatly, bit that error not occurs.
this is command lists which i executed.
# gradle --parallel test
# gradle --parallel metadata:test
# gradle metadata:test
> QuorumControllerTest#testBootstrapZkMigrationRecord is flaky
> ------------------------------------------------------------
>
> Key: KAFKA-15648
> URL: https://issues.apache.org/jira/browse/KAFKA-15648
> Project: Kafka
> Issue Type: Bug
> Components: controller, unit tests
> Reporter: David Arthur
> Priority: Minor
> Labels: flaky-test, good-first-issue
>
> Noticed that this test failed on Jenkins with
> {code}
> org.apache.kafka.server.fault.FaultHandlerException: fatalFaultHandler: exception while completing controller activation: Should not have ZK migrations enabled on a cluster running metadata.version 3.0-IV1
> at app//org.apache.kafka.controller.ActivationRecordsGenerator.recordsForNonEmptyLog(ActivationRecordsGenerator.java:154)
> at app//org.apache.kafka.controller.ActivationRecordsGenerator.generate(ActivationRecordsGenerator.java:229)
> at app//org.apache.kafka.controller.QuorumController$CompleteActivationEvent.generateRecordsAndResult(QuorumController.java:1237)
> at app//org.apache.kafka.controller.QuorumController$ControllerWriteEvent.run(QuorumController.java:784)
> at app//org.apache.kafka.queue.KafkaEventQueue$EventContext.run(KafkaEventQueue.java:127)
> at app//org.apache.kafka.queue.KafkaEventQueue$EventHandler.handleEvents(KafkaEventQueue.java:210)
> at app//org.apache.kafka.queue.KafkaEventQueue$EventHandler.run(KafkaEventQueue.java:181)
> at java.base@11.0.16.1/java.lang.Thread.run(Thread.java:829)
> Caused by: java.lang.RuntimeException: Should not have ZK migrations enabled on a cluster running metadata.version 3.0-IV1
> ... 8 more
> {code}
> I think this exception is a red herring (it's expected from one of the negative test cases). When trying to reproduce this issue locally, I do occasionally see the following type of failure
> {code}
> [2023-10-19 13:42:10,091] INFO Elected new leader: LeaderAndEpoch(leaderId=OptionalInt[0], epoch=1). (org.apache.kafka.metalog.LocalLogManager$SharedLogData:300)
> [2023-10-19 13:42:10,091] DEBUG append(batch=LeaderChangeBatch(newLeader=LeaderAndEpoch(leaderId=OptionalInt[0], epoch=1)), nextEndOffset=0) (org.apache.kafka.metalog.LocalLogManager$SharedLogData:276)
> [2023-10-19 13:42:10,091] DEBUG [LocalLogManager 0] Node 0: running log check. (org.apache.kafka.metalog.LocalLogManager:536)
> [2023-10-19 13:42:10,091] DEBUG [LocalLogManager 0] initialized local log manager for node 0 (org.apache.kafka.metalog.LocalLogManager:685)
> [2023-10-19 13:42:10,091] DEBUG [QuorumController id=0] Creating in-memory snapshot -1 (org.apache.kafka.timeline.SnapshotRegistry:203)
> [2023-10-19 13:42:10,091] INFO [QuorumController id=0] Creating new QuorumController with clusterId 6xRUXZ_kQ1GfuaHK42AS9Q. ZK migration mode is enabled. (org.apache.kafka.controller.QuorumController:1912)
> [2023-10-19 13:42:10,092] INFO [LocalLogManager 0] Node 0: registered MetaLogListener 1082153924 (org.apache.kafka.metalog.LocalLogManager:703)
> [2023-10-19 13:42:10,092] DEBUG [LocalLogManager 0] Node 0: running log check. (org.apache.kafka.metalog.LocalLogManager:536)
> [2023-10-19 13:42:10,092] DEBUG [LocalLogManager 0] Node 0: Executing handleLeaderChange LeaderAndEpoch(leaderId=OptionalInt[0], epoch=1) (org.apache.kafka.metalog.LocalLogManager:578)
> [2023-10-19 13:42:10,092] DEBUG [QuorumController id=0] Executing handleLeaderChange[1]. (org.apache.kafka.controller.QuorumController:577)
> [2023-10-19 13:42:10,092] INFO [QuorumController id=0] In the new epoch 1, the leader is (none). (org.apache.kafka.controller.QuorumController:1179)
> [2023-10-19 13:42:10,092] DEBUG [QuorumController id=0] Processed handleLeaderChange[1] in 50 us (org.apache.kafka.controller.QuorumController:510)
> [2023-10-19 13:42:10,092] DEBUG [QuorumController id=0] Executing handleLeaderChange[1]. (org.apache.kafka.controller.QuorumController:577)
> [2023-10-19 13:42:10,092] INFO [QuorumController id=0] Becoming the active controller at epoch 1, next write offset 1. (org.apache.kafka.controller.QuorumController:1175)
> [2023-10-19 13:42:10,092] DEBUG [QuorumController id=0] Processed handleLeaderChange[1] in 77 us (org.apache.kafka.controller.QuorumController:510)
> [2023-10-19 13:42:10,092] WARN [QuorumController id=0] Performing controller activation. The metadata log appears to be empty. Appending 1 bootstrap record(s) at metadata.version 3.4-IV0 from bootstrap source 'test'. Putting the controller into pre-migration mode. No metadata updates will be allowed until the ZK metadata has been migrated. (org.apache.kafka.controller.QuorumController:108)
> [2023-10-19 13:42:10,092] INFO [QuorumController id=0] Replayed a FeatureLevelRecord setting metadata version to 3.4-IV0 (org.apache.kafka.controller.FeatureControlManager:400)
> [2023-10-19 13:42:10,092] INFO [QuorumController id=0] Replayed a ZkMigrationStateRecord changing the migration state from NONE to PRE_MIGRATION. (org.apache.kafka.controller.FeatureControlManager:421)
> [2023-10-19 13:42:10,092] DEBUG [QuorumController id=0] Got exception while running completeActivation[1](342832465). Invoking handleException. (org.apache.kafka.queue.KafkaEventQueue:132)
> org.apache.kafka.raft.errors.NotLeaderException: Append failed because the given epoch 0 is stale. Current leader epoch = 1
> at org.apache.kafka.metalog.LocalLogManager$SharedLogData.tryAppend(LocalLogManager.java:253)
> at org.apache.kafka.metalog.LocalLogManager$SharedLogData.tryAppend(LocalLogManager.java:233)
> at org.apache.kafka.metalog.LocalLogManager.scheduleAtomicAppend(LocalLogManager.java:795)
> at org.apache.kafka.controller.QuorumController$ControllerWriteEvent$1.apply(QuorumController.java:839)
> at org.apache.kafka.controller.QuorumController$ControllerWriteEvent$1.apply(QuorumController.java:816)
> at org.apache.kafka.controller.QuorumController.appendRecords(QuorumController.java:918)
> at org.apache.kafka.controller.QuorumController$ControllerWriteEvent.run(QuorumController.java:815)
> at org.apache.kafka.queue.KafkaEventQueue$EventContext.run(KafkaEventQueue.java:127)
> at org.apache.kafka.queue.KafkaEventQueue$EventHandler.handleEvents(KafkaEventQueue.java:210)
> at org.apache.kafka.queue.KafkaEventQueue$EventHandler.run(KafkaEventQueue.java:181)
> at java.base/java.lang.Thread.run(Thread.java:833)
> [2023-10-19 13:42:10,092] INFO [QuorumController id=0] completeActivation[1]: event failed with NotLeaderException (treated as NotControllerException) at epoch 1 in 387 microseconds. Renouncing leadership and reverting to the last committed offset -1. (org.apache.kafka.controller.QuorumController:542)
> [2023-10-19 13:42:10,092] ERROR Encountered fatalFaultHandler fault: exception while renouncing leadership (org.apache.kafka.server.fault.MockFaultHandler:44)
> java.lang.IllegalArgumentException: Attempt to resign from epoch 1 which is larger than the current epoch 0
> at org.apache.kafka.metalog.LocalLogManager.resign(LocalLogManager.java:808)
> at org.apache.kafka.controller.QuorumController.renounce(QuorumController.java:1268)
> at org.apache.kafka.controller.QuorumController.handleEventException(QuorumController.java:545)
> at org.apache.kafka.controller.QuorumController.access$800(QuorumController.java:177)
> at org.apache.kafka.controller.QuorumController$ControllerWriteEvent.complete(QuorumController.java:879)
> at org.apache.kafka.controller.QuorumController$ControllerWriteEvent.handleException(QuorumController.java:869)
> at org.apache.kafka.queue.KafkaEventQueue$EventContext.completeWithException(KafkaEventQueue.java:148)
> at org.apache.kafka.queue.KafkaEventQueue$EventContext.run(KafkaEventQueue.java:137)
> at org.apache.kafka.queue.KafkaEventQueue$EventHandler.handleEvents(KafkaEventQueue.java:210)
> at org.apache.kafka.queue.KafkaEventQueue$EventHandler.run(KafkaEventQueue.java:181)
> at java.base/java.lang.Thread.run(Thread.java:833)
> [2023-10-19 13:42:10,093] DEBUG [QuorumController id=0] Processed read migration state(176059074) in 4 us (org.apache.kafka.controller.QuorumController:510)
> [2023-10-19 13:42:10,093] INFO [QuorumController id=0] QuorumController#beginShutdown: shutting down event queue. (org.apache.kafka.queue.KafkaEventQueue:492)
> [2023-10-19 13:42:10,093] DEBUG [QuorumController id=0] KafkaEventQueue#close: Event queue is already shutting down. (org.apache.kafka.queue.KafkaEventQueue:489)
> [2023-10-19 13:42:10,093] INFO [QuorumController id=0] closed event queue. (org.apache.kafka.queue.KafkaEventQueue:514)
> [2023-10-19 13:42:10,093] INFO [LocalLogManager 0] beginShutdown: shutting down event queue. (org.apache.kafka.queue.KafkaEventQueue:492)
> [2023-10-19 13:42:10,093] DEBUG [LocalLogManager 0] Node 0: closing. (org.apache.kafka.metalog.LocalLogManager:653)
> [2023-10-19 13:42:10,094] DEBUG [LocalLogManager 0] beginShutdown: Event queue is already shutting down. (org.apache.kafka.queue.KafkaEventQueue:489)
> [2023-10-19 13:42:10,094] DEBUG [LocalLogManager 0] KafkaEventQueue#close: Event queue is already shutting down. (org.apache.kafka.queue.KafkaEventQueue:489)
> [2023-10-19 13:42:10,094] DEBUG [LocalLogManager 0] Node 0: beginning shutdown. (org.apache.kafka.metalog.LocalLogManager:637)
> [2023-10-19 13:42:10,094] DEBUG append(batch=LeaderChangeBatch(newLeader=LeaderAndEpoch(leaderId=OptionalInt.empty, epoch=2)), nextEndOffset=1) (org.apache.kafka.metalog.LocalLogManager$SharedLogData:276)
> [2023-10-19 13:42:10,094] INFO Elected new leader: LeaderAndEpoch(leaderId=OptionalInt[0], epoch=3). (org.apache.kafka.metalog.LocalLogManager$SharedLogData:300)
> [2023-10-19 13:42:10,094] DEBUG append(batch=LeaderChangeBatch(newLeader=LeaderAndEpoch(leaderId=OptionalInt[0], epoch=3)), nextEndOffset=2) (org.apache.kafka.metalog.LocalLogManager$SharedLogData:276)
> [2023-10-19 13:42:10,094] DEBUG [QuorumController id=0] MetaLogManager.Listener: Event queue is already shutting down. (org.apache.kafka.queue.KafkaEventQueue:489)
> [2023-10-19 13:42:10,094] INFO [LocalLogManager 0] closed event queue. (org.apache.kafka.queue.KafkaEventQueue:514)
> org.apache.kafka.server.fault.FaultHandlerException: fatalFaultHandler: exception while renouncing leadership: Attempt to resign from epoch 1 which is larger than the current epoch 0
> at org.apache.kafka.metalog.LocalLogManager.resign(LocalLogManager.java:808)
> at org.apache.kafka.controller.QuorumController.renounce(QuorumController.java:1268)
> at org.apache.kafka.controller.QuorumController.handleEventException(QuorumController.java:545)
> at org.apache.kafka.controller.QuorumController.access$800(QuorumController.java:177)
> at org.apache.kafka.controller.QuorumController$ControllerWriteEvent.complete(QuorumController.java:879)
> at org.apache.kafka.controller.QuorumController$ControllerWriteEvent.handleException(QuorumController.java:869)
> at org.apache.kafka.queue.KafkaEventQueue$EventContext.completeWithException(KafkaEventQueue.java:148)
> at org.apache.kafka.queue.KafkaEventQueue$EventContext.run(KafkaEventQueue.java:137)
> at org.apache.kafka.queue.KafkaEventQueue$EventHandler.handleEvents(KafkaEventQueue.java:210)
> at org.apache.kafka.queue.KafkaEventQueue$EventHandler.run(KafkaEventQueue.java:181)
> at java.base/java.lang.Thread.run(Thread.java:833)
> Caused by: java.lang.IllegalArgumentException: Attempt to resign from epoch 1 which is larger than the current epoch 0
> ... 11 more
> {code}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)