TLS Socket connection request return with error number -22(EINVAL)

[vipin das]

Hi All,

I am trying to setup a thread network to send  RPC message to a remote http server:https://mainnet.incubed.net). I took http_client sample(sdk-zephyr) and modified slightly to adapt to my application. .

I was successful in sending RPC message to the server via TCP socket connection but I am really struggling to open secure channel(TLS) for communicating with the server. When my application tries to connect using TLS socket it throws an error with error number -22(EINVAL). I am not quite sure why and what mistake I did with respect to config options. 

[00:00:58.561,645] <dbg> http_client: in3_register_https_client: in3 register https
[00:00:58.594,177] <dbg> http_client: setup_socket: Server address: fd97:6739:93e:2:0:0:A756:5EF8 
[00:00:58.594,360] <dbg> net_sock_tls: tls_alloc: (main): Allocated TLS context, 0x20003478
[00:00:58.594,665] <dbg> net_tcp: tcp_conn_ref: (main): conn: 0x2002d320, ref_count: 1
[00:00:58.594,696] <dbg> net_tcp: tcp_conn_alloc: (main): conn: 0x2002d320
[00:00:58.594,757] <dbg> net_sock: zsock_socket_internal: (main): socket: ctx=0x2001031c, fd=1
[00:00:58.594,940] <dbg> net_ctx: net_context_bind: (main): Context 0x2001031c binding to TCP [::]:41215 iface 1 (0x20000a98)
[00:00:58.595,031] <dbg> net_tcp: net_tcp_connect: (main): context: 0x2001031c, local: ::, remote: fd97:6739:93e:2::a756:5ef8
[00:00:58.595,214] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x2002d320 src: fd97:6739:93e:1:649e:fad5:e7ab:366d, dst: fd97:6739:93e:2::a756:5ef8
[00:00:58.595,336] <dbg> net_conn: conn_register_debug: (main): [0x200107b8/6/2/0x3f] remote fd97:6739:93e:2::a756:5ef8/443 
[00:00:58.595,397] <dbg> net_conn: conn_register_debug: (main):   local ::/41215 cb 0x16fc9 ud 0x2001031c
[00:00:58.595,520] <dbg> net_tcp: tcp_in: (main):  [LISTEN Seq=548241854 Ack=0]
[00:00:58.595,764] <dbg> net_tcp: tcp_out_ext: (main): SYN Seq=548241854 Len=0
[00:00:58.595,947] <dbg> net_tcp: tcp_send_process_no_lock: (main): SYN Seq=548241854 Len=0 
[00:00:58.596,160] <dbg> net_tcp: tcp_send: (main): SYN Seq=548241854 Len=0
[00:00:58.596,862] <dbg> net_tcp: tcp_in: (main): LISTEN->SYN_SENT
[00:00:58.648,925] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x2002c6d0 src port 443 dst port 41215 family 2
[00:00:58.648,956] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x200107b8] match found cb 0x16fc9 ud 0x2001031c rank 0x3f
[00:00:58.649,261] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN,ACK Seq=3167820546 Ack=548241855 Len=0 [SYN_SENT Seq=548241855 Ack=0]
[00:00:58.649,322] <dbg> net_tcp: tcp_options_check: (rx_q[0]): len=4
[00:00:58.649,353] <dbg> net_tcp: tcp_options_check: (rx_q[0]): opt: 2, opt_len: 4
[00:00:58.649,353] <dbg> net_tcp: tcp_options_check: (rx_q[0]): MSS=1460
[00:00:58.649,383] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64240 to 3413
[00:00:58.649,414] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2002d320 window_full=0
[00:00:58.649,597] <dbg> net_tcp: tcp_send_timer_cancel: (rx_q[0]): SYN Seq=548241854 Len=0
[00:00:58.649,902] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=548241855 Ack=3167820547 Len=0
[00:00:58.650,085] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=548241855 Ack=3167820547 Len=0 
[00:00:58.650,268] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=548241855 Ack=3167820547 Len=0
[00:00:58.650,390] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN_SENT->ESTABLISHED
[00:00:58.650,604] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x2002d320, ret=0
[00:00:58.650,665] <dbg> net_tcp: net_tcp_recv: (main): context: 0x2001031c, cb: 0x8ce1, user_data: (nil)
[00:00:58.662,567] <err> http_client: Cannot connect to IPv6 remote (-22)
[00:00:58.662,597] <err> http_client: Failed to connect to socket
[00:00:58.662,597] <dbg> http_client: run_https_post: starting tcp failed
[00:00:58.718,750] <dbg> main: main: Error sending rpc request: The request could not be send!
[00:01:06.033,477] <inf> net_l2_openthread: State changed! Flags: 0x00000064 Current role: router

