[Bug] Ledger can not recover with Digest Mismatch Error

[TakaHiR07]

Search before asking

• I searched in the issues and found nothing similar.

Read release policy

• I understand that unsupported versions don't get bug fixes. I will attempt to reproduce the issue on a supported version of Pulsar client and Pulsar broker.

Version

client version : 2.9.5
broker version : 3.0.5
bookie version : 4.16.5

Minimal reproduce step

We are doing perf test in pulsar new version.

use pulsar-perf to produce to a topic with 100 partitions, and simulate that broker restart frequently because of direct memory OOM.

However, after running for long time, the topic become unavailable. And we find that one partition can not recover because of digest mismatch.

We can reproduce this issue, it occurs almost every three days.

broker OOM :

topic become unavailable :

What did you expect to see?

ledger recover success.

What did you see instead?

From the broker log, we see that ledger 6877081 can not recover with digest mismatch. ledger is wrote into 3 quorums without ensemble-change, the config E-Qw-Qa is 3-3-2.

2024-06-04T12:12:17,773+0800 [BookKeeperClientWorker-OrderedExecutor-12-0] ERROR org.apache.bookkeeper.proto.checksum.DigestManager - Mac mismatch for ledger-id: 6877081, entry-id: -1
2024-06-04T12:12:17,774+0800 [BookKeeperClientWorker-OrderedExecutor-12-0] ERROR org.apache.bookkeeper.client.ReadLastConfirmedOp - Mac mismatch for ledger: 6877081, entry: -1 while reading last entry from bookie: ip3:3185
2024-06-04T12:12:17,777+0800 [BookKeeperClientWorker-OrderedExecutor-12-0] ERROR org.apache.bookkeeper.proto.checksum.DigestManager - Mac mismatch for ledger-id: 6877081, entry-id: -1
2024-06-04T12:12:17,777+0800 [BookKeeperClientWorker-OrderedExecutor-12-0] ERROR org.apache.bookkeeper.client.ReadLastConfirmedOp - Mac mismatch for ledger: 6877081, entry: -1 while reading last entry from bookie: ip1:3181
2024-06-04T12:12:17,781+0800 [BookKeeperClientWorker-OrderedExecutor-12-0] ERROR org.apache.bookkeeper.proto.checksum.DigestManager - Mac mismatch for ledger-id: 6877081, entry-id: -1
2024-06-04T12:12:17,781+0800 [BookKeeperClientWorker-OrderedExecutor-12-0] ERROR org.apache.bookkeeper.client.ReadLastConfirmedOp - Mac mismatch for ledger: 6877081, entry: -1 while reading last entry from bookie: ip2:3188

2024-06-04T12:12:17,781+0800 [BookKeeperClientWorker-OrderedExecutor-12-0] ERROR org.apache.bookkeeper.client.ReadLastConfirmedOp - While readLastConfirmed ledger: 6877081 did not hear success responses from all quorums, QuorumCoverage(e:3,w:3,a:2) = [0, 0, 0]
2024-06-04T12:12:17,781+0800 [BookKeeperClientWorker-OrderedExecutor-11-0] ERROR org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [xxx/xxx/persistent/xxxxx-partition-0] Failed to open ledger 6877081: Error while recovering ledger

We have added so many logs to trace the entry, both in broker and bookie. And we add the calculation of entry's md5, aiming to find out where the entry has been changed. The logs and description are as follows.

broker's log :

// entry-326.  broker has wrote 3 same entry into netty channel
2024-06-04T11:42:47,140+0800 [BookKeeperClientWorker-OrderedExecutor-12-0] INFO  org.apache.bookkeeper.proto.PerChannelBookieClient - wtx. lId:6877081, eId:326, rBytes:280374, ctx:ip1/ip1:3181, isAct:true
2024-06-04T11:42:47,281+0800 [pulsar-io-23-10] INFO  org.apache.bookkeeper.util.ByteBufList$Encoder - enc wte. md5:14a10e2af87517e18ae7af4fb0837b26, rBytes:24,36,280338,
2024-06-04T11:42:47,348+0800 [pulsar-io-23-19] INFO  org.apache.bookkeeper.util.ByteBufList$Encoder - enc wte. md5:14a10e2af87517e18ae7af4fb0837b26, rBytes:24,36,280338,
2024-06-04T11:42:47,431+0800 [pulsar-io-23-1] INFO  org.apache.bookkeeper.util.ByteBufList$Encoder - enc wte. md5:14a10e2af87517e18ae7af4fb0837b26, rBytes:24,36,280338,

