Possible race condition during start-up of multiple nodes with KRaft.

[see-quick]

I have found out that sometimes (i.e., 1 out of 20 attempts) during the startup of StrimziKafkaCluster with multiple nodes some nodes may be out-of-sync. Meaning that in broker logs one can see:

java.util.concurrent.CompletionException: org.apache.kafka.common.errors.NotControllerException: No controller appears to be active.
        at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:332)
        at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:347)
        at java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:636)
        at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
        at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162)
        at org.apache.kafka.controller.QuorumController$ControllerWriteEvent.complete(QuorumController.java:884)
        at org.apache.kafka.controller.QuorumController$ControllerWriteEvent.handleException(QuorumController.java:875)
        at org.apache.kafka.queue.KafkaEventQueue$EventContext.completeWithException(KafkaEventQueue.java:153)
        at org.apache.kafka.queue.KafkaEventQueue$EventContext.run(KafkaEventQueue.java:142)
        at org.apache.kafka.queue.KafkaEventQueue$EventHandler.handleEvents(KafkaEventQueue.java:215)
        at org.apache.kafka.queue.KafkaEventQueue$EventHandler.run(KafkaEventQueue.java:186)
        at java.base/java.lang.Thread.run(Thread.java:840)
Caused by: org.apache.kafka.common.errors.NotControllerException: No controller appears to be active

and other nodes have

doesn't match the local key (OptionalInt[1], BKan2iyJb8cHcg-clBpk7A); rejecting the vote (org.apache.kafka.raft.KafkaRaftClient)
[2024-11-25 09:22:31,800] INFO [RaftManager id=1] Voter key for VOTE or BEGIN_QUORUM_EPOCH request didn't match the receiver's replica key: broker-2:9094 (id: 2 rack: null) (org.apache.kafka.raft.KafkaRaftClient)
[2024-11-25 09:22:31,800] INFO [RaftManager id=1] Candidate sent a voter key (Optional[ReplicaKey(id=2, directoryId=Optional.empty)]) in the VOTE request that doesn't match the local key (OptionalInt[1], BKan2iyJb8cHcg-clBpk7A); rejecting the vote (org.apache.kafka.raft.KafkaRaftClient)
[2024-11-25 09:22:31,800] INFO [RaftManager id=1] Voter key for VOTE or BEGIN_QUORUM_EPOCH request didn't match the receiver's replica key: broker-2:9094 (id: 2 rack: null) (org.apache.kafka.raft.KafkaRaftClient)
[2024-11-25 09:22:31,800] INFO [RaftManager id=1] Candidate sent a voter key (Optional[ReplicaKey(id=2, directoryId=Optional.empty)]) in the VOTE request that doesn't match the local key (OptionalInt[1], BKan2iyJb8cHcg-clBpk7A); rejecting the vote (org.apache.kafka.raft.KafkaRaftClient)
[2024-11-25 09:22:31,800] INFO [RaftManager id=1] Voter key for VOTE or BEGIN_QUORUM_EPOCH request didn't match the receiver's replica key: broker-2:9094 (id: 2 rack: null) (org.apache.kafka.raft.KafkaRaftClient)
[2024-11-25 09:22:31,800] INFO [RaftManager id=1] Candidate sent a voter key (Optional[ReplicaKey(id=2, directoryId=Optional.empty)]) in the VOTE request that doesn't match the local key (OptionalInt[1], BKan2iyJb8cHcg-clBpk7A); rejecting the vote (org.apache.kafka.raft.KafkaRaftClient)
[2024-11-25 09:22:31,800] INFO [RaftManager id=1] Voter key for VOTE or BEGIN_QUORUM_EPOCH request didn't match the receiver's replica key: broker-2:9094 (id: 2 rack: null) (org.apache.kafka.raft.KafkaRaftClient)
[2024-11-25 09:22:31,800] INFO [RaftManager id=1] Candidate sent a voter key (Optional[ReplicaKey(id=2, directoryId=Optional.empty)]) in the VOTE request that doesn't match the local key (OptionalInt[1], BKan2iyJb8cHcg-clBpk7A); rejecting the vote (org.apache.kafka.raft.KafkaRaftClient)
[2024-11-25 09:22:31,800] INFO [RaftManager id=1] Voter key for VOTE or BEGIN_QUORUM_EPOCH request didn't match the receiver's replica key: broker-2:9094 (id: 2 rack: null) (org.apache.kafka.raft.KafkaRaftClient)
[

Eventually leading to delayed tests (instead of 14s execution time, the test will run approx 65s)

This is the same test case with 0.108.0 (which uses Kafka 3.8.0) and it seems fine.

Test log:

1. when race happens: [1]
2. when race didn't happen: [2]

[1] - https://gist.github.com/see-quick/e707c1b7e7d6da9ee4ed2ac32ad02df4
[2] - https://gist.github.com/see-quick/43a56c1683babad905c002708a674d49

[showuon]

The error means the there is a node thinks "node 1" is "node 2", so it fails the vote. The log seems get truncated and miss the earlier part. Do we have the complete logs from controller nodes?

Also, this failure happened after adopting kafka v3.9.0, right?

[see-quick]

The error means the there is a node thinks "node 1" is "node 2", so it fails the vote. The log seems get truncated and miss the earlier part. Do we have the complete logs from controller nodes?

Also, this failure happened after adopting kafka v3.9.0, right?

Correct.

I will provide you with all logs from one run:

Broker-0 - https://gist.github.com/see-quick/7733fdfe5f35619572c371e29ed5e706
Broker-1 - https://gist.github.com/see-quick/ec9c5238d80b1b22cbe65437427c0ff3
Broker-2 - https://gist.github.com/see-quick/cac375b0ea00409111ca8a78e4c3c090

[see-quick]

For clarity, this is the same test case but with Kafka 3.8.1 (which is fine). Each test run takes about 8-10s but with Kafka 3.9.0 it takes 15s (and if the case of that problem about 60 s).

Broker-0 - https://gist.github.com/see-quick/5947b28a27f3a712206815984555d558
Broker-1 - https://gist.github.com/see-quick/7382eb19331f870978a3b25dd9c0336b
Broker-2 - https://gist.github.com/see-quick/6fefab8f134de093c03318a1dfecf806