When call openLedgerOp, make the timeout ex is a separate error code #3562

poorbarcode · 2022-10-20T13:14:33Z

Descriptions of the changes in this PR:

Motivation

When we execute bkClient.openLedger(ledgerId), the execution flow is as follows：

start opening the ledger
get ledger meta
read the last confirmed entry
open ledger success

If we get the correct ledgerMeta at step 2, this means that this ledger has not been deleted. If step 3 times out, we should try again to make sure the ledger exists until we get a clear response from the BK server.(High light)However, in the current implementation, the timeout exception is rewritten as a LedgerRecoveryException, making it impossible to determine whether we should retry.

Log:

Oct 17, 2022 22:54:05.818 [BookKeeperClientWorker-OrderedExecutor-16-0] ERROR org.apache.bookkeeper.client.ReadLastConfirmedOp - While readLastConfirmed ledger: 59158316 did not hear success responses from all quorums, QuorumCoverage(e:2,w:2,a:2) = [-23, -23]
Oct 17, 2022 22:54:05.818 [BookKeeperClientWorker-OrderedExecutor-16-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [order/org-217/persistent/p1010-tx] Opened ledger 59158316 for consumer order-service. rc=-10

Looking at the ledger metadata:

LedgerMetadata{formatVersion=3, ensembleSize=2, writeQuorumSize=2, ackQuorumSize=2, state=IN_RECOVERY, digestType=CRC32C, password=base64:, ensembles={0=[***:3181, ***:3181]}, customMetadata={component=***, pulsar/managed-ledger=***, pulsar/cursor=***, application=***}}

Changes

When calling openLedgerOp, do not rewritten TiemoutException as a LedgerRecoveryException
add the dependency: junit4-dataprovider
use @DataProvider to simpler the test case "testOpenLedgerRecover" & "testOpenLedgerNoRecover"

poorbarcode · 2022-10-20T13:14:53Z

ping @zymap @dlg99 @eolivelli @hangc0276 @shoothzj PTAL. Thanks.

codelipenghui · 2022-10-20T14:11:53Z

bookkeeper-server/src/test/java/org/apache/bookkeeper/client/api/BookKeeperBuildersTest.java

@@ -25,6 +25,7 @@
 import static org.junit.Assert.assertArrayEquals;
 import static org.junit.Assert.assertEquals;
 import static org.junit.Assert.fail;
+import static org.mockito.Mockito.*;


Please avoid the star import.

Already remove the star import

codelipenghui · 2022-10-20T14:14:44Z

bookkeeper-server/src/test/java/org/apache/bookkeeper/client/api/BookKeeperBuildersTest.java

+    @Test
+    public void testOpenLedgerNoRecoveryWithTimeoutEx() throws Exception {
+        mockReadEntryTimeout();
+        LedgerMetadata ledgerMetadata = generateLedgerMetadata(ensembleSize,
+                writeQuorumSize, ackQuorumSize, password, customMetadata);
+        registerMockLedgerMetadata(ledgerId, ledgerMetadata);
+        ledgerMetadata.getAllEnsembles().values().forEach(bookieAddressList -> {
+            bookieAddressList.forEach(bookieAddress -> {
+                registerMockEntryForRead(ledgerId, BookieProtocol.LAST_ADD_CONFIRMED, bookieAddress, entryData, -1);
+                registerMockEntryForRead(ledgerId, 0, bookieAddress, entryData, -1);
+            });
+        });
+        try {
+            result(newOpenLedgerOp()
+                .withPassword(ledgerMetadata.getPassword())
+                .withDigestType(DigestType.CRC32)
+                .withLedgerId(ledgerId)
+                .withRecovery(false)
+                .execute());
+            fail("Expect timeout error");
+        } catch (BKException.BKTimeoutException timeoutException) {
+            // Expect timeout error.
+        }
+        // Reset bk client.
+        resetBKClient();
+    }
+
+    @Test
+    public void testOpenLedgerRecoveryWithTimeoutEx() throws Exception {
+        mockReadEntryTimeout();
+        LedgerMetadata ledgerMetadata = generateLedgerMetadata(ensembleSize,
+                writeQuorumSize, ackQuorumSize, password, customMetadata);
+        registerMockLedgerMetadata(ledgerId, ledgerMetadata);
+
+        ledgerMetadata.getAllEnsembles().values().forEach(bookieAddressList -> {
+            bookieAddressList.forEach(bookieAddress -> {
+                registerMockEntryForRead(ledgerId, BookieProtocol.LAST_ADD_CONFIRMED, bookieAddress, entryData, -1);
+                registerMockEntryForRead(ledgerId, 0, bookieAddress, entryData, -1);
+            });
+        });
+        try {
+            result(newOpenLedgerOp()
+                .withPassword(ledgerMetadata.getPassword())
+                .withDigestType(DigestType.CRC32)
+                .withLedgerId(ledgerId)
+                .withRecovery(true)
+                .execute());
+            fail("Expect timeout error");
+        } catch (BKException.BKTimeoutException timeoutException) {
+            // Expect timeout error.
+        }
+        // Reset bk client.
+        resetBKClient();
+    }


It's better to add a data provider to reduce the duplicated code.

Already use @DataProvider to simpler the test case

hangc0276

Nice catch!

hangc0276 · 2022-10-20T15:12:08Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/client/LedgerOpenOp.java

+                            if (ex != null) {
+                                LOG.error("Ledger {} read timeout", ledgerId, ex);
+                            }
+                            openComplete(rc, null);
                        });
                    } else {
                        openComplete(bk.getReturnRc(BKException.Code.LedgerRecoveryException), null);


Do we need to close the ledgerHandle when encountering other exceptions?

Good suggestion. Already fixed

wenbingshen

@poorbarcode Good work. I have only add some minor comments. PTAL.

wenbingshen · 2022-10-21T03:31:55Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/client/LedgerOpenOp.java

+                    } else if (rc == BKException.Code.TimeoutException) {
+                        closeLedgerHandleAsync().whenComplete((r, ex) -> {
+                            if (ex != null) {
+                                LOG.error("Ledger {} read timeout", ledgerId, ex);
+                            }
+                            openComplete(rc, null);
                        });


LOG.error("Ledger {} read timeout", ledgerId, ex);

should be replaced with the following:

LOG.error("Ledger {} close failed", ledgerId, ex);

the ex is not the read timeout exception.

You are right, already fixed

wenbingshen · 2022-10-21T03:33:33Z

bookkeeper-server/src/main/java/org/apache/bookkeeper/client/LedgerOpenOp.java

                    } else {
-                        openComplete(bk.getReturnRc(BKException.Code.LedgerRecoveryException), null);
+                        closeLedgerHandleAsync().whenComplete((r, ex) -> {
+                            openComplete(bk.getReturnRc(BKException.Code.LedgerRecoveryException), null);
+                        });
                    }
                }


