You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@pulsar.apache.org by "TakaHiR07 (via GitHub)" <gi...@apache.org> on 2024/06/14 07:41:34 UTC
[I] [Bug] Ledger can not recover with Digest Mismatch Error [pulsar]
TakaHiR07 opened a new issue, #22906:
URL: https://github.com/apache/pulsar/issues/22906
### Search before asking
- [X] I searched in the [issues](https://github.com/apache/pulsar/issues) and found nothing similar.
### Read release policy
- [X] 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, 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!
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] [Bug] Ledger can not recover with Digest Mismatch Error [pulsar]
Posted by "lhotari (via GitHub)" <gi...@apache.org>.
lhotari commented on issue #22906:
URL: https://github.com/apache/pulsar/issues/22906#issuecomment-2167909944
@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.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] [Bug] Ledger can not recover with Digest Mismatch Error [pulsar]
Posted by "TakaHiR07 (via GitHub)" <gi...@apache.org>.
TakaHiR07 commented on issue #22906:
URL: https://github.com/apache/pulsar/issues/22906#issuecomment-6514069624
> Could you check whether newly written ledgers still get corrupted on a currently supported release (4.0.x, 4.2.x or 5.0.x) with the same OOM/restart test?
The issue is no longer occur in our cluster. And I have found that https://github.com/apache/bookkeeper/pull/4293 is the most important fix for our situation.
So this issue can be closed
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] [Bug] Ledger can not recover with Digest Mismatch Error [pulsar]
Posted by "TakaHiR07 (via GitHub)" <gi...@apache.org>.
TakaHiR07 closed issue #22906: [Bug] Ledger can not recover with Digest Mismatch Error
URL: https://github.com/apache/pulsar/issues/22906
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] [Bug] Ledger can not recover with Digest Mismatch Error [pulsar]
Posted by "lhotari (via GitHub)" <gi...@apache.org>.
lhotari commented on issue #22906:
URL: https://github.com/apache/pulsar/issues/22906#issuecomment-2168209223
> @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 + 4.16.6 rc0.
There's also broker cache race condition fixes which now prevent some similar symptoms.
* #22789
* #22814
* #22818
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] [Bug] Ledger can not recover with Digest Mismatch Error [pulsar]
Posted by "lhotari (via GitHub)" <gi...@apache.org>.
lhotari commented on issue #22906:
URL: https://github.com/apache/pulsar/issues/22906#issuecomment-2167888421
> * 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](https://lists.apache.org/thread/n90zooqfhfdxm2t2okdn40f6gxxqg8zs) 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.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] [Bug] Ledger can not recover with Digest Mismatch Error [pulsar]
Posted by "merlimat (via GitHub)" <gi...@apache.org>.
merlimat commented on issue #22906:
URL: https://github.com/apache/pulsar/issues/22906#issuecomment-6381000063
Thanks for the detailed investigation, @TakaHiR07. Since this was reported, the fixes mentioned in the thread have shipped: #22892 and the BookKeeper fixes for buffer corruption on the V2 protocol path (apache/bookkeeper#4196, #4289, #4293, #4426, in BookKeeper 4.16.6 and later), and the broker cache race fixes #22789, #22814 and #22818. 3.0.x is no longer supported. Could you check whether newly written ledgers still get corrupted on a currently supported release (4.0.x, 4.2.x or 5.0.x) with the same OOM/restart test? If they do, please share the broker and bookie logs and the broker's `bookkeeperUseV2WireProtocol` and TLS settings. Ledgers that were already corrupted won't be repaired by the upgrade. If there's no update, we'll close this issue in a few weeks.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] [Bug] Ledger can not recover with Digest Mismatch Error [pulsar]
Posted by "lhotari (via GitHub)" <gi...@apache.org>.
lhotari commented on issue #22906:
URL: https://github.com/apache/pulsar/issues/22906#issuecomment-2167893586
There are also some pending Bookkeeper issues and PRs that might be related such as apache/bookkeeper#4171 and apache/bookkeeper#4194. /cc @shoothzj
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] [Bug] Ledger can not recover with Digest Mismatch Error [pulsar]
Posted by "TakaHiR07 (via GitHub)" <gi...@apache.org>.
TakaHiR07 commented on issue #22906:
URL: https://github.com/apache/pulsar/issues/22906#issuecomment-2168088487
@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.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org