nRF Connect MQTT returns -22 invalid argument

Hello Support,

In my project I use the nrf52840 with the nRF Connect SDK to create a OpenThread device with an Secure MQTT connection to a broker.

I've got the OpenThread working, I can use the Zephyr DNS and Sockets.

I would like to connect with the Azure IoT Hub. I've used the Zephyr Azure IoT Hub Sample to try and create a connection. This always fails errno 22.

[00:00:09.508,819] <err> net_mqtt_sock_tls: Connect errno: 22
[00:00:09.508,850] <dbg> net_sock.z_impl_zsock_close: (main): close: ctx=0x200018a8, fd=0
[00:00:09.509,063] <dbg> net_sock.z_impl_zsock_close: (main): close: ctx=0x2000ad98, fd=1
[00:00:09.510,528] <err> net_echo_client_sample: mqtt_connect failed -22

So I've set up my own Mosquitto broker. I tested it on my RPi OpenThread Border Router and it seem to be working fine if I used mosquitto_sub and mosquitto_pub. I can use the OpenThread WPAN interface to connect to the Mosquitto broker using port 8883. When I try to connect using the nRF52840, I get the exact same error code.

I've tracked the RTT log output from the nRF52840, the TCPDump from the RPi Border Router and the verbose logs from mosquitto.

RTT Logs:

