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,

Can you share the code where you are sending the packet?

Did you set CONFIG_OPENTHREAD_TCP_ENABLE=y in prj.conf?

Best regards,

Marte

[vipin das]

Hi Marte,

Yes I set the CONFIG_OPENTHREAD_TCP_ENABLE=y in my pro.conf. 

My pro.conf:

# Network shell
CONFIG_NET_SHELL=y
CONFIG_SHELL=y
CONFIG_SHELL_ARGC_MAX=26
CONFIG_SHELL_CMD_BUFF_SIZE=416

CONFIG_ASSERT=y
CONFIG_ASSERT_NO_COND_INFO=y
CONFIG_MBEDTLS_SHA1_C=n

# Default PRNG entropy for nRF53 Series devices is CSPRNG CC312
# which for that purpose is too slow yet
# Use Xoroshiro128+ as PRNG
CONFIG_XOROSHIRO_RANDOM_GENERATOR=y

# Logging
CONFIG_NET_LOG=y
CONFIG_NET_STATISTICS=y
CONFIG_PRINTK=y
CONFIG_CONSOLE=y
CONFIG_LOG=y
CONFIG_LOG_BACKEND_UART=y
CONFIG_LOG_BUFFER_SIZE=15360

# Enable the frame encryption feature in the radio driver, it's required for proper working
# OPENTHREAD_CSL_RECEIVER and OPENTHREAD_LINK_METRICS_SUBJECT features
CONFIG_NRF_802154_ENCRYPTION=y

# Generic networking options
CONFIG_NETWORKING=y
CONFIG_NET_IPV6_NBR_CACHE=n
CONFIG_NET_IPV6_MLD=n
CONFIG_NET_IPV6=y
CONFIG_NET_CONFIG_NEED_IPV6=y
CONFIG_NET_IPV4=n
CONFIG_NET_CONFIG_NEED_IPV4=n
CONFIG_NET_CONFIG_SETTINGS=y
CONFIG_NET_TCP=y # Required for SOCKET STREAM
CONFIG_NET_UDP=y # Required for getting UTC time 
CONFIG_NET_TCP_ISN_RFC6528=n
CONFIG_NET_TCP_LOG_LEVEL_DBG=y
CONFIG_NET_MGMT_EVENT_INFO=y
CONFIG_NET_SOCKETS_LOG_LEVEL_DBG=y
CONFIG_NET_CONN_LOG_LEVEL_DBG=y
CONFIG_NET_CONTEXT_LOG_LEVEL_DBG=y
CONFIG_NET_TCP_LOG_LEVEL_DBG=y

# OpenThread TCP
CONFIG_OPENTHREAD_TCP_ENABLE=y
CONFIG_OPENTHREAD_CLI_TCP_ENABLE=y

# HTTP
CONFIG_HTTP_CLIENT=y

# Network sockets
CONFIG_NET_SOCKETS=y
CONFIG_NET_SOCKETS_POSIX_NAMES=y
CONFIG_NET_SOCKETS_POLL_MAX=4

##### OPENTHREAD #####
# Enable OpenThread features set
CONFIG_OPENTHREAD_NORDIC_LIBRARY_FTD=y
CONFIG_NET_L2_OPENTHREAD=y
CONFIG_OPENTHREAD_THREAD_STACK_SIZE=10240
CONFIG_OPENTHREAD_DEBUG=y
CONFIG_OPENTHREAD_L2_DEBUG=y
CONFIG_OPENTHREAD_MANUAL_START=y
CONFIG_OPENTHREAD_THREAD_VERSION_1_2=y
CONFIG_FPU=y

# Select OpenThread nRF Security backends
CONFIG_CUSTOM_OPENTHREAD_SECURITY=y

# Enable Thread 1.2 features
CONFIG_OPENTHREAD_DUA=y
CONFIG_OPENTHREAD_MLR=y
CONFIG_OPENTHREAD_LINK_METRICS_INITIATOR=y
CONFIG_OPENTHREAD_LINK_METRICS_SUBJECT=y
CONFIG_OPENTHREAD_CSL_RECEIVER=y