also need log error:

if (ex != null) { LOG.error("Ledger {} close failed", ledgerId, ex); }

Already fixed

wenbingshen

nice

hangc0276 · 2022-10-25T01:44:05Z

@poorbarcode Would you please take a look at the failed CI?
https://github.com/apache/bookkeeper/actions/runs/3294663301/jobs/5433755230

eolivelli

Lgtm

hangc0276 · 2022-10-27T01:53:15Z

@poorbarcode Would you please rebase the master? thanks.

zymap · 2022-10-27T03:10:28Z

bookkeeper-server/src/test/java/org/apache/bookkeeper/client/api/BookKeeperBuildersTest.java

@@ -331,47 +330,6 @@ public void testOpenLedgerClientClosed() throws Exception {
            .execute());
    }

-    @Test


Why remove them?

These two tests has been removed into BookKeeperBuildersOpenLedgerTest.java. see #3562 (comment)

poorbarcode · 2022-10-27T03:28:27Z

rerun failure checks

hangc0276 · 2022-10-27T05:10:32Z

@zymap Would you please help take a look? thanks.

…pache#3562) Descriptions of the changes in this PR: ### Motivation When we execute `bkClient.openLedger(ledgerId)`, the execution flow is as follows： 1. start opening the ledger 2. get ledger meta 3. read the last confirmed entry 4. open ledger success If we get the correct ledgerMeta at step 2, this means that this ledger has not been deleted. If step 3 times out, we should try again to make sure the ledger exists until we get a clear response from the BK server.(High light)However, in the current implementation, the timeout exception is rewritten as a `LedgerRecoveryException`, making it impossible to determine whether we should retry. Log: ``` Oct 17, 2022 22:54:05.818 [BookKeeperClientWorker-OrderedExecutor-16-0] ERROR org.apache.bookkeeper.client.ReadLastConfirmedOp - While readLastConfirmed ledger: 59158316 did not hear success responses from all quorums, QuorumCoverage(e:2,w:2,a:2) = [-23, -23] Oct 17, 2022 22:54:05.818 [BookKeeperClientWorker-OrderedExecutor-16-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [order/org-217/persistent/p1010-tx] Opened ledger 59158316 for consumer order-service. rc=-10 ``` Looking at the ledger metadata: ``` LedgerMetadata{formatVersion=3, ensembleSize=2, writeQuorumSize=2, ackQuorumSize=2, state=IN_RECOVERY, digestType=CRC32C, password=base64:, ensembles={0=[***:3181, ***:3181]}, customMetadata={component=***, pulsar/managed-ledger=***, pulsar/cursor=***, application=***}} ``` see also: apache/pulsar#18123 ### Changes - When calling openLedgerOp, do not rewritten `TiemoutException` as a `LedgerRecoveryException` - add the dependency: `junit4-dataprovider` - use `@DataProvider` to simpler the test case "testOpenLedgerRecover" & "testOpenLedgerNoRecover" (cherry picked from commit ef31c7a)

