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, 

Register public certificate issue is solved as I understood tls_credential_add() is not needed in my case as the public certificate is already available. 

New log with TCP Socket:

[00:00:38.685,424] <dbg> net_tcp: tcp_conn_ref: (main): conn: 0x20031098, ref_count: 1
[00:00:38.685,455] <dbg> net_tcp: tcp_conn_alloc: (main): conn: 0x20031098
[00:00:38.685,516] <dbg> net_sock: zsock_socket_internal: (main): socket: ctx=0x200109f8, fd=0
[00:00:38.685,668] <dbg> net_ctx: net_context_bind: (main): Context 0x200109f8 binding to TCP [::]:64372 iface 1 (0x20000ab0)
[00:00:38.685,760] <dbg> net_tcp: net_tcp_connect: (main): context: 0x200109f8, local: ::, remote: fd97:6739:93e:2::a756:5ef8
[00:00:38.685,882] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20031098 src: fd11:22::971:d9ff:d4a:17c1, dst: fd97:6739:93e:2::a756:5ef8
[00:00:38.686,035] <dbg> net_conn: conn_register_debug: (main): [0x20010e94/6/2/0x3f] remote fd97:6739:93e:2::a756:5ef8/80 
[00:00:38.686,065] <dbg> net_conn: conn_register_debug: (main):   local ::/64372 cb 0x16ec5 ud 0x200109f8
[00:00:38.686,218] <dbg> net_tcp: tcp_in: (main):  [LISTEN Seq=2289931732 Ack=0]
[00:00:38.686,492] <dbg> net_tcp: tcp_out_ext: (main): SYN Seq=2289931732 Len=0
[00:00:38.686,645] <dbg> net_tcp: tcp_send_process_no_lock: (main): SYN Seq=2289931732 Len=0 
[00:00:38.686,889] <dbg> net_tcp: tcp_send: (main): SYN Seq=2289931732 Len=0
[00:00:38.687,011] <dbg> net_tcp: tcp_in: (main): LISTEN->SYN_SENT
[00:00:38.756,774] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x200304b0 src port 80 dst port 64372 family 2
[00:00:38.756,835] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x20010e94] match found cb 0x16ec5 ud 0x200109f8 rank 0x3f
[00:00:38.757,171] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN,ACK Seq=1304989996 Ack=2289931733 Len=0 [SYN_SENT Seq=2289931733 Ack=0]
[00:00:38.757,202] <dbg> net_tcp: tcp_options_check: (rx_q[0]): len=4
[00:00:38.757,232] <dbg> net_tcp: tcp_options_check: (rx_q[0]): opt: 2, opt_len: 4
[00:00:38.757,293] <dbg> net_tcp: tcp_options_check: (rx_q[0]): MSS=1460
[00:00:38.757,324] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64240 to 1280
[00:00:38.757,354] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x20031098 window_full=0
[00:00:38.757,537] <dbg> net_tcp: tcp_send_timer_cancel: (rx_q[0]): SYN Seq=2289931732 Len=0
[00:00:38.757,843] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=2289931733 Ack=1304989997 Len=0
[00:00:38.758,026] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=2289931733 Ack=1304989997 Len=0 
[00:00:38.758,239] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=2289931733 Ack=1304989997 Len=0
[00:00:38.758,331] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN_SENT->ESTABLISHED
[00:00:38.758,575] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20031098, ret=0
[00:00:38.758,636] <dbg> net_tcp: net_tcp_recv: (main): context: 0x200109f8, cb: 0x9c1d, user_data: (nil)
[00:00:38.758,789] <dbg> net_tcp: net_tcp_recv: (main): context: 0x200109f8, cb: 0x9c1d, user_data: (nil)
[00:00:38.758,911] <dbg> net_tcp: tcp_window_full: (main): conn: 0x20031098 window_full=0
[00:00:38.758,941] <dbg> net_tcp: net_tcp_queue_data: (main): conn: 0x20031098 Queued 75 bytes (total 75)
[00:00:38.758,972] <dbg> net_tcp: tcp_unsent_len: (main): unsent_len=75
[00:00:38.759,368] <dbg> net_tcp: tcp_out_ext: (main): ACK,PSH Seq=2289931733 Ack=1304989997 Len=75
[00:00:38.759,582] <dbg> net_tcp: tcp_send_process_no_lock: (main): ACK,PSH Seq=2289931733 Ack=1304989997 Len=75 
[00:00:38.759,796] <dbg> net_tcp: tcp_send: (main): ACK,PSH Seq=2289931733 Ack=1304989997 Len=75
[00:00:38.759,887] <dbg> net_tcp: tcp_send_data: (main): conn: 0x20031098 total=75, unacked_len=75, send_win=1280, mss=1280
[00:00:38.759,918] <dbg> net_tcp: tcp_send_data: (main): conn: 0x20031098 send_data_timer=0, send_data_retries=0
[00:00:38.759,948] <dbg> net_tcp: tcp_unsent_len: (main): unsent_len=0
[00:00:38.760,009] <dbg> net_tcp: tcp_window_full: (main): conn: 0x20031098 window_full=0
[00:00:38.760,070] <dbg> net_tcp: net_tcp_recv: (main): context: 0x200109f8, cb: 0x9c1d, user_data: (nil)
[00:00:38.760,192] <dbg> net_tcp: tcp_window_full: (main): conn: 0x20031098 window_full=0
[00:00:38.760,223] <dbg> net_tcp: net_tcp_queue_data: (main): conn: 0x20031098 Queued 7 bytes (total 82)
[00:00:38.760,284] <dbg> net_tcp: tcp_unsent_len: (main): unsent_len=7
[00:00:38.760,314] <dbg> net_tcp: tcp_unsent_len: (main): unsent_len=7
[00:00:38.760,345] <dbg> net_tcp: tcp_window_full: (main): conn: 0x20031098 window_full=0
[00:00:38.835,021] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x200304b0 src port 80 dst port 64372 family 2
[00:00:38.835,052] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x20010e94] match found cb 0x16ec5 ud 0x200109f8 rank 0x3f
[00:00:38.835,388] <dbg> net_tcp: tcp_in: (rx_q[0]): RST Seq=1304989997 Len=0 [ESTABLISHED Seq=2289931733 Ack=1304989997]
[00:00:38.835,418] <dbg> net_tcp: tcp_in: (rx_q[0]): ESTABLISHED->CLOSED
[00:00:38.835,510] <dbg> net_tcp: tcp_conn_unref_debug: (rx_q[0]): conn: 0x20031098, ref_count=1 (tcp_in():2513)
[00:00:38.835,540] <dbg> net_conn: net_conn_unregister: (rx_q[0]): Connection handler 0x20010e94 removed
[00:00:38.835,571] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x200109f8, pkt=(nil), st=-104, user_data=(nil)
[00:00:38.835,601] <dbg> net_sock: zsock_received_cb: (rx_q[0]): Marked socket 0x200109f8 as peer-closed
[00:00:38.835,968] <dbg> net_sock: zsock_recv_stream: (main): NULL return from fifo
[00:00:38.836,029] <dbg> net_sock: z_impl_zsock_close: (main): close: ctx=0x200109f8, fd=0
[00:00:38.836,059] <dbg> net_tcp: net_tcp_recv: (main): context: 0x200109f8, cb: (nil), user_data: (nil)
[00:00:38.836,090] <dbg> net_tcp: net_tcp_unref: (main): context: 0x200109f8, conn: (nil)
[00:00:38.836,120] <dbg> net_ctx: net_context_unref: (main): Context 0x200109f8 released
[00:00:38.892,333] <dbg> main: main: Error sending rpc request: The request could not be send!
[00:00:38.894,378] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20030518 src port 80 dst port 64372 family 2
[00:00:38.894,409] <dbg> net_conn: net_conn_input: (rx_q[0]): No match found.
[00:00:52.692,260] <inf> net_l2_openthread: State changed! Flags: 0x00000064 Current role: router

