ZOOKEEPER-2623: [ADDENDUM] Fix flaky CheckTest::testCluster #2067

kezhuw · 2023-09-19T12:26:56Z

All tests are refactored to fail before #1988 and resist more than 100 runs locally without failure after #1988.

Context

I saw several failed ci actions due to flaky CheckTest::testCluster after #1988 merged:

org.opentest4j.AssertionFailedError: Unable to connect to server
	at org.apache.zookeeper.test.ClientBase.createClient(ClientBase.java:215)
	at org.apache.zookeeper.test.ClientBase.createClient(ClientBase.java:201)
	at org.apache.zookeeper.test.CheckTest.testCluster(CheckTest.java:107)

In investigation, I constructed a commit kezhuw@e452ff9 in branch in my fork basing on code before #1988. The commit is extracted from above flaky test. It still could not resist about 20 runs. So I think we are safe to go with this pr.

If it is a test problem, the test has been refactored and verified locally with enough runs.
If it is a production problem, then it is a possibly unrelated issue.

TLDR: The log reveals potential double leading

I am still investigating, so I can be completely wrong! I was thinking it is related to Oracle Quorum, but the test still fail after changing withOracle to false in setUp.

server3 is the old leader.

2023-09-19 19:10:12,592 [myid:] - INFO  [QuorumPeer[myid=3](plain=127.0.0.1:11267)(secure=disabled):o.a.z.s.q.Leader@591] - LEADING - LEADER ELECTION TOOK - 289 MS

In election after `server3` started, both `server1` and `server2` proposed `server2` as new leader.

2023-09-19 19:10:14,072 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.Follower@286] - shutdown Follower
2023-09-19 19:10:14,072 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.QuorumPeer@920] - Peer state changed: looking
2023-09-19 19:10:14,072 [myid:] - WARN  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.QuorumPeer@1602] - PeerState set to LOOKING
2023-09-19 19:10:14,072 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.QuorumPeer@1471] - LOOKING
2023-09-19 19:10:14,073 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.FastLeaderElection@946] - New election. My id = 2, proposed zxid=0x100000004
2023-09-19 19:10:14,074 [myid:] - INFO  [WorkerReceiver[myid=1]:o.a.z.s.q.f.QuorumOracleMaj@66] - Oracle is set to /Users/kezhuw/Sources/zookeeper/zookeeper-server/target/surefire/test6919410019681875524.junit.dir/oraclePath/0/mastership/value
2023-09-19 19:10:14,074 [myid:] - INFO  [WorkerReceiver[myid=2]:o.a.z.s.q.f.QuorumOracleMaj@66] - Oracle is set to /Users/kezhuw/Sources/zookeeper/zookeeper-server/target/surefire/test6919410019681875524.junit.dir/oraclePath/1/mastership/value
2023-09-19 19:10:14,075 [myid:] - INFO  [WorkerReceiver[myid=1]:o.a.z.s.q.FastLeaderElection$Messenger$WorkerReceiver@391] - Notification: my state:LOOKING; n.sid:2, n.state:LOOKING, n.leader:2, n.round:0x3, n.peerEpoch:0x1, n.zxid:0x100000004, message format version:0x2, n.config version:0x0
2023-09-19 19:10:14,075 [myid:] - INFO  [WorkerReceiver[myid=3]:o.a.z.s.q.FastLeaderElection$Messenger$WorkerReceiver@391] - Notification: my state:LOOKING; n.sid:2, n.state:LOOKING, n.leader:2, n.round:0x3, n.peerEpoch:0x1, n.zxid:0x100000004, message format version:0x2, n.config version:0x0
2023-09-19 19:10:14,075 [myid:] - INFO  [WorkerReceiver[myid=2]:o.a.z.s.q.FastLeaderElection$Messenger$WorkerReceiver@391] - Notification: my state:LOOKING; n.sid:2, n.state:LOOKING, n.leader:2, n.round:0x3, n.peerEpoch:0x1, n.zxid:0x100000004, message format version:0x2, n.config version:0x0
2023-09-19 19:10:14,076 [myid:] - INFO  [WorkerReceiver[myid=1]:o.a.z.s.q.f.QuorumOracleMaj@66] - Oracle is set to /Users/kezhuw/Sources/zookeeper/zookeeper-server/target/surefire/test6919410019681875524.junit.dir/oraclePath/0/mastership/value
2023-09-19 19:10:14,076 [myid:] - INFO  [WorkerReceiver[myid=1]:o.a.z.s.q.FastLeaderElection$Messenger$WorkerReceiver@391] - Notification: my state:LOOKING; n.sid:1, n.state:LOOKING, n.leader:2, n.round:0x3, n.peerEpoch:0x1, n.zxid:0x100000004, message format version:0x2, n.config version:0x0
2023-09-19 19:10:14,076 [myid:] - INFO  [WorkerReceiver[myid=2]:o.a.z.s.q.f.QuorumOracleMaj@66] - Oracle is set to /Users/kezhuw/Sources/zookeeper/zookeeper-server/target/surefire/test6919410019681875524.junit.dir/oraclePath/1/mastership/value
2023-09-19 19:10:14,076 [myid:] - INFO  [WorkerReceiver[myid=3]:o.a.z.s.q.FastLeaderElection$Messenger$WorkerReceiver@391] - Notification: my state:LOOKING; n.sid:1, n.state:LOOKING, n.leader:2, n.round:0x3, n.peerEpoch:0x1, n.zxid:0x100000004, message format version:0x2, n.config version:0x0
2023-09-19 19:10:14,076 [myid:] - INFO  [WorkerReceiver[myid=2]:o.a.z.s.q.FastLeaderElection$Messenger$WorkerReceiver@391] - Notification: my state:LOOKING; n.sid:1, n.state:LOOKING, n.leader:2, n.round:0x3, n.peerEpoch:0x1, n.zxid:0x100000004, message format version:0x2, n.config version:0x0

