[Bug] Some consumers not reconnecting properly

[merlimat]

Search before asking

• I searched in the issues and found nothing similar.

Version

3.1.1

Minimal reproduce step

After unload or TCP connection reset, some consumers are staying in a non-connected state.

What did you expect to see?

Consumer reconnecting

What did you see instead?

There are 2 attempts to reconnect.

From the broker side, the 1st is successful, although the client immediately tries again. The 2nd attempt fails, because this is an exclusive subscription. After that, there are no more attempts from the consumer.

2023-03-27T02:21:15,665+0000 [pulsar-io-4-11] INFO  org.apache.pulsar.broker.service.AbstractDispatcherSingleActiveConsumer - Removing consumer Consumer{subscription=PersistentSubscription{topic=persistent://public/default/my-topic, name=sub}, consumerId=0, consumerName=consumer-b4p4c, address=/127.0.0.6:45003}
2023-03-27T02:21:16,123+0000 [pulsar-io-4-17] INFO  org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.6:55081] Subscribing on topic persistent://public/default/my-topic / sub
2023-03-27T02:21:16,123+0000 [pulsar-io-4-17] INFO  org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/default/persistent/my-topic-sub] Rewind from 3024288:69842 to 3024288:69784
2023-03-27T02:21:16,123+0000 [pulsar-io-4-17] INFO  org.apache.pulsar.broker.service.persistent.PersistentTopic - [persistent://public/default/my-topic][sub] Created new subscription for 0
2023-03-27T02:21:16,123+0000 [pulsar-io-4-17] INFO  org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.6:55081] Created subscription on topic persistent://public/default/my-topic / sub
2023-03-27T02:21:16,281+0000 [pulsar-io-4-17] INFO  org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.6:55081] Subscribing on topic persistent://public/default/my-topic / sub
2023-03-27T02:21:16,281+0000 [pulsar-io-4-17] INFO  org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.6:55081] Consumer with the same id is already created: consumerId=0, consumer=Consumer{subscription=PersistentSubscription{topic=persistent://public/default/my-topic, name=sub}, consumerId=0, consumerName=consumer-b4p4c, address=/127.0.0.6:55081}

Anything else?

No response

Are you willing to submit a PR?

• I'm willing to submit a PR!

[RobertIndie]

Are there any logs from the client side? I couldn't reproduce the issue in 3.1.1.

[BewareMyPower]

+1. It's hard to infer the reason without any client side logs.

I tried both unloading the topic and killing the JVM process by force. The error logs should be like:

2023-03-29 18:36:56.773 ERROR [140448651929344] ClientConnection:615 | [127.0.0.1:33730 -> 127.0.0.1:6650] Read operation failed: End of file
2023-03-29 18:36:56.773 ERROR [140448651929344] ClientConnection:1198 | [127.0.0.1:33730 -> 127.0.0.1:6650] Connection closed with ConnectError
2023-03-29 18:36:56.773 INFO  [140448651929344] HandlerBase:148 | [0x55b449bd1990, consumer-1, 0] Schedule reconnection in 0.1 s

If the connection cannot be established, the reconnection should be triggered like:

2023-03-29 18:37:57.077 WARN  [140448651929344] ClientConnection:449 | [<none> -> pulsar://localhost:6650] Failed to establish connection: Connection refused
2023-03-29 18:37:57.077 INFO  [140448651929344] ClientConnection:1200 | [<none> -> pulsar://localhost:6650] Connection disconnected
2023-03-29 18:37:57.077 INFO  [140448651929344] HandlerBase:148 | [0x55b449bd1990, consumer-1, 0] Schedule reconnection in 0.368 s

[merlimat]

Yes, it would be easier with client logs, though it's not easy to get them for this case.

[BewareMyPower]

Close it by #328