apache / apache/pulsar

[Bug] Receives topic is temporarily unavailable error when bookies are rolling restart

Open
#21,860 6 comments 1 reaction 1 assignee Claimed by @graysonzeng 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 asking

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

### Version

Pulsar 3.1.1

### Minimal reproduce step

broker count: 2
bookie count: 5

broker config:
managedLedgerDefaultAckQuorum: "2"
managedLedgerDefaultEnsembleSize: "4"
managedLedgerDefaultWriteQuorum: "3"

Using pulsar perf the publishing rate is 200000 messages/sec and the total number of messages is 100000000.
Consume it at the same time.

`bin/pulsar-perf produce persistent://pulsar/default/input_test -r 200000 -m 10000000`

`bin/pulsar-perf consume persistent://pulsar/default/input_test -ss sub01`

### What did you expect to see?

Complete the production and consumption of all messages

### What did you see instead?

Consumer receives `topic is temporarily unavailable` errors and is stuck

```java
2024-01-05T18:32:19,950+0800 [pulsar-client-io-1-1] INFO org.apache.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/default2/alltables6-partition-5][subtest04] Subscribing to topic on cnx [id: 0x81eec4ec, L:/11.145.30.236:23196 - R:21.24.16.52/21.24.16.52:6650], consumerId 5
2024-01-05T18:32:19,951+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0xf22ff96d, L:/11.145.30.236:23180 - R:21.24.16.52/21.24.16.52:6650] Received error from server: Topic is temporarily unavailable
2024-01-05T18:32:19,953+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/default2/alltables6-partition-6][subtest04] Failed to subscribe to topic on 21.24.16.52/21.24.16.52:6650
2024-01-05T18:32:19,953+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-6] [subtest04] Error connecting to broker: org.apache.pulsar.client.api.PulsarClientException$LookupException: {"errorMsg":"Topic is temporarily unavailable","reqId":1789164940489895795, "remote":"21.24.16.52/21.24.16.52:6650", "local":"/11.145.30.236:23180"}
2024-01-05T18:32:19,953+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-6] [subtest04] Could not get connection to broker: org.apache.pulsar.client.api.PulsarClientException$LookupException: {"errorMsg":"Topic is temporarily unavailable","reqId":1789164940489895795, "remote":"21.24.16.52/21.24.16.52:6650", "local":"/11.145.30.236:23180"} -- Will try again in 0.1 s
2024-01-05T18:32:19,954+0800 [pulsar-client-io-1-1] INFO org.apache.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/default2/alltables6-partition-2][subtest04] Subscribed to topic on 21.24.16.52/21.24.16.52:6650 -- consumer: 2
2024-01-05T18:32:19,954+0800 [pulsar-client-io-1-1] INFO org.apache.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/default2/alltables6-partition-0][subtest04] Subscribed to topic on 21.24.16.52/21.24.16.52:6650 -- consumer: 0
2024-01-05T18:32:19,955+0800 [pulsar-client-io-1-1] INFO org.apache.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/default2/alltables6-partition-7][subtest04] Subscribed to topic on 21.24.16.52/21.24.16.52:6650 -- consumer: 7
2024-01-05T18:32:19,955+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0xf22ff96d, L:/11.145.30.236:23180 - R:21.24.16.52/21.24.16.52:6650] Received error from server: Topic is temporarily unavailable
2024-01-05T18:32:19,955+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/default2/alltables6-partition-9][subtest04] Failed to subscribe to topic on 21.24.16.52/21.24.16.52:6650
2024-01-05T18:32:19,955+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-9] [subtest04] Error connecting to broker: org.apache.pulsar.client.api.PulsarClientException$LookupException: {"errorMsg":"Topic is temporarily unavailable","reqId":1789164940489895799, "remote":"21.24.16.52/21.24.16.52:6650", "local":"/11.145.30.236:23180"}
2024-01-05T18:32:19,955+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-9] [subtest04] Could not get connection to broker: org.apache.pulsar.client.api.PulsarClientException$LookupException: {"errorMsg":"Topic is temporarily unavailable","reqId":1789164940489895799, "remote":"21.24.16.52/21.24.16.52:6650", "local":"/11.145.30.236:23180"} -- Will try again in 0.1 s
2024-01-05T18:32:19,955+0800 [pulsar-client-io-1-1] INFO org.apache.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/default2/alltables6-partition-8][subtest04] Subscribed to topic on 21.24.16.52/21.24.16.52:6650 -- consumer: 8
2024-01-05T18:32:19,956+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-1] [subtest04] Error connecting to broker: org.apache.pulsar.client.api.PulsarClientException$LookupException: {"errorMsg":"Topic is temporarily unavailable","reqId":1789164940489895802, "remote":"21.24.16.52/21.24.16.52:6650", "local":"/11.145.30.236:23196"}
2024-01-05T18:32:19,956+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-1] [subtest04] Could not get connection to broker: org.apache.pulsar.client.api.PulsarClientException$LookupException: {"errorMsg":"Topic is temporarily unavailable","reqId":1789164940489895802, "remote":"21.24.16.52/21.24.16.52:6650", "local":"/11.145.30.236:23196"} -- Will try again in 0.1 s
2024-01-05T18:32:19,956+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0x81eec4ec, L:/11.145.30.236:23196 - R:21.24.16.52/21.24.16.52:6650] Received error from server: Topic is temporarily unavailable
2024-01-05T18:32:19,957+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/default2/alltables6-partition-3][subtest04] Failed to subscribe to topic on 21.24.16.52/21.24.16.52:6650
2024-01-05T18:32:19,957+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-3] [subtest04] Error connecting to broker: org.apache.pulsar.client.api.PulsarClientException$LookupException: {"errorMsg":"Topic is temporarily unavailable","reqId":1789164940489895803, "remote":"21.24.16.52/21.24.16.52:6650", "local":"/11.145.30.236:23196"}
2024-01-05T18:32:19,957+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-3] [subtest04] Could not get connection to broker: org.apache.pulsar.client.api.PulsarClientException$LookupException: {"errorMsg":"Topic is temporarily unavailable","reqId":1789164940489895803, "remote":"21.24.16.52/21.24.16.52:6650", "local":"/11.145.30.236:23196"} -- Will try again in 0.1 s
2024-01-05T18:32:19,957+0800 [pulsar-client-io-1-1] INFO org.apache.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/default2/alltables6-partition-5][subtest04] Subscribed to topic on 21.24.16.52/21.24.16.52:6650 -- consumer: 5
2024-01-05T18:32:20,054+0800 [pulsar-timer-6-1] INFO org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-6] [subtest04] Reconnecting after connection was closed
2024-01-05T18:32:20,059+0800 [pulsar-timer-6-1] INFO org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-9] [subtest04] Reconnecting after connection was closed
2024-01-05T18:32:20,059+0800 [pulsar-timer-6-1] INFO org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-1] [subtest04] Reconnecting after connection was closed
2024-01-05T18:32:20,059+0800 [pulsar-timer-6-1] INFO org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-3] [subtest04] Reconnecting after connection was closed
2024-01-05T18:32:20,062+0800 [pulsar-client-io-1-1] INFO org.apache.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/default2/alltables6-partition-6][subtest04] Subscribing to topic on cnx [id: 0xf22ff96d, L:/11.145.30.236:23180 - R:21.24.16.52/21.24.16.52:6650], consumerId 6
2024-01-05T18:32:20,063+0800 [pulsar-client-io-1-1] INFO org.apache.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/default2/alltables6-partition-1][subtest04] Subscribing to topic on cnx [id: 0x81eec4ec, L:/11.145.30.236:23196 - R:21.24.16.52/21.24.16.52:6650], consumerId 1
2024-01-05T18:32:20,064+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0xf22ff96d, L:/11.145.30.236:23180 - R:21.24.16.52/21.24.16.52:6650] Received error from server: Topic is temporarily unavailable
2024-01-05T18:32:20,064+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/default2/alltables6-partition-6][subtest04] Failed to subscribe to topic on 21.24.16.52/21.24.16.52:6650
2024-01-05T18:32:20,064+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-6] [subtest04] Error connecting to broker: org.apache.pulsar.client.api.PulsarClientException$LookupException: {"errorMsg":"Topic is temporarily unavailable","reqId":1789164940489895809, "remote":"21.24.16.52/21.24.16.52:6650", "local":"/11.145.30.236:23180"}
2024-01-05T18:32:20,064+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-6] [subtest04] Could not get connection to broker: org.apache.pulsar.client.api.PulsarClientException$LookupException: {"errorMsg":"Topic is temporarily unavailable","reqId":1789164940489895809, "remote":"21.24.16.52/21.24.16.52:6650", "local":"/11.145.30.236:23180"} -- Will try again in 0.188 s
2024-01-05T18:32:20,066+0800 [pulsar-client-io-1-1] INFO org.apache.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/default2/alltables6-partition-9][subtest04] Subscribing to topic on cnx [id: 0xf22ff96d, L:/11.145.30.236:23180 - R:21.24.16.52/21.24.16.52:6650], consumerId 9
2024-01-05T18:32:20,067+0800 [pulsar-client-io-1-1] INFO org.apache.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/default2/alltables6-partition-3][subtest04] Subscribing to topic on cnx [id: 0x81eec4ec, L:/11.145.30.236:23196 - R:21.24.16.52/21.24.16.52:6650], consumerId 3
2024-01-05T18:32:20,067+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0x81eec4ec, L:/11.145.30.236:23196 - R:21.24.16.52/21.24.16.52:6650] Received error from server: Topic is temporarily unavailable
2024-01-05T18:32:20,067+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/default2/alltables6-partition-1][subtest04] Failed to subscribe to topic on 21.24.16.52/21.24.16.52:6650
2024-01-05T18:32:20,067+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-1] [subtest04] Error connecting to broker: org.apache.pulsar.client.api.PulsarClientException$LookupException: {"errorMsg":"Topic is temporarily unavailable","reqId":1789164940489895810, "remote":"21.24.16.52/21.24.16.52:6650", "local":"/11.145.30.236:23196"}
2024-01-05T18:32:20,067+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-1] [subtest04] Could not get connection to broker: org.apache.pulsar.client.api.PulsarClientException$LookupException: {"errorMsg":"Topic is temporarily unavailable","reqId":1789164940489895810, "remote":"21.24.16.52/21.24.16.52:6650", "local":"/11.145.30.236:23196"} -- Will try again in 0.191 s
2024-01-05T18:32:20,068+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0xf22ff96d, L:/11.145.30.236:23180 - R:21.24.16.52/21.24.16.52:6650] Received error from server: Topic is temporarily unavailable
2024-01-05T18:32:20,068+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/default2/alltables6-partition-9][subtest04] Failed to subscribe to topic on 21.24.16.52/21.24.16.52:6650
2024-01-05T18:32:20,068+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-9] [subtest04] Error connecting to broker: org.apache.pulsar.client.api.PulsarClientException$LookupException: {"errorMsg":"Topic is temporarily unavailable","reqId":1789164940489895811, "remote":"21.24.16.52/21.24.16.52:6650", "local":"/11.145.30.236:23180"}
2024-01-05T18:32:20,068+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-9] [subtest04] Could not get connection to broker: org.apache.pulsar.client.api.PulsarClientException$LookupException: {"errorMsg":"Topic is temporarily unavailable","reqId":1789164940489895811, "remote":"21.24.16.52/21.24.16.52:6650", "local":"/11.145.30.236:23180"} -- Will try again in 0.195 s
2024-01-05T18:32:20,070+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0x81eec4ec, L:/11.145.30.236:23196 - R:21.24.16.52/21.24.16.52:6650] Received error from server: Topic is temporarily unavailable
2024-01-05T18:32:20,071+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/default2/alltables6-partition-3][subtest04] Failed to subscribe to topic on 21.24.16.52/21.24.16.52:6650
2024-01-05T18:32:20,071+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-3] [subtest04] Error connecting to broker: org.apache.pulsar.client.api.PulsarClientException$LookupException: {"errorMsg":"Topic is temporarily unavailable","reqId":1789164940489895812, "remote":"21.24.16.52/21.24.16.52:6650", "local":"/11.145.30.236:23196"}
2024-01-05T18:32:20,071+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-3] [subtest04] Could not get connection to broker: org.apache.pulsar.client.api.PulsarClientException$LookupException: {"errorMsg":"Topic is temporarily unavailable","reqId":1789164940489895812, "remote":"21.24.16.52/21.24.16.52:6650", "local":"/11.145.30.236:23196"} -- Will try again in 0.19 s
2024-01-05T18:32:20,254+0800 [pulsar-timer-6-1] INFO org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-6] [subtest04] Reconnecting after connection was closed
2024-01-05T18:32:20,260+0800 [pulsar-timer-6-1] INFO org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-1] [subtest04] Reconnecting after connection was closed
2024-01-05T18:32:20,261+0800 [pulsar-client-io-1-1] INFO org.apache.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/default2/alltables6-partition-6][subtest04] Subscribing to topic on cnx [id: 0xf22ff96d, L:/11.145.30.236:23180 - R:21.24.16.52/21.24.16.52:6650], consumerId 6
2024-01-05T18:32:20,262+0800 [pulsar-timer-6-1] INFO org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-3] [subtest04] Reconnecting after connection was closed
2024-01-05T18:32:20,263+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0xf22ff96d, L:/11.145.30.236:23180 - R:21.24.16.52/21.24.16.52:6650] Received error from server: Topic is temporarily unavailable
2024-01-05T18:32:20,263+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/default2/alltables6-partition-6][subtest04] Failed to subscribe to topic on 21.24.16.52/21.24.16.52:6650
2024-01-05T18:32:20,263+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-6] [subtest04] Error connecting to broker: org.apache.pulsar.client.api.PulsarClientException$LookupException: {"errorMsg":"Topic is temporarily unavailable","reqId":1789164940489895815, "remote":"21.24.16.52/21.24.16.52:6650", "local":"/11.145.30.236:23180"}
2024-01-05T18:32:20,263+0800 [pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-6] [subtest04] Could not get connection to broker: org.apache.pulsar.client.api.PulsarClientException$LookupException: {"errorMsg":"Topic is temporarily unavailable","reqId":1789164940489895815, "remote":"21.24.16.52/21.24.16.52:6650", "local":"/11.145.30.236:23180"} -- Will try again in 0.37 s
2024-01-05T18:32:20,265+0800 [pulsar-timer-6-1] INFO org.apache.pulsar.client.impl.ConnectionHandler - [persistent://pulsar/default2/alltables6-partition-9] [subtest04] Reconnecting after connection was closed

```

Producer receives similar errors

```java
2024-01-05T18:30:12,998+0800 [pulsar-client-io-17-1] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0x0a55fe43, L:/9.165.132.169:50214 - R:21.24.16.52/21.24.16.52:6650] Received error from server: org.apache.pulsar.broker.service.BrokerServiceException$TopicFencedException: Topic is temporarily unavailable
2024-01-05T18:30:12,998+0800 [pulsar-client-io-17-1] ERROR org.apache.pulsar.client.impl.ProducerImpl - [persistent://pulsar/default2/input_test5-partition-4] [input_test07-persistent://pulsar/default2/input_test5-persistent://pulsar/default2/input_test-partition-4-0] Failed to create producer: {\"errorMsg\":\"org.apache.pulsar.broker.service.BrokerServiceException$TopicFencedException: Topic is temporarily unavailable\",\"reqId\":2708211058561300994, \"remote\":\"21.24.16.52/21.24.16.52:6650\", \"local\":\"/9.165.132.169:50214\"}

```

### Anything else?

_No response_

### Are you willing to submit a PR?

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

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.