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,

Thank you. 

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

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

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

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

Regards

Vipin Das 

[vipin das]

Hi Marte,

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

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

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

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

Any clue? 

Regards

Vipin Das

[Marte Myrvold]

Hi,

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

Best regards,

Marte

[vipin das]

Hi,

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

Thanks 

Vipin Das

[vipin das]

Hi Marte, 

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

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

For that I am sharing latest log for your reference. 

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

Thanks 

Vipin Das

[Marte Myrvold]

Hi,

Is this the log from after you got TCP to work? Because in your log, I see that TCP is still failing:

[00:02:02.052,246] <dbg> http_client: run_https_post: starting tcp failed

Best regards,

Marte

[vipin das]

Hi Marte, 

Yes this is the same log after TCP got worked. For this log I just enabled the CONFIG_NET_SOCKETS_SOCKOPT_TLS=y. Don't get confuse with that particular log. That is something I added. 

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

This time it fails at this connect to TLS socket but socket creation is success(socket(family, SOCK_STREAM, IPPROTO_TLS_1_2)). 

Regards

Vipin Das

[Marte Myrvold]

Hi,

So your example is unchanged other than enabling CONFIG_NET_SOCKETS_SOCKOPT_TLS?

Is mbedTLS (CONFIG_MBEDTLS) enabled? Do you have any functionality for TLS? Are you using the correct credentials (certification and private key)?

Best regards,

Marte

[vipin das]

Hi Marte,

Yes you are right. My config related to TLS shared below. 

#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=8192
CONFIG_MBEDTLS_ENTROPY_ENABLED=y
# certificate must fit into one message, fragmenting is not supported
CONFIG_MBEDTLS_SSL_MAX_CONTENT_LEN=8192

#Credentials
CONFIG_TLS_CREDENTIALS=y
CONFIG_TLS_MAX_CREDENTIALS_NUMBER=4

No I don't think I have any functionality for TLS at the moment. 

Please consider me a novice user in networking topics. This is 1st time I am working on TLS socket connection. I just followed some of the existing samples and few discussions. I don't really understand about the certification and private key that you mentioned above. I have created the ca_cert.der for the server and it looks similar like below. 

"-----BEGIN CERTIFICATE-----\n"
"----------------------------------------------------------------\n"
"----------------------------------------------------------------\n"
"----------------------------------------------------------------\n"
"-----END CERTIFICATE-----\n"
"-----BEGIN CERTIFICATE-----\n"
"----------------------------------------------------------------\n"
"----------------------------------------------------------------\n"
"----------------------------------------------------------------\n"
"-----END CERTIFICATE-----\n"
"-----BEGIN CERTIFICATE-----\n"
"----------------------------------------------------------------\n"
"----------------------------------------------------------------\n"
"----------------------------------------------------------------\n"
"-----END CERTIFICATE-----\n"

You can share me any proper TLS sample where I can take a look and get inspired to make my application working 

Regards

Vipin Das

[vipin das]

Hi Marte,

I have added the tis_credential_add() to add the downloaded server certificate to authenticate the remote server. After adding that connect error is -22 (EINVAL). 

