apache / apache/bookkeeper

ReplicationWorker not work problem.

Open
#4,012 1 comment 0 reactions 0 assignees View on GitHub
type/bug
Dominant language
Java
Stars
2k
Forks
976
Avg merge
6d 15h
Merged PRs (30d)
7

Description

### Problem
In our customer prd, they found there are many repeat logs.
```
2023-06-30T01:14:01,252+0000 [ReplicationWorker] ERROR org.apache.bookkeeper.replication.ReplicationWorker - ReplicationWorker failed to replicate Ledger : 46095 for 0 number of times, so deferring the ledger lock release by 9375 msecs
2023-06-30T01:14:01,255+0000 [main-EventThread] INFO org.apache.bookkeeper.meta.ZkLedgerUnderreplicationManager - Latch countdown due to ZK event: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/ledgers/underreplication/locks
2023-06-30T01:14:01,257+0000 [ReplicationWorker] WARN org.apache.bookkeeper.client.RackawareEnsemblePlacementPolicyImpl - Failed to find 1 bookies : excludeBookies [, , ], allBookies [, , ].
2023-06-30T01:14:01,257+0000 [ReplicationWorker] WARN org.apache.bookkeeper.client.RackawareEnsemblePlacementPolicyImpl - Failed to choose a bookie: excluded [, , ], fallback to choose bookie randomly from the cluster.
2023-06-30T01:14:01,257+0000 [ReplicationWorker] WARN org.apache.bookkeeper.client.RackawareEnsemblePlacementPolicyImpl - Failed to find 1 bookies : excludeBookies [, , ], allBookies [, , ].
2023-06-30T01:14:01,257+0000 [ReplicationWorker] WARN org.apache.bookkeeper.replication.ReplicationWorker - BKNotEnoughBookiesException while replicating the fragment
org.apache.bookkeeper.client.BKException$BKNotEnoughBookiesException: Not enough non-faulty bookies available
at org.apache.bookkeeper.client.RackawareEnsemblePlacementPolicyImpl.selectRandomInternal(RackawareEnsemblePlacementPolicyImpl.java:781) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]
at org.apache.bookkeeper.client.RackawareEnsemblePlacementPolicyImpl.selectRandom(RackawareEnsemblePlacementPolicyImpl.java:698) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]
at org.apache.bookkeeper.client.RackawareEnsemblePlacementPolicyImpl.selectFromNetworkLocation(RackawareEnsemblePlacementPolicyImpl.java:587) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]
at org.apache.bookkeeper.client.RackawareEnsemblePlacementPolicy.selectFromNetworkLocation(RackawareEnsemblePlacementPolicy.java:206) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]
at org.apache.bookkeeper.client.RackawareEnsemblePlacementPolicyImpl.selectFromNetworkLocation(RackawareEnsemblePlacementPolicyImpl.java:547) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]
at org.apache.bookkeeper.client.RackawareEnsemblePlacementPolicy.selectFromNetworkLocation(RackawareEnsemblePlacementPolicy.java:227) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]
at org.apache.bookkeeper.client.RackawareEnsemblePlacementPolicyImpl.replaceBookie(RackawareEnsemblePlacementPolicyImpl.java:475) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]
at org.apache.bookkeeper.client.RackawareEnsemblePlacementPolicy.replaceBookie(RackawareEnsemblePlacementPolicy.java:120) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]
at org.apache.bookkeeper.client.BookKeeperAdmin.getReplacementBookiesByIndexes(BookKeeperAdmin.java:1088) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]
at org.apache.bookkeeper.client.BookKeeperAdmin.replicateLedgerFragment(BookKeeperAdmin.java:1137) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]
at org.apache.bookkeeper.replication.ReplicationWorker.rereplicate(ReplicationWorker.java:387) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]
at org.apache.bookkeeper.replication.ReplicationWorker.rereplicate(ReplicationWorker.java:279) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]
at org.apache.bookkeeper.replication.ReplicationWorker.run(ReplicationWorker.java:230) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[io.netty-netty-common-4.1.87.Final.jar:4.1.87.Final]
at java.lang.Thread.run(Thread.java:829) ~[?:?]
```

### For ledger 46095, we get the metadata by the bookkeeper shell
```
bin/bookkeeper shell ledgermetadata -ledgerid 46095

2023-06-30T16:19:10,233+0000 [main] INFO org.apache.bookkeeper.tools.cli.commands.client.LedgerMetaDataCommand - LedgerMetadata{formatVersion=3, ensembleSize=3, writeQuorumSize=3, ackQuorumSize=2, state=CLOSED, length=192, lastEntryId=3, digestType=CRC32, password=base64:, ensembles={0=[bookie-0:3181, bookie-2:3181, bookie-1:3181]}, customMetadata={}}
```

The ledger ensemble is {0=[bookie-0:3181, bookie-2:3181, bookie-1:3181]}, and the LAC is 3.

Then we try to read entries 0-3 from each bookie.

