apache / apache/pulsar

[Bug] Endless loop when shutting down pulsar while a health check request is on going

Open
#24,548 3 comments 0 reactions 0 assignees View on GitHub
type/bug
Dominant language
Java
Stars
15.3k
Forks
3.8k
Avg merge
1d 14h
Merged PRs (30d)
160

Description

### Search before reporting

- [x] I searched in the [issues](https://github.com/apache/pulsar/issues) and found nothing similar.

### Read release policy

- [x] I understand that [unsupported versions](https://pulsar.apache.org/contribute/release-policy/#supported-versions) don't get bug fixes. I will attempt to reproduce the issue on a supported version of Pulsar client and Pulsar broker.

### User environment

docker image apachepulsar/pulsar:4.0.5
java pulsar client 4.0.5

### Issue Description

When shutting down the standelone pulsar 4.0.5, it stops bookkeeper before stopping accepting new pulsar messages. As the result, the broker retry forever to write to bookkeeper, but never succeed, and never stop gracefully. This happens with sending regular messages or even just health check requests.

### Error messages

```text
2025-07-22 11:36:18 Caused by: org.apache.bookkeeper.client.BKException$BKBookieHandleNotAvailableException: Bookie handle is not available
2025-07-22 11:36:18 at org.apache.bookkeeper.client.BKException.create(BKException.java:77) ~[org.apache.bookkeeper-bookkeeper-server-4.17.1.jar:4.17.1]
2025-07-22 11:36:18 at org.apache.bookkeeper.client.PendingReadOp.submitCallback(PendingReadOp.java:161) ~[org.apache.bookkeeper-bookkeeper-server-4.17.1.jar:4.17.1]
2025-07-22 11:36:18 at org.apache.bookkeeper.client.ReadOpBase$LedgerEntryRequest.fail(ReadOpBase.java:164) ~[org.apache.bookkeeper-bookkeeper-server-4.17.1.jar:4.17.1]
2025-07-22 11:36:18 at org.apache.bookkeeper.client.PendingReadOp$SequenceReadRequest.sendNextRead(PendingReadOp.java:349) ~[org.apache.bookkeeper-bookkeeper-server-4.17.1.jar:4.17.1]
2025-07-22 11:36:18 at org.apache.bookkeeper.client.PendingReadOp$SequenceReadRequest.logErrorAndReattemptRead(PendingReadOp.java:392) ~[org.apache.bookkeeper-bookkeeper-server-4.17.1.jar:4.17.1]
2025-07-22 11:36:18 at org.apache.bookkeeper.client.PendingReadOp.readEntryComplete(PendingReadOp.java:101) ~[org.apache.bookkeeper-bookkeeper-server-4.17.1.jar:4.17.1]
2025-07-22 11:36:18 at org.apache.bookkeeper.proto.BookieClientImpl.lambda$completeRead$7(BookieClientImpl.java:352) ~[org.apache.bookkeeper-bookkeeper-server-4.17.1.jar:4.17.1]
2025-07-22 11:36:18 at org.apache.bookkeeper.common.util.SingleThreadExecutor.safeRunTask(SingleThreadExecutor.java:137) ~[org.apache.bookkeeper-bookkeeper-common-4.17.1.jar:4.17.1]
2025-07-22 11:36:18 at org.apache.bookkeeper.common.util.SingleThreadExecutor.run(SingleThreadExecutor.java:113) ~[org.apache.bookkeeper-bookkeeper-common-4.17.1.jar:4.17.1]
2025-07-22 11:36:18 at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[io.netty-netty-common-4.1.121.Final.jar:4.1.121.Final]
2025-07-22 11:36:18 at java.base/java.lang.Thread.run(Unknown Source) [?:?]
2025-07-22 11:36:18 2025-07-22T09:36:18,826+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] ERROR org.apache.pulsar.broker.admin.impl.BrokersBase - [null] Failed to run health check.
2025-07-22 11:36:18 java.util.concurrent.CompletionException: org.apache.pulsar.broker.service.BrokerServiceException$PersistenceException: org.apache.bookkeeper.mledger.ManagedLedgerException$ManagedLedgerInterceptException: org.apache.bookkeeper.client.BKException$BKBookieHandleNotAvailableException: Bookie handle is not available
2025-07-22 11:36:18 at java.base/java.util.concurrent.CompletableFuture.encodeRelay(Unknown Source) ~[?:?]
2025-07-22 11:36:18 at java.base/java.util.concurrent.CompletableFuture.completeRelay(Unknown Source) ~[?:?]
2025-07-22 11:36:18 at java.base/java.util.concurrent.CompletableFuture$UniRelay.tryFire(Unknown Source) ~[?:?]
2025-07-22 11:36:18 at java.base/java.util.concurrent.CompletableFuture.postComplete(Unknown Source) ~[?:?]
2025-07-22 11:36:18 at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(Unknown Source) ~[?:?]
2025-07-22 11:36:18 at org.apache.pulsar.broker.service.BrokerService$2.openLedgerFailed(BrokerService.java:1898) ~[org.apache.pulsar-pulsar-broker-4.0.5.jar:4.0.5]
2025-07-22 11:36:18 at org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl.lambda$asyncOpen$10(ManagedLedgerFactoryImpl.java:471) ~[org.apache.pulsar-managed-ledger-4.0.5.jar:4.0.5]
2025-07-22 11:36:18 at java.base/java.util.concurrent.CompletableFuture.uniExceptionally(Unknown Source) ~[?:?]
2025-07-22 11:36:18 at java.base/java.util.concurrent.CompletableFuture$UniExceptionally.tryFire(Unknown Source) ~[?:?]
2025-07-22 11:36:18 at java.base/java.util.concurrent.CompletableFuture.postComplete(Unknown Source) ~[?:?]
2025-07-22 11:36:18 at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(Unknown Source) ~[?:?]
2025-07-22 11:36:18 at org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl$2.initializeFailed(ManagedLedgerFactoryImpl.java:462) ~[org.apache.pulsar-managed-ledger-4.0.5.jar:4.0.5]
2025-07-22 11:36:18 at org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl$1.lambda$operationComplete$1(ManagedLedgerImpl.java:444) ~[org.apache.pulsar-managed-ledger-4.0.5.jar:4.0.5]
2025-07-22 11:36:18 at java.base/java.util.concurrent.CompletableFuture.uniExceptionally(Unknown Source) ~[?:?]
2025-07-22 11:36:18 at java.base/java.util.concurrent.CompletableFuture$UniExceptionally.tryFire(Unknown Source) ~[?:?]
2025-07-22 11:36:18 at java.base/java.util.concurrent.CompletableFuture.postComplete(Unknown Source) ~[?:?]
2025-07-22 11:36:18 at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(Unknown Source) ~[?:?]
2025-07-22 11:36:18 at org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl.lambda$createLastEntryHandle$0(ManagedLedgerImpl.java:494) ~[org.apache.pulsar-managed-ledger-4.0.5.jar:4.0.5]
2025-07-22 11:36:18 at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(Unknown Source) ~[?:?]
2025-07-22 11:36:18 at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(Unknown Source) ~[?:?]
2025-07-22 11:36:18 at java.base/java.util.concurrent.CompletableFuture.postComplete(Unknown Source) ~[?:?]
2025-07-22 11:36:18 at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(Unknown Source) ~[?:?]
2025-07-22 11:36:18 at org.apache.bookkeeper.client.PendingReadOp.submitCallback(PendingReadOp.java:161) ~[org.apache.bookkeeper-bookkeeper-server-4.17.1.jar:4.17.1]
2025-07-22 11:36:18 at org.apache.bookkeeper.client.ReadOpBase$LedgerEntryRequest.fail(ReadOpBase.java:164) ~[org.apache.bookkeeper-bookkeeper-server-4.17.1.jar:4.17.1]
2025-07-22 11:36:18 at org.apache.bookkeeper.client.PendingReadOp$SequenceReadRequest.sendNextRead(PendingReadOp.java:349) ~[org.apache.bookkeeper-bookkeeper-server-4.17.1.jar:4.17.1]
2025-07-22 11:36:18 at org.apache.bookkeeper.client.PendingReadOp$SequenceReadRequest.logErrorAndReattemptRead(PendingReadOp.java:392) ~[org.apache.bookkeeper-bookkeeper-server-4.17.1.jar:4.17.1]
2025-07-22 11:36:18 at org.apache.bookkeeper.client.PendingReadOp.readEntryComplete(PendingReadOp.java:101) ~[org.apache.bookkeeper-bookkeeper-server-4.17.1.jar:4.17.1]
2025-07-22 11:36:18 at org.apache.bookkeeper.proto.BookieClientImpl.lambda$completeRead$7(BookieClientImpl.java:352) ~[org.apache.bookkeeper-bookkeeper-server-4.17.1.jar:4.17.1]
2025-07-22 11:36:18 at org.apache.bookkeeper.common.util.SingleThreadExecutor.safeRunTask(SingleThreadExecutor.java:137) ~[org.apache.bookkeeper-bookkeeper-common-4.17.1.jar:4.17.1]
2025-07-22 11:36:18 at org.apache.bookkeeper.common.util.SingleThreadExecutor.run(SingleThreadExecutor.java:113) ~[org.apache.bookkeeper-bookkeeper-common-4.17.1.jar:4.17.1]
2025-07-22 11:36:18 at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[io.netty-netty-common-4.1.121.Final.jar:4.1.121.Final]
2025-07-22 11:36:18 at java.base/java.lang.Thread.run(Unknown Source) [?:?]
2025-07-22 11:36:18 Caused by: org.apache.pulsar.broker.service.BrokerServiceException$PersistenceException: org.apache.bookkeeper.mledger.ManagedLedgerException$ManagedLedgerInterceptException: org.apache.bookkeeper.client.BKException$BKBookieHandleNotAvailableException: Bookie handle is not available
2025-07-22 11:36:18 ... 27 more
2025-07-22 11:36:18 Caused by: org.apache.bookkeeper.mledger.ManagedLedgerException$ManagedLedgerInterceptException: org.apache.bookkeeper.client.BKException$BKBookieHandleNotAvailableException: Bookie handle is not available
2025-07-22 11:36:18 Caused by: org.apache.bookkeeper.client.BKException$BKBookieHandleNotAvailableException: Bookie handle is not available
2025-07-22 11:36:18 at org.apache.bookkeeper.client.BKException.create(BKException.java:77) ~[org.apache.bookkeeper-bookkeeper-server-4.17.1.jar:4.17.1]
2025-07-22 11:36:18 ... 10 more
2025-07-22 11:36:18 2025-07-22T09:36:18,834+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] INFO org.eclipse.jetty.server.RequestLog - 172.17.0.1 - - [22/Jul/2025:09:36:18 +0000] "GET /admin/v2/brokers/health?topicVersion=V1 HTTP/1.1" 500 4500 "-" "Pulsar-Java-v4.0.5" 814
2025-07-22 11:36:18 2025-07-22T09:36:18,994+0000 [pulsar-web-49-12] INFO org.apache.pulsar.broker.service.HealthChecker - [null] Running healthCheck with topic=persistent://pulsar/standalone/localhost:8080/healthcheck
2025-07-22 11:36:18 2025-07-22T09:36:18,997+0000 [bookkeeper-ml-scheduler-OrderedScheduler-2-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Opening managed ledger pulsar/standalone/localhost:8080/persistent/healthcheck
2025-07-22 11:36:22 2025-07-22T09:36:22,085+0000 [pulsar-io-18-7] ERROR org.apache.bookkeeper.proto.PerChannelBookieClient - Could not connect to bookie: [id: 0x1c41006f, L:/172.17.0.2:42906]/172.17.0.4:39353, current state CONNECTING :
2025-07-22 11:36:22 io.netty.channel.AbstractChannel$AnnotatedNoRouteToHostException: null: /172.17.0.4:39353
2025-07-22 11:36:22 Caused by: java.net.NoRouteToHostException
```

### Reproducing the issue

Run a standalone pulsar testcontainers version 4.0.5,

container = new PulsarContainer(DEFAULT_IMAGE_NAME.withTag("4.0.5"))
.withFileSystemBind(dataDir.getAbsolutePath().toString(), "/pulsar/data", BindMode.READ_WRITE)
.withEnv("PULSAR_PREFIX_brokerDeduplicationEnabled", "true")
.withEnv("PULSAR_PREFIX_allowAutoTopicCreationType", "partitioned")
.withEnv("PULSAR_PREFIX_defaultNumPartitions", "3")
.withEnv("PULSAR_PREFIX_brokerEntryMetadataInterceptors", "org.apache.pulsar.common.intercept.AppendIndexMetadataInterceptor")
.withEnv("PULSAR_PREFIX_exposingBrokerEntryMetadataToClientEnabled", "true");

Send messages or check health continuously and try to stop the container (admin.brokers().shutDownBrokerGracefully()).

It loops forever without stopping with the provided logs.

### Additional information

It's a race condition, so it's not always occuring but if you run many tests, it happens.

### Are you willing to submit a PR?

- [x] I'm willing to submit a PR!

Contributor guide

Open the contributing guide

Research direction

Start with admin.brokers().shutDownBrokerGracefully() and the BrokerService, HealthChecker, and BrokersBase paths named in the logs. Reproduce the race using the Pulsar 4.0.5 Testcontainers setup while repeatedly sending messages or calling the health endpoint. Done means graceful shutdown completes despite an in-flight health check, with a regression test covering the scenario.

Written by the indexing model from the issue text.

Assessment

Tech stack
docker, java
Domain
backend, distributed-systems, testing-qa
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.