Then both `server2` and `server3` claims they are leaders and "Have quorum of supporters".

2023-09-19 19:10:14,349 [myid:] - INFO  [QuorumPeer[myid=3](plain=127.0.0.1:11267)(secure=disabled):o.a.z.s.q.QuorumPeer@906] - Peer state changed: leading
2023-09-19 19:10:14,349 [myid:] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11265)(secure=disabled):o.a.z.s.q.QuorumPeer@906] - Peer state changed: following
2023-09-19 19:10:14,349 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.QuorumPeer@906] - Peer state changed: leading
2023-09-19 19:10:14,350 [myid:] - INFO  [QuorumPeer[myid=3](plain=127.0.0.1:11267)(secure=disabled):o.a.z.s.q.QuorumPeer@1566] - LEADING
2023-09-19 19:10:14,350 [myid:] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11265)(secure=disabled):o.a.z.s.q.QuorumPeer@1554] - FOLLOWING
2023-09-19 19:10:14,350 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.QuorumPeer@1566] - LEADING

2023-09-19 19:10:14,349 [myid:] - INFO  [QuorumPeer[myid=3](plain=127.0.0.1:11267)(secure=disabled):o.a.z.s.q.QuorumPeer@906] - Peer state changed: leading
2023-09-19 19:10:14,349 [myid:] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11265)(secure=disabled):o.a.z.s.q.QuorumPeer@906] - Peer state changed: following
2023-09-19 19:10:14,349 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.QuorumPeer@906] - Peer state changed: leading
2023-09-19 19:10:14,350 [myid:] - INFO  [QuorumPeer[myid=3](plain=127.0.0.1:11267)(secure=disabled):o.a.z.s.q.QuorumPeer@1566] - LEADING
2023-09-19 19:10:14,350 [myid:] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11265)(secure=disabled):o.a.z.s.q.QuorumPeer@1554] - FOLLOWING
2023-09-19 19:10:14,350 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.QuorumPeer@1566] - LEADING

