[Bug]Pulsar 3.0.5 Topic service unavailable due to broken ledger in __change_events system topic

[fretory]

Search before reporting

• 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.

User environment

• Broker Version: 3.0.5

• Deployment: Kubernetes with Docker

• Problem Description

We have enabled the following features in our Pulsar cluster:

systemTopicEnabled: "true"
topicLevelPoliciesEnabled: "true"

managedLedgerDefaultAckQuorum: "2"
managedLedgerDefaultEnsembleSize: "2"
managedLedgerDefaultWriteQuorum: "2"

Issue Description

After configuring some topic policies, the cluster experienced several restarts or other operations over a period of time. We confirmed that no data was manually modified in BookKeeper during this period.

Subsequently, we observed "Failed to read entries" errors on the system topic __change_events. This issue then blocked the creation of both consumers and producers, rendering the topic service unavailable.

Error messages

Unfortunately, we do not have comprehensive logs from the exact time of the incident. However, this issue has occurred multiple times recently. We will ensure to collect more detailed logs if it recurs.

Reproducing the issue

We don't have a stable way to reproduce this issue. Currently, we've observed that it occurs with a higher probability in host restart scenarios.

Additional information

Workaround

To resolve this, we followed these steps:

1. Deleted the broken ledger on the corresponding BookKeeper (BK) node.
2. After deletion, we might observe logs indicating "No such ledger exists on Metadata Server".
3. Deleted the /schemas/tenant/namespace/__change_events entry in ZooKeeper.
4. Restarted the broker.

After performing these steps, the cluster recovered.

Questions

1. What could be the root cause for the ledger of the __change_events system topic becoming corrupted?
2. It seems unreasonable that a broken ledger in __change_events leads to the entire topic service becoming unavailable. Could there be an enhancement to detect such ledger corruption and automatically reload/recreate the necessary components to prevent service disruption?

Are you willing to submit a PR?

• I'm willing to submit a PR!

[lhotari]

There are changes in this area in PR #22497 and a follow-up fix #23279. However, I'd expect that the error message would be different in that case.

[lhotari]

Could be related to #24265 and #13693, potentially addressed by apache/bookkeeper#4607

[lhotari]

Are you able to reproduce with latest 3.0.12 version of Pulsar? However, that doesn't yet contain apache/bookkeeper#4607.
There are over 500 commits between 3.0.5 and 3.0.12.

https://pulsar.apache.org/release-notes/versioned/pulsar-3.0.5/
https://pulsar.apache.org/release-notes/versioned/pulsar-3.0.6/
https://pulsar.apache.org/release-notes/versioned/pulsar-3.0.7/
https://pulsar.apache.org/release-notes/versioned/pulsar-3.0.8/
https://pulsar.apache.org/release-notes/versioned/pulsar-3.0.9/
https://pulsar.apache.org/release-notes/versioned/pulsar-3.0.10/
https://pulsar.apache.org/release-notes/versioned/pulsar-3.0.11/
https://pulsar.apache.org/release-notes/versioned/pulsar-3.0.12/

[lhotari]

We don't have a stable way to reproduce this issue. Currently, we've observed that it occurs with a higher probability in host restart scenarios.

Are you restarting BookKeeper nodes too?

[fretory]

We don't have a stable way to reproduce this issue. Currently, we've observed that it occurs with a higher probability in host restart scenarios.

Are you restarting BookKeeper nodes too?

Yes, I restarted all the physical machines where the Pulsar service was deployed. I will try the new version, or alternatively, merge the PR you mentioned into our 3.0.5 branch for testing.

[fretory]

It's happening, and the environment hasn't been restarted. So I'm confused.

