apache / apache/pulsar

[Bug][broker] cursor recover to earliest by mistake

Open
#17,812 3 comments 0 reactions 0 assignees View on GitHub
Stale type/bug
Dominant language
Java
Stars
15.3k
Forks
3.8k
Avg merge
1d 14h
Merged PRs (30d)
160

Description

### Search before asking

- [X] I searched in the [issues](https://github.com/apache/pulsar/issues) and found nothing similar.

### Version

server version : pulsar 2.9.3
client version: go client, github.com/Shopify/sarama v1.26.1

### Minimal reproduce step

Our pulsar cluster has large number of producers and consumers. When we do cluster expansion, topic start unload/load.

However, we found that only one group recover cursor to earliest by mistake, the other is correct. All the go client behaviour is the same, it should continue consume from the last consumed offset, shouldn't occur consume from earliest.

The cursor backlog is shown as follow.

![企业微信截图_91711635-9603-46ae-baf8-af85196fdbb3](https://user-images.githubusercontent.com/13505225/191889499-ccb9d1a0-6863-428e-8393-57e7b844dcac.png)

The server log is shown as follow. Sorry for masking topic and group because it contain sensitive information.

I think the ledgerId:22616096 is the actual offset need to recover, but the ledgerId:22254044 is the earliest position. Both the two ledger seems not exist because I can not get them from zk path /ledgers/00/2261/L6096 and /ledgers/00/2225/L4044.

Is it the cursor would recover to earliest once the ledger is not exist ? If true, it is improper.

```
11:18:02.167 [pulsar-io-4-29] INFO org.apache.pulsar.broker.service.ServerCnx - Subscribing on topic xxx / xxx
11:18:02.179 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [xxx] Loading cursor xxx
11:18:02.179 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [xxx] Recovering from bookkeeper ledger cursor: xxx
11:18:02.179 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [xxx] Consumer xxx meta-data recover from ledger 22616096

11:18:02.187 [main-EventThread] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [xxx] Opened ledger xxx. rc=0
11:18:02.202 [BookKeeperClientWorker-OrderedExecutor-12-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [xxx] Cursor xxx recovered to position 22254044:166985

11:18:02.205 [broker-topic-workers-OrderedScheduler-4-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [xxx-xxx] Rewind from 22254044:166986 to 22254044:166986
11:18:02.208 [broker-topic-workers-OrderedScheduler-4-0] INFO org.apache.pulsar.broker.service.persistent.PersistentTopic - [xxx][xxx] Created new subscription for 474
11:18:02.208 [broker-topic-workers-OrderedScheduler-4-0] INFO org.apache.pulsar.broker.service.ServerCnx - Created subscription on topic xxx / xxx

11:18:17.383 [BookKeeperClientWorker-OrderedExecutor-18-0] INFO org.apache.bookkeeper.mledger.impl.MetaStoreImpl - [xxx] [xxx] Updating cursor info ledgerId=22626176 mark-delete=22254044:166985
11:18:17.384 [bookkeeper-ml-scheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [xxx] Updated cursor xxx with ledger id 22626176 md-position=22254044:166985 rd-position=22256398:19705
11:18:17.408 [BookKeeperClientWorker-OrderedExecutor-12-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [xxx][xxx] Successfully closed & deleted ledger 22616096 in cursor

11:22:04.872 [pulsar-msg-expiry-monitor-25-1] INFO org.apache.pulsar.broker.service.persistent.PersistentMessageExpiryMonitor - [xxx][xxx] Starting message expiry check, ttl= 259200 seconds
```

### What did you expect to see?

cursor should recover to correct consumed offset.

### What did you see instead?

cursor do not recover to last consumed position, but recover to earliest

### Anything else?

_No response_

### Are you willing to submit a PR?

- [ ] I'm willing to submit a PR!

Contributor guide

Open the contributing guide

Research direction

Begin at ManagedCursorImpl recovery and ManagedLedgerImpl loading, using the unload/load reproduction and ledger IDs in the logs. Trace why recovery returns 22254044 rather than the last consumed offset, checking the cursor metadata and referenced /ledgers paths; done means the cursor resumes at the correct consumed position after reload.

Written by the indexing model from the issue text.

Assessment

Tech stack
go, java
Domain
backend, distributed-systems
Issue type
Bug
Difficulty
5/5
Estimated time
Over a week
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
20/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.