2023-09-19 19:10:14,351 [myid:] - INFO  [QuorumPeer[myid=3](plain=127.0.0.1:11267)(secure=disabled):o.a.z.s.ZooKeeperServer@385] - Created server with tickTime 2000 ms minSessionTimeout 4000 ms maxSessionTimeout 40000 ms clientPortListenBacklog -1 datadir /Users/kezhuw/Sources/zookeeper/zookeeper-server/target/surefire/test629330749513753216.junit.dir/version-2 snapdir /Users/kezhuw/Sources/zookeeper/zookeeper-server/target/surefire/test629330749513753216.junit.dir/version-2
2023-09-19 19:10:14,351 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.ZooKeeperServer@385] - Created server with tickTime 2000 ms minSessionTimeout 4000 ms maxSessionTimeout 40000 ms clientPortListenBacklog -1 datadir /Users/kezhuw/Sources/zookeeper/zookeeper-server/target/surefire/test8707384250662625929.junit.dir/version-2 snapdir /Users/kezhuw/Sources/zookeeper/zookeeper-server/target/surefire/test8707384250662625929.junit.dir/version-2
2023-09-19 19:10:14,351 [myid:] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11265)(secure=disabled):o.a.z.s.ZooKeeperServer@385] - Created server with tickTime 2000 ms minSessionTimeout 4000 ms maxSessionTimeout 40000 ms clientPortListenBacklog -1 datadir /Users/kezhuw/Sources/zookeeper/zookeeper-server/target/surefire/test7339376089355315026.junit.dir/version-2 snapdir /Users/kezhuw/Sources/zookeeper/zookeeper-server/target/surefire/test7339376089355315026.junit.dir/version-2
2023-09-19 19:10:14,351 [myid:] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11265)(secure=disabled):o.a.z.s.q.Follower@77] - FOLLOWING - LEADER ELECTION TOOK - 603 MS
2023-09-19 19:10:14,351 [myid:] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11265)(secure=disabled):o.a.z.s.q.QuorumPeer@920] - Peer state changed: following - discovery
2023-09-19 19:10:14,351 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.Leader@591] - LEADING - LEADER ELECTION TOOK - 279 MS
2023-09-19 19:10:14,351 [myid:] - INFO  [QuorumPeer[myid=3](plain=127.0.0.1:11267)(secure=disabled):o.a.z.s.q.Leader@591] - LEADING - LEADER ELECTION TOOK - 1284 MS
2023-09-19 19:10:14,353 [myid:] - INFO  [LeaderConnector-/127.0.0.1:11256:o.a.z.s.q.Learner$LeaderConnector@380] - Successfully connected to leader, using address: /127.0.0.1:11256
2023-09-19 19:10:14,353 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.QuorumPeer@920] - Peer state changed: leading - discovery
2023-09-19 19:10:14,353 [myid:] - INFO  [QuorumPeer[myid=3](plain=127.0.0.1:11267)(secure=disabled):o.a.z.s.q.QuorumPeer@920] - Peer state changed: leading - discovery
2023-09-19 19:10:14,353 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.p.FileTxnSnapLog@480] - Snapshotting: 0x100000004 to /Users/kezhuw/Sources/zookeeper/zookeeper-server/target/surefire/test8707384250662625929.junit.dir/version-2/snapshot.100000004
2023-09-19 19:10:14,353 [myid:] - INFO  [QuorumPeer[myid=3](plain=127.0.0.1:11267)(secure=disabled):o.a.z.s.p.FileTxnSnapLog@480] - Snapshotting: 0x100000004 to /Users/kezhuw/Sources/zookeeper/zookeeper-server/target/surefire/test629330749513753216.junit.dir/version-2/snapshot.100000004
2023-09-19 19:10:14,360 [myid:] - INFO  [QuorumPeer[myid=3](plain=127.0.0.1:11267)(secure=disabled):o.a.z.s.ZooKeeperServer@589] - Snapshot taken in 7 ms
2023-09-19 19:10:14,360 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.ZooKeeperServer@589] - Snapshot taken in 7 ms
2023-09-19 19:10:14,363 [myid:] - INFO  [LearnerHandler-/127.0.0.1:52225:o.a.z.s.q.LearnerHandler@511] - Follower sid: 1 : info : 127.0.0.1:11255:11260:participant;127.0.0.1:11265
2023-09-19 19:10:14,365 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.f.QuorumOracleMaj@66] - Oracle is set to /Users/kezhuw/Sources/zookeeper/zookeeper-server/target/surefire/test6919410019681875524.junit.dir/oraclePath/1/mastership/value
2023-09-19 19:10:14,365 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.QuorumPeer@1909] - Dynamic reconfig is disabled, we don't store the last seen config.
2023-09-19 19:10:14,365 [myid:] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11265)(secure=disabled):o.a.z.s.q.QuorumPeer@920] - Peer state changed: following - synchronization
2023-09-19 19:10:14,365 [myid:] - INFO  [LearnerHandler-/127.0.0.1:52225:o.a.z.s.ZKDatabase@347] - On disk txn sync enabled with snapshotSizeFactor 0.33
2023-09-19 19:10:14,365 [myid:] - INFO  [LearnerHandler-/127.0.0.1:52225:o.a.z.s.q.LearnerHandler@806] - Synchronizing with Learner sid: 1 maxCommittedLog=0x100000004 minCommittedLog=0x100000001 lastProcessedZxid=0x100000004 peerLastZxid=0x100000004
2023-09-19 19:10:14,366 [myid:] - INFO  [LearnerHandler-/127.0.0.1:52225:o.a.z.s.q.LearnerHandler@851] - Sending DIFF zxid=0x100000004 for peer sid: 1
2023-09-19 19:10:14,367 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.QuorumPeer@920] - Peer state changed: leading - synchronization
2023-09-19 19:10:14,368 [myid:] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11265)(secure=disabled):o.a.z.s.q.Learner@561] - Getting a diff from the leader 0x100000004
2023-09-19 19:10:14,368 [myid:] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11265)(secure=disabled):o.a.z.s.q.QuorumPeer@925] - Peer state changed: following - synchronization - diff
2023-09-19 19:10:14,369 [myid:] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11265)(secure=disabled):o.a.z.s.q.Learner@733] - Learner received NEWLEADER message
2023-09-19 19:10:14,369 [myid:] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11265)(secure=disabled):o.a.z.s.q.f.QuorumOracleMaj@66] - Oracle is set to /Users/kezhuw/Sources/zookeeper/zookeeper-server/target/surefire/test6919410019681875524.junit.dir/oraclePath/0/mastership/value
2023-09-19 19:10:14,369 [myid:] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11265)(secure=disabled):o.a.z.s.q.QuorumPeer@1909] - Dynamic reconfig is disabled, we don't store the last seen config.
2023-09-19 19:10:14,370 [myid:] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11265)(secure=disabled):o.a.z.s.q.QuorumPeer@925] - Peer state changed: following - synchronization
2023-09-19 19:10:14,370 [myid:] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11265)(secure=disabled):o.a.z.s.q.CommitProcessor@490] - Configuring CommitProcessor with readBatchSize -1 commitBatchSize 1
2023-09-19 19:10:14,370 [myid:] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11265)(secure=disabled):o.a.z.s.q.CommitProcessor@451] - Configuring CommitProcessor with 8 worker threads.
2023-09-19 19:10:14,370 [myid:] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11265)(secure=disabled):o.a.z.s.q.FollowerRequestProcessor@59] - Initialized FollowerRequestProcessor with zookeeper.follower.skipLearnerRequestToNextProcessor as false
2023-09-19 19:10:14,372 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.Leader@1522] - Have quorum of supporters, sids: [[1, 2]]; starting up and setting last processed zxid: 0x200000000
2023-09-19 19:10:14,372 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.Leader@1544] - Dynamic reconfig feature is disabled, skip designatedLeader calculation and reconfig processing.
2023-09-19 19:10:14,373 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.CommitProcessor@490] - Configuring CommitProcessor with readBatchSize -1 commitBatchSize 1
2023-09-19 19:10:14,373 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.CommitProcessor@451] - Configuring CommitProcessor with 8 worker threads.
2023-09-19 19:10:14,373 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.ProposalRequestProcessor@57] - zookeeper.forward_learner_requests_to_commit_processor_disabled = false
2023-09-19 19:10:14,374 [myid:] - INFO  [ProcessThread(sid:2 cport:-1)::o.a.z.s.PrepRequestProcessor@138] - PrepRequestProcessor (sid:2) started, reconfigEnabled=false
2023-09-19 19:10:14,374 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.ContainerManager@83] - Using checkIntervalMs=60000 maxPerMinute=10000 maxNeverUsedIntervalMs=0
2023-09-19 19:10:14,375 [myid:] - INFO  [QuorumPeer[myid=2](plain=127.0.0.1:11266)(secure=disabled):o.a.z.s.q.QuorumPeer@920] - Peer state changed: leading - broadcast
2023-09-19 19:10:14,375 [myid:] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11265)(secure=disabled):o.a.z.s.q.Learner@717] - Learner received UPTODATE message
2023-09-19 19:10:14,375 [myid:] - INFO  [QuorumPeer[myid=1](plain=127.0.0.1:11265)(secure=disabled):o.a.z.s.q.QuorumPeer@920] - Peer state changed: following - broadcast
2023-09-19 19:10:14,409 [myid:] - INFO  [WorkerReceiver[myid=1]:o.a.z.s.q.FastLeaderElection$Messenger$WorkerReceiver@473] - WorkerReceiver is down
2023-09-19 19:10:14,409 [myid:] - INFO  [WorkerReceiver[myid=2]:o.a.z.s.q.FastLeaderElection$Messenger$WorkerReceiver@473] - WorkerReceiver is down
2023-09-19 19:10:14,409 [myid:] - INFO  [WorkerSender[myid=1]:o.a.z.s.q.FastLeaderElection$Messenger$WorkerSender@507] - WorkerSender is down
2023-09-19 19:10:14,409 [myid:] - INFO  [WorkerReceiver[myid=3]:o.a.z.s.q.FastLeaderElection$Messenger$WorkerReceiver@473] - WorkerReceiver is down
2023-09-19 19:10:14,419 [myid:] - INFO  [WorkerSender[myid=2]:o.a.z.s.q.FastLeaderElection$Messenger$WorkerSender@507] - WorkerSender is down
2023-09-19 19:10:14,419 [myid:] - INFO  [WorkerSender[myid=3]:o.a.z.s.q.FastLeaderElection$Messenger$WorkerSender@507] - WorkerSender is down
2023-09-19 19:10:14,432 [myid:] - INFO  [LeaderConnector-/127.0.0.1:11257:o.a.z.s.q.Learner$LeaderConnector@380] - Successfully connected to leader, using address: /127.0.0.1:11257
2023-09-19 19:10:14,450 [myid:] - INFO  [LeaderConnector-/127.0.0.1:11257:o.a.z.s.q.Learner$LeaderConnector@380] - Successfully connected to leader, using address: /127.0.0.1:11257
2023-09-19 19:10:14,455 [myid:] - INFO  [QuorumPeer[myid=3](plain=127.0.0.1:11267)(secure=disabled):o.a.z.s.q.QuorumPeer@1909] - Dynamic reconfig is disabled, we don't store the last seen config.
2023-09-19 19:10:14,456 [myid:] - INFO  [LearnerHandler-/127.0.0.1:52227:o.a.z.s.ZKDatabase@347] - On disk txn sync enabled with snapshotSizeFactor 0.33
2023-09-19 19:10:14,456 [myid:] - INFO  [LearnerHandler-/127.0.0.1:52226:o.a.z.s.ZKDatabase@347] - On disk txn sync enabled with snapshotSizeFactor 0.33
2023-09-19 19:10:14,458 [myid:] - INFO  [QuorumPeer[myid=3](plain=127.0.0.1:11267)(secure=disabled):o.a.z.s.q.QuorumPeer@920] - Peer state changed: leading - synchronization
2023-09-19 19:10:14,465 [myid:] - INFO  [QuorumPeer[myid=3](plain=127.0.0.1:11267)(secure=disabled):o.a.z.s.q.Leader@1522] - Have quorum of supporters, sids: [[3, 4, 5]]; starting up and setting last processed zxid: 0x200000000
2023-09-19 19:10:14,465 [myid:] - INFO  [QuorumPeer[myid=3](plain=127.0.0.1:11267)(secure=disabled):o.a.z.s.q.Leader@1544] - Dynamic reconfig feature is disabled, skip designatedLeader calculation and reconfig processing.
2023-09-19 19:10:14,466 [myid:] - INFO  [QuorumPeer[myid=3](plain=127.0.0.1:11267)(secure=disabled):o.a.z.s.q.CommitProcessor@490] - Configuring CommitProcessor with readBatchSize -1 commitBatchSize 1
2023-09-19 19:10:14,466 [myid:] - INFO  [QuorumPeer[myid=3](plain=127.0.0.1:11267)(secure=disabled):o.a.z.s.q.CommitProcessor@451] - Configuring CommitProcessor with 8 worker threads.
2023-09-19 19:10:14,466 [myid:] - INFO  [QuorumPeer[myid=3](plain=127.0.0.1:11267)(secure=disabled):o.a.z.s.q.ProposalRequestProcessor@57] - zookeeper.forward_learner_requests_to_commit_processor_disabled = false
2023-09-19 19:10:14,469 [myid:] - INFO  [ProcessThread(sid:3 cport:-1)::o.a.z.s.PrepRequestProcessor@138] - PrepRequestProcessor (sid:3) started, reconfigEnabled=false
2023-09-19 19:10:14,469 [myid:] - INFO  [QuorumPeer[myid=3](plain=127.0.0.1:11267)(secure=disabled):o.a.z.s.ContainerManager@83] - Using checkIntervalMs=60000 maxPerMinute=10000 maxNeverUsedIntervalMs=0
2023-09-19 19:10:14,469 [myid:] - INFO  [QuorumPeer[myid=3](plain=127.0.0.1:11267)(secure=disabled):o.a.z.s.q.QuorumPeer@920] - Peer state changed: leading - broadcast

