rf5340 OpenThread TLS handshake problem

[Michal P]

I'm  trying to use  Azure IOT SDK on OpenThread CLI example. I'm getting Tls handshake problem. It might be related to tcp_window_full - anybody has any idea what would be the best way to troubleshoot that?  The same certyficates used on nrf7002 works fine. 

[00:00:07.770,050] <dbg> net_tcp: tcp_out_ext: (main): ACK,PSH Seq=3009090985 Ack=4193561263 Len=7
[00:00:07.781,860] <dbg> net_tcp: tcp_send_process_no_lock: (main): ACK,PSH Seq=3009090985 Ack=4193561263 Len=7 
[00:00:07.794,891] <dbg> net_tcp: tcp_send: (main): ACK,PSH Seq=3009090985 Ack=4193561263 Len=7
[00:00:07.806,274] <dbg> net_if: net_if_tx: (tx_q[0]): Processing (pkt 0x2006c6a8, prio 0) network packet iface 0x20001188/1
[00:00:07.820,129] <dbg> net_tcp: tcp_send_data: (main): conn: 0x2006d800 total=7, unacked_len=7, send_win=1536, mss=1220
[00:00:07.833,709] <dbg> net_tcp: tcp_send_data: (main): conn: 0x2006d800 send_data_timer=0, send_data_retries=0
[00:00:07.846,496] <dbg> net_tcp: tcp_unsent_len: (main): unsent_len=0
[00:00:07.855,651] <dbg> net_tcp: tcp_window_full: (main): conn: 0x2006d800 window_full=0
[00:00:07.867,034] <err> net_sock_tls: TLS handshake error: -2700
[00:00:07.883,209] <dbg> net_tcp: net_tcp_recv: (main): context: 0x20004ea8, cb: (nil), user_data: (nil)
[00:00:07.895,507] <dbg> net_tcp: net_tcp_put: (main):  [ESTABLISHED Seq=3009090985 Ack=4193561263]
[00:00:07.907,135] <dbg> net_tcp: net_tcp_put: (main): context 0x20004ea8 CONNECTED
[00:00:07.917,419] <dbg> net_tcp: net_tcp_put: (main): conn 0x2006d800 pending 7 bytes
[00:00:07.927,947] <dbg> net_tcp: tcp_conn_unref: (main): conn: 0x2006d800, ref_count=2
[00:00:07.938,568] <err> mqtt_helper: mqtt_connect, error: -113
[00:00:07.947,357] <dbg> mqtt_helper: mqtt_state_set: State transition: MQTT_STATE_TRANSPORT_CONNECTING --> MQTT_STATE_DISCONNECTED
[00:00:07.961,791] <err> azure_iot_hub: mqtt_helper_connect failed, error: -113
[00:00:07.971,954] <dbg> azure_iot_hub: iot_hub_state_set: State transition: STATE_CONNECTING --> STATE_DISCONNECTED
[00:00:07.985,076] <err> cli_sample: azure_iot_hub_connect failed: -113
[00:00:08.062,713] <dbg> net_tcp: tcp_in: (rx_q[0]): FIN,ACK Seq=4193561263 Ack=3009090992 Len=0 [ESTABLISHED Seq=3009090985 Ack=4193561263]
[00:00:08.077,911] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64122 to 1536
[00:00:08.088,928] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2006d800 window_full=0
[00:00:08.100,250] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): FIN,ACK Seq=3009090992 Ack=4193561264 Len=0
[00:00:08.112,213] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): FIN,ACK Seq=3009090992 Ack=4193561264 Len=0 
[00:00:08.125,488] <dbg> net_tcp: tcp_send: (rx_q[0]): FIN,ACK Seq=3009090992 Ack=4193561264 Len=0
[00:00:08.137,084] <dbg> net_tcp: tcp_in: (rx_q[0]): ESTABLISHED->LAST_ACK
[00:00:08.146,575] <dbg> net_if: net_if_tx: (tx_q[0]): Processing (pkt 0x2006c658, prio 0) network packet iface 0x20001188/1
[00:00:08.181,060] <dbg> net_tcp: tcp_resend_data: (tcp_work): send_data_retries=0
[00:00:08.191,253] <dbg> net_tcp: tcp_new_reno_log: (tcp_work): conn: 0x2006d800, ca timeout, cwnd=1220, ssthres=2440, fast_pend=0
[00:00:08.205,535] <dbg> net_tcp: tcp_window_full: (tcp_work): conn: 0x2006d800 window_full=0
[00:00:08.216,644] <dbg> net_tcp: tcp_unsent_len: (tcp_work): unsent_len=7
[00:00:08.226,104] <dbg> net_tcp: tcp_unsent_len: (tcp_work): unsent_len=7
[00:00:08.235,900] <dbg> net_tcp: tcp_out_ext: (tcp_work): ACK,PSH Seq=3009090992 Ack=4193561264 Len=7
[00:00:08.247,985] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): FIN,ACK Seq=3009090992 Ack=4193561264 Len=0 in_retransmission
[00:00:08.262,786] <dbg> net_tcp: tcp_send: (tcp_work): FIN,ACK Seq=3009090992 Ack=4193561264 Len=0
[00:00:08.274,505] <dbg> net_tcp: tcp_send_data: (tcp_work): conn: 0x2006d800 total=7, unacked_len=7, send_win=1536, mss=1220
[00:00:08.288,421] <dbg> net_tcp: tcp_send_data: (tcp_work): conn: 0x2006d800 send_data_timer=0, send_data_retries=0
[00:00:08.301,635] <dbg> net_if: net_if_tx: (tx_q[0]): Processing (pkt 0x2006c6f8, prio 0) network packet iface 0x20001188/1
[00:00:08.317,901] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK Seq=4193561264 Ack=3009090993 Len=0 [LAST_ACK Seq=3009090992 Ack=4193561264]
[00:00:08.332,489] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64122 to 1536
[00:00:08.343,536] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2006d800 window_full=0
[00:00:08.354,736] <dbg> net_tcp: tcp_send_timer_cancel: (rx_q[0]): FIN,ACK Seq=3009090992 Ack=4193561264 Len=0
[00:00:08.367,462] <dbg> net_tcp: tcp_conn_close_debug: (rx_q[0]): conn: 0x2006d800 closed by TCP stack (tcp_in():2968)
[00:00:08.380,798] <dbg> net_tcp: tcp_conn_close_debug: (rx_q[0]): LAST_ACK->CLOSED
[00:00:08.391,052] <dbg> net_tcp: tcp_conn_unref: (rx_q[0]): conn: 0x2006d800, ref_count=1
[00:00:08.401,916] <dbg> net_ctx: net_context_unref: (rx_q[0]): Context 0x20004ea8 released
[00:00:08.456,298] <dbg> net_if: net_if_tx: (tx_q[0]): Processing (pkt 0x2006c798, prio 1) network packet iface 0x20001188/1

