Rabbit MQTT Plugin failing to start

[tiaan-lg]

We have set up a cluster of 3 nodes on VM's behind a load balancer

We are using the RabbitMQ MQTT plugin for the messaging protocol and then doing a load test.

After some time the client connections start to drop and one/multiple nodes crash

When they reboot they fail to work at all, and just go into a loop of rebooting.

We looked at the logs and can see that specifically, the rabbitmq_mqtt plugin is failing to start giving the following error

Application rabbitmq_mqtt exited with reason: {timeout,{gen_statem,call,[{mqtt_node,'rabbit@fsk-apnli000000'},trigger_election,5000]}}

The MQTT plugin then never starts again.

This then brings down our entire cluster

We are not sure how to fix this other than clearing everything from the db and re setting up the cluster from scratch

[michaelklishin]

Thank you for your time.

Team RabbitMQ uses GitHub issues for specific actionable items engineers can work on. This assumes that we have a certain amount of information to work with.

Getting all the details necessary to reproduce an issue, make a conclusion or even form a hypothesis about what's happening can take a fair amount of time. Our team is multiple orders of magnitude smaller than the RabbitMQ community. Please help others help you by providing a way to reproduce the behavior you're
observing and sharing as much relevant information as possible on the list:

• Server, client library and plugin (if applicable) versions used
• Server logs
• A code example or terminal transcript that can be used to reproduce
• Full exception stack traces (not a single line message)
• rabbitmqctl status (and, if possible, rabbitmqctl environment output)
• Other relevant things about the environment and workload, e.g. OS/systemd logs, a traffic capture, deployment tool logs, etc

Feel free to edit out hostnames and other potentially sensitive information.

When/if we have a complete enough understanding of what's going on, a recommendation will be provided or a new issues with more context will be filed.

Thank you.

[michaelklishin]

We cannot suggest much without a way to reproduce, logs from all nodes, and any information about what RabbitMQ version was used. All we know is that the plugin failed to initiate a Raft leader election for its client ID tracker. It could be a known scenario addressed in rabbitmq/rabbitmq-mqtt#235 or something else.

[tiaan-lg]

Ok thank you, I will add all the detail requested

[michaelklishin]

Start with exploring the change log and making sure you run 3.8.9 and the node actually has a chance to form a cluster before any load tests begin.

[tiaan-lg]

I can confirm we are using version 3.8.9, how would we know when the cluster has formed correctly?

When setting it up we used the management plugin and the cluster was showing with 3 nodes in it.

[tiaan-lg]

Here is all of the info that we can provide

Server & Client

The server is RabbitMQ version 3.8.9
Running on Windows Server 2019
Using rabbitmq_mqtt plugin version 3.8.9

We then are running a client app for load testing that just fires of connections each with a unique client id (just a guid) this is on a .net core app running client library MqttNet

The test app is at this repo https://github.com/tiaan-lg/MQTT-Test-App

All the logs from the rabbitMQ logs folder and Aditional Info

log.zip

rabbitmqctl status

The rabbitmq app is not running so the status can not be retrieved.

rabbitmqctl environment output

environment.txt

Transcript to reproduce

• Startup 3 nodes (1 per vm)
• See all 3 nodes in the management UI. (Clustering appears to be working)
• Startup several instanced of load testing clients, and watch connections rise. After some time, either the memory will fill up and show red, or it can just happen when there are like 12k connections (no obvious resource exhaustion), you will see it go offline and then come back online, with no connections, and memory will be lower.
• We then noticed when the node comes back, it doesn’t show the two plugins, only the management one, (not rabbitmq_mqtt)
• This then causes one of the other 2 working nodes to then also bomb out because it’s not sharing the load. And within 5 minutes none of the clients can connect cause the nodes are all busy rebooting.
• We have not managed to get more than 12k connections per node, even with the TCP tuning and recommendations. This is not so much the error at the moment, more than when it crashes it needs to recover.

High-Level Explanation and other relevant information

