Broker keep logging Mark deleting an already mark-deleted position
- Dominant language
- Java
- Stars
- 15.3k
- Forks
- 3.8k
- Avg merge
- 1d 14h
- Merged PRs (30d)
- 160
Description
**Describe the bug**
There is a subscription keep logging `Mark deleting an already mark-deleted position` in our production cluster.
```
[persistent://op/growth/sms_produce_b_api_0-partition-2][growth] Failed to delete message at 71317494:-1: org.apache.bookkeeper.mledger.ManagedLedgerException: java.lang.IllegalArgumentException: Mark deleting an already mark-deleted position
```
Topic `persistent://op/growth/sms_produce_b_api_0` has **3** partitions, but only `partition-2` keep logging this issue.
The `internal-stats` shows cursor's `markDeletePosition` is after the firstRange of `individuallyDeletedMessages`:

So every time handle message ack it will select the upper endpoint of the firstRange of `individuallyDeletedMessages` which is ahead of `markDeletePosition`, so a `IllegalArgumentException` will be throw at `org.apache.bookkeeper.mledger.impl.ManagedCursorImpl#setAcknowledgedPosition`.
https://github.com/apache/pulsar/blob/3acdbfe4eac79040be140b423342c28a07dc0327/managed-ledger/src/main/java/org/apache/bookkeeper/mledger/impl/ManagedCursorImpl.java#L2001-L2021
https://github.com/apache/pulsar/blob/3acdbfe4eac79040be140b423342c28a07dc0327/managed-ledger/src/main/java/org/apache/bookkeeper/mledger/impl/ManagedCursorImpl.java#L1580-L1583
Arthas watch output
```
[arthas@261046]$ watch -n 5 -e org.apache.bookkeeper.mledger.impl.ManagedCursorImpl setAcknowledgedPosition {target,params[0],target.markDeletePosition,target.name,target.ledger.name}
Press Q or Ctrl+C to abort.
Affect(class count: 2 , method count: 1) cost in 233 ms, listenerId: 18
method=org.apache.bookkeeper.mledger.impl.ManagedCursorImpl.setAcknowledgedPosition location=AtExceptionExit
ts=2022-01-17 16:54:37; [cost=0.365992ms] result=@ArrayList[
@ManagedCursorImpl[ManagedCursorImpl{ledger=op/growth/persistent/sms_produce_a_api_0-partition-2, name=growth, ackPos=71317769:-1, readPos=86445249:1465}],
@PositionImpl[71257569:341],
@PositionImpl[71317769:-1],
@String[growth],
@String[op/growth/persistent/sms_produce_a_api_0-partition-2],
]
method=org.apache.bookkeeper.mledger.impl.ManagedCursorImpl.setAcknowledgedPosition location=AtExceptionExit
ts=2022-01-17 16:54:44; [cost=0.094147ms] result=@ArrayList[
@ManagedCursorImpl[ManagedCursorImpl{ledger=op/growth/persistent/sms_produce_a_api_0-partition-2, name=growth, ackPos=71317769:-1, readPos=86445249:1466}],
@PositionImpl[71257569:341],
@PositionImpl[71317769:-1],
@String[growth],
@String[op/growth/persistent/sms_produce_a_api_0-partition-2],
]
method=org.apache.bookkeeper.mledger.impl.ManagedCursorImpl.setAcknowledgedPosition location=AtExceptionExit
ts=2022-01-17 16:54:47; [cost=0.09929ms] result=@ArrayList[
@ManagedCursorImpl[ManagedCursorImpl{ledger=op/growth/persistent/sms_produce_a_api_0-partition-2, name=growth, ackPos=71317769:-1, readPos=86445249:1467}],
@PositionImpl[71257569:341],
@PositionImpl[71317769:-1],
@String[growth],
@String[op/growth/persistent/sms_produce_a_api_0-partition-2],
]
method=org.apache.bookkeeper.mledger.impl.ManagedCursorImpl.setAcknowledgedPosition location=AtExceptionExit
ts=2022-01-17 16:54:48; [cost=0.056561ms] result=@ArrayList[
@ManagedCursorImpl[ManagedCursorImpl{ledger=op/growth/persistent/sms_produce_a_api_0-partition-2, name=growth, ackPos=71317769:-1, readPos=86445249:1468}],
@PositionImpl[71257569:341],
@PositionImpl[71317769:-1],
@String[growth],
@String[op/growth/persistent/sms_produce_a_api_0-partition-2],
]
```
I don't know how to reproduce this situation yet, please let me know if need more details.
**Additional context**
- pulsar version: `2.8.1`
- OS: `CentOS Linux release 7.9.2009 (Core)`
- kernel: `3.10.0-1160.45.1.el7.x86_64`
Contributor guide
Research direction
Start in managed-ledger/src/main/java/org/apache/bookkeeper/mledger/impl/ManagedCursorImpl.java, especially setAcknowledgedPosition and the mark-delete handling around the referenced lines. Use the reported cursor positions and internal-stats behavior to understand why an already mark-deleted position is selected. Done means the affected subscription no longer repeatedly logs IllegalArgumentException when handling acknowledgements in this state.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- java
- Domain
- distributed-systems
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 35/100