Rabbitmq-server: Priority queue fails to synchronize after node restart.

[bharris47]

We are running a RabbitMQ cluster (3 nodes) with 3 mirrored, durable, priority queues. Restarting any of the nodes causes the priority queues to fall into an endless sync loop.

The management console shows the queue synchronization progress going from 0% to complete. After a few seconds, the synchronization starts again.

We have tried disabling automatic sync and manually triggering sync, but experience the same behavior.

We initially believed they were failing to sync because there were still messages being sent to the queue. When we stop the producer, the behavior stops momentarily, but resumes immediately upon re-enabling the producer.

Our issue seems very similar to #366, but that is claimed to have been fixed in an earlier version.

Non-priority, durable queues do not exhibit this behavior.

Any help would be much appreciated.

Technical Details

• OS: CentOS Linux release 7.2.1511
• RabbitMQ: 3.6.1
• Erlang 18.2

Crash Details

** Reason for termination ==
** {{badmatch,-1},
    [{rabbit_mirror_queue_slave,update_delta,2,
                                [{file,"src/rabbit_mirror_queue_slave.erl"},
                                 {line,984}]},
     {rabbit_mirror_queue_slave,process_instruction,2,
                                [{file,"src/rabbit_mirror_queue_slave.erl"},
                                 {line,917}]},
     {rabbit_mirror_queue_slave,handle_cast,2,
                                [{file,"src/rabbit_mirror_queue_slave.erl"},
                                 {line,254}]},
     {gen_server2,handle_msg,2,[{file,"src/gen_server2.erl"},{line,1049}]},
     {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]}

[Morthy]

Also occurring for us, with nearly the same setup/config but OS is Debian 7

[epretha]

Hi,
We were not able to reproduce the issue with the information provided. It would be really helpful if you could kindly share with us the configuration applied and any script that you might have to reproduce the issue.

Could you also kindly send us the full log files for all the nodes in the cluster?
This will help us to understand the context under which the problem occurred.

Thank you very much in advance.

[bharris47]

@epretha do you guys have any private channels where we could send the logs and other details as opposed to this public Github forum.

[michaelklishin]

@bharris47 michael at RabbitMQ domain is one way.

[bharris47]

@michaelklishin did my logs shed any light on this issue? It continues to be a problem for us.

[michaelklishin]

@bharris47 I'm afraid there wasn't much progress on this issue recently.

[michaelklishin]

@bharris47 can you please trim the logs a bit? 100 MB in size compressed suggests there are probably months of data, or a lot of repetitive entries. The last few days should be sufficient.

[bharris47]

@michaelklishin this is only around a day of logs. Is there anything specific we can grep for or filter to get a more concise log file for you?

[michaelklishin]

Just trim to the last 30% then. Thank you.

On 25 abr 2016, at 18:27, Ben Harris [email protected] wrote:

@michaelklishin this is only around a day of logs. Is there anything specific we can grep for or filter to get a more concise log file for you?

—
You are receiving this because you were mentioned.
Reply to this email directly or view it on GitHub

[bharris47]

Some further notes as we've been researching this issue.

We have the same setup as mentioned initially. A priority queue is in an unsynchronized state with a slave node. I press "Synchronise" in an attempt to mirror the queue to the unsynchronized node. Tailing the logs on the master node yields:

=INFO REPORT==== 27-Apr-2016::01:18:35 ===
Mirrored queue 'rabbit_killer_celery.1' in vhost 'test': Synchronising: mirrors ['rabbit@data-rabbitmq-test-test-01-04.***.info'] to sync

=INFO REPORT==== 27-Apr-2016::01:18:36 ===
Mirrored queue 'rabbit_killer_celery.1' in vhost 'test': Synchronising: 36000 messages

=INFO REPORT==== 27-Apr-2016::01:18:37 ===
Mirrored queue 'rabbit_killer_celery.1' in vhost 'test': Synchronising: 70000 messages

=INFO REPORT==== 27-Apr-2016::01:18:38 ===
Mirrored queue 'rabbit_killer_celery.1' in vhost 'test': Synchronising: 102000 messages

=INFO REPORT==== 27-Apr-2016::01:18:39 ===
Mirrored queue 'rabbit_killer_celery.1' in vhost 'test': Synchronising: 122000 messages

=INFO REPORT==== 27-Apr-2016::01:18:40 ===
Mirrored queue 'rabbit_killer_celery.1' in vhost 'test': Synchronising: 151000 messages

=INFO REPORT==== 27-Apr-2016::01:18:41 ===
Mirrored queue 'rabbit_killer_celery.1' in vhost 'test': Synchronising: 189000 messages

=INFO REPORT==== 27-Apr-2016::01:18:42 ===
Mirrored queue 'rabbit_killer_celery.1' in vhost 'test': Synchronising: 214000 messages

=INFO REPORT==== 27-Apr-2016::01:18:42 ===
Mirrored queue 'rabbit_killer_celery.1' in vhost 'test': Synchronising: complete

It seems as if the master node believes that all the messages have been synchronized.

The unsychronised node still shows as unsychronised and logs the following:

=ERROR REPORT==== 27-Apr-2016::01:24:26 ===
** Generic server <0.19982.0> terminating
** Last message in was {'$gen_cast',
                           {gm,{ack,
                                   [<<9,243,150,47,97,42,180,240,71,211,
                                      233,164,163,224,247,187>>]}}}
** When Server state == {state,
                         {amqqueue,
                          {resource,<<"test">>,queue,
                           <<"rabbit_killer_celery.1">>},
                          true,false,none,
                          [{<<"x-max-priority">>,signedint,10}],
...

This sample is followed by a large dump of what appears to be message data and the same crash log as posted in my initial message.

[Dzol]

There have been some recent fixes related to synchronizing mirrored queues. Issue #714 solved a deadlock in their synchronization which might have been the cause here. The crash shown might not be a direct symptom of it but caused by wrong syncing through the GM module. We will continue investigating. Our other finding concerns the folds, over several backing queues, which are specific to priority queues. This could cause the bad match in the call to update_delta/2.

[bharris47]

Thanks for the heads up @Dzol. Unfortunately, the issue persists in RabbitMQ 3.6.2 RC1.

[dcorbacho]

Hi @bharris47, the endless sync loop could be caused by #676. That issue requires Erlang 18.3.1, as it is a bug in Mnesia.

I can check for you if that is happening in your cluster. Could you share with us the output of rabbitmqctl eval 'rabbit_diagnostics:maybe_stuck().' in all nodes when the endless loop happens? You can send it through Michael.

We we'll continue investigating the [{rabbit_mirror_queue_slave,update_delta,2 crash, as that is not a known symptom of #676.

[Dzol]

@bharris47: We can reproduce the error reports from the logs but seeing the same symptoms on the management console is proving more difficult. We'll investigate the reason behind those error reports and return to the issue of reproducing the symptoms on the management console in the near future.

[dcorbacho]

We are still investigating the issue, but we wanted to post a quick update.

We are reproducing the issue using three nodes: bunny, hare and rabbit. Bunny and hare are slaves, while rabbit holds the master of the mirrored queues. Hare is restarted in the middle of the test, while load is being injected into the system, and after it rejoins the cluster, the node bunny crashes as reported in this ticket.

The crash happens processing the depth instruction: https://github.com/rabbitmq/rabbitmq-server/blob/master/src/rabbit_mirror_queue_slave.erl#L937

When hare rejoins the cluster, it triggers the depth call:
https://github.com/rabbitmq/rabbitmq-server/blob/master/src/rabbit_mirror_queue_slave.erl#L140
https://github.com/rabbitmq/rabbitmq-server/blob/master/src/rabbit_mirror_queue_coordinator.erl#L365
https://github.com/rabbitmq/rabbitmq-server/blob/master/src/rabbit_mirror_queue_master.erl#L542

Bunny has messages stored by rabbit_variable_queue in the qi_pending_ack queue, which seem to have been removed from the master, as the master's depth is 0.

Bunny crashes two seconds after hare is detected down, while the messages still in bunny have gone through drain_confirmed/2 in the master node four seconds before the crash: https://github.com/rabbitmq/rabbitmq-server/blob/stable/src/rabbit_mirror_queue_master.erl#L340. The messages are stored in the master seen_status with the tag error.

Best guess is that some notifications get lost, or the down notification is not properly handled in bunny when hare goes down. We continue working on this.

[dcorbacho]

This crash is caused by an improper handling of the acknowledgments (automatic or manual) in the priority queues, bringing nodes down is not the cause of the issue. We can reproduce the crash without bringing any node down, simply by triggering request_depth in the GM at any time. Some messages stay in the slaves queue index waiting for acknowledge, but are not registered in the master anymore.

[dcorbacho]

The original problem is easy reproducible with the Java client using channel.basicQos(5);.

The crash happens with messages that arrive at the slave by the synchronisation, because the ordering of the messages was reverted during the handling of the priority queues. Thus, acknowledgments could not be processed as those messages had not yet been dropped.

PR #842 closes this.

[amulyas]

Milestone is confusing is this fix available in 3.6.3?

[michaelklishin]

Yes.

[amulyas]

we are using 3.6.3 and having this issue .. pivotal support saying they can reproduce this issue

[michaelklishin]

If Pivotal support says they can reproduce, presumably they will share a way to reproduce with our team at some point. The best way the community can help is to help test 3.6.6 milestone releases.

[automatedops]

We haven't seen this issue on 3.6.5.

[dcorbacho]

@amulyas we are able to reproduce a similar issue without using priority queues, so although the crash seems the same it has a different root cause. You can follow it up on #944