…3562) Descriptions of the changes in this PR: ### Motivation When we execute `bkClient.openLedger(ledgerId)`, the execution flow is as follows： 1. start opening the ledger 2. get ledger meta 3. read the last confirmed entry 4. open ledger success If we get the correct ledgerMeta at step 2, this means that this ledger has not been deleted. If step 3 times out, we should try again to make sure the ledger exists until we get a clear response from the BK server.(High light)However, in the current implementation, the timeout exception is rewritten as a `LedgerRecoveryException`, making it impossible to determine whether we should retry. Log: ``` Oct 17, 2022 22:54:05.818 [BookKeeperClientWorker-OrderedExecutor-16-0] ERROR org.apache.bookkeeper.client.ReadLastConfirmedOp - While readLastConfirmed ledger: 59158316 did not hear success responses from all quorums, QuorumCoverage(e:2,w:2,a:2) = [-23, -23] Oct 17, 2022 22:54:05.818 [BookKeeperClientWorker-OrderedExecutor-16-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [order/org-217/persistent/p1010-tx] Opened ledger 59158316 for consumer order-service. rc=-10 ``` Looking at the ledger metadata: ``` LedgerMetadata{formatVersion=3, ensembleSize=2, writeQuorumSize=2, ackQuorumSize=2, state=IN_RECOVERY, digestType=CRC32C, password=base64:, ensembles={0=[***:3181, ***:3181]}, customMetadata={component=***, pulsar/managed-ledger=***, pulsar/cursor=***, application=***}} ``` see also: apache/pulsar#18123 ### Changes - When calling openLedgerOp, do not rewritten `TiemoutException` as a `LedgerRecoveryException` - add the dependency: `junit4-dataprovider` - use `@DataProvider` to simpler the test case "testOpenLedgerRecover" & "testOpenLedgerNoRecover" (cherry picked from commit ef31c7a)

…pache#3562) Descriptions of the changes in this PR: ### Motivation When we execute `bkClient.openLedger(ledgerId)`, the execution flow is as follows： 1. start opening the ledger 2. get ledger meta 3. read the last confirmed entry 4. open ledger success If we get the correct ledgerMeta at step 2, this means that this ledger has not been deleted. If step 3 times out, we should try again to make sure the ledger exists until we get a clear response from the BK server.(High light)However, in the current implementation, the timeout exception is rewritten as a `LedgerRecoveryException`, making it impossible to determine whether we should retry. Log: ``` Oct 17, 2022 22:54:05.818 [BookKeeperClientWorker-OrderedExecutor-16-0] ERROR org.apache.bookkeeper.client.ReadLastConfirmedOp - While readLastConfirmed ledger: 59158316 did not hear success responses from all quorums, QuorumCoverage(e:2,w:2,a:2) = [-23, -23] Oct 17, 2022 22:54:05.818 [BookKeeperClientWorker-OrderedExecutor-16-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [order/org-217/persistent/p1010-tx] Opened ledger 59158316 for consumer order-service. rc=-10 ``` Looking at the ledger metadata: ``` LedgerMetadata{formatVersion=3, ensembleSize=2, writeQuorumSize=2, ackQuorumSize=2, state=IN_RECOVERY, digestType=CRC32C, password=base64:, ensembles={0=[***:3181, ***:3181]}, customMetadata={component=***, pulsar/managed-ledger=***, pulsar/cursor=***, application=***}} ``` see also: apache/pulsar#18123 ### Changes - When calling openLedgerOp, do not rewritten `TiemoutException` as a `LedgerRecoveryException` - add the dependency: `junit4-dataprovider` - use `@DataProvider` to simpler the test case "testOpenLedgerRecover" & "testOpenLedgerNoRecover" (cherry picked from commit ef31c7a)

