Issue getting cellfund MQTT to work on 9160

[DawidRicsys]

I have a GSM application connecting to MQTT that worked previously refuse to work when I picked it up again to improve on it.

To make sure there isnt a problem in my firmware I'm trying to get the GSM fundamentals course to run as well but im still running into a problem.

Running lesson4, ex1 solution without any changes, apart from adding logging levels, I get this output:

*** Booting nRF Connect SDK v2.5.0 ***
[00:00:00.305,328] <inf> Lesson4_Exercise1: Initializing modem library
[00:00:00.554,870] <inf> Lesson4_Exercise1: Connecting to LTE network
[00:00:03.210,174] <inf> Lesson4_Exercise1: RRC mode: Connected
[00:00:04.364,013] <inf> Lesson4_Exercise1: Network registration status: Connected - home network
[00:00:04.364,135] <inf> Lesson4_Exercise1: Connected to LTE network
[00:00:41.129,943] <inf> Lesson4_Exercise1: IPv4 Address found 91.121.93.94
[00:00:41.130,371] <inf> Lesson4_Exercise1: Connection to broker using mqtt_connect
[00:00:41.130,645] <dbg> net_mqtt_sock_tcp: mqtt_client_tcp_connect: (0x2000d2d8): Created socket 0
[00:00:41.484,771] <dbg> net_mqtt_sock_tcp: mqtt_client_tcp_connect: (0x2000d2d8): Connect completed
[00:00:41.484,802] <dbg> net_mqtt_enc: connect_request_encode: Encoding Protocol Description.
                                       4d 51 54 54                                      |MQTT
[00:00:41.484,832] <dbg> net_mqtt_enc: pack_utf8_str: (0x2000d2d8): >> str_size:00000006 cur:0x2000dd37, end:0x2000ddb2
[00:00:41.484,863] <dbg> net_mqtt_enc: pack_uint16: (0x2000d2d8): >> val:0004 cur:0x2000dd37, end:0x2000ddb2
[00:00:41.484,863] <dbg> net_mqtt_enc: connect_request_encode: (0x2000d2d8): Encoding Protocol Version 04.
[00:00:41.484,893] <dbg> net_mqtt_enc: pack_uint8: (0x2000d2d8): >> val:04 cur:0x2000dd3d, end:0x2000ddb2
[00:00:41.484,893] <dbg> net_mqtt_enc: pack_uint8: (0x2000d2d8): >> val:00 cur:0x2000dd3e, end:0x2000ddb2
[00:00:41.484,924] <dbg> net_mqtt_enc: connect_request_encode: (0x2000d2d8): Encoding Keep Alive Time 003c.
[00:00:41.484,924] <dbg> net_mqtt_enc: pack_uint16: (0x2000d2d8): >> val:003c cur:0x2000dd3f, end:0x2000ddb2
[00:00:41.484,954] <dbg> net_mqtt_enc: connect_request_encode: Encoding Client Id.
                                       6e 72 66 2d 33 35 31 35  31 36 31 37 32 36 38 37 |nrf-3515 16172687
                                       37 38 32                                         |782