#Socket settings
CONFIG_NET_SOCKETS_SOCKOPT_TLS=n
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=32768
CONFIG_MBEDTLS_TLS_LIBRARY=y
CONFIG_MBEDTLS_X509_LIBRARY=y
CONFIG_MBEDTLS_PEM_CERTIFICATE_FORMAT=y
# certificate must fit into one message, fragmenting is not supported
CONFIG_MBEDTLS_SSL_MAX_CONTENT_LEN=4096

Can someone tell me what should I try to resolve this problem. 

Regards

Vipin Das

[Jørgen Holmefjord]

Hi,

Can you post the changes you have made to the sample? As far as I can see, the original sample does not implement OpenThread support.

Do you get any warnings when building the application?

Have you done a sniffer trace, to see if there is any error from the on-air traffic?

Best regards,
Jørgen

[vipin das]

Hi Jørgen, 

I didn't make any relevant modification to http_client to harm the working of that (I believe). 

static int establish_connection(sa_family_t family, const char* ipv6_addr, 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, ipv6_addr, &net_sin(addr)->sin_addr);
  }
  else {
    net_sin6(addr)->sin6_family = AF_INET6;
    net_sin6(addr)->sin6_port   = htons(port);
    inet_pton(AF_INET6, ipv6_addr, &net_sin6(addr)->sin6_addr);
    LOG_DBG("Server address: %s ", ipv6_addr);
  }

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

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

/**
 *
 */
static void server_response_cb(struct http_response* rsp, enum http_final_call final_data, void* user_data) {
  if (final_data == HTTP_DATA_MORE) {
    LOG_DBG("Partial data received (%zd bytes)", rsp->data_len);
  }
  else if (final_data == HTTP_DATA_FINAL) {
    LOG_DBG("All the data received (%zd bytes)", rsp->data_len);
  }

  LOG_DBG("Response to %s", (const char*) user_data);
  LOG_DBG("Response status %s", rsp->http_status);
}

/**
 *
 */
static int setup_socket_connection(sa_family_t family, const char* ipv6_addr, int port,
                                   int* sock, struct sockaddr* addr, socklen_t addr_len) {
  int ret = 0;

  ret = establish_connection(family, ipv6_addr, port, sock, addr, addr_len);
  if (ret < 0 || *sock < 0) {
    LOG_ERR("Setup socket connection failed");
    return -1;
  }
  return ret;
}

I don't see any critical warnings. 

/ncs/zephyr/include/zephyr/zephyr.h:13:2: warning: #warning "<zephyr/zephyr.h> is deprecated, include <zephyr/kernel.h> instead" [-Wcpp]
   13 | #warning "<zephyr/zephyr.h> is deprecated, include <zephyr/kernel.h> instead"

I have tried to setup sniffer but due to some reasons my nrf-sniffer interface is not detected in the Wireshark tool. I tried multiple steps and different version but couldn't succeed. 

But by just disabling CONFIG_NET_SOCKETS_SOCKOPT_TLS, the same code works for TCP socket connection and able to send and receive RPC message to our remote server. 

Regards

Vipin Das

[vipin das]

Hi Jørgen,

I could solve the EINVAL(-22) error wrt to TLS socket connection. 

But now I am seeing new error. Could you please comment on the below error. 

[00:00:33.341,827] <err> net_sock_tls: TLS handshake error: -7780
[00:00:33.343,750] <err> http_client: Cannot connect to IPv6 remote (-113)
[00:00:33.343,780] <err> http_client: Setup socket Failed
[00:00:33.343,780] <err> http_client: Failed to connect to socket

Regards

Vipin Das

[Jørgen Holmefjord]

Looks like your error is similar to this thread. Can you check if the suggestions there help you resolve your issue?

[vipin das]

Hi Jørgen,

Thanks!!!

Before I post my query, I have seen the above mentioned discussion and tried some of the configuration changes but nothing helps.  