// entry-332. only 2 encoder has wrote 2 same entry into netty channel. This is corresponding to bookie logs, two bookie has wrote 332. However, one bookie' entry is with error md5.
2024-06-04T11:42:47,264+0800 [BookKeeperClientWorker-OrderedExecutor-12-0] DEBUG org.apache.bookkeeper.proto.checksum.DigestManager - lId:6877081, eId:332, toSend.byt:288707. head.byt:36, head.cap:36, head.ind:0  data.byt:288671, data.cap:524288, data.ind:26 wrap.byt:288671, wrap.cap:524288, wrap.ind:26,
2024-06-04T11:42:47,390+0800 [pulsar-io-23-19] INFO  org.apache.bookkeeper.util.ByteBufList$Encoder - enc wte. md5:0ba0cfe0a90b0b9185bb98cf0a62fef1, rBytes:24,36,288671,
2024-06-04T11:42:47,451+0800 [pulsar-io-23-20] INFO  org.apache.bookkeeper.util.ByteBufList$Encoder - enc wte. md5:0ba0cfe0a90b0b9185bb98cf0a62fef1, rBytes:24,36,288671,


// entry-336. No encoder log.
2024-06-04T11:42:47,276+0800 [BookKeeperClientWorker-OrderedExecutor-12-0] DEBUG org.apache.bookkeeper.proto.checksum.DigestManager - lId:6877081, eId:336, toSend.byt:286996. head.byt:36, head.cap:36, head.ind:0  data.byt:286960, data.cap:1048576, data.ind:577218 wrap.byt:286960, wrap.cap:1048576, wrap.ind:577218,

// broker OOM, hang out and restart
2024-06-04T11:42:47,462+0800 [BookKeeperClientWorker-OrderedExecutor-7-0] DEBUG org.apache.bookkeeper.proto.checksum.DigestManager - lId:6877095, eId:103, toSend.byt:295125. head.byt:36, head.cap:36, head.ind:0  data.byt:295089, data.cap:2097152, data.ind:862513 wrap.byt:295089, wrap.

2024-06-04T11:43:58,125+0800 [main] INFO  org.apache.pulsar.broker.PulsarService - Starting Pulsar Broker service

ip1:3181 (bookie1)

// finally write to entry-327
2024-06-04T11:42:47,464+0800 [bookie-io-1-6] DEBUG org.apache.bookkeeper.bookie.storage.ldb.SingleDirectoryDbLedgerStorage - Add entry. 6877081@326, lac:315, rBytes:280374, isRec:false, ctx:/broker-ip:54828, isAct:true, md5:14a10e2af87517e18ae7af4fb0837b26
2024-06-04T11:42:48,110+0800 [bookie-io-1-6] DEBUG org.apache.bookkeeper.bookie.storage.ldb.SingleDirectoryDbLedgerStorage - Add entry. 6877081@327, lac:315, rBytes:276621, isRec:false, ctx:/broker-ip:54828, isAct:true, md5:4041e2e6d9db97cc87879210fed093bb

ip2:3188(bookie2)

// finally write into entry-332
2024-06-04T11:42:47,388+0800 [bookie-io-1-7] DEBUG org.apache.bookkeeper.bookie.storage.ldb.SingleDirectoryDbLedgerStorage - Add entry. 6877081@326, lac:315, rBytes:280374, isRec:false, ctx:/broker-ip:46648, isAct:true, md5:14a10e2af87517e18ae7af4fb0837b26
2024-06-04T11:42:47,390+0800 [bookie-io-1-7] DEBUG org.apache.bookkeeper.bookie.storage.ldb.SingleDirectoryDbLedgerStorage - Add entry. 6877081@327, lac:315, rBytes:276621, isRec:false, ctx:/broker-ip:46648, isAct:true, md5:4f8e094d002ca5f0c56166fd9648f679

2024-06-04T11:42:48,086+0800 [bookie-io-1-7] DEBUG org.apache.bookkeeper.bookie.storage.ldb.SingleDirectoryDbLedgerStorage - Add entry. 6877081@332, lac:315, rBytes:288707, isRec:false, ctx:/broker-ip:46648, isAct:true, md5:3fb182464e4e3ba2d286b8cd62349eab

ip3:3185(bookie3)

