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,

I have started looking into your issue, and will come back to you tomorrow.

Best regards,

Marte

[vipin das]

Hi Marte, 

Looking forward to seeing your suggestions and feedback. Feel free to ask in case if I miss to add into the description. 

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