MQTT Sample Not Connecting on nRF9160 Board

[RodWatt]

Hi,

Sorry, i am new to MQTT so may be asking a stupid question, please bear with me. 

I am trying to run the MQTT sample (nrf\samples\net\mqtt) and get the following output

*** Booting nRF Connect SDK v3.5.99-ncs1-1 ***
[00:00:00.312,896] <inf> network: Bringing network interface up and connecting to the network
[00:00:00.505,187] <inf> nrf_modem_lib_trace: Trace thread ready
[00:00:00.506,500] <inf> nrf_modem_lib_trace: Trace level override: 2
[00:00:00.508,270] <err> lte_lc: Could not send AT command, error: 65536
[00:00:00.508,270] <err> lte_lc: Failed to set system mode and mode preference, err -14
+CEREG: 2,"01B0","081A1682",7,0,0,"11100000","11100000"
+CSCON: 1
+CSCON: 0
+CSCON: 1
+CGEV: ME PDN ACT 0,0
+CNEC_ESM: 50,0
+CEREG: 1,"01B0","081A1682",7,,,"00011110","00011011"
[00:00:15.113,403] <inf> network: Network connectivity established
+CSCON: 0
+CSCON: 1
+CSCON: 0
+CSCON: 1
+CSCON: 0
+CSCON: 1
+CSCON: 0
+CSCON: 1
[00:00:43.618,835] <err> mqtt_helper: mqtt_connect, error: -116
[00:00:43.618,865] <err> transport: Failed connecting to MQTT, error code: -116
+CSCON: 0

Looking at the cellular monitor, it suggests I am connecting?

Any pointers would be appreciated

Rod

[Øyvind]

Hello Rod, 

What MQTT broker are you trying to connect? And with what SIM card? 

From the start of the log, the LTE Link Controller reports the following

[00:00:00.508,270] <err> lte_lc: Could not send AT command, error: 65536
[00:00:00.508,270] <err> lte_lc: Failed to set system mode and mode preference, err -14

#define NRF_EFAULT 14           /**< Bad address */

#define NRF_ETIMEDOUT 116       /**< Connection timed out */

Here is my output after building the default MQTT sample (with nRF Connect SDK v2.6.0)

+CSCON: 1
+CGEV: ME PDN ACT 0,0
+CNEC_ESM: 50,0
+CEREG: 5,"8173","01165700",7,,,"11100000","11100000"
[00:00:09.843,292] <inf> network: Network connectivity established
[00:00:15.231,231] <inf> transport: Connected to MQTT broker
[00:00:15.231,262] <inf> transport: Hostname: test.mosquitto.org
[00:00:15.231,323] <inf> transport: Client ID: 350457791991456
[00:00:15.231,323] <inf> transport: Port: 1883
[00:00:15.231,353] <inf> transport: TLS: No
[00:00:15.231,414] <inf> transport: Subscribing to: 350457791991456/my/subscribe/topic
[00:00:15.303,253] <inf> transport: Subscribed to topic 350457791991456/my/subscribe/topic
+CSCON: 0
[00:01:00.324,523] <inf> transport: Published message: "Hello MQTT! Current uptime is: 60315" on topic: "350457791991456/my/publish/topic"
+CSCON: 1
+CSCON: 0
[00:02:00.324,707] <inf> transport: Published message: "Hello MQTT! Current uptime is: 120315" on topic: "350457791991456/my/publish/topic"
+CSCON: 1
+CSCON: 0

KInd regards,
Øyvind

[RodWatt]

Hi Øyvind,

I have not changed the code so am trying to connect to the default of test.mosquitto.org. I am using a Tesco PAYG SIM currently but have tried SIMS from EE and Vodafone. Can you recommend one? I am based in the UK.

Cheers,

Rod

[Øyvind]

Hello, 

RodWatt said:

I am using a Tesco PAYG SIM currently but have tried SIMS from EE and Vodafone