Could you tell me how it looks. Where is the problem. 

New log with TLS Socket:

[00:01:08.330,535] <dbg> net_conn: conn_register_debug: (main):   local ::/65362 cb 0x17ffd ud 0x2001396c
[00:01:08.330,657] <dbg> net_tcp: tcp_in: (main):  [LISTEN Seq=3585118676 Ack=0]
[00:01:08.330,932] <dbg> net_tcp: tcp_out_ext: (main): SYN Seq=3585118676 Len=0
[00:01:08.331,085] <dbg> net_tcp: tcp_send_process_no_lock: (main): SYN Seq=3585118676 Len=0 
[00:01:08.331,298] <dbg> net_tcp: tcp_send: (main): SYN Seq=3585118676 Len=0
[00:01:08.331,420] <dbg> net_tcp: tcp_in: (main): LISTEN->SYN_SENT
[00:01:08.333,770] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x200333c0 src port 443 dst port 63379 family 2
[00:01:08.333,831] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x20013be4] match found cb 0x17ffd ud 0x2001382c rank 0x3f
[00:01:08.334,106] <dbg> net_tcp: tcp_in: (rx_q[0]): RST Seq=1183333143 Len=0 [ESTABLISHED Seq=62085212 Ack=1183333143]
[00:01:08.334,167] <dbg> net_tcp: tcp_in: (rx_q[0]): ESTABLISHED->CLOSED
[00:01:08.334,228] <dbg> net_tcp: tcp_conn_unref_debug: (rx_q[0]): conn: 0x20033d70, ref_count=1 (tcp_in():2513)
[00:01:08.334,259] <dbg> net_conn: net_conn_unregister: (rx_q[0]): Connection handler 0x20013be4 removed
[00:01:08.334,289] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x2001382c, pkt=(nil), st=-104, user_data=(nil)
[00:01:08.334,320] <dbg> net_sock: zsock_received_cb: (rx_q[0]): Marked socket 0x2001382c as peer-closed
[00:01:08.430,603] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x200333c0 src port 443 dst port 58403 family 2
[00:01:08.430,664] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x20013c28] match found cb 0x17ffd ud 0x200138cc rank 0x3f
[00:01:08.430,969] <dbg> net_tcp: tcp_in: (rx_q[0]): RST Seq=2457617469 Len=0 [ESTABLISHED Seq=254582845 Ack=2457617469]
[00:01:08.430,999] <dbg> net_tcp: tcp_in: (rx_q[0]): ESTABLISHED->CLOSED
[00:01:08.431,060] <dbg> net_tcp: tcp_conn_unref_debug: (rx_q[0]): conn: 0x20033fa8, ref_count=1 (tcp_in():2513)
[00:01:08.431,091] <dbg> net_conn: net_conn_unregister: (rx_q[0]): Connection handler 0x20013c28 removed
[00:01:08.431,152] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x200138cc, pkt=(nil), st=-104, user_data=(nil)
[00:01:08.431,182] <dbg> net_sock: zsock_received_cb: (rx_q[0]): Marked socket 0x200138cc as peer-closed
[00:01:08.436,981] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x200333c0 src port 443 dst port 65362 family 2
[00:01:08.437,011] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x20013ba0] match found cb 0x17ffd ud 0x2001396c rank 0x3f
[00:01:08.437,347] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN,ACK Seq=1830652639 Ack=3585118677 Len=0 [SYN_SENT Seq=3585118677 Ack=0]
[00:01:08.437,408] <dbg> net_tcp: tcp_options_check: (rx_q[0]): len=4
[00:01:08.437,438] <dbg> net_tcp: tcp_options_check: (rx_q[0]): opt: 2, opt_len: 4
[00:01:08.437,438] <dbg> net_tcp: tcp_options_check: (rx_q[0]): MSS=1460
[00:01:08.437,469] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64240 to 1280
[00:01:08.437,500] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x20033b38 window_full=0
[00:01:08.437,683] <dbg> net_tcp: tcp_send_timer_cancel: (rx_q[0]): SYN Seq=3585118676 Len=0
[00:01:08.437,988] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=3585118677 Ack=1830652640 Len=0
[00:01:08.438,171] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=3585118677 Ack=1830652640 Len=0 
[00:01:08.438,385] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=3585118677 Ack=1830652640 Len=0
[00:01:08.438,476] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN_SENT->ESTABLISHED
[00:01:08.438,720] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20033b38, ret=0
[00:01:08.438,751] <dbg> net_tcp: net_tcp_recv: (main): context: 0x2001396c, cb: 0x9d55, user_data: (nil)
[00:01:08.438,812] <err> http_client: Cannot connect to IPv6 remote (-2)
[00:01:08.438,842] <err> http_client: Failed to connect to socket
[00:01:08.438,842] <dbg> http_client: run_https_post: starting tcp failed
[00:01:08.522,583] <dbg> http_client: setup_socket: Setup socket info: Server address: fd97:6739:93e:2:0:0:A756:5EF8
[00:01:08.522,613] <err> http_client: Failed to create IPv6 HTTP socket (-23)
[00:01:08.522,644] <err> http_client: Setup socket Failed
[00:01:08.522,644] <err> http_client: Failed to connect to socket
[00:01:08.522,674] <dbg> http_client: run_https_post: starting tcp failed
[00:01:08.605,682] <dbg> http_client: setup_socket: Setup socket info: Server address: fd97:6739:93e:2:0:0:A756:5EF8
[00:01:08.605,712] <err> http_client: Failed to create IPv6 HTTP socket (-23)
[00:01:08.605,743] <err> http_client: Setup socket Failed
[00:01:08.605,743] <err> http_client: Failed to connect to socket
[00:01:08.605,773] <dbg> http_client: run_https_post: starting tcp failed
[00:01:08.688,690] <dbg> http_client: setup_socket: Setup socket info: Server address: fd97:6739:93e:2:0:0:A756:5EF8
[00:01:08.688,751] <err> http_client: Failed to create IPv6 HTTP socket (-23)
[00:01:08.688,751] <err> http_client: Setup socket Failed
[00:01:08.688,751] <err> http_client: Failed to connect to socket
[00:01:08.688,781] <dbg> http_client: run_https_post: starting tcp failed
[00:01:08.744,964] <dbg> main: main: Error sending rpc request: The request could not be send!
[00:01:08.828,796] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x200333c0 src port 443 dst port 65362 family 2
[00:01:08.828,826] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x20013ba0] match found cb 0x17ffd ud 0x2001396c rank 0x3f
[00:01:08.829,132] <dbg> net_tcp: tcp_in: (rx_q[0]): RST Seq=1830652640 Len=0 [ESTABLISHED Seq=3585118677 Ack=1830652640]
[00:01:08.829,162] <dbg> net_tcp: tcp_in: (rx_q[0]): ESTABLISHED->CLOSED
[00:01:08.829,223] <dbg> net_tcp: tcp_conn_unref_debug: (rx_q[0]): conn: 0x20033b38, ref_count=1 (tcp_in():2513)
[00:01:08.829,254] <dbg> net_conn: net_conn_unregister: (rx_q[0]): Connection handler 0x20013ba0 removed
[00:01:08.829,315] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x2001396c, pkt=(nil), st=-104, user_data=(nil)
[00:01:08.829,345] <dbg> net_sock: zsock_received_cb: (rx_q[0]): Marked socket 0x2001396c as peer-closed
[00:01:17.318,511] <inf> net_l2_openthread: State changed! Flags: 0x00000064 Current role: router

