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

[Jørgen Holmefjord]

Hi,

Sorry for the slow response. I see that you marked the previous answer as verified answer, does this mean that you managed to resolve the issue? If so, can you post the solution for other users looking for the same thing?

Best regards,
Jørgen