geniusjoe opened a new issue, #24323: URL: https://github.com/apache/pulsar/issues/24323
### 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 Broker version: docker image `apachepulsar/pulsar:4.0.4` Client library type: https://github.com/apache/pulsar-client-go/commit/a5c6dee1af2d693a7db40720b436d05d1228ab51 Client Operating system and hardware type: `Linux VM-152-173-centos 5.4.203-1-tlinux4-0011.1 #1 SMP Tue Apr 18 16:47:40 CST 2023 x86_64 x86_64 x86_64 GNU/Linux` ### Issue Description I notice there is a flaky test in pulsar client go `TestPartitionTopicsConsumerPubSubEncryption` https://github.com/apache/pulsar-client-go/blob/a5c6dee1af2d693a7db40720b436d05d1228ab51/pulsar/consumer_test.go#L537. This test case sometimes fail when related topic turned to unavailable status. ### Error messages ```text go client test output === RUN TestPartitionTopicsConsumerPubSubEncryption time="2025-05-20T03:42:45Z" level=info msg="Connecting to broker" remote_addr="pulsar://localhost:6650" time="2025-05-20T03:42:45Z" level=info msg="TCP connection established" local_addr="127.0.0.1:51860" remote_addr="pulsar://localhost:6650" time="2025-05-20T03:42:45Z" level=info msg="Connection is ready" local_addr="127.0.0.1:51860" remote_addr="pulsar://localhost:6650" time="2025-05-20T03:42:45Z" level=info msg="Connected producer" cnx="127.0.0.1:51860 -> 127.0.0.1:6650" epoch=0 topic="persistent://public/default/testGetPartitions-partition-5" time="2025-05-20T03:42:45Z" level=info msg="Connected producer" cnx="127.0.0.1:51860 -> 127.0.0.1:6650" epoch=0 topic="persistent://public/default/testGetPartitions-partition-2" time="2025-05-20T03:42:45Z" level=info msg="Created producer" cnx="127.0.0.1:51860 -> 127.0.0.1:6650" producerID=1 producer_name=standalone-0-150 topic="persistent://public/default/testGetPartitions-partition-5" time="2025-05-20T03:42:45Z" level=info msg="Connected producer" cnx="127.0.0.1:51860 -> 127.0.0.1:6650" epoch=0 topic="persistent://public/default/testGetPartitions-partition-4" time="2025-05-20T03:42:45Z" level=info msg="Created producer" cnx="127.0.0.1:51860 -> 127.0.0.1:6650" producerID=6 producer_name=standalone-0-155 topic="persistent://public/default/testGetPartitions-partition-4" time="2025-05-20T03:42:45Z" level=info msg="Connected producer" cnx="127.0.0.1:51860 -> 127.0.0.1:6650" epoch=0 topic="persistent://public/default/testGetPartitions-partition-1" time="2025-05-20T03:42:45Z" level=info msg="Created producer" cnx="127.0.0.1:51860 -> 127.0.0.1:6650" producerID=5 producer_name=standalone-0-154 topic="persistent://public/default/testGetPartitions-partition-1" time="2025-05-20T03:42:45Z" level=info msg="Connected producer" cnx="127.0.0.1:51860 -> 127.0.0.1:6650" epoch=0 topic="persistent://public/default/testGetPartitions-partition-0" time="2025-05-20T03:42:45Z" level=info msg="Created producer" cnx="127.0.0.1:51860 -> 127.0.0.1:6650" producerID=4 producer_name=standalone-0-153 topic="persistent://public/default/testGetPartitions-partition-0" time="2025-05-20T03:42:45Z" level=info msg="Connected producer" cnx="127.0.0.1:51860 -> 127.0.0.1:6650" epoch=0 topic="persistent://public/default/testGetPartitions-partition-3" time="2025-05-20T03:42:45Z" level=info msg="Created producer" cnx="127.0.0.1:51860 -> 127.0.0.1:6650" producerID=3 producer_name=standalone-0-151 topic="persistent://public/default/testGetPartitions-partition-3" time="2025-05-20T03:42:45Z" level=info msg="Created producer" cnx="127.0.0.1:51860 -> 127.0.0.1:6650" producerID=2 producer_name=standalone-0-152 topic="persistent://public/default/testGetPartitions-partition-2" time="2025-05-20T03:42:45Z" level=info msg="Connected consumer" consumerID=5 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-2" time="2025-05-20T03:42:45Z" level=info msg="Connected consumer" consumerID=1 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-5" time="2025-05-20T03:42:45Z" level=info msg="Connected consumer" consumerID=3 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-4" time="2025-05-20T03:42:45Z" level=info msg="Connected consumer" consumerID=2 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-1" time="2025-05-20T03:42:45Z" level=info msg="Connected consumer" consumerID=4 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-0" time="2025-05-20T03:42:45Z" level=info msg="Created consumer" consumerID=2 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-1" time="2025-05-20T03:42:45Z" level=info msg="Created consumer" consumerID=3 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-4" time="2025-05-20T03:42:45Z" level=info msg="Connected consumer" consumerID=6 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-3" time="2025-05-20T03:42:45Z" level=info msg="Created consumer" consumerID=6 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-3" time="2025-05-20T03:42:45Z" level=info msg="Created consumer" consumerID=5 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-2" time="2025-05-20T03:42:45Z" level=info msg="Created consumer" consumerID=1 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-5" time="2025-05-20T03:42:45Z" level=info msg="Created consumer" consumerID=4 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-0" time="2025-05-20T03:43:15Z" level=info msg="Broker notification of Closed producer: 1" local_addr="127.0.0.1:51860" remote_addr="pulsar://localhost:6650" time="2025-05-20T03:43:15Z" level=warning msg="Connection was closed" cnx="127.0.0.1:51860 -> 127.0.0.1:6650" producerID=1 producer_name=standalone-0-150 topic="persistent://public/default/testGetPartitions-partition-5" time="2025-05-20T03:43:15Z" level=info msg="Broker notification of Closed producer: 2" local_addr="127.0.0.1:51860" remote_addr="pulsar://localhost:6650" time="2025-05-20T03:43:15Z" level=warning msg="Connection was closed" cnx="127.0.0.1:51860 -> 127.0.0.1:6650" producerID=2 producer_name=standalone-0-152 topic="persistent://public/default/testGetPartitions-partition-2" time="2025-05-20T03:43:15Z" level=info msg="runEventsLoop will reconnect in producer" producerID=1 producer_name=standalone-0-150 topic="persistent://public/default/testGetPartitions-partition-5" time="2025-05-20T03:43:15Z" level=info msg="Broker notification of Closed consumer: 5" local_addr="127.0.0.1:51860" remote_addr="pulsar://localhost:6650" time="2025-05-20T03:43:15Z" level=info msg="Broker notification of Closed consumer: 1" local_addr="127.0.0.1:51860" remote_addr="pulsar://localhost:6650" time="2025-05-20T03:43:15Z" level=info msg="runEventsLoop will reconnect in producer" producerID=2 producer_name=standalone-0-152 topic="persistent://public/default/testGetPartitions-partition-2" consumer_test.go:603: Error Trace: /pulsar/pulsar-client-go/pulsar/consumer_test.go:603 Error: Expected nil, but got: context.deadlineExceededError{} Test: TestPartitionTopicsConsumerPubSubEncryption time="2025-05-20T03:43:15Z" level=info msg="Closing consumer=4" consumerID=4 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-0" time="2025-05-20T03:43:15Z" level=info msg="Closing consumer=2" consumerID=2 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-1" time="2025-05-20T03:43:15Z" level=info msg="Closing consumer=6" consumerID=6 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-3" time="2025-05-20T03:43:15Z" level=info msg="Closing consumer=3" consumerID=3 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-4" time="2025-05-20T03:43:15Z" level=error msg="Failed to redeliver closing or closed consumer" consumerID=6 name=yxwxx state=Closing subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-3" time="2025-05-20T03:43:15Z" level=error msg="unable to send permits" consumerID=6 error="consumer closing or closed" name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-3" time="2025-05-20T03:43:15Z" level=error msg="Failed to redeliver closing or closed consumer" consumerID=6 name=yxwxx state=Closing subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-3" time="2025-05-20T03:43:15Z" level=error msg="unable to send permits" consumerID=6 error="consumer closing or closed" name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-3" time="2025-05-20T03:43:15Z" level=error msg="Failed to create producer at send PRODUCER request" error="server error: ServiceNotReady: org.apache.pulsar.broker.service.BrokerServiceException$TopicFencedException: Topic is temporarily unavailable" producerID=1 producer_name=standalone-0-150 topic="persistent://public/default/testGetPartitions-partition-5" time="2025-05-20T03:43:15Z" level=info msg="Closed consumer" consumerID=3 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-4" time="2025-05-20T03:43:15Z" level=error msg="Failed to create consumer" consumerID=5 error="server error: ServiceNotReady: Topic is temporarily unavailable" name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-2" time="2025-05-20T03:43:15Z" level=error msg="Failed to create consumer at reconnect" consumerID=5 error="server error: ServiceNotReady: Topic is temporarily unavailable" name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-2" time="2025-05-20T03:43:15Z" level=error msg="Failed to create producer at send PRODUCER request" error="server error: ServiceNotReady: org.apache.pulsar.broker.service.BrokerServiceException$TopicFencedException: Topic is temporarily unavailable" producerID=2 producer_name=standalone-0-152 topic="persistent://public/default/testGetPartitions-partition-2" time="2025-05-20T03:43:15Z" level=error msg="Failed to create producer at reconnect" error="server error: ServiceNotReady: org.apache.pulsar.broker.service.BrokerServiceException$TopicFencedException: Topic is temporarily unavailable" producerID=2 producer_name=standalone-0-152 topic="persistent://public/default/testGetPartitions-partition-2" time="2025-05-20T03:43:15Z" level=info msg="Reconnecting to broker" assignedBrokerURL= delayReconnectTime=105.279204ms producerID=2 producer_name=standalone-0-152 topic="persistent://public/default/testGetPartitions-partition-2" time="2025-05-20T03:43:15Z" level=info msg="Closed consumer" consumerID=6 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-3" time="2025-05-20T03:43:15Z" level=info msg="Closed consumer" consumerID=2 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-1" time="2025-05-20T03:43:15Z" level=info msg="Closed consumer" consumerID=4 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-0" time="2025-05-20T03:43:15Z" level=error msg="Failed to create consumer" consumerID=1 error="server error: ServiceNotReady: Topic is temporarily unavailable" name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-5" time="2025-05-20T03:43:15Z" level=error msg="Failed to create producer at reconnect" error="server error: ServiceNotReady: org.apache.pulsar.broker.service.BrokerServiceException$TopicFencedException: Topic is temporarily unavailable" producerID=1 producer_name=standalone-0-150 topic="persistent://public/default/testGetPartitions-partition-5" time="2025-05-20T03:43:15Z" level=info msg="Reconnecting to broker" assignedBrokerURL= consumerID=5 delayReconnectTime=118.10888ms name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-2" time="2025-05-20T03:43:15Z" level=info msg="Closing consumer=5" consumerID=5 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-2" time="2025-05-20T03:43:15Z" level=info msg="Reconnecting to broker" assignedBrokerURL= delayReconnectTime=105.695828ms producerID=1 producer_name=standalone-0-150 topic="persistent://public/default/testGetPartitions-partition-5" time="2025-05-20T03:43:15Z" level=error msg="Failed to create consumer at reconnect" consumerID=1 error="server error: ServiceNotReady: Topic is temporarily unavailable" name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-5" time="2025-05-20T03:43:15Z" level=info msg="Reconnecting to broker" assignedBrokerURL= consumerID=1 delayReconnectTime=115.500383ms name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-5" time="2025-05-20T03:43:15Z" level=info msg="Closing consumer=1" consumerID=1 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-5" time="2025-05-20T03:43:15Z" level=info msg="Closed consumer" consumerID=5 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-2" time="2025-05-20T03:43:15Z" level=info msg="Closed consumer" consumerID=1 name=yxwxx subscription=my-sub topic="persistent://public/default/testGetPartitions-partition-5" time="2025-05-20T03:43:15Z" level=info msg="Closing producer" producerID=4 producer_name=standalone-0-153 topic="persistent://public/default/testGetPartitions-partition-0" time="2025-05-20T03:43:15Z" level=info msg="Closed producer" producerID=4 producer_name=standalone-0-153 topic="persistent://public/default/testGetPartitions-partition-0" time="2025-05-20T03:43:15Z" level=info msg="Closing producer" producerID=5 producer_name=standalone-0-154 topic="persistent://public/default/testGetPartitions-partition-1" time="2025-05-20T03:43:15Z" level=info msg="Closed producer" producerID=5 producer_name=standalone-0-154 topic="persistent://public/default/testGetPartitions-partition-1" time="2025-05-20T03:43:15Z" level=info msg="Closing producer" producerID=2 producer_name=standalone-0-152 topic="persistent://public/default/testGetPartitions-partition-2" time="2025-05-20T03:43:15Z" level=info msg="Closed producer" producerID=2 producer_name=standalone-0-152 topic="persistent://public/default/testGetPartitions-partition-2" time="2025-05-20T03:43:15Z" level=info msg="Closing producer" producerID=3 producer_name=standalone-0-151 topic="persistent://public/default/testGetPartitions-partition-3" time="2025-05-20T03:43:15Z" level=info msg="Closed producer" producerID=3 producer_name=standalone-0-151 topic="persistent://public/default/testGetPartitions-partition-3" time="2025-05-20T03:43:15Z" level=info msg="Closing producer" producerID=6 producer_name=standalone-0-155 topic="persistent://public/default/testGetPartitions-partition-4" time="2025-05-20T03:43:15Z" level=info msg="Closed producer" producerID=6 producer_name=standalone-0-155 topic="persistent://public/default/testGetPartitions-partition-4" time="2025-05-20T03:43:15Z" level=info msg="Closing producer" producerID=1 producer_name=standalone-0-150 topic="persistent://public/default/testGetPartitions-partition-5" time="2025-05-20T03:43:15Z" level=info msg="Closed producer" producerID=1 producer_name=standalone-0-150 topic="persistent://public/default/testGetPartitions-partition-5" --- FAIL: TestPartitionTopicsConsumerPubSubEncryption (30.11s) panic: runtime error: invalid memory address or nil pointer dereference [recovered] panic: runtime error: invalid memory address or nil pointer dereference [signal SIGSEGV: segmentation violation code=0x1 addr=0x68 pc=0x1473938] goroutine 4797 [running]: testing.tRunner.func1.2({0x1733e40, 0x228b090}) /pulsar/go/src/testing/testing.go:1632 +0x3fc testing.tRunner.func1() /pulsar/go/src/testing/testing.go:1635 +0x6b6 panic({0x1733e40?, 0x228b090?}) /pulsar/go/src/runtime/panic.go:791 +0x132 github.com/apache/pulsar-client-go/pulsar.TestPartitionTopicsConsumerPubSubEncryption(0xc000a0c1a0) /pulsar/pulsar-client-go/pulsar/consumer_test.go:604 +0xfd8 testing.tRunner(0xc000a0c1a0, 0x1919130) /pulsar/go/src/testing/testing.go:1690 +0x227 created by testing.(*T).Run in goroutine 1 /pulsar/go/src/testing/testing.go:1743 +0x826 FAIL github.com/apache/pulsar-client-go/pulsar 122.619s pulsar broker log 2025-05-20T03:42:45,049+0000 [metadata-store-28-1] INFO org.apache.pulsar.broker.admin.AdminResource - [anonymous] Successfully created partitioned topic persistent://public/default/testGetPartitions 2025-05-20T03:42:45,059+0000 [metadata-store-28-1] INFO org.apache.pulsar.broker.admin.AdminResource - [anonymous] Successfully created partitioned for topic persistent://public/default/testGetPartitions for the remote clusters 2025-05-20T03:42:45,060+0000 [metadata-store-28-1] INFO org.eclipse.jetty.server.RequestLog - 127.0.0.1 - - [20/May/2025:03:42:45 +0000] "PUT /admin/v2/persistent/public/default/testGetPartitions/partitions HTTP/1.1" 204 0 "-" "Go-http-client/1.1" 27 2025-05-20T03:42:45,062+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] connected with role=anonymous using authMethod=, clientVersion=Pulsar Go version unknown, clientProtocolVersion=20, proxyVersion=null 2025-05-20T03:42:45,071+0000 [pulsar-13-1] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Opening managed ledger public/default/persistent/testGetPartitions-partition-0 2025-05-20T03:42:45,071+0000 [pulsar-13-8] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Opening managed ledger public/default/persistent/testGetPartitions-partition-5 2025-05-20T03:42:45,071+0000 [pulsar-13-2] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Opening managed ledger public/default/persistent/testGetPartitions-partition-3 2025-05-20T03:42:45,071+0000 [pulsar-13-7] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Opening managed ledger public/default/persistent/testGetPartitions-partition-2 2025-05-20T03:42:45,071+0000 [pulsar-13-2] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Opening managed ledger public/default/persistent/testGetPartitions-partition-4 2025-05-20T03:42:45,071+0000 [pulsar-13-7] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Opening managed ledger public/default/persistent/testGetPartitions-partition-1 2025-05-20T03:42:45,084+0000 [metadata-store-28-1] INFO org.apache.pulsar.metadata.impl.AbstractMetadataStore - Deleting path: /ledgers/idgen/ID-0000000234 (v. Optional.empty) 2025-05-20T03:42:45,085+0000 [metadata-store-28-1] INFO org.apache.pulsar.metadata.impl.AbstractMetadataStore - Deleting path: /ledgers/idgen/ID-0000000235 (v. Optional.empty) 2025-05-20T03:42:45,085+0000 [metadata-store-28-1] INFO org.apache.pulsar.metadata.impl.AbstractMetadataStore - Deleting path: /ledgers/idgen/ID-0000000236 (v. Optional.empty) 2025-05-20T03:42:45,085+0000 [metadata-store-28-1] INFO org.apache.pulsar.metadata.impl.AbstractMetadataStore - Deleting path: /ledgers/idgen/ID-0000000237 (v. Optional.empty) 2025-05-20T03:42:45,085+0000 [metadata-store-28-1] INFO org.apache.pulsar.metadata.impl.AbstractMetadataStore - Deleting path: /ledgers/idgen/ID-0000000238 (v. Optional.empty) 2025-05-20T03:42:45,085+0000 [metadata-store-28-1] INFO org.apache.pulsar.metadata.impl.AbstractMetadataStore - Deleting path: /ledgers/idgen/ID-0000000239 (v. Optional.empty) 2025-05-20T03:42:45,091+0000 [metadata-store-28-1] INFO org.apache.pulsar.metadata.impl.AbstractMetadataStore - Deleted path: /ledgers/idgen/ID-0000000234 (v. Optional.empty) 2025-05-20T03:42:45,091+0000 [metadata-store-28-1] INFO org.apache.bookkeeper.client.LedgerCreateOp - Ensemble: [bk0test] for ledger: 234 2025-05-20T03:42:45,091+0000 [metadata-store-28-1] INFO org.apache.pulsar.metadata.impl.AbstractMetadataStore - Deleted path: /ledgers/idgen/ID-0000000235 (v. Optional.empty) 2025-05-20T03:42:45,091+0000 [metadata-store-28-1] INFO org.apache.bookkeeper.client.LedgerCreateOp - Ensemble: [bk0test] for ledger: 235 2025-05-20T03:42:45,091+0000 [metadata-store-28-1] INFO org.apache.pulsar.metadata.impl.AbstractMetadataStore - Deleted path: /ledgers/idgen/ID-0000000236 (v. Optional.empty) 2025-05-20T03:42:45,091+0000 [metadata-store-28-1] INFO org.apache.bookkeeper.client.LedgerCreateOp - Ensemble: [bk0test] for ledger: 236 2025-05-20T03:42:45,091+0000 [BookKeeperClientWorker-OrderedExecutor-6-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/default/persistent/testGetPartitions-partition-3] Created ledger 234 after closed null 2025-05-20T03:42:45,091+0000 [metadata-store-28-1] INFO org.apache.pulsar.metadata.impl.AbstractMetadataStore - Deleted path: /ledgers/idgen/ID-0000000237 (v. Optional.empty) 2025-05-20T03:42:45,091+0000 [BookKeeperClientWorker-OrderedExecutor-7-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/default/persistent/testGetPartitions-partition-5] Created ledger 235 after closed null 2025-05-20T03:42:45,091+0000 [metadata-store-28-1] INFO org.apache.bookkeeper.client.LedgerCreateOp - Ensemble: [bk0test] for ledger: 237 2025-05-20T03:42:45,091+0000 [metadata-store-28-1] INFO org.apache.pulsar.metadata.impl.AbstractMetadataStore - Deleted path: /ledgers/idgen/ID-0000000238 (v. Optional.empty) 2025-05-20T03:42:45,091+0000 [metadata-store-28-1] INFO org.apache.bookkeeper.client.LedgerCreateOp - Ensemble: [bk0test] for ledger: 238 2025-05-20T03:42:45,091+0000 [metadata-store-28-1] INFO org.apache.pulsar.metadata.impl.AbstractMetadataStore - Deleted path: /ledgers/idgen/ID-0000000239 (v. Optional.empty) 2025-05-20T03:42:45,091+0000 [metadata-store-28-1] INFO org.apache.bookkeeper.client.LedgerCreateOp - Ensemble: [bk0test] for ledger: 239 2025-05-20T03:42:45,091+0000 [BookKeeperClientWorker-OrderedExecutor-6-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/default/persistent/testGetPartitions-partition-4] Created ledger 238 after closed null 2025-05-20T03:42:45,091+0000 [BookKeeperClientWorker-OrderedExecutor-5-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/default/persistent/testGetPartitions-partition-2] Created ledger 236 after closed null 2025-05-20T03:42:45,091+0000 [BookKeeperClientWorker-OrderedExecutor-4-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/default/persistent/testGetPartitions-partition-0] Created ledger 239 after closed null 2025-05-20T03:42:45,091+0000 [BookKeeperClientWorker-OrderedExecutor-5-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/default/persistent/testGetPartitions-partition-1] Created ledger 237 after closed null 2025-05-20T03:42:45,099+0000 [bookkeeper-ml-scheduler-OrderedScheduler-6-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl - [public/default/persistent/testGetPartitions-partition-3] Successfully initialize managed ledger 2025-05-20T03:42:45,099+0000 [bookkeeper-ml-scheduler-OrderedScheduler-7-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl - [public/default/persistent/testGetPartitions-partition-5] Successfully initialize managed ledger 2025-05-20T03:42:45,099+0000 [bookkeeper-ml-scheduler-OrderedScheduler-4-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl - [public/default/persistent/testGetPartitions-partition-0] Successfully initialize managed ledger 2025-05-20T03:42:45,099+0000 [bookkeeper-ml-scheduler-OrderedScheduler-5-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl - [public/default/persistent/testGetPartitions-partition-2] Successfully initialize managed ledger 2025-05-20T03:42:45,100+0000 [bookkeeper-ml-scheduler-OrderedScheduler-6-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl - [public/default/persistent/testGetPartitions-partition-4] Successfully initialize managed ledger 2025-05-20T03:42:45,100+0000 [bookkeeper-ml-scheduler-OrderedScheduler-5-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerFactoryImpl - [public/default/persistent/testGetPartitions-partition-1] Successfully initialize managed ledger 2025-05-20T03:42:45,100+0000 [broker-topic-workers-OrderedExecutor-6-0] INFO org.apache.pulsar.broker.service.BrokerService - Created topic persistent://public/default/testGetPartitions-partition-2 - dedup is disabled 2025-05-20T03:42:45,100+0000 [broker-topic-workers-OrderedExecutor-5-0] INFO org.apache.pulsar.broker.service.BrokerService - Created topic persistent://public/default/testGetPartitions-partition-3 - dedup is disabled 2025-05-20T03:42:45,100+0000 [broker-topic-workers-OrderedExecutor-4-0] INFO org.apache.pulsar.broker.service.BrokerService - Created topic persistent://public/default/testGetPartitions-partition-5 - dedup is disabled 2025-05-20T03:42:45,100+0000 [broker-topic-workers-OrderedExecutor-0-0] INFO org.apache.pulsar.broker.service.BrokerService - Created topic persistent://public/default/testGetPartitions-partition-4 - dedup is disabled 2025-05-20T03:42:45,100+0000 [broker-topic-workers-OrderedExecutor-5-0] INFO org.apache.pulsar.broker.service.BrokerService - Created topic persistent://public/default/testGetPartitions-partition-0 - dedup is disabled 2025-05-20T03:42:45,100+0000 [broker-topic-workers-OrderedExecutor-5-0] INFO org.apache.pulsar.broker.service.BrokerService - Created topic persistent://public/default/testGetPartitions-partition-1 - dedup is disabled 2025-05-20T03:42:45,105+0000 [broker-topic-workers-OrderedExecutor-0-0] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Created new producer: Producer{topic=PersistentTopic{topic=persistent://public/default/testGetPartitions-partition-5}, client=[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected], producerName=standalone-0-150, producerId=1}, role: anonymous 2025-05-20T03:42:45,105+0000 [broker-topic-workers-OrderedExecutor-7-0] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Created new producer: Producer{topic=PersistentTopic{topic=persistent://public/default/testGetPartitions-partition-3}, client=[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected], producerName=standalone-0-151, producerId=3}, role: anonymous 2025-05-20T03:42:45,105+0000 [broker-topic-workers-OrderedExecutor-7-0] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Created new producer: Producer{topic=PersistentTopic{topic=persistent://public/default/testGetPartitions-partition-2}, client=[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected], producerName=standalone-0-152, producerId=2}, role: anonymous 2025-05-20T03:42:45,105+0000 [broker-topic-workers-OrderedExecutor-0-0] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Created new producer: Producer{topic=PersistentTopic{topic=persistent://public/default/testGetPartitions-partition-4}, client=[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected], producerName=standalone-0-155, producerId=6}, role: anonymous 2025-05-20T03:42:45,105+0000 [broker-topic-workers-OrderedExecutor-6-0] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Created new producer: Producer{topic=PersistentTopic{topic=persistent://public/default/testGetPartitions-partition-0}, client=[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected], producerName=standalone-0-153, producerId=4}, role: anonymous 2025-05-20T03:42:45,105+0000 [broker-topic-workers-OrderedExecutor-6-0] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Created new producer: Producer{topic=PersistentTopic{topic=persistent://public/default/testGetPartitions-partition-1}, client=[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected], producerName=standalone-0-154, producerId=5}, role: anonymous 2025-05-20T03:42:45,110+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected]] Subscribing on topic persistent://public/default/testGetPartitions-partition-5 / my-sub. consumerId: 1, role: anonymous 2025-05-20T03:42:45,110+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected]] Subscribing on topic persistent://public/default/testGetPartitions-partition-3 / my-sub. consumerId: 6, role: anonymous 2025-05-20T03:42:45,110+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected]] Subscribing on topic persistent://public/default/testGetPartitions-partition-1 / my-sub. consumerId: 2, role: anonymous 2025-05-20T03:42:45,110+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected]] Subscribing on topic persistent://public/default/testGetPartitions-partition-2 / my-sub. consumerId: 5, role: anonymous 2025-05-20T03:42:45,110+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected]] Subscribing on topic persistent://public/default/testGetPartitions-partition-0 / my-sub. consumerId: 4, role: anonymous 2025-05-20T03:42:45,110+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected]] Subscribing on topic persistent://public/default/testGetPartitions-partition-4 / my-sub. consumerId: 3, role: anonymous 2025-05-20T03:42:45,115+0000 [ForkJoinPool.commonPool-worker-4] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/default/persistent/testGetPartitions-partition-2] Cursor my-sub recovered to position 236:-1 2025-05-20T03:42:45,115+0000 [ForkJoinPool.commonPool-worker-8] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/default/persistent/testGetPartitions-partition-5] Cursor my-sub recovered to position 235:-1 2025-05-20T03:42:45,115+0000 [ForkJoinPool.commonPool-worker-1] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/default/persistent/testGetPartitions-partition-1] Cursor my-sub recovered to position 237:-1 2025-05-20T03:42:45,115+0000 [ForkJoinPool.commonPool-worker-5] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/default/persistent/testGetPartitions-partition-3] Cursor my-sub recovered to position 234:-1 2025-05-20T03:42:45,115+0000 [ForkJoinPool.commonPool-worker-4] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/default/persistent/testGetPartitions-partition-0] Cursor my-sub recovered to position 239:-1 2025-05-20T03:42:45,115+0000 [ForkJoinPool.commonPool-worker-1] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/default/persistent/testGetPartitions-partition-4] Cursor my-sub recovered to position 238:-1 2025-05-20T03:42:45,120+0000 [bookkeeper-ml-scheduler-OrderedScheduler-5-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/default/persistent/testGetPartitions-partition-2] Opened new cursor: ManagedCursorImpl{ledger=public/default/persistent/testGetPartitions-partition-2, name=my-sub, ackPos=236:-1, readPos=236:0} 2025-05-20T03:42:45,120+0000 [bookkeeper-ml-scheduler-OrderedScheduler-6-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/default/persistent/testGetPartitions-partition-3] Opened new cursor: ManagedCursorImpl{ledger=public/default/persistent/testGetPartitions-partition-3, name=my-sub, ackPos=234:-1, readPos=234:0} 2025-05-20T03:42:45,120+0000 [bookkeeper-ml-scheduler-OrderedScheduler-4-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/default/persistent/testGetPartitions-partition-0] Opened new cursor: ManagedCursorImpl{ledger=public/default/persistent/testGetPartitions-partition-0, name=my-sub, ackPos=239:-1, readPos=239:0} 2025-05-20T03:42:45,120+0000 [bookkeeper-ml-scheduler-OrderedScheduler-7-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/default/persistent/testGetPartitions-partition-5] Opened new cursor: ManagedCursorImpl{ledger=public/default/persistent/testGetPartitions-partition-5, name=my-sub, ackPos=235:-1, readPos=235:0} 2025-05-20T03:42:45,121+0000 [bookkeeper-ml-scheduler-OrderedScheduler-5-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/default/persistent/testGetPartitions-partition-1] Opened new cursor: ManagedCursorImpl{ledger=public/default/persistent/testGetPartitions-partition-1, name=my-sub, ackPos=237:-1, readPos=237:0} 2025-05-20T03:42:45,121+0000 [bookkeeper-ml-scheduler-OrderedScheduler-6-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/default/persistent/testGetPartitions-partition-4] Opened new cursor: ManagedCursorImpl{ledger=public/default/persistent/testGetPartitions-partition-4, name=my-sub, ackPos=238:-1, readPos=238:0} 2025-05-20T03:42:45,121+0000 [pulsar-transaction-executor-21-1] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/default/persistent/testGetPartitions-partition-3-my-sub] Rewind from 234:0 to 234:0 2025-05-20T03:42:45,121+0000 [pulsar-transaction-executor-17-1] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/default/persistent/testGetPartitions-partition-2-my-sub] Rewind from 236:0 to 236:0 2025-05-20T03:42:45,121+0000 [pulsar-transaction-executor-14-1] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/default/persistent/testGetPartitions-partition-5-my-sub] Rewind from 235:0 to 235:0 2025-05-20T03:42:45,121+0000 [pulsar-transaction-executor-21-1] INFO org.apache.pulsar.broker.service.persistent.PersistentSubscription - backlog for persistent://public/default/testGetPartitions-partition-3 - 0 2025-05-20T03:42:45,121+0000 [pulsar-transaction-executor-14-1] INFO org.apache.pulsar.broker.service.persistent.PersistentSubscription - backlog for persistent://public/default/testGetPartitions-partition-5 - 0 2025-05-20T03:42:45,121+0000 [pulsar-transaction-executor-17-1] INFO org.apache.pulsar.broker.service.persistent.PersistentSubscription - backlog for persistent://public/default/testGetPartitions-partition-2 - 0 2025-05-20T03:42:45,121+0000 [pulsar-transaction-executor-21-1] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Created subscription on topic persistent://public/default/testGetPartitions-partition-3 / my-sub 2025-05-20T03:42:45,121+0000 [pulsar-transaction-executor-17-1] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Created subscription on topic persistent://public/default/testGetPartitions-partition-2 / my-sub 2025-05-20T03:42:45,121+0000 [pulsar-transaction-executor-14-1] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Created subscription on topic persistent://public/default/testGetPartitions-partition-5 / my-sub 2025-05-20T03:42:45,121+0000 [pulsar-transaction-executor-21-1] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/default/persistent/testGetPartitions-partition-0-my-sub] Rewind from 239:0 to 239:0 2025-05-20T03:42:45,121+0000 [pulsar-transaction-executor-15-1] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/default/persistent/testGetPartitions-partition-1-my-sub] Rewind from 237:0 to 237:0 2025-05-20T03:42:45,121+0000 [pulsar-transaction-executor-21-1] INFO org.apache.pulsar.broker.service.persistent.PersistentSubscription - backlog for persistent://public/default/testGetPartitions-partition-0 - 0 2025-05-20T03:42:45,122+0000 [pulsar-transaction-executor-21-1] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Created subscription on topic persistent://public/default/testGetPartitions-partition-0 / my-sub 2025-05-20T03:42:45,122+0000 [pulsar-transaction-executor-17-1] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/default/persistent/testGetPartitions-partition-4-my-sub] Rewind from 238:0 to 238:0 2025-05-20T03:42:45,122+0000 [pulsar-transaction-executor-15-1] INFO org.apache.pulsar.broker.service.persistent.PersistentSubscription - backlog for persistent://public/default/testGetPartitions-partition-1 - 0 2025-05-20T03:42:45,122+0000 [pulsar-transaction-executor-15-1] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Created subscription on topic persistent://public/default/testGetPartitions-partition-1 / my-sub 2025-05-20T03:42:45,122+0000 [pulsar-transaction-executor-17-1] INFO org.apache.pulsar.broker.service.persistent.PersistentSubscription - backlog for persistent://public/default/testGetPartitions-partition-4 - 0 2025-05-20T03:42:45,122+0000 [pulsar-transaction-executor-17-1] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Created subscription on topic persistent://public/default/testGetPartitions-partition-4 / my-sub ... other test cases log 2025-05-20T03:43:15,100+0000 [pulsar-transaction-executor-20-1] WARN org.apache.pulsar.broker.transaction.buffer.impl.TopicTransactionBuffer - Closing topic persistent://public/default/testGetPartitions-partition-5 due to read transaction buffer snapshot while recovering the transaction buffer throw exception java.util.concurrent.TimeoutException: null at java.base/java.util.concurrent.CompletableFuture.timedGet(Unknown Source) ~[?:?] at java.base/java.util.concurrent.CompletableFuture.get(Unknown Source) ~[?:?] at org.apache.pulsar.broker.transaction.buffer.impl.TableView.wait(TableView.java:96) ~[org.apache.pulsar-pulsar-broker-4.0.4.jar:4.0.4] at org.apache.pulsar.broker.transaction.buffer.impl.TableView.readLatest(TableView.java:63) ~[org.apache.pulsar-pulsar-broker-4.0.4.jar:4.0.4] at org.apache.pulsar.broker.transaction.buffer.impl.SingleSnapshotAbortedTxnProcessorImpl.lambda$recoverFromSnapshot$1(SingleSnapshotAbortedTxnProcessorImpl.java:93) ~[org.apache.pulsar-pulsar-broker-4.0.4.jar:4.0.4] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[?:?] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[?:?] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[io.netty-netty-common-4.1.119.Final.jar:4.1.119.Final] at java.base/java.lang.Thread.run(Unknown Source) [?:?] 2025-05-20T03:43:15,100+0000 [pulsar-transaction-executor-16-1] WARN org.apache.pulsar.broker.transaction.buffer.impl.TopicTransactionBuffer - Closing topic persistent://public/default/testGetPartitions-partition-2 due to read transaction buffer snapshot while recovering the transaction buffer throw exception java.util.concurrent.TimeoutException: null at java.base/java.util.concurrent.CompletableFuture.timedGet(Unknown Source) ~[?:?] at java.base/java.util.concurrent.CompletableFuture.get(Unknown Source) ~[?:?] at org.apache.pulsar.broker.transaction.buffer.impl.TableView.wait(TableView.java:96) ~[org.apache.pulsar-pulsar-broker-4.0.4.jar:4.0.4] at org.apache.pulsar.broker.transaction.buffer.impl.TableView.readLatest(TableView.java:63) ~[org.apache.pulsar-pulsar-broker-4.0.4.jar:4.0.4] at org.apache.pulsar.broker.transaction.buffer.impl.SingleSnapshotAbortedTxnProcessorImpl.lambda$recoverFromSnapshot$1(SingleSnapshotAbortedTxnProcessorImpl.java:93) ~[org.apache.pulsar-pulsar-broker-4.0.4.jar:4.0.4] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[?:?] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[?:?] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[io.netty-netty-common-4.1.119.Final.jar:4.1.119.Final] at java.base/java.lang.Thread.run(Unknown Source) [?:?] 2025-05-20T03:43:15,102+0000 [pulsar-transaction-executor-20-1] INFO org.apache.pulsar.broker.service.Producer - Disconnecting producer: Producer{topic=PersistentTopic{topic=persistent://public/default/testGetPartitions-partition-5}, client=[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected], producerName=standalone-0-150, producerId=1}, assignedBrokerLookupData: Optional.empty 2025-05-20T03:43:15,102+0000 [pulsar-transaction-executor-16-1] INFO org.apache.pulsar.broker.service.Producer - Disconnecting producer: Producer{topic=PersistentTopic{topic=persistent://public/default/testGetPartitions-partition-2}, client=[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected], producerName=standalone-0-152, producerId=2}, assignedBrokerLookupData: Optional.empty 2025-05-20T03:43:15,102+0000 [pulsar-transaction-executor-16-1] INFO org.apache.pulsar.broker.service.Consumer - Disconnecting consumer: Consumer{subscription=PersistentSubscription{topic=persistent://public/default/testGetPartitions-partition-2, name=my-sub}, consumerId=5, consumerName=yxwxx, address=[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected]} 2025-05-20T03:43:15,102+0000 [pulsar-transaction-executor-20-1] INFO org.apache.pulsar.broker.service.Consumer - Disconnecting consumer: Consumer{subscription=PersistentSubscription{topic=persistent://public/default/testGetPartitions-partition-5, name=my-sub}, consumerId=1, consumerName=yxwxx, address=[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected]} 2025-05-20T03:43:15,102+0000 [pulsar-transaction-executor-16-1] INFO org.apache.pulsar.broker.service.AbstractDispatcherSingleActiveConsumer - Removing consumer Consumer{subscription=PersistentSubscription{topic=persistent://public/default/testGetPartitions-partition-2, name=my-sub}, consumerId=5, consumerName=yxwxx, address=[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected]} 2025-05-20T03:43:15,102+0000 [pulsar-transaction-executor-20-1] INFO org.apache.pulsar.broker.service.AbstractDispatcherSingleActiveConsumer - Removing consumer Consumer{subscription=PersistentSubscription{topic=persistent://public/default/testGetPartitions-partition-5, name=my-sub}, consumerId=1, consumerName=yxwxx, address=[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected]} 2025-05-20T03:43:15,102+0000 [pulsar-transaction-executor-16-1] INFO org.apache.pulsar.broker.service.persistent.PersistentSubscription - [persistent://public/default/testGetPartitions-partition-2][my-sub] Successfully closed subscription [ManagedCursorImpl{ledger=public/default/persistent/testGetPartitions-partition-2, name=my-sub, ackPos=236:-1, readPos=236:0}] 2025-05-20T03:43:15,102+0000 [pulsar-transaction-executor-20-1] INFO org.apache.pulsar.broker.service.persistent.PersistentSubscription - [persistent://public/default/testGetPartitions-partition-5][my-sub] Successfully closed subscription [ManagedCursorImpl{ledger=public/default/persistent/testGetPartitions-partition-5, name=my-sub, ackPos=235:-1, readPos=235:0}] 2025-05-20T03:43:15,102+0000 [pulsar-transaction-executor-20-1] INFO org.apache.pulsar.broker.service.persistent.PersistentSubscription - [persistent://public/default/testGetPartitions-partition-5][my-sub] Successfully closed the subscription 2025-05-20T03:43:15,102+0000 [pulsar-transaction-executor-16-1] INFO org.apache.pulsar.broker.service.persistent.PersistentSubscription - [persistent://public/default/testGetPartitions-partition-2][my-sub] Successfully closed the subscription 2025-05-20T03:43:15,103+0000 [pulsar-transaction-executor-20-1] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/default/persistent/testGetPartitions-partition-5] Closing managed ledger 2025-05-20T03:43:15,103+0000 [pulsar-transaction-executor-16-1] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/default/persistent/testGetPartitions-partition-2] Closing managed ledger 2025-05-20T03:43:15,104+0000 [pulsar-transaction-executor-16-1] ERROR org.apache.pulsar.broker.transaction.buffer.impl.TopicTransactionBuffer - [persistent://public/default/testGetPartitions-partition-2]Transaction buffer failed to recover snapshot! java.util.concurrent.CompletionException: java.util.concurrent.TimeoutException at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(Unknown Source) ~[?:?] at java.base/java.util.concurrent.CompletableFuture.completeThrowable(Unknown Source) ~[?:?] at java.base/java.util.concurrent.CompletableFuture$UniAccept.tryFire(Unknown Source) ~[?:?] at java.base/java.util.concurrent.CompletableFuture.postComplete(Unknown Source) ~[?:?] at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(Unknown Source) ~[?:?] at org.apache.pulsar.broker.transaction.buffer.impl.SingleSnapshotAbortedTxnProcessorImpl.lambda$recoverFromSnapshot$1(SingleSnapshotAbortedTxnProcessorImpl.java:103) ~[org.apache.pulsar-pulsar-broker-4.0.4.jar:4.0.4] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[?:?] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[?:?] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[io.netty-netty-common-4.1.119.Final.jar:4.1.119.Final] at java.base/java.lang.Thread.run(Unknown Source) [?:?] Caused by: java.util.concurrent.TimeoutException at java.base/java.util.concurrent.CompletableFuture.timedGet(Unknown Source) ~[?:?] at java.base/java.util.concurrent.CompletableFuture.get(Unknown Source) ~[?:?] at org.apache.pulsar.broker.transaction.buffer.impl.TableView.wait(TableView.java:96) ~[org.apache.pulsar-pulsar-broker-4.0.4.jar:4.0.4] at org.apache.pulsar.broker.transaction.buffer.impl.TableView.readLatest(TableView.java:63) ~[org.apache.pulsar-pulsar-broker-4.0.4.jar:4.0.4] at org.apache.pulsar.broker.transaction.buffer.impl.SingleSnapshotAbortedTxnProcessorImpl.lambda$recoverFromSnapshot$1(SingleSnapshotAbortedTxnProcessorImpl.java:93) ~[org.apache.pulsar-pulsar-broker-4.0.4.jar:4.0.4] ... 4 more 2025-05-20T03:43:15,104+0000 [pulsar-transaction-executor-20-1] ERROR org.apache.pulsar.broker.transaction.buffer.impl.TopicTransactionBuffer - [persistent://public/default/testGetPartitions-partition-5]Transaction buffer failed to recover snapshot! java.util.concurrent.CompletionException: java.util.concurrent.TimeoutException at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(Unknown Source) ~[?:?] at java.base/java.util.concurrent.CompletableFuture.completeThrowable(Unknown Source) ~[?:?] at java.base/java.util.concurrent.CompletableFuture$UniAccept.tryFire(Unknown Source) ~[?:?] at java.base/java.util.concurrent.CompletableFuture.postComplete(Unknown Source) ~[?:?] at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(Unknown Source) ~[?:?] at org.apache.pulsar.broker.transaction.buffer.impl.SingleSnapshotAbortedTxnProcessorImpl.lambda$recoverFromSnapshot$1(SingleSnapshotAbortedTxnProcessorImpl.java:103) ~[org.apache.pulsar-pulsar-broker-4.0.4.jar:4.0.4] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[?:?] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[?:?] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[io.netty-netty-common-4.1.119.Final.jar:4.1.119.Final] at java.base/java.lang.Thread.run(Unknown Source) [?:?] Caused by: java.util.concurrent.TimeoutException at java.base/java.util.concurrent.CompletableFuture.timedGet(Unknown Source) ~[?:?] at java.base/java.util.concurrent.CompletableFuture.get(Unknown Source) ~[?:?] at org.apache.pulsar.broker.transaction.buffer.impl.TableView.wait(TableView.java:96) ~[org.apache.pulsar-pulsar-broker-4.0.4.jar:4.0.4] at org.apache.pulsar.broker.transaction.buffer.impl.TableView.readLatest(TableView.java:63) ~[org.apache.pulsar-pulsar-broker-4.0.4.jar:4.0.4] at org.apache.pulsar.broker.transaction.buffer.impl.SingleSnapshotAbortedTxnProcessorImpl.lambda$recoverFromSnapshot$1(SingleSnapshotAbortedTxnProcessorImpl.java:93) ~[org.apache.pulsar-pulsar-broker-4.0.4.jar:4.0.4] ... 4 more 2025-05-20T03:43:15,105+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected]] Subscribing on topic persistent://public/default/testGetPartitions-partition-2 / my-sub. consumerId: 5, role: anonymous 2025-05-20T03:43:15,105+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected]] Subscribing on topic persistent://public/default/testGetPartitions-partition-5 / my-sub. consumerId: 1, role: anonymous 2025-05-20T03:43:15,112+0000 [metadata-store-28-1] WARN org.apache.pulsar.broker.service.AbstractTopic - [persistent://public/default/testGetPartitions-partition-5] Attempting to add producer to a fenced topic 2025-05-20T03:43:15,112+0000 [metadata-store-28-1] WARN org.apache.pulsar.broker.service.AbstractTopic - [persistent://public/default/testGetPartitions-partition-2] Attempting to add producer to a fenced topic 2025-05-20T03:43:15,112+0000 [metadata-store-28-1] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/testGetPartitions-partition-2] Attempting to subscribe to a fenced topic 2025-05-20T03:43:15,112+0000 [metadata-store-28-1] WARN org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860][persistent://public/default/testGetPartitions-partition-2][my-sub] Failed to create consumer: consumerId=5, Topic is temporarily unavailable 2025-05-20T03:43:15,112+0000 [metadata-store-28-1] WARN org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/testGetPartitions-partition-5] Attempting to subscribe to a fenced topic 2025-05-20T03:43:15,112+0000 [metadata-store-28-1] WARN org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860][persistent://public/default/testGetPartitions-partition-5][my-sub] Failed to create consumer: consumerId=1, Topic is temporarily unavailable 2025-05-20T03:43:15,113+0000 [bookkeeper-ml-scheduler-OrderedScheduler-5-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/default/persistent/testGetPartitions-partition-2][my-sub] Closed cursor at md-position=236:-1 2025-05-20T03:43:15,113+0000 [bookkeeper-ml-scheduler-OrderedScheduler-7-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/default/persistent/testGetPartitions-partition-5][my-sub] Closed cursor at md-position=235:-1 2025-05-20T03:43:15,115+0000 [pulsar-io-22-9] WARN org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Failed to add producer to topic persistent://public/default/testGetPartitions-partition-5: producerId=1, Topic is temporarily unavailable 2025-05-20T03:43:15,115+0000 [pulsar-io-22-9] WARN org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Failed to add producer to topic persistent://public/default/testGetPartitions-partition-2: producerId=2, Topic is temporarily unavailable 2025-05-20T03:43:15,117+0000 [bookkeeper-ml-scheduler-OrderedScheduler-5-0] INFO org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/testGetPartitions-partition-2] Topic closed 2025-05-20T03:43:15,117+0000 [bookkeeper-ml-scheduler-OrderedScheduler-7-0] INFO org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/testGetPartitions-partition-5] Topic closed 2025-05-20T03:43:15,124+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Closing consumer: consumerId=4 2025-05-20T03:43:15,124+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.AbstractDispatcherSingleActiveConsumer - Removing consumer Consumer{subscription=PersistentSubscription{topic=persistent://public/default/testGetPartitions-partition-0, name=my-sub}, consumerId=4, consumerName=yxwxx, address=[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected]} 2025-05-20T03:43:15,124+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Closed consumer, consumerId=4 2025-05-20T03:43:15,124+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Closing consumer: consumerId=2 2025-05-20T03:43:15,124+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.AbstractDispatcherSingleActiveConsumer - Removing consumer Consumer{subscription=PersistentSubscription{topic=persistent://public/default/testGetPartitions-partition-1, name=my-sub}, consumerId=2, consumerName=yxwxx, address=[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected]} 2025-05-20T03:43:15,124+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Closed consumer, consumerId=2 2025-05-20T03:43:15,124+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Closing consumer: consumerId=6 2025-05-20T03:43:15,124+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.AbstractDispatcherSingleActiveConsumer - Removing consumer Consumer{subscription=PersistentSubscription{topic=persistent://public/default/testGetPartitions-partition-3, name=my-sub}, consumerId=6, consumerName=yxwxx, address=[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected]} 2025-05-20T03:43:15,124+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Closed consumer, consumerId=6 2025-05-20T03:43:15,125+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Closing consumer: consumerId=3 2025-05-20T03:43:15,125+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.AbstractDispatcherSingleActiveConsumer - Removing consumer Consumer{subscription=PersistentSubscription{topic=persistent://public/default/testGetPartitions-partition-4, name=my-sub}, consumerId=3, consumerName=yxwxx, address=[id: 0x0f7a91ed, L:/127.0.0.1:6650 - R:/127.0.0.1:51860] [SR:127.0.0.1, state:Connected]} 2025-05-20T03:43:15,125+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Closed consumer, consumerId=3 2025-05-20T03:43:15,133+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Closing consumer: consumerId=5 2025-05-20T03:43:15,133+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [5] Consumer was not registered on the connection: /127.0.0.1:51860 2025-05-20T03:43:15,133+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Closing consumer: consumerId=1 2025-05-20T03:43:15,133+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [1] Consumer was not registered on the connection: /127.0.0.1:51860 2025-05-20T03:43:15,134+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [PersistentTopic{topic=persistent://public/default/testGetPartitions-partition-0}][standalone-0-153] Closing producer on cnx /127.0.0.1:51860. producerId=4 2025-05-20T03:43:15,134+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [PersistentTopic{topic=persistent://public/default/testGetPartitions-partition-0}][standalone-0-153] Closed producer on cnx /127.0.0.1:51860. producerId=4 2025-05-20T03:43:15,135+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [PersistentTopic{topic=persistent://public/default/testGetPartitions-partition-1}][standalone-0-154] Closing producer on cnx /127.0.0.1:51860. producerId=5 2025-05-20T03:43:15,135+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [PersistentTopic{topic=persistent://public/default/testGetPartitions-partition-1}][standalone-0-154] Closed producer on cnx /127.0.0.1:51860. producerId=5 2025-05-20T03:43:15,135+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:51860] Producer 2 was not registered on the connection 2025-05-20T03:43:15,135+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [PersistentTopic{topic=persistent://public/default/testGetPartitions-partition-3}][standalone-0-151] Closing producer on cnx /127.0.0.1:51860. producerId=3 2025-05-20T03:43:15,135+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [PersistentTopic{topic=persistent://public/default/testGetPartitions-partition-3}][standalone-0-151] Closed producer on cnx /127.0.0.1:51860. producerId=3 2025-05-20T03:43:15,136+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [PersistentTopic{topic=persistent://public/default/testGetPartitions-partition-4}][standalone-0-155] Closing producer on cnx /127.0.0.1:51860. producerId=6 2025-05-20T03:43:15,136+0000 [pulsar-io-22-9] INFO org.apache.pulsar.broker.service.ServerCnx - [PersistentTopic{topic=persistent://public/default/testGetPartitions-partition-4}][standalone-0-155] Closed producer on cnx /127.0.0.1:51860. producerId=6 ``` ### Reproducing the issue I think the easiest way to reproduce is running `make standalone` Makefile command in pulsar client go root path directory with high memory usage (mine 10.5G/15.4G). ``` /data/code/dev/pulsar-client-go (dev/http-lookup-schema*) # ls -alh 127 ↵ root@VM-152-173-centos total 232K drwxr-xr-x 15 root root 4.0K May 15 15:45 . drwxr-xr-x 13 root root 4.0K Apr 27 21:35 .. -rw-r--r-- 1 root root 1.9K Aug 14 2024 .asf.yaml -rw-r--r-- 1 root root 74K May 6 20:50 CHANGELOG.md -rw-r--r-- 1 root root 2.8K Aug 14 2024 CONTRIBUTING.md drwxr-xr-x 3 root root 4.0K Aug 14 2024 distribution -rw-r--r-- 1 root root 1.8K May 6 20:50 Dockerfile drwxr-xr-x 2 root root 4.0K Aug 14 2024 docs drwxr-xr-x 7 root root 4.0K Aug 14 2024 examples drwxr-xr-x 8 root root 4.0K May 15 15:14 .git drwxr-xr-x 4 root root 4.0K Aug 14 2024 .github -rw-r--r-- 1 root root 172 Feb 25 22:17 .gitignore -rw-r--r-- 1 root root 1.3K Feb 25 22:17 .golangci.yml -rw-r--r-- 1 root root 5.3K May 6 21:03 go.mod -rw-r--r-- 1 root root 34K May 6 20:50 go.sum drwxr-xr-x 5 root root 4.0K May 20 20:36 .idea drwxr-xr-x 9 root root 4.0K Aug 14 2024 integration-tests -rw-r--r-- 1 root root 12K Aug 14 2024 LICENSE -rw-r--r-- 1 root root 898 Aug 14 2024 licenserc.toml drwxr-xr-x 2 root root 4.0K May 20 11:43 logs -rw-r--r-- 1 root root 3.9K May 15 15:14 Makefile -rw-r--r-- 1 root root 167 Aug 14 2024 NOTICE drwxr-xr-x 5 root root 4.0K Feb 25 22:17 oauth2 drwxr-xr-x 2 root root 4.0K Dec 2 10:26 perf drwxr-xr-x 7 root root 4.0K May 15 15:14 pulsar drwxr-xr-x 3 root root 4.0K Aug 14 2024 pulsaradmin -rw-r--r-- 1 root root 6.2K May 6 20:50 README.md drwxr-xr-x 2 root root 4.0K May 15 15:14 scripts -------------------------------------------------------------------------------------------------------------------------------------------------------- /data/code/dev/pulsar-client-go (dev/http-lookup-schema*) # make test_standalone ``` ### Additional information I think this issue might related to https://github.com/apache/pulsar/issues/21916, because this issue also enable compaction and stuck in `reader.readNextAsync()` function https://github.com/apache/pulsar/blob/578591985e54ba998a15cf61a1f89b5fe71c16a8/pulsar-broker/src/main/java/org/apache/pulsar/broker/transaction/buffer/impl/TableView.java#L63 ### Are you willing to submit a PR? - [ ] I'm willing to submit a PR! -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected]
