Windows eacces / eexist error on journal.jif file during pause minority

[Gsantomaggio]

The following errors occurs only in Windows after pause minority

   ** {{badmatch,{error,{"c:/rmqdata/db/rabbit@WIN-NCNMMKRPVMR-mnesia/queues/997D2EGEQM85T4DGH6EEPV91Y",
                          eexist}}},

and

** Reason for termination == 
** {{badmatch,{error,{"c:/rmqdata/db/rabbit@WIN-NCNMMKRPVMR-mnesia/queues/997D2EGEQM85T4DGH6EEPV91Y/journal.jif",
                      eacces}}},

Here the steps to reproduce it:

Versions: RabbitMQ 3.5.7 on Erlang 17.3

STEP 1 - Create a RabbitMQ cluster with 3 machines:

1. Debian
2. Debian
3. Windows 2012 server

Policy:{"ha-mode":"all","ha-sync-mode":"automatic"}
rabbitmq.config:

[
  {kernel, [
    {net_ticktime,  15}
  ]},
  {rabbit, [
    {queue_index_embed_msgs_below, 128},
    {queue_index_max_journal_entries, 512},
    {cluster_partition_handling, pause_minority}
  ]}
].

STEP 2 - Publish persistent messages :

for (int i = 0; i < 10 ; i++) {
            threadChannels.submit(new Runnable() {
                public void run() {

                    try {
                        Channel channel = connection.createChannel();

                        for (int j = 0; j < 50000; j++) {
                            channel.basicPublish(exchange_name,"",MessageProperties.PERSISTENT_BASIC, new byte[1024]);
                            Thread.sleep(30);
                        }

STEP 3 - When RabbitMQ starts to write the queue-index files inside the directory: %RABBITMQ_BASE%\db\rabbit@WIN-NCNMMKRPVMR-mnesia\queues
add a Windows firewall rule to get Windows in network partition.

Firewall rule note: it is enough to block incoming connection from one on Debian machine.

LOGS

 * pause_minority mode enabled
    We will therefore pause until the *entire* cluster recovers

During the stopping :

=INFO REPORT==== 12-Jan-2016::16:00:45 ===
Mirrored queue 'myQuueue3' in vhost '/': Synchronising: complete

=ERROR REPORT==== 12-Jan-2016::16:01:17 ===
** Generic server <0.1374.0> terminating
** Last message in was {'$gen_cast',go}
** When Server state == {not_started,
                            {amqqueue,
                                {resource,<<"/">>,queue,<<"myQuueue1">>},
                                true,false,none,[],<7603.11283.0>,
                                [<7602.2511.0>],
                                [],[],
                                [{vhost,<<"/">>},
                                 {name,<<"asdsada">>},
                                 {pattern,<<>>},
                                 {'apply-to',<<"all">>},
                                 {definition,
                                     [{<<"ha-mode">>,<<"all">>},
                                      {<<"ha-sync-mode">>,<<"automatic">>}]},
                                 {priority,0}],
                                [{<7602.2512.0>,<7602.2511.0>},
                                 {<7603.11285.0>,<7603.11283.0>}],
                                [],live}}
** Reason for termination == 
** {{badmatch,{error,{"c:/rmqdata/db/rabbit@WIN-NCNMMKRPVMR-mnesia/queues/77FUPFJL6LYV1XUWFXRXYOTE",
                      eexist}}},
    [{rabbit_mirror_queue_slave,handle_go,1,[]},
     {rabbit_mirror_queue_slave,handle_cast,2,[]},
     {gen_server2,handle_msg,2,[]},
     {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,237}]}]}

Note: The error sometime occurs also during the start_app after pause minority

Here the full logs

I didn't test (yet) if in this situation RabbitMQ loses messages.

[michaelklishin]

Note that eexists is very different from eaccess and most likely can simply be ignored (given the file can be used, of course).

[Gsantomaggio]

I'm testing the issue using the version 3.6.0.

=INFO REPORT==== 14-Jan-2016::14:24:49 ===
Starting RabbitMQ 3.6.0 on Erlang 17.3
Copyright (C) 2007-2015 Pivotal Software, Inc.
Licensed under the MPL.  See http://www.rabbitmq.com/

And I had this error:

** Reason for termination == 
** {{badmatch,{error,{"c:/rmqdata/db/rabbit@WIN-NCNMMKRPVMR-mnesia/queues/D3P5UZWQOW7DKGCO3YXAZ6WWO",
                      eexist}}},
    [{rabbit_queue_index,reset_state,1,
                         [{file,"src/rabbit_queue_index.erl"},{line,276}]},
     {rabbit_variable_queue,reset_qi_state,1,
                            [{file,"src/rabbit_variable_queue.erl"},
                             {line,1646}]},
     {rabbit_variable_queue,purge_and_index_reset,1,
                            [{file,"src/rabbit_variable_queue.erl"},
                             {line,1620}]},
     {rabbit_variable_queue,delete_and_terminate,2,
                            [{file,"src/rabbit_variable_queue.erl"},
                             {line,545}]},
     {rabbit_priority_queue,delete_and_terminate,2,
                            [{file,"src/rabbit_priority_queue.erl"},
                             {line,181}]},
     {gen_server2,terminate,3,[{file,"src/gen_server2.erl"},{line,1146}]},
     {proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,247}]}]} 

Seems exactly this #341

I tried to put also the Debian nodes in network partition, and I (sometimes) had this error:

** Reason for termination ==
** {{badmatch,{error,enoent}},
    [{rabbit_queue_index,append_journal_to_segment,1,
                         [{file,"src/rabbit_queue_index.erl"},{line,831}]},
     {rabbit_queue_index,'-flush_journal/1-fun-0-',2,
                         [{file,"src/rabbit_queue_index.erl"},{line,816}]},
     {lists,foldl,3,[{file,"lists.erl"},{line,1261}]},
     {rabbit_queue_index,segment_fold,3,
                         [{file,"src/rabbit_queue_index.erl"},{line,1000}]},
     {rabbit_queue_index,flush_journal,1,
                         [{file,"src/rabbit_queue_index.erl"},{line,808}]},
     {rabbit_variable_queue,handle_pre_hibernate,1,
                            [{file,"src/rabbit_variable_queue.erl"},
                             {line,838}]},

The stack is different from windows, but enoent sounds like a problem during the creation and destroy the queue directory.

It looks similar to the Windows situation even if it is different enoent is different from eaccess.

From what have seen until now the problem seems not related only to Windows.
Even only eaccess happens in Windows.

Unfortunately, the error doesn't occur systematically both in Windows and Debian.

[Gsantomaggio]

I found other conditions where this error is raised as:

** Reason for termination == 
** {{badmatch,{error,{"c:/Users/gabriele/AppData/Roaming/RabbitMQ/db/RABBIT~1/queues/1Y30DXXRLPQ8IQFHDELJQGHP5",
                      eacces}}},
    [{rabbit_queue_index,delete_and_terminate,1,
                         [{file,"src/rabbit_queue_index.erl"},{line,305}]},
     {rabbit_variable_queue,purge_pending_ack_delete_and_terminate,1,

All the conditions seem to lead to the call rabbit_file:recursive_delete

[dcorbacho]

I believe that the enoent error on Debian with nodes in network partition comes from the prim_file:open call in:
https://github.com/rabbitmq/rabbitmq-server/blob/rabbitmq_v3_6_0/src/file_handle_cache.erl#L752

It seems it tries to reopen a handle that for some reason has been deleted.

[dcorbacho]

I did some investigation on this issue while working on #676, #714 and #749. While I was tracing the queue processes, I saw how the queue would receive the delete_and_terminate call and remove the indexes, but just after that it would receive a publish message that will cause this crash. That is understandable, as the index have been removed, but I could not get to the root cause of how a publish is processed when the queue is being terminated. At some point, when I increased the logs to get more details, the issue did not happen anymore. It might be related to timings.

[dcorbacho]

#863 (derived from #802) solves the overlap between stop/start of slaves which can trigger this bug. The stopping slave process removes the queue index, while the new incarnation of the slave tries to access to it and thus the badmatch with enoent or the opposite with eexist.

[michaelklishin]

Will close until we come across a different way to reproduce. Thank you, @dcorbacho and @Gsantomaggio.