PerTest/Java or python/pika AMQP client sometimes stops receiving messages from stream queues after connection recovery to a cluster post- rolling upgrade #4114

devkits · 2022-02-05T20:08:21Z

devkits
Feb 5, 2022

Hi everyone,

Looking for some tips that would help me triage and RC the following issue.

PerTest/Java or python/pika AMQP client sometimes stops receiving messages from stream queues after connection recovery to a cluster post- rolling upgrade. On a subsequent manually-induced event that causes another connection drop/recovery messages are received again. Could this be due to cluster/queue configuration or perhaps graceful node shutdown is not happening for some reason(is there a way to check)? Perhaps it's the timing of the connection recovery and the state of a cluster node that is causing this?

Things seem happy otherwise and cluster looks green after each upgrade. Throughput is minimal as I am only focusing testing consumer/producer recovery from cluster upgrades or updates to k8s resource limits.
Note: this is only an issue with stream queues. I cannot reproduce this for quorum queues and connection recovery seems to be much quicker as well.

I think I see this issue with pika (aiopika or regular non-blocking pika) more frequently than with PerfTest, but in the interest of simplicity will only share PerfTest details for now.

Environment: RMQ 3.9.13 on EKS in AWS on a 3-node cluster

PerfTest/Java:
./PerfTest --uri amqp://username:[email protected]:5672 --exchange -x 1 -y 1 -r 0.1 --predeclared -e salt_minion_command_exchange -u salt_minion_command_queue -qos 1

.....
id: test-112729-523, time: 4101.073s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 33063/33063/33063/33063/33063 µs
id: test-112729-523, time: 4111.072s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 40721/40721/40721/40721/40721 µs
id: test-112729-523, time: 4121.074s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 41959/41959/41959/41959/41959 µs
id: test-112729-523, time: 4131.079s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 40798/40798/40798/40798/40798 µs
id: test-112729-523, time: 4141.074s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 32388/32388/32388/32388/32388 µs
id: test-112729-523, time: 4151.076s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 40830/40830/40830/40830/40830 µs
id: test-112729-523, time: 4161.074s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 41892/41892/41892/41892/41892 µs
id: test-112729-523, time: 4171.074s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 41056/41056/41056/41056/41056 µs
id: test-112729-523, time: 4181.074s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 31935/31935/31935/31935/31935 µs
id: test-112729-523, time: 4191.073s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 62032/62032/62032/62032/62032 µs
id: test-112729-523, time: 4201.074s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 32869/32869/32869/32869/32869 µs
id: test-112729-523, time: 4211.074s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 34556/34556/34556/34556/34556 µs
id: test-112729-523, time: 4221.075s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 33656/33656/33656/33656/33656 µs
id: test-112729-523, time: 4231.075s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 38236/38236/38236/38236/38236 µs
id: test-112729-523, time: 4241.075s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4251.070s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4261.074s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4274.085s, sent: 0.08 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
12:38:48.202 [AMQP Connection 3.19.177.182:5672] WARN  com.rabbitmq.perf.Consumer - Error while recovering consumer amq.ctag-rioql23_0AAW1vjHSpDVJA on queue salt_minion_command_queue on connection perf-test-consumer-0
java.io.IOException: null
	at com.rabbitmq.client.impl.AMQChannel.wrap(AMQChannel.java:129)
	at com.rabbitmq.client.impl.AMQChannel.wrap(AMQChannel.java:125)
	at com.rabbitmq.client.impl.ChannelN.basicConsume(ChannelN.java:1384)
	at com.rabbitmq.client.impl.recovery.AutorecoveringChannel.basicConsume(AutorecoveringChannel.java:541)
	at com.rabbitmq.perf.Consumer.recover(Consumer.java:329)
	at com.rabbitmq.perf.Recovery$3.handleRecovery(Recovery.java:85)
	at com.rabbitmq.client.impl.recovery.AutorecoveringConnection.notifyRecoveryListenersComplete(AutorecoveringConnection.java:643)
	at com.rabbitmq.client.impl.recovery.AutorecoveringConnection.beginAutomaticRecovery(AutorecoveringConnection.java:581)
	at com.rabbitmq.client.impl.recovery.AutorecoveringConnection.lambda$addAutomaticRecoveryListener$3(AutorecoveringConnection.java:509)
	at com.rabbitmq.client.impl.AMQConnection.notifyRecoveryCanBeginListeners(AMQConnection.java:817)
	at com.rabbitmq.client.impl.AMQConnection.doFinalShutdown(AMQConnection.java:794)
	at com.rabbitmq.client.impl.AMQConnection$MainLoop.run(AMQConnection.java:678)
	at java.base/java.lang.Thread.run(Thread.java:832)
