API delete endpoint intermittently runs into an exception in rabbit_exchange:serialise_events/1

[rauno56]

Describe the bug

I'm maintaining an automation tool that manages rabbitMQ resources. The tool sometimes needs to create or delete tens to multiple hundreds of resources at once. If the request count is bigger than 10 the API often returns an 400 error:

[warning] <0.77274.0> Delete exchange error: {'EXIT',
[warning] <0.77274.0>     {function_clause,
[warning] <0.77274.0>         [{rabbit_exchange,serialise_events,
[warning] <0.77274.0>              [undefined],
[warning] <0.77274.0>              [{file,"rabbit_exchange.erl"},{line,81}]},
[warning] <0.77274.0>          {rabbit_exchange,serial,1,[{file,"rabbit_exchange.erl"},{line,89}]},
[warning] <0.77274.0>          {rabbit_binding,'-process_deletions/1-fun-0-',2,
[warning] <0.77274.0>              [{file,"rabbit_binding.erl"},{line,436}]},
[warning] <0.77274.0>          {dict,map_bucket,2,[{file,"dict.erl"},{line,482}]},
[warning] <0.77274.0>          {dict,map_bkt_list,2,[{file,"dict.erl"},{line,478}]},
[warning] <0.77274.0>          {dict,map_bkt_list,2,[{file,"dict.erl"},{line,478}]},
[warning] <0.77274.0>          {dict,map_seg_list,2,[{file,"dict.erl"},{line,473}]},
[warning] <0.77274.0>          {dict,map_dict,2,[{file,"dict.erl"},{line,468}]}]}}
[warning] <0.77277.0> Delete exchange error: {'EXIT',
[warning] <0.77277.0>     {function_clause,
[warning] <0.77277.0>         [{rabbit_exchange,serialise_events,
[warning] <0.77277.0>              [undefined],
[warning] <0.77277.0>              [{file,"rabbit_exchange.erl"},{line,81}]},
[warning] <0.77277.0>          {rabbit_exchange,serial,1,[{file,"rabbit_exchange.erl"},{line,89}]},
[warning] <0.77277.0>          {rabbit_binding,'-process_deletions/1-fun-0-',2,
[warning] <0.77277.0>              [{file,"rabbit_binding.erl"},{line,436}]},
[warning] <0.77277.0>          {dict,map_bucket,2,[{file,"dict.erl"},{line,482}]},
[warning] <0.77277.0>          {dict,map_bkt_list,2,[{file,"dict.erl"},{line,478}]},
[warning] <0.77277.0>          {dict,map_bkt_list,2,[{file,"dict.erl"},{line,478}]},
[warning] <0.77277.0>          {dict,map_seg_list,2,[{file,"dict.erl"},{line,473}]},
[warning] <0.77277.0>          {dict,map_dict,2,[{file,"dict.erl"},{line,468}]}]}}

There's mostly two or more failing requests at once. Above logs show one case with two of them(note the timestamp).

I suspect there's a race-condition deleting bindings or something, but I'm speculating.

Either way, a more useful error than the one above would be really helpful.

Reproduction steps

I'll provide a script for repro needed.

Expected behavior

Human readable error message.

Additional context

Server version: 3.13.6

[michaelklishin]

@rauno56 we cannot suggest anything with the amount of information.

The stack trace at scenario that involves a binding deletion, so my best guess is that it is what we was up to a couple of years ago. I won't guess any further, we do not guess in this community.

In 4.x with Khepri, binding deletion will be single operation in the data store instead of a transaction over a potentially large number of rows, which is the case with Mnesia.

[michaelklishin]

Looks like an exchanged that has just been deleted concurrently is passed on to a function that notifies exchange decorators. It could simply be more defensive as I don't know what the error message would look like and how that would help anyone.

[rauno56]

What kind of information could I provide more that would help to get to the bottom of this?

The stack trace at scenario that involves a binding deletion

If that's the case(I cannot read Erlang's stack traces tbh), I speculate that it has to do with deleting two exchanges or a exchange and queue that are bound together in the same binding.

that it is what we was up to a couple of years ago

Any further context so I can confirm?

error message would look like and how that would help anyone.

If the above speculations are right it should not even error.

If they are not right, it should error with something that explains how to avoid it - because it is in fact possible to avoid it by adding a delay between delete requests.

[michaelklishin]

The usual minimum any maintainer would need to investigate an issue: RabbitMQ version, full logs from all nodes (with sensitive values edited out), and a set of specific steps we can use to reproduce.

[michaelklishin]

If the above speculations are right it should not even error

You are welcome to investigate the issue since this is open source software and you haven't shared any steps to reproduce.

The exception can be avoided by making the function in the title more defensive (it receives undefined as the argument according to the snippet).

[michaelklishin]

Just for comparison, this is another approach to reporting something: the reporter goes to incredible lengths to help us collectively understand a tricky behavior that is not even a RabbitMQ behavior per se but affects RabbitMQ AMQP 1.0 shovels.

And here all we have is a stack trace and a suggestion to "do N deletion requests concurrently."

[michaelklishin]

A potentially highly relevant discussion where I explain what may be the root cause and what the possible options are (in 4.0.x) #13030.

[michaelklishin]

Also somewhat relevant #12927 but the issue there was binding churn, which was resolved (a close to two orders of magnitude improvement) by moving to 4.0.5 and switching to Khepri.

[michaelklishin]

I have added a note to the 4.0 release notes that explain the fundamental problem, how Khepri fundamentally addresses it, and what those who are still on Mnesia or 3.x versions can do to work around it.