But I tried to connect to "google.com" using the same code, here I don't see any TLS handshake issue but socket connect is failed here as well. 

[00:00:37.959,228] <dbg> http_client: establish_connection: ai_family: 2 ai_socktype: 1 ai_protocol: 6 ai_addrlen: 24
[00:00:37.959,411] <dbg> net_sock_tls: tls_alloc: (main): Allocated TLS context, 0x200034b0
[00:00:37.959,686] <dbg> net_tcp: tcp_conn_ref: (main): conn: 0x20030100, ref_count: 1
[00:00:37.959,716] <dbg> net_tcp: tcp_conn_alloc: (main): conn: 0x20030100
[00:00:37.959,777] <dbg> net_sock: zsock_socket_internal: (main): socket: ctx=0x200103c8, fd=1
[00:00:37.959,808] <dbg> http_client: establish_connection: TLS Socket fd: 0
[00:00:37.959,960] <dbg> net_ctx: net_context_bind: (main): Context 0x200103c8 binding to TCP [::]:37717 iface 1 (0x20000ab8)
[00:00:37.960,083] <dbg> net_tcp: net_tcp_connect: (main): context: 0x200103c8, local: ::, remote: fd97:6739:93e:2::808:808
[00:00:37.960,235] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20030100 src: fd97:6739:93e:1:99b4:2ddc:2e2b:7ac1, dst: fd97:6739:93e:2::808:808
[00:00:37.960,388] <dbg> net_conn: conn_register_debug: (main): [0x20010974/6/2/0x3f] remote fd97:6739:93e:2::808:808/443 
[00:00:37.960,418] <dbg> net_conn: conn_register_debug: (main):   local ::/37717 cb 0x18045 ud 0x200103c8
[00:00:37.960,571] <dbg> net_tcp: tcp_in: (main):  [LISTEN Seq=3072386416 Ack=0]
[00:00:37.960,815] <dbg> net_tcp: tcp_out_ext: (main): SYN Seq=3072386416 Len=0
[00:00:37.960,968] <dbg> net_tcp: tcp_send_process_no_lock: (main): SYN Seq=3072386416 Len=0 
[00:00:37.961,181] <dbg> net_tcp: tcp_send: (main): SYN Seq=3072386416 Len=0
[00:00:37.961,578] <dbg> net_tcp: tcp_in: (main): LISTEN->SYN_SENT
[00:00:38.013,000] <dbg> in3_ot: pingResponseCallback: Ping reply
[00:00:38.013,000] <dbg> in3_ot: printIpv6Address: Mesh Local EID Address: fd97.6739.093e.0002.0000.0000.0808.0808
[00:00:38.019,622] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x2002f4b0 src port 443 dst port 37717 family 2
[00:00:38.019,653] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x20010974] match found cb 0x18045 ud 0x200103c8 rank 0x3f
[00:00:38.019,989] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN,ACK Seq=2596550350 Ack=3072386417 Len=0 [SYN_SENT Seq=3072386417 Ack=0]
[00:00:38.020,019] <dbg> net_tcp: tcp_options_check: (rx_q[0]): len=4
[00:00:38.020,050] <dbg> net_tcp: tcp_options_check: (rx_q[0]): opt: 2, opt_len: 4
[00:00:38.020,080] <dbg> net_tcp: tcp_options_check: (rx_q[0]): MSS=1412
[00:00:38.020,111] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 65535 to 1280
[00:00:38.020,141] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x20030100 window_full=0
[00:00:38.020,294] <dbg> net_tcp: tcp_send_timer_cancel: (rx_q[0]): SYN Seq=3072386416 Len=0
[00:00:38.020,599] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=3072386417 Ack=2596550351 Len=0
[00:00:38.020,812] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=3072386417 Ack=2596550351 Len=0 
[00:00:38.020,996] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=3072386417 Ack=2596550351 Len=0
[00:00:38.021,087] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN_SENT->ESTABLISHED
[00:00:38.021,331] <dbg> net_tcp: net_tcp_connect: (main): conn: 0x20030100, ret=0
[00:00:38.021,392] <dbg> net_tcp: net_tcp_recv: (main): context: 0x200103c8, cb: 0x8e55, user_data: (nil)
[00:00:38.051,879] <err> http_client: Cannot connect to IPv6 remote (-22)
[00:00:38.051,910] <dbg> net_sock: z_impl_zsock_close: (main): close: ctx=0x200034b0, fd=0
[00:00:38.052,062] <dbg> net_sock: z_impl_zsock_close: (main): close: ctx=0x200103c8, fd=1
[00:00:38.052,093] <dbg> net_tcp: net_tcp_recv: (main): context: 0x200103c8, cb: (nil), user_data: (nil)
[00:00:38.052,276] <dbg> net_tcp: net_tcp_put: (main):  [ESTABLISHED Seq=3072386417 Ack=2596550351]
[00:00:38.052,307] <dbg> net_tcp: net_tcp_put: (main): context 0x200103c8 CONNECTED
[00:00:38.052,337] <dbg> net_tcp: net_tcp_put: (main): TCP connection in active close, not disposing yet (waiting 22753ms)

