Broker Shutdown while unloading bundles about pulsar

[merlimat]

Uhm, this smells like a deadlock in latest master code.. Can you take a jstack of the broker process (before it restarts itself) and attach it here?

[merlimat]

Can you also share which configuration you have modified from default ?

There should be no need to set loadBalancerAutoBundleSplitEnabled=true for the load balancer to work. That flag is to control whether to dynamically split bundles based on load, but the load balancer works event without that.

[lovelle]

Hi Matteo.

Here is jstack from broker just a moment before shutdown: jstack_broker.txt

The parameters we have changed in brokers are:

brokerDeleteInactiveTopicsEnabled=false
maxUnackedMessagesPerConsumer=1000000
managedLedgerDefaultEnsembleSize=3
managedLedgerDefaultWriteQuorum=3
loadBalancerPlacementStrategy=weightedRandomSelection
loadBalancerReportUpdateMaxIntervalMinutes=5
loadBalancerSheddingIntervalMinutes=15
loadBalancerAutoBundleSplitEnabled=true
managedLedgerCacheSizeMB=4096

We are aware that broker should balance fine without loadBalancerAutoBundleSplitEnabled enabled, but we were testing all features that seemed to fit our requirements for production env.

Thanks for your help.
Bye.

[merlimat]

Ok, we could see the problem from the jstack. This is the thread that is deadlocking itself :

"main-EventThread" #21 daemon prio=5 os_prio=0 tid=0x00007f7ee0eae000 nid=0x34 waiting on condition [0x00007f7e4bffe000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000c6f087e8> (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 com.github.benmanes.caffeine.cache.LocalAsyncLoadingCache$LoadingCacheView.get(LocalAsyncLoadingCache.java:383)
    at com.yahoo.pulsar.common.naming.NamespaceBundleFactory.getBundles(NamespaceBundleFactory.java:130)
    at com.yahoo.pulsar.broker.namespace.NamespaceService.getBundle(NamespaceService.java:140)
    at com.yahoo.pulsar.broker.service.BrokerService.addTopicToStatsMaps(BrokerService.java:524)
    at com.yahoo.pulsar.broker.service.BrokerService.lambda$refreshTopicToStatsMaps$11(BrokerService.java:550)
    at com.yahoo.pulsar.broker.service.BrokerService$$Lambda$326/1860451344.accept(Unknown Source)
    at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1374)
    at java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:580)
    at com.yahoo.pulsar.broker.service.BrokerService.refreshTopicToStatsMaps(BrokerService.java:549)
    at com.yahoo.pulsar.broker.namespace.NamespaceService$2.processResult(NamespaceService.java:571)
    at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:554)
    at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:505)

The problem was introduced in current master (not in 1.15.x). There is a mix of ZK async and sync operations due to a cache miss on the ZooKeeperDataCache.

From the same ZK MainEvent thread we process the event and eventually trigger a sync ZK read that cannot complete because it needs the MainEvent thread to process the read response.

[merlimat]

Fixed in #115