Here I see socket setup is getting failed. Could you tell me what is happening here.

Regards

Vipin Das

[vipin das]

Hi Marte,

Any update on the issue. 

Regards

Vipin Das

[Marte Myrvold]

Hi,

There are some problems with setting up the socket. First it fails to connect to IPv6 remote due to the socket not existing, but afterwards you are unable to open sockets because there are too many open sockets. Can you share the code where you connect and open the socket? Is it similar to connect_socket() and setup_socket() in http_client?

Best regards,

Marte

[vipin das]

Hi Marte,

Thanks. It is very much similar as in the http_client. 

connect_socket:

static int connect_socket(sa_family_t family, const char* server, int port,
                          int* sock, struct sockaddr* addr, socklen_t addr_len) {
  int ret;

  ret = setup_socket(family, server, port, sock, addr, addr_len);
  if (ret < 0 || *sock < 0) {
    LOG_ERR("Setup socket Failed");
    return -1;
  }

  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;
  }
  return ret;
}

setup_socket:

static int setup_socket(sa_family_t family, const char* server, int port, int* sock, struct sockaddr* addr, socklen_t addr_len) {
  const char* family_str = family == AF_INET ? "IPv4" : "IPv6";
  int         ret        = 0;

  memset(addr, 0, addr_len);

  if (family == AF_INET) {
    net_sin(addr)->sin_family = AF_INET;
    net_sin(addr)->sin_port   = htons(port);
    inet_pton(family, server, &net_sin(addr)->sin_addr);
  }
  else {
    net_sin6(addr)->sin6_family = AF_INET6;
    net_sin6(addr)->sin6_port   = htons(port);
    inet_pton(AF_INET6, server, &net_sin6(addr)->sin6_addr);
    LOG_DBG("Setup socket info: Server address: %s", server);
  }

#if defined(CONFIG_NET_SOCKETS_SOCKOPT_TLS)
  sec_tag_t sec_tag_list[] = {CA_CERTIFICATE_TAG};

  *sock = socket(family, SOCK_STREAM, IPPROTO_TLS_1_2);
  if (*sock >= 0) {
    ret = setsockopt(*sock, SOL_TLS, TLS_SEC_TAG_LIST, sec_tag_list, sizeof(sec_tag_list));
    if (ret < 0) {
      LOG_ERR("Failed to set %s secure option (%d)", family_str, -errno);
      ret = -errno;
    }

    ret = setsockopt(*sock, SOL_TLS, TLS_HOSTNAME, TLS_PEER_HOSTNAME, sizeof(TLS_PEER_HOSTNAME));
    if (ret < 0) {
      LOG_ERR("Failed to set %s TLS_HOSTNAME "
              "option (%d)",
              family_str, -errno);
      ret = -errno;
    }
  }
#else
  *sock    = socket(family, SOCK_STREAM, IPPROTO_TCP);
#endif

  if (*sock < 0) {
    LOG_ERR("Failed to create %s HTTP socket (%d)", family_str, -errno);
  }
  return ret;
}