There does not seem to be an issue with the SIM you are using, from what I can see in the Cellular Monitor. You are connected to home network using LTE-M. The signal might be a little bad. 

Could you please provide a modem trace from your device?

Kind regards,
Øyvind

[RodWatt]

trace-2024-06-18T15-55-53.314Z.mtrace

Fullscreen 2024-06-18T15_55_37.310Z-log.txt Download

2024-06-18T15:55:37.810Z INFO Initialising nrfutil module: device
2024-06-18T15:55:37.856Z DEBUG Application data folder: /Users/Watt/Library/Application Support/nrfconnect/pc-nrfconnect-cellularmonitor
2024-06-18T15:55:37.907Z DEBUG Sending event "cellularmonitor: running nrfutil device"
2024-06-18T15:55:37.908Z DEBUG App pc-nrfconnect-cellularmonitor v2.4.0 (official)
2024-06-18T15:55:37.908Z DEBUG App path: /Users/Watt/.nrfconnect-apps/node_modules/pc-nrfconnect-cellularmonitor
2024-06-18T15:55:37.908Z DEBUG nRFConnect 5.0.0, required by the app is (>=4.4.1)
2024-06-18T15:55:37.908Z DEBUG nRFConnect path: /Applications/nRF Connect for Desktop.app/Contents/Resources/app.asar
2024-06-18T15:55:37.908Z DEBUG HomeDir: /Users/Watt
2024-06-18T15:55:37.908Z DEBUG TmpDir: /var/folders/6r/sz2bj71s1292yfx9dy5bj87r0000gn/T/
2024-06-18T15:55:37.911Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T15:55:37.912Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T15:55:37.912Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T15:55:40.162Z DEBUG Sending event "cellularmonitor: running nrfutil device"
2024-06-18T15:55:46.489Z DEBUG Sending event "cellularmonitor: running nrfutil device"
2024-06-18T15:55:46.489Z DEBUG Sending event "cellularmonitor: running nrfutil device"
2024-06-18T15:55:46.491Z DEBUG Sending event "cellularmonitor: running nrfutil device"
2024-06-18T15:55:47.032Z INFO Using nrfutil-device core version: 7.12.0
2024-06-18T15:55:47.180Z INFO Using nrfutil-device version: 2.1.1
2024-06-18T15:55:47.180Z INFO Using nrf-device-lib version: 0.17.5
2024-06-18T15:55:47.180Z INFO Using nrfjprog DLL version: 10.24.0
2024-06-18T15:55:47.181Z INFO Using JLink version: JLink_V7.82 
2024-06-18T15:55:47.181Z WARN Installed JLink version does not match the expected version (JLink_V7.94e)
2024-06-18T15:55:47.262Z INFO Getting serialport options from persistent store 000960039212.pc-nrfconnect-cellularmonitor
2024-06-18T15:55:47.263Z DEBUG Sending event "cellularmonitor: device connected"
2024-06-18T15:55:50.093Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T15:55:50.109Z DEBUG Sending event "cellularmonitor: running nrfutil device"
2024-06-18T15:55:50.416Z DEBUG Trace database already downloaded: mfw_nrf9160_1.1.4_trace-db.json
2024-06-18T15:55:50.416Z DEBUG Trace database already downloaded: mfw_nrf9160_1.1.4-FOTA-TEST_trace-db.json
2024-06-18T15:55:50.416Z DEBUG Trace database already downloaded: mfw_nrf9160_1.1.5_trace-db.json
2024-06-18T15:55:50.416Z DEBUG Trace database already downloaded: mfw_nrf9160_1.1.5-FOTA-TEST_trace-db.json
2024-06-18T15:55:50.416Z DEBUG Trace database already downloaded: mfw_nrf9160_1.2.3_trace-db.json
2024-06-18T15:55:50.416Z DEBUG Trace database already downloaded: mfw_nrf9160_1.2.3-FOTA-TEST_trace-db.json
2024-06-18T15:55:50.416Z DEBUG Trace database already downloaded: mfw_nrf9160_1.2.7_trace-db.json
2024-06-18T15:55:50.416Z DEBUG Trace database already downloaded: mfw_nrf9160_1.2.7-FOTA-TEST_trace-db.json
2024-06-18T15:55:50.416Z DEBUG Trace database already downloaded: mfw_nrf9160_1.2.8_trace-db.json
2024-06-18T15:55:50.416Z DEBUG Trace database already downloaded: mfw_nrf9160_1.2.8-FOTA-TEST_trace-db.json
2024-06-18T15:55:50.416Z DEBUG Trace database already downloaded: mfw_nrf9160_1.3.0_trace-db.json
2024-06-18T15:55:50.416Z DEBUG Trace database already downloaded: mfw_nrf9160_1.3.0-FOTA-TEST_trace-db.json
2024-06-18T15:55:50.417Z DEBUG Trace database already downloaded: mfw_nrf9160_1.3.1_trace-db.json
2024-06-18T15:55:50.417Z DEBUG Trace database already downloaded: mfw_nrf9160_1.3.1-FOTA-TEST_trace-db.json
2024-06-18T15:55:50.417Z DEBUG Trace database already downloaded: mfw_nrf9160_1.3.2_trace-db.json
2024-06-18T15:55:50.417Z DEBUG Trace database already downloaded: mfw_nrf9160_1.3.2-FOTA-TEST_trace-db.json
2024-06-18T15:55:50.417Z DEBUG Trace database already downloaded: mfw_nrf9160_1.3.3_trace-db.json
2024-06-18T15:55:50.417Z DEBUG Trace database already downloaded: mfw_nrf9160_1.3.3-FOTA-TEST_trace-db.json
2024-06-18T15:55:50.417Z DEBUG Trace database already downloaded: mfw_nrf9160_1.3.4_trace-db.json
2024-06-18T15:55:50.417Z DEBUG Trace database already downloaded: mfw_nrf9160_1.3.4-FOTA-TEST_trace-db.json
2024-06-18T15:55:50.417Z DEBUG Trace database already downloaded: mfw_nrf9160_1.3.5_trace-db.json
2024-06-18T15:55:50.417Z DEBUG Trace database already downloaded: mfw_nrf9160_1.3.5-FOTA-TEST_trace-db.json
2024-06-18T15:55:50.417Z DEBUG Trace database already downloaded: mfw_nrf9160_1.3.6_trace-db.json
2024-06-18T15:55:50.417Z DEBUG Trace database already downloaded: mfw_nrf9160_1.3.6-FOTA-TEST_trace-db.json
2024-06-18T15:55:50.503Z INFO Selected device with s/n 000960039212
2024-06-18T15:55:50.507Z DEBUG Terminal Serial Port: Will attempt to auto-connect to serial port /dev/tty.usbmodem0009600392121
2024-06-18T15:55:50.508Z DEBUG Sending event "cellularmonitor: device selected"
2024-06-18T15:55:50.519Z INFO Opened port with options: {"path":"/dev/tty.usbmodem0009600392121","baudRate":115200}
2024-06-18T15:55:51.520Z DEBUG Terminal Serial Port: Could not detect AT Host library
2024-06-18T15:55:53.314Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T15:55:54.324Z INFO Started tracefile
2024-06-18T15:55:54.324Z INFO Refreshing dashboard in 5 seconds
2024-06-18T15:55:54.325Z DEBUG Sending event "cellularmonitor: Starting Raw trace"
2024-06-18T15:55:54.328Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T15:55:55.645Z INFO Detected trace DB: /Users/Watt/Library/Application Support/nrfconnect/pc-nrfconnect-cellularmonitor/trace_db_cache/nRF9160/1.2.3/0191538f-d3a5-4fe9-8f54-ba7cad9460c0/mfw_nrf9160_1.2.3_trace-db.json
2024-06-18T15:56:24.623Z INFO Device is in line mode.
2024-06-18T15:56:24.623Z DEBUG Failed to auto detect modem version using AT+CGMR: ([00:01:11.461,944] <err> nrf_modem_lib_netif: Modem error: 0x10, PC: 0x692b6
ASSERTION FAIL [!arch_is_in_isr()] @ WEST_TOPDIR/zephyr/kernel/mutex.c:110
	mutexes cannot be used inside ISRs
[00:01:11.462,066] <err> os: r0/a1:  0x00000004  r1/a2:  0x0000006e  r2/a3:  0x00000003
[00:01:11.462,097] <err> os: r3/a4:  0x20011248 r12/ip:  0x00000014 r14/lr:  0x0002104f
[00:01:11.462,097] <err> os:  xpsr:  0x4100003a
[00:01:11.462,097] <err> os: Faulting instruction address (r15/pc): 0x00025f36
[00:01:11.462,158] <err> os: >>> ZEPHYR FATAL ERROR 4: Kernel pa)
2024-06-18T15:56:24.623Z ERROR AT command AT+CFUN=1 failed: [00:01:11.461,944] <err> nrf_modem_lib_netif: Modem error: 0x10, PC: 0x692b6
ASSERTION FAIL [!arch_is_in_isr()] @ WEST_TOPDIR/zephyr/kernel/mutex.c:110
	mutexes cannot be used inside ISRs
