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?
