Skip to content

Fix race condition in skipEntries that moves readPosition and markDeletePosition incorrectly - #1478

Merged
merlimat merged 1 commit into
apache:masterfrom
rdhabalia:invalid_range
Mar 31, 2018
Merged

Fix race condition in skipEntries that moves readPosition and markDeletePosition incorrectly#1478
merlimat merged 1 commit into
apache:masterfrom
rdhabalia:invalid_range

Conversation

@rdhabalia

@rdhabalia rdhabalia commented Mar 30, 2018

Copy link
Copy Markdown
Contributor

Motivation

If we try to skipEntries for a cursor then first it derives markDeletePosition and then asynchronously it tries to setAcknowledgedPosition where first it sets readPosition (advance the readPosition if new markDeletePosition is higher than it) and then it again calculates markDeletePosition with new individualDeletedMessages. Now, if individualDeletedMessages has been changed since last markDeletePosition is calculated then it makes markDeletePosition higher than readPosition which creates below exception and it causes failure while fetching stats of the broker.

17:37:14.186 [pulsar-web-80-5] INFO  o.a.b.mledger.impl.ManagedCursorImpl - [prop/cluster/namespace/persistent/topic] Skipping 20000000 entries on cursor TNS
17:37:32.999 [pulsar-stats-updater-73-1] ERROR o.a.p.b.s.persistent.PersistentTopic - Got exception when creating consumer stats for subscription TNS: Invalid range: (457099258:506678?457066468:227060]
:
:
21:05:33.004 [pulsar-stats-updater-73-1] ERROR o.a.p.b.s.persistent.PersistentTopic - Got exception when creating consumer stats for subscription TNS: Invalid range: (457099258:506678?457072668:177109]
java.lang.IllegalArgumentException: Invalid range: (457099258:506678?457072668:177109]
        at com.google.common.collect.Range.<init>(Range.java:366) ~[guava-15.0.jar:na]
        at com.google.common.collect.Range.create(Range.java:156) ~[guava-15.0.jar:na]
        at com.google.common.collect.Range.openClosed(Range.java:206) ~[guava-15.0.jar:na]
        at org.apache.bookkeeper.mledger.impl.ManagedCursorImpl.getNumberOfEntriesSinceFirstNotAckedMessage(ManagedCursorImpl.java:630) ~[managed-ledger-1.20.6-incubating-yahoo.jar:1.20.6-incubating-yahoo]
        at org.apache.pulsar.broker.service.persistent.PersistentSubscription.getNumberOfEntriesSinceFirstNotAckedMessage(PersistentSubscription.java:453) ~[pulsar-broker-1.20.6-incubating-yahoo.jar:1.20.6-incubating-yahoo]
        at org.apache.pulsar.broker.service.persistent.PersistentTopic.lambda$31(PersistentTopic.java:1078) ~[pulsar-broker-1.20.6-incubating-yahoo.jar:1.20.6-incubating-yahoo]
        at org.apache.pulsar.common.util.collections.ConcurrentOpenHashMap$Section.forEach(ConcurrentOpenHashMap.java:386) ~[pulsar-common-1.20.6-incubating-yahoo.jar:1.20.6-incubating-yahoo]
        at org.apache.pulsar.common.util.collections.ConcurrentOpenHashMap.forEach(ConcurrentOpenHashMap.java:160) ~[pulsar-common-1.20.6-incubating-yahoo.jar:1.20.6-incubating-yahoo]
        at org.apache.pulsar.broker.service.persistent.PersistentTopic.updateRates(PersistentTopic.java:1025) ~[pulsar-broker-1.20.6-incubating-yahoo.jar:1.20.6-incubating-yahoo]
        at org.apache.pulsar.broker.service.PulsarStats.lambda$5(PulsarStats.java:124) ~[pulsar-broker-1.20.6-incubating-yahoo.jar:1.20.6-incubating-yahoo]
        at org.apache.pulsar.common.util.collections.ConcurrentOpenHashMap$Section.forEach(ConcurrentOpenHashMap.java:386) ~[pulsar-common-1.20.6-incubating-yahoo.jar:1.20.6-incubating-yahoo]
        at org.apache.pulsar.common.util.collections.ConcurrentOpenHashMap.forEach(ConcurrentOpenHashMap.java:160) ~[pulsar-common-1.20.6-incubating-yahoo.jar:1.20.6-incubating-yahoo]
        at org.apache.pulsar.broker.service.PulsarStats.lambda$3(PulsarStats.java:122) ~[pulsar-broker-1.20.6-incubating-yahoo.jar:1.20.6-incubating-yahoo]
        at org.apache.pulsar.common.util.collections.ConcurrentOpenHashMap$Section.forEach(ConcurrentOpenHashMap.java:386) ~[pulsar-common-1.20.6-incubating-yahoo.jar:1.20.6-incubating-yahoo]
        at org.apache.pulsar.common.util.collections.ConcurrentOpenHashMap.forEach(ConcurrentOpenHashMap.java:160) ~[pulsar-common-1.20.6-incubating-yahoo.jar:1.20.6-incubating-yahoo]
        at org.apache.pulsar.broker.service.PulsarStats.lambda$0(PulsarStats.java:114) ~[pulsar-broker-1.20.6-incubating-yahoo.jar:1.20.6-incubating-yahoo]
        at org.apache.pulsar.common.util.collections.ConcurrentOpenHashMap$Section.forEach(ConcurrentOpenHashMap.java:386) ~[pulsar-common-1.20.6-incubating-yahoo.jar:1.20.6-incubating-yahoo]
        at org.apache.pulsar.common.util.collections.ConcurrentOpenHashMap.forEach(ConcurrentOpenHashMap.java:160) ~[pulsar-common-1.20.6-incubating-yahoo.jar:1.20.6-incubating-yahoo]
        at org.apache.pulsar.broker.service.PulsarStats.updateStats(PulsarStats.java:104) ~[pulsar-broker-1.20.6-incubating-yahoo.jar:1.20.6-incubating-yahoo]
        at org.apache.pulsar.broker.service.BrokerService.updateRates(BrokerService.java:756) ~[pulsar-broker-1.20.6-incubating-yahoo.jar:1.20.6-incubating-yahoo]

