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

[vipin das]

Hi Marte,

Thank you. 

I fixed the Bad request error also. The problem got solved after removing req.content_type_value="application/json;charset=UTF-8". 

But now I am getting Response status Internal Server Error(500). I am sharing the log for the new error. 

[00:00:45.584,472] <dbg> net_tcp: tcp_out_ext: (main): ACK Seq=2585330419 Ack=1588306744 Len=0
[00:00:45.584,655] <dbg> net_tcp: tcp_send_process_no_lock: (main): ACK Seq=2585330419 Ack=1588306744 Len=0 
[00:00:45.584,869] <dbg> net_tcp: tcp_send: (main): ACK Seq=2585330419 Ack=1588306744 Len=0
[00:00:45.584,991] <dbg> net_http: on_message_begin: (main): -- HTTP POST response (headers) --
[00:00:45.585,052] <dbg> net_http: on_status: (main): HTTP response status 500 Internal Server Error
[00:00:45.585,266] <dbg> net_http: print_header_field: (main): [6] Server
[00:00:45.585,510] <dbg> net_http: print_header_field: (main): [21] nginx/1.14.0 (Ubuntu)
[00:00:45.585,693] <dbg> net_http: print_header_field: (main): [4] Date
[00:00:45.585,937] <dbg> net_http: print_header_field: (main): [29] Fri, 27 Jan 2023 10:46:48 GMT
[00:00:45.586,120] <dbg> net_http: print_header_field: (main): [12] Content-Type
[00:00:45.586,303] <dbg> net_http: print_header_field: (main): [31] application/json; charset=utf-8
[00:00:45.586,486] <dbg> net_http: print_header_field: (main): [14] Content-Length
[00:00:45.586,639] <dbg> net_http: print_header_field: (main): [3] 115
[00:00:45.586,822] <dbg> net_http: print_header_field: (main): [10] Connection
[00:00:45.586,975] <dbg> net_http: print_header_field: (main): [10] keep-alive
[00:00:45.587,127] <dbg> net_http: print_header_field: (main): [27] Access-Control-Allow-Origin
[00:00:45.587,280] <dbg> net_http: print_header_field: (main): [1] *
[00:00:45.587,402] <dbg> net_http: print_header_field: (main): [28] Access-Control-Allow-Headers
[00:00:45.587,524] <dbg> net_http: print_header_field: (main): [58] Origin, X-Requested-With, Content-Type, Accept, User-Agent
[00:00:45.587,615] <dbg> net_http: print_header_field: (main): [14] X-Request-Time
[00:00:45.587,677] <dbg> net_http: print_header_field: (main): [7] 0.65 ms
[00:00:45.657,623] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20022f80 src port 80 dst port 37746 family 2
[00:00:45.657,653] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x2000f7e0] match found cb 0x17115 ud 0x2000f234 rank 0x3f
[00:00:45.658,050] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK,PSH Seq=1588306744 Ack=2585330419 Len=119 [ESTABLISHED Seq=2585330419 Ack=1588306744]
[00:00:45.658,081] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64079 to 1280
[00:00:45.658,111] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x20023bd0 window_full=0
[00:00:45.658,447] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=2585330419 Ack=1588306863 Len=0
[00:00:45.658,630] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=2585330419 Ack=1588306863 Len=0 
[00:00:45.658,843] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=2585330419 Ack=1588306863 Len=0
[00:00:45.658,966] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x2000f234, pkt=0x20022f80, st=0, user_data=(nil)
[00:00:45.659,362] <dbg> net_http: print_header_field: (main): [0] 
[00:00:45.659,393] <dbg> net_http: on_headers_complete: (main): Status 500, skipping body
[00:00:45.659,423] <dbg> net_http: on_message_complete: (main): -- HTTP POST response (complete) --
[00:00:45.659,454] <dbg> net_http: http_wait_data: (main): Calling callback for 460 len data
[00:00:45.659,454] <dbg> http_client: server_response_cb: All the data received (460 bytes)
[00:00:45.659,484] <dbg> http_client: server_response_cb: Response to IPv6 POST
[00:00:45.659,515] <dbg> http_client: server_response_cb: Response status Internal Server Error
[00:00:45.659,545] <dbg> net_http: http_client_req: (main): Received 460 bytes
[00:00:45.659,606] <dbg> net_sock: z_impl_zsock_close: (main): close: ctx=0x2000f234, fd=0
[00:00:45.659,637] <dbg> net_tcp: net_tcp_recv: (main): context: 0x2000f234, cb: (nil), user_data: (nil)
[00:00:45.659,820] <dbg> net_tcp: net_tcp_put: (main):  [ESTABLISHED Seq=2585330419 Ack=1588306863]
[00:00:45.659,851] <dbg> net_tcp: net_tcp_put: (main): context 0x2000f234 CONNECTED
[00:00:45.659,881] <dbg> net_tcp: net_tcp_put: (main): TCP connection in active close, not disposing yet (waiting 22753ms)
[00:00:45.660,186] <dbg> net_tcp: tcp_out_ext: (main): FIN,ACK Seq=2585330419 Ack=1588306863 Len=0
[00:00:45.660,400] <dbg> net_tcp: tcp_send_process_no_lock: (main): FIN,ACK Seq=2585330419 Ack=1588306863 Len=0 
[00:00:45.660,675] <dbg> net_tcp: tcp_send: (main): FIN,ACK Seq=2585330419 Ack=1588306863 Len=0
[00:00:45.660,797] <dbg> net_tcp: net_tcp_put: (main): ESTABLISHED->FIN_WAIT_1
[00:00:45.716,949] <dbg> main: main: Error sending rpc request: The request could not be send!
[00:00:45.773,284] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20022f80 src port 80 dst port 37746 family 2
[00:00:45.773,315] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x2000f7e0] match found cb 0x17115 ud 0x2000f234 rank 0x3f
[00:00:45.773,681] <dbg> net_tcp: tcp_in: (rx_q[0]): FIN,ACK Seq=1588306863 Ack=2585330420 Len=0 [FIN_WAIT_1 Seq=2585330420 Ack=1588306863]
[00:00:45.773,712] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64078 to 1280
[00:00:45.773,742] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x20023bd0 window_full=0
[00:00:45.773,956] <dbg> net_tcp: tcp_send_timer_cancel: (rx_q[0]): FIN,ACK Seq=2585330419 Ack=1588306863 Len=0
[00:00:45.774,261] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=2585330420 Ack=1588306864 Len=0
[00:00:45.774,444] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=2585330420 Ack=1588306864 Len=0 
[00:00:45.774,658] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=2585330420 Ack=1588306864 Len=0
[00:00:45.774,749] <dbg> net_tcp: tcp_in: (rx_q[0]): FIN_WAIT_1->TIME_WAIT
[00:00:47.274,993] <dbg> net_tcp: tcp_timewait_timeout: (tcp_work): conn: 0x20023bd0  [TIME_WAIT Seq=2585330420 Ack=1588306864]
[00:00:47.275,024] <dbg> net_tcp: net_tcp_unref: (tcp_work): context: 0x2000f234, conn: 0x20023bd0
[00:00:47.275,054] <dbg> net_tcp: tcp_conn_unref_debug: (tcp_work): conn: 0x20023bd0, ref_count=1 (net_tcp_unref():484)
[00:00:47.275,085] <dbg> net_conn: net_conn_unregister: (tcp_work): Connection handler 0x2000f7e0 removed
[00:00:47.275,238] <dbg> net_ctx: net_context_unref: (tcp_work): Context 0x2000f234 released