[00:00:09.333,251] <dbg> net_echo_client_sample.try_to_connect: attempting to connect...
[00:00:09.333,557] <dbg> net_sock_tls.tls_alloc: (main): Allocated TLS context, 0x200018a8
[00:00:09.333,862] <dbg> net_sock.zsock_socket_internal: (main): socket: ctx=0x2000ad98, fd=1
[00:00:09.334,136] <dbg> net_ctx.net_context_bind: (main): Context 0x2000ad98 binding to TCP [::]:53926 iface 1 (0x20000ba0)
[00:00:09.334,869] <dbg> net_conn.conn_register_debug: (main): [0x2000b4c8/6/2/0x3f] remote fd3f:76ab:550:1:8354:af69:ade3:c4e7/8883 
[00:00:09.334,899] <dbg> net_conn.conn_register_debug: (main):   local ::/53926 cb 0x14b95 ud 0x2000ad98
[00:00:09.366,119] <dbg> net_conn.net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20032ad8 src port 8883 dst port 53926 family 2
[00:00:09.366,149] <dbg> net_conn.net_conn_input: (rx_q[0]): [0x2000b4c8] match found cb 0x14b95 ud 0x2000ad98 rank 0x3f
[00:00:09.508,819] <err> net_mqtt_sock_tls: Connect errno: 22
[00:00:09.508,850] <dbg> net_sock.z_impl_zsock_close: (main): close: ctx=0x200018a8, fd=0
[00:00:09.509,063] <dbg> net_sock.z_impl_zsock_close: (main): close: ctx=0x2000ad98, fd=1
[00:00:09.510,528] <err> net_echo_client_sample: mqtt_connect failed -22
[00:00:09.510,803] <dbg> net_sock_tls.tls_alloc: (main): Allocated TLS context, 0x200018a8
[00:00:09.511,138] <dbg> net_sock.zsock_socket_internal: (main): socket: ctx=0x2000ae40, fd=1
[00:00:09.511,413] <dbg> net_ctx.net_context_bind: (main): Context 0x2000ae40 binding to TCP [::]:47182 iface 1 (0x20000ba0)
[00:00:09.511,840] <dbg> net_conn.conn_register_debug: (main): [0x2000b484/6/2/0x3f] remote fd3f:76ab:550:1:8354:af69:ade3:c4e7/8883 
[00:00:09.511,871] <dbg> net_conn.conn_register_debug: (main):   local ::/47182 cb 0x14b95 ud 0x2000ae40
[00:00:09.526,428] <dbg> net_conn.net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20032a90 src port 8883 dst port 53926 family 2
[00:00:09.526,489] <dbg> net_conn.net_conn_input: (rx_q[0]): [0x2000b4c8] match found cb 0x14b95 ud 0x2000ad98 rank 0x3f
[00:00:09.560,150] <dbg> net_conn.net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20032b68 src port 8883 dst port 47182 family 2
[00:00:09.560,211] <dbg> net_conn.net_conn_input: (rx_q[0]): [0x2000b484] match found cb 0x14b95 ud 0x2000ae40 rank 0x3f
[00:00:09.698,699] <err> net_mqtt_sock_tls: Connect errno: 22
[00:00:09.698,730] <dbg> net_sock.z_impl_zsock_close: (main): close: ctx=0x200018a8, fd=0
[00:00:09.698,944] <dbg> net_sock.z_impl_zsock_close: (main): close: ctx=0x2000ae40, fd=1
[00:00:09.700,378] <err> net_echo_client_sample: mqtt_connect failed -22
[00:00:09.700,683] <dbg> net_sock_tls.tls_alloc: (main): Allocated TLS context, 0x200018a8
[00:00:09.700,988] <dbg> net_sock.zsock_socket_internal: (main): socket: ctx=0x2000aee8, fd=1
[00:00:09.701,385] <dbg> net_ctx.net_context_bind: (main): Context 0x2000aee8 binding to TCP [::]:33684 iface 1 (0x20000ba0)
[00:00:09.701,782] <dbg> net_conn.conn_register_debug: (main): [0x2000b440/6/2/0x3f] remote fd3f:76ab:550:1:8354:af69:ade3:c4e7/8883 
[00:00:09.701,812] <dbg> net_conn.conn_register_debug: (main):   local ::/33684 cb 0x14b95 ud 0x2000aee8
[00:00:09.715,332] <dbg> net_conn.net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20032a48 src port 8883 dst port 47182 family 2
[00:00:09.715,362] <dbg> net_conn.net_conn_input: (rx_q[0]): [0x2000b484] match found cb 0x14b95 ud 0x2000ae40 rank 0x3f
[00:00:09.733,123] <dbg> net_conn.net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20032a90 src port 8883 dst port 33684 family 2
[00:00:09.733,154] <dbg> net_conn.net_conn_input: (rx_q[0]): [0x2000b440] match found cb 0x14b95 ud 0x2000aee8 rank 0x3f
[00:00:09.776,855] <dbg> net_conn.net_conn_unregister: (tcp_work): Connection handler 0x2000b4c8 removed
[00:00:09.776,947] <dbg> net_ctx.net_context_unref: (tcp_work): Context 0x2000ad98 released
[00:00:09.873,504] <err> net_mqtt_sock_tls: Connect errno: 22
[00:00:09.873,535] <dbg> net_sock.z_impl_zsock_close: (main): close: ctx=0x200018a8, fd=0
[00:00:09.873,748] <dbg> net_sock.z_impl_zsock_close: (main): close: ctx=0x2000aee8, fd=1
[00:00:09.875,213] <err> net_echo_client_sample: mqtt_connect failed -22
[00:00:09.889,770] <dbg> net_conn.net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20032a90 src port 8883 dst port 33684 family 2
[00:00:09.889,801] <dbg> net_conn.net_conn_input: (rx_q[0]): [0x2000b440] match found cb 0x14b95 ud 0x2000aee8 rank 0x3f
[00:00:09.965,759] <dbg> net_conn.net_conn_unregister: (tcp_work): Connection handler 0x2000b484 removed
[00:00:09.965,881] <dbg> net_ctx.net_context_unref: (tcp_work): Context 0x2000ae40 released
[00:00:10.140,197] <dbg> net_conn.net_conn_unregister: (tcp_work): Connection handler 0x2000b440 removed
[00:00:10.140,289] <dbg> net_ctx.net_context_unref: (tcp_work): Context 0x2000aee8 released

Mosquitto verbose logs on RPi:

1657281902: Sending PINGRESP to auto-C18AD217-5344-764C-9454-780D869BB160
1657281962: Received PINGREQ from auto-C18AD217-5344-764C-9454-780D869BB160
1657281962: Sending PINGRESP to auto-C18AD217-5344-764C-9454-780D869BB160
1657282008: New connection from fd3f:76ab:550:1:2a9d:e83a:3e:84a7:53926 on port 8883.
1657282008: Client <unknown> disconnected: Protocol error.
1657282009: New connection from fd3f:76ab:550:1:2a9d:e83a:3e:84a7:47182 on port 8883.
1657282009: Client <unknown> disconnected: Protocol error.
1657282009: New connection from fd3f:76ab:550:1:2a9d:e83a:3e:84a7:33684 on port 8883.
1657282009: Client <unknown> disconnected: Protocol error.
1657282022: Received PINGREQ from auto-C18AD217-5344-764C-9454-780D869BB160

TCPDump RPi:

13:43:21.562789 IP6 (hlim 64, next-header TCP (6) payload length: 24) fd3f:76ab:550:1:2a9d:e83a:3e:84a7.44755 > fd3f:76ab:550:1:8354:af69:ade3:c4e7.8883: Flags [S], cksum 0xc4da (correct), seq 2288272725, win 1280, options [mss 1280], length 0
13:43:21.562932 IP6 (flowlabel 0x4d0df, hlim 64, next-header TCP (6) payload length: 24) fd3f:76ab:550:1:8354:af69:ade3:c4e7.8883 > fd3f:76ab:550:1:2a9d:e83a:3e:84a7.44755: Flags [S.], cksum 0x2595 (correct), seq 2143954961, ack 2288272726, win 64660, options [mss 1220], length 0
13:43:21.589637 IP6 (hlim 64, next-header TCP (6) payload length: 20) fd3f:76ab:550:1:2a9d:e83a:3e:84a7.44755 > fd3f:76ab:550:1:8354:af69:ade3:c4e7.8883: Flags [.], cksum 0x33f7 (correct), ack 1, win 1280, length 0
13:43:21.725409 IP6 (hlim 64, next-header TCP (6) payload length: 20) fd3f:76ab:550:1:2a9d:e83a:3e:84a7.44755 > fd3f:76ab:550:1:8354:af69:ade3:c4e7.8883: Flags [F.], cksum 0x33f6 (correct), seq 1, ack 1, win 1280, length 0
13:43:21.725978 IP6 (flowlabel 0x4d0df, hlim 64, next-header TCP (6) payload length: 20) fd3f:76ab:550:1:8354:af69:ade3:c4e7.8883 > fd3f:76ab:550:1:2a9d:e83a:3e:84a7.44755: Flags [F.], cksum 0x3c61 (correct), seq 1, ack 2, win 64659, length 0
13:43:21.730555 IP6 (hlim 64, next-header TCP (6) payload length: 24) fd3f:76ab:550:1:2a9d:e83a:3e:84a7.58357 > fd3f:76ab:550:1:8354:af69:ade3:c4e7.8883: Flags [S], cksum 0x0a96 (correct), seq 3371731427, win 1280, options [mss 1280], length 0
13:43:21.730688 IP6 (flowlabel 0xfdb74, hlim 64, next-header TCP (6) payload length: 24) fd3f:76ab:550:1:8354:af69:ade3:c4e7.8883 > fd3f:76ab:550:1:2a9d:e83a:3e:84a7.58357: Flags [S.], cksum 0xf83d (correct), seq 114234399, ack 3371731428, win 64660, options [mss 1220], length 0
13:43:21.752260 IP6 (hlim 64, next-header TCP (6) payload length: 20) fd3f:76ab:550:1:2a9d:e83a:3e:84a7.44755 > fd3f:76ab:550:1:8354:af69:ade3:c4e7.8883: Flags [.], cksum 0x33f5 (correct), ack 2, win 1280, length 0
13:43:21.765145 IP6 (hlim 64, next-header TCP (6) payload length: 20) fd3f:76ab:550:1:2a9d:e83a:3e:84a7.58357 > fd3f:76ab:550:1:8354:af69:ade3:c4e7.8883: Flags [.], cksum 0x06a0 (correct), ack 1, win 1280, length 0
13:43:21.894054 IP6 (hlim 64, next-header TCP (6) payload length: 20) fd3f:76ab:550:1:2a9d:e83a:3e:84a7.58357 > fd3f:76ab:550:1:8354:af69:ade3:c4e7.8883: Flags [F.], cksum 0x069f (correct), seq 1, ack 1, win 1280, length 0
13:43:21.894598 IP6 (flowlabel 0xfdb74, hlim 64, next-header TCP (6) payload length: 20) fd3f:76ab:550:1:8354:af69:ade3:c4e7.8883 > fd3f:76ab:550:1:2a9d:e83a:3e:84a7.58357: Flags [F.], cksum 0x0f0a (correct), seq 1, ack 2, win 64659, length 0
13:43:21.900673 IP6 (hlim 64, next-header TCP (6) payload length: 24) fd3f:76ab:550:1:2a9d:e83a:3e:84a7.49553 > fd3f:76ab:550:1:8354:af69:ade3:c4e7.8883: Flags [S], cksum 0xd506 (correct), seq 3007117202, win 1280, options [mss 1280], length 0
13:43:21.900821 IP6 (flowlabel 0x5bc43, hlim 64, next-header TCP (6) payload length: 24) fd3f:76ab:550:1:8354:af69:ade3:c4e7.8883 > fd3f:76ab:550:1:2a9d:e83a:3e:84a7.49553: Flags [S.], cksum 0xaf04 (correct), seq 1604243193, ack 3007117203, win 64660, options [mss 1220], length 0
13:43:21.911005 IP6 (hlim 64, next-header TCP (6) payload length: 20) fd3f:76ab:550:1:2a9d:e83a:3e:84a7.58357 > fd3f:76ab:550:1:8354:af69:ade3:c4e7.8883: Flags [.], cksum 0x069e (correct), ack 2, win 1280, length 0
13:43:21.923881 IP6 (hlim 64, next-header TCP (6) payload length: 20) fd3f:76ab:550:1:2a9d:e83a:3e:84a7.49553 > fd3f:76ab:550:1:8354:af69:ade3:c4e7.8883: Flags [.], cksum 0xbd66 (correct), ack 1, win 1280, length 0
13:43:22.056881 IP6 (hlim 64, next-header TCP (6) payload length: 20) fd3f:76ab:550:1:2a9d:e83a:3e:84a7.49553 > fd3f:76ab:550:1:8354:af69:ade3:c4e7.8883: Flags [F.], cksum 0xbd65 (correct), seq 1, ack 1, win 1280, length 0
13:43:22.057384 IP6 (flowlabel 0x5bc43, hlim 64, next-header TCP (6) payload length: 20) fd3f:76ab:550:1:8354:af69:ade3:c4e7.8883 > fd3f:76ab:550:1:2a9d:e83a:3e:84a7.49553: Flags [F.], cksum 0xc5d0 (correct), seq 1, ack 2, win 64659, length 0
13:43:22.071057 IP6 (hlim 64, next-header TCP (6) payload length: 20) fd3f:76ab:550:1:2a9d:e83a:3e:84a7.49553 > fd3f:76ab:550:1:8354:af69:ade3:c4e7.8883: Flags [.], cksum 0xbd64 (correct), ack 2, win 1280, length 0

