Whole RabbitMQ startup stuck if recovering one queue index crashes

[gomoripeti]

I am reproducing this on main @ 7e3fa92 but we've seen this on 3.11.x in the wild.
Using a 1-node cluster with classic queues.

When persistent message store is recovering it goes through the files of classic queue indices. I intentionally corrupted one queue data so it crashes. What is initially unexpected to me is that the startup of RabbitMQ is blocked and never finishes. As it is stuck in the rabbit app startup the plugins like the management plugin are never started, so it's not fully visible what the status is.

I got as far in tracking down the issue that the persistent msg store process is waiting for the results via a gatherer, while the result never comes because the worker_pool_worker crashed. This commit explicitly unlinks the worker from the gatherer ad20a63 so the behaviour definitely has some intentional aspect. If I revert that commit the crash propagates crashing the gatherer, the msg store and ultimately the vhost is unable to start. But imo this is still a more limited scope than the current behaviour. The management UI starts up and shows the vhost is down (while other vhosts, queues etc can still operate).

Log snippets

2023-05-24 19:02:31.182971+02:00 [warning] <0.10978.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_persistent" : recovery terms differ from present
2023-05-24 19:02:31.182971+02:00 [warning] <0.10978.0> rebuilding indices from scratch
2023-05-24 19:02:31.183113+02:00 [debug] <0.10978.0> Rebuilding message location index after unclean shutdown...
2023-05-24 19:02:31.183144+02:00 [debug] <0.10978.0> Rebuilding message refcount...
2023-05-24 19:02:31.185736+02:00 [error] <0.10815.0> ** Generic server <0.10815.0> terminating
2023-05-24 19:02:31.185736+02:00 [error] <0.10815.0> ** Last message in was {'$gen_cast',
2023-05-24 19:02:31.185736+02:00 [error] <0.10815.0>                            {submit_async,
2023-05-24 19:02:31.185736+02:00 [error] <0.10815.0>                                #Fun<rabbit_classic_queue_index_v2.10.95142755>,
2023-05-24 19:02:31.185736+02:00 [error] <0.10815.0>                                <0.10814.0>}}
2023-05-24 19:02:31.185736+02:00 [error] <0.10815.0> ** When Server state == undefined
2023-05-24 19:02:31.185736+02:00 [error] <0.10815.0> ** Reason for termination ==
2023-05-24 19:02:31.185736+02:00 [error] <0.10815.0> ** {function_clause,
2023-05-24 19:02:31.185736+02:00 [error] <0.10815.0>        [{rabbit_queue_index,journal_minus_segment1,
2023-05-24 19:02:31.185736+02:00 [error] <0.10815.0>             [{no_pub,no_del,ack},
...
2023-05-24 19:02:31.185736+02:00 [error] <0.10815.0>         {rabbit_classic_queue_index_v2,'-queue_index_walker/1-fun-1-',2,
2023-05-24 19:02:31.185736+02:00 [error] <0.10815.0>             [{file,"rabbit_classic_queue_index_v2.erl"},{line,1118}]},
2023-05-24 19:02:31.185736+02:00 [error] <0.10815.0>         {worker_pool_worker,handle_cast,2,
2023-05-24 19:02:31.185736+02:00 [error] <0.10815.0>             [{file,"worker_pool_worker.erl"},{line,113}]},
2023-05-24 19:02:31.185736+02:00 [error] <0.10815.0>         {gen_server2,handle_msg,2,[{file,"gen_server2.erl"},{line,1067}]},
...
2023-05-24 19:02:31.186117+02:00 [error] <0.10815.0>   crasher:
2023-05-24 19:02:31.186117+02:00 [error] <0.10815.0>     initial call: worker_pool_worker:init/1
2023-05-24 19:02:31.186117+02:00 [error] <0.10815.0>     pid: <0.10815.0>
...
2023-05-24 19:02:31.186117+02:00 [error] <0.10815.0>     ancestors: [worker_pool_sup,rabbit_sup,<0.10678.0>]
2023-05-24 19:02:31.186117+02:00 [error] <0.10815.0>     message_queue_len: 0
2023-05-24 19:02:31.186117+02:00 [error] <0.10815.0>     messages: []
# only linked to its supervisor
2023-05-24 19:02:31.186117+02:00 [error] <0.10815.0>     links: [<0.10813.0>]
...
2023-05-24 19:02:31.186117+02:00 [error] <0.10815.0>     trap_exit: false

2023-05-24 19:02:31.186993+02:00 [error] <0.10813.0>     supervisor: {local,worker_pool_sup}
2023-05-24 19:02:31.186993+02:00 [error] <0.10813.0>     errorContext: child_terminated

Process infos
(I did not capture that during the repro, but the main rabbit process is blocked waiting for the vhost process which is waiting for the msg store process)

# msg_store process blocked
81> erlang:process_info(list_to_pid("<0.10978.0>"), [dictionary, monitors, current_stacktrace]).
[{dictionary,[{'$initial_call',{rabbit_msg_store,init,1}},
              {'$ancestors',[<0.10964.0>,<0.10963.0>,rabbit_vhost_sup_sup,
                             rabbit_sup,<0.10678.0>]}]},
 {monitors,[{process,<0.10982.0>}]},
 {current_stacktrace,[{gen,do_call,4,
                           [{file,"gen.erl"},{line,240}]},
                      {gen_server2,call,3,[{file,"gen_server2.erl"},{line,342}]},
                      {rabbit_classic_queue_index_v2,queue_index_walker,1,
                                                     [{file,"rabbit_classic_queue_index_v2.erl"},{line,1128}]},
                      {rabbit_msg_store,count_msg_refs,3,
                                        [{file,"rabbit_msg_store.erl"},{line,1675}]},
                      {rabbit_msg_store,build_index,3,
                                        [{file,"rabbit_msg_store.erl"},{line,1780}]},
                      {rabbit_msg_store,init,1,
                                        [{file,"rabbit_msg_store.erl"},{line,806}]},
                      {gen_server2,init_it,6,
                                   [{file,"gen_server2.erl"},{line,565}]},
                      {proc_lib,init_p_do_apply,3,
                                [{file,"proc_lib.erl"},{line,241}]}]}]

# gatherer hibernated
82> erlang:process_info(list_to_pid("<0.10982.0>"), [dictionary, monitors, current_stacktrace]).
[{dictionary,[{rand_seed,{#{max => 288230376151711743,type => exsplus,
                            next => #Fun<rand.5.65977474>,jump => #Fun<rand.3.65977474>},
                          [19423983024216908|52613944085398753]}},
              {'$initial_call',{gatherer,init,1}},
              {'$ancestors',[<0.10978.0>,<0.10964.0>,<0.10963.0>,
                             rabbit_vhost_sup_sup,rabbit_sup,<0.10678.0>]}]},
 {monitors,[]},
 {current_stacktrace,[]}]
(rabbit@Peters-MacBook-Pro)83> rr(gatherer).
[gstate]

# msg_store proc blocked in gatherer state
84> sys:get_state(list_to_pid("<0.10982.0>")).
{gs2_state,<0.10978.0>,<0.10982.0>,
           #gstate{forks = 1,
                   values = {[],[]},
                   blocked = {[{<0.10978.0>,
                                #Ref<0.2610424390.2972975109.138810>}],
                              []}},
           gatherer,hibernate,
           {backoff,1522,1000,10000,
                    {#{max => 288230376151711743,type => exsplus,
                       next => #Fun<rand.5.65977474>,jump => #Fun<rand.3.65977474>},
                     [52613944085398753|182362430194551768]}},
           {queue,[],[],0},
...}

This needs no mirroring and can affect CQv2 as well (if we are able to crash rabbit_classic_queue_index_v2:queue_index_walker_reader/2 somehow)

Is there anything that could be done about this? What is the background of commit ad20a63?

[lhoguin]

I have opened #8338 to revert the commit as it doesn't seem necessary anymore. It seemed necessary while developing CQv2 initially but I guess it was a mistake.

[gomoripeti]

thank you!