ZOOKEEPER-4643, ZOOKEEPER-4646 & ZOOKEEPER-4394: Committed txns lost / NullPointerException in Learner.syncWithLeader() #2152

AlphaCanisMajoris · 2024-03-28T10:35:20Z

This fix aims to fix a bunch of issues in follower's syncWithLeader().
e.g.,
ZOOKEEPER-4394: NullPointerException when follower receives COMMIT after replying NEWLEADER ack in syncWithLeader().
Explanation: In syncWithLeader(), a follower may receive the COMMIT message after replying NEWLEADER ack. e.g., a follower receives the following messages in order:
DIFF -> PROPOSAL -> COMMIT -> PROPOSAL -> NEWLEADER -> COMMIT -> UPTODATE

NullPointerException will occur if the corresponding PROPOSAL has been processed and removed from the "packetsNotCommitted" during the follower process NEWLEADER.

To fix this, when the follower receives NEWLEADER, it does the following things in order:

take snapshot if needed;
persist and process the committed txns according to "packetsCommitted" synchronously (these txns have been committed by leader). Note that leave the outstanding proposals in "packetsNotCommitted" (not in "packetsCommitted") to be processed later;
update currentEpoch;
reply NEWLEADER ack.

After the follower replies UPTODATE ack, it persist the txns in "packetsNotCommitted" and commit the txns in "packetsCommitted" asynchronously.

Besides, this fixes some other issues in Learner.syncWithLeader():
ZOOKEEPER-3023: Flaky test: Zab1_0Test#testNormalFollowerRunWithDiff
ZOOKEEPER-4643: Committed txns lost when follower crashes after updating currentEpoch
ZOOKEEPER-4646: Committed txns lost when follower crashes after replying NEWLEADER ack
ZOOKEEPER-4685: Leader shutdown due to follower replies PROPOSAL ack before NEWLEADER ack in Synchronization phase

We have leveraged the TLA+ specifications of ZooKeeper and verified the correctness of this fix.

AlphaCanisMajoris · 2024-03-28T13:41:00Z

When the follower processes the NEWLEADER message, it only persists and processes the txns that the leader asks it to COMMIT. This guarantees no loss of committed txns because the follower syncs the leader's committed history before replying NEWLEADER ack (ZOOKEEPER-4646).