17:37:32.999 [pulsar-stats-updater-73-1] ERROR o.a.p.b.s.persistent.PersistentTopic - Got exception when creating consumer stats for subscription TNS: Invalid range: (457099258:506678?457066468:227060]
17:38:33.000 [pulsar-stats-updater-73-1] ERROR o.a.p.b.s.persistent.PersistentTopic - Got exception when creating consumer stats for subscription TNS: Invalid range: (457099258:506678?457066468:261560]
17:39:32.997 [pulsar-stats-updater-73-1] ERROR o.a.p.b.s.persistent.PersistentTopic - Got exception when creating consumer stats for subscription TNS: Invalid range: (457099258:506678?457066468:298060]
17:40:32.999 [pulsar-stats-updater-73-1] ERROR o.a.p.b.s.persistent.PersistentTopic - Got exception when creating consumer stats for subscription TNS: Invalid range: (457099258:506678?457066468:336560]
17:41:33.000 [pulsar-stats-updater-73-1] ERROR o.a.p.b.s.persistent.PersistentTopic - Got exception when creating consumer stats for subscription TNS: Invalid range: (457099258:506678?457066468:373560]
17:42:33.000 [pulsar-stats-updater-73-1] ERROR o.a.p.b.s.persistent.PersistentTopic - Got exception when creating consumer stats for subscription TNS: Invalid range: (457099258:506678?457066468:409060]
17:43:32.998 [pulsar-stats-updater-73-1] ERROR o.a.p.b.s.persistent.PersistentTopic - Got exception when creating consumer stats for subscription TNS: Invalid range: (457099258:506678?457066468:446560]
17:44:32.999 [pulsar-stats-updater-73-1] ERROR o.a.p.b.s.persistent.PersistentTopic - Got exception when creating consumer stats for subscription TNS: Invalid range: (457099258:506678?457066468:483560]
17:45:33.003 [pulsar-stats-updater-73-1] ERROR o.a.p.b.s.persistent.PersistentTopic - Got exception when creating consumer stats for subscription TNS: Invalid range: (457099258:506678?457066468:520560]
17:46:32.995 [pulsar-stats-updater-73-1] ERROR o.a.p.b.s.persistent.PersistentTopic - Got exception when creating consumer stats for subscription TNS: Invalid range: (457099258:506678?457066468:557060]
17:47:33.000 [pulsar-stats-updater-73-1] ERROR o.a.p.b.s.persistent.PersistentTopic - Got exception when creating consumer stats for subscription TNS: Invalid range: (457099258:506678?457066468:591560]
17:48:32.997 [pulsar-stats-updater-73-1] ERROR o.a.p.b.s.persistent.PersistentTopic - Got exception when creating consumer stats for subscription TNS: Invalid range: (457099258:506678?457066468:626560]
17:49:32.999 [pulsar-stats-updater-73-1] ERROR o.a.p.b.s.persistent.PersistentTopic - Got exception when creating consumer stats for subscription TNS: Invalid range: (457099258:506678?457066468:664560]
17:50:33.000 [pulsar-stats-updater-73-1] ERROR o.a.p.b.s.persistent.PersistentTopic - Got exception when creating consumer stats for subscription TNS: Invalid range: (457099258:506678?457066468:699360]
17:51:32.996 [pulsar-stats-updater-73-1] ERROR o.a.p.b.s.persistent.PersistentTopic - Got exception when creating consumer stats for subscription TNS: Invalid range: (457099258:506678?457066468:736560]
17:52:32.997 [pulsar-stats-updater-73-1] ERROR o.a.p.b.s.persistent.PersistentTopic - Got exception when creating consumer stats for subscription TNS: Invalid range: (457099258:506678?457066468:771560]
:

Modifications

sets readPosition in the last after calculating markDeletePosition.

Result

It fixes above exception while skipping entries.

@rdhabalia rdhabalia added the type/bug The PR fixed a bug or issue reported a bug label Mar 30, 2018
@rdhabalia rdhabalia added this to the 2.0.0-incubating milestone Mar 30, 2018
@rdhabalia rdhabalia self-assigned this Mar 30, 2018
@merlimat

merlimat commented Mar 30, 2018

Copy link
Copy Markdown
Contributor

Fix looks good, is it easy to reproduce this issue? Would it happen by having a thread acking messages and then other thread calling reset cursor?

jai1
jai1 approved these changes Mar 30, 2018
View reviewed changes

@jai1 jai1 left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice Find

@rdhabalia

rdhabalia commented Mar 30, 2018

Copy link
Copy Markdown
Contributor Author

Would it happen by having a thread acking messages and then other thread calling reset cursor?

that's correct. skipping entries and acking happens in different thread.
It's little tricky to reproduce in unit-test, but I will try or will do it in separate PR.

merlimat
merlimat approved these changes Mar 31, 2018
View reviewed changes

@merlimat merlimat left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍

@merlimat
merlimat merged commit 2eda972 into apache:master Mar 31, 2018
sschepens pushed a commit to sschepens/pulsar that referenced this pull request Sep 5, 2019
@rdhabalia @sschepens
Fix race condition in skipEntries that moves readPosition and markDel…
8407157 
…etePosition incorrectly (apache#1478)
sschepens pushed a commit to sschepens/pulsar that referenced this pull request Sep 5, 2019
@rdhabalia @sschepens
Fix race condition in skipEntries that moves readPosition and markDel…
4b4f09b 
…etePosition incorrectly (apache#1478)
@lhotari lhotari mentioned this pull request Oct 19, 2020
Closed
@sijie sijie mentioned this pull request Oct 19, 2020
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@merlimat merlimat merlimat approved these changes
@jai1 jai1 jai1 approved these changes

Assignees

@rdhabalia rdhabalia

Labels

type/bug The PR fixed a bug or issue reported a bug

Projects

None yet

Milestone

2.0.0-incubating

Development

Successfully merging this pull request may close these issues.

3 participants

@rdhabalia @merlimat @jai1