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

[dejans]

Hi,

The command "AT%CMNG" can be used for listing all keys and certificates in the modem. You could check if you have all certificates that you expect.

It is generally recommended that the application removes only those keys that it wrote previously to the modem.

Best regards,
Dejan

[Hayden Ball]

Thanks Dejan.

We did not remove any certificates that we did not write.

[dejans]

Hi,

Have you double checked that you have all certificates as expected?

Best regards,
Dejan

[Hayden Ball]

Hi Dejan,

When I checked our certificate (stored originally in slot 24) the hash didn't match the hash I expected.

Re-writing the certificate did not correct this, so I assume I've been calculating the hash incorrectly. Please can you point me at some documentation to show how to calculate or read the certificate hash in the same way that the nRF9160 is displaying it with `AT%CMNG=1`?

Can you point me at some documentation to show what other certificates should be installed, and their expected values?

As mentioned above, I no longer have access to the original devkit that I was seeing the issue on, and I don't want to risk bricking another devkit.

Regards,

Hayden

[dejans]

Hi,

You could have a look at modem key management library.

Best regards,
Dejan

[Hayden Ball]

Hi Dejan,

Yes - this has been very helpful in allowing us to set and clear certificates.

It doesn't answer my question of which certificates we expect to be installed on the nRF9160, nor does it help me answer your previous question of whether all certificates are expected.

It also doesn't really help answer the original question - why does the modem appear to hang if a certificate with a 4096 bit key is used.

[dejans]

Hi,

Modem can contain several certificates and keys. It is important that you verify that the certificates which are written to the modem are there. Which certificates are expected depends on what has previously been written to the modem. 

Regarding your question of modem which appears to be hanging, you can read about TLS limitations of the modem in modem firmware release notes file. This file is available in the modem firmware zip file that can be found on our nrf9160 Downloads page. It might be that mentioned limitations are exceeded in your case.

Best regards,
Dejan