Reportportal: [v5] Service-API consumer can't connect to RabbitMQ queues during autoscaling

[ivan-sukhomlyn]

Describe the bug

RabbitMQ consumer of Service-API can't connect to the queue due to already connected consumer in exclusive mode by another consumer from another Service-API process.
This situation produces a lot of warnings from Service-API instances that work in autoscaling mode.
Link to the source code related to the issue - https://github.com/reportportal/service-api/blob/74a954601ad9eea14a0650f5c1ae9bd91031e2ba/src/main/java/com/epam/ta/reportportal/core/configs/rabbit/ReportingConfiguration.java#L188

To Reproduce

1. Setup HorizontalPodAutoscaling for Service-API in the Kubernetes cluster with 5 as a maximum number of pods.
2. Deploy Service-API with the following parameters:

RP_AMQP_QUEUES=25
RP_AMQP_QUEUESPERPOD=5

1. Increase traffic to the ReportPortal and make API possible for scaling.
2. HPA increases the desired number of pods to 3, for example.
3. Service-API pods start in the cluster
4. Bunch of warning logs related to consumer connection are present for Service-API

│ api 2020-04-05 14:08:34.230  INFO 1 --- [TaskExecutor-18] o.s.a.r.l.SimpleMessageListenerContainer : Restarting Consumer@426a792: tags=[[]], channel=Cached Rabbit Channel: AMQChannel(amqp://[email protected] │
│ 0.198.96:5672/,155), conn: Proxy@23ec63af Shared Rabbit Connection: SimpleConnection@35524549 [delegate=amqp://[email protected]:5672/, localPort= 48910], acknowledgeMode=AUTO local queue size=0      │
│ api 2020-04-05 14:08:34.486  INFO 1 --- [.20.198.96:5672] o.s.a.r.c.CachingConnectionFactory       : Channel shutdown: channel error; protocol method: #method<channel.close>(reply-code=403, reply-text=ACC │
│ ESS_REFUSED - queue 'reporting.4' in vhost '/' in exclusive use, class-id=60, method-id=20)                                                                                                                  │
│ api 2020-04-05 14:08:35.628  WARN 1 --- [TaskExecutor-18] o.s.a.r.l.SimpleMessageListenerContainer : Exclusive consumer failure: com.rabbitmq.client.ShutdownSignalException: channel error; protocol method │
│ : #method<channel.close>(reply-code=403, reply-text=ACCESS_REFUSED - queue 'reporting.0' in vhost '/' in exclusive use, class-id=60, method-id=20)                                                           │
│ api 2020-04-05 14:08:35.740  INFO 1 --- [TaskExecutor-18] o.s.a.r.l.SimpleMessageListenerContainer : Restarting Consumer@630ca69e: tags=[[]], channel=Cached Rabbit Channel: AMQChannel(amqp://rabbitmq@172. │
│ 20.198.96:5672/,156), conn: Proxy@23ec63af Shared Rabbit Connection: SimpleConnection@35524549 [delegate=amqp://[email protected]:5672/, localPort= 48910], acknowledgeMode=AUTO local queue size=0     │
│ api 2020-04-05 14:08:36.211  INFO 1 --- [.20.198.96:5672] o.s.a.r.c.CachingConnectionFactory       : Channel shutdown: channel error; protocol method: #method<channel.close>(reply-code=403, reply-text=ACC │
│ ESS_REFUSED - queue 'reporting.0' in vhost '/' in exclusive use, class-id=60, method-id=20)                                                                                                                  │
│ api 2020-04-05 14:08:37.740  WARN 1 --- [TaskExecutor-19] o.s.a.r.l.SimpleMessageListenerContainer : Exclusive consumer failure: com.rabbitmq.client.ShutdownSignalException: channel error; protocol method │
│ : #method<channel.close>(reply-code=403, reply-text=ACCESS_REFUSED - queue 'reporting.1' in vhost '/' in exclusive use, class-id=60, method-id=20)                                                           │
│ api 2020-04-05 14:08:37.776  INFO 1 --- [TaskExecutor-19] o.s.a.r.l.SimpleMessageListenerContainer : Restarting Consumer@1f0cf60d: tags=[[]], channel=Cached Rabbit Channel: AMQChannel(amqp://rabbitmq@172. │
│ 20.198.96:5672/,159), conn: Proxy@23ec63af Shared Rabbit Connection: SimpleConnection@35524549 [delegate=amqp://[email protected]:5672/, localPort= 48910], acknowledgeMode=AUTO local queue size=0     │
│ api 2020-04-05 14:08:37.884  INFO 1 --- [.20.198.96:5672] o.s.a.r.c.CachingConnectionFactory       : Channel shutdown: channel error; protocol method: #method<channel.close>(reply-code=403, reply-text=ACC │
│ ESS_REFUSED - queue 'reporting.1' in vhost '/' in exclusive use, class-id=60, method-id=20)                                                                                                                  │
│ api 2020-04-05 14:08:38.564  WARN 1 --- [TaskExecutor-19] o.s.a.r.l.SimpleMessageListenerContainer : Exclusive consumer failure: com.rabbitmq.client.ShutdownSignalException: channel error; protocol method │
│ : #method<channel.close>(reply-code=403, reply-text=ACCESS_REFUSED - queue 'reporting.2' in vhost '/' in exclusive use, class-id=60, method-id=20)                                                           │
│ api 2020-04-05 14:08:38.664  INFO 1 --- [TaskExecutor-19] o.s.a.r.l.SimpleMessageListenerContainer : Restarting Consumer@7fa9ff2b: tags=[[]], channel=Cached Rabbit Channel: AMQChannel(amqp://rabbitmq@172. │
│ 20.198.96:5672/,161), conn: Proxy@23ec63af Shared Rabbit Connection: SimpleConnection@3552454

Expected behavior
Service-API consumers can connect to proper RabbitMQ queues during the scaling process without messages that ACCESS_REFUSED due to exclusive mode usage

Additional context
Service-API version - 5.0.0
RabbitMQ version - 3.8.0

[evjlobanova]

@pbortnik @AlehB @Yumfriez @irynakozak2 Could you please check the issue?

[evjlobanova]

Assigned on @irynakozak2

[irynakozak2]

hello @ivan-sukhomlyn,
issue will be checked on our side

[irynakozak2]

@ivan-sukhomlyn hello,
this case has been checked on our side and all consumers(need some time after starting the service-api service) be connected to all queues and that behavior in the logs is expected(service-api looking over the non-busy queues). Could you please check that all consumers are connected to queues in your case, and if yes, we added the ticket to the backlog for replacing log level "WARN" to log level "INFO".

[ivan-sukhomlyn]

@irynakozak2 Hi,
Thanks for the reply!
In my opinion, the problem is not related to logs. RabbitMQ reports and close requests to of consumers for connection to queues because of they are used in the exclusive mode. More details - https://www.rabbitmq.com/queues.html#properties
During the rolling update process, new pods of an API service always reconnect to queues that produce such logs as mentioned in the description.

If you agree that it's a normal behavior of the system and you really need to use RabbitMQ queues as exclusive with an actual queue deletion after connection closing from the previous consumer (service-api k8s pod), yes - log level can be changed.

[irynakozak2]

@ivan-sukhomlyn yes, as for now, this is normal behavior: the logic 1 consumer per 1 queue was originally designed this way. I've raised the ticket to our backlog for changing the log level. Thanks a lot!