tcpdump on Border router

root@beaglebone:/home/debian# tcpdump -i wpan0 -n
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on wpan0, link-type RAW (Raw IP), capture size 262144 bytes
05:24:13.978907 IP 192.168.255.249.58009 > 40.113.176.181.8883: Flags [S], seq 3009090453, win 1536, options [mss 1220], length 0
05:24:14.010139 IP 40.113.176.181.8883 > 192.168.255.249.58009: Flags [S.], seq 4193557732, ack 3009090454, win 64660, options [mss 1440], length 0
05:24:14.562688 IP 192.168.255.249.58009 > 40.113.176.181.8883: Flags [.], ack 1, win 1536, length 0
05:24:14.614176 IP 192.168.255.249.58009 > 40.113.176.181.8883: Flags [P.], seq 1:532, ack 1, win 1536, length 531
05:24:14.652401 IP 40.113.176.181.8883 > 192.168.255.249.58009: Flags [.], seq 1:1221, ack 532, win 64129, length 1220
05:24:14.966189 IP 192.168.255.249.58009 > 40.113.176.181.8883: Flags [.], ack 1221, win 1536, length 0
05:24:15.000493 IP 40.113.176.181.8883 > 192.168.255.249.58009: Flags [.], seq 1221:2441, ack 532, win 64129, length 1220
05:24:15.233025 IP 192.168.255.249.58009 > 40.113.176.181.8883: Flags [.], ack 2441, win 1536, length 0
05:24:15.261542 IP 40.113.176.181.8883 > 192.168.255.249.58009: Flags [P.], seq 2441:3531, ack 532, win 64129, length 1090
05:24:15.881532 IP 192.168.255.249.58009 > 40.113.176.181.8883: Flags [.], ack 3531, win 1536, length 0
05:24:15.887323 IP 192.168.255.249.58009 > 40.113.176.181.8883: Flags [P.], seq 532:539, ack 3531, win 1536, length 7
05:24:15.927808 IP 40.113.176.181.8883 > 192.168.255.249.58009: Flags [F.], seq 3531, ack 539, win 64122, length 0
05:24:16.045340 IP 192.168.255.249.58009 > 40.113.176.181.8883: Flags [F.], seq 539, ack 3532, win 1536, length 0
05:24:16.074453 IP 40.113.176.181.8883 > 192.168.255.249.58009: Flags [.], ack 540, win 64122, length 0
05:24:16.296158 IP 192.168.255.249.58009 > 40.113.176.181.8883: Flags [F.], seq 539, ack 3532, win 1536, length 0
05:24:16.324369 IP 40.113.176.181.8883 > 192.168.255.249.58009: Flags [.], ack 540, win 0, length 0

[Sigurd Hellesvik]

Hi,

From https://gist.github.com/erikcorry/b25bdcacf3e0086f8a2afb688420678e#file-mbedtls-errors-txt-L29:

"0x2700 X509 - Certificate verification failed, e.g. CRL, CA or signature check failed"

I think this would be the same as MBEDTLS_ERR_X509_CERT_VERIFY_FAILED.

When I look up that I find  [TCP with TLS on nRF7002-DK] mbedtls_ssl_handshake() function returns error -2700 (MBEDTLS_ERR_X509_CERT_VERIFY_FAILED) .

For TLS over Openthread, I found this case:  Adaption to TCP+TLS on top of OpenThread. 

Have a look at those cases and see if you are able to figure something out?

Regards,
Sigurd Hellesvik