Server Envirment:

• Environment is a test environment (we are busy setting up a mqqt cluster and testing it with the view to go into production with 100k to 200k clients.
• We have an azure load balancer on port 1883 with 3 VMs. Windows Server 2019

Client setup:

• We have written a small c# test app, where each instance of it creates 10k connections and then leaves them idle (like our devices in the field will do)
• We are using MqttNet - https://github.com/chkr1011/MQTTnet

Thank you for being so prompt in response, feel free to DM me and we can also give you access to our system.

We can run a nother setup and show how it fails in real time.

[tiaan-lg]

Hi

We have additional info, the server starts up fine without the mqtt plugin and then when we try to enable it we get this error

Applying plugin configuration to rabbit@fsk-apnli000000...
Stack trace:

** (CaseClauseError) no case clause matching: {:could_not_start, :rabbitmq_mqtt, {:rabbitmq_mqtt, {:bad_return, {{:rabbit_mqtt, :start, [:normal, []]}, {:EXIT, {:timeout, {:gen_statem, :call, [{:mqtt_node, :"rabbit@fsk-apnli000000"}, :trigger_election, 5000]}}}}}}}
    (rabbitmqctl) lib/rabbitmq/cli/plugins/plugins_helpers.ex:210: RabbitMQ.CLI.Plugins.Helpers.update_enabled_plugins/2
    (rabbitmqctl) lib/rabbitmq/cli/plugins/plugins_helpers.ex:107: RabbitMQ.CLI.Plugins.Helpers.update_enabled_plugins/4
    (rabbitmqctl) lib/rabbitmq/cli/plugins/commands/enable_command.ex:121: anonymous fn/6 in RabbitMQ.CLI.Plugins.Commands.EnableCommand.do_run/2
    (elixir) lib/stream.ex:1311: anonymous fn/2 in Stream.iterate/2
    (elixir) lib/stream.ex:1497: Stream.do_unfold/4
    (elixir) lib/stream.ex:1568: Enumerable.Stream.do_each/4
    (elixir) lib/stream.ex:936: Stream.do_enum_transform/7
    (elixir) lib/stream.ex:1568: Enumerable.Stream.do_each/4

{:case_clause, {:could_not_start, :rabbitmq_mqtt, {:rabbitmq_mqtt, {:bad_return, {{:rabbit_mqtt, :start, [:normal, []]}, {:EXIT, {:timeout, {:gen_statem, :call, [{:mqtt_node, :"rabbit@fsk-apnli000000"}, :trigger_election, 5000]}}}}}}}}

When the broker crashed there were about 20k queues active.

[tiaan-lg]

@michaelklishin Could a limit on Disk IOPS be causing the trigger_election call to timeout?

[michaelklishin]

I highly doubt it.

[Zapnologica]

Is there any update on this?

We are busy testing the mqqt plugin, and we are just having issues with it. It seems the plugin crashes, and then it cannot restart again, causing the entire cluster to go down.

We are running 3 windows virtual machines in a cluster, with the mqqt plugin enabled. rabbitmq_mqtt plugin version 3.8.9

[michaelklishin]

We cannot comment on "the plugin crashes". If you are certain what you see is what's described in this issue, consider sharing logs at debug level. A plugin startup can affect only one node.

[Zapnologica]

Only one node is effected at a time, but because the one node goes down, the other nodes get a sudden increase in traffic, which then causes them to crash and not restart. I'm not too sure how to share the logs at debug level. I am fairly new to rabbit mq.

[michaelklishin]

Accoding to the provided logs, this cluster experience all kinds of highly unusual events, such as…

Node Fails to Rejoin the Cluster Because Its Cluster Identity is Different

2020-12-02 15:35:04.936 [error] <0.349.0> Mnesia('rabbit@fsk-apnli000001'): ** ERROR ** (core dumped to file: "c:/Users/FskAdmin/AppData/Roaming/RabbitMQ/MnesiaCore.rabbit@fsk-apnli000001_1606_923304_923000")
 ** FATAL ** Failed to merge schema: Bad cookie in table definition rabbit_user_permission: 'rabbit@fsk-apnli000001' = {cstruct,rabbit_user_permission,set,[],['rabbit@fsk-apnli000002','rabbit@fsk-apnli000001','rabbit@fsk-apnli000000'],[],[],0,read_write,false,[],[],false,user_permission,[user_vhost,permission],[],[],[],{{1645484109215744,-576460752303423295,1},'rabbit@fsk-apnli000000'},{{4,0},{'rabbit@fsk-apnli000002',{1606,918469,603000}}}}, 'rabbit@fsk-apnli000000' = {cstruct,rabbit_user_permission,set,[],['rabbit@fsk-apnli000000'],[],[],0,read_write,false,[],[],false,user_permission,[user_vhost,permission],[],[],[],{{1645487923865600,-576460752303423199,1},'rabbit@fsk-apnli000000'},{{2,0},[]}}

means that a node tried to join a cluster it was not previously a member of. The "cookie" here refers to a schema database identity and has nothing to do with the Erlang cookie. I fail to see how this can happen according to the set of steps above but logs don't lie.

Nodes Stop Responding to Inter-Node Heartbeats

2020-12-02 14:34:20 =ERROR REPORT====
** Node 'rabbit@fsk-apnli000002' not responding **
** Removing (timedout) connection **

Can be just an indication that a peer node has gone down.

MQTT Plugin Timing Out on Triggering Elections

2020-12-02 14:38:05.211 [error] <0.596.0> BOOT FAILED
2020-12-02 14:38:05.211 [error] <0.596.0> ===========
2020-12-02 14:38:05.211 [error] <0.596.0> Error during startup: {error,
2020-12-02 14:38:05.211 [error] <0.596.0>                        {rabbitmq_mqtt,
2020-12-02 14:38:05.211 [error] <0.596.0>                         {bad_return,
2020-12-02 14:38:05.211 [error] <0.596.0>                          {{rabbit_mqtt,start,[normal,[]]},
2020-12-02 14:38:05.211 [error] <0.596.0>                           {'EXIT',
2020-12-02 14:38:05.211 [error] <0.596.0>                            {timeout,
2020-12-02 14:38:05.211 [error] <0.596.0>                             {gen_statem,call,
2020-12-02 14:38:05.211 [error] <0.596.0>                              [{mqtt_node,'rabbit@fsk-apnli000001'},
2020-12-02 14:38:05.211 [error] <0.596.0>                               trigger_election,5000]}}}}}}}
2020-12-02 14:38:05.211 [error] <0.596.0> 
2020-12-02 14:38:05.211 [info] <0.801.0> [{initial_call,{application_master,init,['Argument__1','Argument__2','Argument__3','Argument__4']}},{pid,<0.801.0>},{registered_name,[]},{error_info,{exit,{bad_return,{{rabbit_mqtt,start,[normal,[]]},{'EXIT',{timeout,{gen_statem,call,[{mqtt_node,'rabbit@fsk-apnli000001'},trigger_election,5000]}}}}},[{application_master,init,4,[{file,"application_master.erl"},{line,138}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,249}]}]}},{ancestors,[<0.800.0>]},{message_queue_len,1},{messages,[{'EXIT',<0.802.0>,normal}]},{links,[<0.800.0>,<0.44.0>]},{dictionary,[]},{trap_exit,true},{status,running},{heap_size,610},{stack_size,27},{reductions,227}], []
2020-12-02 14:38:05.211 [error] <0.801.0> CRASH REPORT Process <0.801.0> with 0 neighbours exited with reason: {timeout,{gen_statem,call,[{mqtt_node,'rabbit@fsk-apnli000001'},trigger_election,5000]}} in application_master:init/4 line 138

