geniusjoe commented on PR #1434:
URL:
https://github.com/apache/pulsar-client-go/pull/1434#issuecomment-3542398661
@crossoverJie
I'm sorry for late reply. I think this case passed because Unload() is an
async operation and we call Receive() function before it finished.
I modified a little test case to make sure we call Receive() after Unload()
finish, which will fail because subscription still has one unack message:
```Go
consumer, err := client.Subscribe(ConsumerOptions{
Topic: topic,
SubscriptionName: "my-sub",
EnableZeroQueueConsumer: true,
Type: Shared, // using Shared subscription
type to support unack subscription stats
})
...
// send 10 messages
for i := 0; i < 10; i++ {
msg, err := producer.Send(ctx, &ProducerMessage{
Payload: []byte(fmt.Sprintf("hello-%d", i)),
Key: "pulsar",
Properties: map[string]string{
"key-1": "pulsar-1",
},
})
assert.Nil(t, err)
log.Printf("send message: %s", msg.String())
}
log.Println("unloading topic")
topicName, err := utils.GetTopicName(topic)
assert.Nil(t, err)
err = admin.Topics().Unload(*topicName)
assert.Nil(t, err)
log.Println("unloaded topic")
time.Sleep(1 * time.Minute) // wait for topic unload finish
// receive 10 messages
for i := 0; i < 10; i++ {
msg, err := consumer.Receive(context.Background())
if err != nil {
log.Fatal(err)
}
expectMsg := fmt.Sprintf("hello-%d", i)
expectProperties := map[string]string{
"key-1": "pulsar-1",
}
assert.Equal(t, []byte(expectMsg), msg.Payload())
assert.Equal(t, "pulsar", msg.Key())
assert.Equal(t, expectProperties, msg.Properties())
// ack message
err = consumer.Ack(msg)
assert.Nil(t, err)
log.Printf("receive message: %s", msg.ID().String())
}
// send one more message and we do not manually receive it
_, err = producer.Send(ctx, &ProducerMessage{
Payload: []byte(fmt.Sprintf("hello-%d", 11)),
Key: "pulsar",
Properties: map[string]string{
"key-1": "pulsar-1",
},
})
// wait for broker send messages to consumer and topic stats
update finish
time.Sleep(1 * time.Minute)
topicStats, err := admin.Topics().GetStats(*topicName)
for _, subscriptionStats := range topicStats.Subscriptions {
assert.Equal(t, subscriptionStats.Consumers[0].UnAckedMessages,
0)
}
```
<img width="3840" height="1351" alt="WXWorkCapture_17633877849880"
src="https://github.com/user-attachments/assets/6d694b01-96aa-4386-a9ad-51cea9168c1e";
/>
Log below, and we can find that consumer call a `requesting more permits=1`
before receive(), and store received message in messageCh
```Go
2025/11/17 22:10:17 unloading topic
time=2025-11-17T22:10:17.205+08:00 level=DEBUG msg="Got command!
type:CLOSE_PRODUCER close_producer:{producer_id:1
request_id:18446744073709551615} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.205+08:00 level=DEBUG msg="Received command:
type:CLOSE_PRODUCER close_producer:{producer_id:1
request_id:18446744073709551615} -- payload: <nil>"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.205+08:00 level=INFO msg="Broker notification of
Closed producer: 1" remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.205+08:00 level=WARN msg="Connection was closed"
topic=persistent://public/default/my-topic-127315028
producer_name=standalone-1000-30 producerID=1 cnx="<my-pod>:34634 ->
<my-pod>:6650"
time=2025-11-17T22:10:17.205+08:00 level=DEBUG msg="Got command!
type:CLOSE_CONSUMER close_consumer:{consumer_id:1
request_id:18446744073709551615} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.205+08:00 level=DEBUG msg="Received command:
type:CLOSE_CONSUMER close_consumer:{consumer_id:1
request_id:18446744073709551615} -- payload: <nil>"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.205+08:00 level=INFO msg="Broker notification of
Closed consumer: 1" remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.205+08:00 level=DEBUG msg="connection closed and
send to connectClosedCh" consumerID=1 name=dqnmg
topic=persistent://public/default/my-topic-127315028 subscription=my-sub
time=2025-11-17T22:10:17.205+08:00 level=DEBUG msg="runEventsLoop will
reconnect" consumerID=1 name=dqnmg
topic=persistent://public/default/my-topic-127315028 subscription=my-sub
time=2025-11-17T22:10:17.205+08:00 level=DEBUG msg="Getting pooled
connection" logicalAddr=pulsar://localhost:6650
physicalAddr=pulsar://localhost:6650 keySuffix=0
time=2025-11-17T22:10:17.205+08:00 level=DEBUG msg="Found connection in pool
key=localhost:6650-localhost:6650-0 logical_addr=pulsar://localhost:6650
physical_addr=pulsar://localhost:6650"
time=2025-11-17T22:10:17.205+08:00 level=DEBUG msg="Write data: 67"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:10:17.205+08:00 level=INFO msg="runEventsLoop will
reconnect in producer" topic=persistent://public/default/my-topic-127315028
producer_name=standalone-1000-30 producerID=1
time=2025-11-17T22:10:17.205+08:00 level=DEBUG msg="Getting pooled
connection" logicalAddr=pulsar://localhost:6650
physicalAddr=pulsar://localhost:6650 keySuffix=0
time=2025-11-17T22:10:17.205+08:00 level=DEBUG msg="Found connection in pool
key=localhost:6650-localhost:6650-0 logical_addr=pulsar://localhost:6650
physical_addr=pulsar://localhost:6650"
time=2025-11-17T22:10:17.205+08:00 level=DEBUG msg="Write data: 67"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:10:17.207+08:00 level=DEBUG msg="Got command!
type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:7 authoritative:true
proxy_through_service_url:false} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:10:17.207+08:00 level=DEBUG msg="Received command:
type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:7 authoritative:true
proxy_through_service_url:false} -- payload: <nil>"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:10:17.207+08:00 level=DEBUG msg="Got command!
type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:8 authoritative:true
proxy_through_service_url:false} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:10:17.207+08:00 level=DEBUG msg="Received command:
type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:8 authoritative:true
proxy_through_service_url:false} -- payload: <nil>"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:10:17.207+08:00 level=DEBUG msg="Got
topic{persistent://public/default/my-topic-127315028} lookup response:
&{Response:type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:8 authoritative:true
proxy_through_service_url:false} Cnx:0xc0004d4160}"
serviceURL=pulsar://localhost:6650 serviceURL=pulsar://localhost:6650
time=2025-11-17T22:10:17.207+08:00 level=DEBUG msg="Successfully looked up
topic{persistent://public/default/my-topic-127315028} on broker.
pulsar://<my-pod>:6650 / - Use proxy: false"
serviceURL=pulsar://localhost:6650 serviceURL=pulsar://localhost:6650
time=2025-11-17T22:10:17.207+08:00 level=DEBUG msg="Lookup result:
&{pulsar://<my-pod>:6650 pulsar://<my-pod>:6650}"
topic=persistent://public/default/my-topic-127315028
producer_name=standalone-1000-30 producerID=1
time=2025-11-17T22:10:17.207+08:00 level=DEBUG msg="The partition producer
schema is nil" topic=persistent://public/default/my-topic-127315028
producer_name=standalone-1000-30 producerID=1
time=2025-11-17T22:10:17.207+08:00 level=DEBUG msg="Getting pooled
connection" logicalAddr=pulsar://<my-pod>:6650
physicalAddr=pulsar://<my-pod>:6650 keySuffix=0
time=2025-11-17T22:10:17.207+08:00 level=DEBUG msg="Found connection in pool
key=<my-pod>:6650-<my-pod>:6650-0 logical_addr=pulsar://<my-pod>:6650
physical_addr=pulsar://<my-pod>:6650"
time=2025-11-17T22:10:17.207+08:00 level=DEBUG msg="Write data: 94"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.207+08:00 level=DEBUG msg="Got
topic{persistent://public/default/my-topic-127315028} lookup response:
&{Response:type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:7 authoritative:true
proxy_through_service_url:false} Cnx:0xc0004d4160}"
serviceURL=pulsar://localhost:6650 serviceURL=pulsar://localhost:6650
time=2025-11-17T22:10:17.207+08:00 level=DEBUG msg="Successfully looked up
topic{persistent://public/default/my-topic-127315028} on broker.
pulsar://<my-pod>:6650 / - Use proxy: false"
serviceURL=pulsar://localhost:6650 serviceURL=pulsar://localhost:6650
time=2025-11-17T22:10:17.207+08:00 level=DEBUG msg="Lookup result:
&{pulsar://<my-pod>:6650 pulsar://<my-pod>:6650}" consumerID=1 name=dqnmg
topic=persistent://public/default/my-topic-127315028 subscription=my-sub
time=2025-11-17T22:10:17.207+08:00 level=DEBUG msg="The partition consumer
schema is nil" consumerID=1 name=dqnmg
topic=persistent://public/default/my-topic-127315028 subscription=my-sub
time=2025-11-17T22:10:17.207+08:00 level=DEBUG msg="Getting pooled
connection" logicalAddr=pulsar://<my-pod>:6650
physicalAddr=pulsar://<my-pod>:6650 keySuffix=0
time=2025-11-17T22:10:17.207+08:00 level=DEBUG msg="Found connection in pool
key=<my-pod>:6650-<my-pod>:6650-0 logical_addr=pulsar://<my-pod>:6650
physical_addr=pulsar://<my-pod>:6650"
time=2025-11-17T22:10:17.207+08:00 level=DEBUG msg="Write data: 89"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.210+08:00 level=DEBUG msg="Got command! type:ERROR
error:{request_id:9 error:ServiceNotReady
message:\"org.apache.pulsar.broker.service.BrokerServiceException$TopicFencedException:
Topic is temporarily unavailable\"} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.210+08:00 level=DEBUG msg="Received command:
type:ERROR error:{request_id:9 error:ServiceNotReady
message:\"org.apache.pulsar.broker.service.BrokerServiceException$TopicFencedException:
Topic is temporarily unavailable\"} -- payload: <nil>"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.210+08:00 level=ERROR msg="Failed to create
producer at send PRODUCER request"
topic=persistent://public/default/my-topic-127315028
producer_name=standalone-1000-30 producerID=1 error="server error:
ServiceNotReady:
org.apache.pulsar.broker.service.BrokerServiceException$TopicFencedException:
Topic is temporarily unavailable"
time=2025-11-17T22:10:17.210+08:00 level=ERROR msg="Failed to create
producer at reconnect" topic=persistent://public/default/my-topic-127315028
producer_name=standalone-1000-30 producerID=1 error="server error:
ServiceNotReady:
org.apache.pulsar.broker.service.BrokerServiceException$TopicFencedException:
Topic is temporarily unavailable"
time=2025-11-17T22:10:17.210+08:00 level=INFO msg="Reconnecting to broker"
topic=persistent://public/default/my-topic-127315028
producer_name=standalone-1000-30 producerID=1 assignedBrokerURL=""
delayReconnectTime=110.870734ms
time=2025-11-17T22:10:17.210+08:00 level=DEBUG msg="Got command! type:ERROR
error:{request_id:10 error:ServiceNotReady message:\"Topic is temporarily
unavailable\"} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.210+08:00 level=DEBUG msg="Received command:
type:ERROR error:{request_id:10 error:ServiceNotReady message:\"Topic is
temporarily unavailable\"} -- payload: <nil>"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.210+08:00 level=ERROR msg="Failed to create
consumer" consumerID=1 name=dqnmg
topic=persistent://public/default/my-topic-127315028 subscription=my-sub
error="server error: ServiceNotReady: Topic is temporarily unavailable"
time=2025-11-17T22:10:17.210+08:00 level=ERROR msg="Failed to create
consumer at reconnect" consumerID=1 name=dqnmg
topic=persistent://public/default/my-topic-127315028 subscription=my-sub
error="server error: ServiceNotReady: Topic is temporarily unavailable"
time=2025-11-17T22:10:17.210+08:00 level=INFO msg="Reconnecting to broker"
consumerID=1 name=dqnmg topic=persistent://public/default/my-topic-127315028
subscription=my-sub assignedBrokerURL="" delayReconnectTime=112.475971ms
2025/11/17 22:10:17 unloaded topic
time=2025-11-17T22:10:17.321+08:00 level=DEBUG msg="Getting pooled
connection" logicalAddr=pulsar://localhost:6650
physicalAddr=pulsar://localhost:6650 keySuffix=0
time=2025-11-17T22:10:17.321+08:00 level=DEBUG msg="Found connection in pool
key=localhost:6650-localhost:6650-0 logical_addr=pulsar://localhost:6650
physical_addr=pulsar://localhost:6650"
time=2025-11-17T22:10:17.321+08:00 level=DEBUG msg="Write data: 67"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:10:17.322+08:00 level=DEBUG msg="Got command!
type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:11 authoritative:true
proxy_through_service_url:false} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:10:17.322+08:00 level=DEBUG msg="Received command:
type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:11 authoritative:true
proxy_through_service_url:false} -- payload: <nil>"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:10:17.322+08:00 level=DEBUG msg="Got
topic{persistent://public/default/my-topic-127315028} lookup response:
&{Response:type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:11 authoritative:true
proxy_through_service_url:false} Cnx:0xc0004d4160}"
serviceURL=pulsar://localhost:6650 serviceURL=pulsar://localhost:6650
time=2025-11-17T22:10:17.322+08:00 level=DEBUG msg="Successfully looked up
topic{persistent://public/default/my-topic-127315028} on broker.
pulsar://<my-pod>:6650 / - Use proxy: false"
serviceURL=pulsar://localhost:6650 serviceURL=pulsar://localhost:6650
time=2025-11-17T22:10:17.322+08:00 level=DEBUG msg="Lookup result:
&{pulsar://<my-pod>:6650 pulsar://<my-pod>:6650}"
topic=persistent://public/default/my-topic-127315028
producer_name=standalone-1000-30 producerID=1
time=2025-11-17T22:10:17.322+08:00 level=DEBUG msg="The partition producer
schema is nil" topic=persistent://public/default/my-topic-127315028
producer_name=standalone-1000-30 producerID=1
time=2025-11-17T22:10:17.322+08:00 level=DEBUG msg="Getting pooled
connection" logicalAddr=pulsar://<my-pod>:6650
physicalAddr=pulsar://<my-pod>:6650 keySuffix=0
time=2025-11-17T22:10:17.322+08:00 level=DEBUG msg="Found connection in pool
key=<my-pod>:6650-<my-pod>:6650-0 logical_addr=pulsar://<my-pod>:6650
physical_addr=pulsar://<my-pod>:6650"
time=2025-11-17T22:10:17.322+08:00 level=DEBUG msg="Write data: 94"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.323+08:00 level=DEBUG msg="Getting pooled
connection" logicalAddr=pulsar://localhost:6650
physicalAddr=pulsar://localhost:6650 keySuffix=0
time=2025-11-17T22:10:17.323+08:00 level=DEBUG msg="Found connection in pool
key=localhost:6650-localhost:6650-0 logical_addr=pulsar://localhost:6650
physical_addr=pulsar://localhost:6650"
time=2025-11-17T22:10:17.323+08:00 level=DEBUG msg="Write data: 67"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:10:17.324+08:00 level=DEBUG msg="Got command!
type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:13 authoritative:true
proxy_through_service_url:false} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:10:17.324+08:00 level=DEBUG msg="Received command:
type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:13 authoritative:true
proxy_through_service_url:false} -- payload: <nil>"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:10:17.324+08:00 level=DEBUG msg="Got
topic{persistent://public/default/my-topic-127315028} lookup response:
&{Response:type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:13 authoritative:true
proxy_through_service_url:false} Cnx:0xc0004d4160}"
serviceURL=pulsar://localhost:6650 serviceURL=pulsar://localhost:6650
time=2025-11-17T22:10:17.324+08:00 level=DEBUG msg="Successfully looked up
topic{persistent://public/default/my-topic-127315028} on broker.
pulsar://<my-pod>:6650 / - Use proxy: false"
serviceURL=pulsar://localhost:6650 serviceURL=pulsar://localhost:6650
time=2025-11-17T22:10:17.324+08:00 level=DEBUG msg="Lookup result:
&{pulsar://<my-pod>:6650 pulsar://<my-pod>:6650}" consumerID=1 name=dqnmg
topic=persistent://public/default/my-topic-127315028 subscription=my-sub
time=2025-11-17T22:10:17.324+08:00 level=DEBUG msg="The partition consumer
schema is nil" consumerID=1 name=dqnmg
topic=persistent://public/default/my-topic-127315028 subscription=my-sub
time=2025-11-17T22:10:17.324+08:00 level=DEBUG msg="Getting pooled
connection" logicalAddr=pulsar://<my-pod>:6650
physicalAddr=pulsar://<my-pod>:6650 keySuffix=0
time=2025-11-17T22:10:17.324+08:00 level=DEBUG msg="Found connection in pool
key=<my-pod>:6650-<my-pod>:6650-0 logical_addr=pulsar://<my-pod>:6650
physical_addr=pulsar://<my-pod>:6650"
time=2025-11-17T22:10:17.324+08:00 level=DEBUG msg="Write data: 89"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.342+08:00 level=DEBUG msg="Got command!
type:SUCCESS success:{request_id:14} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.342+08:00 level=DEBUG msg="Received command:
type:SUCCESS success:{request_id:14} -- payload: <nil>"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.342+08:00 level=DEBUG msg="Got command!
type:PRODUCER_SUCCESS producer_success:{request_id:12
producer_name:\"standalone-1000-30\" last_sequence_id:-1 schema_version:\"\"
producer_ready:true} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.342+08:00 level=DEBUG msg="Received command:
type:PRODUCER_SUCCESS producer_success:{request_id:12
producer_name:\"standalone-1000-30\" last_sequence_id:-1 schema_version:\"\"
producer_ready:true} -- payload: <nil>" remote_addr=pulsar://<my-pod>:6650
local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.342+08:00 level=INFO msg="Connected producer"
topic=persistent://public/default/my-topic-127315028
producer_name=standalone-1000-30 producerID=1 cnx="<my-pod>:34634 ->
<my-pod>:6650" epoch=2
time=2025-11-17T22:10:17.342+08:00 level=INFO msg="Reconnected producer to
broker" topic=persistent://public/default/my-topic-127315028
producer_name=standalone-1000-30 producerID=1 cnx="<my-pod>:34634 ->
<my-pod>:6650"
time=2025-11-17T22:10:17.342+08:00 level=INFO msg="Connected consumer"
consumerID=1 name=dqnmg topic=persistent://public/default/my-topic-127315028
subscription=my-sub
time=2025-11-17T22:10:17.342+08:00 level=INFO msg="Reconnected consumer to
broker" consumerID=1 name=dqnmg
topic=persistent://public/default/my-topic-127315028 subscription=my-sub
time=2025-11-17T22:10:17.342+08:00 level=INFO msg="zeroQueueConsumer
reconnect, reset availablePermits" consumerID=1 name=dqnmg
topic=persistent://public/default/my-topic-127315028 subscription=my-sub
time=2025-11-17T22:10:17.342+08:00 level=DEBUG msg="requesting more
permits=1 available=1" consumerID=1 name=dqnmg
topic=persistent://public/default/my-topic-127315028 subscription=my-sub
time=2025-11-17T22:10:17.342+08:00 level=DEBUG msg="Write data: 16"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.342+08:00 level=DEBUG msg="dispatcher received
connection event" consumerID=1 name=dqnmg
topic=persistent://public/default/my-topic-127315028 subscription=my-sub
time=2025-11-17T22:10:17.342+08:00 level=DEBUG msg="dispatcher requesting
initial permits=0" consumerID=1 name=dqnmg
topic=persistent://public/default/my-topic-127315028 subscription=my-sub
time=2025-11-17T22:10:17.358+08:00 level=DEBUG msg="Got command!
type:MESSAGE message:{consumer_id:1 message_id:{ledgerId:1273 entryId:0
partition:-1}} with payload size: 112 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.358+08:00 level=DEBUG msg="Received command:
type:MESSAGE message:{consumer_id:1 message_id:{ledgerId:1273 entryId:0
partition:-1}} -- payload: &{[14 1 235 51 7 69 0 0 0 60 10 18 115 116 97 110
100 97 108 111 110 101 45 49 48 48 48 45 51 48 16 0 24 213 227 155 145 169 51
34 17 10 5 107 101 121 45 49 18 8 112 117 108 115 97 114 45 49 50 6 112 117 108
115 97 114 72 42 88 1 0 0 0 31 10 17 10 5 107 101 121 45 49 18 8 112 117 108
115 97 114 45 49 18 6 112 117 108 115 97 114 24 7 64 0 104 101 108 108 111 45
48] 0 112 {{} {} 0} <nil> <nil>}" remote_addr=pulsar://<my-pod>:6650
local_addr=<my-pod>:34634
time=2025-11-17T22:10:17.358+08:00 level=DEBUG msg="Got Message:
consumer_id:1 message_id:{ledgerId:1273 entryId:0 partition:-1}"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:47.129+08:00 level=DEBUG msg="Got command! type:PING
ping:{} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:10:47.129+08:00 level=DEBUG msg="Received command:
type:PING ping:{} -- payload: <nil>" remote_addr=pulsar://localhost:6650
local_addr=127.0.0.1:54964
time=2025-11-17T22:10:47.129+08:00 level=DEBUG msg="Responding to PING
request" remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:10:47.129+08:00 level=DEBUG msg="Write data: 13"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:10:47.133+08:00 level=DEBUG msg="Sending PING"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:10:47.133+08:00 level=DEBUG msg="Write data: 13"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:10:47.133+08:00 level=DEBUG msg="Got command! type:PONG
pong:{} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:10:47.133+08:00 level=DEBUG msg="Received command:
type:PONG pong:{} -- payload: <nil>" remote_addr=pulsar://localhost:6650
local_addr=127.0.0.1:54964
time=2025-11-17T22:10:47.133+08:00 level=DEBUG msg="Received PONG response"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:10:47.137+08:00 level=DEBUG msg="Sending PING"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:47.137+08:00 level=DEBUG msg="Write data: 13"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:47.138+08:00 level=DEBUG msg="Got command! type:PONG
pong:{} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:47.138+08:00 level=DEBUG msg="Received command:
type:PONG pong:{} -- payload: <nil>" remote_addr=pulsar://<my-pod>:6650
local_addr=<my-pod>:34634
time=2025-11-17T22:10:47.138+08:00 level=DEBUG msg="Received PONG response"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:47.138+08:00 level=DEBUG msg="Got command! type:PING
ping:{} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:47.138+08:00 level=DEBUG msg="Received command:
type:PING ping:{} -- payload: <nil>" remote_addr=pulsar://<my-pod>:6650
local_addr=<my-pod>:34634
time=2025-11-17T22:10:47.138+08:00 level=DEBUG msg="Responding to PING
request" remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:10:47.138+08:00 level=DEBUG msg="Write data: 13"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:11:17.129+08:00 level=DEBUG msg="Got command! type:PING
ping:{} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:11:17.129+08:00 level=DEBUG msg="Received command:
type:PING ping:{} -- payload: <nil>" remote_addr=pulsar://localhost:6650
local_addr=127.0.0.1:54964
time=2025-11-17T22:11:17.129+08:00 level=DEBUG msg="Responding to PING
request" remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:11:17.129+08:00 level=DEBUG msg="Write data: 13"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:11:17.132+08:00 level=DEBUG msg="Sending PING"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:11:17.133+08:00 level=DEBUG msg="Write data: 13"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:11:17.133+08:00 level=DEBUG msg="Got command! type:PONG
pong:{} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:11:17.133+08:00 level=DEBUG msg="Received command:
type:PONG pong:{} -- payload: <nil>" remote_addr=pulsar://localhost:6650
local_addr=127.0.0.1:54964
time=2025-11-17T22:11:17.133+08:00 level=DEBUG msg="Received PONG response"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:11:17.138+08:00 level=DEBUG msg="Sending PING"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:11:17.138+08:00 level=DEBUG msg="Write data: 13"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:11:17.138+08:00 level=DEBUG msg="Got command! type:PONG
pong:{} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:11:17.138+08:00 level=DEBUG msg="Received command:
type:PONG pong:{} -- payload: <nil>" remote_addr=pulsar://<my-pod>:6650
local_addr=<my-pod>:34634
time=2025-11-17T22:11:17.138+08:00 level=DEBUG msg="Received PONG response"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:11:17.138+08:00 level=DEBUG msg="Got command! type:PING
ping:{} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:11:17.139+08:00 level=DEBUG msg="Received command:
type:PING ping:{} -- payload: <nil>" remote_addr=pulsar://<my-pod>:6650
local_addr=<my-pod>:34634
time=2025-11-17T22:11:17.139+08:00 level=DEBUG msg="Responding to PING
request" remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:11:17.139+08:00 level=DEBUG msg="Write data: 13"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:11:17.173+08:00 level=DEBUG msg="Auto discovering new
partitions" topic=my-topic-127315028
time=2025-11-17T22:11:17.174+08:00 level=DEBUG msg="Getting pooled
connection" logicalAddr=pulsar://localhost:6650
physicalAddr=pulsar://localhost:6650 keySuffix=0
time=2025-11-17T22:11:17.174+08:00 level=DEBUG msg="Found connection in pool
key=localhost:6650-localhost:6650-0 logical_addr=pulsar://localhost:6650
physical_addr=pulsar://localhost:6650"
time=2025-11-17T22:11:17.174+08:00 level=DEBUG msg="Write data: 63"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:11:17.175+08:00 level=DEBUG msg="Got command!
type:PARTITIONED_METADATA_RESPONSE partitionMetadataResponse:{partitions:0
request_id:15 response:Success} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:11:17.175+08:00 level=DEBUG msg="Received command:
type:PARTITIONED_METADATA_RESPONSE partitionMetadataResponse:{partitions:0
request_id:15 response:Success} -- payload: <nil>"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:54964
time=2025-11-17T22:11:17.175+08:00 level=DEBUG msg="Got
topic{my-topic-127315028} partitioned metadata response:
&{Response:type:PARTITIONED_METADATA_RESPONSE
partitionMetadataResponse:{partitions:0 request_id:15 response:Success}
Cnx:0xc0004d4160}" serviceURL=pulsar://localhost:6650
serviceURL=pulsar://localhost:6650
time=2025-11-17T22:11:17.175+08:00 level=DEBUG msg="Number of partitions in
topic has not changed" topic=my-topic-127315028
time=2025-11-17T22:11:17.218+08:00 level=DEBUG msg="requesting more
permits=1 available=1" consumerID=1 name=dqnmg
topic=persistent://public/default/my-topic-127315028 subscription=my-sub
2025/11/17 22:11:17 receive message: 1273:0:-1
time=2025-11-17T22:11:17.218+08:00 level=DEBUG msg="requesting more
permits=1 available=1" consumerID=1 name=dqnmg
topic=persistent://public/default/my-topic-127315028 subscription=my-sub
time=2025-11-17T22:11:17.218+08:00 level=DEBUG msg="Write data: 16"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:11:17.218+08:00 level=DEBUG msg="Write data: 16"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:11:17.223+08:00 level=DEBUG msg="Got command!
type:MESSAGE message:{consumer_id:1 message_id:{ledgerId:1273 entryId:1
partition:-1}} with payload size: 112 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:11:17.223+08:00 level=DEBUG msg="Received command:
type:MESSAGE message:{consumer_id:1 message_id:{ledgerId:1273 entryId:1
partition:-1}} -- payload: &{[14 1 23 77 77 45 0 0 0 60 10 18 115 116 97 110
100 97 108 111 110 101 45 49 48 48 48 45 51 48 16 1 24 216 227 155 145 169 51
34 17 10 5 107 101 121 45 49 18 8 112 117 108 115 97 114 45 49 50 6 112 117 108
115 97 114 72 42 88 1 0 0 0 31 10 17 10 5 107 101 121 45 49 18 8 112 117 108
115 97 114 45 49 18 6 112 117 108 115 97 114 24 7 64 1 104 101 108 108 111 45
49] 0 112 {{} {} 0} <nil> <nil>}" remote_addr=pulsar://<my-pod>:6650
local_addr=<my-pod>:34634
time=2025-11-17T22:11:17.223+08:00 level=DEBUG msg="Got Message:
consumer_id:1 message_id:{ledgerId:1273 entryId:1 partition:-1}"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:11:17.223+08:00 level=DEBUG msg="Got command!
type:MESSAGE message:{consumer_id:1 message_id:{ledgerId:1273 entryId:2
partition:-1}} with payload size: 112 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
time=2025-11-17T22:11:17.223+08:00 level=DEBUG msg="Received command:
type:MESSAGE message:{consumer_id:1 message_id:{ledgerId:1273 entryId:2
partition:-1}} -- payload: &{[14 1 124 13 199 141 0 0 0 60 10 18 115 116 97 110
100 97 108 111 110 101 45 49 48 48 48 45 51 48 16 2 24 220 227 155 145 169 51
34 17 10 5 107 101 121 45 49 18 8 112 117 108 115 97 114 45 49 50 6 112 117 108
115 97 114 72 42 88 1 0 0 0 31 10 17 10 5 107 101 121 45 49 18 8 112 117 108
115 97 114 45 49 18 6 112 117 108 115 97 114 24 7 64 2 104 101 108 108 111 45
50] 0 112 {{} {} 0} <nil> <nil>}" remote_addr=pulsar://<my-pod>:6650
local_addr=<my-pod>:34634
time=2025-11-17T22:11:17.223+08:00 level=DEBUG msg="Got Message:
consumer_id:1 message_id:{ledgerId:1273 entryId:2 partition:-1}"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:34634
2025/11/17 22:11:17 receive message: 1273:1:-1
```
<img width="3840" height="1538" alt="image"
src="https://github.com/user-attachments/assets/91ab4fd5-53fb-4c2d-9508-59a5eb9a7f6a";
/>
Below is previous test case, we can found that we called Receive() before
Unload finish, so that the previous flow took no effect, at this time there is
only one permit and test passed:
```
2025/11/17 23:07:49 unloading topic
time=2025-11-17T23:07:49.183+08:00 level=DEBUG msg="Got command!
type:CLOSE_PRODUCER close_producer:{producer_id:1
request_id:18446744073709551615} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.184+08:00 level=DEBUG msg="Received command:
type:CLOSE_PRODUCER close_producer:{producer_id:1
request_id:18446744073709551615} -- payload: <nil>"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.184+08:00 level=INFO msg="Broker notification of
Closed producer: 1" remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.184+08:00 level=WARN msg="Connection was closed"
topic=persistent://public/default/my-topic-90865775
producer_name=standalone-1000-32 producerID=1 cnx="<my-pod>:45038 ->
<my-pod>:6650"
time=2025-11-17T23:07:49.184+08:00 level=DEBUG msg="Got command!
type:CLOSE_CONSUMER close_consumer:{consumer_id:1
request_id:18446744073709551615} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.184+08:00 level=INFO msg="runEventsLoop will
reconnect in producer" topic=persistent://public/default/my-topic-90865775
producer_name=standalone-1000-32 producerID=1
time=2025-11-17T23:07:49.184+08:00 level=DEBUG msg="Received command:
type:CLOSE_CONSUMER close_consumer:{consumer_id:1
request_id:18446744073709551615} -- payload: <nil>"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.184+08:00 level=INFO msg="Broker notification of
Closed consumer: 1" remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.184+08:00 level=DEBUG msg="connection closed and
send to connectClosedCh" topic=persistent://public/default/my-topic-90865775
subscription=my-sub consumerID=1 name=qzrrz
time=2025-11-17T23:07:49.184+08:00 level=DEBUG msg="Getting pooled
connection" logicalAddr=pulsar://localhost:6650
physicalAddr=pulsar://localhost:6650 keySuffix=0
time=2025-11-17T23:07:49.184+08:00 level=DEBUG msg="Found connection in pool
key=localhost:6650-localhost:6650-0 logical_addr=pulsar://localhost:6650
physical_addr=pulsar://localhost:6650"
time=2025-11-17T23:07:49.184+08:00 level=DEBUG msg="Write data: 66"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:47754
time=2025-11-17T23:07:49.184+08:00 level=DEBUG msg="runEventsLoop will
reconnect" topic=persistent://public/default/my-topic-90865775
subscription=my-sub consumerID=1 name=qzrrz
time=2025-11-17T23:07:49.184+08:00 level=DEBUG msg="Getting pooled
connection" logicalAddr=pulsar://localhost:6650
physicalAddr=pulsar://localhost:6650 keySuffix=0
time=2025-11-17T23:07:49.184+08:00 level=DEBUG msg="Found connection in pool
key=localhost:6650-localhost:6650-0 logical_addr=pulsar://localhost:6650
physical_addr=pulsar://localhost:6650"
time=2025-11-17T23:07:49.184+08:00 level=DEBUG msg="Write data: 66"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:47754
time=2025-11-17T23:07:49.184+08:00 level=DEBUG msg="Got command!
type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:7 authoritative:true
proxy_through_service_url:false} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:47754
time=2025-11-17T23:07:49.184+08:00 level=DEBUG msg="Received command:
type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:7 authoritative:true
proxy_through_service_url:false} -- payload: <nil>"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:47754
time=2025-11-17T23:07:49.185+08:00 level=DEBUG msg="Got command!
type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:8 authoritative:true
proxy_through_service_url:false} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:47754
time=2025-11-17T23:07:49.185+08:00 level=DEBUG msg="Received command:
type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:8 authoritative:true
proxy_through_service_url:false} -- payload: <nil>"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:47754
time=2025-11-17T23:07:49.185+08:00 level=DEBUG msg="Got
topic{persistent://public/default/my-topic-90865775} lookup response:
&{Response:type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:8 authoritative:true
proxy_through_service_url:false} Cnx:0xc0000d4000}"
serviceURL=pulsar://localhost:6650 serviceURL=pulsar://localhost:6650
time=2025-11-17T23:07:49.185+08:00 level=DEBUG msg="Successfully looked up
topic{persistent://public/default/my-topic-90865775} on broker.
pulsar://<my-pod>:6650 / - Use proxy: false"
serviceURL=pulsar://localhost:6650 serviceURL=pulsar://localhost:6650
time=2025-11-17T23:07:49.185+08:00 level=DEBUG msg="Lookup result:
&{pulsar://<my-pod>:6650 pulsar://<my-pod>:6650}"
topic=persistent://public/default/my-topic-90865775 subscription=my-sub
consumerID=1 name=qzrrz
time=2025-11-17T23:07:49.185+08:00 level=DEBUG msg="The partition consumer
schema is nil" topic=persistent://public/default/my-topic-90865775
subscription=my-sub consumerID=1 name=qzrrz
time=2025-11-17T23:07:49.185+08:00 level=DEBUG msg="Got
topic{persistent://public/default/my-topic-90865775} lookup response:
&{Response:type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:7 authoritative:true
proxy_through_service_url:false} Cnx:0xc0000d4000}"
serviceURL=pulsar://localhost:6650 serviceURL=pulsar://localhost:6650
time=2025-11-17T23:07:49.185+08:00 level=DEBUG msg="Successfully looked up
topic{persistent://public/default/my-topic-90865775} on broker.
pulsar://<my-pod>:6650 / - Use proxy: false"
serviceURL=pulsar://localhost:6650 serviceURL=pulsar://localhost:6650
time=2025-11-17T23:07:49.185+08:00 level=DEBUG msg="Lookup result:
&{pulsar://<my-pod>:6650 pulsar://<my-pod>:6650}"
topic=persistent://public/default/my-topic-90865775
producer_name=standalone-1000-32 producerID=1
time=2025-11-17T23:07:49.185+08:00 level=DEBUG msg="The partition producer
schema is nil" topic=persistent://public/default/my-topic-90865775
producer_name=standalone-1000-32 producerID=1
time=2025-11-17T23:07:49.185+08:00 level=DEBUG msg="Getting pooled
connection" logicalAddr=pulsar://<my-pod>:6650
physicalAddr=pulsar://<my-pod>:6650 keySuffix=0
time=2025-11-17T23:07:49.185+08:00 level=DEBUG msg="Getting pooled
connection" logicalAddr=pulsar://<my-pod>:6650
physicalAddr=pulsar://<my-pod>:6650 keySuffix=0
time=2025-11-17T23:07:49.185+08:00 level=DEBUG msg="Found connection in pool
key=<my-pod>:6650-<my-pod>:6650-0 logical_addr=pulsar://<my-pod>:6650
physical_addr=pulsar://<my-pod>:6650"
time=2025-11-17T23:07:49.185+08:00 level=DEBUG msg="Write data: 93"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.185+08:00 level=DEBUG msg="Found connection in pool
key=<my-pod>:6650-<my-pod>:6650-0 logical_addr=pulsar://<my-pod>:6650
physical_addr=pulsar://<my-pod>:6650"
time=2025-11-17T23:07:49.186+08:00 level=DEBUG msg="Got command! type:ERROR
error:{request_id:10 error:ServiceNotReady
message:\"org.apache.pulsar.broker.service.BrokerServiceException$TopicFencedException:
Topic is temporarily unavailable\"} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.186+08:00 level=DEBUG msg="Received command:
type:ERROR error:{request_id:10 error:ServiceNotReady
message:\"org.apache.pulsar.broker.service.BrokerServiceException$TopicFencedException:
Topic is temporarily unavailable\"} -- payload: <nil>"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.186+08:00 level=ERROR msg="Failed to create
producer at send PRODUCER request"
topic=persistent://public/default/my-topic-90865775
producer_name=standalone-1000-32 producerID=1 error="server error:
ServiceNotReady:
org.apache.pulsar.broker.service.BrokerServiceException$TopicFencedException:
Topic is temporarily unavailable"
time=2025-11-17T23:07:49.186+08:00 level=ERROR msg="Failed to create
producer at reconnect" topic=persistent://public/default/my-topic-90865775
producer_name=standalone-1000-32 producerID=1 error="server error:
ServiceNotReady:
org.apache.pulsar.broker.service.BrokerServiceException$TopicFencedException:
Topic is temporarily unavailable"
time=2025-11-17T23:07:49.186+08:00 level=INFO msg="Reconnecting to broker"
topic=persistent://public/default/my-topic-90865775
producer_name=standalone-1000-32 producerID=1 assignedBrokerURL=""
delayReconnectTime=112.746658ms
time=2025-11-17T23:07:49.186+08:00 level=DEBUG msg="Write data: 88"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.187+08:00 level=DEBUG msg="Got command! type:ERROR
error:{request_id:9 error:ServiceNotReady message:\"Topic is temporarily
unavailable\"} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.187+08:00 level=DEBUG msg="Received command:
type:ERROR error:{request_id:9 error:ServiceNotReady message:\"Topic is
temporarily unavailable\"} -- payload: <nil>"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.187+08:00 level=ERROR msg="Failed to create
consumer" topic=persistent://public/default/my-topic-90865775
subscription=my-sub consumerID=1 name=qzrrz error="server error:
ServiceNotReady: Topic is temporarily unavailable"
time=2025-11-17T23:07:49.187+08:00 level=ERROR msg="Failed to create
consumer at reconnect" topic=persistent://public/default/my-topic-90865775
subscription=my-sub consumerID=1 name=qzrrz error="server error:
ServiceNotReady: Topic is temporarily unavailable"
time=2025-11-17T23:07:49.187+08:00 level=INFO msg="Reconnecting to broker"
topic=persistent://public/default/my-topic-90865775 subscription=my-sub
consumerID=1 name=qzrrz delayReconnectTime=111.086774ms assignedBrokerURL=""
2025/11/17 23:07:49 unloaded topic
time=2025-11-17T23:07:49.197+08:00 level=DEBUG msg="requesting more
permits=1 available=1" topic=persistent://public/default/my-topic-90865775
subscription=my-sub consumerID=1 name=qzrrz
time=2025-11-17T23:07:49.197+08:00 level=DEBUG msg="Write data: 16"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.299+08:00 level=DEBUG msg="Getting pooled
connection" logicalAddr=pulsar://localhost:6650
physicalAddr=pulsar://localhost:6650 keySuffix=0
time=2025-11-17T23:07:49.299+08:00 level=DEBUG msg="Found connection in pool
key=localhost:6650-localhost:6650-0 logical_addr=pulsar://localhost:6650
physical_addr=pulsar://localhost:6650"
time=2025-11-17T23:07:49.299+08:00 level=DEBUG msg="Write data: 66"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:47754
time=2025-11-17T23:07:49.299+08:00 level=DEBUG msg="Getting pooled
connection" logicalAddr=pulsar://localhost:6650
physicalAddr=pulsar://localhost:6650 keySuffix=0
time=2025-11-17T23:07:49.299+08:00 level=DEBUG msg="Found connection in pool
key=localhost:6650-localhost:6650-0 logical_addr=pulsar://localhost:6650
physical_addr=pulsar://localhost:6650"
time=2025-11-17T23:07:49.299+08:00 level=DEBUG msg="Write data: 66"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:47754
time=2025-11-17T23:07:49.306+08:00 level=DEBUG msg="Got command!
type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:11 authoritative:true
proxy_through_service_url:false} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:47754
time=2025-11-17T23:07:49.306+08:00 level=DEBUG msg="Received command:
type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:11 authoritative:true
proxy_through_service_url:false} -- payload: <nil>"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:47754
time=2025-11-17T23:07:49.306+08:00 level=DEBUG msg="Got command!
type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:12 authoritative:true
proxy_through_service_url:false} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:47754
time=2025-11-17T23:07:49.306+08:00 level=DEBUG msg="Received command:
type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:12 authoritative:true
proxy_through_service_url:false} -- payload: <nil>"
remote_addr=pulsar://localhost:6650 local_addr=127.0.0.1:47754
time=2025-11-17T23:07:49.306+08:00 level=DEBUG msg="Got
topic{persistent://public/default/my-topic-90865775} lookup response:
&{Response:type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:12 authoritative:true
proxy_through_service_url:false} Cnx:0xc0000d4000}"
serviceURL=pulsar://localhost:6650 serviceURL=pulsar://localhost:6650
time=2025-11-17T23:07:49.306+08:00 level=DEBUG msg="Successfully looked up
topic{persistent://public/default/my-topic-90865775} on broker.
pulsar://<my-pod>:6650 / - Use proxy: false"
serviceURL=pulsar://localhost:6650 serviceURL=pulsar://localhost:6650
time=2025-11-17T23:07:49.307+08:00 level=DEBUG msg="Lookup result:
&{pulsar://<my-pod>:6650 pulsar://<my-pod>:6650}"
topic=persistent://public/default/my-topic-90865775
producer_name=standalone-1000-32 producerID=1
time=2025-11-17T23:07:49.307+08:00 level=DEBUG msg="The partition producer
schema is nil" topic=persistent://public/default/my-topic-90865775
producer_name=standalone-1000-32 producerID=1
time=2025-11-17T23:07:49.307+08:00 level=DEBUG msg="Getting pooled
connection" logicalAddr=pulsar://<my-pod>:6650
physicalAddr=pulsar://<my-pod>:6650 keySuffix=0
time=2025-11-17T23:07:49.307+08:00 level=DEBUG msg="Found connection in pool
key=<my-pod>:6650-<my-pod>:6650-0 logical_addr=pulsar://<my-pod>:6650
physical_addr=pulsar://<my-pod>:6650"
time=2025-11-17T23:07:49.307+08:00 level=DEBUG msg="Write data: 93"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.307+08:00 level=DEBUG msg="Got
topic{persistent://public/default/my-topic-90865775} lookup response:
&{Response:type:LOOKUP_RESPONSE
lookupTopicResponse:{brokerServiceUrl:\"pulsar://<my-pod>:6650\"
response:Connect request_id:11 authoritative:true
proxy_through_service_url:false} Cnx:0xc0000d4000}"
serviceURL=pulsar://localhost:6650 serviceURL=pulsar://localhost:6650
time=2025-11-17T23:07:49.307+08:00 level=DEBUG msg="Successfully looked up
topic{persistent://public/default/my-topic-90865775} on broker.
pulsar://<my-pod>:6650 / - Use proxy: false"
serviceURL=pulsar://localhost:6650 serviceURL=pulsar://localhost:6650
time=2025-11-17T23:07:49.307+08:00 level=DEBUG msg="Lookup result:
&{pulsar://<my-pod>:6650 pulsar://<my-pod>:6650}"
topic=persistent://public/default/my-topic-90865775 subscription=my-sub
consumerID=1 name=qzrrz
time=2025-11-17T23:07:49.307+08:00 level=DEBUG msg="The partition consumer
schema is nil" topic=persistent://public/default/my-topic-90865775
subscription=my-sub consumerID=1 name=qzrrz
time=2025-11-17T23:07:49.307+08:00 level=DEBUG msg="Getting pooled
connection" logicalAddr=pulsar://<my-pod>:6650
physicalAddr=pulsar://<my-pod>:6650 keySuffix=0
time=2025-11-17T23:07:49.307+08:00 level=DEBUG msg="Found connection in pool
key=<my-pod>:6650-<my-pod>:6650-0 logical_addr=pulsar://<my-pod>:6650
physical_addr=pulsar://<my-pod>:6650"
time=2025-11-17T23:07:49.307+08:00 level=DEBUG msg="Write data: 88"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.325+08:00 level=DEBUG msg="Got command!
type:SUCCESS success:{request_id:14} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.325+08:00 level=DEBUG msg="Received command:
type:SUCCESS success:{request_id:14} -- payload: <nil>"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.325+08:00 level=INFO msg="Connected consumer"
topic=persistent://public/default/my-topic-90865775 subscription=my-sub
consumerID=1 name=qzrrz
time=2025-11-17T23:07:49.325+08:00 level=INFO msg="Reconnected consumer to
broker" topic=persistent://public/default/my-topic-90865775 subscription=my-sub
consumerID=1 name=qzrrz
time=2025-11-17T23:07:49.325+08:00 level=INFO msg="zeroQueueConsumer
reconnect, reset availablePermits"
topic=persistent://public/default/my-topic-90865775 subscription=my-sub
consumerID=1 name=qzrrz
time=2025-11-17T23:07:49.325+08:00 level=DEBUG msg="requesting more
permits=1 available=1" topic=persistent://public/default/my-topic-90865775
subscription=my-sub consumerID=1 name=qzrrz
time=2025-11-17T23:07:49.325+08:00 level=DEBUG msg="Write data: 16"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.325+08:00 level=DEBUG msg="dispatcher received
connection event" topic=persistent://public/default/my-topic-90865775
subscription=my-sub consumerID=1 name=qzrrz
time=2025-11-17T23:07:49.326+08:00 level=DEBUG msg="dispatcher requesting
initial permits=0" topic=persistent://public/default/my-topic-90865775
subscription=my-sub consumerID=1 name=qzrrz
time=2025-11-17T23:07:49.326+08:00 level=DEBUG msg="Got command!
type:PRODUCER_SUCCESS producer_success:{request_id:13
producer_name:\"standalone-1000-32\" last_sequence_id:-1 schema_version:\"\"
producer_ready:true} with payload size: 0 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.326+08:00 level=DEBUG msg="Received command:
type:PRODUCER_SUCCESS producer_success:{request_id:13
producer_name:\"standalone-1000-32\" last_sequence_id:-1 schema_version:\"\"
producer_ready:true} -- payload: <nil>" remote_addr=pulsar://<my-pod>:6650
local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.326+08:00 level=INFO msg="Connected producer"
topic=persistent://public/default/my-topic-90865775
producer_name=standalone-1000-32 producerID=1 cnx="<my-pod>:45038 ->
<my-pod>:6650" epoch=2
time=2025-11-17T23:07:49.326+08:00 level=INFO msg="Reconnected producer to
broker" topic=persistent://public/default/my-topic-90865775
producer_name=standalone-1000-32 producerID=1 cnx="<my-pod>:45038 ->
<my-pod>:6650"
time=2025-11-17T23:07:49.332+08:00 level=DEBUG msg="Got command!
type:MESSAGE message:{consumer_id:1 message_id:{ledgerId:1278 entryId:0
partition:-1}} with payload size: 112 maxMsgSize: 5242880"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.332+08:00 level=DEBUG msg="Received command:
type:MESSAGE message:{consumer_id:1 message_id:{ledgerId:1278 entryId:0
partition:-1}} -- payload: &{[14 1 172 18 214 12 0 0 0 60 10 18 115 116 97 110
100 97 108 111 110 101 45 49 48 48 48 45 51 50 16 0 24 154 188 238 146 169 51
34 17 10 5 107 101 121 45 49 18 8 112 117 108 115 97 114 45 49 50 6 112 117 108
115 97 114 72 42 88 1 0 0 0 31 10 17 10 5 107 101 121 45 49 18 8 112 117 108
115 97 114 45 49 18 6 112 117 108 115 97 114 24 7 64 0 104 101 108 108 111 45
48] 0 112 {{} {} 0} <nil> <nil>}" remote_addr=pulsar://<my-pod>:6650
local_addr=<my-pod>:45038
time=2025-11-17T23:07:49.332+08:00 level=DEBUG msg="Got Message:
consumer_id:1 message_id:{ledgerId:1278 entryId:0 partition:-1}"
remote_addr=pulsar://<my-pod>:6650 local_addr=<my-pod>:45038
2025/11/17 23:07:49 receive message: 1278:0:-1
```
--
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]
