'No such ledger exists on Bookies' exceptions after updating from 2.9.2 to 2.10.4

[dmercuriali]

Hi,

After updating pulsar from 2.9.2 to 2.10.4, new messages seems to be stored in a wrong ledger.

(This will be a long post, sorry)

Staging environment infos
Pulsar from 2.9.2 to 2.10.4
Netty from 4.1.74.Final to 4.1.86.Final
Bookkeeper 4.14.4 (unchanged)
Zookeeper 3.8.0 (unchanged)

Cluster made of:

• 3 zk nodes
• 3 pulsar brokers
• 3 bookies

Messages inserts are done with the Producer api, while topic reads are done with the Reader api (and we store the last processed messageid on the DB).

I can't find the root of the problem but I think it's something related to the ManagedLedgers.

I've taken the topic 'idc9169/ns/events' as an examble.
On the DB we have this last MessageId: 69484988:47:-1:0

When I try to produce some messages, no exception is thrown and the returned message ids looks like this: 11298:0:-1:0. The ledgerId is way lower than the one on DB.
Searching for the two ledgers with the bk cli or bkvm I'm able to find the ledger 69484988, but not the "new" 11298.

Infos on the 69484988

Ledger 69484988
Cluster: default
idc9169/ns/persistent/events
Age: 9196 minutes
Created at: 21/4/2023, 09:09:38
State: CLOSED
Ensemble size: 2 (number of bookies)
WriteQuorumSize: 2 (number of copies)
AckQuorumSize: 2
Size: 26.91 KB
LastEntryId: 47
Password:
DigestType: CRC32C
Closed: true
MetadataFormatVersion: 3
component: managed-ledger
pulsar/managed-ledger: idc9169/ns/persistent/events 

ManagedLedger info returned from /admin/v2/persistent/idc9169/ns/events/internal-info:

{
    "version": 1930,
    "creationDate": "2022-02-03T12:24:18.084+01:00",
    "modificationDate": "2023-04-27T14:34:06.209+02:00",
    "ledgers": [
        {
            "ledgerId": 10371,
            "entries": 39,
            "size": 12374,
            "isOffloaded": false
        },
        {
            "ledgerId": 10681,
            "entries": 1,
            "size": 95,
            "isOffloaded": false
        },
        {
            "ledgerId": 10862,
            "entries": 9,
            "size": 6557,
            "isOffloaded": false
        },
        {
            "ledgerId": 11298,
            "isOffloaded": false
        },
        {
            "ledgerId": 69482672,
            "entries": 39,
            "size": 8153,
            "isOffloaded": false
        },
        {
            "ledgerId": 69483268,
            "entries": 1,
            "size": 224,
            "isOffloaded": false
        },
        {
            "ledgerId": 69483284,
            "entries": 9,
            "size": 2016,
            "isOffloaded": false
        }
    ],
    "cursors": {}
}

In the ManagedLedgerImpl.log I see

