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,

115 is ENETDOWN (network is down) and 116 is ETIMEDOUT (connection timed out).

Can you set up an 802.15.4 sniffer and collect a sniffer log of when you try to set up TCP socket? Make sure to use the same Thread nwk key as the default one in the samples, or share your nwk key here.

Are you able to collect logs from the server? If so, are you able to see if anything is happening there?

Best regards,

Marte

[vipin das]

Hi Marte,

Thank you. 

I am not sure how quickly I can setup the sniffer for 802.15.4 as I don't have spare dongle with me. I have only one spare nRF5340 DK. I think I cannot setup sniffer on that. But let me see how fast I can set it up.Do you have any other thoughts on this issue or something I can try. 

Currently I am using the default network key for my thread network. 

So far I didn't check the logs on the server side. But can check the logs tomorrow. 

Regards

Vipin Das 

[vipin das]

Hi Marte,

Finally I figured it out the reason for the above mentioned issue. OpenThread's TCP stack interferes with Zephyr's stack. Jonathan from OpenThread gave a hint on the problem and disabling the config solves the issue. 

But I might need your support on figuring out some other issues.  

• I am getting response(Bad Request)  from server as follows. "http_client: server_response_cb: Response status Bad Request". Do you think I should do anything in the configuration. Below is my code snippet for http header formation. Could you please tell what is wrong here with my request. 

char* fields[]         = {"Host:mainnet.incubed.net", "User-Agent: openthread https for in3", NULL};
    req.header_fields      = fields;
    req.optional_headers   = fields;
    req.content_type_value = "application/json";
    req.method             = HTTP_POST;
    req.url                = "/";
    req.host               = SERVER_ADDR6;
    req.protocol           = "HTTP/1.1";
    req.payload            = msg;
    req.payload_len        = len;
    req.response           = server_response_cb;
    req.recv_buf           = recv_buf_ipv6;
    req.recv_buf_len       = sizeof(recv_buf_ipv6);
    ret                    = http_client_req(sock6, &req, timeout, "IPv6 POST");