[00:00:41.484,985] <dbg> net_mqtt_enc: pack_utf8_str: (0x2000d2d8): >> str_size:00000015 cur:0x2000dd41, end:0x2000ddb2
[00:00:41.484,985] <dbg> net_mqtt_enc: pack_uint16: (0x2000d2d8): >> val:0013 cur:0x2000dd41, end:0x2000ddb2
[00:00:41.485,015] <dbg> net_mqtt_enc: mqtt_encode_fixed_header: (0x2000d2d8): << msg type:0x10 length:0x0000001f
[00:00:41.485,046] <dbg> net_mqtt_enc: packet_length_encode: (0x2000d2d8): >> length:0x0000001f cur:(nil), end:(nil)
[00:00:41.485,046] <dbg> net_mqtt_enc: mqtt_encode_fixed_header: (0x2000d2d8): Fixed header length = 02
[00:00:41.485,076] <dbg> net_mqtt_enc: pack_uint8: (0x2000d2d8): >> val:10 cur:0x2000dd35, end:0x2000ddb2
[00:00:41.485,076] <dbg> net_mqtt_enc: packet_length_encode: (0x2000d2d8): >> length:0x0000001f cur:0x2000dd36, end:0x2000ddb2
[00:00:41.485,565] <inf> net_mqtt: Connect completed
[00:00:48.783,111] <inf> Lesson4_Exercise1: Publishing: Hi from the nRF91 Series device
[00:00:48.783,142] <inf> Lesson4_Exercise1: to topic: devacademy/publish/topic len: 24
[00:00:48.783,172] <dbg> net_mqtt: mqtt_publish: (0x2000d380): [CID 0x2000d430]:[State 0x02]: >> Topic size 0x00000018, Data size 0x0000001f
[00:00:48.783,203] <dbg> net_mqtt: mqtt_publish: (0x2000d380): [CID 0x2000d430]:[State 0x02]: << result 0xffffff80
[00:00:48.783,203] <inf> Lesson4_Exercise1: Failed to send message, -128
[00:00:58.672,515] <inf> Lesson4_Exercise1: Publishing: Hi from the nRF91 Series device
[00:00:58.672,546] <inf> Lesson4_Exercise1: to topic: devacademy/publish/topic len: 24
[00:00:58.672,576] <dbg> net_mqtt: mqtt_publish: (0x2000d380): [CID 0x2000d430]:[State 0x02]: >> Topic size 0x00000018, Data size 0x0000001f
[00:00:58.672,607] <dbg> net_mqtt: mqtt_publish: (0x2000d380): [CID 0x2000d430]:[State 0x02]: << result 0xffffff80
[00:00:58.672,607] <inf> Lesson4_Exercise1: Failed to send message, -128
[00:01:41.485,717] <err> Lesson4_Exercise1: Error in mqtt_live: -128
[00:01:41.485,717] <inf> Lesson4_Exercise1: Disconnecting MQTT client
[00:01:41.485,748] <err> Lesson4_Exercise1: Could not disconnect MQTT client: -128
[00:01:41.485,778] <inf> Lesson4_Exercise1: Reconnecting in 60 seconds...

It seems to me that the mqtt_event_handler function does not get called, leading me to suspect there is a socket problem somewhere? I did add tracing prints to try and see where my problem is but the event handler never seemed to fire?

Also looking at my personal mqtt brokers logs, the DK definitely connects to the broker, but does not seem to initiate a connection:

Heres a normal connection from an NRF device connecting via Wifi:

2024-06-06T13:23:47: New connection from XXX.XXX.XXX.XXX:44540 on port 1883.
2024-06-06T13:23:47: New client connected from XXX.XXX.XXX.XXX:44540 as XXXXXXXX (p2, c1, k10, u'XXXXXXX').

The 9160 DK only initiates a new connection but the client connection does not seem to occur.

I'm using SDKv2.5.0 if that makes a difference although ive always used it.

Edited for better formatting.

[Michal]

Hello,

I will look more into it after the weekend.

Best regards,

Michal

[Michal]

You could try to add the following configs to maybe get more information:

CONFIG_NET_LOG=y
CONFIG_MQTT_LOG_LEVEL_DBG=y

Best regards,

Michal

[DawidRicsys]

Good evening Michal. Those were the logging options I already added to the prj.config.

My only difference from the normal ./v2.4.0-v2.x.x/lesson4/cellfund_less4_exer1_solution example is the logging that you suggested.

I get a similar capture as previously posted in this thread.

*** Booting nRF Connect SDK v2.5.0 ***
[00:00:00.394,866] <inf> Lesson4_Exercise1: Initializing modem library
[00:00:00.644,592] <inf> Lesson4_Exercise1: Connecting to LTE network
[00:00:02.650,177] <inf> Lesson4_Exercise1: RRC mode: Connected
[00:00:03.742,706] <inf> Lesson4_Exercise1: Network registration status: Connected - home network
[00:00:03.742,828] <inf> Lesson4_Exercise1: Connected to LTE network
[00:00:40.670,013] <inf> Lesson4_Exercise1: IPv4 Address found 20.82.16.164
[00:00:40.670,410] <inf> Lesson4_Exercise1: Connection to broker using mqtt_connect
[00:00:40.670,715] <dbg> net_mqtt_sock_tcp: mqtt_client_tcp_connect: (0x2000ced8): Created socket 0
[00:00:40.989,868] <dbg> net_mqtt_sock_tcp: mqtt_client_tcp_connect: (0x2000ced8): Connect completed
[00:00:40.989,929] <dbg> net_mqtt_enc: connect_request_encode: Encoding Protocol Description.
                                       4d 51 54 54                                      |MQTT
