Repeated exception "channel is already closed due to clean channel shutdown"

[Christoph Hausner]

Hello everyone,

now and then, the connection between clients and our RabbitMQ server may reset. I noticed that in this case, we get a very large number of the same exception in our Java client:

2018-02-15 00:49:36,603 [WARN] com.rabbitmq.client.impl.ForgivingExceptionHandler - An unexpected connection driver error occured (Exception message: Connection reset)

2018-02-15 00:49:41,636 [ERROR] com.rabbitmq.client.impl.ForgivingExceptionHandler - Caught an exception when recovering topology Caught an exception while recovering queue workloads: channel is already closed due to clean channel shutdown; protocol method: #method<channel.close>(reply-code=200, reply-text=OK, class-id=0, method-id=0)
com.rabbitmq.client.TopologyRecoveryException: Caught an exception while recovering queue workloads: channel is already closed due to clean channel shutdown; protocol method: #method<channel.close>(reply-code=200, reply-text=OK, class-id=0, method-id=0)
        at com.rabbitmq.client.impl.recovery.AutorecoveringConnection.recoverQueues(AutorecoveringConnection.java:632)
        at com.rabbitmq.client.impl.recovery.AutorecoveringConnection.recoverEntities(AutorecoveringConnection.java:583)
        at com.rabbitmq.client.impl.recovery.AutorecoveringConnection.beginAutomaticRecovery(AutorecoveringConnection.java:506)
        at com.rabbitmq.client.impl.recovery.AutorecoveringConnection.access$000(AutorecoveringConnection.java:53)
        at com.rabbitmq.client.impl.recovery.AutorecoveringConnection$1.recoveryCanBegin(AutorecoveringConnection.java:435)
        at com.rabbitmq.client.impl.AMQConnection.notifyRecoveryCanBeginListeners(AMQConnection.java:700)
        at com.rabbitmq.client.impl.AMQConnection.doFinalShutdown(AMQConnection.java:694)
        at com.rabbitmq.client.impl.AMQConnection$MainLoop.run(AMQConnection.java:584)
        at java.lang.Thread.run(Thread.java:748)
Caused by: com.rabbitmq.client.AlreadyClosedException: channel is already closed due to clean channel shutdown; protocol method: #method<channel.close>(reply-code=200, reply-text=OK, class-id=0, method-id=0)
        at com.rabbitmq.client.impl.AMQChannel.ensureIsOpen(AMQChannel.java:209)
        at com.rabbitmq.client.impl.AMQChannel.rpc(AMQChannel.java:270)
        at com.rabbitmq.client.impl.AMQChannel.privateRpc(AMQChannel.java:233)
        at com.rabbitmq.client.impl.AMQChannel.exnWrappingRpc(AMQChannel.java:128)
        at com.rabbitmq.client.impl.ChannelN.queueDeclare(ChannelN.java:948)
        at com.rabbitmq.client.impl.ChannelN.queueDeclare(ChannelN.java:50)
        at com.rabbitmq.client.impl.recovery.RecordedQueue.recover(RecordedQueue.java:53)
        at com.rabbitmq.client.impl.recovery.AutorecoveringConnection.recoverQueues(AutorecoveringConnection.java:608)
        ... 8 common frames omitted

<200 instances of the same exception>

2018-02-15 00:49:41,767 [ERROR] com.rabbitmq.client.impl.ForgivingExceptionHandler - Caught an exception when recovering topology Caught an exception while recovering queue result.389: channel is already closed due to clean channel shutdown; protocol method: #method<channel.close>(reply-code=200, reply-text=OK, class-id=0, method-id=0)
com.rabbitmq.client.TopologyRecoveryException: Caught an exception while recovering queue result.389: channel is already closed due to clean channel shutdown; protocol method: #method<channel.close>(reply-code=200, reply-text=OK, class-id=0, method-id=0)
        at com.rabbitmq.client.impl.recovery.AutorecoveringConnection.recoverQueues(AutorecoveringConnection.java:632)
        at com.rabbitmq.client.impl.recovery.AutorecoveringConnection.recoverEntities(AutorecoveringConnection.java:583)
        at com.rabbitmq.client.impl.recovery.AutorecoveringConnection.beginAutomaticRecovery(AutorecoveringConnection.java:506)
        at com.rabbitmq.client.impl.recovery.AutorecoveringConnection.access$000(AutorecoveringConnection.java:53)
        at com.rabbitmq.client.impl.recovery.AutorecoveringConnection$1.recoveryCanBegin(AutorecoveringConnection.java:435)
        at com.rabbitmq.client.impl.AMQConnection.notifyRecoveryCanBeginListeners(AMQConnection.java:700)
        at com.rabbitmq.client.impl.AMQConnection.doFinalShutdown(AMQConnection.java:694)
        at com.rabbitmq.client.impl.AMQConnection$MainLoop.run(AMQConnection.java:584)
        at java.lang.Thread.run(Thread.java:748)