…pache#3562) Descriptions of the changes in this PR: ### Motivation When we execute `bkClient.openLedger(ledgerId)`, the execution flow is as follows： 1. start opening the ledger 2. get ledger meta 3. read the last confirmed entry 4. open ledger success If we get the correct ledgerMeta at step 2, this means that this ledger has not been deleted. If step 3 times out, we should try again to make sure the ledger exists until we get a clear response from the BK server.(High light)However, in the current implementation, the timeout exception is rewritten as a `LedgerRecoveryException`, making it impossible to determine whether we should retry. Log: ``` Oct 17, 2022 22:54:05.818 [BookKeeperClientWorker-OrderedExecutor-16-0] ERROR org.apache.bookkeeper.client.ReadLastConfirmedOp - While readLastConfirmed ledger: 59158316 did not hear success responses from all quorums, QuorumCoverage(e:2,w:2,a:2) = [-23, -23] Oct 17, 2022 22:54:05.818 [BookKeeperClientWorker-OrderedExecutor-16-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [order/org-217/persistent/p1010-tx] Opened ledger 59158316 for consumer order-service. rc=-10 ``` Looking at the ledger metadata: ``` LedgerMetadata{formatVersion=3, ensembleSize=2, writeQuorumSize=2, ackQuorumSize=2, state=IN_RECOVERY, digestType=CRC32C, password=base64:, ensembles={0=[***:3181, ***:3181]}, customMetadata={component=***, pulsar/managed-ledger=***, pulsar/cursor=***, application=***}} ``` see also: apache/pulsar#18123 ### Changes - When calling openLedgerOp, do not rewritten `TiemoutException` as a `LedgerRecoveryException` - add the dependency: `junit4-dataprovider` - use `@DataProvider` to simpler the test case "testOpenLedgerRecover" & "testOpenLedgerNoRecover" (cherry picked from commit ef31c7a) (cherry picked from commit cee32aa)

…pache#3562) Descriptions of the changes in this PR: ### Motivation When we execute `bkClient.openLedger(ledgerId)`, the execution flow is as follows： 1. start opening the ledger 2. get ledger meta 3. read the last confirmed entry 4. open ledger success If we get the correct ledgerMeta at step 2, this means that this ledger has not been deleted. If step 3 times out, we should try again to make sure the ledger exists until we get a clear response from the BK server.(High light)However, in the current implementation, the timeout exception is rewritten as a `LedgerRecoveryException`, making it impossible to determine whether we should retry. Log: ``` Oct 17, 2022 22:54:05.818 [BookKeeperClientWorker-OrderedExecutor-16-0] ERROR org.apache.bookkeeper.client.ReadLastConfirmedOp - While readLastConfirmed ledger: 59158316 did not hear success responses from all quorums, QuorumCoverage(e:2,w:2,a:2) = [-23, -23] Oct 17, 2022 22:54:05.818 [BookKeeperClientWorker-OrderedExecutor-16-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [order/org-217/persistent/p1010-tx] Opened ledger 59158316 for consumer order-service. rc=-10 ``` Looking at the ledger metadata: ``` LedgerMetadata{formatVersion=3, ensembleSize=2, writeQuorumSize=2, ackQuorumSize=2, state=IN_RECOVERY, digestType=CRC32C, password=base64:, ensembles={0=[***:3181, ***:3181]}, customMetadata={component=***, pulsar/managed-ledger=***, pulsar/cursor=***, application=***}} ``` see also: apache/pulsar#18123 ### Changes - When calling openLedgerOp, do not rewritten `TiemoutException` as a `LedgerRecoveryException` - add the dependency: `junit4-dataprovider` - use `@DataProvider` to simpler the test case "testOpenLedgerRecover" & "testOpenLedgerNoRecover"

poorbarcode force-pushed the improve/open_ledger_op_timeout branch 2 times, most recently from 62b42f5 to 7eeb397 Compare October 20, 2022 14:05

codelipenghui reviewed Oct 20, 2022

