Spring AMQP client auto reconnect but do not consuming binding queue.

[Emre gündoğdu]

Hi,

We are using a cluster that are consist of  3 node EC2 which inside Autoscaling Group running on AWS.We are using peer_discovery plugin on AWS.RabbitMQ application running on EC2 instance behind Elastic Load balancer and each node have plugin list enabled and used.

[rabbitmq_auth_backend_cache,rabbitmq_auth_backend_http,rabbitmq_event_exchange,rabbitmq_management,rabbitmq_mqtt,rabbitmq_peer_discovery_aws].

Each nodes are C5.xlarge machine type running .

Each nodes below filedescriptor setting

[root@ip-172-20-92-239 bin]# sysctl fs.file-nr

fs.file-nr = 1152       0       500000

[root@ip-172-20-92-239 bin]# sysctl fs.file-max

fs.file-max = 500000

[root@ip-172-20-92-239 bin]#

Currently Rabbitmq Cluster Status

root@ip-172-20-92-239 bin]# rabbitmqctl cluster_status

Cluster status of node rab...@ip-172-20-92-239.eu-central-1.compute.internal ...

[{nodes,[{disc,['rab...@ip-172-20-89-6.eu-central-1.compute.internal',

                'rab...@ip-172-20-91-53.eu-central-1.compute.internal',

                'rab...@ip-172-20-92-239.eu-central-1.compute.internal']}]},

 {running_nodes,['rab...@ip-172-20-91-53.eu-central-1.compute.internal',

                 'rab...@ip-172-20-89-6.eu-central-1.compute.internal',

                 'rab...@ip-172-20-92-239.eu-central-1.compute.internal']},

 {cluster_name,<<"rab...@ip-172-20-91-53.eu-central-1.compute.internal">>},

 {partitions,[]},

 {alarms,[{'rab...@ip-172-20-91-53.eu-central-1.compute.internal',[]},

          {'rab...@ip-172-20-89-6.eu-central-1.compute.internal',[]},

          {'rab...@ip-172-20-92-239.eu-central-1.compute.internal',[]}]}]

Currently Used by Below Policies

[root@ip-172-20-92-239 bin]# rabbitmqctl list_policies

Listing policies for vhost "/" ...

vhost   name    pattern apply-to        definition      priority

/       HA Policy       .*      all     {"ha-mode":"all","ha-sync-mode":"automatic","queue-master-locator":"random","queue-mode":"lazy"}        0

Currently now out queues

[root@ip-172-20-92-239 bin]# rabbitmqctl list_queues

Timeout: 60.0 seconds ...

Listing queues for vhost / ...

name    messages

aliveness-test  0

mqtt-subscription-6234f548624a4049952d4da1082ea6c1qos1  0

mqtt-subscription-5878835a4cd343d58e1d54e5912fa28dqos1  0

connection-events-ttl   0

mqtt-subscription-2c26412febe14a21a74dda8b4f63c711qos1  0

mqtt-subscription-006f67b831b94f4cae7bd816e98dcb44qos1  0

mqtt-subscription-c02e1831c8cb4188bc9a67949a287958qos1  0

mqtt-subscription-ceed2495743042fbb7d8a5d726609eb8qos1  0

mqtt-subscription-76a349a3b6d8450a8e607caa64e3bdb2qos1  0

amqpQueue       232025

mqtt-subscription-8d7790ee2e8f4a3596f5d6b2d26df0f4qos1  0

mqtt-subscription-b817abb5b4754403b7aa95016c5d7c36qos1  0

mqtt-subscription-7a7f9ce15d6b4532a2ec71f338d40b21qos1  0

mqtt-subscription-825034de3efb4c4b9af998a070c7bca8qos1  0

mqtt-subscription-91f9cccd500f48ae8be0bccbb3352821qos1  0

mqtt-subscription-e77c04a968e44d4086d38b61a1dc4bb1qos1  0

mqtt-subscription-afac130a235b408e93ef5ff09ff65705qos1  0

mqtt-subscription-fb231880a393422aa8c9f26de5410b63qos1  0

