Writing to MQTT socket failed: badarg

[pfeifi01]

Describe the bug

After filing the last bug, that was then converted to discussion #9195 we have now installed v3.12.5, but we still run into issues.

After starting the RabbitMQ and after automatically establishing connection with clients, it only took a few seconds that we lost connection again and found new errors in the log files.

Here is the log file

Reproduction steps

See #9195

Expected behavior

• no "bad arg" error messages
• no "failed to establish because socket addresses could not be determined: einval" error messages

Additional context

No response

[lukebakken]

This is the related discussion - #9196

[ansd]

@pfeifi01 please upload the log file to this GitHub issue instead to dubious 3rd party websites.

[pfeifi01]

[email protected]

last time it was too big.

[lukebakken]

Just so you know, you can compress files using Zip or gzip and upload them.

[ansd]

Thanks for the log file.

Compared to #9196, I now see a very good improvement:
Once an MQTT connection process fails to write to the socket, the connection logs an error and terminates immediately. There are no memory alarms anymore.

The log file show the following errors starting at roughly the same time:

<0.366.0> ** Generic server rabbit_disk_monitor terminating
<0.366.0> ** Last message in was update
<0.366.0> ** When Server state == {state,"c:/Users/adm_FERAG/AppData/Roaming/RabbitMQ/db/rabbit@PAPPFERAGPS01-mnesia",
<0.366.0>                                50000000,33246449664,100,10000,
<0.366.0>                                #Ref<0.3676696284.3581411342.197188>,false,
<0.366.0>                                true,10,120000,
<0.366.0>                                {win32,nt},
<0.366.0>                                not_used}
<0.366.0> ** Reason for termination ==
<0.366.0> ** {badarith,[{erlang,'-',
<0.366.0>                       ['NaN',50000000],
<0.366.0>                       [{error_info,#{module => erl_erts_errors}}]},
<0.366.0>               {rabbit_disk_monitor,interval,1,
<0.366.0>                                    [{file,"rabbit_disk_monitor.erl"},
<0.366.0>                                     {line,428}]},
<0.366.0>               {rabbit_disk_monitor,start_timer,1,
<0.366.0>                                    [{file,"rabbit_disk_monitor.erl"},
<0.366.0>                                     {line,419}]},
<0.366.0>               {rabbit_disk_monitor,handle_info,2,
<0.366.0>                                    [{file,"rabbit_disk_monitor.erl"},
<0.366.0>                                     {line,194}]},
<0.366.0>               {gen_server,try_dispatch,4,
<0.366.0>                           [{file,"gen_server.erl"},{line,1123}]},
<0.366.0>               {gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,1200}]},
<0.366.0>               {proc_lib,init_p_do_apply,3,
<0.366.0>                         [{file,"proc_lib.erl"},{line,240}]}]}
<0.366.0> 

@lukebakken we may want to fix this crash regression caused by #8837.

We also see

[info] <0.883.0> MQTT detected network error for <<"10.162.39.103:59294 -> 192.168.10.131:1883">>: econnaborted

and

[error] <0.1015.0> writing to MQTT socket #Port<0.117> failed: badarg

and

[error] <0.2585.0> MQTT connection 10.162.39.120:53779 -> 192.168.10.131:1883 failed to establish because socket addresses could not be determined: einval

The last one as documented in

rabbitmq-server/deps/rabbitmq_mqtt/src/rabbit_mqtt_processor.erl

Lines 104 to 112 in 0341b5f

	%% Check whether peer closed the connection.
	%% For example, this can happen when connection was blocked because of resource
	%% alarm and client therefore disconnected due to client side CONNACK timeout.
	case rabbit_net:socket_ends(Socket, inbound) of
	{ok, SocketEnds} ->
	process_connect(ConnectPacket, Socket, ConnName, SendFun, SocketEnds);
	{error, Reason} ->
	{error, {socket_ends, Reason}}
	end.

means that an MQTT client connected to RabbitMQ, but when RabbitMQ processes the CONNECT packet the client already closed the socket. We can log this at info or warning level instead of error level. However, there is not a lot RabbitMQ can do in this case: If the client closed the TCP connection before RabbitMQ has had a chance to process the CONNECT packet, RabbitMQ will have to close the connection.

The other errors also indicate TCP connection issues from the server to the client: econnaborted means the connection was aborted. The badarg error is caused by not being abled to write to the socket.

In summary, since all these errors start to happen at roughly the same time, based on the log file I suspect that RabbitMQ is overloaded. I don't see a bug in the MQTT plugin. If adding more resources to RabbitMQ does not help and you suspect that RabbitMQ behaves not correctly, please perform profiling as described in https://www.rabbitmq.com/monitoring.html and https://blog.rabbitmq.com/posts/2022/05/flame-graphs/ .

Converting this issue to a discussion.

[ansd]

I also wrote an MQTT performance and scalability checklist in https://next.rabbitmq.com/mqtt.html#scalability

[ansd]

If you think there are MQTT workloads that RabbitMQ should be able to handle, but doesn't, then please provide a GitHub repo with reproduction steps including all client workload and all server configurations, for example as done in https://github.com/ansd/rabbitmq-mqtt/tree/blog-post-native-mqtt/one-to-one