Spring-amqp: Exceptions when using anonymous, exclusive queues

1
votes

I've got a series of tomcat/spring applications for which messages need to be sent from single instances of several different servers to numerous clients, using a couple of different fanout exchanges. Each server instance has its own set of exchanges. The exchanges are declared by the server, and anonymous queues generated by each client and bound to those exchanges. I'm using anonymous queues because I don't know in advance how many consumers there will be, and of course I can't bind multiple consumers to a single named queue without undermining the nature of the fanout exchange. On the client side, I'm getting a ton of exceptions in my logs relating to attempts to re-declare or delete these anonymous queues.

To paint a clearer picture: Imagine I've got 2 services, Service A and Service B, each of which publishes to a pair of fanout exchanges - say ExchangeA1, ExchangeA2 for service A, and ExchangeB1, ExchangeB2 for service B. Now imagine I've got a single client establishing randomly-named queues bound to each of those 4 exchanges so it can monitor messages from both services.

Messages are sent successfully from the server-side to the exchanges without issue, so I'll leave off the server-side config, though I can provide that if it becomes relevant. Here's the client-side spring-config:

<rabbit:queue id="ClientQ1" />
<rabbit:queue id="ClientQ2" />

<!-- declare the exchanges so we can bind to them -->
<rabbit:fanout-exchange id="ExchangeA1.id" name="ExchangeA1">
    <rabbit:bindings>
        <rabbit:binding queue="ClientQ1"/>
    </rabbit:bindings>
</rabbit:fanout-exchange>

<rabbit:fanout-exchange id="ExchangeA2.id" name="ExchangeA2">
    <rabbit:bindings>
        <rabbit:binding queue="ClientQ2"/>
    </rabbit:bindings>
</rabbit:fanout-exchange>

<rabbit:connection-factory id="rabbitConnectionFactory"  <!-- this is a simple singleton bean that establishes an SSL connection to rabbitmq -->
                        connection-factory="rabbitMQConnectionFactoryBean"
                        publisher-confirms="true"
                        channel-cache-size="5" />

<rabbit:admin id="myRabbitAdmin" connection-factory="rabbitConnectionFactory"/>

<rabbit:listener-container id="rabbitListenerContainer"
                           acknowledge="auto"
                           prefetch="1000"
                           connection-factory="rabbitConnectionFactory"
                           message-converter="EventMessageConverterBean" >

    <rabbit:listener ref="Q1ListenerBean"
                     admin="myRabbitAdmin"
                     method="processEvent"
                     queue-names="#{ClientQ1.name}" />

    <rabbit:listener ref="Q2ListenerBean"
                     admin="myRabbitAdmin"
                     method="processEvent"
                     queue-names="#{ClientQ2.name}" />

</rabbit:listener-container>

Now, imagine that in some other dependency of this client, the same configuration is essentially repeated for bindings to ExchangeB(1,2).

Upon startup, I'm seeing loads of exceptions following this pattern:

ERROR - SimpleMessageListenerContainer$AsyncMessageProcessingConsumer.run(1158) | Consumer received fatal exception on startup
org.springframework.amqp.rabbit.listener.QueuesNotAvailableException: Cannot prepare queue for listener. Either the queue doesn't exist or the broker will not allow us to use it.
at org.springframework.amqp.rabbit.listener.BlockingQueueConsumer.start(BlockingQueueConsumer.java:481)
at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer$AsyncMessageProcessingConsumer.run(SimpleMessageListenerContainer.java:1083)
at java.lang.Thread.run(Thread.java:748)
Caused by: org.springframework.amqp.rabbit.listener.BlockingQueueConsumer$DeclarationException: Failed to declare queue(s):[e4d2b49c-140f-4893-a764-4c84f945d482]
at org.springframework.amqp.rabbit.listener.BlockingQueueConsumer.attemptPassiveDeclarations(BlockingQueueConsumer.java:554)
at org.springframework.amqp.rabbit.listener.BlockingQueueConsumer.start(BlockingQueueConsumer.java:453)
... 2 more
Caused by: java.io.IOException
at com.rabbitmq.client.impl.AMQChannel.wrap(AMQChannel.java:106)
at com.rabbitmq.client.impl.AMQChannel.wrap(AMQChannel.java:102)
at com.rabbitmq.client.impl.AMQChannel.exnWrappingRpc(AMQChannel.java:124)
at com.rabbitmq.client.impl.ChannelN.queueDeclarePassive(ChannelN.java:801)
at com.rabbitmq.client.impl.ChannelN.queueDeclarePassive(ChannelN.java:61)
at sun.reflect.GeneratedMethodAccessor56.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.amqp.rabbit.connection.CachingConnectionFactory$CachedChannelInvocationHandler.invoke(CachingConnectionFactory.java:666)
at com.sun.proxy.$Proxy114.queueDeclarePassive(Unknown Source)
at org.springframework.amqp.rabbit.listener.BlockingQueueConsumer.attemptPassiveDeclarations(BlockingQueueConsumer.java:533)
... 3 more
Caused by: com.rabbitmq.client.ShutdownSignalException: channel error; protocol method: #method<channel.close>(reply-code=405, reply-text=RESOURCE_LOCKED - cannot obtain exclusive access to locked queue 'e4d2b49c-140f-4893-a764-4c84f945d482' in vhost '/', class-id=50, method-id=10)
at com.rabbitmq.utility.ValueOrException.getValue(ValueOrException.java:67)
at com.rabbitmq.utility.BlockingValueOrException.uninterruptibleGetValue(BlockingValueOrException.java:33)
at com.rabbitmq.client.impl.AMQChannel$BlockingRpcContinuation.getReply(AMQChannel.java:343)
at com.rabbitmq.client.impl.AMQChannel.privateRpc(AMQChannel.java:216)
at com.rabbitmq.client.impl.AMQChannel.exnWrappingRpc(AMQChannel.java:118)
... 11 more

My debugging has lead me to the redeclareElementsIfNecessary() method in SimpleMessageListenerContainer(:954), which attempts to redeclare all queues/exhcnages/bindings if any are missing. This fails because rabbitmq will not allow exclusive queues to be redelcared. (or so I think)

Searching for similar issues lead me to this: Spring AMQP v1.4.2 - Rabbit reconnection issue on network failure , which is tangentially related, but the solution is not applicable to my problem. Since anonymous queues are by nature exclusive, and I must use anonymous queues, I seem to be stuck between a rock and a hard place. My questions are these:

  1. Am I doing something wrong w/r/t my listener configuration? Could I change my configuration in some way i'm missing that would alleviate this problem?
  2. Why is redeclareElementsIfNecessary being invoked? It seems to me that all of the queues in question should exist after the first declaration.
  3. Are these errors truly innocuous? If so, how can I go about intercepting them to avoid all the exceptions showing up in my logs?

Any information would be appreciated.

spring-amqp 1.4.6

rabbitmq 3.6.10

Update 1 Some relevant spring-debug log output related to rabbit:admin:

17:22:14,783 DEBUG RabbitAdmin:382 - Initializing declarations
17:22:14,784 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'serviceAExchange1'
17:22:14,784 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'serviceAExchange2'
17:22:14,784 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'serviceBExchange1'
17:22:14,784 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'serviceBExchange2'
17:22:14,784 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'org.springframework.amqp.core.TopicExchange#0'
17:22:14,784 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'org.springframework.amqp.core.TopicExchange#1'
17:22:14,784 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'org.springframework.amqp.core.TopicExchange#2'
17:22:14,784 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'ServiceAQueue1'
17:22:14,784 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'ServiceAQueue2'
17:22:14,784 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'ServiceBQueue1'
17:22:14,784 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'ServiceBQueue2'
17:22:14,784 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'consumer.index.amqp.consumerQueue'
17:22:14,785 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'org.springframework.amqp.rabbit.config.BindingFactoryBean#0'
17:22:14,785 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'org.springframework.amqp.rabbit.config.BindingFactoryBean#1'
17:22:14,786 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'org.springframework.amqp.rabbit.config.BindingFactoryBean#2'
17:22:14,786 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'org.springframework.amqp.rabbit.config.BindingFactoryBean#3'
17:22:14,786 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'org.springframework.amqp.rabbit.config.BindingFactoryBean#4'
17:22:14,786  INFO RabbitAdmin:399 - Auto-declaring a non-durable, auto-delete, or exclusive Queue (07475112-7be0-4c8d-b6e5-3279e81a1aff) durable:false, auto-delete:true, exclusive:true. It will be redeclared if the broker stops and is restarted while the connection factory is alive, but all messages will be lost.
17:22:14,786  INFO RabbitAdmin:399 - Auto-declaring a non-durable, auto-delete, or exclusive Queue (e4825008-954f-4154-bd61-9b67e0ff582e) durable:false, auto-delete:true, exclusive:true. It will be redeclared if the broker stops and is restarted while the connection factory is alive, but all messages will be lost.
17:22:14,786  INFO RabbitAdmin:399 - Auto-declaring a non-durable, auto-delete, or exclusive Queue (001bd357-6203-49a6-b573-7f1a998ff750) durable:false, auto-delete:true, exclusive:true. It will be redeclared if the broker stops and is restarted while the connection factory is alive, but all messages will be lost.
17:22:14,786  INFO RabbitAdmin:399 - Auto-declaring a non-durable, auto-delete, or exclusive Queue (3880a65f-0104-4c99-96ac-1958ace7e2e0) durable:false, auto-delete:true, exclusive:true. It will be redeclared if the broker stops and is restarted while the connection factory is alive, but all messages will be lost.
17:22:14,786  INFO RabbitAdmin:399 - Auto-declaring a non-durable, auto-delete, or exclusive Queue (3b1bc32a-872e-4fc3-ba2a-de200bc7b758) durable:false, auto-delete:true, exclusive:true. It will be redeclared if the broker stops and is restarted while the connection factory is alive, but all messages will be lost.
17:22:14,791  INFO CachingConnectionFactory:213 - Created new connection: SimpleConnection@3158bf2b [delegate=amqp://[email protected]:5671/]
17:22:14,791 DEBUG RabbitAdmin:382 - Initializing declarations
17:22:14,791 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'serviceAExchange1'
17:22:14,791 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'serviceAExchange2'
17:22:14,791 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'serviceBExchange1'
17:22:14,791 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'serviceBExchange2'
17:22:14,791 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'org.springframework.amqp.core.TopicExchange#0'
17:22:14,792 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'org.springframework.amqp.core.TopicExchange#1'
17:22:14,792 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'org.springframework.amqp.core.TopicExchange#2'
17:22:14,792 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'ServiceAQueue1'
17:22:14,792 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'ServiceAQueue2'
17:22:14,792 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'ServiceBQueue1'
17:22:14,792 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'ServiceBQueue2'
17:22:14,792 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'consumer.index.amqp.consumerQueue'
17:22:14,792 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'org.springframework.amqp.rabbit.config.BindingFactoryBean#0'
17:22:14,792 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'org.springframework.amqp.rabbit.config.BindingFactoryBean#1'
17:22:14,792 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'org.springframework.amqp.rabbit.config.BindingFactoryBean#2'
17:22:14,792 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'org.springframework.amqp.rabbit.config.BindingFactoryBean#3'
17:22:14,792 DEBUG DefaultListableBeanFactory:251 - Returning cached instance of singleton bean 'org.springframework.amqp.rabbit.config.BindingFactoryBean#4'
17:22:14,792  INFO RabbitAdmin:399 - Auto-declaring a non-durable, auto-delete, or exclusive Queue (07475112-7be0-4c8d-b6e5-3279e81a1aff) durable:false, auto-delete:true, exclusive:true. It will be redeclared if the broker stops and is restarted while the connection factory is alive, but all messages will be lost.
17:22:14,792  INFO RabbitAdmin:399 - Auto-declaring a non-durable, auto-delete, or exclusive Queue (e4825008-954f-4154-bd61-9b67e0ff582e) durable:false, auto-delete:true, exclusive:true. It will be redeclared if the broker stops and is restarted while the connection factory is alive, but all messages will be lost.
17:22:14,792  INFO RabbitAdmin:399 - Auto-declaring a non-durable, auto-delete, or exclusive Queue (001bd357-6203-49a6-b573-7f1a998ff750) durable:false, auto-delete:true, exclusive:true. It will be redeclared if the broker stops and is restarted while the connection factory is alive, but all messages will be lost.
17:22:14,792  INFO RabbitAdmin:399 - Auto-declaring a non-durable, auto-delete, or exclusive Queue (3880a65f-0104-4c99-96ac-1958ace7e2e0) durable:false, auto-delete:true, exclusive:true. It will be redeclared if the broker stops and is restarted while the connection factory is alive, but all messages will be lost.
17:22:14,792  INFO RabbitAdmin:399 - Auto-declaring a non-durable, auto-delete, or exclusive Queue (3b1bc32a-872e-4fc3-ba2a-de200bc7b758) durable:false, auto-delete:true, exclusive:true. It will be redeclared if the broker stops and is restarted while the connection factory is alive, but all messages will be lost.
17:22:14,811 DEBUG CachingConnectionFactory:395 - Creating cached Rabbit Channel from PublisherCallbackChannelImpl: AMQChannel(amqp://[email protected]:5671/,1)
17:22:14,811 DEBUG CachingConnectionFactory:395 - Creating cached Rabbit Channel from PublisherCallbackChannelImpl: AMQChannel(amqp://[email protected]:5671/,1)
17:22:14,821 DEBUG RabbitTemplate:1045 - Executing callback on RabbitMQ Channel: Cached Rabbit Channel: PublisherCallbackChannelImpl: AMQChannel(amqp://[email protected]:5671/,1)
17:22:14,821 DEBUG RabbitAdmin:444 - declaring Exchange 'serviceAExchange1'
17:22:14,822 DEBUG RabbitTemplate:1045 - Executing callback on RabbitMQ Channel: Cached Rabbit Channel: PublisherCallbackChannelImpl: AMQChannel(amqp://[email protected]:5671/,1)
17:22:14,825 DEBUG RabbitAdmin:444 - declaring Exchange 'serviceAExchange1'
17:22:14,827 DEBUG RabbitAdmin:444 - declaring Exchange 'serviceAExchange2'
17:22:14,828 DEBUG RabbitAdmin:444 - declaring Exchange 'serviceAExchange2'
17:22:14,829 DEBUG RabbitAdmin:444 - declaring Exchange 'serviceBExchange1'
17:22:14,830 DEBUG RabbitAdmin:444 - declaring Exchange 'serviceBExchange1'
17:22:14,832 DEBUG RabbitAdmin:444 - declaring Exchange 'serviceBExchange2'
17:22:14,835 DEBUG RabbitAdmin:444 - declaring Exchange 'serviceBExchange2'
17:22:14,836 DEBUG RabbitAdmin:472 - declaring Queue '07475112-7be0-4c8d-b6e5-3279e81a1aff'
17:22:14,837 DEBUG RabbitAdmin:472 - declaring Queue '07475112-7be0-4c8d-b6e5-3279e81a1aff'
17:22:14,843 DEBUG RabbitAdmin:472 - declaring Queue 'e4825008-954f-4154-bd61-9b67e0ff582e'
17:22:14,845 DEBUG RabbitAdmin:472 - declaring Queue '001bd357-6203-49a6-b573-7f1a998ff750'
17:22:14,848 DEBUG RabbitAdmin:472 - declaring Queue '3880a65f-0104-4c99-96ac-1958ace7e2e0'
17:22:14,853 DEBUG RabbitAdmin:472 - declaring Queue '3b1bc32a-872e-4fc3-ba2a-de200bc7b758'
17:22:14,856 DEBUG PublisherCallbackChannelImpl:654 - PendingConfirms cleared
17:22:14,856 DEBUG RabbitAdmin:511 - Binding destination [07475112-7be0-4c8d-b6e5-3279e81a1aff (QUEUE)] to exchange [serviceAExchange1] with routing key []
17:22:14,858 ERROR CachingConnectionFactory:292 - Channel shutdown: channel error; protocol method: #method<channel.close>(reply-code=405, reply-text=RESOURCE_LOCKED - cannot obtain exclusive access to locked queue '07475112-7be0-4c8d-b6e5-3279e81a1aff' in vhost '/', class-id=50, method-id=10)
17:22:14,859 DEBUG CachingConnectionFactory:673 - Detected closed channel on exception.  Re-initializing: PublisherCallbackChannelImpl: AMQChannel(amqp://[email protected]:5671/,1)
17:22:14,860 DEBUG RabbitAdmin:511 - Binding destination [e4825008-954f-4154-bd61-9b67e0ff582e (QUEUE)] to exchange [serviceAExchange2] with routing key []
17:22:14,862 DEBUG RabbitAdmin:511 - Binding destination [001bd357-6203-49a6-b573-7f1a998ff750 (QUEUE)] to exchange [serviceBExchange1] with routing key []
17:22:14,864  WARN RabbitAdmin:494 - Failed to declare queue:Queue [name=07475112-7be0-4c8d-b6e5-3279e81a1aff, durable=false, autoDelete=true, exclusive=true, arguments=null], continuing...
java.io.IOException
        at com.rabbitmq.client.impl.AMQChannel.wrap(AMQChannel.java:106)
        [...]
Caused by: com.rabbitmq.client.ShutdownSignalException: channel error; protocol method: #method<channel.close>(reply-code=405, reply-text=RESOURCE_LOCKED - cannot obtain exclusive access to locked queue '07475112-7be0-4c8d-b6e5-3279e81a1aff' in vhost '/', class-id=50, method-id=10)
[ More declaration errors follow ]
1
springrabbitmqspring-amqpspring-rabbit
It is weird that one queue is declared two times, but all others are declared only one time: 17:22:14,836 DEBUG RabbitAdmin:472 - declaring Queue 07475112-7be0-4c8d-b6e5-3279e81a1aff 17:22:14,837 DEBUG RabbitAdmin:472 - declaring Queue 07475112-7be0-4c8d-b6e5-3279e81a1aff' Exactly this queue is mentioned later in the exception. Maybe you could publish your project on github or bitbucket so we can check the whole configuration. – Sergii Zhevzhyk
Other queues were mentioned in additional exceptions that I didn't include. I'm also not sure why that one in particular is declared twice in a row. Unfortunately, publishing the rest of the project is not possible. – Fopedush

1 Answers

4
votes

1.4.6 is nearly 2 years old; do you see the same behavior with the current version (1.7.4)?

The exception reply-code=405, reply-text=RESOURCE_LOCKED implies you have two consumers on the queue. A common mistake with Spring Apps on Tomcat (or any web container) is to load the application context twice - once in the root application context and again in the dispatcher servlet's context.

Turning on DEBUG logging for org.springframework and going over all the beans declarations should help.

I just loaded your config into a simple app (main) and I don't see any problems, even after force-closing the connection via the admin UI...

Auto-declaring a non-durable, auto-delete, or exclusive Queue (47c551b8-c290-4ff0-ae42-11f24d576399) durable:false, auto-delete:true, exclusive:true. It will be redeclared if the broker stops and is restarted while the connection factory is alive, but all messages will be lost.
Auto-declaring a non-durable, auto-delete, or exclusive Queue (c494990e-9069-4561-8d64-1eb0373cf681) durable:false, auto-delete:true, exclusive:true. It will be redeclared if the broker stops and is restarted while the connection factory is alive, but all messages will be lost.
Started So46496960Application in 1.454 seconds (JVM running for 1.879)
#method<connection.close>(reply-code=320, reply-text=CONNECTION_FORCED - Closed via management plugin, class-id=0, method-id=0)
#method<connection.close>(reply-code=320, reply-text=CONNECTION_FORCED - Closed via management plugin, class-id=0, method-id=0)
SimpleConnection@5fa6541 [delegate=amqp://[email protected]:5672/, localPort= 58388], acknowledgeMode=AUTO local queue size=0
SimpleConnection@5fa6541 [delegate=amqp://[email protected]:5672/, localPort= 58388], acknowledgeMode=AUTO local queue size=0
rabbitConnectionFactory#4015e40b:1/SimpleConnection@712becf3 [delegate=amqp://[email protected]:5672/, localPort= 58404]
Auto-declaring a non-durable, auto-delete, or exclusive Queue (47c551b8-c290-4ff0-ae42-11f24d576399) durable:false, auto-delete:true, exclusive:true. It will be redeclared if the broker stops and is restarted while the connection factory is alive, but all messages will be lost.
Auto-declaring a non-durable, auto-delete, or exclusive Queue (c494990e-9069-4561-8d64-1eb0373cf681) durable:false, auto-delete:true, exclusive:true. It will be redeclared if the broker stops and is restarted while the connection factory is alive, but all messages will be lost.