mqtt-subscription-e4088ab2b67d4b679de80ff08ee3795bqos1  0

mqtt-subscription-2b2eced99476468d8fc5422a9d1c15c5qos1  0

mqtt-subscription-7aec85e417b44d068f372ee1c1401422qos1  0

mqtt-subscription-d819e69ea6104bfca596a8b693348dcfqos1  0

mqtt-subscription-e833fa43364e47b6bcf6ec1fe6a2ea32qos1  0

mqtt-subscription-533d61cafe9849e986d4d51a9df3a6e1qos1  0

mqtt-subscription-c77d88b933ca4570a1475d224e86f3c9qos1  0

mqtt-subscription-f266c721e52a4edfb794d88b6925ee8dqos1  0

mqtt-subscription-d11a1898fbd9402194223464b5fd2c74qos1  0

mqtt-subscription-b9809fc0d55f4c1588ab7621f43624a5qos1  0

mqtt-subscription-cfd787db70bf4cf7b6da241a7e017d6cqos1  0

mqtt-subscription-eed2b0ca886543409304ad7af15a747dqos1  0

mqtt-subscription-1e5d75e3813f4c2ba81b028a068dfb30qos1  0

mqtt-subscription-4008680f936348c78c8d881177ea8ba9qos1  0

mqtt-subscription-1f175aa1b1124fa7be7c70e233eb6c81qos1  0

mqtt-subscription-a2c79b5b53204e5da4449f2cd06e48cfqos1  0

mqtt-subscription-d833650f5f6e469eafe60fe281da4005qos1  0

mqtt-subscription-18094595b2894a69a2a5407005bed014qos1  0

mqtt-subscription-8244515b27f04f45b6e2ff93bcb4c9a6qos1  0

mqtt-subscription-24d07051674f4a0ea0a20883c91dba8eqos1  0

mqtt-subscription-cda847f2d6694e3097ab9c7981840b1aqos1  0

mqtt-subscription-afff7493a7c04c8fb523a8e3b153bb90qos1  0

mqtt-subscription-61d7414e2a144f948ec012574eb712a9qos1  0

mqtt-subscription-45e88360d0ec438394f32ceb04a9dee5qos1  0

mqtt-subscription-db29eb9de124412d96dc02f510eaaa40qos1  0

mqtt-subscription-e1a7773bbe764e74a50c040c2e500d7bqos1  0

mqtt-subscription-9aeb33c6677b4e07a933a9bc5758283aqos1  0

Currently Listing AMQP Connection

root@ip-172-20-92-239 bin]# rabbitmqctl list_connections

Listing connections ...

user    peer_host       peer_port       state

rozaydin        172.20.93.96    60990   running

amqpuser        172.20.93.96    61296   running

amqpuser        172.20.88.175   64216   running

rozaydin        172.20.93.96    2094    running

Our Spring Application run 2 ECS task so that are using amqpuser to connection to the broker is shown two that is fine. But when i list amqp consumer from rabbitmqctl there are no any amqp consumer listed which are using amqpuser 

root@ip-172-20-92-239 bin]# rabbitmqctl list_consumers

Listing consumers on vhost / ...

queue_name      channel_pid     consumer_tag    ack_required    prefetch_count  arguments

connection-events-ttl   <rab...@ip-172-20-92-239.eu-central-1.compute.internal.2.22272.0>       amq.ctag-2cYPIdrWpiqaREVEzjRJ-A true    0       []

connection-events-ttl   <rab...@ip-172-20-89-6.eu-central-1.compute.internal.3.10323.0> amq.ctag-0MlJON10riZhttAa3Goj8w true    0       []

And Also In the management UI as Below Consumer Tabs is grayed

We are using Spring AMQP 2.1.7

Why AMQP client stop consuming and put any info, error, warn log to the application log.The problem on there inside Rabbimq cluster configuration or our Spring AMQP code ? 

 At the following time out AMQP consumer getting below error.

019-07-25 02:51:21.882 [INFO ] [ ] [-exec-3] [ o.s.a.rabbit.connection.CachingConnectionFactory:468]: Attempting to connect to: mqtt.connectivity.eu-central-b.internal.mindsphere.io:5672