### Read from bookie-0:3181
```
bin/bookkeeper shell readledger -bookie bookie-0:3181 -msg -ledgerid 46095 -fe 0 -le 4
2023-06-30T09:59:09,866+0000 [BookieClientScheduler-OrderedExecutor-0-0] INFO org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand - --------- Lid=46095, Eid=0 ---------
2023-06-30T09:59:09,867+0000 [BookieClientScheduler-OrderedExecutor-0-0] INFO org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand - Data: xxx

2023-06-30T09:59:09,872+0000 [BookieClientScheduler-OrderedExecutor-0-0] INFO org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand - --------- Lid=46095, Eid=1 ---------
2023-06-30T09:59:09,873+0000 [BookieClientScheduler-OrderedExecutor-0-0] INFO org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand - Data: xxx
2023-06-30T09:59:09,874+0000 [BookieClientScheduler-OrderedExecutor-0-0] INFO org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand - --------- Lid=46095, Eid=2 ---------
2023-06-30T09:59:09,875+0000 [BookieClientScheduler-OrderedExecutor-0-0] INFO org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand - Data: xxx
2023-06-30T09:59:09,876+0000 [BookieClientScheduler-OrderedExecutor-0-0] INFO org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand - --------- Lid=46095, Eid=3 ---------
2023-06-30T09:59:09,876+0000 [BookieClientScheduler-OrderedExecutor-0-0] INFO org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand - Data: xxx
```

### Read from bookie-1:3181
```
bin/bookkeeper shell readledger -bookie bookie-1:3181 -msg -ledgerid 46095 -fe 0 -le 4

2023-06-30T09:58:50,806+0000 [BookieClientScheduler-OrderedExecutor-0-0] INFO org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand - --------- Lid=46095, Eid=0 ---------
2023-06-30T09:58:50,807+0000 [BookieClientScheduler-OrderedExecutor-0-0] INFO org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand - Data: xxx
2023-06-30T09:58:50,809+0000 [BookieClientScheduler-OrderedExecutor-0-0] INFO org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand - --------- Lid=46095, Eid=1 ---------
2023-06-30T09:58:50,810+0000 [BookieClientScheduler-OrderedExecutor-0-0] INFO org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand - Data: xxx
2023-06-30T09:58:50,811+0000 [BookieClientScheduler-OrderedExecutor-0-0] INFO org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand - --------- Lid=46095, Eid=2 ---------
2023-06-30T09:58:50,812+0000 [BookieClientScheduler-OrderedExecutor-0-0] INFO org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand - Data: xxx
2023-06-30T09:58:50,813+0000 [BookieClientScheduler-OrderedExecutor-0-0] INFO org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand - --------- Lid=46095, Eid=3 ---------
2023-06-30T09:58:50,813+0000 [BookieClientScheduler-OrderedExecutor-0-0] INFO org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand - Data: xxx
```

### Read from bookie-2:3181

```
bin/bookkeeper shell readledger -bookie bookie-2:3181 -msg -ledgerid 46095 -fe 0 -le 4
2023-06-30T09:59:24,094+0000 [main] ERROR org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand - Error future.get while reading entries from ledger 46095
java.util.concurrent.ExecutionException: org.apache.bookkeeper.client.BKException$BKNoSuchLedgerExistsException: No such ledger exists on Bookies
at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:395) ~[?:?]
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1999) ~[?:?]
at org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand.lambda$readledger$1(ReadLedgerCommand.java:215) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]
at java.util.stream.Streams$RangeLongSpliterator.forEachRemaining(Streams.java:228) ~[?:?]
at java.util.stream.LongPipeline$Head.forEach(LongPipeline.java:577) ~[?:?]
at org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand.readledger(ReadLedgerCommand.java:192) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]
at org.apache.bookkeeper.tools.cli.commands.bookie.ReadLedgerCommand.apply(ReadLedgerCommand.java:136) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]
at org.apache.bookkeeper.bookie.BookieShell$ReadLedgerEntriesCmd.runCmd(BookieShell.java:633) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]
at org.apache.bookkeeper.bookie.BookieShell$MyCommand.runCmd(BookieShell.java:237) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]
at org.apache.bookkeeper.bookie.BookieShell.run(BookieShell.java:2281) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]
at org.apache.bookkeeper.bookie.BookieShell.main(BookieShell.java:2372) ~[org.apache.bookkeeper-bookkeeper-server-4.14.7.jar:4.14.7]

```

Ledger 46095 does not exist in bookie-2:3181.

### Root cause
The config E:W:A=3:3:2, that means: "Once the entry is written to two bookies, the write request is considered successful."

So ledger 46095 just be stored at bookie-0:3181 and bookie-1:3181.

When the AutoRecovery works, it finds that ledger 46095 does not exist in bookie-2:3181, it will start the replication process to copy 46095 to a new node. However, there are only three bookies in the entire cluster [bookie-0:3181, bookie-1:3181, bookie-2:3181].

In the current logic, when selecting a new node, all ensemble bookies of the current ledger 46095 are excluded, so there are no new nodes available. That's why we see the exception message."

### Action
If there are no extra bookies available at present, we can downgrade: the node to be replaced is not down, and we can re-replicate the data to itself.

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.