All tests are refactored to fail before apache#1988 and resist more than 100 runs locally without failure after apache#1988.

kezhuw · 2023-09-20T10:08:31Z

I ran ci twice and both failed but for different reasons(ZOOKEEPER-4746, ZOOKEEPER-4745). I think ci is not a blocker for us to go.

@anmolnar @eolivelli @maoling @symat @tisonkun Anyone available to review this pr ? It is all about test code. It already failed two recently ci actions.

anmolnar

lgtm.

tisonkun

Thank you!

)

ZOOKEEPER-2623: [ADDENDUM] Fix flaky CheckTest::testCluster

7d1a767

All tests are refactored to fail before apache#1988 and resist more than 100 runs locally without failure after apache#1988.

kezhuw closed this Sep 20, 2023

kezhuw reopened this Sep 20, 2023

ztzg force-pushed the master branch from 1c60545 to e2070be Compare October 3, 2023 12:57

anmolnar approved these changes Oct 11, 2023

View reviewed changes

This was referenced Oct 16, 2023

ZOOKEEPER-4761: CLI tool read saved clientid fail #2079

Merged

ZOOKEEPER-2623: Fix database corruption caused by quorum check #1988

Merged

tisonkun approved these changes Oct 17, 2023

View reviewed changes

tisonkun merged commit dc99bd7 into apache:master Oct 17, 2023
24 of 25 checks passed

AlphaCanisMajoris pushed a commit to AlphaCanisMajoris/zookeeper that referenced this pull request Mar 28, 2024

ZOOKEEPER-2623: [ADDENDUM] Fix flaky CheckTest::testCluster (apache#2067

f7bc5b5

)

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ZOOKEEPER-2623: [ADDENDUM] Fix flaky CheckTest::testCluster #2067

ZOOKEEPER-2623: [ADDENDUM] Fix flaky CheckTest::testCluster #2067

kezhuw commented Sep 19, 2023 •

edited

kezhuw commented Sep 20, 2023

anmolnar left a comment

tisonkun left a comment

ZOOKEEPER-2623: [ADDENDUM] Fix flaky CheckTest::testCluster #2067

ZOOKEEPER-2623: [ADDENDUM] Fix flaky CheckTest::testCluster #2067

Conversation

kezhuw commented Sep 19, 2023 • edited

Context

TLDR: The log reveals potential double leading

kezhuw commented Sep 20, 2023

anmolnar left a comment

Choose a reason for hiding this comment

tisonkun left a comment

Choose a reason for hiding this comment

kezhuw commented Sep 19, 2023 •

edited