MQTT Connect fails with error -116 when using TLS

[Hayden Ball]

I'm building the `nrf/samples/net/mqtt` sample for the nrf9160dk, specifying a custom certificate inside `src/modules/transport/credentials` as directed in the Kconfig file.

The CA and client certificate / key are specified in the "correct" PEM format, formatted as a C string with newline characters. Sending `at AT%CMNG=2,24,0` correctly reads back the CA certificate.

I'm building with the following flags:

west build -t flash -b nrf9160dk_nrf9160_ns nrf/samples/net/mqtt -DCONFIG_MQTT_HELPER_PORT=8883 -DCONFIG_MQTT_SAMPLE_TRANSPORT_BROKER_HOSTNAME=\"mqtt.preview.playerdata.co.uk\" -DCONFIG_SHELL_BACKEND_RTT=y -DCONFIG_USE_SEGGER_RTT=y -DCONFIG_SHELL=y -DCONFIG_MQTT_HELPER_LOG_LEVEL_DBG=y -DCONFIG_MQTT_LOG_LEVEL_DBG=y -DCONFIG_NRF_MODEM_LIB_LOG_LEVEL_DBG=y -DCONFIG_NRF_MODEM_LOG=y -DCONFIG_MODEM_KEY_MGMT=y -DCONFIG_MQTT_HELPER_SEC_TAG=24 -DCONFIG_MQTT_LIB_TLS=y -DCONFIG_MQTT_LIB=y -DCONFIG_NRF_MODEM_LIB_TRACE=y -DCONFIG_MODEM_KEY_MGMT_LOG_LEVEL_DBG=y -DCONFIG_AT_SHELL=y

The result is that `mqtt_connect` fails with error code -116:

rtt:~$