[00:01:57.147,583] <dbg> http_client: in3_register_https_client: in3 register https
[00:01:57.180,664] <dbg> http_client: setup_socket: Setup socket info: Server address: fd97:6739:93e:2:0:0:A756:5EF8
[00:01:57.180,847] <dbg> net_sock_tls: tls_alloc: (main): Allocated TLS context, 0x20003478
[00:01:57.181,152] <dbg> net_tcp: tcp_conn_ref: (main): conn: 0x2002d020, ref_count: 1
[00:01:57.181,182] <dbg> net_tcp: tcp_conn_alloc: (main): conn: 0x2002d020
[00:01:57.181,274] <dbg> net_sock: zsock_socket_internal: (main): socket: ctx=0x2001031c, fd=1
[00:01:57.181,457] <dbg> net_tcp: net_tcp_connect: (main): context: 0x2001031c, local: ::, remote: fd97:6739:93e:2::a756:5ef8
[00:01:57.181,640] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x2002d020 src: fd97:6739:93e:1:8ea6:548e:c791:187, dst: fd97:6739:93e:2::a756:5ef8
[00:01:57.181,762] <dbg> net_conn: conn_register_debug: (main): [0x200107b8/6/2/0x3f] remote fd97:6739:93e:2::a756:5ef8/443
[00:01:57.181,823] <dbg> net_conn: conn_register_debug: (main):   local ::/35905 cb 0x16c01 ud 0x2001031c
[00:01:57.181,945] <dbg> net_tcp: tcp_in: (main):  [LISTEN Seq=1369800138 Ack=0]
[00:01:57.182,220] <dbg> net_tcp: tcp_out_ext: (main): SYN Seq=1369800138 Len=0
[00:01:57.182,373] <dbg> net_tcp: tcp_send_process_no_lock: (main): SYN Seq=1369800138 Len=0
[00:01:57.182,617] <dbg> net_tcp: tcp_send: (main): SYN Seq=1369800138 Len=0
[00:01:57.183,319] <dbg> net_tcp: tcp_in: (main): LISTEN->SYN_SENT
[00:01:57.231,292] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x2002c3d0 src port 443 dst port 35905 family 2
[00:01:57.231,323] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x200107b8] match found cb 0x16c01 ud 0x2001031c rank 0x3f
[00:01:57.231,658] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN,ACK Seq=3663983358 Ack=1369800139 Len=0 [SYN_SENT Seq=1369800139 Ack=0]
[00:01:57.231,689] <dbg> net_tcp: tcp_options_check: (rx_q[0]): len=4
[00:01:57.231,719] <dbg> net_tcp: tcp_options_check: (rx_q[0]): opt: 2, opt_len: 4
[00:01:57.231,750] <dbg> net_tcp: tcp_options_check: (rx_q[0]): MSS=1460
[00:01:57.231,781] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64240 to 3413
[00:01:57.231,811] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2002d020 window_full=0
[00:01:57.231,964] <dbg> net_tcp: tcp_send_timer_cancel: (rx_q[0]): SYN Seq=1369800138 Len=0
[00:01:57.232,299] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=1369800139 Ack=3663983359 Len=0
[00:01:57.232,482] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=1369800139 Ack=3663983359 Len=0
[00:01:57.232,666] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=1369800139 Ack=3663983359 Len=0
[00:01:57.232,788] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN_SENT->ESTABLISHED
[00:01:57.233,001] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x2002d020, ret=0
[00:01:57.233,062] <dbg> net_tcp: net_tcp_recv: (main): context: 0x2001031c, cb: 0x8ce1, user_data: (nil)
[00:01:57.233,245] <err> http_client: Cannot connect to IPv6 remote (-22)
[00:01:57.233,245] <err> http_client: Failed to connect to socket
[00:01:57.233,245] <dbg> http_client: run_https_post: starting tcp failed
[00:01:57.290,252] <dbg> main: main: Error sending rpc request: The request could not be send!
[00:02:07.629,394] <inf> net_l2_openthread: State changed! Flags: 0x00000064 Current role: router
[00:02:57.395,874] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x2002c3d0 src port 443 dst port 35905 family 2
[00:02:57.395,904] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x200107b8] match found cb 0x16c01 ud 0x2001031c rank 0x3f
[00:02:57.396,301] <dbg> net_tcp: tcp_in: (rx_q[0]): FIN,ACK Seq=3663983359 Ack=1369800139 Len=0 [ESTABLISHED Seq=1369800139 Ack=3663983359]
[00:02:57.396,331] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64240 to 3413
[00:02:57.396,362] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2002d020 window_full=0
[00:02:57.396,667] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): FIN,ACK Seq=1369800139 Ack=3663983360 Len=0
[00:02:57.396,881] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): FIN,ACK Seq=1369800139 Ack=3663983360 Len=0 
[00:02:57.397,155] <dbg> net_tcp: tcp_send: (rx_q[0]): FIN,ACK Seq=1369800139 Ack=3663983360 Len=0
[00:02:57.397,277] <dbg> net_tcp: tcp_in: (rx_q[0]): ESTABLISHED->LAST_ACK
[00:02:57.457,122] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x2002c3d0 src port 443 dst port 35905 family 2
[00:02:57.457,153] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x200107b8] match found cb 0x16c01 ud 0x2001031c rank 0x3f
[00:02:57.457,519] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK Seq=3663983360 Ack=1369800140 Len=0 [LAST_ACK Seq=1369800139 Ack=3663983360]
[00:02:57.457,550] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64239 to 3413
[00:02:57.457,580] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2002d020 window_full=0
[00:02:57.457,794] <dbg> net_tcp: tcp_send_timer_cancel: (rx_q[0]): FIN,ACK Seq=1369800139 Ack=3663983360 Len=0
[00:02:57.457,855] <dbg> net_tcp: tcp_in: (rx_q[0]): LAST_ACK->CLOSED
[00:02:57.457,885] <dbg> net_tcp: tcp_conn_unref_debug: (rx_q[0]): conn: 0x2002d020, ref_count=1 (tcp_in():2513)
[00:02:57.457,916] <dbg> net_conn: net_conn_unregister: (rx_q[0]): Connection handler 0x200107b8 removed
[00:02:57.457,977] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x2001031c, pkt=(nil), st=0, user_data=(nil)
[00:02:57.458,007] <dbg> net_sock: zsock_received_cb: (rx_q[0]): Marked socket 0x2001031c as peer-closed

Just to update the present status of my issue. 

Regards

Vipin Das