2025-06-25T01:53:29,966+0000 [BookKeeperClientWorker-OrderedExecutor-3-0] ERROR org.apache.bookkeeper.proto.PerChannelBookieClien
t - Read for failed on bookie pulsar-bookie-1.pulsar-bookie.pulsar.svc.cluster.local:3181 code EIO
2025-06-25T01:53:29,966+0000 [BookKeeperClientWorker-OrderedExecutor-3-0] INFO  org.apache.bookkeeper.client.PendingReadOp - Erro
r: Error while reading ledger while reading L23 E0 from bookie: pulsar-bookie-1.pulsar-bookie.pulsar.svc.cluster.local:3181
2025-06-25T01:53:29,966+0000 [BookKeeperClientWorker-OrderedExecutor-3-0] ERROR org.apache.bookkeeper.client.PendingReadOp - Read
 of ledger entry failed: L23 E0-E0, Sent to [pulsar-bookie-1.pulsar-bookie.pulsar.svc.cluster.local:3181], Heard from [] : bitset
 = {}, Error = 'Error while reading ledger'. First unread entry is (-1, rc = null)
2025-06-25T01:53:29,966+0000 [BookKeeperClientWorker-OrderedExecutor-3-0] WARN  org.apache.pulsar.broker.service.ServerCnx - [/6.
6.152.162:47776][persistent://****/****/__change_events-partition-0][multiTopicsReader-6c94ee162f] Failed to create co
nsumer: consumerId=4552, Error while reading ledger -  ledger=23 - operation=Failed to read entry - entry=0
2025-06-25T01:53:29,966+0000 [pulsar-io-5-4] WARN  org.apache.pulsar.client.impl.ClientCnx - [id: 0x7cd76445, L:/6.6.152.162:4777
6 - R:pulsar-broker-0.pulsar-broker.pulsar.svc.cluster.local/6.6.152.162:6650] Received error from server: Error while reading le
dger -  ledger=23 - operation=Failed to read entry - entry=0
2025-06-25T01:53:29,966+0000 [pulsar-io-5-4] WARN  org.apache.pulsar.client.impl.MultiTopicsConsumerImpl - [MultiTopicsConsumer-3
2645] Failed to subscribe for topic [persistent://****/****/__change_events] in topics consumer org.apache.pulsar.clie
nt.api.PulsarClientException: {"errorMsg":"Error while reading ledger -  ledger=23 - operation=Failed to read entry - entry=0","r
eqId":4262065335649691244, "remote":"pulsar-broker-0.pulsar-broker.pulsar.svc.cluster.local/6.6.152.162:6650", "local":"/6.6.152.
162:47776"}
2025-06-25T01:53:29,966+0000 [broker-client-shared-internal-executor-7-1] WARN  org.apache.pulsar.client.impl.MultiTopicsConsumer
Impl - [MultiTopicsConsumer-32645] Failed to subscribe for topic [persistent://****/****/__change_events] in topics co
nsumer, subscribe error: org.apache.pulsar.client.api.PulsarClientException: {"errorMsg":"Error while reading ledger -  ledger=23
 - operation=Failed to read entry - entry=0","reqId":4262065335649691244, "remote":"pulsar-broker-0.pulsar-broker.pulsar.svc.clus
ter.local/6.6.152.162:6650", "local":"/6.6.152.162:47776"}
2025-06-25T01:53:29,966+0000 [broker-client-shared-internal-executor-7-1] WARN  org.apache.pulsar.client.impl.MultiTopicsConsumer
Impl - [MultiTopicsConsumer-32645] Failed to subscribe topics: org.apache.pulsar.client.api.PulsarClientException: {"errorMsg":"E
rror while reading ledger -  ledger=23 - operation=Failed to read entry - entry=0","reqId":4262065335649691244, "remote":"pulsar-
broker-0.pulsar-broker.pulsar.svc.cluster.local/6.6.152.162:6650", "local":"/6.6.152.162:47776"}, closing consumer
java.util.concurrent.CompletionException: org.apache.pulsar.client.api.PulsarClientException: {"errorMsg":"Error while reading le
dger -  ledger=23 - operation=Failed to read entry - entry=0","reqId":4262065335649691244, "remote":"pulsar-broker-0.pulsar-broke
r.pulsar.svc.cluster.local/6.6.152.162:6650", "local":"/6.6.152.162:47776"}
	at org.apache.pulsar.client.impl.ClientCnx.handleError(ClientCnx.java:792) ~[org.apache.pulsar-pulsar-client-original-v3.0.5-v
1.0.1.jar:v3.0.5-v1.0.1]
Caused by: org.apache.pulsar.client.api.PulsarClientException: {"errorMsg":"Error while reading ledger -  ledger=23 - operation=F
ailed to read entry - entry=0","reqId":4262065335649691244, "remote":"pulsar-broker-0.pulsar-broker.pulsar.svc.cluster.local/6.6.
152.162:6650", "local":"/6.6.152.162:47776"}
	at org.apache.pulsar.client.impl.ClientCnx.handleError(ClientCnx.java:793) ~[org.apache.pulsar-pulsar-client-original-v3.0.5-v
1.0.1.jar:v3.0.5-v1.0.1]
2025-06-25T01:53:29,967+0000 [broker-client-shared-internal-executor-7-1] ERROR org.apache.pulsar.broker.service.SystemTopicBased
TopicPoliciesService - [****/****] Failed to create reader on __change_events topic
java.util.concurrent.CompletionException: org.apache.pulsar.client.api.PulsarClientException: {"errorMsg":"Error while reading le
dger -  ledger=23 - operation=Failed to read entry - entry=0","reqId":4262065335649691244, "remote":"pulsar-broker-0.pulsar-broke
r.pulsar.svc.cluster.local/6.6.152.162:6650", "local":"/6.6.152.162:47776"}
	at org.apache.pulsar.client.impl.ClientCnx.handleError(ClientCnx.java:792) ~[org.apache.pulsar-pulsar-client-original-v3.0.5-v
1.0.1.jar:v3.0.5-v1.0.1]
Caused by: org.apache.pulsar.client.api.PulsarClientException: {"errorMsg":"Error while reading ledger -  ledger=23 - operation=F
ailed to read entry - entry=0","reqId":4262065335649691244, "remote":"pulsar-broker-0.pulsar-broker.pulsar.svc.cluster.local/6.6.
152.162:6650", "local":"/6.6.152.162:47776"}
	at org.apache.pulsar.client.impl.ClientCnx.handleError(ClientCnx.java:793) ~[org.apache.pulsar-pulsar-client-original-v3.0.5-v
1.0.1.jar:v3.0.5-v1.0.1]
2025-06-25T01:53:29,967+0000 [broker-client-shared-internal-executor-7-1] ERROR org.apache.pulsar.broker.service.BrokerService - 
Topic creation encountered an exception by initialize topic policies service. topic_name=persistent://****/****/topic
-partition-0 error_message={"errorMsg":"Error while reading ledger -  ledger=23 - operation=Failed to read entry - entr
y=0","reqId":4262065335649691244, "remote":"pulsar-broker-0.pulsar-broker.pulsar.svc.cluster.local/6.6.152.162:6650", "local":"/6
.6.152.162:47776"}
org.apache.pulsar.client.api.PulsarClientException: {"errorMsg":"Error while reading ledger -  ledger=23 - operation=Failed to re
ad entry - entry=0","reqId":4262065335649691244, "remote":"pulsar-broker-0.pulsar-broker.pulsar.svc.cluster.local/6.6.152.162:665
0", "local":"/6.6.152.162:47776"}

[lhotari]

Pulsar 3.0.13 release and Pulsar 4.0.6 release are now available with BookKeeper 4.16.7 and 4.17.2 which includes a fix apache/bookkeeper#4607.

[fretory]

Pulsar 3.0.13 release and Pulsar 4.0.6 release are now available with BookKeeper 4.16.7 and 4.17.2 which includes a fix apache/bookkeeper#4607.

Thanks for the update. I have some reservations about this being the root cause. I've been running the test code from that issue continuously for the past four days and haven't been able to reproduce the problem once.

I doubt this would corrupt the data and cause it to be subsequently cleaned up by the BookKeeper garbage collection thread.

    // you 
    @org.junit.jupiter.api.Test 
    public void test() throws InterruptedException {
        byte[] bytes = new byte[1024];
        while (true) {
            var buf = Unpooled.buffer(1024);
            buf.writerIndex(1024);
            if (ByteBufUtil.compare(buf, Unpooled.wrappedBuffer(bytes)) != 0) {
                System.out.println(ByteBufUtil.hexDump(buf));
            }
        }
    }

Nevertheless, I will upgrade to the new version and test it. I'll report back on the results.