nRF52840 prj.conf:

# Generic networking options
CONFIG_NETWORKING=y
CONFIG_NET_UDP=y
CONFIG_NET_TCP=y
CONFIG_NET_IPV6=y
CONFIG_NET_IPV4=n
CONFIG_NET_SOCKETS=y
CONFIG_NET_SOCKETS_SOCKOPT_TLS=y
CONFIG_NET_SOCKETS_POSIX_NAMES=y
CONFIG_NET_SOCKETS_POLL_MAX=4
# CONFIG_NET_CONNECTION_MANAGER=y

# Kernel options
CONFIG_MAIN_STACK_SIZE=2048
CONFIG_ENTROPY_GENERATOR=y
CONFIG_TEST_RANDOM_GENERATOR=y
CONFIG_INIT_STACKS=y

# Logging
CONFIG_NET_LOG=y
CONFIG_LOG=y
CONFIG_NET_STATISTICS=y
CONFIG_PRINTK=y

# Network buffers
CONFIG_NET_PKT_RX_COUNT=16
CONFIG_NET_PKT_TX_COUNT=16
CONFIG_NET_BUF_RX_COUNT=80
CONFIG_NET_BUF_TX_COUNT=80
CONFIG_NET_CONTEXT_NET_PKT_POOL=y

# IP address options
CONFIG_NET_IF_UNICAST_IPV6_ADDR_COUNT=3
CONFIG_NET_IF_MCAST_IPV6_ADDR_COUNT=4
CONFIG_NET_MAX_CONTEXTS=10