# Local IPV4/IPV6 address config
CONFIG_NET_CONFIG_MY_IPV4_ADDR="192.168.0.162"
CONFIG_NET_CONFIG_MY_IPV6_ADDR="2001:db8::1"
# Server IPV4/IPV6 address config
CONFIG_NET_CONFIG_PEER_IPV4_ADDR="167.86.94.248"
CONFIG_NET_CONFIG_PEER_IPV6_ADDR="fd97:6739:93e:2:0:0:A756:5EF8"
#CONFIG_NET_CONFIG_PEER_IPV4_ADDR="46.4.105.116"
#CONFIG_NET_CONFIG_PEER_IPV6_ADDR="fd97:6739:93e:2:0:0:2E04:6974"

#Socket settings
CONFIG_NET_SOCKETS_SOCKOPT_TLS=y
CONFIG_NET_SOCKETS_ENABLE_DTLS=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_SSL_PROTO_DTLS=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

CONFIG_NET_CONNECTION_MANAGER=y

As I mentioned above, I have tried using echo_client sample as well as http_client sample. 

code snippet from http_client:

static int send_https_post(char* msg, int len) {
  struct sockaddr_in6 addr6;
  int                 sock6   = -1;
  int32_t             timeout = 3 * MSEC_PER_SEC;
  int                 ret     = 0;
  int                 port    = HTTP_PORT;

#if defined(CONFIG_NET_SOCKETS_SOCKOPT_TLS)
  ret = tls_credential_add(CA_CERTIFICATE_TAG, TLS_CREDENTIAL_CA_CERTIFICATE, ca_certificate, sizeof(ca_certificate));
  if (ret < 0) {
    LOG_ERR("Failed to register public certificate: %d", ret);
    return ret;
  }
  port = HTTPS_PORT;
#endif

  if (IS_ENABLED(CONFIG_NET_IPV6)) {
    ret = connect_socket(AF_INET6, SERVER_ADDR6, port, &sock6, (struct sockaddr*) &addr6, sizeof(addr6));
    if (ret < 0) {
      LOG_ERR("Failed to connect to socket");
      return ret;
    }
  }

  if (sock6 < 0) {
    LOG_ERR("Cannot create HTTP connection.");
    return -ECONNABORTED;
  }
#if 1
  if (sock6 >= 0 && IS_ENABLED(CONFIG_NET_IPV6)) {
    struct http_request req;
    memset(&req, 0, sizeof(req));
    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");
    close(sock6);
  }
#endif
  return ret;
}

code snippet from echo_client:

static ssize_t sendall(int sock, const void* buf, size_t len) {
  while (len) {
    ssize_t out_len = send(sock, buf, len, 0);

    if (out_len < 0) {
      return out_len;
    }
    buf = (const char*) buf + out_len;
    len -= out_len;
  }
  return 0;
}

static int send_tcp_request(struct netif_info* netif, char* msg, int msg_len) {
  int ret;
  LOG_DBG("send tcp packet");
  do {
    netif->tcp.expecting = sys_rand32_get() % msg_len;
  } while (netif->tcp.expecting == 0U);

  netif->tcp.received = 0U;

  ret = sendall(netif->tcp.sock, msg, netif->tcp.expecting);

  if (ret < 0) {
    LOG_ERR("%s TCP: Failed to send data, errno %d", netif->proto, errno);
  }
  else {
    LOG_DBG("%s TCP: Sent %d bytes", netif->proto, netif->tcp.expecting);
  }

  return ret;
}

Adding few more logs from http client sample: 

1. Log without TLS: 