[00:01:11.462,066] <err> os: r0/a1:  0x00000004  r1/a2:  0x0000006e  r2/a3:  0x00000003
[00:01:11.462,097] <err> os: r3/a4:  0x20011248 r12/ip:  0x00000014 r14/lr:  0x0002104f
[00:01:11.462,097] <err> os:  xpsr:  0x4100003a
[00:01:11.462,097] <err> os: Faulting instruction address (r15/pc): 0x00025f36
[00:01:11.462,158] <err> os: >>> ZEPHYR FATAL ERROR 4: Kernel pa
2024-06-18T15:57:36.256Z ERROR AT command AT%XCONNSTAT=1 failed: nic on CPU 0
[00:01:11.462,158] <err> os: Fault during interrupt handling

[00:01:11.462,188] <err> os: Current thread: 0x20011a28 (unknown)
[00:01:11.530,212] <err> fatal_error: Resetting system
*** Booting nRF Connect SDK v3.5.99-ncs1-1 ***
[00:00:00.251,831] <inf> network: Bringing network interface up and connecting to the network
[00:00:00.444,274] <inf> nrf_modem_lib_trace: Trace thread ready
[00:00:00.445,617] <inf> nrf_modem_lib_trace: Trace level override: 2
[00:00:00.447,357] <err> lte_lc: Could not send AT command, error: 65536
[00:00:00.447,387] <err> lte_lc: Failed to set system mode and mode preference, err -14
+CEREG: 90