Besides, this fix removes the redundant acks for the PROPOSALs of committed txns in SYNCHRONIZATION phase. In fact, there is no need to reply PROPOSAL acks for these committed txns. Because these txns have been committed by the leader, their PROPOSAL acks are redundant for the leader (See Leader#processAck).

AlphaCanisMajoris · 2024-03-30T16:43:41Z

Analysis of #2111 and #1848:

#2111 can avoid ZOOKEEPER-4643, but it cannot fix other issues like ZOOKEEPER-4394: the NullPointerException problem when the follower receives COMMIT after replying NEWLEADER ack in syncWithLeader().

In #1848, when receiving NEWLEADER, the follower only persists and processes the packets according to "packetsCommitted". It still keeps the outstanding proposals in "packetsNotCommitted" to avoid NullPointerException when receiving COMMIT packet(s) right after replying NEWLEADER ack (ZOOKEEPER-4394).

Take #2111 and #1848 into consideration, this fix avoids a group of issues in SYNCHRONIZATION, including ZOOKEEPER-4643, ZOOKEEPER-4646, ZOOKEEPER-4685, ZOOKEEPER-4394 and the problem of flaky tests ZOOKEEPER-3023.

AlphaCanisMajoris · 2024-03-30T17:17:54Z

Add a test case: Zab1_0Test#testNormalFollowerRun_ProcessCommitInSyncAfterAckNewLeader. This checks the case when the follower receives PROPOSAL, NEWLEADER, COMMIT & UPTODATE in order during Learner.syncWithLeader().

eolivelli · 2024-03-30T18:34:48Z

One curiosity:

We have leveraged the TLA+ specifications of ZooKeeper and verified the correctness of this fix.

Who is 'we' ?
Can you share your tests?

ZOOKEEPER-4394: NullPointerException when follower receives COMMIT after replying NEWLEADER ack ZOOKEEPER-4643: Committed txns lost when follower crashes after updating currentEpoch ZOOKEEPER-4646: Committed txns lost when follower crashes after replying NEWLEADER ack ZOOKEEPER-4685: Leader shutdown due to follower replies PROPOSAL ack before NEWLEADER ack in Synchronization phase ZOOKEEPER-3023: Flaky tests: Zab1_0Test#testNormalFollowerRunWithDiff

AlphaCanisMajoris · 2024-03-31T12:39:39Z

One curiosity:

We have leveraged the TLA+ specifications of ZooKeeper and verified the correctness of this fix.

Who is 'we' ?

We are a research team dedicated to the verification of distributed systems using TLA+.
We participated in the development of the TLA+ specifications for Zab & ZooKeeper.

Based on ZooKeeper's existing specification, we refine the actions according to the code implementation to explore the possible interleaving of multi-node and multi-threading events with failures. Then we check the specification to see whether it violates some invariants (derived from Zab paper and code) with the model checker.

For example, when we specify Learner.syncWithLeader(..) in version 3.9.1, the model checking found the issue traces
of ZOOKEEPER-4643, ZOOKEEPER-4646, ZOOKEEPER-4394, ZOOKEEPER-4685 and ZOOKEEPER-3023.

When specifying Learner.syncWithLeader(..) in version 3.9.2 (fixed by #2111), the issue traces of ZOOKEEPER-4394 and ZOOKEEPER-3023 can be detected.

More details of the specifications can be found in this repo.

Can you share your tests?

We verify this fix with the TLA+ specification zk_pr_2152.

Some details in this specification: according to the fix in this PR, the logic when a follower receives NEWLEADER is specified into three actions:

FollowerProcessNEWLEADER_pr2152_1: Take snapshot if needed; persist and commit requests according to "packetsCommitted".
FollowerProcessNEWLEADER_pr2152_2: Update currentEpoch.
FollowerProcessNEWLEADER_pr2152_3: Reply NEWLEADER ack.

The verification statistics are provided here. No violation is found during the checking with various configurations.

kezhuw

+1, I have left some comments though.

Sorry for late. It has been a while since #1848(2 years) and thought on #1925(nearly 1 year) for me to bring back.

@li4wang @yisong-yue @jonmv @hanm Sorry for ping you, but would you mind take a look for this ?

kezhuw · 2024-04-01T04:09:53Z

zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/Learner.java

+                        /*
+                         * @see https://github.com/apache/zookeeper/pull/1848
+                         * Persist and process the committed txns in "packetsNotCommitted"
+                         * according to "packetsCommitted", which have been committed by


The comment is somewhat misunderstanding. The key is to log these committed ones, they are considered committed before election by the paper. All the reason we touch packetsNotCommitted here is to make sure it is not logRequest again in broadcast phase. I think it might be better to rename packetsNotCommitted to packetsNotLogged as @jeffrey-xiao did in #1930. "log" is a disk operation, "commit" is an agreement. What we want here should be "log committed txns agreed in election".

Coming into the implementation, new proposals could still be committed before NEWLEADER since LearnerHandler does not issue NEWLEADER right after these committed txns. But it does not harm us here as we are potentially to persist more but not less and new leader expect no ack for committed ones.

kezhuw · 2024-04-01T04:19:21Z

zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/Learner.java

+                         *
+                         * @see https://issues.apache.org/jira/browse/ZOOKEEPER-4394
+                         * Keep the outstanding proposals in "packetsNotCommitted" to avoid
+                         * NullPointerException when the follower receives COMMIT packet(s)


Given my comments above, then we should not clear packetsNotCommitted apparently. All txns not in packetsCommitted are proposals from new election.

kezhuw · 2024-04-01T04:38:47Z

zookeeper-server/src/test/java/org/apache/zookeeper/server/quorum/Zab1_0Test.java

-                    long start = System.currentTimeMillis();
-                    while (createSessionZxid != f.fzk.getLastProcessedZxid()
-                                   && (System.currentTimeMillis() - start) < 50) {
-                        Thread.sleep(1);


When specifying Learner.syncWithLeader(..) in version 3.9.2 (fixed by #2111), the issue traces of ZOOKEEPER-4394 and ZOOKEEPER-3023 can be detected.

I did not see ZOOKEEPER-3023 after #2111. But if you are verifying this using TLA, this is doomed to failure. I am +1 to revert this to pre ZOOKEEPER-2678.

kezhuw · 2024-04-01T04:41:30Z

zookeeper-server/src/test/java/org/apache/zookeeper/server/quorum/Zab1_0Test.java

+
+                    qp.setType(Leader.NEWLEADER);
+                    qp.setZxid(ZxidUtils.makeZxid(1, 0));
+                    oa.writeRecord(qp, null);


qp.data should be cleared.

kezhuw · 2024-04-01T04:45:34Z

zookeeper-server/src/test/java/org/apache/zookeeper/server/quorum/Zab1_0Test.java

+                    // Leader sends an outstanding proposal
+                    long proposalZxid = ZxidUtils.makeZxid(1, 1001);
+                    proposeSetData(qp, proposalZxid, "data2", 2);
+                    oa.writeRecord(qp, null);


I think it is what ZOOKEEPER-4394 tried to report. New proposals are issued before NEWLEADER. This is the gap between paper and implementation.

kezhuw · 2024-04-01T04:51:34Z

zookeeper-server/src/test/java/org/apache/zookeeper/server/quorum/Zab1_0Test.java

+                    // The outstanding proposal has not been persisted yet
+                    ZKDatabase zkDb2 = new ZKDatabase(new FileTxnSnapLog(logDir, snapDir));
+                    long lastZxid = zkDb2.loadDataBase();
+                    assertEquals("data1", new String(zkDb2.getData("/foo", stat, null)));


This seems an extra enforce to the paper. But given that we are driving the test step by step and we are testing implementation, I am +1 on this. By the paper, we should not have this problem and assertions should still hold anyway as there are no new proposals from new leader before NEWLEADER.

…hLeader(..) to make it more understandable

jonmv · 2024-04-03T06:06:27Z

Hi, this is great!

As luck would have it, I had to rebase my fork onto 3.9.2 a few weeks ago, and due to conflicts with #2111 I already reviewed that commit. My conclusion then was that the NPE this PR fixes still remained an issue, and I think there are additional fixes in #1925 related to shutdown of the ZK database/server, that would also lead to (mostly harmless) duplicate series in the transaction log.

I've dedicated some time for reviewing this PR, and will also make sure to mint a fresh PR with any outstanding fixes from #1925, in the hope that I may finally close that fork.

jonmv · 2024-04-04T11:40:18Z

I think the changes in this PR look good 👍

From what I can tell, the union of #2111, this, and #2154 (which I just opened) should together cover #1925, which is now a battle-proven patch, used by vespa.ai for the last year and a half.

AlphaCanisMajoris · 2024-04-10T13:48:51Z

Hi, @kezhuw. thanks a lot for your careful review! I've updated the code fix in this pr. Could u please take some time to check the new commit and see if there is anything else that needs improvement? Thanks!

AlphaCanisMajoris · 2024-04-11T07:58:54Z

Hi @eolivelli. Sorry for bother you, but would you mind take a look at this pr and consider merging it?

This pr fixes a bunch of issues in follower's syncWithLeader() that stay unresolved for a long time. Besides, it can drive the following fixes like #2154.
It is built based on the latest fix #2111. It has been checked by the new added test case Zab1_0Test#testNormalFollowerRun_ProcessCommitInSyncAfterAckNewLeader and the TLA+ specification verification results.

AlphaCanisMajoris force-pushed the ZK-4643 branch from dad7545 to ca51c7c Compare March 28, 2024 13:20

AlphaCanisMajoris force-pushed the ZK-4643 branch from c600496 to acb4405 Compare March 31, 2024 04:34

AlphaCanisMajoris force-pushed the ZK-4643 branch from acb4405 to cdd13ca Compare March 31, 2024 05:30

kezhuw approved these changes Apr 1, 2024

View reviewed changes

Rename "packetsNotCommitted" to "packetsNotLogged" in Learner.syncWit…

f95a261

…hLeader(..) to make it more understandable

jonmv mentioned this pull request Apr 4, 2024

Jonmv/zookeeper 4541 take 2 #2154

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ZOOKEEPER-4643, ZOOKEEPER-4646 & ZOOKEEPER-4394: Committed txns lost / NullPointerException in Learner.syncWithLeader() #2152

ZOOKEEPER-4643, ZOOKEEPER-4646 & ZOOKEEPER-4394: Committed txns lost / NullPointerException in Learner.syncWithLeader() #2152

AlphaCanisMajoris commented Mar 28, 2024 •

edited

AlphaCanisMajoris commented Mar 28, 2024 •

edited

AlphaCanisMajoris commented Mar 30, 2024 •

edited

AlphaCanisMajoris commented Mar 30, 2024

eolivelli commented Mar 30, 2024

AlphaCanisMajoris commented Mar 31, 2024

kezhuw left a comment

kezhuw Apr 1, 2024

kezhuw Apr 1, 2024

kezhuw Apr 1, 2024

kezhuw Apr 1, 2024

kezhuw Apr 1, 2024

kezhuw Apr 1, 2024

jonmv commented Apr 3, 2024

jonmv commented Apr 4, 2024

AlphaCanisMajoris commented Apr 10, 2024

AlphaCanisMajoris commented Apr 11, 2024

ZOOKEEPER-4643, ZOOKEEPER-4646 & ZOOKEEPER-4394: Committed txns lost / NullPointerException in Learner.syncWithLeader() #2152

Are you sure you want to change the base?

ZOOKEEPER-4643, ZOOKEEPER-4646 & ZOOKEEPER-4394: Committed txns lost / NullPointerException in Learner.syncWithLeader() #2152

Conversation

AlphaCanisMajoris commented Mar 28, 2024 • edited

AlphaCanisMajoris commented Mar 28, 2024 • edited

AlphaCanisMajoris commented Mar 30, 2024 • edited

AlphaCanisMajoris commented Mar 30, 2024

eolivelli commented Mar 30, 2024

AlphaCanisMajoris commented Mar 31, 2024

kezhuw left a comment

Choose a reason for hiding this comment

kezhuw Apr 1, 2024

Choose a reason for hiding this comment

kezhuw Apr 1, 2024

Choose a reason for hiding this comment

kezhuw Apr 1, 2024

Choose a reason for hiding this comment

kezhuw Apr 1, 2024

Choose a reason for hiding this comment

kezhuw Apr 1, 2024

Choose a reason for hiding this comment

kezhuw Apr 1, 2024

Choose a reason for hiding this comment

jonmv commented Apr 3, 2024

jonmv commented Apr 4, 2024

AlphaCanisMajoris commented Apr 10, 2024

AlphaCanisMajoris commented Apr 11, 2024

AlphaCanisMajoris commented Mar 28, 2024 •

edited

AlphaCanisMajoris commented Mar 28, 2024 •

edited

AlphaCanisMajoris commented Mar 30, 2024 •

edited