@tiaan-lg do you monitor nodes to have at least some idea as to what makes the node run out of memory? TCP connections, and MQTT state on top are not free, so at the very least see Tuning for a Large Number of Connections.

There is evidence of memory alarms going off, suggesting that the node's memory usage grows over time:

**********************************************************
*** Publishers will be blocked until this alarm clears ***
**********************************************************
2020-12-02 11:35:40.479 [info] <0.22879.23> accepting MQTT connection <0.22879.23> (102.37.100.34:36841 -> 10.0.0.5:1883, client id: 970f5032-8aac-4cce-9766-6b96d79b80c2)
2020-12-02 11:35:40.479 [info] <0.22905.23> MQTT vhost picked using plugin configuration or default
2020-12-02 11:35:40.510 [info] <0.22905.23> accepting MQTT connection <0.22905.23> (102.37.100.34:36843 -> 10.0.0.5:1883, client id: dc27c0d4-e5e7-4251-864b-688abf831b17)
2020-12-02 11:35:40.542 [info] <0.22930.23> MQTT vhost picked using plugin configuration or default
2020-12-02 11:35:40.557 [info] <0.22930.23> accepting MQTT connection <0.22930.23> (155.93.207.31:61549 -> 10.0.0.5:1883, client id: 43ed4581-80bb-4551-80f7-89801c2b9401)
2020-12-02 11:35:40.932 [info] <0.5997.0> vm_memory_high_watermark set. Memory used:6235095040 allowed:6012180070
2020-12-02 11:35:40.932 [warning] <0.5995.0> memory resource limit alarm set on node 'rabbit@fsk-apnli000001'.

