Amonymous login MQTT messages seem to randomly crash the rabbit

[Alexia Death]

I have a bit of a pickle...

I was using EMQ for mqtt broker for ages and my small homebrew IoT rig ticked over nicely. However debugging is pain on MQ so I switched to Rabbit that as AMQ broker has given me minimal amount of grief and has some nice things I can do for debugging like custom bindings and such. but now it seems Ive ran into a bug...

Most connections work fine, however every 6th or so produces this:

2019-06-29 22:26:39.808 [info] <0.913.0> closing MQTT connection <0.913.0> (192.168.1.8:60050 -> 192.168.1.8:1883)
2019-06-29 22:26:44.965 [error] <0.949.0> ** Generic server <0.949.0> terminating
** Last message in was {tcp,#Port<0.106>,<<16,35,0,4,77,81,84,84,4,2,0,60,0,23,112,97,104,111,47,67,52,55,53,67,70,48,53,49,65,68,70,49,49,51,70,56,50,48,148,4,0,27,47,104,111,109,101,108,121,47,114,102,108,105,110,107,47,114,101,113,117,101,115,116,47,52,53,95,50,123,1
0,32,32,32,32,34,98,111,100,121,34,58,32,123,10,32,32,32,32,32,32,32,32,34,97,99,116,105,111,110,34,58,32,34,115,101,110,100,34,44,32,10,32,32,32,32,32,32,32,32,34,97,100,100,114,101,115,115,34,58,32,34,75,97,107,117,59,52,53,59,50,59,34,44,32,10,32,32,32,32,32,32,32,32
,34,115,119,105,116,99,104,95,99,111,109,109,97,110,100,34,58,32,34,79,70,70,34,44,32,10,32,32,32,32,32,32,32,32,34,115,119,105,116,99,104,95,105,100,34,58,32,34,52,53,95,50,34,44,32,10,32,32,32,32,32,32,32,32,34,115,119,105,116,99,104,95,109,111,100,101,108,34,58,32,11
0,117,108,108,10,32,32,32,32,125,44,32,10,32,32,32,32,34,99,108,105,101,110,116,95,105,100,34,58,32,34,114,102,108,105,110,107,34,44,32,10,32,32,32,32,34,104,97,114,100,119,97,114,101,95,105,100,101,110,116,105,102,105,101,114,34,58,32,34,52,53,95,50,34,44,32,10,32,32,3
2,32,34,104,97,114,100,119,97,114,101,95,110,97,109,101,34,58,32,34,83,112,97,32,108,105,103,104,116,32,116,119,111,34,44,32,10,32,32,32,32,34,109,101,115,115,97,103,101,95,105,100,34,58,32,34,50,48,49,57,45,48,54,45,50,57,32,...>>}
** When Server state == {state,#Port<0.106>,"192.168.1.8:58078 -> 192.168.1.8:1883",true,undefined,false,running,{none,none},<0.948.0>,false,none,{proc_state,#Port<0.106>,#{},{undefined,undefined},{0,nil},{0,nil},undefined,1,undefined,undefined,undefined,{undefined,unde
fined},undefined,<<"amq.topic">>,{amqp_adapter_info,{0,0,0,0,0,65535,49320,264},1883,{0,0,0,0,0,65535,49320,264},58078,<<"192.168.1.8:58078 -> 192.168.1.8:1883">>,{'MQTT',"N/A"},[{channels,1},{channel_max,1},{frame_max,0},{client_properties,[{<<"product">>,longstr,<<"MQ
TT client">>}]},{ssl,false}]},none,undefined,undefined,#Fun<rabbit_mqtt_processor.0.130296119>,{0,0,0,0,0,65535,49320,264}},undefined,{state,fine,5000,undefined}}
** Reason for termination ==  
** {{badmatch,{error,einval}},[{rabbit_mqtt_processor,process_login,4,[{file,"src/rabbit_mqtt_processor.erl"},{line,521}]},{rabbit_mqtt_processor,process_request,3,[{file,"src/rabbit_mqtt_processor.erl"},{line,132}]},{rabbit_mqtt_processor,process_frame,2,[{file,"src/ra
bbit_mqtt_processor.erl"},{line,72}]},{rabbit_mqtt_reader,process_received_bytes,2,[{file,"src/rabbit_mqtt_reader.erl"},{line,282}]},{gen_server2,handle_msg,2,[{file,"src/gen_server2.erl"},{line,1056}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,249}]}]}
2019-06-29 22:26:44.966 [error] <0.949.0> CRASH REPORT Process <0.949.0> with 0 neighbours exited with reason: no match of right hand value {error,einval} in rabbit_mqtt_processor:process_login/4 line 521 in gen_server2:terminate/3 line 1172
2019-06-29 22:26:44.966 [error] <0.947.0> Supervisor {<0.947.0>,rabbit_mqtt_connection_sup} had child rabbit_mqtt_reader started with rabbit_mqtt_reader:start_link(<0.948.0>, {acceptor,{0,0,0,0,0,0,0,0},1883}) at <0.949.0> exit with reason no match of right hand value {
error,einval} in rabbit_mqtt_processor:process_login/4 line 521 in context child_terminated
2019-06-29 22:26:44.966 [error] <0.947.0> Supervisor {<0.947.0>,rabbit_mqtt_connection_sup} had child rabbit_mqtt_reader started with rabbit_mqtt_reader:start_link(<0.948.0>, {acceptor,{0,0,0,0,0,0,0,0},1883}) at <0.949.0> exit with reason reached_max_restart_intensity
in context shutdown

and the message is lost - the subscribers never see it.

This looks like a bug to me... or is there something in the config I can look at?

Best,

Alexia

[Alexia Death]

Client(python one) is under the impression that publish worked fine and send succeded..

[Alexia Death]

Hmmm, It may be that I figured it out myself...

mqtt.tcp_listen_options.exit_on_close = false

The conf sample sets it to true. This is a hit and run client and seems the default is inappropriate for it. It seems the backend was terminating occasionally without having completed it's work because client closed connection faster.

Best,

Alexia

On Saturday, June 29, 2019 at 10:34:48 PM UTC+3, Alexia Death wrote:

[Michael Klishin]

Your thinking makes sense, even though all the exception tells us is that a connection socket was in the EINVAL state at the time

of attempted operation. This indeed very likely is a sign of a race condition between connection being closed and an operation

(such as message delivery) being performed on it.

I don't know if disabling exit_on_close is the right approach but if it works for you and you don't observe any connection leaks [1], go for it.

1. https://www.rabbitmq.com/connections.html#monitoring

--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To post to this group, send email to rabbitm...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/rabbitmq-users/a688709e-f020-40ec-a19a-f095931ecd69%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

MK

Staff Software Engineer, Pivotal/RabbitMQ