Adaption to TCP+TLS on top of OpenThread.

[vipin das]

Hi All,

I am currently working on establishing a thread network to communicate to our http server:https://mainnet.incubed.net). In order to setting up that I took echo_client and http_client sample and adapted to our need. Below diagram is my network configuration with RPi connected with ethernet. 

I was successful in pinging the http server from thread network. Here I wanted to send TCP packets to remote server via OT network. 

I am novice to networking topics so it is really hard for me to understand and interpret the logs from the thread device. Below given is the log from the one node:

[00:00:00.396,331] <inf> ieee802154_nrf5: nRF5 802154 radio initialized
[00:00:00.396,728] <dbg> net_tcp: net_tcp_init: (main): Workq started. Thread ID: 0x20008378
[00:00:00.411,651] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.411,682] <inf> fs_nvs: alloc wra: 0, fe8
[00:00:00.411,682] <inf> fs_nvs: data wra: 0, 0
[00:00:00.412,994] <inf> net_l2_openthread: State changed! Flags: 0x00038200 Current role: disabled
[00:00:00.418,487] <inf> net_config: Initializing network
[00:00:00.418,487] <inf> net_config: Waiting interface 1 (0x20000a08) to be up...
[00:00:30.419,189] <err> net_config: Timeout while waiting network interface
[00:00:30.419,219] <err> net_config: Network initialization failed (-115)
[00:00:30.419,525] <inf> in3_ot: Waiting for host to be ready to communicate
[00:00:30.423,675] <inf> usb_cdc_acm: Device suspended
[00:00:30.621,520] <inf> usb_cdc_acm: Device resumed
[00:00:30.737,701] <inf> usb_cdc_acm: Device suspended
[00:00:30.945,312] <inf> usb_cdc_acm: Device resumed
[00:00:31.006,927] <inf> usb_cdc_acm: Device configured
[00:00:44.243,072] <inf> net_l2_openthread: State changed! Flags: 0x00004000 Current role: disabled
[00:00:44.243,713] <inf> net_l2_openthread: State changed! Flags: 0x00020000 Current role: disabled
[00:00:44.243,804] <inf> net_l2_openthread: State changed! Flags: 0x00040000 Current role: disabled
[00:00:44.243,896] <inf> net_l2_openthread: State changed! Flags: 0x00000100 Current role: disabled
[00:00:44.247,131] <inf> net_l2_openthread: State changed! Flags: 0x00010000 Current role: disabled
[00:00:44.247,222] <inf> net_l2_openthread: State changed! Flags: 0x00008000 Current role: disabled
[00:00:44.247,741] <inf> net_l2_openthread: State changed! Flags: 0x10000000 Current role: disabled
[00:00:44.247,985] <inf> net_l2_openthread: State changed! Flags: 0x10000000 Current role: disabled
[00:00:44.249,053] <inf> net_l2_openthread: State changed! Flags: 0x00001000 Current role: disabled
[00:00:44.249,237] <wrn> net_l2_openthread: No address info provided with event, please enable CONFIG_NET_MGMT_EVENT_INFO
[00:00:44.249,267] <wrn> net_l2_openthread: No address info provided with event, please enable CONFIG_NET_MGMT_EVENT_INFO
[00:00:44.249,389] <inf> net_l2_openthread: State changed! Flags: 0x00000001 Current role: disabled
[00:00:44.249,450] <wrn> net_l2_openthread: No address info provided with event, please enable CONFIG_NET_MGMT_EVENT_INFO
[00:00:44.249,542] <inf> net_l2_openthread: State changed! Flags: 0x00000008 Current role: disabled
[00:00:44.249,664] <inf> net_l2_openthread: State changed! Flags: 0x01000000 Current role: disabled
[00:00:44.249,786] <inf> net_l2_openthread: State changed! Flags: 0x00000004 Current role: detached
[00:00:44.249,938] <inf> net_l2_openthread: State changed! Flags: 0x00000001 Current role: detached
[00:00:44.250,030] <wrn> net_l2_openthread: No address info provided with event, please enable CONFIG_NET_MGMT_EVENT_INFO
[00:00:44.250,152] <inf> net_l2_openthread: State changed! Flags: 0x00001000 Current role: detached
[00:00:44.250,274] <wrn> net_l2_openthread: No address info provided with event, please enable CONFIG_NET_MGMT_EVENT_INFO
[00:00:44.250,396] <inf> net_l2_openthread: State changed! Flags: 0x00001000 Current role: detached
[00:00:44.250,549] <wrn> net_l2_openthread: No address info provided with event, please enable CONFIG_NET_MGMT_EVENT_INFO
[00:00:44.250,640] <inf> net_l2_openthread: State changed! Flags: 0x00000010 Current role: detached
[00:00:44.251,373] <inf> net_l2_openthread: State changed! Flags: 0x10000000 Current role: detached
[00:00:46.497,467] <inf> net_l2_openthread: State changed! Flags: 0x200012a4 Current role: child
[00:00:46.497,741] <inf> net_l2_openthread: State changed! Flags: 0x00000001 Current role: child
[00:00:46.497,863] <wrn> net_l2_openthread: No address info provided with event, please enable CONFIG_NET_MGMT_EVENT_INFO
[00:00:46.497,894] <wrn> net_l2_openthread: No address info provided with event, please enable CONFIG_NET_MGMT_EVENT_INFO
[00:00:46.497,955] <dbg> in3_ot: ping_send: Ping Server:
[00:00:46.497,985] <dbg> in3_ot: print_ipv6_address: Mesh Local EID Address: fd97.6739.093e.0002.0000.0000.a756.5ef8
[00:00:46.498,596] <dbg> in3_ot: ping_send: ping send response:0
[00:00:46.498,626] <dbg> main: main: Connected to thread network
[00:00:46.499,145] <dbg> net_tcp: tcp_conn_ref: (main): conn: 0x20033d58, ref_count: 1
[00:00:46.499,176] <dbg> net_tcp: tcp_conn_alloc: (main): conn: 0x20033d58
[00:00:46.499,389] <dbg> net_tcp: net_tcp_connect: (main): context: 0x20013814, local: ::, remote: fd97:6739:93e:2::a756:5ef8
[00:00:46.499,542] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20033d58 src: fd11:22::271f:b127:ea60:6f99, dst: fd97:6739:93e:2::a756:5ef8
[00:00:46.499,664] <dbg> net_tcp: tcp_in: (main):  [LISTEN Seq=1723021025 Ack=0]
[00:00:46.499,938] <dbg> net_tcp: tcp_out_ext: (main): SYN Seq=1723021025 Len=0
[00:00:46.500,091] <dbg> net_tcp: tcp_send_process_no_lock: (main): SYN Seq=1723021025 Len=0 
[00:00:46.500,305] <dbg> net_tcp: tcp_send: (main): SYN Seq=1723021025 Len=0
[00:00:46.500,671] <dbg> net_tcp: tcp_in: (main): LISTEN->SYN_SENT
[00:00:46.567,230] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK,RST Seq=0 Ack=1723021026 Len=0 [SYN_SENT Seq=1723021026 Ack=0]
[00:00:46.567,260] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN_SENT->CLOSED
[00:00:46.567,352] <dbg> net_tcp: tcp_conn_unref_debug: (rx_q[0]): conn: 0x20033d58, ref_count=1 (tcp_in():2513)
[00:00:46.567,382] <dbg> net_tcp: tcp_conn_unref_debug: (rx_q[0]): conn: 0x20033d58 is waiting on connect semaphore
[00:00:46.573,516] <dbg> in3_ot: ping_reply_cb: Ping reply
[00:00:46.573,547] <dbg> in3_ot: print_ipv6_address: Mesh Local EID Address: fd97.6739.093e.0002.0000.0000.a756.5ef8