# Network shell
CONFIG_NET_SHELL=y

# The addresses are selected so that qemu<->qemu connectivity works ok.
# For linux<->qemu connectivity, create a new conf file and swap the
# addresses (so that peer address is ending to 2).
CONFIG_NET_CONFIG_SETTINGS=y
CONFIG_NET_CONFIG_NEED_IPV6=y
CONFIG_NET_CONFIG_NEED_IPV4=n
CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=2048

# DNS Settings
CONFIG_DNS_RESOLVER=y
CONFIG_DNS_SERVER_IP_ADDRESSES=y
CONFIG_DNS_SERVER1="FDAA:BB:1::2"
CONFIG_OPENTHREAD_DNS_CLIENT=y

# disable external crystal
CONFIG_CLOCK_CONTROL_NRF_K32SRC_XTAL=n
# enable synth crystal for powered devices
CONFIG_CLOCK_CONTROL_NRF_K32SRC_SYNTH=y
# enable RC crystal for battery devices
# CONFIG_CLOCK_CONTROL_NRF_K32SRC_RC is not set

# NEWLIB C
CONFIG_NEWLIB_LIBC=y

# Enable MQTT Lib support
CONFIG_MQTT_LIB=y
CONFIG_MQTT_LIB_TLS=y
# MQTT - Maximum MQTT keepalive timeout specified by Azure IoT Hub
CONFIG_MQTT_KEEPALIVE=1767

# Heap and stacks
CONFIG_HEAP_MEM_POOL_SIZE=4096

# cJSON
CONFIG_CJSON_LIB=y

#
# overlay-log.conf
#
CONFIG_LOG=y
# CONFIG_LOG_MODE_IMMEDIATE=y
CONFIG_LOG_BACKEND_SHOW_COLOR=n

CONFIG_LOG_BUFFER_SIZE=2048

CONFIG_LOG_MODE_MINIMAL=n
CONFIG_LOG_MODE_DEFERRED=y
# fix str dup alloc failures
CONFIG_LOG_STRDUP_MAX_STRING=150
CONFIG_LOG_STRDUP_BUF_COUNT=48

CONFIG_NET_LOG=y

CONFIG_NET_SOCKETS_LOG_LEVEL_DBG=y
CONFIG_NET_CONN_LOG_LEVEL_DBG=y
CONFIG_NET_CONTEXT_LOG_LEVEL_DBG=y

#
#overlay-ot.conf
#
CONFIG_NEWLIB_LIBC=y

# Disable TCP and IPv4 (TCP disabled to avoid heavy traffic)
CONFIG_NET_TCP=y
CONFIG_NET_IPV4=n