// finally write into entry-336
2024-06-04T11:42:47,350+0800 [bookie-io-1-4] DEBUG org.apache.bookkeeper.bookie.storage.ldb.SingleDirectoryDbLedgerStorage - Add entry. 6877081@326, lac:315, rBytes:280374, isRec:false, ctx:/broker-ip:40636, isAct:true, md5:14a10e2af87517e18ae7af4fb0837b26
2024-06-04T11:42:47,351+0800 [bookie-io-1-4] DEBUG org.apache.bookkeeper.bookie.storage.ldb.SingleDirectoryDbLedgerStorage - Add entry. 6877081@327, lac:315, rBytes:276621, isRec:false, ctx:/broker-ip:40636, isAct:true, md5:4f8e094d002ca5f0c56166fd9648f679

2024-06-04T11:42:47,403+0800 [bookie-io-1-4] DEBUG org.apache.bookkeeper.bookie.storage.ldb.SingleDirectoryDbLedgerStorage - Add entry. 6877081@332, lac:315, rBytes:288707, isRec:false, ctx:/broker-ip:40636, isAct:true, md5:0ba0cfe0a90b0b9185bb98cf0a62fef1
2024-06-04T11:42:48,978+0800 [bookie-io-1-4] DEBUG org.apache.bookkeeper.bookie.storage.ldb.SingleDirectoryDbLedgerStorage - Add entry. 6877081@336, lac:315, rBytes:286996, isRec:false, ctx:/broker-ip:40636, isAct:true, md5:ca496cb654fb638e9d883b3a58bef66f

From the above log, we find that

• entry'md5 is correct in broker. But between "broker encoder -> netty channel -> bookie", the entry's md5 become error.
• this case may occur when broker OOM and hang out and restart .

Anything else?

No response

Are you willing to submit a PR?

• I'm willing to submit a PR!

[lhotari]

• entry'md5 is correct in broker. But between "broker encoder -> netty channel -> bookie", the entry's md5 become error.

This is most likely fixed by #22892 in Pulsar and with Bookkeeper fixes apache/bookkeeper#4426, apache/bookkeeper#4196, apache/bookkeeper#4289 and apache/bookkeeper#4293. The Bookkeeper fixes are included in 4.16.6 release candidate 0 which was recently published and will be part of 4.16.6 release. We will release Pulsar 3.0.6, 3.2.4 and 3.3.1 with the fixes after the Bookkeeper release has completed.

However, after running for long time, the topic become unavailable. And we find that one partition can not recover because of digest mismatch.

Does this issue also preserve after bookie and broker restarts? In that case this matches the symptoms which should get fixed with the above fixes. Bookkeeper doesn't validate the digest when it stores data. If the data gets corrupted before storing (because of bugs), corrupted data gets stored and it seems that it requires manual intervention (or using the dangerous autoSkipNonRecoverableData setting in brokers) to skip the entries that are corrupted.

[lhotari]

There are also some pending Bookkeeper issues and PRs that might be related such as apache/bookkeeper#4171 and apache/bookkeeper#4194. /cc @shoothzj

[lhotari]

@TakaHiR07 Do you happen to use TLS between brokers and bookies? One possible workaround until Pulsar 3.0.6/3.2.4/3.3.1 is released with Bookkeeper 4.16.6 is to set bookkeeperUseV2WireProtocol=false in brokers. That would prevent one source of data corruption that is fixed in Netty 4.1.111.Final as explained in #22892.
bookkeeperUseV2WireProtocol=false works around the issue since it makes copies of buffers in bookkeeper V3 protocol serialization. Although there's V3 protocol, the usage of V2 protocol is more optimal for performance and is recommended.

[TakaHiR07]

@lhotari The issue is preserve after restart, actually data gets corrupted before storing. And we do not use TLS, but we use bookkeeperUseV2WireProtocol=true.
Maybe I will try to test again with the newest code.

[lhotari]

@lhotari The issue is preserve after restart, actually data gets corrupted before storing. And we do not use TLS, but we use bookkeeperUseV2WireProtocol=true. Maybe I will try to test again with the newest code.

Yes, Please test with recent branch-3.0 + BK 4.16.6 rc0.

There's also broker cache race condition fixes which now prevent some similar symptoms.

• [fix][ml] Fix race conditions in RangeCache #22789
• [improve][ml] RangeCache refactoring: test race conditions and prevent endless loops #22814
• [improve][ml] RangeCache refactoring follow-up: use StampedLock instead of synchronized #22818