Can someone tell me what is happening here and what I did wrong or not taken into my consideration. 

Regards

Vipin Das

[Marte Myrvold]

Hi,

Is this the log from after you got TCP to work? Because in your log, I see that TCP is still failing:

[00:02:02.052,246] <dbg> http_client: run_https_post: starting tcp failed

Best regards,

Marte

[vipin das]

Hi Marte, 

Yes this is the same log after TCP got worked. For this log I just enabled the CONFIG_NET_SOCKETS_SOCKOPT_TLS=y. Don't get confuse with that particular log. That is something I added. 

ret = connect(*sock, addr, addr_len);
  if (ret < 0) {
    LOG_ERR("Cannot connect to %s remote (%d)", family == AF_INET ? "IPv4" : "IPv6", -errno);
    ret = -errno;
  }

This time it fails at this connect to TLS socket but socket creation is success(socket(family, SOCK_STREAM, IPPROTO_TLS_1_2)). 

Regards

Vipin Das

[Marte Myrvold]

Hi,

So your example is unchanged other than enabling CONFIG_NET_SOCKETS_SOCKOPT_TLS?

Is mbedTLS (CONFIG_MBEDTLS) enabled? Do you have any functionality for TLS? Are you using the correct credentials (certification and private key)?

Best regards,

Marte