CONFIG_NET_IPV6_NBR_CACHE=n
CONFIG_NET_IPV6_MLD=n
CONFIG_NET_CONFIG_NEED_IPV4=n
CONFIG_NET_CONFIG_MY_IPV4_ADDR=""
CONFIG_NET_CONFIG_PEER_IPV4_ADDR=""

CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=2048

# Enable OpenThread shell
CONFIG_SHELL=y
CONFIG_OPENTHREAD_SHELL=y
CONFIG_SHELL_STACK_SIZE=3072

CONFIG_NET_L2_OPENTHREAD=y

CONFIG_OPENTHREAD_DEBUG=y
CONFIG_OPENTHREAD_L2_DEBUG=y
CONFIG_OPENTHREAD_L2_LOG_LEVEL_INF=y

# Same network Master Key for client and server
CONFIG_OPENTHREAD_NETWORKKEY="00:11:22:33:44:55:66:77:88:99:aa:bb:cc:dd:ee:ff"
CONFIG_OPENTHREAD_NETWORK_NAME="OpenThreadDemo"
CONFIG_OPENTHREAD_PANID=4660
CONFIG_OPENTHREAD_CHANNEL=15

# WPAN local address, by default mesh-local address is used
CONFIG_NET_CONFIG_MY_IPV6_ADDR="fd3f:76ab:550:1:2a9d:e83a:3e:84a7"

# CONFIG_OPENTHREAD_MBEDTLS_CHOICE=y # Use source mbedtls not Builtin

# A sample configuration to enable Thread Joiner, uncomment if needed
#CONFIG_OPENTHREAD_JOINER=y
#CONFIG_OPENTHREAD_JOINER_AUTOSTART=y

# Enable diagnostic module, uncomment if needed
#CONFIG_OPENTHREAD_DIAG=y

#
#overlay-tls.conf
#
CONFIG_MAIN_STACK_SIZE=4096
CONFIG_NET_BUF_RX_COUNT=100
CONFIG_NET_BUF_TX_COUNT=100

# mbedTLS tweaks
# CONFIG_MBEDTLS_SSL_MAX_CONTENT_LEN=768
CONFIG_MBEDTLS_DEBUG_C=y
CONFIG_MBEDTLS_DEBUG=y
CONFIG_MBEDTLS_DEBUG_LEVEL=4

# TLS configuration
CONFIG_MBEDTLS=y
CONFIG_MBEDTLS_BUILTIN=y
CONFIG_MBEDTLS_ENABLE_HEAP=y
CONFIG_MBEDTLS_HEAP_SIZE=100000
CONFIG_MBEDTLS_SSL_MAX_CONTENT_LEN=10240
CONFIG_MBEDTLS_PEM_CERTIFICATE_FORMAT=y

CONFIG_NET_SOCKETS_SOCKOPT_TLS=y
CONFIG_NET_SOCKETS_TLS_MAX_CONTEXTS=4
CONFIG_NET_SOCKETS_ENABLE_DTLS=y
CONFIG_POSIX_MAX_FDS=8

I am sure the nRF52840 makes a TCP connection with the broker, and I can see it negotiates a MTU. However I do not know why the Connect fails.

*Edit I just tried the same using the 1883 port and without TLS, I got the same result. MBedTLS has nothing to do with the problem. The TCPDump and RTT logs are not different.

The Mosquitto output is a little different though:

1657295433: New connection from fd3f:76ab:550:1:2a9d:e83a:3e:84a7:56435 on port 1883.
1657295433: Client <unknown> closed its connection.
1657295433: New connection from fd3f:76ab:550:1:2a9d:e83a:3e:84a7:42324 on port 1883.
1657295433: Client <unknown> closed its connection.
1657295433: New connection from fd3f:76ab:550:1:2a9d:e83a:3e:84a7:62730 on port 1883.
1657295433: Client <unknown> closed its connection.

How do I debug this?

Related