Topology recovery occasionally declares a server-named queue multiple times

[sn4kebite]

Occasionally when recovering after a connection loss, and using server-generated queue names, the client will declare the queue multiple times. If also consuming from the queue, only one of the declared queues will be consumed from (the rest will have no consumers).

I've verified via wireshark that it does in fact send multiple Queue.Declares after receiving Channel.Open-Ok. This does not seem to happen if specifying a non-empty queue name.

Steps to reproduce:

1. Run the sample code below
2. Close the connection (eg. via rabbitmqctl or the management interface)
3. When the client recovers, it will occasionally declare two or more queues (usually takes two or three attempts)

Environment:

• RabbitMQ 3.7.8 / Erlang 20.3.8.5 (rabbitmq:3.7-management Docker image)
• Client library version 5.1.0
• microsoft/dotnet:2.1-aspnetcore-runtime on Debian 9.6 (Linux 4.9.0-8-amd64)

Also reproduced with:

• RabbitMQ 3.7.9 / Erlang 21.2
• Client library version 5.1.0 and latest master at 13a9567
• .NET Core 2.2.100
• Arch Linux 4.19.8-arch1-1-ARCH

RabbitMQ server log:

2019-01-17 12:27:54.083 [info] <0.18069.5> accepting AMQP connection <0.18069.5> (127.0.0.1:34237 -> 127.0.0.1:5672)
2019-01-17 12:27:54.099 [info] <0.18069.5> Connection <0.18069.5> (127.0.0.1:34237 -> 127.0.0.1:5672) has a client-provided name: recovery test
2019-01-17 12:27:54.103 [info] <0.18069.5> connection <0.18069.5> (127.0.0.1:34237 -> 127.0.0.1:5672 - recovery test): user 'guest' authenticated and granted access to vhost '/'
2019-01-17 12:28:00.151 [error] <0.18069.5> Error on AMQP connection <0.18069.5> (127.0.0.1:34237 -> 127.0.0.1:5672 - recovery test, vhost: '/', user: 'guest', state: running), channel 0:
 operation none caused a connection exception connection_forced: "Closed via management plugin"
2019-01-17 12:28:00.167 [info] <0.18088.5> Closing connection <0.18069.5> because "Closed via management plugin"
2019-01-17 12:28:00.213 [info] <0.18069.5> closing AMQP connection <0.18069.5> (127.0.0.1:34237 -> 127.0.0.1:5672 - recovery test, vhost: '/', user: 'guest')
2019-01-17 12:28:05.188 [info] <0.18099.5> accepting AMQP connection <0.18099.5> (127.0.0.1:43633 -> 127.0.0.1:5672)
2019-01-17 12:28:05.190 [info] <0.18099.5> Connection <0.18099.5> (127.0.0.1:43633 -> 127.0.0.1:5672) has a client-provided name: recovery test
2019-01-17 12:28:05.193 [info] <0.18099.5> connection <0.18099.5> (127.0.0.1:43633 -> 127.0.0.1:5672 - recovery test): user 'guest' authenticated and granted access to vhost '/'
2019-01-17 12:28:15.699 [warning] <0.18099.5> closing AMQP connection <0.18099.5> (127.0.0.1:43633 -> 127.0.0.1:5672 - recovery test, vhost: '/', user: 'guest'):
client unexpectedly closed TCP connection

Sample code:

using System;
using RabbitMQ.Client;

namespace rabbitmq_recovery_test
{
    class Program
    {
        static void Main(string[] args)
        {
            Console.WriteLine("Initializing");
            ConnectionFactory factory = new ConnectionFactory();
            IConnection connection = factory.CreateConnection("recovery test");
            IModel channel = connection.CreateModel();
            channel.QueueDeclare("", false, true, false, null);
            Console.WriteLine("Connected");
            Console.ReadLine();
        }
    }
}

I can provide the output from rabbitmq-collect-env if needed, but I would need some time to strip it of any sensitive information.

[michaelklishin]

Please post the key piece of evidence: the traffic capture.

[sn4kebite]

Here's a fresh capture: rabbitmq-dotnet.zip

[michaelklishin]

Thank you. We had to address something similar in the Java client a few years ago, so I have a couple of guesses as to what might be the reason. We'll get to it early next week.

[michaelklishin]

Per discussion with @kjnilsson: our leading hypothesis is that it's the same problem as described in this piece of Java client recovery implementation.

[lukebakken]

#43 already fixed the issue mentioned in @michaelklishin 's comment. Investigating this issue further.