Caused by: com.rabbitmq.client.AlreadyClosedException: channel is already closed due to clean channel shutdown; protocol method: #method<channel.close>(reply-code=200, reply-text=OK, class-id=0, method-id=0)
        at com.rabbitmq.client.impl.AMQChannel.ensureIsOpen(AMQChannel.java:209)
        at com.rabbitmq.client.impl.AMQChannel.rpc(AMQChannel.java:270)
        at com.rabbitmq.client.impl.AMQChannel.privateRpc(AMQChannel.java:233)
        at com.rabbitmq.client.impl.AMQChannel.exnWrappingRpc(AMQChannel.java:128)
        at com.rabbitmq.client.impl.ChannelN.queueDeclare(ChannelN.java:948)
        at com.rabbitmq.client.impl.ChannelN.queueDeclare(ChannelN.java:50)
        at com.rabbitmq.client.impl.recovery.RecordedQueue.recover(RecordedQueue.java:53)
        at com.rabbitmq.client.impl.recovery.AutorecoveringConnection.recoverQueues(AutorecoveringConnection.java:608)
        ... 8 common frames omitted

We first get a warning, then 5 seconds later, the same exception is thrown over and over again, until after ~100ms when, I assume, the connection could be re-established (or at least the exceptions do not get thrown anymore). It's great that RabbitMQ attempts to perform auto-recovery but I think something is wrong with our setup because of the repeated exceptions.

Would be thankful for any tips or advice.

-- Christoph

[Michael Klishin]

Something cleanly (as in Channel#close called by your app) closes the channel during recovery.

Connection recovery happens every 5 seconds by default:
http://www.rabbitmq.com/api-guide.html.

The only relevant known issue I can think of is https://github.com/rabbitmq/rabbitmq-java-client/pull/343,

so make sure you run 4.5.0.

--
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-users+unsubscribe@googlegroups.com.
To post to this group, send email to rabbitmq-users@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

MK

Staff Software Engineer, Pivotal/RabbitMQ

[Michael Klishin]

Actually no, that's not the issue I was thinking about.

Anyhow, the best source of information for everyone would be

a traffic capture during the recurring event [1]. It can reliably tell whether

something tries to close the channel from the client end.

1. http://www.rabbitmq.com/amqp-wireshark.html

To post to this group, send email to rabbitm...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

MK

Staff Software Engineer, Pivotal/RabbitMQ

[Christoph Hausner]

Thanks Michael for the quick response.

I just noticed now that there is exactly one exception thrown for each queue on the server. That explains why we are getting so many exceptions. But I do not understand yet why the exception is about a channel being closed while the auto-recovery is in progress. At the time when the exceptions are thrown, we do not perform any actions on the queues and also should not have any open channels. All channels used to perform actions should have been closed much earlier (although I wouldn't completely rule out that we have a bug here and don't close channels).

Can you explain a bit more what the exception means exactly? Which closed channel is it referring to?

To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.

To post to this group, send email to rabbitm...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

MK

Staff Software Engineer, Pivotal/RabbitMQ

[Michael Klishin]

Christoph,

I cannot possibly know since I have no access to your system.

You cannot close a channel twice, so if it's already closed (cleanly by the app or due to a channel-level *protocol* exception), closing it again
will fail.

Use Wireshark to find out what is really going on on the wire. Guessing will likely end up being too costly:
http://www.rabbitmq.com/amqp-wireshark.html

If you are not familiar with channels in RabbitMQ, see http://www.rabbitmq.com/tutorials/amqp-concepts.html.
If you are not familiar with how automatic connection recovery and channel termination works, see

http://www.rabbitmq.com/api-guide.html#shutdown-overview
http://www.rabbitmq.com/api-guide.html#recovery

[Michael Klishin]

Server and client logs are also important sources of information. Both have to be inspected in order to make an informed conclusion.

To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-users+unsubscribe@googlegroups.com.
To post to this group, send email to rabbitmq-users@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[vikinghawk]

When using topology recovery, you can't close the Channel that you use to declare queues, exchanges, or bindings. The recovery logic stores the Channel and queue/exchange/binding details when you first declare the entity. It uses that same channel during the recovery process to re-declare the queue so if your code explicitly closed it at any point then recovery will always fail. I encountered the same issue a few years ago when I first implemented. It would be good to update the client doc to make this clear.

What i ended up doing was ensuring the Channel i used to create the queue and bindings was the same channel i used to create the consumer. Another option would be to use a dedicated channel to do all your queue and binding declarations and leave it open.

[Michael Klishin]

Thank you for the clarification, vikinghawk.

To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-users+unsubscribe@googlegroups.com.
To post to this group, send email to rabbitmq-users@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[Christoph Hausner]

Thanks a lot, vikinghawk. That definitely explains why auto-recovery is failing. For declaring queues, we currently open a new channel, declare the queue and immediately close the channel. The RabbitMQ website says:

"That is why you shouldn't close a channel after it has created some resources (queues, exchanges, bindings) or topology recovery for those resources will fail later, as the channel has been closed. Instead, leave creating channels open for the life of the application."

I wonder if leaving channels open forever could lead to problems after some time? Since we are using RabbitMQ for RPC-style communication, we are basically creating a new temporary reply queue for each incoming request to our REST API. That means there might be tens of thousands of queues created every day.

[vikinghawk]

Check out the direct reply to feature [1]. Its more efficient and this problem goes away as you no longer need temp queues.

[1] https://www.rabbitmq.com/direct-reply-to.html

[Christoph Hausner]

Interesting, I will investigate whether we could make use of direct reply-to. Thanks.