This is no evidence of a memory leak since every connection consumes resources.

einval Socket Errors at Code that Rejects Clients with Duplicate IDs

** {{badmatch,{error,einval}},[{rabbit_mqtt_processor,process_login,4,[{file,"src/rabbit_mqtt_processor.erl"},{line,545}]},{rabbit_mqtt_processor,process_request,3,[{file,"src/rabbit_mqtt_processor.erl"},{line,129}]},{rabbit_mqtt_processor,process_frame,2,[{file,"src/rabbit_mqtt_processor.erl"},{line,69}]},{rabbit_mqtt_reader,process_received_bytes,2,[{file,"src/rabbit_mqtt_reader.erl"},{line,303}]},{gen_server2,handle_msg,2,[{file,"src/gen_server2.erl"},{line,1067}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,259}]}]}
2020-12-02 11:37:05.752 [error] <0.3387.17> MQTT: a socket write failed, the socket might already be closed
2020-12-02 11:37:05.752 [info] <0.26420.21> MQTT connection "102.37.100.34:34153 -> 10.0.0.5:1883" will terminate because peer closed TCP connection
2020-12-02 11:37:05.752 [info] <0.3238.17> MQTT connection "155.93.207.31:57178 -> 10.0.0.5:1883" will terminate because peer closed TCP connection
2020-12-02 11:37:05.752 [info] <0.20878.23> MQTT connection "155.93.207.31:61531 -> 10.0.0.5:1883" will terminate because peer closed TCP connection
2020-12-02 11:37:05.752 [info] <0.26076.21> MQTT connection "102.37.100.34:34139 -> 10.0.0.5:1883" will terminate because peer closed TCP connection
2020-12-02 11:37:05.752 [info] <0.3982.17> MQTT connection "155.93.207.31:53437 -> 10.0.0.5:1883" will terminate because peer closed TCP connection
2020-12-02 11:37:05.752 [info] <0.27407.21> MQTT connection "155.93.207.31:60408 -> 10.0.0.5:1883" will terminate because peer closed TCP connection