2019-07-25 02:51:00.116 [ERROR] [ ] [96:5672] [ o.s.a.rabbit.connection.CachingConnectionFactory:1517]: Channel shutdown: connection error

2019-07-25 02:51:00.117 [ERROR] [ ] [96:5672] [ o.s.a.rabbit.connection.CachingConnectionFactory:1517]: Channel shutdown: connection error

2019-07-25 02:51:00.118 [ERROR] [ ] [96:5672] [ o.s.a.rabbit.connection.CachingConnectionFactory:1517]: Channel shutdown: connection error

2019-07-25 02:51:00.120 [ERROR] [ ] [96:5672] [ o.s.a.rabbit.connection.CachingConnectionFactory:1517]: Channel shutdown: connection error

2019-07-25 02:51:00.120 [WARN ] [8ea3488056c74a50862074a6cfb749d7] [hread-9] [ c.s.m.o.p.subscriber.communication.AmqpListener:83]: ShutdownSignal Received for consumerTag: amq.ctag-wCJHNQK5eg36BXnoNmUcbA
com.rabbitmq.client.ShutdownSignalException: connection error
at com.rabbitmq.client.impl.AMQConnection.startShutdown(AMQConnection.java:916)
at com.rabbitmq.client.impl.AMQConnection.shutdown(AMQConnection.java:906)
at com.rabbitmq.client.impl.AMQConnection.handleFailure(AMQConnection.java:706)
at com.rabbitmq.client.impl.AMQConnection.access$400(AMQConnection.java:48)
at com.rabbitmq.client.impl.AMQConnection$MainLoop.run(AMQConnection.java:605)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.io.EOFException: null
at java.io.DataInputStream.readUnsignedByte(DataInputStream.java:290)
at com.rabbitmq.client.impl.Frame.readFrom(Frame.java:91)
at com.rabbitmq.client.impl.SocketFrameHandler.readFrame(SocketFrameHandler.java:164)
at com.rabbitmq.client.impl.AMQConnection$MainLoop.run(AMQConnection.java:596)
... 1 common frames omitted

2019-07-25 02:51:00.121 [WARN ] [ea59fb99895d487eaad6978093cce4f6] [read-12] [ c.s.m.o.p.subscriber.communication.AmqpListener:83]: ShutdownSignal Received for consumerTag: amq.ctag-Tb0iaxEOyXC_kyLXWprLtQ
com.rabbitmq.client.ShutdownSignalException: connection error
at com.rabbitmq.client.impl.AMQConnection.startShutdown(AMQConnection.java:916)
at com.rabbitmq.client.impl.AMQConnection.shutdown(AMQConnection.java:906)
at com.rabbitmq.client.impl.AMQConnection.handleFailure(AMQConnection.java:706)
at com.rabbitmq.client.impl.AMQConnection.access$400(AMQConnection.java:48)
at com.rabbitmq.client.impl.AMQConnection$MainLoop.run(AMQConnection.java:605)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.io.EOFException: null
at java.io.DataInputStream.readUnsignedByte(DataInputStream.java:290)
at com.rabbitmq.client.impl.Frame.readFrom(Frame.java:91)
at com.rabbitmq.client.impl.SocketFrameHandler.readFrame(SocketFrameHandler.java:164)
at com.rabbitmq.client.impl.AMQConnection$MainLoop.run(AMQConnection.java:596)
... 1 common frames omitted

2019-07-25 02:51:21.882 [INFO ] [ ] [-exec-3] [ o.s.a.rabbit.connection.CachingConnectionFactory:468]: Attempting to connect to: mqtt.connectivity.eu-central-b.internal.mindsphere.io:5672

2019-07-25 02:51:21.894 [INFO ] [ ] [-exec-3] [ o.s.a.rabbit.connection.CachingConnectionFactory:496]: Created new connection: cachingConnectionFactory#7331196b:1/SimpleConnection@7b7a0ca6 [delegate=amqp://amqp...@172.20.88.175:5672/, localPort= 54982]

