4.1.x: a priority classic queue runs into an exception in rabbit_variable_queue:d/1

[klemenStanic]

Describe the bug

We are experiencing an issue where a specific queue (classic) in our RabbitMQ server, used with Celery, frequently enters a crashed state. Other queues continue to function normally. Restarting the queue or the server temporarily resolves the issue, but it recurs after some time.

Celery throws this error:

Unrecoverable error: NotFound(404, "NOT_FOUND - queue 'celery_job_opening' in vhost '/' has crashed and failed to restart", (50, 10), 'Queue.declare')

Rabbitmq log shows this:

2025-07-14 08:19:11.472056+02:00 [error] <0.470.0> ** Reason for termination ==
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0> ** {function_clause,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>        [{rabbit_variable_queue,d,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>             [{delta,1806336,2,0,1806337}],
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>             [{file,"src/rabbit_variable_queue.erl"},{line,988}]},
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>         {rabbit_variable_queue,maybe_deltas_to_betas,4,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>             [{file,"src/rabbit_variable_queue.erl"},{line,2379}]},
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>         {rabbit_variable_queue,fetch_from_q3,1,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>             [{file,"src/rabbit_variable_queue.erl"},{line,2245}]},
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>         {rabbit_variable_queue,queue_out,1,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>             [{file,"src/rabbit_variable_queue.erl"},{line,1266}]},
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>         {rabbit_variable_queue,collect_by_predicate,3,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>             [{file,"src/rabbit_variable_queue.erl"},{line,1563}]},
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>         {rabbit_variable_queue,remove_by_predicate,2,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>             [{file,"src/rabbit_variable_queue.erl"},{line,1501}]},
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>         {rabbit_variable_queue,dropwhile,2,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>             [{file,"src/rabbit_variable_queue.erl"},{line,558}]},
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>         {rabbit_priority_queue,find2,4,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>             [{file,"src/rabbit_priority_queue.erl"},{line,509}]}]}
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0> 
2025-07-14 08:19:15.001471+02:00 [error] <0.470.0>   crasher:
2025-07-14 08:19:15.001471+02:00 [error] <0.470.0>     initial call: rabbit_amqqueue_process:init/1
2025-07-14 08:19:15.001471+02:00 [error] <0.470.0>     pid: <0.470.0>
2025-07-14 08:19:15.001471+02:00 [error] <0.470.0>     registered_name: []
2025-07-14 08:19:15.001471+02:00 [error] <0.470.0>     exception exit: {function_clause,
...

RabbitMQ version: 4.1.2
Erlang version: 27.3.4.1
Celery version: 5.5.2
Kombu version: 5.5.3
OS: linux/amd64
Clustered: no
Any plugins enabled: rabbitmq_delayed_message_exchange,rabbitmq_management,rabbitmq_prometheus,rabbitmq_shovel,rabbitmq_shovel_management

During the crash, there is no abnormal system resources usage.

Attaching the Server state at the time of the crash (from /var/log/[email protected]) and the corresponding erl_crash.dump.

rabbitmq_crash_log_subset.txt
erl_crash.dump.txt

Reproduction steps

Can't reliably reproduce.

Expected behavior

The queue not crashing.

Additional context

No response

[michaelklishin]

@klemenStanic we cannot suggest much without a way to reproduce. Even with a simulation of a workload using PerfTest, investigating such issues can take weeks.

"Use a quorum queue, they use completely different storage from CQs" is the only recommendation I have.

[michaelklishin]

According to the log, this is a CQ with priorities, the stack trace originates in rabbit_priority_queue:

2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>     supervisor: {<0.469.0>,rabbit_amqqueue_sup}
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>     errorContext: child_terminated
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>     reason: {function_clause,
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                 [{rabbit_variable_queue,d,
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                      [{delta,1806336,2,0,1806337}],
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                      [{file,"src/rabbit_variable_queue.erl"},{line,988}]},
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                  {rabbit_variable_queue,maybe_deltas_to_betas,4,
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                      [{file,"src/rabbit_variable_queue.erl"},{line,2379}]},
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                  {rabbit_variable_queue,fetch_from_q3,1,
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                      [{file,"src/rabbit_variable_queue.erl"},{line,2245}]},
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                  {rabbit_variable_queue,queue_out,1,
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                      [{file,"src/rabbit_variable_queue.erl"},{line,1266}]},
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                  {rabbit_variable_queue,collect_by_predicate,3,
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                      [{file,"src/rabbit_variable_queue.erl"},{line,1563}]},
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                  {rabbit_variable_queue,remove_by_predicate,2,
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                      [{file,"src/rabbit_variable_queue.erl"},{line,1501}]},
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                  {rabbit_variable_queue,dropwhile,2,
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                      [{file,"src/rabbit_variable_queue.erl"},{line,558}]},
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                  {rabbit_priority_queue,find2,4,
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                      [{file,"src/rabbit_priority_queue.erl"},{line,509}]}]}
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>     offender: [{pid,<0.470.0>},
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                {id,rabbit_amqqueue},
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                {mfargs,
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                    {rabbit_amqqueue_process,start_link,
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                        [{amqqueue,
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                             {resource,<<"/">>,queue,<<"celery_job_opening">>},
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                             true,false,none,
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                             [{<<"x-max-priority">>,signedint,10},
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                              {<<"x-queue-type">>,longstr,<<"classic">>}],
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                             <0.6056536.0>,[],[],[],undefined,undefined,[],[],
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                             stopped,0,[],<<"/">>,
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                             #{user => <<"pl_k8s_pie_user">>},
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                             rabbit_classic_queue,#{}},
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                         <0.468.0>]}},
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                {restart_type,transient},
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                {significant,true},
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                {shutdown,600000},
2025-07-14 08:19:15.018494+02:00 [error] <0.469.0>                {child_type,worker}]

[michaelklishin]

And the function in question is

d(Delta = #delta { start_seq_id = Start, count = Count, end_seq_id = End })
  when Start + Count =< End ->
    Delta.

so condition in the function guard does not hold true. The input is:

{delta,1806336,2,0,1806337}

which in record form would be

#delta {
  start_seq_id = 1806336,
  count = 2,
  transient = 0,
  end_seq_id = 1806337
}

and the condition is off by 1.

That's as much as we can say from the log, and the runtime crash dump is usually irrelevant when investigating a CQ or CQ message store exception.

[michaelklishin]

#13856 and #12848 could potentially be relevant but besides the #delta off-by-one discovered in the stack trace above, we don't have any other clues to work with.

[mkuratczyk]

@klemenStanic have you use an older version of RabbitMQ before and it worked without issues? If so, what version was it?

[klemenStanic]

We had no issues on 4.1.0, but hard to say, whether this has anything to do with our problem.
We've been running 4.1.2 for quite a while now, but the issues started couple of days ago.

[gomoripeti]

just throwing in some more chips of information

• although the rabbit_variable_queue:d function is called in many code paths, the crash stack trace points to this line https://github.com/rabbitmq/rabbitmq-server/blob/v4.1.2/deps/rabbit/src/rabbit_variable_queue.erl#L2379
  we know that Q3s is empty (whatever it means)

• 1806336 rem 4096 =:= 0, start_seq_id is on a segment boundary, a lower bound,
  1806336 div 4096 = 441 it is the first entry in segment 441

  #delta {
    start_seq_id = 1806336,
    count = 2,
    transient = 0,
    end_seq_id = 1806337
  }
  

• I think its prio 4 sub-queue that crashed

2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                            {4,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                             {vqstate,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                              {0,[],[]},
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                              {0,[],[]},
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                              {delta,1802269,2,0,1806337},
...

segments of the queue index (of prio4)
segment 441 has 1 unacked message
and it is the last segment :O

2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                               #{426 => 1,436 => 6,441 => 1,416 => 150,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                                 415 => 102,422 => 3,421 => 46,429 => 3,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                                 399 => 3,434 => 2,398 => 12,408 => 151,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                                 424 => 2,418 => 4,427 => 1,396 => 7,403 => 3,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                                 391 => 155,437 => 2,410 => 1,431 => 1,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                                 440 => 1,438 => 11,425 => 4,401 => 2,430 => 1,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                                 395 => 5,404 => 2,390 => 1,419 => 14,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                                 392 => 1560,428 => 3,435 => 42,405 => 1,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                                 411 => 2,397 => 3,439 => 4,407 => 1,420 => 19,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                                 432 => 4,406 => 6,423 => 13,433 => 3,412 => 5,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                                 409 => 3,417 => 10,414 => 7,393 => 19,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                                 402 => 2,400 => 1,394 => 1,413 => 5},

(segmets sorted in a friendlier format

[{390,1},{391,155},{392,1560},{393,19},{394,1},{395,5},{396,7},{397,3},{398,12},{399,3},{400,1},{401,2},{402,2},{403,3},{404,2},{405,1},{406,6},{407,1},{408,151},{409,3},{410,1},{411,2},{412,5},{413,5},{414,7},{415,102},{416,150},{417,10},{418,4},{419,14},{420,19},{421,46},{422,3},{423,13},{424,2},{425,4},{426,1},{427,1},{428,3},{429,3},{430,1},{431,1},{432,4},{433,3},{434,2},{435,42},{436,6},{437,2},{438,11},{439,4},{440,1},{441,1}]

The queue storage has the last message with seq_id 1806336 in its cache

2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                              {qs,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                               <<"/var/lib/rabbitmq/mnesia/rabbit@pl-rabbitmq/msg_stores/vhosts/628WB79CIFDYO9LJI6DK
MI09L/queues/CRRKXCJHUPGZ2B7TTJE9GMYRQ/">>,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                               441,3528,#{},0,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                               #{1806336 =>
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                                  {64,3456,
2025-07-14 08:19:11.472056+02:00 [error] <0.470.0>                                   {mc,mc_amqpl,
...

These are just random observations but it looks like it is the count which is wrong, there is no second message

[michaelklishin]

Yes, the working theory is that this must be a message originally stored by a 3.x node.

[klemenStanic]

Since my last update, we've tried to completely wipe all rabbitmq (/var/lib/rabbitmq/mnesia) data and started ingesting from stratch, with the same configuration. Some queues were still crashing, even non-priority ones.
We've now tried to downgrade to version 4.0.7, will see if this is one more stable for us 🤞

[gomoripeti]

thanks for the update, could you attach one or a few more of the recent crash logs (the big one with the complete report) maybe some common patterns can be spotted in them
is it always the same few queues that crashed or is it randomly any queue?

[michaelklishin]

That does not really help us understand what's going on. If you can reliably trigger this exception, please put together an executable example with PerfTest (it can publish arbitrary user-provided payloads, not just the ones it generates).

[lhoguin]

The very first crash log would be good to have (if different than what you provided).

Otherwise I wonder if some message got acked twice.

[klemenStanic]

Sorry for the late response.

We've identified a problem in our celery application, causing the workers to unexpectedly shut down (with sigkill signal).
This probably triggered a spike in the number dangling or unexpectedly closed connections to the RabbitMQ broker.

Since we addressed this issue, there have been no further queue crashes.

[lhoguin]

Thank you for the feedback. Then that means we also have a bug in RabbitMQ related to unexpected client shutdowns that cause CQs to miscount a message somewhere. Could you provide details in how you use Celery? How messages get published/consumed, if there's auto acks, publisher confirms or any other flags.