deleteSubscription fails and leaves a dangling thread in jetty threadpool
- 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
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