MQTT sockets disconnect upon connect

mfarver

I’ve been trying to replace the backend in the tracker sample with one written directly against the mqtt library in zephyr. The socket used for connecting appears to close immediately after the connection attempt (net_sock.z_impl_zsock_close). I’ve compared the message sent by the mqtt library with one from my (working MQTT client) on my PC and they are identical. Not really sure what is going on.

[00:00:07.626,983] <inf> app_main: Evt: APP_EVENT_CELLULAR_DISCONNECT [00:00:07.634,246] <inf> app_main: Evt: APP_EVENT_CELLULAR_CONNECTED [00:00:07.641,632] <dbg> nrf9160_gps.gps_thread: A-GPS data update needed [00:00:07.649,566] <inf> app_main: Evt: APP_EVENT_GPS_STARTED [00:00:07.656,127] <inf> app_main: Evt: APP_EVENT_AGPS_REQUEST [00:00:07.662,719] <inf> app_main: APP_EVENT_AGPS_REQUEST: 1 [00:00:07.669,830] <dbg> net_mqtt_sock_tcp.mqtt_client_tcp_connect: (0x20016438): Created socket 1 [00:00:08.620,574] <dbg> nrf9160_gps.gps_thread: Waiting for time window to operate [00:00:10.715,332] <dbg> net_mqtt_sock_tcp.mqtt_client_tcp_connect: (0x20016438): Connect completed [00:00:10.725,494] <dbg> net_mqtt_enc.Encoding Protocol Description. 4d 51 54 54 |MQTT [00:00:10.742,431] <dbg> net_mqtt_enc.pack_utf8_str: (0x20016438): >> str_size:00000006 cur:0x20018f31, end:0x2001932c [00:00:10.754,272] <dbg> net_mqtt_enc.pack_uint16: (0x20016438): >> val:0004 cur:0x20018f31, end:0x2001932c [00:00:10.765,075] <dbg> net_mqtt_enc.connect_request_encode: (0x20016438): Encoding Protocol Version 04. [00:00:10.775,695] <dbg> net_mqtt_enc.pack_uint8: (0x20016438): >> val:04 cur:0x20018f37, end:0x2001932c [00:00:10.786,224] <dbg> net_mqtt_enc.pack_uint8: (0x20016438): >> val:00 cur:0x20018f38, end:0x2001932c [00:00:10.796,752] <dbg> net_mqtt_enc.connect_request_encode: (0x20016438): Encoding Keep Alive Time 003c. [00:00:10.807,464] <dbg> net_mqtt_enc.pack_uint16: (0x20016438): >> val:003c cur:0x20018f39, end:0x2001932c [00:00:10.818,267] <dbg> net_mqtt_enc.Encoding Client Id. 6e 72 66 2d 33 35 32 36 35 36 31 30 37 32 33 35 |nrf-3526 56107235 30 30 30 |000 [00:00:10.844,146] <dbg> net_mqtt_enc.pack_utf8_str: (0x20016438): >> str_size:00000015 cur:0x20018f3b, end:0x2001932c [00:00:10.855,987] <dbg> net_mqtt_enc.pack_uint16: (0x20016438): >> val:0013 cur:0x20018f3b, end:0x2001932c [00:00:10.866,821] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x20016438): << msg type:0x10 length:0x0000001f [00:00:10.878,082] <dbg> net_mqtt_enc.packet_length_encode: (0x20016438): >> length:0x0000001f cur:(nil), end:(nil) [00:00:10.889,678] <dbg> net_mqtt_enc.mqtt_encode_fixed_header: (0x20016438): Fixed header length = 02 [00:00:10.900,024] <dbg> net_mqtt_enc.pack_uint8: (0x20016438): >> val:10 cur:0x20018f2f, end:0x2001932c [00:00:10.910,583] <dbg> net_mqtt_enc.packet_length_encode: (0x20016438): >> length:0x0000001f cur:0x20018f30, end:0x2001932c [00:00:10.923,065] <dbg> net_mqtt.Writing packet. 10 1f 00 04 4d 51 54 54 04 02 00 3c 00 13 6e 72 |....MQTT ...<..nr 66 2d 33 35 32 36 35 36 31 30 37 32 33 35 30 30 |f-352656 10723500 30 |0 [00:00:10.957,275] <dbg> net_mqtt.client_connect: (0x20016438): Connect completed [00:00:10.965,637] <inf> backend_mqtt: mqtt_connect called [00:00:15.973,541] <wrn> date_time: sntp_query, error: -116 [00:00:15.980,133] <dbg> net_sock.z_impl_zsock_close: (0x20015838): close: ctx=0x200197a0, fd=2 [00:00:16.937,805] <dbg> net_sock.z_impl_zsock_close: (0x20015838): close: ctx=0x200197a0, fd=2
Running out of ideas to try, anyone have a guess or something I should look at?

jaredwolff

mfarver Look like you’re also making a call to an NTP server at the same time? In my experience, I couldn’t trust opening two separate sockets at once. One operation first, in my case SNTP, wait for it to finish before connecting to MQTT.

You also should make sure that you’re connected to MQTT before you attempt so send any data.

mfarver

I was able to do a capture with Soracom’s nifty packet capture feature. It showed that the connection was being made to the MQTT server and the server was sending back an MQTT CONNACK. So I knew I had everything configured right and it was something in the code. The solution that ended up working was to call mqtt_input function in a background thread every 100ms or so. This gave the MQTT library more chances to receive and process the reply. Once I did that everything started working as expected.

jaredwolff

Ahh yea! mqtt_live and mqtt_input are important functions to run in a separate thread. All of the MQTT implementations that I’ve seen have this. Good catch!