[00:00:46.867,492] <dbg> net_tcp: tcp_conn_ref: (main): conn: 0x20031098, ref_count: 1
[00:00:46.867,553] <dbg> net_tcp: tcp_conn_alloc: (main): conn: 0x20031098
[00:00:46.867,584] <dbg> net_sock: zsock_socket_internal: (main): socket: ctx=0x200109f8, fd=0
[00:00:46.867,736] <dbg> net_ctx: net_context_bind: (main): Context 0x200109f8 binding to TCP [::]:41102 iface 1 (0x20000ab0)
[00:00:46.867,828] <dbg> net_tcp: net_tcp_connect: (main): context: 0x200109f8, local: ::, remote: fd97:6739:93e:2::a756:5ef8
[00:00:46.867,950] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20031098 src: fd11:22::b348:1bf4:ff33:58ce, dst: fd97:6739:93e:2::a756:5ef8
[00:00:46.868,103] <dbg> net_conn: conn_register_debug: (main): [0x20010e94/6/2/0x3f] remote fd97:6739:93e:2::a756:5ef8/80 
[00:00:46.868,133] <dbg> net_conn: conn_register_debug: (main):   local ::/41102 cb 0x16e91 ud 0x200109f8
[00:00:46.868,286] <dbg> net_tcp: tcp_in: (main):  [LISTEN Seq=1626007064 Ack=0]
[00:00:46.868,530] <dbg> net_tcp: tcp_out_ext: (main): SYN Seq=1626007064 Len=0
[00:00:46.868,713] <dbg> net_tcp: tcp_send_process_no_lock: (main): SYN Seq=1626007064 Len=0 
[00:00:46.868,927] <dbg> net_tcp: tcp_send: (main): SYN Seq=1626007064 Len=0
[00:00:46.869,049] <dbg> net_tcp: tcp_in: (main): LISTEN->SYN_SENT
[00:00:46.871,093] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20030448 src port 80 dst port 34062 family 2
[00:00:46.871,124] <dbg> net_conn: net_conn_input: (rx_q[0]): No match found.
[00:00:46.922,668] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20030448 src port 80 dst port 41102 family 2
[00:00:46.922,729] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x20010e94] match found cb 0x16e91 ud 0x200109f8 rank 0x3f
[00:00:46.923,065] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN,ACK Seq=1973167572 Ack=1626007065 Len=0 [SYN_SENT Seq=1626007065 Ack=0]
[00:00:46.923,095] <dbg> net_tcp: tcp_options_check: (rx_q[0]): len=4
[00:00:46.923,126] <dbg> net_tcp: tcp_options_check: (rx_q[0]): opt: 2, opt_len: 4
[00:00:46.923,156] <dbg> net_tcp: tcp_options_check: (rx_q[0]): MSS=1460
[00:00:46.923,217] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64240 to 1280
[00:00:46.923,248] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x20031098 window_full=0
[00:00:46.923,400] <dbg> net_tcp: tcp_send_timer_cancel: (rx_q[0]): SYN Seq=1626007064 Len=0
[00:00:46.923,706] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=1626007065 Ack=1973167573 Len=0
[00:00:46.923,919] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=1626007065 Ack=1973167573 Len=0 
[00:00:46.924,102] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=1626007065 Ack=1973167573 Len=0
[00:00:46.924,224] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN_SENT->ESTABLISHED
[00:00:46.924,468] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20031098, ret=0
[00:00:46.924,499] <dbg> net_tcp: net_tcp_recv: (main): context: 0x200109f8, cb: 0x9be9, user_data: (nil)
[00:00:46.924,682] <dbg> net_tcp: net_tcp_recv: (main): context: 0x200109f8, cb: 0x9be9, user_data: (nil)
[00:00:46.924,804] <dbg> net_tcp: tcp_window_full: (main): conn: 0x20031098 window_full=0
[00:00:46.924,835] <dbg> net_tcp: net_tcp_queue_data: (main): conn: 0x20031098 Queued 75 bytes (total 75)
[00:00:46.924,865] <dbg> net_tcp: tcp_unsent_len: (main): unsent_len=75
[00:00:46.925,262] <dbg> net_tcp: tcp_out_ext: (main): ACK,PSH Seq=1626007065 Ack=1973167573 Len=75
[00:00:46.925,476] <dbg> net_tcp: tcp_send_process_no_lock: (main): ACK,PSH Seq=1626007065 Ack=1973167573 Len=75 
[00:00:46.925,689] <dbg> net_tcp: tcp_send: (main): ACK,PSH Seq=1626007065 Ack=1973167573 Len=75
[00:00:46.925,781] <dbg> net_tcp: tcp_send_data: (main): conn: 0x20031098 total=75, unacked_len=75, send_win=1280, mss=1280
[00:00:46.925,811] <dbg> net_tcp: tcp_send_data: (main): conn: 0x20031098 send_data_timer=0, send_data_retries=0
[00:00:46.925,842] <dbg> net_tcp: tcp_unsent_len: (main): unsent_len=0
[00:00:46.925,903] <dbg> net_tcp: tcp_window_full: (main): conn: 0x20031098 window_full=0
[00:00:46.925,964] <dbg> net_tcp: net_tcp_recv: (main): context: 0x200109f8, cb: 0x9be9, user_data: (nil)
[00:00:46.926,086] <dbg> net_tcp: tcp_window_full: (main): conn: 0x20031098 window_full=0
[00:00:46.926,116] <dbg> net_tcp: net_tcp_queue_data: (main): conn: 0x20031098 Queued 7 bytes (total 82)
[00:00:46.926,147] <dbg> net_tcp: tcp_unsent_len: (main): unsent_len=7
[00:00:46.926,208] <dbg> net_tcp: tcp_unsent_len: (main): unsent_len=7
[00:00:46.926,239] <dbg> net_tcp: tcp_window_full: (main): conn: 0x20031098 window_full=0
[00:00:46.983,062] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20030448 src port 80 dst port 41102 family 2
[00:00:46.983,093] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x20010e94] match found cb 0x16e91 ud 0x200109f8 rank 0x3f
[00:00:46.983,428] <dbg> net_tcp: tcp_in: (rx_q[0]): RST Seq=1973167573 Len=0 [ESTABLISHED Seq=1626007065 Ack=1973167573]
[00:00:46.983,459] <dbg> net_tcp: tcp_in: (rx_q[0]): ESTABLISHED->CLOSED
[00:00:46.983,551] <dbg> net_tcp: tcp_conn_unref_debug: (rx_q[0]): conn: 0x20031098, ref_count=1 (tcp_in():2513)
[00:00:46.983,581] <dbg> net_conn: net_conn_unregister: (rx_q[0]): Connection handler 0x20010e94 removed
[00:00:46.983,612] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x200109f8, pkt=(nil), st=-104, user_data=(nil)
[00:00:46.983,673] <dbg> net_sock: zsock_received_cb: (rx_q[0]): Marked socket 0x200109f8 as peer-closed
[00:00:46.984,008] <dbg> net_sock: zsock_recv_stream: (main): NULL return from fifo
[00:00:46.984,039] <dbg> net_sock: z_impl_zsock_close: (main): close: ctx=0x200109f8, fd=0
[00:00:46.984,100] <dbg> net_tcp: net_tcp_recv: (main): context: 0x200109f8, cb: (nil), user_data: (nil)
[00:00:46.984,130] <dbg> net_tcp: net_tcp_unref: (main): context: 0x200109f8, conn: (nil)
[00:00:46.984,161] <dbg> net_ctx: net_context_unref: (main): Context 0x200109f8 released
[00:00:47.040,374] <dbg> main: main: Error sending rpc request: The request could not be send!
[00:00:47.042,419] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x200304b0 src port 80 dst port 41102 family 2
[00:00:47.042,449] <dbg> net_conn: net_conn_input: (rx_q[0]): No match found.
[00:00:49.501,647] <inf> net_l2_openthread: State changed! Flags: 0x00000064 Current role: router

