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

[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

[Marte Myrvold]

Hi,

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

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

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

Best regards,

Marte

[vipin das]

Hi Marte,

Thank you. 

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

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

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

Regards

Vipin Das 

[vipin das]

Hi Marte,

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

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

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

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

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

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

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

  #Socket settings
  CONFIG_NET_SOCKETS_SOCKOPT_TLS=y
  CONFIG_POSIX_MAX_FDS=8
  CONFIG_NET_SOCKETS_TLS_MAX_CONTEXTS=10
  
  #MBEDTLS and security configuration 
  CONFIG_MBEDTLS_CFG_FILE="config-tls-generic.h"
  CONFIG_OPENTHREAD_MBEDTLS_CHOICE=y
  CONFIG_MBEDTLS_TLS_VERSION_1_2=y
  CONFIG_MBEDTLS_TLS_LIBRARY=y
  CONFIG_MBEDTLS_SSL_PROTO_TLS1_2=y
  
  # TLS configuration
  CONFIG_MBEDTLS=y
  CONFIG_MBEDTLS_BUILTIN=y
  CONFIG_MBEDTLS_ENABLE_HEAP=y
  CONFIG_MBEDTLS_HEAP_SIZE=64000
  CONFIG_MBEDTLS_ENTROPY_ENABLED=y
  # certificate must fit into one message, fragmenting is not supported
  CONFIG_MBEDTLS_SSL_MAX_CONTENT_LEN=10240
  CONFIG_MBEDTLS_PEM_CERTIFICATE_FORMAT=n
  
  #Credentials
  CONFIG_TLS_CREDENTIALS=y
  CONFIG_TLS_MAX_CREDENTIALS_NUMBER=4

  Regards

  Vipin Das 

[vipin das]

Hi Marte, 

Any update on my last posted questions? 

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

Thanks 

Vipin Das

[Marte Myrvold]

Hi,

vipin das said:

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

Please share the complete log of this.

Have you checked the logs on the server?

vipin das said:

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

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

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

vipin das said:

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

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

Best regards,

Marte

[vipin das]

Hi Marte,

Thank you. 

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

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

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

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

Regards

Vipin Das