Initially I wanted to see I am able to connect to TCP socket later I I will try to make TLS work. So please take a look at below given logs: 

1st:

[00:00:00.308,074] <inf> ieee802154_nrf5: nRF5 802154 radio initialized
[00:00:00.308,441] <dbg> net_tcp: net_tcp_init: (main): Workq started. Thread ID: 0x20005428
[00:00:00.322,723] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.322,723] <inf> fs_nvs: alloc wra: 0, f48
[00:00:00.322,753] <inf> fs_nvs: data wra: 0, 1f4
[00:00:00.331,420] <inf> net_l2_openthread: State changed! Flags: 0x1007c300 Current role: disabled
[00:00:00.335,784] <inf> net_config: Initializing network
[00:00:00.335,784] <inf> net_config: Waiting interface 1 (0x20000ab0) to be up...
[00:00:30.336,486] <err> net_config: Timeout while waiting network interface
[00:00:30.336,517] <err> net_config: Network initialization failed (-115)
[00:00:30.336,944] <inf> in3_ot: Waiting for host to be ready to communicate
[00:00:30.341,064] <inf> usb_cdc_acm: Device suspended
[00:00:30.538,879] <inf> usb_cdc_acm: Device resumed
[00:00:30.655,090] <inf> usb_cdc_acm: Device suspended
[00:00:30.884,216] <inf> usb_cdc_acm: Device resumed
[00:00:30.943,786] <inf> usb_cdc_acm: Device configured
[00:00:41.255,187] <inf> net_l2_openthread: State changed! Flags: 0x10000000 Current role: disabled
[00:00:41.255,920] <inf> net_l2_openthread: State changed! Flags: 0x10000000 Current role: disabled
[00:00:41.257,019] <inf> net_l2_openthread: State changed! Flags: 0x00001000 Current role: disabled
[00:00:41.257,324] <inf> net_l2_openthread: State changed! Flags: 0x00000001 Current role: disabled
[00:00:41.257,507] <inf> net_l2_openthread: State changed! Flags: 0x00000008 Current role: disabled
[00:00:41.257,629] <inf> net_l2_openthread: State changed! Flags: 0x01000000 Current role: disabled
[00:00:41.257,751] <inf> net_l2_openthread: State changed! Flags: 0x00000004 Current role: detached
[00:00:41.257,904] <inf> net_l2_openthread: State changed! Flags: 0x00000001 Current role: detached
[00:00:41.258,148] <inf> net_l2_openthread: State changed! Flags: 0x00001000 Current role: detached
[00:00:41.258,392] <inf> net_l2_openthread: State changed! Flags: 0x00001000 Current role: detached
[00:00:41.258,636] <inf> net_l2_openthread: State changed! Flags: 0x00000010 Current role: detached
[00:00:41.259,002] <inf> net_l2_openthread: State changed! Flags: 0x00000020 Current role: detached
[00:00:41.490,570] <inf> net_l2_openthread: State changed! Flags: 0x00001084 Current role: router
[00:00:41.491,485] <dbg> in3_ot: sendOpenThreadPing: Ping Server:
[00:00:41.491,516] <dbg> in3_ot: printIpv6Address: Mesh Local EID Address: fd97.6739.093e.0002.0000.0000.a756.5ef8
[00:00:41.491,851] <dbg> in3_ot: sendOpenThreadPing: ping send response:0
[00:00:41.492,065] <dbg> http_client: in3_register_https_client: in3 register https
[00:00:41.524,871] <dbg> http_client: setup_socket: Setup socket info: Server address: fd97:6739:93e:2:0:0:A756:5EF8
[00:00:41.525,085] <dbg> net_tcp: tcp_conn_ref: (main): conn: 0x20031098, ref_count: 1
[00:00:41.525,115] <dbg> net_tcp: tcp_conn_alloc: (main): conn: 0x20031098
[00:00:41.525,146] <dbg> net_sock: zsock_socket_internal: (main): socket: ctx=0x200109f8, fd=0
[00:00:41.525,268] <dbg> net_ctx: net_context_bind: (main): Context 0x200109f8 binding to TCP [::]:37464 iface 1 (0x20000ab0)
[00:00:41.525,360] <dbg> net_tcp: net_tcp_connect: (main): context: 0x200109f8, local: ::, remote: fd97:6739:93e:2::a756:5ef8
[00:00:41.525,512] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20031098 src: ::, dst: fd97:6739:93e:2::a756:5ef8
[00:00:41.525,634] <dbg> net_conn: conn_register_debug: (main): [0x20010e94/6/2/0x3f] remote fd97:6739:93e:2::a756:5ef8/80 
[00:00:41.525,665] <dbg> net_conn: conn_register_debug: (main):   local ::/37464 cb 0x16f05 ud 0x200109f8
[00:00:41.525,787] <dbg> net_tcp: tcp_in: (main):  [LISTEN Seq=1506709185 Ack=0]
[00:00:41.526,062] <dbg> net_tcp: tcp_out_ext: (main): SYN Seq=1506709185 Len=0
[00:00:41.526,245] <dbg> net_tcp: tcp_send_process_no_lock: (main): SYN Seq=1506709185 Len=0 
[00:00:41.526,458] <dbg> net_tcp: tcp_send: (main): SYN Seq=1506709185 Len=0
[00:00:41.526,824] <dbg> net_tcp: tcp_in: (main): LISTEN->SYN_SENT
[00:00:41.551,513] <inf> net_l2_openthread: State changed! Flags: 0x00000200 Current role: router
[00:00:41.551,574] <inf> net_l2_openthread: State changed! Flags: 0x00000001 Current role: router
[00:00:41.742,004] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): SYN Seq=1506709185 Len=0 in_retransmission
[00:00:41.742,218] <dbg> net_tcp: tcp_send: (tcp_work): SYN Seq=1506709185 Len=0
[00:00:41.957,550] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): SYN Seq=1506709185 Len=0 in_retransmission
[00:00:41.957,763] <dbg> net_tcp: tcp_send: (tcp_work): SYN Seq=1506709185 Len=0
[00:00:42.173,095] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): SYN Seq=1506709185 Len=0 in_retransmission
[00:00:42.173,309] <dbg> net_tcp: tcp_send: (tcp_work): SYN Seq=1506709185 Len=0
[00:00:42.388,610] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): SYN Seq=1506709185 Len=0 in_retransmission
[00:00:42.388,824] <dbg> net_tcp: tcp_send: (tcp_work): SYN Seq=1506709185 Len=0
[00:00:42.604,156] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): SYN Seq=1506709185 Len=0 in_retransmission
[00:00:42.604,370] <dbg> net_tcp: tcp_send: (tcp_work): SYN Seq=1506709185 Len=0
[00:00:42.819,702] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): SYN Seq=1506709185 Len=0 in_retransmission
[00:00:42.819,946] <dbg> net_tcp: tcp_send: (tcp_work): SYN Seq=1506709185 Len=0
[00:00:43.035,247] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): SYN Seq=1506709185 Len=0 in_retransmission
[00:00:43.035,461] <dbg> net_tcp: tcp_send: (tcp_work): SYN Seq=1506709185 Len=0