2019-07-25 02:51:57.787 [INFO ] [ ] [-exec-4] [ o.s.a.rabbit.connection.CachingConnectionFactory:468]: Attempting to connect to: mqtt.connectivity.eu-central-b.internal.mindsphere.io:5672

2019-07-25 02:51:57.798 [INFO ] [ ] [-exec-4] [ o.s.a.rabbit.connection.CachingConnectionFactory:496]: Created new connection: cachingConnectionFactory#76f4b65:1/SimpleConnection@ba4231d [delegate=amqp://amqp...@172.20.88.175:5672/, localPort= 40468]

At the Same time when I have look at all cluster members nodes there are several logs releated the AMQP connection as below screenshot.

When We are look at each line details begining of the same time problem occurent on the client side 

2019-07-25 02:51:00.113 [warning] <0.11596.644> closing AMQP connection <0.11596.644> (172.20.93.96:32818 -> 172.20.91.53:5672 - cachingConnectionFactory#7331196b:0, vhost: '/', user: 'amqpuser'):

client unexpectedly closed TCP connection

2019-07-25 02:51:00.113 [warning] <0.30759.664> closing AMQP connection <0.30759.664> (172.20.93.96:11122 -> 172.20.92.239:5672 - cachingConnectionFactory#76f4b65:0, vhost: '/', user: 'amqpuser'):

client unexpectedly closed TCP connection

2019-07-25 02:51:00.113 [warning] <0.13477.663> closing AMQP connection <0.13477.663> (172.20.93.96:20002 -> 172.20.92.239:5672, vhost: '/', user: 'amqpuser'):

client unexpectedly closed TCP connection

2019-07-25 02:51:00.113 [warning] <0.7018.442> closing AMQP connection <0.7018.442> (172.20.93.96:14464 -> 172.20.89.6:5672, vhost: '/', user: 'amqpuser'):

client unexpectedly closed TCP connection

2019-07-25 02:51:21.887 [info] <0.11955.648> accepting AMQP connection <0.11955.648> (172.20.88.175:14088 -> 172.20.91.53:5672)

2019-07-25 02:51:21.891 [info] <0.11955.648> Connection <0.11955.648> (172.20.88.175:14088 -> 172.20.91.53:5672) has a client-provided name: cachingConnectionFactory#7331196b:1

2019-07-25 02:51:21.893 [info] <0.11955.648> connection <0.11955.648> (172.20.88.175:14088 -> 172.20.91.53:5672 - cachingConnectionFactory#7331196b:1): user 'amqpuser' authenticated and granted access to vhost '/'

2019-07-25 02:51:57.792 [info] <0.18534.667> accepting AMQP connection <0.18534.667> (172.20.88.175:31860 -> 172.20.92.239:5672)

2019-07-25 02:51:57.795 [info] <0.18534.667> Connection <0.18534.667> (172.20.88.175:31860 -> 172.20.92.239:5672) has a client-provided name: cachingConnectionFactory#76f4b65:1

2019-07-25 02:51:57.797 [info] <0.18534.667> connection <0.18534.667> (172.20.88.175:31860 -> 172.20.92.239:5672 - cachingConnectionFactory#76f4b65:1): user 'amqpuser' authenticated and granted access to vhost '/'

[Emre gündoğdu]

I have another comment

There 4 task running and connected and consume  queue to the RabbitMQ Cluster. When i test restart one node of the cluster during the restart time one of the 4 consumer (spring amqp) that has been already connected to the restarter node shutdown connection but 1 task did not re consume again but remain task ( Remain 3 consumer) continue consume.

Our Spring Amqp Code connection Factory code block

    public CachingConnectionFactory cachingConnectionFactory(ConnectionFactory connectionFactory) {
        return new CachingConnectionFactory(connectionFactory);
        CachingConnectionFactory cachingConnectionFactory =
                new CachingConnectionFactory(connectionFactory);
}

By default Spring AMQP disable default amqp client autorecovery mechanism then so spring amqp its own autorecovery mechanism but maybe something wrong inside spring amqp client did not auto recovery (connection recovered but do not consume)  when i node restart

We have to set enable to force ampq client autorecory instead of spring amqp client autorecovery from code block ??

        cachingConnectionFactory.getRabbitConnectionFactory().setAutomaticRecoveryEnabled(true);
        return cachingConnectionFactory;

29 Temmuz 2019 Pazartesi 21:18:12 UTC+3 tarihinde Emre gündoğdu yazdı:

Hi,

We are using a cluster that are consist of  3 node EC2 which inside Autoscaling Group running on AWS.We are using peer_discovery plugin on AWS.RabbitMQ application running on EC2 instance behind Elastic Load balancer and each node have plugin list enabled and used.

[rabbitmq_auth_backend_cache,rabbitmq_auth_backend_http,rabbitmq_event_exchange,rabbitmq_management,rabbitmq_mqtt,rabbitmq_peer_discovery_aws].

Each nodes are C5.xlarge machine type running .

Each nodes below filedescriptor setting

[root@ip-172-20-92-239 bin]# sysctl fs.file-nr

fs.file-nr = 1152       0       500000

[root@ip-172-20-92-239 bin]# sysctl fs.file-max

fs.file-max = 500000

[root@ip-172-20-92-239 bin]#

Currently Rabbitmq Cluster Status

root@ip-172-20-92-239 bin]# rabbitmqctl cluster_status

Cluster status of node rab...@ip-172-20-92-239.eu-central-1.compute.internal ...

[{nodes,[{disc,['rabbit@ip-172-20-89-6.eu-central-1.compute.internal',

                'rab...@ip-172-20-91-53.eu-central-1.compute.internal',

                'rab...@ip-172-20-92-239.eu-central-1.compute.internal']}]},

 {running_nodes,['rabbit@ip-172-20-91-53.eu-central-1.compute.internal',

                 'rab...@ip-172-20-89-6.eu-central-1.compute.internal',

                 'rab...@ip-172-20-92-239.eu-central-1.compute.internal']},

 {cluster_name,<<"rabbit@ip-172-20-91-53.eu-central-1.compute.internal">>},

 {partitions,[]},

 {alarms,[{'rabbit@ip-172-20-91-53.eu-central-1.compute.internal',[]},

2019-07-25 02:51:21.894 [INFO ] [ ] [-exec-3] [ o.s.a.rabbit.connection.CachingConnectionFactory:496]: Created new connection: cachingConnectionFactory#7331196b:1/SimpleConnection@7b7a0ca6 [delegate=amqp://amqpuser@172.20.88.175:5672/, localPort= 54982]

2019-07-25 02:51:57.787 [INFO ] [ ] [-exec-4] [ o.s.a.rabbit.connection.CachingConnectionFactory:468]: Attempting to connect to: mqtt.connectivity.eu-central-b.internal.mindsphere.io:5672

2019-07-25 02:51:57.798 [INFO ] [ ] [-exec-4] [ o.s.a.rabbit.connection.CachingConnectionFactory:496]: Created new connection: cachingConnectionFactory#76f4b65:1/SimpleConnection@ba4231d [delegate=amqp://amqpuser@172.20.88.175:5672/, localPort= 40468]

[Gary Russell]

You should ask questions about Spring on Stack Overflow, not here.

There will be diagnostic information in the application logs.

The listener container will stop itself if it can't passively declare the queue in 15 seconds, by default - all this will be logged.

You can increase this time by increasing the declarationRetries (default 3) and/or the failedDeclarationRetryInterval (default 5000ms).

If you can't figure it out from the logs, ask on Stack Overflow, tagged with spring-amqp, upload the application logs someplace 

(pastebin, github gist etc) and put a link in the question. Also show all of your Spring configuration.

Turning on autorecovery in the amqp-client won't make any difference.

[{nodes,[{disc,['rab...@ip-172-20-89-6.eu-central-1.compute.internal',

                'rab...@ip-172-20-91-53.eu-central-1.compute.internal',

                'rab...@ip-172-20-92-239.eu-central-1.compute.internal']}]},

 {running_nodes,['rab...@ip-172-20-91-53.eu-central-1.compute.internal',

                 'rab...@ip-172-20-89-6.eu-central-1.compute.internal',

                 'rab...@ip-172-20-92-239.eu-central-1.compute.internal']},

 {cluster_name,<<"rab...@ip-172-20-91-53.eu-central-1.compute.internal">>},

 {partitions,[]},

 {alarms,[{'rab...@ip-172-20-91-53.eu-central-1.compute.internal',[]},

2019-07-25 02:51:21.894 [INFO ] [ ] [-exec-3] [ o.s.a.rabbit.connection.CachingConnectionFactory:496]: Created new connection: cachingConnectionFactory#7331196b:1/SimpleConnection@7b7a0ca6 [delegate=amqp://amqp...@172.20.88.175:5672/, localPort= 54982]

2019-07-25 02:51:57.787 [INFO ] [ ] [-exec-4] [ o.s.a.rabbit.connection.CachingConnectionFactory:468]: Attempting to connect to: mqtt.connectivity.eu-central-b.internal.mindsphere.io:5672

2019-07-25 02:51:57.798 [INFO ] [ ] [-exec-4] [ o.s.a.rabbit.connection.CachingConnectionFactory:496]: Created new connection: cachingConnectionFactory#76f4b65:1/SimpleConnection@ba4231d [delegate=amqp://amqp...@172.20.88.175:5672/, localPort= 40468]

At the Same time when I have look at all cluster members nodes there are several logs releated the AMQP connection as below screenshot.

When We are look at each line details begining of the same time problem occurent on the client side 

2019-07-25 02:51:00.113 [warning] <0.11596.644> closing AMQP connection <0.11596.644> (172.20.93.96:32818 -> 172.20.91.53:5672 - cachingConnectionFactory#7331196b:0, vhost: '/', user: 'amqpuser'):

client unexpectedly closed TCP connection

2019-07-25 02:51:00.113 [warning] <0.30759.664> closing AMQP connection <0.30759.664> (172.20.93.96:11122 -> 172.20.92.239:5672 - cachingConnectionFactory#76f4b65:0, vhost: '/', user: 'amqpuser'):

client unexpectedly closed TCP connection

2019-07-25 02:51:00.113 [warning] <0.13477.663> closing AMQP connection <0.13477.663> (172.20.93.96:20002 -> 172.20.92.239:5672, vhost: '/', user: 'amqpuser'):

client unexpectedly closed TCP connection

2019-07-25 02:51:00.113 [warning] <0.7018.442> closing AMQP connection <0.7018.442> (172.20.93.96:14464 -> 172.20.89.6:5672, vhost: '/', user: 'amqpuser'):

client unexpectedly closed TCP connection

2019-07-25 02:51:21.887 [info] <0.11955.648> accepting AMQP connection <0.11955.648> (172.20.88.175:14088 -> 172.20.91.53:5672)

2019-07-25 02:51:21.891 [info] <0.11955.648> Connection <0.11955.648> (172.20.88.175:14088 -> 172.20.91.53:5672) has a client-provided name: cachingConnectionFactory#7331196b:1

2019-07-25 02:51:21.893 [info] <0.11955.648> connection <0.11955.648> (172.20.88.175:14088 -> 172.20.91.53:5672 - cachingConnectionFactory#7331196b:1): user 'amqpuser' authenticated and granted access to vhost '/'

2019-07-25 02:51:57.792 [info] <0.18534.667> accepting AMQP connection <0.18534.667> (172.20.88.175:31860 -> 172.20.92.239:5672)

2019-07-25 02:51:57.795 [info] <0.18534.667> Connection <0.18534.667> (172.20.88.175:31860 -> 172.20.92.239:5672) has a client-provided name: cachingConnectionFactory#76f4b65:1

2019-07-25 02:51:57.797 [info] <0.18534.667> connection <0.18534.667> (172.20.88.175:31860 -> 172.20.92.239:5672 - cachingConnectionFactory#76f4b65:1): user 'amqpuser' authenticated and granted access to vhost '/'

--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/rabbitmq-users/9cd8e761-306f-40b5-9af5-468ad11da7c7%40googlegroups.com.