Caused by: com.rabbitmq.client.ShutdownSignalException: connection error; protocol method: #method<connection.close>(reply-code=506, reply-text=RESOURCE_ERROR - queue 'salt_minion_command_queue' in vhost '/' does not not have a running local replica, class-id=60, method-id=20)
	at com.rabbitmq.utility.ValueOrException.getValue(ValueOrException.java:66)
	at com.rabbitmq.utility.BlockingValueOrException.uninterruptibleGetValue(BlockingValueOrException.java:36)
	at com.rabbitmq.client.impl.AMQChannel$BlockingRpcContinuation.getReply(AMQChannel.java:502)
	at com.rabbitmq.client.impl.ChannelN.basicConsume(ChannelN.java:1378)
	... 10 common frames omitted
id: test-112729-523, time: 4281.074s, sent: 0.14 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4291.075s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4301.075s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 32634/32634/32634/32634/32634 µs
id: test-112729-523, time: 4311.074s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 32546/32546/32546/32546/32546 µs
id: test-112729-523, time: 4321.073s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 34941/34941/34941/34941/34941 µs
id: test-112729-523, time: 4331.072s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 33353/33353/33353/33353/33353 µs
id: test-112729-523, time: 4341.075s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 34334/34334/34334/34334/34334 µs
id: test-112729-523, time: 4351.074s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 37353/37353/37353/37353/37353 µs
id: test-112729-523, time: 4361.073s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 35297/35297/35297/35297/35297 µs
id: test-112729-523, time: 4371.071s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 34960/34960/34960/34960/34960 µs
id: test-112729-523, time: 4381.071s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 38926/38926/38926/38926/38926 µs
id: test-112729-523, time: 4391.075s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 32944/32944/32944/32944/32944 µs
id: test-112729-523, time: 4401.073s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 34352/34352/34352/34352/34352 µs
id: test-112729-523, time: 4411.073s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 42642/42642/42642/42642/42642 µs
id: test-112729-523, time: 4421.073s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 42658/42658/42658/42658/42658 µs
id: test-112729-523, time: 4431.074s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 33551/33551/33551/33551/33551 µs
id: test-112729-523, time: 4441.071s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 34476/34476/34476/34476/34476 µs
id: test-112729-523, time: 4451.071s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 42853/42853/42853/42853/42853 µs
id: test-112729-523, time: 4461.075s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 35407/35407/35407/35407/35407 µs
12:41:50.906 [AMQP Connection 18.189.60.216:5672] WARN  com.rabbitmq.perf.Consumer - Error while recovering consumer amq.ctag-rioql23_0AAW1vjHSpDVJA on queue salt_minion_command_queue on connection perf-test-consumer-0
java.io.IOException: null
	at com.rabbitmq.client.impl.AMQChannel.wrap(AMQChannel.java:129)
	at com.rabbitmq.client.impl.AMQChannel.wrap(AMQChannel.java:125)
	at com.rabbitmq.client.impl.ChannelN.basicConsume(ChannelN.java:1384)
	at com.rabbitmq.client.impl.recovery.AutorecoveringChannel.basicConsume(AutorecoveringChannel.java:541)
	at com.rabbitmq.perf.Consumer.recover(Consumer.java:329)
	at com.rabbitmq.perf.Recovery$3.handleRecovery(Recovery.java:85)
	at com.rabbitmq.client.impl.recovery.AutorecoveringConnection.notifyRecoveryListenersComplete(AutorecoveringConnection.java:643)
	at com.rabbitmq.client.impl.recovery.AutorecoveringConnection.beginAutomaticRecovery(AutorecoveringConnection.java:581)
	at com.rabbitmq.client.impl.recovery.AutorecoveringConnection.lambda$addAutomaticRecoveryListener$3(AutorecoveringConnection.java:509)
	at com.rabbitmq.client.impl.AMQConnection.notifyRecoveryCanBeginListeners(AMQConnection.java:817)
	at com.rabbitmq.client.impl.AMQConnection.doFinalShutdown(AMQConnection.java:794)
	at com.rabbitmq.client.impl.AMQConnection$MainLoop.run(AMQConnection.java:678)
	at java.base/java.lang.Thread.run(Thread.java:832)