2nd:

[00:00:36.100,524] <dbg> net_tcp: tcp_send: (tcp_work): SYN Seq=4280518776 Len=0
[00:00:36.326,812] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): SYN Seq=4280518776 Len=0 in_retransmission
[00:00:36.327,026] <dbg> net_tcp: tcp_send: (tcp_work): SYN Seq=4280518776 Len=0
[00:00:36.553,344] <dbg> net_tcp: tcp_send_process_no_lock: (tcp_work): SYN Seq=4280518776 Len=0 in_retransmission
[00:00:36.553,375] <dbg> net_tcp: tcp_conn_unref_debug: (tcp_work): conn: 0x20031098, ref_count=1 (tcp_send_process():568)
[00:00:36.553,405] <dbg> net_tcp: tcp_conn_unref_debug: (tcp_work): conn: 0x20031098 is waiting on connect semaphore
[00:00:37.288,635] <dbg> net_tcp: tcp_conn_unref_debug: (main): conn: 0x20031098, ref_count=1 (net_tcp_connect():2856)
[00:00:37.288,665] <dbg> net_conn: net_conn_unregister: (main): Connection handler 0x20010e94 removed
[00:00:37.288,787] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20031098, ret=-116
[00:00:37.288,818] <err> http_client: Cannot connect to IPv6 remote (-116)
[00:00:37.288,848] <err> http_client: Failed to connect to socket
[00:00:37.288,848] <dbg> http_client: run_https_post: starting tcp failed
[00:00:37.373,229] <dbg> http_client: setup_socket: Setup socket info: Server address: fd97:6739:93e:2:0:0:A756:5EF8
[00:00:37.373,413] <dbg> net_tcp: tcp_conn_ref: (main): conn: 0x20031098, ref_count: 1
[00:00:37.373,443] <dbg> net_tcp: tcp_conn_alloc: (main): conn: 0x20031098
[00:00:37.373,504] <dbg> net_sock: zsock_socket_internal: (main): socket: ctx=0x20010a98, fd=1
[00:00:37.373,626] <dbg> net_ctx: net_context_bind: (main): Context 0x20010a98 binding to TCP [::]:37159 iface 1 (0x20000ab0)
[00:00:37.373,748] <dbg> net_tcp: net_tcp_connect: (main): context: 0x20010a98, local: ::, remote: fd97:6739:93e:2::a756:5ef8
[00:00:37.373,870] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20031098 src: fd97:6739:93e:1:9356:10a6:172a:4184, dst: fd97:6739:93e:2::a756:5ef8
[00:00:37.373,992] <dbg> net_conn: conn_register_debug: (main): [0x20010e94/6/2/0x3f] remote fd97:6739:93e:2::a756:5ef8/80 
[00:00:37.374,053] <dbg> net_conn: conn_register_debug: (main):   local ::/37159 cb 0x16f05 ud 0x20010a98
[00:00:37.374,176] <dbg> net_tcp: tcp_in: (main):  [LISTEN Seq=326464843 Ack=0]
[00:00:37.374,450] <dbg> net_tcp: tcp_out_ext: (main): SYN Seq=326464843 Len=0
[00:00:37.374,603] <dbg> net_tcp: tcp_send_process_no_lock: (main): SYN Seq=326464843 Len=0 
[00:00:37.374,816] <dbg> net_tcp: tcp_send: (main): SYN Seq=326464843 Len=0
[00:00:37.375,579] <dbg> net_tcp: tcp_in: (main): LISTEN->SYN_SENT
[00:00:37.471,466] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20030448 src port 80 dst port 37159 family 2
[00:00:37.471,496] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x20010e94] match found cb 0x16f05 ud 0x20010a98 rank 0x3f
[00:00:37.471,832] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN,ACK Seq=192238644 Ack=326464844 Len=0 [SYN_SENT Seq=326464844 Ack=0]
[00:00:37.471,862] <dbg> net_tcp: tcp_options_check: (rx_q[0]): len=4
[00:00:37.471,893] <dbg> net_tcp: tcp_options_check: (rx_q[0]): opt: 2, opt_len: 4
[00:00:37.471,923] <dbg> net_tcp: tcp_options_check: (rx_q[0]): MSS=1460
[00:00:37.471,954] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64240 to 1280
[00:00:37.471,984] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x20031098 window_full=0
[00:00:37.472,137] <dbg> net_tcp: tcp_send_timer_cancel: (rx_q[0]): SYN Seq=326464843 Len=0
[00:00:37.472,442] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=326464844 Ack=192238645 Len=0
[00:00:37.472,625] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=326464844 Ack=192238645 Len=0 
[00:00:37.472,808] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=326464844 Ack=192238645 Len=0
[00:00:37.472,900] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN_SENT->ESTABLISHED
[00:00:37.473,144] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20031098, ret=0
[00:00:37.473,205] <dbg> net_tcp: net_tcp_recv: (main): context: 0x20010a98, cb: 0x9c5d, user_data: (nil)
[00:00:37.473,358] <dbg> net_tcp: net_tcp_recv: (main): context: 0x20010a98, cb: 0x9c5d, user_data: (nil)
[00:00:37.473,510] <dbg> net_tcp: tcp_window_full: (main): conn: 0x20031098 window_full=0
[00:00:37.473,541] <dbg> net_tcp: net_tcp_queue_data: (main): conn: 0x20031098 Queued 75 bytes (total 75)
[00:00:37.473,571] <dbg> net_tcp: tcp_unsent_len: (main): unsent_len=75

