Wrong ReadLastAddConfirmed logic that can lead to data loss in client applications
- Dominant language
- Java
- Stars
- 2k
- Forks
- 976
- Avg merge
- 6d 15h
- Merged PRs (30d)
- 7
Description
**BUG REPORT**
***Describe the bug***
We have found a bug when invoking `ReadLastAddConfirmed` that may lead the Bookkeeper client to return a wrong last entry or no entries at all when querying the Bookies. This behavior goes against of what is stated in the Javadoc, as it does not return the maximum entry id for a ledger within an ensemble: https://github.com/apache/bookkeeper/blob/67a02db73d62188fc8a143bd9a37038ae770e90a/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/api/ReadHandle.java#L116
```
Obtains asynchronously the last confirmed write from a quorum of bookies. This call obtains the the last add confirmed each bookie has received for this ledger and returns the maximum.
```
Applications that rely on this method to return the actual last valid entry in a ledger may wrongly believe that a ledger is empty and discard it (e.g., rollover), thus losing data.
This is a real reproduction of the problem. Lets consider an ensemble with 3 Bookies (`pravega-bk-bookie-0`, `pravega-bk-bookie-1`, and `pravega-bk-bookie-2` in the logs) where `ensembleSize=writeQuorum=ackQuorum=3`. After storing some data in the system we induce a destructive restart in `pravega-bk-bookie-2`, meaning that its data is wiped out (but it's identity is still the same). Then, our application tries to recover its internal state reading the data stored in Bookkeeper, and the problem manifests as follows:
1. Our application tries to read from ledger 5 to recover its internal state after the failure induced in `pravega-bk-bookie-2`:
```
2021-02-17 12:29:47,741 2251502 [Thread-10239] INFO i.p.s.server.logs.DurableLog - DurableLog[1]: Starting.
```
2. To this end, the first thing it does is to ask the Bookkeeper client for the last entry of ledger 5 to start its internal recovery process with the data stored in Bookkeeper. As you can see, the metadata is correctly fetched from Zookeeper for ledger 5:
```
2021-02-17 12:29:47,750 2251511 [Thread-10234-EventThread] DEBUG o.a.b.client.MetadataUpdateLoop - UpdateLoop(ledgerId=5,loopId=6425f4c2) success
```
3. We observe parallel reads issued to the 3 Bookies in the ensemble:
```
2021-02-17 12:29:47,752 2251513 [BookKeeperClientWorker-OrderedExecutor-1-0] DEBUG o.a.b.proto.PerChannelBookieClient - Got Read response from bookie:pravega-bk-bookie-2.pravega-bk-bookie-headless.default.svc.cluster.local:3181 rc:ENOENTRY, ledger:5:entry:-1:entryLength:0
2021-02-17 12:29:47,754 2251515 [BookKeeperClientWorker-OrderedExecutor-1-0] DEBUG o.a.b.proto.PerChannelBookieClient - Got Read response from bookie:pravega-bk-bookie-1.pravega-bk-bookie-headless.default.svc.cluster.local:3181 rc:EOK, ledger:5:entry:-1:entryLength:139
2021-02-17 12:29:47,754 2251515 [BookKeeperClientWorker-OrderedExecutor-1-0] DEBUG o.a.b.proto.PerChannelBookieClient - Got Read response from bookie:pravega-bk-bookie-0.pravega-bk-bookie-headless.default.svc.cluster.local:3181 rc:EOK, ledger:5:entry:-1:entryLength:139
```
As you can see, the non-restarted Bookies are returning the right info about the last entry (`rc:EOK, ledger:5:entry:-1:entryLength:139`), whereas the restarted Bookie is returning that it has no such an entry (`rc:ENOENTRY, ledger:5:entry:-1:entryLength:0`). This scenario is expected, as we induced a destructive restart in `pravega-bk-bookie-2`.
4. Unfortunately, instead of waiting for the responses from all the Bookies and get the highest available entry in ledger 5, the Bookkeeper client returns considering only the response of the restarted Bookie. This is visible in the log message we observe:
```
2021-02-17 12:29:47,752 2251513 [BookKeeperClientWorker-OrderedExecutor-1-0] DEBUG o.a.b.client.ReadLastConfirmedOp - Read Complete with enough validResponses for ledger: 5, entry: -1
```
Which corresponds to this line: https://github.com/apache/bookkeeper/blob/67a02db73d62188fc8a143bd9a37038ae770e90a/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/ReadLastConfirmedOp.java#L144
5. From this point onwards, the client provides an error response to the client application, outputting that there is no such an entry in ledger 5 and that the last available entry is 0 (according to the restarted Bookie):
```
2021-02-17 12:29:47,757 2251518 [BookKeeperClientWorker-OrderedExecutor-1-0] DEBUG o.a.bookkeeper.client.PendingReadOp - No such entry found on bookie. L5 E1 bookie: pravega-bk-bookie-2.pravega-bk-bookie-headless.default.svc.cluster.local:3181
```
6.Then, the logic of the client application closes the ledger and performs a rollover, thus discarding the actual data being stored in the other 2 Bookies:
```
2021-02-17 12:29:47,762 2251523 [BookKeeperClientWorker-OrderedExecutor-1-0] DEBUG o.a.bookkeeper.client.PendingAddOp - Submit callback (lid:5, eid: 0). rc:0
2021-02-17 12:29:47,762 2251523 [BookKeeperClientWorker-OrderedExecutor-1-0] INFO o.a.b.client.ReadOnlyLedgerHandle - Closing recovered ledger 5 at entry 0
...
2021-02-17 12:29:47,767 2251528 [Thread-10234-EventThread] DEBUG o.a.b.client.MetadataUpdateLoop - UpdateLoop(ledgerId=5,loopId=5aab3780) success
2021-02-17 12:29:47,768 2251529 [core-7] INFO i.p.s.s.impl.bookkeeper.Ledgers - Log[1]: Fenced out Ledger Id = 5, Sequence = 1, Status = Unknown.
```
This leads the application to suffer data loss sporadically, mainly depending on the result of the race condition of reads when executing `ReadLastConfirmedOp:readEntryComplete()`.
The actual root cause of the problem is a wrong logic in `RoundRobinDistributionSchedule.RRQuorumCoverageSet:checkCovered()` used inside `ReadLastConfirmedOp:readEntryComplete()` . The current logic of this function allows it to return `true` even if only 1 Bookie in the ensemble does not contain such an entry or ledger (error codes `BKException.Code.NoSuchEntryException` or `BKException.Code.NoSuchLedgerExistsException`), irrespective of whether other Bookies in the ensemble do contain the right data or not. The bug is a combination of the wrong logic in `RoundRobinDistributionSchedule.RRQuorumCoverageSet:checkCovered()` plus the condition in `ReadLastConfirmedOp:readEntryComplete()` that uses that function to return the last entry to the client:
https://github.com/apache/bookkeeper/blob/67a02db73d62188fc8a143bd9a37038ae770e90a/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/ReadLastConfirmedOp.java#L140
Note that this may lead applications to believe that the ledger is empty when it is actually not, so causing a potential data loss if applications decide to discard that ledger.
_Important_: In fact, this bug was found and apparently fixed in this commit: https://github.com/apache/bookkeeper/commit/5e399df67c2aa1e5f228c62ba8533ca3293ab147. After having a look to the new logic introduced, it seems to fix the situation that is leading to a data loss in our testing scenario. However, by some reason, this change was (mostly) reverted in this commit: https://github.com/apache/bookkeeper/commit/f373cb5976ebca41ae036a26ba69f1c341897c08. Therefore, `master`, `branch-4.13`, `branch-4.12`, and `branch-4.11` seem to contain this bug and such potential data loss for client applications.
***To Reproduce***
We do not have a unit test yet to reproduce the problem in a standalone manner, but we normally get this error executing distributed system tests in our project (https://github.com/pravega/pravega). The concrete test that induces the failure is [this one](https://github.com/pravega/pravega/blob/master/test/system/src/test/java/io/pravega/test/system/BookieFailoverTest.java): it creates a 3 Bookie ensemble, writes some data, perform a destructive restart on one Bookie and then let the system to recover reading the data from Bookkeeper. We exercise this scenario frequently and we get data loss events in around 20% of the cases.
***Expected behavior***
The reads should wait for the responses of more Bookies, as it was proposed in commit: https://github.com/apache/bookkeeper/commit/5e399df67c2aa1e5f228c62ba8533ca3293ab147.
***Screenshots***
n/a.
***Additional context***
Consider to bring back the logic in https://github.com/apache/bookkeeper/commit/5e399df67c2aa1e5f228c62ba8533ca3293ab147 to the impacted branches.
Contributor guide
Assessment
This issue has not been assessed yet.