Caused by: com.rabbitmq.client.ShutdownSignalException: connection error; protocol method: #method<connection.close>(reply-code=506, reply-text=RESOURCE_ERROR - queue 'salt_minion_command_queue' in vhost '/' does not not have a running local replica, class-id=60, method-id=20)
	at com.rabbitmq.utility.ValueOrException.getValue(ValueOrException.java:66)
	at com.rabbitmq.utility.BlockingValueOrException.uninterruptibleGetValue(BlockingValueOrException.java:36)
	at com.rabbitmq.client.impl.AMQChannel$BlockingRpcContinuation.getReply(AMQChannel.java:502)
	at com.rabbitmq.client.impl.ChannelN.basicConsume(ChannelN.java:1378)
	... 10 common frames omitted
id: test-112729-523, time: 4471.072s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4481.073s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 42592/42592/42592/42592/42592 µs
id: test-112729-523, time: 4491.073s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 35833/35833/35833/35833/35833 µs
id: test-112729-523, time: 4501.071s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 34943/34943/34943/34943/34943 µs
id: test-112729-523, time: 4511.070s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4521.070s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4531.072s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4541.066s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4551.065s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4561.067s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4571.070s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4581.073s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4591.074s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4601.073s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4611.074s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4621.075s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4631.073s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4641.073s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4651.072s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4661.073s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4671.073s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-112729-523, time: 4681.073s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
....

Notice from the above output that first recovery was successful but after another upgrade/recovery the receive message rate dropped to zero. Hopefully I did not misinterpret the output. Thanks.

acogoluegnes · 2022-02-07T07:11:05Z

acogoluegnes
Feb 7, 2022
Maintainer

Thanks for sharing these details.

Do you have steps to reproduce the problem locally?

6 replies

acogoluegnes Feb 7, 2022
Maintainer

I mean a local cluster or even node. Removing layers (cloud, K8S, etc) would help a lot to diagnose the problem.

devkits Feb 7, 2022
Author

Ok, I will spend some time on this.
However, is there an exiting automated test that tests this specific or similar scenario that is part of some CI pipeline? Thanks.

devkits Feb 10, 2022
Author

So I've reproduced this on our private k8s cloud - Calatrava (backed by VMware Tanzu TKG). Only seeing this for stream queues and not quorum queues.
The k8s deployment factor is important for our POC, so I would rather keep this deployment factor.
Client Logs:

➜  scripts ./PerfTest --uri amqp://user:[email protected]:5672 --exchange -x 1 -y 1 -r 0.1 --predeclared -e salt_minion_command_exchange -u salt_minion_command_queue -qos 1 
id: test-205950-072, starting consumer #0
id: test-205950-072, starting consumer #0, channel #0
id: test-205950-072, starting producer #0
id: test-205950-072, starting producer #0, channel #0
id: test-205950-072, time: 2.808s, sent: 0.36 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 12.807s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 100245/100245/100245/100245/100245 µs
id: test-205950-072, time: 22.811s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 95373/95373/95373/95373/95373 µs
id: test-205950-072, time: 32.808s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 96262/96262/96262/96262/96262 µs
id: test-205950-072, time: 42.809s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 96481/96481/96481/96481/96481 µs
id: test-205950-072, time: 52.808s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 96291/96291/96291/96291/96291 µs
id: test-205950-072, time: 62.806s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 93612/93612/93612/93612/93612 µs
id: test-205950-072, time: 72.807s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 96350/96350/96350/96350/96350 µs
id: test-205950-072, time: 82.810s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 102006/102006/102006/102006/102006 µs
id: test-205950-072, time: 92.810s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 92685/92685/92685/92685/92685 µs
id: test-205950-072, time: 102.806s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 96827/96827/96827/96827/96827 µs
id: test-205950-072, time: 112.809s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 93635/93635/93635/93635/93635 µs
id: test-205950-072, time: 122.808s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 94017/94017/94017/94017/94017 µs
id: test-205950-072, time: 132.810s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 97206/97206/97206/97206/97206 µs
id: test-205950-072, time: 142.808s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 94773/94773/94773/94773/94773 µs
id: test-205950-072, time: 152.809s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 94425/94425/94425/94425/94425 µs
id: test-205950-072, time: 162.810s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 97082/97082/97082/97082/97082 µs
id: test-205950-072, time: 172.806s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 95979/95979/95979/95979/95979 µs
id: test-205950-072, time: 182.810s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 93667/93667/93667/93667/93667 µs
id: test-205950-072, time: 192.808s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 94647/94647/94647/94647/94647 µs
id: test-205950-072, time: 202.815s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 96561/96561/96561/96561/96561 µs
id: test-205950-072, time: 212.809s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 98377/98377/98377/98377/98377 µs
id: test-205950-072, time: 222.808s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 96104/96104/96104/96104/96104 µs
id: test-205950-072, time: 232.810s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 100873/100873/100873/100873/100873 µs
id: test-205950-072, time: 242.807s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 95560/95560/95560/95560/95560 µs
id: test-205950-072, time: 252.807s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 92774/92774/92774/92774/92774 µs
id: test-205950-072, time: 262.808s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 93367/93367/93367/93367/93367 µs
id: test-205950-072, time: 272.810s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 96921/96921/96921/96921/96921 µs
id: test-205950-072, time: 282.808s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 104945/104945/104945/104945/104945 µs
21:04:40.569 [RabbitMQ Error On Write Thread] ERROR c.r.perf.RelaxedExceptionHandler - An unexpected connection driver error occured
java.net.SocketException: Broken pipe
	at java.base/sun.nio.ch.NioSocketImpl.implWrite(NioSocketImpl.java:420)
	at java.base/sun.nio.ch.NioSocketImpl.write(NioSocketImpl.java:440)
	at java.base/sun.nio.ch.NioSocketImpl$2.write(NioSocketImpl.java:826)
	at java.base/java.net.Socket$SocketOutputStream.write(Socket.java:1052)
	at java.base/java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:81)
	at java.base/java.io.BufferedOutputStream.flush(BufferedOutputStream.java:142)
	at java.base/java.io.DataOutputStream.flush(DataOutputStream.java:122)
	at com.rabbitmq.client.impl.SocketFrameHandler.flush(SocketFrameHandler.java:197)
	at com.rabbitmq.client.impl.AMQConnection.flush(AMQConnection.java:636)
	at com.rabbitmq.client.impl.AMQCommand.transmit(AMQCommand.java:134)
	at com.rabbitmq.client.impl.AMQChannel.quiescingTransmit(AMQChannel.java:455)
	at com.rabbitmq.client.impl.AMQChannel.quiescingTransmit(AMQChannel.java:434)
	at com.rabbitmq.client.impl.AMQConnection.handleConnectionClose(AMQConnection.java:915)
	at com.rabbitmq.client.impl.AMQConnection.processControlCommand(AMQConnection.java:868)
	at com.rabbitmq.client.impl.AMQConnection$1.processAsync(AMQConnection.java:265)
	at com.rabbitmq.client.impl.AMQChannel.handleCompleteInboundCommand(AMQChannel.java:182)
	at com.rabbitmq.client.impl.AMQChannel.handleFrame(AMQChannel.java:114)
	at com.rabbitmq.client.impl.AMQConnection.readFrame(AMQConnection.java:719)
	at com.rabbitmq.client.impl.AMQConnection.access$300(AMQConnection.java:47)
	at com.rabbitmq.client.impl.AMQConnection$MainLoop.run(AMQConnection.java:666)
	at java.base/java.lang.Thread.run(Thread.java:832)