[00:00:40.989,929] <dbg> net_mqtt_enc: pack_utf8_str: (0x2000ced8): >> str_size:00000006 cur:0x2000d937, end:0x2000d9b2
[00:00:40.989,959] <dbg> net_mqtt_enc: pack_uint16: (0x2000ced8): >> val:0004 cur:0x2000d937, end:0x2000d9b2
[00:00:40.989,959] <dbg> net_mqtt_enc: connect_request_encode: (0x2000ced8): Encoding Protocol Version 04.
[00:00:40.989,990] <dbg> net_mqtt_enc: pack_uint8: (0x2000ced8): >> val:04 cur:0x2000d93d, end:0x2000d9b2
[00:00:40.989,990] <dbg> net_mqtt_enc: pack_uint8: (0x2000ced8): >> val:00 cur:0x2000d93e, end:0x2000d9b2
[00:00:40.990,020] <dbg> net_mqtt_enc: connect_request_encode: (0x2000ced8): Encoding Keep Alive Time 003c.
[00:00:40.990,051] <dbg> net_mqtt_enc: pack_uint16: (0x2000ced8): >> val:003c cur:0x2000d93f, end:0x2000d9b2
[00:00:40.990,081] <dbg> net_mqtt_enc: connect_request_encode: Encoding Client Id.
                                       6e 72 66 2d 33 35 31 35  31 36 31 37 32 36 38 37 |nrf-3515 16172687
                                       37 38 32                                         |782
[00:00:40.990,081] <dbg> net_mqtt_enc: pack_utf8_str: (0x2000ced8): >> str_size:00000015 cur:0x2000d941, end:0x2000d9b2
[00:00:40.990,112] <dbg> net_mqtt_enc: pack_uint16: (0x2000ced8): >> val:0013 cur:0x2000d941, end:0x2000d9b2
[00:00:40.990,112] <dbg> net_mqtt_enc: mqtt_encode_fixed_header: (0x2000ced8): << msg type:0x10 length:0x0000001f
[00:00:40.990,142] <dbg> net_mqtt_enc: packet_length_encode: (0x2000ced8): >> length:0x0000001f cur:(nil), end:(nil)
[00:00:40.990,142] <dbg> net_mqtt_enc: mqtt_encode_fixed_header: (0x2000ced8): Fixed header length = 02
[00:00:40.990,173] <dbg> net_mqtt_enc: pack_uint8: (0x2000ced8): >> val:10 cur:0x2000d935, end:0x2000d9b2
[00:00:40.990,173] <dbg> net_mqtt_enc: packet_length_encode: (0x2000ced8): >> length:0x0000001f cur:0x2000d936, end:0x2000d9b2
[00:00:40.990,661] <inf> net_mqtt: Connect completed
[00:01:22.313,842] <inf> Lesson4_Exercise1: Publishing: Hi from the nRF91 Series device
[00:01:22.313,873] <inf> Lesson4_Exercise1: to topic: devacademy/publish/topic len: 24
[00:01:22.313,903] <dbg> net_mqtt: mqtt_publish: (0x2000cf80): [CID 0x2000d030]:[State 0x02]: >> Topic size 0x00000018, Data size 0x0000001f
[00:01:22.313,934] <dbg> net_mqtt: mqtt_publish: (0x2000cf80): [CID 0x2000d030]:[State 0x02]: << result 0xffffff80
[00:01:22.313,934] <inf> Lesson4_Exercise1: Failed to send message, -128
[00:01:31.950,714] <inf> Lesson4_Exercise1: Publishing: Hi from the nRF91 Series device
[00:01:31.950,744] <inf> Lesson4_Exercise1: to topic: devacademy/publish/topic len: 24
[00:01:31.950,775] <dbg> net_mqtt: mqtt_publish: (0x2000cf80): [CID 0x2000d030]:[State 0x02]: >> Topic size 0x00000018, Data size 0x0000001f
[00:01:31.950,805] <dbg> net_mqtt: mqtt_publish: (0x2000cf80): [CID 0x2000d030]:[State 0x02]: << result 0xffffff80
[00:01:31.950,805] <inf> Lesson4_Exercise1: Failed to send message, -128
[00:01:40.990,814] <err> Lesson4_Exercise1: Error in mqtt_live: -128
[00:01:40.990,814] <inf> Lesson4_Exercise1: Disconnecting MQTT client
[00:01:40.990,844] <err> Lesson4_Exercise1: Could not disconnect MQTT client: -128
[00:01:40.990,875] <inf> Lesson4_Exercise1: Reconnecting in 60 seconds...
[00:02:40.990,936] <inf> Lesson4_Exercise1: Connection to broker using mqtt_connect
[00:02:40.991,241] <dbg> net_mqtt_sock_tcp: mqtt_client_tcp_connect: (0x2000ced8): Created socket 1
[00:02:42.955,718] <dbg> net_mqtt_sock_tcp: mqtt_client_tcp_connect: (0x2000ced8): Connect completed
[00:02:42.955,749] <dbg> net_mqtt_enc: connect_request_encode: Encoding Protocol Description.
                                       4d 51 54 54                                      |MQTT