2. Log with TLS:

[00:00:31.012,329] <inf> usb_cdc_acm: Device configured
[00:00:56.555,480] <inf> net_l2_openthread: State changed! Flags: 0x00004000 Current role: disabled
[00:00:56.556,121] <inf> net_l2_openthread: State changed! Flags: 0x00020000 Current role: disabled
[00:00:56.556,213] <inf> net_l2_openthread: State changed! Flags: 0x00040000 Current role: disabled
[00:00:56.556,304] <inf> net_l2_openthread: State changed! Flags: 0x00000100 Current role: disabled
[00:00:56.559,539] <inf> net_l2_openthread: State changed! Flags: 0x00010000 Current role: disabled
[00:00:56.559,631] <inf> net_l2_openthread: State changed! Flags: 0x00008000 Current role: disabled
[00:00:56.560,150] <inf> net_l2_openthread: State changed! Flags: 0x10000000 Current role: disabled
[00:00:56.560,394] <inf> net_l2_openthread: State changed! Flags: 0x10000000 Current role: disabled
[00:00:56.561,462] <inf> net_l2_openthread: State changed! Flags: 0x00001000 Current role: disabled
[00:00:56.561,798] <inf> net_l2_openthread: State changed! Flags: 0x00000001 Current role: disabled
[00:00:56.561,981] <inf> net_l2_openthread: State changed! Flags: 0x00000008 Current role: disabled
[00:00:56.562,133] <inf> net_l2_openthread: State changed! Flags: 0x01000000 Current role: disabled
[00:00:56.562,255] <inf> net_l2_openthread: State changed! Flags: 0x00000004 Current role: detached
[00:00:56.562,377] <inf> net_l2_openthread: State changed! Flags: 0x00000001 Current role: detached
[00:00:56.562,622] <inf> net_l2_openthread: State changed! Flags: 0x00001000 Current role: detached
[00:00:56.562,866] <inf> net_l2_openthread: State changed! Flags: 0x00001000 Current role: detached
[00:00:56.563,110] <inf> net_l2_openthread: State changed! Flags: 0x00000010 Current role: detached
[00:00:56.563,842] <inf> net_l2_openthread: State changed! Flags: 0x10000000 Current role: detached
[00:00:59.231,292] <inf> net_l2_openthread: State changed! Flags: 0x200012a4 Current role: child
[00:00:59.231,567] <inf> net_l2_openthread: State changed! Flags: 0x00000001 Current role: child
[00:00:59.231,842] <dbg> in3_ot: sendOpenThreadPing: Ping Server:
[00:00:59.231,872] <dbg> in3_ot: printIpv6Address: Mesh Local EID Address: fd97.6739.093e.0002.0000.0000.a756.5ef8
[00:00:59.232,482] <dbg> in3_ot: sendOpenThreadPing: ping send response:0
[00:00:59.232,696] <dbg> http_client: in3_register_https_client: in3 register https
[00:00:59.264,526] <dbg> net_sock_tls: tls_alloc: (main): Allocated TLS context, 0x20005098
[00:00:59.264,831] <dbg> net_tcp: tcp_conn_ref: (main): conn: 0x20034228, ref_count: 1
[00:00:59.264,862] <dbg> net_tcp: tcp_conn_alloc: (main): conn: 0x20034228
[00:00:59.264,892] <dbg> net_sock: zsock_socket_internal: (main): socket: ctx=0x20013a0c, fd=1
[00:00:59.265,075] <dbg> net_ctx: net_context_bind: (main): Context 0x20013a0c binding to TCP [::]:40289 iface 1 (0x20000ab8)
[00:00:59.265,167] <dbg> net_tcp: net_tcp_connect: (main): context: 0x20013a0c, local: ::, remote: fd97:6739:93e:2::a756:5ef8
[00:00:59.265,289] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20034228 src: fd11:22::ad23:b907:951b:2e7e, dst: fd97:6739:93e:2::a756:5ef8
[00:00:59.265,441] <dbg> net_conn: conn_register_debug: (main): [0x20013ea8/6/2/0x3f] remote fd97:6739:93e:2::a756:5ef8/4443 
[00:00:59.265,472] <dbg> net_conn: conn_register_debug: (main):   local ::/40289 cb 0x186dd ud 0x20013a0c
[00:00:59.265,594] <dbg> net_tcp: tcp_in: (main):  [LISTEN Seq=695962656 Ack=0]
[00:00:59.265,869] <dbg> net_tcp: tcp_out_ext: (main): SYN Seq=695962656 Len=0
[00:00:59.266,021] <dbg> net_tcp: tcp_send_process_no_lock: (main): SYN Seq=695962656 Len=0 
[00:00:59.266,235] <dbg> net_tcp: tcp_send: (main): SYN Seq=695962656 Len=0
[00:00:59.266,601] <dbg> net_tcp: tcp_in: (main): LISTEN->SYN_SENT
[00:00:59.321,868] <dbg> in3_ot: pingResponseCallback: Ping reply
[00:00:59.321,868] <dbg> in3_ot: printIpv6Address: Mesh Local EID Address: fd97.6739.093e.0002.0000.0000.a756.5ef8
[00:00:59.339,538] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x200335d8 src port 4443 dst port 40289 family 2
[00:00:59.339,569] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x20013ea8] match found cb 0x186dd ud 0x20013a0c rank 0x3f
[00:00:59.339,874] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK,RST Seq=0 Ack=695962657 Len=0 [SYN_SENT Seq=695962657 Ack=0]
[00:00:59.339,935] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN_SENT->CLOSED
[00:00:59.339,996] <dbg> net_tcp: tcp_conn_unref_debug: (rx_q[0]): conn: 0x20034228, ref_count=1 (tcp_in():2513)
[00:00:59.340,026] <dbg> net_tcp: tcp_conn_unref_debug: (rx_q[0]): conn: 0x20034228 is waiting on connect semaphore
[00:00:59.790,802] <inf> net_l2_openthread: State changed! Flags: 0x00000064 Current role: router
[00:01:02.266,754] <dbg> net_tcp: tcp_conn_unref_debug: (main): conn: 0x20034228, ref_count=1 (net_tcp_connect():2856)
[00:01:02.266,784] <dbg> net_conn: net_conn_unregister: (main): Connection handler 0x20013ea8 removed
[00:01:02.266,906] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20034228, ret=-116
[00:01:02.266,967] <err> http_client: Cannot connect to IPv6 remote (-116)
[00:01:02.266,967] <err> http_client: Failed to connect to socket
[00:01:02.266,998] <dbg> http_client: run_https_post: starting tcp failed
[00:01:02.349,914] <err> http_client: Failed to register public certificate: -17
[00:01:02.349,914] <dbg> http_client: run_https_post: starting tcp failed
[00:01:02.433,593] <err> http_client: Failed to register public certificate: -17
[00:01:02.433,593] <dbg> http_client: run_https_post: starting tcp failed
[00:01:02.517,425] <err> http_client: Failed to register public certificate: -17
[00:01:02.517,456] <dbg> http_client: run_https_post: starting tcp failed
[00:01:02.601,287] <err> http_client: Failed to register public certificate: -17
[00:01:02.601,318] <dbg> http_client: run_https_post: starting tcp failed
[00:01:02.685,150] <err> http_client: Failed to register public certificate: -17
[00:01:02.685,150] <dbg> http_client: run_https_post: starting tcp failed
[00:01:02.769,165] <err> http_client: Failed to register public certificate: -17
[00:01:02.769,195] <dbg> http_client: run_https_post: starting tcp failed
[00:01:02.825,836] <dbg> main: main: Error sending rpc request: The request could not be send!

Regards

VIpin Das

[Marte Myrvold]

Hi,

I see that you are getting this in your log:

Failed to register public certificate: -17

Error 17 is EEXIST, which means that the file exists. This might be caused by calling tls_credential_add() several places with the same sec_tag and type. I see that you are calling it in send_https_post(). Does it work the first time, and then fails the following times, or does it fail from the beginning?

Best regards,

Marte

[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