Does Pulsar 4.0.12 or 4.0.13 fully address this namespace topic-policy cache failure after bundle shedding?

[kaminski-dev]

We are looking for confirmation that an incident on Apache Pulsar 4.0.10 matches issue #25294 and that upgrading to 4.0.12 or 4.0.13 is the correct fix.

Our evidence points to a stuck or aborted topic-policy cache initialization for one namespace. An automatic bundle move triggered the incident. One partition remained unavailable for several hours and recovered only after we unloaded the namespace.

The production logs released during that recovery match the __change_events reader and policyCacheInitMap failure described in #25294. The main uncertainty is that we did not capture a heap dump before recovery, so we cannot prove which specific reader race caused the shared future to remain pending.

Environment

• Apache Pulsar broker: 4.0.10
• Java: 21
• Load manager: org.apache.pulsar.broker.loadbalance.impl.ModularLoadManagerImpl
• Load shedding strategy: org.apache.pulsar.broker.loadbalance.impl.AvgShedder
• Load placement strategy: org.apache.pulsar.broker.loadbalance.impl.AvgShedder
• Brokers: 4
• Broker resources: 1 CPU and 6 GiB memory per broker
• Broker heap: 2560 MiB
• Broker direct-memory limit: 2304 MiB
• System topics: enabled
• Topic-level policies: enabled
• Geo-replication: enabled between two clusters
• S3 tiered storage: enabled
• Managed-ledger read priority: bookkeeper-first
• Topic auto-creation: disabled

Relevant runtime configuration:

loadBalancerEnabled=true
loadBalancerSheddingEnabled=true
loadBalancerSheddingIntervalMinutes=1
loadBalancerSheddingGracePeriodMinutes=30
loadBalancerLoadSheddingStrategy=org.apache.pulsar.broker.loadbalance.impl.AvgShedder
loadBalancerLoadPlacementStrategy=org.apache.pulsar.broker.loadbalance.impl.AvgShedder

loadBalancerCPUResourceWeight=1.0
loadBalancerBandwidthInResourceWeight=1.0
loadBalancerBandwidthOutResourceWeight=1.0
loadBalancerMemoryResourceWeight=0.0
loadBalancerDirectMemoryResourceWeight=0.0

loadBalancerAvgShedderLowThreshold=15
loadBalancerAvgShedderHitCountLowThreshold=8
loadBalancerAvgShedderHighThreshold=40
loadBalancerAvgShedderHitCountHighThreshold=2
maxUnloadPercentage=0.2

loadBalancerAutoBundleSplitEnabled=true
loadBalancerAutoUnloadSplitBundlesEnabled=true
loadBalancerNamespaceBundleMaxTopics=750
defaultNamespaceBundleSplitAlgorithm=topic_count_equally_divide

maxConcurrentTopicLoadRequest=5000
topicLoadTimeoutSeconds=60
namespaceBundleUnloadingTimeoutMs=60000

managedLedgerCacheSizeMB=512
managedLedgerMaxReadsInFlightSizeInMB=346
managedLedgerOffloadMaxThreads=2
managedLedgerOffloadReadThreads=2
managedLedgerDataReadPriority=bookkeeper-first

replicationProducerQueueSize=500

The custom container image uses the upstream apachepulsar/pulsar-all:4.0.10 image and adds authentication, authorization and logging libraries. It does not modify Pulsar broker code.

Incident timeline

Times below are UTC.

05:33:41

AvgShedder moved a bundle from broker-2 to broker-1:

[AvgShedder] Unloading bundle: <tenant>/<namespace>/0x40000000_0x80000000
from broker broker-2 to dest broker broker-1

The load-balancer log immediately before the move showed:

maxBroker score: 99.53
maxBroker throughput: 20061768 bytes/s
maxBroker msgRate: 46300 msg/s

minBroker score: 1.38
minBroker throughput: 0
minBroker msgRate: 0

isMsgRateToOffload: true
trafficMarkedToOffload: 9260 msg/s

The high score difference exceeded our configured threshold of 40 for the required two observations.

The affected topic was partitioned. Partitions 0 and 1 remained available. Partition 2 belonged to the moved bundle.

The source broker logged the topic unload and disconnected its producers:

[persistent://<tenant>/<namespace>/<topic>-partition-2] Unloading topic
Disconnecting producer ... assignedBrokerLookupData: Optional.empty

The destination broker then acquired the bundle and started its eager preload:

Successfully acquired ownership of OwnedBundle(
  bundle=<tenant>/<namespace>/0x40000000_0x80000000,
  isActive=1)

Loading all topics on bundle: <tenant>/<namespace>/0x40000000_0x80000000

The bundle currently contains 131 persistent topics.

05:33 onward

The destination broker repeatedly failed to load partition 2:

Failed to load persistent://<tenant>/<namespace>/<topic>-partition-2 after 60000 ms

Producer creation failed with:

Failed to create topic persistent://<tenant>/<namespace>/<topic>-partition-2

org.apache.pulsar.common.util.FutureUtil$LowOverheadTimeoutException:
Failed to load topic within timeout

Consumer creation for this and other topics in the same namespace also failed with the same topic-load timeout.

The failures repeated every minute. Broker health checks continued to pass, and unrelated topics on the same broker remained available.

A direct admin request reproduced the failure:

pulsar-admin topics stats \
  persistent://<tenant>/<namespace>/<topic>-partition-2

HTTP 504 Gateway Timeout

Independent partition checks returned:

partition-0: OK
partition-1: OK
partition-2: FAILED

Topic lookup consistently assigned partition 2 to broker-1.

05:35:48

AvgShedder moved a second bundle from the same namespace:

[AvgShedder] Unloading bundle: <tenant>/<namespace>/0xc0000000_0xffffffff
from broker broker-2 to dest broker broker-0

This happened about two minutes after the first bundle move.

The namespace's __change_events topic is currently in bundle 0x00000000_0x40000000. We do not have enough retained logs to prove whether that system-topic bundle also changed ownership during the original incident.

Several hours later

We unloaded the full namespace through the admin API. The command completed successfully.

During cleanup, the brokers released many pending topic loads. The first useful root-cause logs appeared at this point:

Failed to prepare policies cache for namespace <tenant>/<namespace>
due to previously logged error

org.apache.pulsar.client.api.PulsarClientException$AlreadyClosedException:
The consumer which subscribes the topic
persistent://<tenant>/<namespace>/__change_events
with subscription name __system_reader-reader-<id>
was already closed when cleaning and closing the consumers

The same policy-cache exception was then propagated into the affected partition and many other waiting topic loads:

Topic creation encountered an exception by initialize topic policies service.
topic_name=persistent://<tenant>/<namespace>/<topic>-partition-2
error_message=The consumer which subscribes the topic
persistent://<tenant>/<namespace>/__change_events ... was already closed

The exception came from ConsumerBase.failPendingReceives while the namespace unload closed the system-topic reader.

After reassignment, all three partitions responded immediately:

partition-0: OK
partition-1: OK
partition-2: OK

Post-recovery diagnostics

We captured a thread dump, class histogram and heap dump after the namespace unload. We understand that this is too late to prove the original pending operation, but we inspected it to confirm the recovered state.

The thread dump showed:

• 107 live Java threads
• no BLOCKED threads
• no Java-level deadlock
• idle broker-client internal executor
• idle broker topic worker
• idle Pulsar ordered executors
• idle metadata, BookKeeper and offload executors
• no thread executing SystemTopicBasedTopicPoliciesService or TopicPolicyReader

Eclipse Memory Analyzer showed:

• 73 TopicPolicyReader instances
• 73 entries in SystemTopicBasedTopicPoliciesService.policyCacheInitMap
• all 73 policy-reader consumers in Ready state
• one replacement reader for the affected namespace's __change_events topic
• the affected namespace's shared policy-cache future completed normally
• no pending namespace-keyed policy-cache future remained

The original reader named in the cleanup exception was no longer present, which is expected because the namespace unload closed it and installed a replacement before the dump was taken.

The MAT leak report did not identify policy readers or policy-cache futures as leak suspects. Its main retained groups were normal managed-ledger metadata and producer schema caches.

Our source-code interpretation

In Pulsar 4.0.10, BrokerService.getTopic waits for topic-policy initialization before it creates or returns a persistent topic:

return getTopicPoliciesBypassSystemTopic(topicName, LOCAL_ONLY)
    .thenCompose(optionalTopicPolicies -> {
        // compute/load the topic
    });

SystemTopicBasedTopicPoliciesService.prepareInitPoliciesCacheAsync creates one shared future per namespace:

return policyCacheInitMap.computeIfAbsent(namespace, key -> {
    CompletableFuture<Reader<PulsarEvent>> readerFuture = createSystemTopicClient(namespace);
    readerCaches.put(namespace, readerFuture);

    CompletableFuture<Void> initFuture = readerFuture.thenCompose(reader -> {
        CompletableFuture<Void> stageFuture = new CompletableFuture<>();
        initPolicesCache(reader, stageFuture);
        return stageFuture.thenAccept(ignore -> readMorePoliciesAsync(reader));
    });

    return initFuture;
});

initPolicesCache recursively calls hasMoreEventsAsync and readNextAsync until the reader reaches the end of __change_events. There is no timeout around this loop in 4.0.10.

The individual topic load has a 60-second timeout:

CompletableFuture<Optional<Topic>> topicFuture = FutureUtil.createFutureWithTimeout(
    Duration.ofSeconds(topicLoadTimeoutSeconds),
    executor,
    () -> FAILED_TO_LOAD_TOPIC_TIMEOUT_EXCEPTION);

However, this timeout completes only the topic future. It does not cancel the policy reader or clear the shared policyCacheInitMap entry. This appears to explain why each retry failed while the underlying namespace state remained stuck.

Bundle acquisition also calls PulsarService.loadNamespaceTopics, which submits a load for every persistent topic in the bundle. In our case this may have submitted around 131 concurrent topic loads on a broker with one CPU and maxConcurrentTopicLoadRequest=5000. We see this as an amplifier rather than the correctness bug.

Related upstream fixes

The incident appears closely related to:

• #25294, topic unavailable because the topic-policy cache reader is stuck
• #25998, compacted read can become stuck after closely spaced unload and reconnect operations
• #26025, bound topic-policy cache initialization and clean poisoned shared state
• #26132, prevent an old closing topic-policy reader from aborting a new cache initialization
• #26145, prevent stale topic-unload cleanup from removing a newer active topic cache entry

The first three fixes are in Pulsar 4.0.12. The last fix is in Pulsar 4.0.13.

Our production cleanup exception is very similar to the evidence in #25294, including the pending topic-policy operations being released when the reader closes.

Questions

1. Does this evidence look sufficient to classify the incident as the same failure described in [Bug] topic unavailable because topic policy cache loading reader is stuck #25294?
2. Would you expect [fix][broker] Fix compacted read could be stuck forever or message loss due to cursor mark delete #25998, [fix][broker] Don't let a stuck or aborted topic policies cache init make a namespace's topics unloadable #26025 and [fix][broker] Don't let a closing topic-policies reader abort a concurrent cache-init reload #26132 in Pulsar 4.0.12 to prevent this exact failure and allow automatic recovery if a policy reader gets stuck?
3. Would you recommend upgrading directly to 4.0.13 because bundle unload initiated the incident and [fix][broker] Prevent stale topic unload cleanup from removing active cache entries #26145 adds further unload-cache race protection?
4. Can [fix][broker] Fix compacted read could be stuck forever or message loss due to cursor mark delete #25998 be triggered when two user-topic bundles from the same namespace move close together, even if we cannot prove that the bundle containing __change_events moved in the retained logs?
5. Is maxConcurrentTopicLoadRequest=5000 too high for a one-CPU broker with geo-replication and tiered storage? Would a value around 250-500 be a reasonable starting point?
6. Is there another metric, debug log or runtime inspection we should collect if this happens again before the upgrade?
7. Apart from a heap dump and thread dump, is there a supported way to inspect policyCacheInitMap, the __change_events reader position and compacted-reader state on a live broker?

Any confirmation or correction of our interpretation would be appreciated.

We plan to upgrade to 4.0.13, but confirmation that our diagnosis is correct would be helpful. We would also appreciate advice on whether to lower topic-load concurrency or increase broker CPU. Our brokers usually run at only 5-15% CPU, but we are happy to increase their capacity if more headroom is needed during bundle loading and recovery.

[lhotari]

It's not possible to say that all possible issues are fixed. The most likely ones are fixed in 4.0.13/4.2.4 (same fixes in both). I'd recommend upgrading to 4.0.13 in your case.

[lhotari]

some details in #25116 (comment)

[kaminski-dev]

Thanks, will upgrade and report back if we face something similar. Will try to capture a heap dump as well.