apache / apache/pulsar

Broker keep logging Mark deleting an already mark-deleted position

Open
#13,788 8 comments 0 reactions 0 assignees View on GitHub
type/bug
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`:
![image](https://user-images.githubusercontent.com/5058708/149744523-da2a5d84-966c-4ac4-87fa-e35f9d69979b.png)

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

Open the contributing 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.