[00:01:11.298,461] <err> nrf_modem_lib_netif: Modem error: 0x10, PC: 0x692b6
ASSERTION FAIL [!arch_is_in_isr()] @ WEST_TOPDIR/zephyr/kernel/mutex.c:110
	mutexes cannot be used inside ISRs
[00:01:11.298,553] <err> os: r0/a1:  0x00000004  r1/a2:  0x0000006e  r2/a3:  0x00000003
[00:01:11.298,583] <err> os: r3/a4:  0x20011248 r12/ip:  0x00000014 r14/lr:  0x0002104f
[00:01:11.298,583] <err> os:  xpsr:  0x4100003a
[00:01:11.298,614] <err> os: Faulting instruction address (r15/pc): 0x00025f36
[00:01:11.298,645] <err> os: >>> ZEPHYR FATAL ERROR
2024-06-18T16:01:05.244Z DEBUG Sending event "cellularmonitor: Open serial terminal"
2024-06-18T16:03:09.357Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T16:03:09.377Z DEBUG Sending event "cellularmonitor: Stopping trace"
2024-06-18T16:03:09.397Z INFO Finished tracefile
2024-06-18T16:03:48.593Z DEBUG Sending event "cellularmonitor: Open serial terminal"
2024-06-18T16:04:10.398Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T16:04:10.449Z INFO Started tracefile
2024-06-18T16:04:10.450Z INFO Refreshing dashboard in 5 seconds
2024-06-18T16:04:10.466Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T16:04:10.518Z DEBUG Sending event "cellularmonitor: Starting Raw trace"
2024-06-18T16:05:55.156Z DEBUG Sending event "cellularmonitor: Open file directory"
2024-06-18T16:08:13.077Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T16:08:13.127Z DEBUG Sending event "cellularmonitor: Stopping trace"
2024-06-18T16:08:13.174Z INFO Finished tracefile
2024-06-18T16:08:22.343Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T16:08:22.344Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T16:08:22.357Z DEBUG Sending event "cellularmonitor: Toggle save trace to file"
2024-06-18T16:08:27.952Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T16:08:27.954Z DEBUG Sending event "cellularmonitor: Toggle save trace to file"
2024-06-18T16:09:56.957Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T16:09:56.996Z INFO Started tracefile
2024-06-18T16:09:56.997Z INFO Reseting device
2024-06-18T16:09:57.012Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T16:09:57.074Z DEBUG Sending event "cellularmonitor: Starting Raw trace"
2024-06-18T16:09:57.095Z DEBUG Sending event "cellularmonitor: running nrfutil device"
2024-06-18T16:10:02.406Z INFO Refreshing dashboard in 5 seconds
2024-06-18T16:10:34.450Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T16:10:34.483Z DEBUG Sending event "cellularmonitor: Stopping trace"
2024-06-18T16:10:34.564Z INFO Finished tracefile
2024-06-18T16:10:38.307Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T16:10:38.339Z INFO Started tracefile
2024-06-18T16:10:38.340Z INFO Reseting device
2024-06-18T16:10:38.354Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T16:10:38.524Z DEBUG Sending event "cellularmonitor: Starting Raw trace"
2024-06-18T16:10:38.570Z DEBUG Sending event "cellularmonitor: running nrfutil device"
2024-06-18T16:10:44.714Z INFO Refreshing dashboard in 5 seconds
2024-06-18T16:11:08.476Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T16:11:08.693Z DEBUG Sending event "cellularmonitor: Stopping trace"
2024-06-18T16:11:08.758Z INFO Finished tracefile
2024-06-18T16:15:18.527Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T16:15:18.527Z DEBUG Could not locate wireshark executable in /Applications/Wireshark.app
2024-06-18T16:15:18.528Z DEBUG Sending event "cellularmonitor: Toggle save trace to file"
2024-06-18T16:16:13.406Z DEBUG Sending event "cellularmonitor: Toggle save trace to file"
2024-06-18T16:16:14.277Z DEBUG Sending event "cellularmonitor: Toggle save trace to file"
2024-06-18T16:16:21.981Z INFO Started tracefile
2024-06-18T16:16:21.982Z INFO Reseting device
2024-06-18T16:16:21.989Z DEBUG Sending event "cellularmonitor: Starting Raw trace"
2024-06-18T16:16:21.989Z DEBUG Sending event "cellularmonitor: Starting Live trace"
2024-06-18T16:16:21.992Z DEBUG Sending event "cellularmonitor: running nrfutil device"
2024-06-18T16:17:58.881Z DEBUG Sending event "cellularmonitor: Stopping trace"
2024-06-18T16:17:58.888Z INFO Finished tracefile
2024-06-18T16:18:02.134Z INFO Started tracefile
2024-06-18T16:18:02.134Z INFO Reseting device
2024-06-18T16:18:02.142Z DEBUG Sending event "cellularmonitor: Starting Raw trace"
2024-06-18T16:18:02.142Z DEBUG Sending event "cellularmonitor: Starting Live trace"
2024-06-18T16:18:02.146Z DEBUG Sending event "cellularmonitor: running nrfutil device"
2024-06-18T16:18:15.954Z ERROR Error when creating trace: wireshark process closed or pipe error  plugin path: /Users/Watt/.nrfconnect-apps/node_modules/pc-nrfconnect-cellularmonitor/node_modules/@nordicsemiconductor/nrf-monitor-lib-js/Release/darwin-x64/nrfml-wireshark-named-pipe-sink.nrfml
2024-06-18T16:18:15.954Z DEBUG Full error: {"error_code":21,"message":"wireshark process closed or pipe error  plugin path: /Users/Watt/.nrfconnect-apps/node_modules/pc-nrfconnect-cellularmonitor/node_modules/@nordicsemiconductor/nrf-monitor-lib-js/Release/darwin-x64/nrfml-wireshark-named-pipe-sink.nrfml","origin":"Error when running nrfml operation worker."}
2024-06-18T16:18:42.554Z DEBUG Sending event "cellularmonitor: Stopping trace"
2024-06-18T16:19:00.073Z INFO Started tracefile
2024-06-18T16:19:00.073Z INFO Reseting device
2024-06-18T16:19:00.096Z DEBUG Sending event "cellularmonitor: Starting Raw trace"
2024-06-18T16:19:00.097Z DEBUG Sending event "cellularmonitor: Starting Live trace"
2024-06-18T16:19:00.100Z DEBUG Sending event "cellularmonitor: running nrfutil device"
2024-06-18T16:19:12.642Z ERROR Error when creating trace: wireshark process closed or pipe error  plugin path: /Users/Watt/.nrfconnect-apps/node_modules/pc-nrfconnect-cellularmonitor/node_modules/@nordicsemiconductor/nrf-monitor-lib-js/Release/darwin-x64/nrfml-wireshark-named-pipe-sink.nrfml
2024-06-18T16:19:12.642Z DEBUG Full error: {"error_code":21,"message":"wireshark process closed or pipe error  plugin path: /Users/Watt/.nrfconnect-apps/node_modules/pc-nrfconnect-cellularmonitor/node_modules/@nordicsemiconductor/nrf-monitor-lib-js/Release/darwin-x64/nrfml-wireshark-named-pipe-sink.nrfml","origin":"Error when running nrfml operation worker."}
2024-06-18T16:20:49.573Z DEBUG Sending event "cellularmonitor: Stopping trace"
2024-06-18T16:20:51.402Z DEBUG Sending event "cellularmonitor: Toggle save trace to file"
2024-06-18T16:26:44.102Z DEBUG Sending event "cellularmonitor: Open file directory"
2024-06-18T16:26:44.310Z DEBUG Sending event "cellularmonitor: Open file directory"

is this what you need?

Rod

[Øyvind]

Thanks Rod! The logs show that you are having same hard fault, and this might be related to the modem FW you are running. Any reason for running mfw 1.2.3, could you try with modem fw 1.3.x?

[RodWatt]

No, no reason, i just have not updated to the latest :-( I will update the modem firmware and let you know. 

Thanks,

Rod

[RodWatt]

Hi Øyvind,

I updated the firmware to the latest version.

However, this seems to have introduced more errors. The trace-sim-lte connection-ppm status is stuck at Trace.

There is also an error around the database.

Do i need to change something else to use the latest firmware?

Rod

[RodWatt]

I moved to 1.3.5 and saw the same error but when i moved to 1.3.4, it seems to be working better.

Its still not connecting 

Here is the trace file

trace-2024-06-21T15-21-04.370Z.mtrace

Any suggestions?

Rod

[Øyvind]

Thanks Rod! 

The device is timing out during the connection. My initial thought is that your connection is poor, i.e. bad signal strength. 

At what location are you testing?

Kind regards,
Øyvind