[vipin das]

Hi Marte,

Yes you are right. My config related to TLS shared below. 

#Socket settings
CONFIG_NET_SOCKETS_SOCKOPT_TLS=y
CONFIG_POSIX_MAX_FDS=8
CONFIG_NET_SOCKETS_TLS_MAX_CONTEXTS=10

#MBEDTLS and security configuration 
CONFIG_MBEDTLS_CFG_FILE="config-tls-generic.h"
CONFIG_OPENTHREAD_MBEDTLS_CHOICE=y
CONFIG_MBEDTLS_TLS_VERSION_1_2=y
CONFIG_MBEDTLS_TLS_LIBRARY=y
CONFIG_MBEDTLS_SSL_PROTO_TLS1_2=y

# TLS configuration
CONFIG_MBEDTLS=y
CONFIG_MBEDTLS_BUILTIN=y
CONFIG_MBEDTLS_ENABLE_HEAP=y
CONFIG_MBEDTLS_HEAP_SIZE=8192
CONFIG_MBEDTLS_ENTROPY_ENABLED=y
# certificate must fit into one message, fragmenting is not supported
CONFIG_MBEDTLS_SSL_MAX_CONTENT_LEN=8192

#Credentials
CONFIG_TLS_CREDENTIALS=y
CONFIG_TLS_MAX_CREDENTIALS_NUMBER=4

No I don't think I have any functionality for TLS at the moment. 

Please consider me a novice user in networking topics. This is 1st time I am working on TLS socket connection. I just followed some of the existing samples and few discussions. I don't really understand about the certification and private key that you mentioned above. I have created the ca_cert.der for the server and it looks similar like below. 

"-----BEGIN CERTIFICATE-----\n"
"----------------------------------------------------------------\n"
"----------------------------------------------------------------\n"
"----------------------------------------------------------------\n"
"-----END CERTIFICATE-----\n"
"-----BEGIN CERTIFICATE-----\n"
"----------------------------------------------------------------\n"
"----------------------------------------------------------------\n"
"----------------------------------------------------------------\n"
"-----END CERTIFICATE-----\n"
"-----BEGIN CERTIFICATE-----\n"
"----------------------------------------------------------------\n"
"----------------------------------------------------------------\n"
"----------------------------------------------------------------\n"
"-----END CERTIFICATE-----\n"

You can share me any proper TLS sample where I can take a look and get inspired to make my application working 

Regards

Vipin Das

[vipin das]

Hi Marte,

I have added the tis_credential_add() to add the downloaded server certificate to authenticate the remote server. After adding that connect error is -22 (EINVAL). 

