fmiguelez opened a new issue #9591:
URL: https://github.com/apache/pulsar/issues/9591
**Describe the bug**
We have a SpringBoot application that acts as a Gateway. Client connects
using WebSockets/STOMP and application connects to Pulsar. We have only one
`PulsarClient` instance that creates each `Consumer` or `Reader` associated
with a `STOMP` subscription.
We also expose a REST API to allow operation on namespaces/topics (basically
create or destroy whole namespace+topics).
In our tests we frequently see weird issues related to consumers that
actually fail to close on `close()` method call due to underlying
reconnections. After we call `close()` on specific `Consumer` sometimes we see
`ConsumerImpl` log messages regarding reconnections that **should not happen,
as consumer has already been closed**. We see an example below.
```
2021-02-16 01:34:59.408 INFO 28248 --- [subscriptionMessageSender-7]
c.k.o.d.a.a.s.SubscriptionMessageSender : Subscription stopped:
{sessionId=8f1d0f50-fde0-67d8-6eeb-0677c6d5b6b8, subscriptionId=7, mode=all,
persistent-subscription=test-2021-02-16T01:34:59.177, ack=client,
destination=/test/dummy-objects}
2021-02-16 01:34:59.411 WARN 28248 --- [pulsar-client-io-5-1]
org.apache.pulsar.client.impl.ClientCnx : [id: 0xca0aa6fb, L:/127.0.0.1:55740
- R:localhost/127.0.0.1:6650] Received error from server: Subscription is fenced
2021-02-16 01:34:59.412 WARN 28248 --- [pulsar-client-io-5-1]
o.a.pulsar.client.impl.ConsumerImpl :
[persistent://dbus/test/dummy-objects][test-2021-02-16T01:34:59.177] Failed to
subscribe to topic on localhost/127.0.0.1:6650
2021-02-16 01:34:59.412 WARN 28248 --- [pulsar-client-io-5-1]
o.a.p.client.impl.ConnectionHandler :
[persistent://dbus/test/dummy-objects] [test-2021-02-16T01:34:59.177] Could not
get connection to broker: Subscription is fenced -- Will try again in 0.1 s
2021-02-16 01:34:59.412 WARN 28248 --- [pulsar-client-io-5-1]
org.apache.pulsar.client.impl.ClientCnx : [id: 0xca0aa6fb, L:/127.0.0.1:55740
- R:localhost/127.0.0.1:6650] Received error from server: Subscription is fenced
2021-02-16 01:34:59.412 WARN 28248 --- [pulsar-client-io-5-1]
o.a.pulsar.client.impl.ConsumerImpl :
[persistent://dbus/test/dummy-objects][test-2021-02-16T01:34:59.177] Failed to
subscribe to topic on localhost/127.0.0.1:6650
2021-02-16 01:34:59.413 WARN 28248 --- [pulsar-client-io-5-1]
o.a.p.client.impl.ConnectionHandler :
[persistent://dbus/test/dummy-objects] [test-2021-02-16T01:34:59.177] Could not
get connection to broker: Subscription is fenced -- Will try again in 0.1 s
2021-02-16 01:34:59.413 INFO 28248 --- [pulsar-client-io-5-1]
o.a.pulsar.client.impl.ConsumerImpl :
[persistent://dbus/test/dummy-objects][test-2021-02-16T01:34:59.177]
Successfully reset subscription to message id -1:-1:-1
2021-02-16 01:34:59.418 INFO 28248 --- [pulsar-client-io-5-1]
o.a.pulsar.client.impl.ConsumerImpl :
[persistent://dbus/test/dummy-objects][test-2021-02-16T01:34:59.177] Subscribed
to topic on localhost/127.0.0.1:6650 -- consumer: 32
2021-02-16 01:34:59.420 WARN 28248 --- [subscriptionMessageSender-7]
c.k.o.d.a.a.s.SubscriptionMessageSender : 3 subscriptions still stopping.
Pending by session: {8f1d0f50-fde0-67d8-6eeb-0677c6d5b6b8=[10, 6, 9]}
2021-02-16 01:34:59.420 INFO 28248 --- [subscriptionMessageSender-6]
c.k.o.d.a.a.s.SubscriptionMessageSender : Subscription stopped:
{sessionId=8f1d0f50-fde0-67d8-6eeb-0677c6d5b6b8, subscriptionId=10, mode=all,
persistent-subscription=test-2021-02-16T01:34:59.177, ack=client,
destination=/test/dummy-objects}
2021-02-16 01:34:59.420 WARN 28248 --- [subscriptionMessageSender-6]
c.k.o.d.a.a.s.SubscriptionMessageSender : 2 subscriptions still stopping.
Pending by session: {8f1d0f50-fde0-67d8-6eeb-0677c6d5b6b8=[6, 9]}
2021-02-16 01:34:59.420 INFO 28248 --- [subscriptionMessageSender-4]
c.k.o.d.a.a.s.SubscriptionMessageSender : Subscription stopped:
{sessionId=8f1d0f50-fde0-67d8-6eeb-0677c6d5b6b8, subscriptionId=6, mode=all,
persistent-subscription=test-2021-02-16T01:34:59.177, ack=client,
destination=/test/dummy-objects}
2021-02-16 01:34:59.421 WARN 28248 --- [subscriptionMessageSender-4]
c.k.o.d.a.a.s.SubscriptionMessageSender : 1 subscriptions still stopping.
Pending by session: {8f1d0f50-fde0-67d8-6eeb-0677c6d5b6b8=[9]}
2021-02-16 01:34:59.421 INFO 28248 --- [subscriptionMessageSender-1]
c.k.o.d.a.a.s.SubscriptionMessageSender : Subscription stopped:
{sessionId=8f1d0f50-fde0-67d8-6eeb-0677c6d5b6b8, subscriptionId=9, mode=all,
persistent-subscription=test-2021-02-16T01:34:59.177, ack=client,
destination=/test/dummy-objects}
2021-02-16 01:34:59.421 INFO 28248 --- [subscriptionMessageSender-1]
c.k.o.d.a.a.s.SubscriptionMessageSender : No more subscriptions pending to
stop.
2021-02-16 01:34:59.494 INFO 28248 --- [clientOutboundChannel-17]
c.k.o.d.a.a.listener.AsyncEventListener : Session disconnection detected for
{sessionId:2c361589-01fa-36b5-7a80-e5587ef1df09}
2021-02-16 01:34:59.508 INFO 28248 --- [pulsar-timer-8-1]
o.a.p.client.impl.ConnectionHandler :
[persistent://dbus/test/dummy-objects] [test-2021-02-16T01:34:59.177]
Reconnecting after timeout
2021-02-16 01:34:59.510 INFO 28248 --- [pulsar-client-io-5-1]
o.a.pulsar.client.impl.ConsumerImpl :
[persistent://dbus/test/dummy-objects][test-2021-02-16T01:34:59.177]
Subscribing to topic on cnx [id: 0xca0aa6fb, L:/127.0.0.1:55740 -
R:localhost/127.0.0.1:6650], consumerId 28
2021-02-16 01:34:59.513 INFO 28248 --- [pulsar-timer-8-1]
o.a.p.client.impl.ConnectionHandler :
[persistent://dbus/test/dummy-objects] [test-2021-02-16T01:34:59.177]
Reconnecting after connection was closed
2021-02-16 01:34:59.515 INFO 28248 --- [pulsar-timer-8-1]
o.a.p.client.impl.ConnectionHandler :
[persistent://dbus/test/dummy-objects] [test-2021-02-16T01:34:59.177]
Reconnecting after connection was closed
2021-02-16 01:34:59.515 INFO 28248 --- [pulsar-client-io-5-1]
o.a.pulsar.client.impl.ConsumerImpl :
[persistent://dbus/test/dummy-objects][test-2021-02-16T01:34:59.177]
Subscribing to topic on cnx [id: 0xca0aa6fb, L:/127.0.0.1:55740 -
R:localhost/127.0.0.1:6650], consumerId 31
2021-02-16 01:34:59.518 INFO 28248 --- [pulsar-client-io-5-1]
o.a.pulsar.client.impl.ConsumerImpl :
[persistent://dbus/test/dummy-objects][test-2021-02-16T01:34:59.177]
Subscribing to topic on cnx [id: 0xca0aa6fb, L:/127.0.0.1:55740 -
R:localhost/127.0.0.1:6650], consumerId 30
2021-02-16 01:34:59.518 WARN 28248 --- [pulsar-client-io-5-1]
org.apache.pulsar.client.impl.ClientCnx : [id: 0xca0aa6fb, L:/127.0.0.1:55740
- R:localhost/127.0.0.1:6650] Received error from server: Exclusive consumer is
already connected
2021-02-16 01:34:59.518 WARN 28248 --- [pulsar-client-io-5-1]
o.a.pulsar.client.impl.ConsumerImpl :
[persistent://dbus/test/dummy-objects][test-2021-02-16T01:34:59.177] Failed to
subscribe to topic on localhost/127.0.0.1:6650
2021-02-16 01:34:59.518 WARN 28248 --- [pulsar-client-io-5-1]
o.a.p.client.impl.ConnectionHandler :
[persistent://dbus/test/dummy-objects] [test-2021-02-16T01:34:59.177] Could not
get connection to broker: Exclusive consumer is already connected -- Will try
again in 0.188 s
```
When we see these log messages:
- Any new `Consumer` using same subscription will fail (we limit to max one
consumer)
- Deleting subscriptions using Admin API will result on subscriptions being
recreated (a zombie `Consumer` is still connected)
- Deleting topics with Admin API will cause them to be automatically
recreated (due to the previous subscriptions) if namespace is present, even
when we recreate it (delete and create it again)
**To Reproduce**
Create and close `Consumer` instances with same `PulsarClient` instance.
**Expected behavior**
On the one hand no underlying reconnections that keep subscription (and
consumer) alive once `Consumer.close()` has been called. Consumer should be
effectively killed.
On the other hand if a subscription is deleted using Admin API (directly or
by deleting containing topic or namespace), consumer on the other side using it
should close underlying connection and die (not trying to reconnect).
**Desktop (please complete the following information):**
- OS: Docker Desktop for Windows
**Additional context**
Seen on Pulsar 2.7.0
----------------------------------------------------------------
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.
For queries about this service, please contact Infrastructure at:
[email protected]
