[Bug] Bookkeeper returns mac mismatch while reading

[KannarFr]

Search before asking

• I searched in the issues and found nothing similar.

Version

2.11.3 to 3.1.0

Minimal reproduce step

N/A

What did you expect to see?

No error

What did you see instead?

After bumped I got a lot of exceptions as:

2023-10-23T15:01:29,964+0000 [BookKeeperClientWorker-OrderedExecutor-7-0] INFO  org.apache.bookkeeper.client.PendingReadOp - Mac mismatch while reading L16702 E0 from bookie: yo-bookkeeper-c3-n3
2023-10-23T15:01:29,965+0000 [BookKeeperClientWorker-OrderedExecutor-7-0] ERROR org.apache.bookkeeper.client.PendingReadOp - Read of ledger entry failed: L16702 E0-E0, Sent to [yo-bookkeeper-c3-n14, yo-bookkeeper-c3-n3, yo-bookkeeper-c3-n7], Heard from [yo-bookkeeper-c3-n14, yo-bookkeeper-c3-n3, yo-bookkeeper-c3-n7] : bitset = {0, 1, 2}, Error = 'Entry digest does not match'. First unread entry is (-1, rc = null)
2023-10-23T15:01:29,966+0000 [main] ERROR org.apache.bookkeeper.client.BookKeeperAdmin - Error reading entry 0 from ledger 16702
org.apache.bookkeeper.client.BKException$BKDigestMatchException: Entry digest does not match
        at org.apache.bookkeeper.client.SyncCallbackUtils.finish(SyncCallbackUtils.java:83) ~[org.apache.bookkeeper-bookkeeper-server-4.16.2.jar:4.16.2]
        at org.apache.bookkeeper.client.SyncCallbackUtils$SyncReadCallback.readComplete(SyncCallbackUtils.java:229) ~[org.apache.bookkeeper-bookkeeper-server-4.16.2.jar:4.16.2]
        at org.apache.bookkeeper.client.LedgerHandle$4.onFailure(LedgerHandle.java:818) ~[org.apache.bookkeeper-bookkeeper-server-4.16.2.jar:4.16.2]
        at org.apache.bookkeeper.common.concurrent.FutureEventListener.accept(FutureEventListener.java:38) ~[org.apache.bookkeeper-bookkeeper-common-4.16.2.jar:4.16.2]
        at org.apache.bookkeeper.common.concurrent.FutureEventListener.accept(FutureEventListener.java:26) ~[org.apache.bookkeeper-bookkeeper-common-4.16.2.jar:4.16.2]
        at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863) ~[?:?]
        at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841) ~[?:?]
        at java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:482) ~[?:?]
        at org.apache.bookkeeper.common.util.SingleThreadExecutor.safeRunTask(SingleThreadExecutor.java:137) ~[org.apache.bookkeeper-bookkeeper-common-4.16.2.jar:4.16.2]
        at org.apache.bookkeeper.common.util.SingleThreadExecutor.run(SingleThreadExecutor.java:107) ~[org.apache.bookkeeper-bookkeeper-common-4.16.2.jar:4.16.2]
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[io.netty-netty-common-4.1.94.Final.jar:4.1.94.Final]
        at java.lang.Thread.run(Thread.java:833) ~[?:?]

org.apache.pulsar.broker.service.schema.exceptions.SchemaException: Entry digest does not match -  ledger=103622248 - operation=Failed to read entry - entry=0
        at org.apache.pulsar.broker.service.schema.BookkeeperSchemaStorage.bkException(BookkeeperSchemaStorage.java:711)
        at org.apache.pulsar.broker.service.schema.BookkeeperSchemaStorage$Functions.lambda$getLedgerEntry$0(BookkeeperSchemaStorage.java:655)
        at org.apache.bookkeeper.client.LedgerHandle$4.onFailure(LedgerHandle.java:818)
        at org.apache.bookkeeper.common.concurrent.FutureEventListener.accept(FutureEventListener.java:38)
        at org.apache.bookkeeper.common.concurrent.FutureEventListener.accept(FutureEventListener.java:26)
        at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
        at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
        at java.base/java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:482)
        at org.apache.bookkeeper.common.util.SingleThreadExecutor.safeRunTask(SingleThreadExecutor.java:137)
        at org.apache.bookkeeper.common.util.SingleThreadExecutor.run(SingleThreadExecutor.java:107)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:833)

Anything else?

No response

Are you willing to submit a PR?

• I'm willing to submit a PR!

[KannarFr]

I'm rollbacking brokers (only) to 2.11.

EDIT: It fixed the issue. So there is an issue with rendering on the client side on v2.11+.