• Could you please tell me any config option to enable the http_client log to see the http request(header + payload)  that I send to http server. Soon I will setup the sniffer for 802.15.4, hope that helps bit more right? 
• After this I wanted to use TLS socket for a secure communication. But when I enable 
  CONFIG_NET_SOCKETS_SOCKOPT_TLS, I get an error as seen below log: 

  [00:00:35.928,649] <dbg> in3_ot: sendOpenThreadPing: Ping Server:
  [00:00:35.928,680] <dbg> in3_ot: printIpv6Address: Mesh Local EID Address: fd97.6739.093e.0002.0000.0000.a756.5ef8
  [00:00:35.929,016] <dbg> in3_ot: sendOpenThreadPing: ping send response:0
  [00:00:35.929,229] <dbg> http_client: in3_register_https_client: in3 register https
  [00:00:35.962,066] <dbg> http_client: setup_socket: Setup socket info: Server address: fd97:6739:93e:2:0:0:A756:5EF8
  [00:00:35.962,219] <dbg> net_sock_tls: tls_alloc: (main): Allocated TLS context, 0x200050b0
  [00:00:35.962,524] <dbg> net_tcp: tcp_conn_ref: (main): conn: 0x200328e8, ref_count: 1
  [00:00:35.962,554] <dbg> net_tcp: tcp_conn_alloc: (main): conn: 0x200328e8
  [00:00:35.962,585] <dbg> net_sock: zsock_socket_internal: (main): socket: ctx=0x20011fcc, fd=1
  [00:00:35.962,738] <dbg> net_ctx: net_context_bind: (main): Context 0x20011fcc binding to TCP [::]:39902 iface 1 (0x20000ab8)
  [00:00:35.962,890] <dbg> net_tcp: net_tcp_connect: (main): context: 0x20011fcc, local: ::, remote: fd97:6739:93e:2::a756:5ef8
  [00:00:35.962,982] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x200328e8 src: ::, dst: fd97:6739:93e:2::a756:5ef8
  [00:00:35.963,104] <dbg> net_conn: conn_register_debug: (main): [0x20012578/6/2/0x3f] remote fd97:6739:93e:2::a756:5ef8/443 
  [00:00:35.963,165] <dbg> net_conn: conn_register_debug: (main):   local ::/39902 cb 0x18425 ud 0x20011fcc
  [00:00:35.963,287] <dbg> net_tcp: tcp_in: (main):  [LISTEN Seq=1480259692 Ack=0]
  [00:00:35.963,562] <dbg> net_tcp: tcp_out_ext: (main): SYN Seq=1480259692 Len=0
  [00:00:35.963,714] <dbg> net_tcp: tcp_send_process_no_lock: (main): SYN Seq=1480259692 Len=0 
  [00:00:35.963,958] <dbg> net_tcp: tcp_send: (main): SYN Seq=1480259692 Len=0
  [00:00:35.964,294] <dbg> net_tcp: tcp_in: (main): LISTEN->SYN_SENT
  [00:00:35.989,471] <inf> net_l2_openthread: State changed! Flags: 0x00000200 Current role: router
  [00:00:35.989,532] <inf> net_l2_openthread: State changed! Flags: 0x00000001 Current role: router
  [00:00:36.188,507] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): SYN Seq=1480259692 Len=0 in_retransmission
  [00:00:36.188,720] <dbg> net_tcp: tcp_send: (tcp_work): SYN Seq=1480259692 Len=0
  [00:00:36.413,055] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): SYN Seq=1480259692 Len=0 in_retransmission
  [00:00:36.413,269] <dbg> net_tcp: tcp_send: (tcp_work): SYN Seq=1480259692 Len=0
  [00:00:36.637,573] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): SYN Seq=1480259692 Len=0 in_retransmission
  [00:00:36.637,786] <dbg> net_tcp: tcp_send: (tcp_work): SYN Seq=1480259692 Len=0
  [00:00:36.862,091] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): SYN Seq=1480259692 Len=0 in_retransmission
  [00:00:36.862,304] <dbg> net_tcp: tcp_send: (tcp_work): SYN Seq=1480259692 Len=0
  [00:00:37.086,608] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): SYN Seq=1480259692 Len=0 in_retransmission
  [00:00:37.086,822] <dbg> net_tcp: tcp_send: (tcp_work): SYN Seq=1480259692 Len=0
  [00:00:37.311,157] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): SYN Seq=1480259692 Len=0 in_retransmission
  [00:00:37.311,370] <dbg> net_tcp: tcp_send: (tcp_work): SYN Seq=1480259692 Len=0
  [00:00:37.535,675] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): SYN Seq=1480259692 Len=0 in_retransmission
  [00:00:37.535,888] <dbg> net_tcp: tcp_send: (tcp_work): SYN Seq=1480259692 Len=0
  [00:00:37.760,223] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): SYN Seq=1480259692 Len=0 in_retransmission
  [00:00:37.760,437] <dbg> net_tcp: tcp_send: (tcp_work): SYN Seq=1480259692 Len=0
  [00:00:37.984,771] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): SYN Seq=1480259692 Len=0 in_retransmission
  [00:00:37.985,015] <dbg> net_tcp: tcp_send: (tcp_work): SYN Seq=1480259692 Len=0
  [00:00:38.209,320] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): SYN Seq=1480259692 Len=0 in_retransmission
  [00:00:38.209,381] <dbg> net_tcp: tcp_conn_unref_debug: (tcp_work): conn: 0x200328e8, ref_count=1 (tcp_send_process():568)
  [00:00:38.209,411] <dbg> net_tcp: tcp_conn_unref_debug: (tcp_work): conn: 0x200328e8 is waiting on connect semaphore
  [00:00:38.964,416] <dbg> net_tcp: tcp_conn_unref_debug: (main): conn: 0x200328e8, ref_count=1 (net_tcp_connect():2856)
  [00:00:38.964,477] <dbg> net_conn: net_conn_unregister: (main): Connection handler 0x20012578 removed
  [00:00:38.964,599] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x200328e8, ret=-116
  [00:00:38.964,630] <err> http_client: Cannot connect to IPv6 remote (-116)
  [00:00:38.964,660] <err> http_client: Failed to connect to socket
  [00:00:38.964,660] <dbg> http_client: run_https_post: starting tcp failed
  [00:00:39.021,118] <dbg> main: main: Error sending rpc request: The request could not be send!

  Could you please tell why connection to TLS socket is getting failed here.  My TLS config from prj.conf. 

  #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=64000
  CONFIG_MBEDTLS_ENTROPY_ENABLED=y
  # certificate must fit into one message, fragmenting is not supported
  CONFIG_MBEDTLS_SSL_MAX_CONTENT_LEN=10240
  CONFIG_MBEDTLS_PEM_CERTIFICATE_FORMAT=n
  
  #Credentials
  CONFIG_TLS_CREDENTIALS=y
  CONFIG_TLS_MAX_CREDENTIALS_NUMBER=4

  Regards

  Vipin Das 

[vipin das]

Hi Marte, 

Any update on my last posted questions? 

Could you please tell the possible reasons for Bad HTTP request? 

Thanks 

Vipin Das

[Marte Myrvold]

Hi,

vipin das said:

I am getting response(Bad Request)  from server as follows. "http_client: server_response_cb: Response status Bad Request". Do you think I should do anything in the configuration. Below is my code snippet for http header formation. Could you please tell what is wrong here with my request. 

Please share the complete log of this.

Have you checked the logs on the server?

vipin das said:

Could you please tell me any config option to enable the http_client log to see the http request(header + payload)  that I send to http server. Soon I will setup the sniffer for 802.15.4, hope that helps bit more right? 

Set the log level to debug, i.e CONFIG_NET_HTTP_LOG_LEVEL_DBG=y.

The sniffer log might help with figuring out what is happening, yes.

vipin das said:

After this I wanted to use TLS socket for a secure communication.

Let us focus on getting TCP to work first, before focusing on TLS.

Best regards,

Marte