[00:02:42.955,780] <dbg> net_mqtt_enc: pack_utf8_str: (0x2000ced8): >> str_size:00000006 cur:0x2000d937, end:0x2000d9b2
[00:02:42.955,780] <dbg> net_mqtt_enc: pack_uint16: (0x2000ced8): >> val:0004 cur:0x2000d937, end:0x2000d9b2
[00:02:42.955,810] <dbg> net_mqtt_enc: connect_request_encode: (0x2000ced8): Encoding Protocol Version 04.
[00:02:42.955,810] <dbg> net_mqtt_enc: pack_uint8: (0x2000ced8): >> val:04 cur:0x2000d93d, end:0x2000d9b2
[00:02:42.955,841] <dbg> net_mqtt_enc: pack_uint8: (0x2000ced8): >> val:00 cur:0x2000d93e, end:0x2000d9b2
[00:02:42.955,841] <dbg> net_mqtt_enc: connect_request_encode: (0x2000ced8): Encoding Keep Alive Time 003c.
[00:02:42.955,871] <dbg> net_mqtt_enc: pack_uint16: (0x2000ced8): >> val:003c cur:0x2000d93f, end:0x2000d9b2
[00:02:42.955,902] <dbg> net_mqtt_enc: connect_request_encode: Encoding Client Id.
                                       6e 72 66 2d 33 35 31 35  31 36 31 37 32 36 38 37 |nrf-3515 16172687
                                       37 38 32                                         |782
[00:02:42.955,932] <dbg> net_mqtt_enc: pack_utf8_str: (0x2000ced8): >> str_size:00000015 cur:0x2000d941, end:0x2000d9b2
[00:02:42.955,932] <dbg> net_mqtt_enc: pack_uint16: (0x2000ced8): >> val:0013 cur:0x2000d941, end:0x2000d9b2
[00:02:42.955,963] <dbg> net_mqtt_enc: mqtt_encode_fixed_header: (0x2000ced8): << msg type:0x10 length:0x0000001f
[00:02:42.955,963] <dbg> net_mqtt_enc: packet_length_encode: (0x2000ced8): >> length:0x0000001f cur:(nil), end:(nil)
[00:02:42.955,993] <dbg> net_mqtt_enc: mqtt_encode_fixed_header: (0x2000ced8): Fixed header length = 02
[00:02:42.955,993] <dbg> net_mqtt_enc: pack_uint8: (0x2000ced8): >> val:10 cur:0x2000d935, end:0x2000d9b2
[00:02:42.956,024] <dbg> net_mqtt_enc: packet_length_encode: (0x2000ced8): >> length:0x0000001f cur:0x2000d936, end:0x2000d9b2
[00:02:42.956,481] <inf> net_mqtt: Connect completed
[00:03:42.956,604] <err> Lesson4_Exercise1: Error in mqtt_live: -128
[00:03:42.956,604] <inf> Lesson4_Exercise1: Disconnecting MQTT client
[00:03:42.956,634] <err> Lesson4_Exercise1: Could not disconnect MQTT client: -128
[00:03:42.956,665] <inf> Lesson4_Exercise1: Reconnecting in 60 seconds...

Section starting at 1:40.990 to 02:42.956,481 repeats indefinitely leading me to suspect the mqtt_evt_handler isnt being called.

[Michal]

What if you try another broker?

For example try reverting that commit:

https://github.com/NordicDeveloperAcademy/cell-fund/commit/2cbecebe2d9019f51c8122459a87fb08076c39e6

Best regards,

Michal

[DawidRicsys]

Hi Michal, Apologies I was on leave last week.

Ive already tried different brokers and all have the same error and behaviour.

On a personal broker Ive found that the connection does take place, the broker registers that a device with the correct IP address connects, but then the client seems to hang as a client connection is never started as shown in my first post.

[Michal]

No worries. Thank you for the information.

Could you upload a modem trace of the issue as well?

Best regards,

Michal