With the same code, the result is different for another server(eth-mainnet.g.alchemy.com)

[00:00:32.912,048] <dbg> in3_ot: pingResponseCallback: Ping reply
[00:00:32.912,048] <dbg> in3_ot: printIpv6Address: Mesh Local EID Address: fd97.6739.093e.0002.0000.0000.6812.2b47
[00:00:32.977,539] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x2002f4a0 src port 443 dst port 43175 family 2
[00:00:32.977,600] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x20010974] match found cb 0x18045 ud 0x200103c8 rank 0x3f
[00:00:32.977,935] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK Seq=2701949632 Ack=3965925004 Len=0 [ESTABLISHED Seq=3965924917 Ack=2701949632]
[00:00:32.977,966] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64153 to 1280
[00:00:32.977,996] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x200300f0 window_full=0
[00:00:32.978,057] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x200300f0 len_acked=87
[00:00:32.978,118] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x200300f0 window_full=0
[00:00:32.978,149] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x200300f0 total=0, unacked_len=0, send_win=1280, mss=1280
[00:00:32.978,179] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x200300f0 send_data_timer=1, send_data_retries=0
[00:00:32.978,210] <dbg> net_tcp: tcp_unsent_len: (rx_q[0]): unsent_len=0
[00:00:32.978,271] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x200300f0 window_full=0
[00:00:33.576,904] <dbg> net_conn: net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x2002f4a0 src port 443 dst port 43175 family 2
[00:00:33.576,934] <dbg> net_conn: net_conn_input: (rx_q[0]): [0x20010974] match found cb 0x18045 ud 0x200103c8 rank 0x3f
[00:00:33.577,301] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK,PSH Seq=2701949632 Ack=3965925004 Len=7 [ESTABLISHED Seq=3965925004 Ack=2701949632]
[00:00:33.577,331] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 64153 to 1280
[00:00:33.577,362] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x200300f0 window_full=0
[00:00:33.577,697] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=3965925004 Ack=2701949639 Len=0
[00:00:33.577,911] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=3965925004 Ack=2701949639 Len=0 
[00:00:33.578,094] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=3965925004 Ack=2701949639 Len=0
[00:00:33.578,216] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x200103c8, pkt=0x2002f4a0, st=0, user_data=(nil)
[00:00:33.578,552] <err> net_sock_tls: TLS handshake error: -7780
[00:00:33.579,437] <err> http_client: Cannot connect to IPv6 remote (-113)
[00:00:33.579,467] <dbg> net_sock: z_impl_zsock_close: (main): close: ctx=0x200034b0, fd=0
[00:00:33.580,322] <dbg> net_sock: z_impl_zsock_close: (main): close: ctx=0x200103c8, fd=1
[00:00:33.580,352] <dbg> net_tcp: net_tcp_recv: (main): context: 0x200103c8, cb: (nil), user_data: (nil)
[00:00:33.580,535] <dbg> net_tcp: net_tcp_put: (main):  [ESTABLISHED Seq=3965925004 Ack=2701949639]
[00:00:33.580,596] <dbg> net_tcp: net_tcp_put: (main): context 0x200103c8 CONNECTED
[00:00:33.580,627] <dbg> net_tcp: net_tcp_put: (main): TCP connection in active close, not disposing yet (waiting 22753ms)

What do you think about this two different behaviour. Feel free to ask any missing points. I am really blocked because of this issue. 

Regards

Vipin Das

[vipin das]

Hi Jørgen,

Any comments on my last question. 

Regards

Vipin Das