3rd:

[00:01:09.119,964] <dbg> net_tcp: tcp_out_ext: (main): SYN Seq=2522094062 Len=0
[00:01:09.120,117] <dbg> net_tcp: tcp_send_process_no_lock: (main): SYN Seq=2522094062 Len=0 
[00:01:09.120,330] <dbg> net_tcp: tcp_send: (main): SYN Seq=2522094062 Len=0
[00:01:09.121,093] <dbg> net_tcp: tcp_in: (main): LISTEN->SYN_SENT
[00:01:09.172,637] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20030448 src port 80 dst port 65078 family 2
[00:01:09.172,668] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x20010e94] match found cb 0x16f05 ud 0x20010a98 rank 0x3f
[00:01:09.173,004] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN,ACK Seq=3955719044 Ack=2522094063 Len=0 [SYN_SENT Seq=2522094063 Ack=0]
[00:01:09.173,034] <dbg> net_tcp: tcp_options_check: (rx_q[0]): len=4
[00:01:09.173,065] <dbg> net_tcp: tcp_options_check: (rx_q[0]): opt: 2, opt_len: 4
[00:01:09.173,095] <dbg> net_tcp: tcp_options_check: (rx_q[0]): MSS=1460
[00:01:09.173,126] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64240 to 1280
[00:01:09.173,156] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x20031098 window_full=0
[00:01:09.173,339] <dbg> net_tcp: tcp_send_timer_cancel: (rx_q[0]): SYN Seq=2522094062 Len=0
--- 21 messages dropped ---
[00:01:09.173,614] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=2522094063 Ack=3955719045 Len=0
[00:01:09.173,828] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=2522094063 Ack=3955719045 Len=0 
[00:01:09.174,011] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=2522094063 Ack=3955719045 Len=0
--- 27 messages dropped ---
[00:01:09.174,133] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN_SENT->ESTABLISHED
[00:01:09.174,346] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20031098, ret=0
[00:01:09.248,168] <dbg> net_tcp: tcp_in: (rx_q[0]): ESTABLISHED->CLOSED
[00:01:09.248,229] <dbg> net_tcp: tcp_conn_unref_debug: (rx_q[0]): conn: 0x20031098, ref_count=1 (tcp_in():2513)
[00:01:09.248,260] <dbg> net_conn: net_conn_unregister: (rx_q[0]): Connection handler 0x20010e94 removed
[00:01:09.248,291] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x20010a98, pkt=(nil), st=-104, user_data=(nil)
[00:01:09.409,240] <dbg> net_tcp: tcp_options_check: (rx_q[0]): MSS=1460
--- 31 messages dropped ---
[00:01:09.409,271] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64240 to 1280
[00:01:09.409,301] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x20031098 window_full=0
[00:01:09.409,484] <dbg> net_tcp: tcp_send_timer_cancel: (rx_q[0]): SYN Seq=2790064174 Len=0
[00:01:09.409,759] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=2790064175 Ack=1960114298 Len=0
--- 12 messages dropped ---
[00:01:09.491,424] <dbg> net_sock: z_impl_zsock_close: (main): close: ctx=0x20010a98, fd=1
[00:01:09.491,455] <dbg> net_tcp: net_tcp_recv: (main): context: 0x20010a98, cb: (nil), user_data: (nil)
[00:01:09.491,516] <dbg> net_tcp: net_tcp_unref: (main): context: 0x20010a98, conn: (nil)
[00:01:09.491,546] <dbg> net_ctx: net_context_unref: (main): Context 0x20010a98 released
[00:01:09.576,385] <dbg> net_tcp: tcp_send: (main): SYN Seq=1024053545 Len=0
[00:01:09.576,507] <dbg> net_tcp: tcp_in: (main): LISTEN->SYN_SENT
[00:01:09.579,071] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20030518 src port 80 dst port 65485 family 2
[00:01:09.579,101] <dbg> net_conn: net_conn_input: (rx_q[0]): No match found.
[00:01:09.647,186] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20030518 src port 80 dst port 51242 family 2
[00:01:09.647,216] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x20010e94] match found cb 0x16f05 ud 0x20010a98 rank 0x3f
[00:01:09.647,552] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN,ACK Seq=901099195 Ack=1024053546 Len=0 [SYN_SENT Seq=1024053546 Ack=0]
[00:01:09.647,583] <dbg> net_tcp: tcp_options_check: (rx_q[0]): len=4
[00:01:09.647,613] <dbg> net_tcp: tcp_options_check: (rx_q[0]): opt: 2, opt_len: 4
[00:01:09.647,644] <dbg> net_tcp: tcp_options_check: (rx_q[0]): MSS=1460
[00:01:09.647,674] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64240 to 1280
[00:01:09.647,705] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x20031098 window_full=0
[00:01:09.647,857] <dbg> net_tcp: tcp_send_timer_cancel: (rx_q[0]): SYN Seq=1024053545 Len=0
[00:01:09.648,162] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=1024053546 Ack=901099196 Len=0
[00:01:09.648,376] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=1024053546 Ack=901099196 Len=0 
[00:01:09.648,559] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=1024053546 Ack=901099196 Len=0
[00:01:09.648,651] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN_SENT->ESTABLISHED
[00:01:09.648,864] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20031098, ret=0
[00:01:09.648,925] <dbg> net_tcp: net_tcp_recv: (main): context: 0x20010a98, cb: 0x9c5d, user_data: (nil)
[00:01:09.649,078] <dbg> net_tcp: net_tcp_recv: (main): context: 0x20010a98, cb: 0x9c5d, user_data: (nil)
[00:01:09.649,230] <dbg> net_tcp: tcp_window_full: (main): conn: 0x20031098 window_full=0
[00:01:09.649,261] <dbg> net_tcp: net_tcp_queue_data: (main): conn: 0x20031098 Queued 75 bytes (total 75)
[00:01:09.649,261] <dbg> net_tcp: tcp_unsent_len: (main): unsent_len=75
[00:01:09.649,658] <dbg> net_tcp: tcp_out_ext: (main): ACK,PSH Seq=1024053546 Ack=901099196 Len=75
[00:01:09.649,841] <dbg> net_tcp: tcp_send_process_no_lock: (main): ACK,PSH Seq=1024053546 Ack=901099196 Len=75 
[00:01:09.650,054] <dbg> net_tcp: tcp_send: (main): ACK,PSH Seq=1024053546 Ack=901099196 Len=75
[00:01:09.650,146] <dbg> net_tcp: tcp_send_data: (main): conn: 0x20031098 total=75, unacked_len=75, send_win=1280, mss=1280
[00:01:09.650,177] <dbg> net_tcp: tcp_send_data: (main): conn: 0x20031098 send_data_timer=0, send_data_retries=0
[00:01:09.650,207] <dbg> net_tcp: tcp_unsent_len: (main): unsent_len=0
[00:01:09.650,268] <dbg> net_tcp: tcp_window_full: (main): conn: 0x20031098 window_full=0