*** Booting Zephyr OS build v3.3.99-ncs1-1 ***
[00:00:00.327,972] <inf> network: Bringing network interface up
[00:00:00.328,002] <inf> nrf_modem: Initializing libmodem 2.4.1-lte-7821d3f67ae9
[00:00:00.328,430] <dbg> nrf_modem: Control region at 0x20008000 (0x4e8 bytes)
[00:00:00.328,460] <dbg> nrf_modem: TX region at 0x200084e8 (0x2000 bytes)
[00:00:00.328,491] <dbg> nrf_modem: RX region at 0x2000a568 (0x2000 bytes)
[00:00:00.328,521] <dbg> nrf_modem: Trace region at 0x2000c568 (0x4000 bytes)
[00:00:00.329,132] <dbg> mqtt_helper: mqtt_state_set: State transition: MQTT_STATE_UNINIT --> MQTT_STATE_DISCONNECTED
[00:00:00.330,352] <dbg> mqtt_helper: mqtt_helper_poll_loop: Waiting for connection_poll_sem
--- 14 messages dropped ---
[00:00:00.565,216] <dbg> nrf_modem: AT+CEDRXS=3
[00:00:00.565,551] <dbg> nrf_modem: _nrf_modem_lib_init: Modem init callback: 0x30eb7
[00:00:00.565,643] <dbg> nrf_modem: AT%XEPCO=1
[00:00:00.566,070] <dbg> nrf_modem: _nrf_modem_lib_init: Modem init callback: 0xa7cd
[00:00:00.566,131] <dbg> nrf_modem: AT+CMEE?
[00:00:00.566,589] <dbg> nrf_modem: AT+CMEE=1
[00:00:00.820,465] <dbg> nrf_modem: AT+CMEE=0
[00:00:00.820,861] <dbg> nrf_modem: AT+CMEE?
[00:00:00.821,380] <dbg> nrf_modem: AT+CMEE=1
[00:00:02.239,044] <dbg> nrf_modem: AT+CMEE=0
[00:00:02.239,471] <dbg> nrf_modem: AT+CMEE?
[00:00:02.239,990] <dbg> nrf_modem: AT+CMEE=1
[00:00:02.297,821] <dbg> nrf_modem: AT+CMEE=0
[00:00:02.298,156] <dbg> nrf_modem: _nrf_modem_lib_init: Modem init callback: 0x30b61
[00:00:02.298,217] <inf> nrf_modem_lib_trace: Trace thread ready
[00:00:02.298,339] <dbg> nrf_modem: AT%XMODEMTRACE=1,2
[00:00:02.299,713] <inf> nrf_modem_lib_trace: Trace level override: 2
[00:00:02.299,835] <dbg> nrf_modem: AT%XSYSTEMMODE?
[00:00:02.300,384] <dbg> nrf_modem: AT+CEREG=5
[00:00:02.306,823] <dbg> nrf_modem: AT+CSCON=1
[00:00:02.307,250] <inf> network: Connecting...
[00:00:02.307,373] <dbg> nrf_modem: AT+CEREG=5
[00:00:02.307,769] <dbg> nrf_modem: AT+CSCON=1
[00:00:02.308,197] <dbg> nrf_modem: AT+CFUN=21
[00:00:02.339,050] <dbg> nrf_modem: AT+CNEC=16
[00:00:02.339,538] <dbg> nrf_modem: AT+CGEREP=1
[00:00:04.756,774] <dbg> nrf_modem: AT+CGPADDR=0
[00:00:04.858,642] <inf> network: IP Up
[00:00:09.858,978] <dbg> nrf_modem: AT+CGSN
[00:00:09.859,649] <dbg> mqtt_helper: broker_init: Resolving IP address for mqtt.preview.playerdata.co.uk
[00:00:09.859,741] <inf> nrf_modem: getaddrinfo() fam: 0x0, type 0x1, proto 0x6
[00:00:10.010,253] <inf> nrf_modem: RPC_IP_GETADDRINFO_RES, result RPC_IP_ERR_OK
[00:00:10.010,345] <dbg> nrf_modem: ai_length 0x39, ai_family 0x1, ai_addrlen 0x4, ai_namelen 0x1d
[00:00:10.010,437] <inf> nrf_modem: Resolved 34.105.196.147
[00:00:10.010,681] <dbg> mqtt_helper: broker_init: IPv4 Address found 34.105.196.147 (AF_INET)
[00:00:10.010,742] <dbg> mqtt_helper: mqtt_state_set: State transition: MQTT_STATE_DISCONNECTED --> MQTT_STATE_TRANSPORT_CONNECTING
[00:00:10.010,803] <inf> nrf_modem: socket() fam 0x1, type 0x1, proto 0x102
[00:00:10.011,108] <inf> nrf_modem: RPC_IP_OPEN_RES, result RPC_IP_ERR_OK
[00:00:10.011,230] <dbg> nrf_modem: TLS peer verification 2, fd 0x0
[00:00:10.011,291] <dbg> nrf_modem: TLS tags: 1, fd 0x0
[00:00:10.011,413] <dbg> nrf_modem: TLS hostname: mqtt.preview.playerdata.co.uk, fd 0x0
[00:00:10.011,444] <inf> nrf_modem: connect() fd 0x0
[00:00:10.011,505] <inf> nrf_modem: sa_family 0x1, destaddr_len 0x4, destport 8883
[00:00:10.071,563] <inf> nrf_modem: RPC_IP_CONNECT_RES fd 0x0, result RPC_IP_ERR_OK
[00:00:10.071,655] <dbg> nrf_modem: Waiting for handshake semaphore
[00:00:10.071,746] <inf> nrf_modem: Attaching sock fd 0x0
[00:00:10.071,777] <dbg> nrf_modem: Hostname: mqtt.preview.playerdata.co.uk
[00:00:10.071,838] <dbg> nrf_modem: role 0x2, verify 0x2, cache 0x0, tags count 1
[00:00:10.071,868] <dbg> nrf_modem: tag[0]: 24
[00:00:10.115,631] <inf> nrf_modem: RPC_IP_TLS_ATTACH_RES fd 0x0, result RPC_IP_ERR_OK
[00:00:27.930,206] <inf> nrf_modem: RPC_IP_CLOSED_NTF fd 0x0
[00:00:27.930,236] <inf> nrf_modem: Close reason RPC_IP_ERR_CONN_RESET
[00:00:27.931,030] <inf> nrf_modem: RPC_IP_TLS_HANDSHAKE_COMPLETE_NTF fd 0x0, result RPC_IP_ERR_TIMEOUT
[00:00:27.931,121] <inf> nrf_modem: close() fd 0x0
[00:00:27.932,403] <inf> nrf_modem: RPC_IP_CLOSE_RES fd 0x0, result RPC_IP_ERR_OK
[00:00:27.932,525] <err> mqtt_helper: mqtt_connect, error: -116
[00:00:27.932,556] <dbg> mqtt_helper: mqtt_state_set: State transition: MQTT_STATE_TRANSPORT_CONNECTING --> MQTT_STATE_DISCONNECTED
[00:00:27.932,586] <err> transport: Failed connecting to MQTT, error code: -116

Checking the server logs, it doesn't appear that the board has attempted to make a connection with the MQTT server.

[Hayden Ball]

I'll add that I've validated that there is a common cipher suite - both the modem and the server accept at least `ECDHE-RSA-AES256-GCM-SHA384` (if I've understood the modem documentation correctly).

[dejans]

Hi,

Which network does your board connect to?

Could you provide full log from your application and from the server?

Could you provide modem trace using Trace Collector v2? Alternatively, you can use Cellular Monitor nRF Connect for Desktop application for capturing the traces.

Best regards,
Dejan

[Hayden Ball]

The Cellular Monitor isn't particularly helpful:

[Hayden Ball]

Disabling RTT and moving somewhere with a better cellular connection, I was able to get the following:

trace-2023-09-21T13-36-22.987Z.mtrace

[dejans]

Hi,

Here are useful links for capturing traces with Trace Collector v2 and Cellular Monitor.

Best regards,
Dejan

[Hayden Ball]

Thanks Dejan.

Are you able to provide some advice about what the problem might actually be?

The above trace was captured successfully while the problem was occurring.

[dejans]

Hi,

Hayden Ball said:

I provided a modem trace already but it was removed from the thread. I'll try and generate another one.

Unfortunately, the modem trace file is missing from the ticket. Could you please send modem trace again?

The screenshot from Cellular Monitor shows that there was a trace file of 1.6 MB created, but process was not stopped. To continue from there, you could just press Stop, and then click on file (.mtrace), save it to the disk and upload it to the ticket. 

Best regards,
Dejan

[Hayden Ball]

2451.trace-2023-09-21T13-36-22.987Z.mtrace