id: test-205950-072, time: 292.810s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 103773/103773/103773/103773/103773 µs
id: test-205950-072, time: 302.810s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 312.810s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 102715/102715/102715/102715/102715 µs
id: test-205950-072, time: 322.810s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 95799/95799/95799/95799/95799 µs
id: test-205950-072, time: 332.809s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 101352/101352/101352/101352/101352 µs
id: test-205950-072, time: 342.809s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 104517/104517/104517/104517/104517 µs
id: test-205950-072, time: 352.810s, sent: 0.10 msg/s, received: 0.10 msg/s, min/median/75th/95th/99th consumer latency: 94603/94603/94603/94603/94603 µs
21:05:52.848 [RabbitMQ Error On Write Thread] ERROR c.r.perf.RelaxedExceptionHandler - An unexpected connection driver error occured
java.net.SocketException: Broken pipe
	at java.base/sun.nio.ch.NioSocketImpl.implWrite(NioSocketImpl.java:420)
	at java.base/sun.nio.ch.NioSocketImpl.write(NioSocketImpl.java:440)
	at java.base/sun.nio.ch.NioSocketImpl$2.write(NioSocketImpl.java:826)
	at java.base/java.net.Socket$SocketOutputStream.write(Socket.java:1052)
	at java.base/java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:81)
	at java.base/java.io.BufferedOutputStream.flush(BufferedOutputStream.java:142)
	at java.base/java.io.DataOutputStream.flush(DataOutputStream.java:122)
	at com.rabbitmq.client.impl.SocketFrameHandler.flush(SocketFrameHandler.java:197)
	at com.rabbitmq.client.impl.AMQConnection.flush(AMQConnection.java:636)
	at com.rabbitmq.client.impl.AMQCommand.transmit(AMQCommand.java:134)
	at com.rabbitmq.client.impl.AMQChannel.quiescingTransmit(AMQChannel.java:455)
	at com.rabbitmq.client.impl.AMQChannel.quiescingTransmit(AMQChannel.java:434)
	at com.rabbitmq.client.impl.AMQConnection.handleConnectionClose(AMQConnection.java:915)
	at com.rabbitmq.client.impl.AMQConnection.processControlCommand(AMQConnection.java:868)
	at com.rabbitmq.client.impl.AMQConnection$1.processAsync(AMQConnection.java:265)
	at com.rabbitmq.client.impl.AMQChannel.handleCompleteInboundCommand(AMQChannel.java:182)
	at com.rabbitmq.client.impl.AMQChannel.handleFrame(AMQChannel.java:114)
	at com.rabbitmq.client.impl.AMQConnection.readFrame(AMQConnection.java:719)
	at com.rabbitmq.client.impl.AMQConnection.access$300(AMQConnection.java:47)
	at com.rabbitmq.client.impl.AMQConnection$MainLoop.run(AMQConnection.java:666)
	at java.base/java.lang.Thread.run(Thread.java:832)
id: test-205950-072, time: 368.833s, sent: 0.06 msg/s, received: 0.06 msg/s, min/median/75th/95th/99th consumer latency: 94992/94992/94992/94992/94992 µs
id: test-205950-072, time: 372.811s, sent: 0.25 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 382.810s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 392.808s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 402.811s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 412.806s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 422.809s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 432.807s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 442.807s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 452.809s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 462.808s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 472.809s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 482.808s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 492.807s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 502.810s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 512.810s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 522.809s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 532.810s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 542.811s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs
id: test-205950-072, time: 552.807s, sent: 0.10 msg/s, received: 0 msg/s, min/median/75th/95th/99th consumer latency: 0/0/0/0/0 µs

pr-rmq-helm-rabbitmq.zip

Server Logs: (attached)

devkits Feb 10, 2022
Author

Debug logs (from a different run):
pr-rmq-helm-rabbitmq_debug.zip

devkits Feb 13, 2022
Author

AFAIK, this was traced to this: #4133

PerTest/Java or python/pika AMQP client sometimes stops receiving messages from stream queues after connection recovery to a cluster post- rolling upgrade #4114

Uh oh!

Uh oh!

devkits Feb 5, 2022

Replies: 1 comment · 6 replies

Uh oh!

acogoluegnes Feb 7, 2022 Maintainer

Uh oh!

acogoluegnes Feb 7, 2022 Maintainer

Uh oh!

Uh oh!

devkits Feb 7, 2022 Author

Uh oh!

Uh oh!

devkits Feb 10, 2022 Author

Uh oh!

devkits Feb 10, 2022 Author

Uh oh!

devkits Feb 13, 2022 Author

devkits
Feb 5, 2022

Replies: 1 comment 6 replies

acogoluegnes
Feb 7, 2022
Maintainer

acogoluegnes Feb 7, 2022
Maintainer

devkits Feb 7, 2022
Author

devkits Feb 10, 2022
Author

devkits Feb 10, 2022
Author

devkits Feb 13, 2022
Author