23-04-27-14-34-06	Opening managed ledger idc9169/ns/persistent/events
23-04-27-14-34-06	Opening managed ledger idc9169/ns/persistent/__change_events
23-04-27-14-34-06	[idc9169/ns/persistent/events] Ledger not found: 69483934
23-04-27-14-34-06	[idc9169/ns/persistent/events] Creating ledger, metadata: {application=[B@6acf8b7a, component=[B@1f598c1e, pulsar/managed-ledger=[B@6e6a9032} - metadata ops timeout : 60 seconds
23-04-27-14-34-06	[idc9169/ns/persistent/__change_events] Creating ledger, metadata: {application=[B@6acf8b7a, component=[B@1f598c1e, pulsar/managed-ledger=[B@6c91f57f} - metadata ops timeout : 60 seconds
23-04-27-14-34-06	[idc9169/ns/persistent/events] Created ledger 11298
23-04-27-14-34-06	[idc9169/ns/persistent/__change_events] Created ledger 11301
23-04-27-14-34-06	[idc9169/ns/persistent/events] Opened new cursor: NonDurableCursorImpl{ledger=idc9169/ns/persistent/events, ackPos=10862:8, readPos=10862:9}
23-04-27-14-34-06	[idc9169/ns/persistent/events] Deleted empty ledger ledgerId=11029 rc=0
23-04-27-14-34-06	[idc9169/ns/persistent/__change_events] Loading cursor __compaction
23-04-27-14-34-06	[idc9169/ns/persistent/__change_events] Deleted empty ledger ledgerId=10861 rc=0
23-04-27-14-34-06	[idc9169/ns/persistent/__change_events] Recovery for cursor __compaction completed. pos=11301:-1 -- todo=0
23-04-27-14-34-23	[idc9169/ns/persistent/events] Opened new cursor: NonDurableCursorImpl{ledger=idc9169/ns/persistent/events, ackPos=10862:8, readPos=10862:9}

So it looks like the ledger creation was fine, the messages were written, but then I can't find the new ledger on the bookies.

Also note that here a new legder for the __change_events topic is created, but calling /admin/v2/persistent/idc9169/ns/events/stats?getPreciseBacklog=true&subscriptionBacklogSize=false&getEarliestTimeInBacklog=false results in

23-04-27-16-56-57	10.168.10.117 - - [27/Apr/2023:16:56:57 +0200] "GET /admin/v2/persistent/idc9169/ns/events/stats?getPreciseBacklog=true&subscriptionBacklogSize=false&getEarliestTimeInBacklog=false HTTP/1.1" 200 2393 "-" "Pulsar-Java-v2.10.4" 4
23-04-27-16-56-57	Create topic policies system topic client persistent://idc9169/ns/__change_events
23-04-27-16-56-57	[/10.168.10.118:38490] Subscribing on topic persistent://idc9169/ns/__change_events / reader-0fca2661ab
23-04-27-16-56-57	[/10.168.10.118:38490][persistent://idc9169/ns/__change_events][reader-0fca2661ab] Failed to create consumer: consumerId=696, No such ledger exists on Metadata Server -  ledger=69058818 - operation=Failed to open ledger
23-04-27-16-56-57	[persistent://idc9169/ns/__change_events][reader-0fca2661ab] Failed to subscribe to topic on sviluppo07-cs7.sviluppo.dna/10.168.10.118:6650
23-04-27-16-56-57	[persistent://idc9169/ns/__change_events] [reader-0fca2661ab] Could not get connection to broker: {"errorMsg":"No such ledger exists on Metadata Server -  ledger=69058818 - operation=Failed to open ledger","reqId":2478662800353164782, "remote":"sviluppo07-cs7.sviluppo.dna/10.168.10.118:6650", "local":"/10.168.10.118:38490"} -- Will try again in 0.1 s

It's trying to read from ledger 69058818 but fails
The ledger 69058818 exists on bk and on zk

Ledger 69058818
Cluster: default
idc9169/ns/__change_events
Age: 397618 minutes
Created at: 25/7/2022, 15:56:03
State: CLOSED
Ensemble size: 2 (number of bookies)
WriteQuorumSize: 2 (number of copies)
AckQuorumSize: 2
Size: 7.2 KB
LastEntryId: 0
Password:
DigestType: CRC32C
Closed: true
MetadataFormatVersion: 3
component: schema
application: pulsar
pulsar/schemaId: idc9169/ns/__change_events 

I similar error is returned by admin/v2/persistent/idc9169/ns/events/lastMessageId -> 500 No such ledger exists on Bookies

In the PulsarRegistrationClient logs I see the right bookies (all writable).

I'm not sure what else to look for, any ideas?

Thanks to anyone willing to read all this.

[eolivelli]

"__change_events" is a new "system" topic that is automatically created for every namespace.

Please ensure that you have enabled "system topics" in your broker configuration

@BewareMyPower would you please take a look ?

[dmercuriali]

Yes it's enabled. To be sure I checked with /admin/v2/brokers/configuration/runtime:
"systemTopicEnabled":"true"
systemTopicSchemaCompatibilityStrategy":"ALWAYS_COMPATIBLE"

[BewareMyPower]

I didn't have any clue for it at the moment. Maybe we need to check the ZK nodes.

[dmercuriali]

Sorry for the delay, we had to move some staging environments and I can't reproduce the problem on the new one. We are recovering the old env.
Could it be something related to the age of the topic? On our old staging/production env we have some old tenants/topics, originally created with pulsar 2.6.3

About the ZK nodes, what should I look for? With the zkCli I can get the ledger info (/ledgers/.../<ledgerid>) in a somewhat readable format, but the /managed-ledgers/<tenant>/<ns>/persistent/<topic> seems a byte array. Is there an utility in pulsar to get the ZK node content in a readable format?

[aluccaroni]

@BewareMyPower let us known which info we need to extract

[BewareMyPower]

Sorry I didn't think of anything helpful at the moment. I think you can open an issue or send an email to let more people know.