apache / apache/pulsar

deleteSubscription fails and leaves a dangling thread in jetty threadpool

Open
#5,383 6 comments 0 reactions 0 assignees View on GitHub
lifecycle/stale type/bug
Dominant language
Java
Stars
15.3k
Forks
3.8k
Avg merge
1d 22h
Merged PRs (30d)
142

Description

**Describe the bug**
For unknown reasons, a `deleteSubscription` call can fail and it leaves around a dangling thread in the the broker, specifically the Jetty server threadpool. If this happens too many times, the broker can start having issues as Jetty is starved of threads.

**To Reproduce**
Not sure of exactly what happens, but here appears to be what usually gets me into this state
Steps to reproduce the behavior:
1. Use `pulsar-flink` (https://github.com/streamnative/pulsar-flink) to create a subscription with the `earliest` start position
2. Have your flink app fail very quickly
3. Using jstack, noticing the danging thread waiting to delete the subscription

**Expected behavior**
The subscription deletion should either succeed or result in a proper failure that doesn't leave a dangling thread.

**Screenshots**
In the logs, this is what I see when the call fails:
```
0:51:09.507 [pulsar-web-33-3] INFO org.apache.pulsar.broker.service.persistent.PersistentSubscription - [persistent://code/gerrit-events/bridge-talent-management:ref-updated][flink-pulsar-16a30186-aa62-4c3b-b576-612da2bfbf51] Unsubscribing
00:51:09.507 [pulsar-web-33-3] INFO org.apache.pulsar.broker.service.persistent.PersistentSubscription - [persistent://code/gerrit-events/bridge-talent-management:ref-updated][flink-pulsar-16a30186-aa62-4c3b-b576-612da2bfbf51] Successfully closed subscription [ManagedCursorImpl{ledger=code/gerrit-events/persistent/bridge-talent-management%3Aref-updated, name=flink-pulsar-16a30186-aa62-4c3b-b576-612da2bfbf51, ackPos=608:-1, readPos=608:-1}]
00:51:09.508 [pulsar-web-33-3] INFO org.apache.bookkeeper.mledger.impl.MetaStoreImplZookeeper - [code/gerrit-events/persistent/bridge-talent-management%3Aref-updated] Remove consumer=flink-pulsar-16a30186-aa62-4c3b-b576-612da2bfbf51
00:51:09.510 [bookkeeper-ml-workers-OrderedExecutor-2-0] ERROR org.apache.bookkeeper.common.util.SafeRunnable - Unexpected throwable caught
java.lang.IllegalArgumentException: inconsistent range
at java.util.concurrent.ConcurrentSkipListMap$SubMap.(ConcurrentSkipListMap.java:2620) ~[?:1.8.0_212]
at java.util.concurrent.ConcurrentSkipListMap.subMap(ConcurrentSkipListMap.java:2078) ~[?:1.8.0_212]
at org.apache.bookkeeper.mledger.util.RangeCache.removeRange(RangeCache.java:132) ~[org.apache.pulsar-managed-ledger-original-2.4.1-inst2.jar:2.4.1-inst2]
at org.apache.bookkeeper.mledger.impl.EntryCacheImpl.invalidateEntries(EntryCacheImpl.java:151) ~[org.apache.pulsar-managed-ledger-original-2.4.1-inst2.jar:2.4.1-inst2]
at org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl$7.operationComplete(ManagedLedgerImpl.java:777) ~[org.apache.pulsar-managed-ledger-original-2.4.1-inst2.jar:2.4.1-inst2]
at org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl$7.operationComplete(ManagedLedgerImpl.java:765) ~[org.apache.pulsar-managed-ledger-original-2.4.1-inst2.jar:2.4.1-inst2]
at org.apache.bookkeeper.mledger.impl.MetaStoreImplZookeeper.lambda$null$13(MetaStoreImplZookeeper.java:308) ~[org.apache.pulsar-managed-ledger-original-2.4.1-inst2.jar:2.4.1-inst2]
at org.apache.bookkeeper.mledger.util.SafeRun$1.safeRun(SafeRun.java:32) ~[org.apache.pulsar-managed-ledger-original-2.4.1-inst2.jar:2.4.1-inst2]
at org.apache.bookkeeper.common.util.SafeRunnable.run(SafeRunnable.java:36) [org.apache.bookkeeper-bookkeeper-common-4.9.2.jar:4.9.2]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
```

This then results in the following thread sticking around waiting for a future to complete:
```
"pulsar-web-33-11" #95 prio=5 os_prio=0 tid=0x00007ff06a5b0000 nid=0xe2 waiting on condition [0x00007ff0048b7000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000008553c2b0> (a java.util.concurrent.CompletableFuture$Signaller)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1693)
at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3323)
at java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1729)
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1895)
at org.apache.pulsar.broker.admin.impl.PersistentTopicsBase.internalDeleteSubscription(PersistentTopicsBase.java:770)
at org.apache.pulsar.broker.admin.v2.PersistentTopics.deleteSubscription(PersistentTopics.java:535)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)

...
```

**Desktop (please complete the following information):**
Pulsar 2.4.1 on Linux

**Additional context**
It seems like there are two problems here:
1. Why the `InconsistentRange` exception happens in the first place. I think what happens here is that ` PositionImpl slowestConsumerPosition = cursors.getSlowestReaderPosition();` can return `-1` or maybe `0`, this is then out of range for the entry cache. I think this happens in cases where a topic and it's subscription never receives messages. It may only happen when using the "reader" API?. This seems like a fairly minor problem and could probably be solved by just catching that exception properly.
2. The real problem appears to be that we do an unbound `get` on a future in the web api. It seems like all `future.get` should have a timeout to prevent threads from sticking around for forever.

Contributor guide

Open the contributing guide

Research direction

Start with PersistentTopicsBase.java at internalDeleteSubscription and trace the future completion through ManagedLedgerImpl.java, EntryCacheImpl.java, and RangeCache.java. Reproduce with pulsar-flink using an earliest subscription and a quickly failing Flink app, then inspect the broker with jstack. Done means subscription deletion completes or fails cleanly without an indefinitely waiting Jetty thread, with the inconsistent-range path handled appropriately.

Written by the indexing model from the issue text.

Assessment

Tech stack
java
Domain
api, backend, 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.