4th

[00:03:33.441,802] <dbg> net_tcp: tcp_conn_ref: (main): conn: 0x20031098, ref_count: 1
[00:03:33.441,833] <dbg> net_tcp: tcp_conn_alloc: (main): conn: 0x20031098
[00:03:33.441,894] <dbg> net_sock: zsock_socket_internal: (main): socket: ctx=0x200109f8, fd=0
[00:03:33.442,016] <dbg> net_ctx: net_context_bind: (main): Context 0x200109f8 binding to TCP [::]:59799 iface 1 (0x20000ab0)
[00:03:33.442,138] <dbg> net_tcp: net_tcp_connect: (main): context: 0x200109f8, local: ::, remote: fd97:6739:93e:2::a756:5ef8
[00:03:33.442,260] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20031098 src: fd97:6739:93e:1:9356:10a6:172a:4184, dst: fd97:6739:93e:2::a756:5ef8
[00:03:33.442,413] <dbg> net_conn: conn_register_debug: (main): [0x20010e94/6/2/0x3f] remote fd97:6739:93e:2::a756:5ef8/80 
[00:03:33.442,443] <dbg> net_conn: conn_register_debug: (main):   local ::/59799 cb 0x16f05 ud 0x200109f8
[00:03:33.442,596] <dbg> net_tcp: tcp_in: (main):  [LISTEN Seq=3852373274 Ack=0]
[00:03:33.442,871] <dbg> net_tcp: tcp_out_ext: (main): SYN Seq=3852373274 Len=0
[00:03:33.443,023] <dbg> net_tcp: tcp_send_process_no_lock: (main): SYN Seq=3852373274 Len=0 
[00:03:33.443,267] <dbg> net_tcp: tcp_send: (main): SYN Seq=3852373274 Len=0
[00:03:33.443,389] <dbg> net_tcp: tcp_in: (main): LISTEN->SYN_SENT
[00:03:33.445,404] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20030448 src port 80 dst port 51731 family 2
[00:03:33.445,434] <dbg> net_conn: net_conn_input: (rx_q[0]): No match found.
[00:03:33.556,335] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20030448 src port 80 dst port 59799 family 2
[00:03:33.556,365] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x20010e94] match found cb 0x16f05 ud 0x200109f8 rank 0x3f
[00:03:33.556,732] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN,ACK Seq=1071215906 Ack=3852373275 Len=0 [SYN_SENT Seq=3852373275 Ack=0]
[00:03:33.556,762] <dbg> net_tcp: tcp_options_check: (rx_q[0]): len=4
[00:03:33.556,793] <dbg> net_tcp: tcp_options_check: (rx_q[0]): opt: 2, opt_len: 4
[00:03:33.556,823] <dbg> net_tcp: tcp_options_check: (rx_q[0]): MSS=1460
[00:03:33.556,854] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64240 to 1280
[00:03:33.556,884] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x20031098 window_full=0
[00:03:33.557,067] <dbg> net_tcp: tcp_send_timer_cancel: (rx_q[0]): SYN Seq=3852373274 Len=0
[00:03:33.557,342] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=3852373275 Ack=1071215907 Len=0
[00:03:33.557,556] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=3852373275 Ack=1071215907 Len=0 
[00:03:33.557,769] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=3852373275 Ack=1071215907 Len=0
[00:03:33.557,861] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN_SENT->ESTABLISHED
[00:03:33.558,105] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20031098, ret=0
[00:03:33.558,166] <dbg> net_tcp: net_tcp_recv: (main): context: 0x200109f8, cb: 0x9c5d, user_data: (nil)
[00:03:33.558,319] <dbg> net_tcp: net_tcp_recv: (main): context: 0x200109f8, cb: 0x9c5d, user_data: (nil)
[00:03:33.558,441] <dbg> net_tcp: tcp_window_full: (main): conn: 0x20031098 window_full=0
[00:03:33.558,471] <dbg> net_tcp: net_tcp_queue_data: (main): conn: 0x20031098 Queued 75 bytes (total 75)
[00:03:33.558,502] <dbg> net_tcp: tcp_unsent_len: (main): unsent_len=75
[00:03:33.558,898] <dbg> net_tcp: tcp_out_ext: (main): ACK,PSH Seq=3852373275 Ack=1071215907 Len=75
[00:03:33.559,112] <dbg> net_tcp: tcp_send_process_no_lock: (main): ACK,PSH Seq=3852373275 Ack=1071215907 Len=75 
[00:03:33.559,326] <dbg> net_tcp: tcp_send: (main): ACK,PSH Seq=3852373275 Ack=1071215907 Len=75
[00:03:33.559,417] <dbg> net_tcp: tcp_send_data: (main): conn: 0x20031098 total=75, unacked_len=75, send_win=1280, mss=1280
[00:03:33.559,448] <dbg> net_tcp: tcp_send_data: (main): conn: 0x20031098 send_data_timer=0, send_data_retries=0
[00:03:33.559,478] <dbg> net_tcp: tcp_unsent_len: (main): unsent_len=0
[00:03:33.559,539] <dbg> net_tcp: tcp_window_full: (main): conn: 0x20031098 window_full=0
[00:03:33.559,631] <dbg> net_tcp: net_tcp_recv: (main): context: 0x200109f8, cb: 0x9c5d, user_data: (nil)
[00:03:33.559,753] <dbg> net_tcp: tcp_window_full: (main): conn: 0x20031098 window_full=0
[00:03:33.559,783] <dbg> net_tcp: net_tcp_queue_data: (main): conn: 0x20031098 Queued 7 bytes (total 82)
[00:03:33.559,814] <dbg> net_tcp: tcp_unsent_len: (main): unsent_len=7
[00:03:33.559,844] <dbg> net_tcp: tcp_unsent_len: (main): unsent_len=7
[00:03:33.559,906] <dbg> net_tcp: tcp_window_full: (main): conn: 0x20031098 window_full=0
[00:03:33.636,505] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20030448 src port 80 dst port 59799 family 2
[00:03:33.636,535] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x20010e94] match found cb 0x16f05 ud 0x200109f8 rank 0x3f
[00:03:33.636,871] <dbg> net_tcp: tcp_in: (rx_q[0]): RST Seq=1071215907 Len=0 [ESTABLISHED Seq=3852373275 Ack=1071215907]
[00:03:33.636,901] <dbg> net_tcp: tcp_in: (rx_q[0]): ESTABLISHED->CLOSED
[00:03:33.636,962] <dbg> net_tcp: tcp_conn_unref_debug: (rx_q[0]): conn: 0x20031098, ref_count=1 (tcp_in():2513)
[00:03:33.637,023] <dbg> net_conn: net_conn_unregister: (rx_q[0]): Connection handler 0x20010e94 removed
[00:03:33.637,054] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x200109f8, pkt=(nil), st=-104, user_data=(nil)
[00:03:33.637,084] <dbg> net_sock: zsock_received_cb: (rx_q[0]): Marked socket 0x200109f8 as peer-closed
[00:03:33.637,420] <dbg> net_sock: zsock_recv_stream: (main): NULL return from fifo
[00:03:33.637,481] <dbg> net_sock: z_impl_zsock_close: (main): close: ctx=0x200109f8, fd=0
[00:03:33.637,512] <dbg> net_tcp: net_tcp_recv: (main): context: 0x200109f8, cb: (nil), user_data: (nil)
[00:03:33.637,573] <dbg> net_tcp: net_tcp_unref: (main): context: 0x200109f8, conn: (nil)
[00:03:33.637,603] <dbg> net_ctx: net_context_unref: (main): Context 0x200109f8 released
[00:03:33.694,519] <dbg> main: main: Error sending rpc request: The request could not be send!
[00:03:33.696,563] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x200304b0 src port 80 dst port 59799 family 2
[00:03:33.696,624] <dbg> net_conn: net_conn_input: (rx_q[0]): No match found.
[00:03:44.043,151] <inf> net_l2_openthread: State changed! Flags: 0x00000064 Current role: router

I have shared almost complete log from one power cycle. From the above given logs, I noticed two err things which I didn't understand well why? 

1:

[00:00:30.336,486] <err> net_config: Timeout while waiting network interface
[00:00:30.336,517] <err> net_config: Network initialization failed (-115)

2:

:00:37.288,787] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20031098, ret=-116
[00:00:37.288,818] <err> http_client: Cannot connect to IPv6 remote (-116)
[00:00:37.288,848] <err> http_client: Failed to connect to socket

What it means with error code -116: Stale NFS file handle? 

Regards

Vipin Das 

[vipin das]

Hi Marte,

Sorry to ask on this issue again as I am really blocked because of this. I know you are also busy with lot of other issues. 

I am ready to try any suggestions you make to resolve this. Do you think " net_config: Network initialisation failed (-115)" has anything to do with this error " Cannot connect to IPv6 remote (-116)".

Regards

Vipin Das