View reviewed changes

poorbarcode mentioned this pull request Oct 20, 2022

[improve] [test] Add test to ensure that cursor data is not lost if the recover timeout fails apache/pulsar#18123

Open

4 tasks

poorbarcode requested a review from codelipenghui October 20, 2022 14:58

hangc0276 reviewed Oct 20, 2022

View reviewed changes

hangc0276 requested review from eolivelli, dlg99, merlimat and zymap and removed request for codelipenghui October 20, 2022 15:14

hangc0276 assigned poorbarcode Oct 20, 2022

hangc0276 added type/bug area/bookie release/4.14.6 release/4.15.3 labels Oct 20, 2022

hangc0276 added this to the 4.16.0 milestone Oct 20, 2022

poorbarcode requested review from hangc0276 and removed request for eolivelli, dlg99, merlimat and zymap October 20, 2022 15:30

wenbingshen requested changes Oct 21, 2022

View reviewed changes

poorbarcode requested review from wenbingshen and removed request for hangc0276 October 21, 2022 03:56

wenbingshen approved these changes Oct 21, 2022

View reviewed changes

codelipenghui approved these changes Oct 24, 2022

View reviewed changes

hangc0276 approved these changes Oct 25, 2022

View reviewed changes

poorbarcode force-pushed the improve/open_ledger_op_timeout branch from 613b36d to 0379732 Compare October 26, 2022 11:21

poorbarcode requested review from eolivelli and removed request for dlg99, merlimat and zymap October 26, 2022 11:24

eolivelli approved these changes Oct 26, 2022

View reviewed changes

poorbarcode added 8 commits October 27, 2022 10:18

When call openLedgerOp, make the timeout ex is a separate error code

9ea88ec

Use @dataProvider to simplify test code

e68a38a

remove star import

8fc63cc

fix tope

6291e59

close ledgerHandle when encountering other exceptions

07cc8da

address comment: Correct logs

dbafafd

fix ImportOrder

0152ea8

avoid add new dependency

5c31945

poorbarcode force-pushed the improve/open_ledger_op_timeout branch from 0379732 to 5c31945 Compare October 27, 2022 02:18

zymap reviewed Oct 27, 2022

View reviewed changes

codelipenghui approved these changes Oct 27, 2022

View reviewed changes

hangc0276 merged commit ef31c7a into apache:master Oct 27, 2022

poorbarcode deleted the improve/open_ledger_op_timeout branch October 27, 2022 07:17

zymap added the cherry-picked/branch-4.15 label Nov 3, 2022

hangc0276 added the cherry-picked/branch-4.14 label Nov 7, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

When call openLedgerOp, make the timeout ex is a separate error code #3562

When call openLedgerOp, make the timeout ex is a separate error code #3562

poorbarcode commented Oct 20, 2022 •

edited

Loading

poorbarcode commented Oct 20, 2022

codelipenghui Oct 20, 2022

poorbarcode Oct 20, 2022

codelipenghui Oct 20, 2022

poorbarcode Oct 20, 2022

poorbarcode Oct 20, 2022

hangc0276 left a comment

hangc0276 Oct 20, 2022

poorbarcode Oct 20, 2022

wenbingshen left a comment

wenbingshen Oct 21, 2022

poorbarcode Oct 21, 2022

wenbingshen Oct 21, 2022

poorbarcode Oct 21, 2022

wenbingshen left a comment

hangc0276 commented Oct 25, 2022

eolivelli left a comment

hangc0276 commented Oct 27, 2022

zymap Oct 27, 2022

codelipenghui Oct 27, 2022

poorbarcode Oct 27, 2022

poorbarcode commented Oct 27, 2022

hangc0276 commented Oct 27, 2022

When call openLedgerOp, make the timeout ex is a separate error code #3562

When call openLedgerOp, make the timeout ex is a separate error code #3562

Conversation

poorbarcode commented Oct 20, 2022 • edited Loading

Motivation

Changes

poorbarcode commented Oct 20, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

hangc0276 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

wenbingshen left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

wenbingshen left a comment

Choose a reason for hiding this comment

hangc0276 commented Oct 25, 2022

eolivelli left a comment

Choose a reason for hiding this comment

hangc0276 commented Oct 27, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

poorbarcode commented Oct 27, 2022

hangc0276 commented Oct 27, 2022

poorbarcode commented Oct 20, 2022 •

edited

Loading