channels registered with connection.NotifyClose not always get notified

[sknaumov]

I've encountered a bug with RabbitMQ v3.6.9 - it seems that under certain conditions channel that is registered with connection.NotifyClose is not actually notified about connection closure.

Here are the logs with annotations:

// block on reading from channel that is registered with NotifyClose
May 14 11:35:08 ip-10-0-6-12 wss-server[9857]: Start to monitor connection
May 14 11:35:09 ip-10-0-6-12 wss-server[9857]: Configuring amqp command consumer
May 14 11:35:09 ip-10-0-6-12 wss-server[9857]: Started AMQP command consumer
May 14 11:35:38 ip-10-0-6-12 wss-server[9857]: AMQP command consuming stopped, connection to rabbitmq lost

// here connection monitor unblocked, got result from channel and logged it.
May 14 11:35:38 ip-10-0-6-12 wss-server[9857]: AMQP connection problem: Exception (320) Reason: "CONNECTION_FORCED - broker forced connection closu
May 14 11:35:38 ip-10-0-6-12 wss-server[9857]: AMQP reconnection problem: dial tcp 10.0.11.124:5672: connect: connection refused
... // rabbit-mq service gets restarted
May 14 11:35:44 ip-10-0-6-12 wss-server[9857]: AMQP reconnection problem: dial tcp 10.0.11.124:5672: connect: connection refused

// client successfully reconnected to rabbit-mq
May 14 11:35:45 ip-10-0-6-12 wss-server[9857]: Validating RabbitMQ Exchanges configuration
May 14 11:35:45 ip-10-0-6-12 wss-server[9857]: Notifying listeners about successful AMQP reconnection
May 14 11:35:45 ip-10-0-6-12 wss-server[9857]: regenerating the bind queue after AMQP reconnect
May 14 11:35:45 ip-10-0-6-12 wss-server[9857]: Reinitializing AMQP consumer
May 14 11:35:45 ip-10-0-6-12 wss-server[9857]: Stopped AMQP command consumer
May 14 11:35:45 ip-10-0-6-12 wss-server[9857]: Configuring amqp command consumer

// once again block on reading channel that is registered with NotifyClose
May 14 11:35:45 ip-10-0-6-12 wss-server[9857]: Start to monitor connection

// here is the problem - some unexpected command received, it causes connection closure without notification
May 14 11:35:45 ip-10-0-6-12 wss-server[9857]: could not bind device to the command exchange: Exception (503) Reason: "unexpected command received"
May 14 11:35:45 ip-10-0-6-12 wss-server[9857]: Error in AMQP dead commands consumer: Exception (503) Reason: "unexpected command received"
May 14 11:35:45 ip-10-0-6-12 wss-server[9857]: could not bind device to the command exchange: Exception (504) Reason: "channel/connection is not op
May 14 11:35:45 ip-10-0-6-12 wss-server[9857]: could not bind device to the command exchange: Exception (504) Reason: "channel/connection is not op

// infinite cycle, as program has not been notified that connection is closed
May 14 11:35:45 ip-10-0-6-12 wss-server[9857]: Error creating AMQP queue: Exception (504) Reason: "channel/connection is not open"
May 14 11:35:45 ip-10-0-6-12 wss-server[9857]: Error creating AMQP queue: Exception (504) Reason: "channel/connection is not open"
May 14 11:35:45 ip-10-0-6-12 wss-server[9857]: Error creating AMQP queue: Exception (504) Reason: "channel/connection is not open"

[fangniu]

+1

[DmRk-Vl]

+1

[sknaumov]

It was my bad - even though I used single channel per connection, I had to monitor channel state too, as there could be a case when channel gets closed while connection is still alive.