[KannarFr]

A bit more context

2023-10-23T13:35:47,556+0000 [BookKeeperClientWorker-OrderedExecutor-9-0] ERROR org.apache.bookkeeper.client.PendingReadOp - Read of ledger entry failed: L103556923 E0-E0, Sent to [yo-bookkeeper-c3-n8, yo-bookkeeper-c3-n6, yo-bookkeeper-c3-n4], Heard from [yo-bookkeeper-c3-n8, yo-bookkeeper-c3-n6, yo-bookkeeper-c3-n4] : bitset = {0, 1, 2}, Error = 'Entry digest does not match'. First unread entry is (-1, rc = null)
2023-10-23T13:35:47,556+0000 [BookKeeperClientWorker-OrderedExecutor-9-0] WARN  org.apache.pulsar.broker.service.ServerCnx - [/192.168.2.5:48818][persistent://user_421c40fa-009e-433c-a93b-fc77551a2406/logs/__change_events-partition-0][multiTopicsReader-02b7f937a6] Failed to create consumer: consumerId=2104, Entry digest does not match -  ledger=103556923 - operation=Failed to read entry - entry=0

Where Read of ledger entry failed: L**103556923** E0-E0 really looks like trying to read an empty ledger.

$ bookkeeper shell ledgermetadata -ledgerid 103556923
2023-10-23T21:28:51,808+0000 [main] INFO  org.apache.bookkeeper.tools.cli.commands.client.LedgerMetaDataCommand - LedgerMetadata{formatVersion=3, ensembleSize=5, writeQuorumSize=3, ackQuorumSize=2, state=CLOSED, length=8336, lastEntryId=0, digestType=CRC32C, password=base64:, ensembles={0=[yo-bookkeeper-c3-n4, yo-bookkeeper-c3-n6, yo-bookkeeper-c3-n8, yo-bookkeeper-c3-n9, yo-bookkeeper-c3-n15]}, customMetadata={component=base64:c2NoZW1h, application=base64:cHVsc2Fy, pulsar/schemaId=base64:dXNlcl80MjFjNDBmYS0wMDllLTQzM2MtYTkzYi1mYzc3NTUxYTI0MDYvbG9ncy9fX2NoYW5nZV9ldmVudHM=}}

[miton18]

We hit the same errors on Pulsar v3.0.1

[hangc0276]

We hit the same errors on Pulsar v3.0.1

@miton18 Do you have any way to reproduce this issue?

[miton18]

We hit the same errors on Pulsar v3.0.1

@miton18 Do you have any way to reproduce this issue?

sadly, no

It happens when upgrading brokers to v3.x.x

[hangc0276]

We hit the same errors on Pulsar v3.0.1

@miton18 Do you have any way to reproduce this issue?

sadly, no

It happens when upgrading brokers to v3.x.x

Only upgrade broker, doesn't upgrade the bookie, right?

[miton18]

bookies has been upgraded to v3.1.0 without issues

[miton18]

ok, trying to read a ledger from bookkeeper itself also throw the same error...

023-10-26T09:40:26,062+0000 [main] INFO org.apache.bookkeeper.tools.cli.commands.client.LedgerMetaDataCommand - LedgerMetadata{formatVersion=3, ensembleSize=5, writeQuorumSize=3, ackQuorumSize=3, state=CLOSED, length=8336, lastEntryId=0, digestType=CRC32C, password=base64:, ensembles={0=[yo-bookkeeper-c3-n12, yo-bookkeeper-c3-n8, yo-bookkeeper-c3-n14, yo-bookkeeper-c3-n6, yo-bookkeeper-c3-n3]}, customMetadata={component=base64:c2NoZW1h, application=base64:cHVsc2Fy, pulsar/schemaId=base64:b3JnYV8yMWQ3ZjZkMy04Mzk3LTQ3ODItOWE2NS05MWVjYWMxYTQ1OTUvbG9ncy9fX2NoYW5nZV9ldmVudHM=}}

[KannarFr]

Looks fixed in 3.1.1.

[lhotari]

There are some reports on Pulsar Slack that this issue happens when bookkeeperUseV2WireProtocol=false or TLS is enabled for Bookkeeper. @hangc0276 I wonder what the possible bug fix has been if this is already fixed?

[Debashish-Mallick]

Looks fixed in 3.1.1.

@KannarFr Have you checked with 3.0.XX version. Basically Its working, if we set bookkeeperUseV2WireProtocol=true in broker configmap.

[KannarFr]

No, I didn't but should I use v2 (legacy) wire proto? I mean this can fix the issue, but this is a jump in the past, nope? :D