2020-12-02 11:37:05.736 [error] <0.1524.17> MQTT: a socket write failed, the socket might already be closed
2020-12-02 11:37:05.736 [error] <0.26105.21> MQTT: a socket write failed, the socket might already be closed
2020-12-02 11:37:05.736 [info] <0.2128.17> MQTT connection "102.37.100.34:27519 -> 10.0.0.5:1883" will terminate because peer closed TCP connection
2020-12-02 11:37:05.736 [info] <0.1194.17> MQTT connection "155.93.207.31:57124 -> 10.0.0.5:1883" will terminate because peer closed TCP connection
2020-12-02 11:37:05.736 [info] <0.27188.21> MQTT connection "102.37.100.34:34185 -> 10.0.0.5:1883" will terminate because peer closed TCP connection
2020-12-02 11:37:05.736 [info] <0.4006.17> MQTT connection "155.93.207.31:57198 -> 10.0.0.5:1883" will terminate because peer closed TCP connection
2020-12-02 11:37:05.736 [error] <0.26420.21> MQTT: a socket write failed, the socket might already be closed
2020-12-02 11:37:05.736 [error] <0.3238.17> MQTT: a socket write failed, the socket might already be closed
2020-12-02 11:37:05.736 [info] <0.27944.21> MQTT connection "102.37.100.34:34221 -> 10.0.0.5:1883" will terminate because peer closed TCP connection
2020-12-02 11:37:05.736 [error] <0.20878.23> MQTT: a socket write failed, the socket might already be closed
2020-12-02 11:37:05.752 [info] <0.2032.17> MQTT connection "155.93.207.31:57146 -> 10.0.0.5:1883" will terminate because peer closed TCP connection
2020-12-02 11:37:05.752 [info] <0.25982.21> MQTT connection "102.37.100.34:34135 -> 10.0.0.5:1883" will terminate because peer closed TCP connection
2020-12-02 11:37:05.752 [info] <0.1524.17> MQTT connection "102.37.100.34:27499 -> 10.0.0.5:1883" will terminate because peer closed TCP connection
2020-12-02 11:37:05.752 [info] <0.26105.21> MQTT connection "155.93.207.31:11198 -> 10.0.0.5:1883" will terminate because peer closed TCP connection
2020-12-02 11:37:05.752 [error] <0.26076.21> MQTT: a socket write failed, the socket might already be closed
2020-12-02 11:37:05.752 [error] <0.27407.21> MQTT: a socket write failed, the socket might already be closed
2020-12-02 11:37:05.752 [error] <0.27311.21> MQTT: a socket write failed, the socket might already be closed

suggests that the node is experiencing a high connection churn scenario, which is indeed common with brute force/flood connection tests.

Hypothesis

My best guess is that on top of the above observations, at some point the node runs out of file descriptors and fails to persist some of its state. That would explain some of the weird behavior above. On Windows there can be all kinds of tools that can prevent a process from doing what it expects to be able to do, such as anti-virus software. That must be disabled for RabbitMQ nodes and node data directory.

[michaelklishin]

So my conclusion so far is that the node is run out of resources by a flood connection test. It certainly hits its memory alarm limit. I cannot know what uses the memory but node can report a decently detailed breakdown.

Nodes also seem to run out of file descriptor or a socket limit of some kind, or both, likely due to the test creating a high connection churn scenario which is a very problematic scenario that requires optimization of certain settings. A node that has run out of file descriptors and cannot open a connection to its peers will fail in all kinds of weird ways.

Supporting 200K connections is unrealistic with all defaults for both RabbitMQ TCP buffer size and kernel TCP settings (that can keep connections in TIME_WAIT state for long enough to drive nodes out of sockets/file descriptors). The docs explain the key variables involved. Some are Linux-specific
because that's where the majority of users run such workloads.

[baelter]

For the record we are also seeing this on clusters with a lot of mqtt connections. Our "solution" has been to delete the quorum dir in mnesia (1 node clusters).

[carlhoerberg]

For the record we are also seeing this on clusters with a lot of mqtt connections. Our "solution" has been to delete the quorum dir in mnesia (1 node clusters).

We've seen it for <3.8.10 clusters, this is probably fixed with #2692, which was shipped with https://github.com/rabbitmq/rabbitmq-server/releases/tag/v3.8.10