[00:01:57.147,583] <dbg> http_client: in3_register_https_client: in3 register https
[00:01:57.180,664] <dbg> http_client: setup_socket: Setup socket info: Server address: fd97:6739:93e:2:0:0:A756:5EF8
[00:01:57.180,847] <dbg> net_sock_tls: tls_alloc: (main): Allocated TLS context, 0x20003478
[00:01:57.181,152] <dbg> net_tcp: tcp_conn_ref: (main): conn: 0x2002d020, ref_count: 1
[00:01:57.181,182] <dbg> net_tcp: tcp_conn_alloc: (main): conn: 0x2002d020
[00:01:57.181,274] <dbg> net_sock: zsock_socket_internal: (main): socket: ctx=0x2001031c, fd=1
[00:01:57.181,457] <dbg> net_tcp: net_tcp_connect: (main): context: 0x2001031c, local: ::, remote: fd97:6739:93e:2::a756:5ef8
[00:01:57.181,640] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x2002d020 src: fd97:6739:93e:1:8ea6:548e:c791:187, dst: fd97:6739:93e:2::a756:5ef8
[00:01:57.181,762] <dbg> net_conn: conn_register_debug: (main): [0x200107b8/6/2/0x3f] remote fd97:6739:93e:2::a756:5ef8/443
[00:01:57.181,823] <dbg> net_conn: conn_register_debug: (main):   local ::/35905 cb 0x16c01 ud 0x2001031c
[00:01:57.181,945] <dbg> net_tcp: tcp_in: (main):  [LISTEN Seq=1369800138 Ack=0]
[00:01:57.182,220] <dbg> net_tcp: tcp_out_ext: (main): SYN Seq=1369800138 Len=0
[00:01:57.182,373] <dbg> net_tcp: tcp_send_process_no_lock: (main): SYN Seq=1369800138 Len=0
[00:01:57.182,617] <dbg> net_tcp: tcp_send: (main): SYN Seq=1369800138 Len=0
[00:01:57.183,319] <dbg> net_tcp: tcp_in: (main): LISTEN->SYN_SENT
[00:01:57.231,292] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x2002c3d0 src port 443 dst port 35905 family 2
[00:01:57.231,323] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x200107b8] match found cb 0x16c01 ud 0x2001031c rank 0x3f
[00:01:57.231,658] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN,ACK Seq=3663983358 Ack=1369800139 Len=0 [SYN_SENT Seq=1369800139 Ack=0]
[00:01:57.231,689] <dbg> net_tcp: tcp_options_check: (rx_q[0]): len=4
[00:01:57.231,719] <dbg> net_tcp: tcp_options_check: (rx_q[0]): opt: 2, opt_len: 4
[00:01:57.231,750] <dbg> net_tcp: tcp_options_check: (rx_q[0]): MSS=1460
[00:01:57.231,781] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64240 to 3413
[00:01:57.231,811] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2002d020 window_full=0
[00:01:57.231,964] <dbg> net_tcp: tcp_send_timer_cancel: (rx_q[0]): SYN Seq=1369800138 Len=0
[00:01:57.232,299] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=1369800139 Ack=3663983359 Len=0
[00:01:57.232,482] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=1369800139 Ack=3663983359 Len=0
[00:01:57.232,666] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=1369800139 Ack=3663983359 Len=0
[00:01:57.232,788] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN_SENT->ESTABLISHED
[00:01:57.233,001] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x2002d020, ret=0
[00:01:57.233,062] <dbg> net_tcp: net_tcp_recv: (main): context: 0x2001031c, cb: 0x8ce1, user_data: (nil)
[00:01:57.233,245] <err> http_client: Cannot connect to IPv6 remote (-22)
[00:01:57.233,245] <err> http_client: Failed to connect to socket
[00:01:57.233,245] <dbg> http_client: run_https_post: starting tcp failed
[00:01:57.290,252] <dbg> main: main: Error sending rpc request: The request could not be send!
[00:02:07.629,394] <inf> net_l2_openthread: State changed! Flags: 0x00000064 Current role: router
[00:02:57.395,874] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x2002c3d0 src port 443 dst port 35905 family 2
[00:02:57.395,904] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x200107b8] match found cb 0x16c01 ud 0x2001031c rank 0x3f
[00:02:57.396,301] <dbg> net_tcp: tcp_in: (rx_q[0]): FIN,ACK Seq=3663983359 Ack=1369800139 Len=0 [ESTABLISHED Seq=1369800139 Ack=3663983359]
[00:02:57.396,331] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64240 to 3413
[00:02:57.396,362] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2002d020 window_full=0
[00:02:57.396,667] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): FIN,ACK Seq=1369800139 Ack=3663983360 Len=0
[00:02:57.396,881] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): FIN,ACK Seq=1369800139 Ack=3663983360 Len=0 
[00:02:57.397,155] <dbg> net_tcp: tcp_send: (rx_q[0]): FIN,ACK Seq=1369800139 Ack=3663983360 Len=0
[00:02:57.397,277] <dbg> net_tcp: tcp_in: (rx_q[0]): ESTABLISHED->LAST_ACK
[00:02:57.457,122] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x2002c3d0 src port 443 dst port 35905 family 2
[00:02:57.457,153] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x200107b8] match found cb 0x16c01 ud 0x2001031c rank 0x3f
[00:02:57.457,519] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK Seq=3663983360 Ack=1369800140 Len=0 [LAST_ACK Seq=1369800139 Ack=3663983360]
[00:02:57.457,550] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64239 to 3413
[00:02:57.457,580] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2002d020 window_full=0
[00:02:57.457,794] <dbg> net_tcp: tcp_send_timer_cancel: (rx_q[0]): FIN,ACK Seq=1369800139 Ack=3663983360 Len=0
[00:02:57.457,855] <dbg> net_tcp: tcp_in: (rx_q[0]): LAST_ACK->CLOSED
[00:02:57.457,885] <dbg> net_tcp: tcp_conn_unref_debug: (rx_q[0]): conn: 0x2002d020, ref_count=1 (tcp_in():2513)
[00:02:57.457,916] <dbg> net_conn: net_conn_unregister: (rx_q[0]): Connection handler 0x200107b8 removed
[00:02:57.457,977] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x2001031c, pkt=(nil), st=0, user_data=(nil)
[00:02:57.458,007] <dbg> net_sock: zsock_received_cb: (rx_q[0]): Marked socket 0x2001031c as peer-closed

Just to update the present status of my issue. 

Regards

Vipin Das