We have checked the logs on the server as well but because of the Bad request we could not catch much information. Hopefully I will get new dongle today to setup sniffer. Will have more update on the issue by Monday. 

Regards

Vipin Das 

[vipin das]

Hi Marte,

I was trying to setup nRF sniffer tool as per the page: https://infocenter.nordicsemi.com/index.jsp?topic=%2Fug_sniffer_802154%2FUG%2Fsniffer_802154%2Finstalling_sniffer_802154.html. I followed each steps and copied the nrf802154_sniffer.py into Wireshark(3.6.11) ext cap folder. Even I verified the python script

das@Vipins-MBP extcap % python3 nrf802154_sniffer.py --extcap-interfaces                         
extcap {version=0.7.2}{help=https://github.com/NordicSemiconductor/nRF-Sniffer-for-802.15.4}{display=nRF Sniffer for 802.15.4}
interface {value=/dev/cu.usbmodemEC108B497C3D1}{display=nRF Sniffer for 802.15.4}
control {number=6}{type=button}{role=logger}{display=Log}{tooltip=Show capture log}

But nRF Sniffer for 802.15.4 interface is not detecting on the Wireshark. Did I miss any thing here.

I looked many other discussion but nothing helps in my case. Even I tried with 2 different Wireshark versions(3.6 & 4.0). 

Any clue? 

Regards

Vipin Das

[Marte Myrvold]

Hi,

Did you restart your computer after installing Wireshark and configuring the sniffer? I have seen several cases where the sniffer does not show up until after a restart. Are you using a dongle or DK as sniffer?

Best regards,

Marte

[vipin das]

Hi,

Yes I have restarted the my Mac after the installation. I am using a dongle. 

Thanks 

Vipin Das

[vipin das]

Hi Marte, 

I am able to send/receive RPC request/response to our server using TCP socket connection.

Now we can focus on TLS. Could you please help me to trace out the issue with TLS socket. 

For that I am sharing latest log for your reference. 

[00:02:01.942,169] <dbg> http_client: in3_register_https_client: in3 register https
[00:02:01.974,884] <dbg> http_client: setup_socket: Setup socket info: Server address: fd97:6739:93e:2:0:0:A756:5EF8
[00:02:01.975,067] <dbg> net_sock_tls: tls_alloc: (main): Allocated TLS context, 0x20003478
[00:02:01.975,402] <dbg> net_tcp: tcp_conn_ref: (main): conn: 0x20022920, ref_count: 1
[00:02:01.975,433] <dbg> net_tcp: tcp_conn_alloc: (main): conn: 0x20022920
[00:02:01.975,463] <dbg> net_sock: zsock_socket_internal: (main): socket: ctx=0x2001031c, fd=1
[00:02:01.975,646] <dbg> net_tcp: net_tcp_connect: (main): context: 0x2001031c, local: ::, remote: fd97:6739:93e:2::a756:5ef8
[00:02:01.975,860] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20022920 src: fd97:6739:93e:1:aa57:96ae:30b:a5a4, dst: fd97:6739:93e:2::a756:5ef8
[00:02:01.975,982] <dbg> net_conn: conn_register_debug: (main): [0x200107b8/6/2/0x3f] remote fd97:6739:93e:2::a756:5ef8/443 
[00:02:01.976,043] <dbg> net_conn: conn_register_debug: (main):   local ::/40755 cb 0x16b71 ud 0x2001031c
[00:02:01.976,165] <dbg> net_tcp: tcp_in: (main):  [LISTEN Seq=492892335 Ack=0]
[00:02:01.976,440] <dbg> net_tcp: tcp_out_ext: (main): SYN Seq=492892335 Len=0
[00:02:01.976,593] <dbg> net_tcp: tcp_send_process_no_lock: (main): SYN Seq=492892335 Len=0 
[00:02:01.976,806] <dbg> net_tcp: tcp_send: (main): SYN Seq=492892335 Len=0
[00:02:01.977,508] <dbg> net_tcp: tcp_in: (main): LISTEN->SYN_SENT
[00:02:02.050,292] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20021cd0 src port 443 dst port 40755 family 2
[00:02:02.050,354] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x200107b8] match found cb 0x16b71 ud 0x2001031c rank 0x3f
[00:02:02.050,689] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN,ACK Seq=4288225015 Ack=492892336 Len=0 [SYN_SENT Seq=492892336 Ack=0]
[00:02:02.050,720] <dbg> net_tcp: tcp_options_check: (rx_q[0]): len=4
[00:02:02.050,750] <dbg> net_tcp: tcp_options_check: (rx_q[0]): opt: 2, opt_len: 4
[00:02:02.050,781] <dbg> net_tcp: tcp_options_check: (rx_q[0]): MSS=1460
[00:02:02.050,811] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64240 to 1280
[00:02:02.050,842] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x20022920 window_full=0
[00:02:02.050,994] <dbg> net_tcp: tcp_send_timer_cancel: (rx_q[0]): SYN Seq=492892335 Len=0
[00:02:02.051,300] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=492892336 Ack=4288225016 Len=0
[00:02:02.051,513] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=492892336 Ack=4288225016 Len=0 
[00:02:02.051,696] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=492892336 Ack=4288225016 Len=0
[00:02:02.051,788] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN_SENT->ESTABLISHED
[00:02:02.052,001] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20022920, ret=0
[00:02:02.052,062] <dbg> net_tcp: net_tcp_recv: (main): context: 0x2001031c, cb: 0x8ca1, user_data: (nil)
[00:02:02.052,215] <err> http_client: Cannot connect to IPv6 remote (-2)
[00:02:02.052,215] <err> http_client: Failed to connect to socket
[00:02:02.052,246] <dbg> http_client: run_https_post: starting tcp failed
[00:02:02.108,856] <dbg> main: main: Error sending rpc request: The request could not be send!
[00:02:05.325,256] <inf> net_l2_openthread: State changed! Flags: 0x00000064 Current role: router

Thanks 

Vipin Das