HI
I had some great support in this ticket so I will try my luck again.
We want to migrate our application from SPM to TFM. We use SDK 2.1.0. We communicate with the cloud using mTLS, setting up our socket as following:
Fullscreen
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
static int setup_socket(const char *server_name, const char *server_ip, int port,
int *sock, struct sockaddr *address, socklen_t addressLen,
int ca_certificate_tag, SOCKET_MANAGER_PEER_VERIFY_t verifyMode) {
const sa_family_t family = AF_INET;
int ret = 0;
memset(address, 0, addressLen);
net_sin(address)->sin_family = AF_INET;
net_sin(address)->sin_port = htons(port);
zsock_inet_pton(family, server_ip, &net_sin(address)->sin_addr);
struct timeval timeout = {
.tv_sec = 5
};
sec_tag_t sec_tag_list_2[] = {
CA2_CERTIFICATE_TAG,
CREDENTIAL_PK_CERTIFICATE_TAG
};
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
static int setup_socket(const char *server_name, const char *server_ip, int port,
int *sock, struct sockaddr *address, socklen_t addressLen,
int ca_certificate_tag, SOCKET_MANAGER_PEER_VERIFY_t verifyMode) {
const sa_family_t family = AF_INET;
int ret = 0;
memset(address, 0, addressLen);
net_sin(address)->sin_family = AF_INET;
net_sin(address)->sin_port = htons(port);
zsock_inet_pton(family, server_ip, &net_sin(address)->sin_addr);
struct timeval timeout = {
.tv_sec = 5
};
sec_tag_t sec_tag_list_2[] = {
CA2_CERTIFICATE_TAG,
CREDENTIAL_PK_CERTIFICATE_TAG
};
*sock = zsock_socket(family, SOCK_STREAM, IPPROTO_TLS_1_2);
if (*sock >= 0) {
ret = zsock_setsockopt(*sock, SOL_TLS, TLS_SEC_TAG_LIST,
sec_tag_list_2, sizeof(sec_tag_list_2));
if (ret < 0) {
LOG_ERR("Failed to set secure option (%d)", -errno);
return -errno;
}
// Set up TLS peer verification /
int verify = verifyMode;
ret = zsock_setsockopt(*sock, SOL_TLS, TLS_PEER_VERIFY, &verify, sizeof(verify));
if (ret < 0) {
LOG_ERR("Failed to set TLS_PEER_VERIFY option (%d)", -errno);
ret = -errno;
}
if( server_name != NULL ){
ret = zsock_setsockopt(*sock, SOL_TLS, TLS_HOSTNAME,
server_name,
strlen(server_name));
if (ret < 0) {
LOG_ERR("Failed to set TLS_HOSTNAME option (%d)", -errno);
ret = -errno;
}
}
if( m_enable_timeout )
{
ret = zsock_setsockopt(*sock, SOL_SOCKET, SO_RCVTIMEO, &timeout,
sizeof(timeout));
if (ret < 0) {
LOG_ERR("Failed to set receive timeout (%d)", -errno);
ret = -errno;
}
ret = zsock_setsockopt(*sock, SOL_SOCKET, SO_SNDTIMEO, &timeout,
sizeof(timeout));
if (ret < 0) {
LOG_ERR("Failed to set send timeout (%d)", -errno);
ret = -errno;
}
}
if ( ret >= 0 )
{
LOG_INF("Set TLS socketopt successful");
}
}
if (*sock < 0) {
LOG_ERR("Failed to create HTTP socket (%d)", -errno);
return -errno;
}
return ret;
}
This is pretty similar to your psa tls sample.
We used the following (relevant) KConfig Options with SPM:
Fullscreen
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
CONFIG_SPM=y
CONFIG_MBEDTLS=y
CONFIG_MBEDTLS_BUILTIN=y
CONFIG_MBEDTLS_ENABLE_HEAP=y
CONFIG_MBEDTLS_HEAP_SIZE=59000
CONFIG_BASE64=y
CONFIG_THREAD_NAME=y
CONFIG_MBEDTLS_SSL_MAX_CONTENT_LEN=16384
CONFIG_NET_SOCKETS_SOCKOPT_TLS=y
CONFIG_MBEDTLS_PEM_CERTIFICATE_FORMAT=y
CONFIG_MBEDTLS_SERVER_NAME_INDICATION=y
CONFIG_NET_SOCKETS_TLS_MAX_CONTEXTS=1
CONFIG_MBEDTLS_CIPHER_GCM_ENABLED=y
CONFIG_MBEDTLS_MAC_MD5_ENABLED=n
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
CONFIG_SPM=y CONFIG_MBEDTLS=y CONFIG_MBEDTLS_BUILTIN=y CONFIG_MBEDTLS_ENABLE_HEAP=y CONFIG_MBEDTLS_HEAP_SIZE=59000 CONFIG_BASE64=y CONFIG_THREAD_NAME=y CONFIG_MBEDTLS_SSL_MAX_CONTENT_LEN=16384 CONFIG_NET_SOCKETS_SOCKOPT_TLS=y CONFIG_MBEDTLS_PEM_CERTIFICATE_FORMAT=y CONFIG_MBEDTLS_SERVER_NAME_INDICATION=y CONFIG_NET_SOCKETS_TLS_MAX_CONTEXTS=1 CONFIG_MBEDTLS_CIPHER_GCM_ENABLED=y CONFIG_MBEDTLS_MAC_MD5_ENABLED=n # Networking CONFIG_NET_CONFIG_SETTINGS=y CONFIG_NET_HOSTNAME_ENABLE=y CONFIG_NET_HOSTNAME_UNIQUE=y CONFIG_NET_HOSTNAME="XXXX_" CONFIG_NETWORKING=y CONFIG_NET_LOG=y CONFIG_NET_NATIVE=y CONFIG_NET_UDP=y CONFIG_NET_TCP=y CONFIG_NET_IPV4=y CONFIG_NET_IPV6=n CONFIG_NET_SOCKETS_OFFLOAD=n CONFIG_NET_SOCKETS=y CONFIG_NET_SOCKETS_POSIX_NAMES=n CONFIG_NET_SOCKETS_POLL_MAX=4 CONFIG_NET_DHCPV4=y CONFIG_NET_SOCKETS_SOCKOPT_TLS=y CONFIG_NET_TCP_ISN_RFC6528=n CONFIG_NET_TCP_MAX_SEND_WINDOW_SIZE=1152 CONFIG_NET_CONTEXT_RCVTIMEO=y CONFIG_NET_CONTEXT_SNDTIMEO=y CONFIG_NET_MAX_CONN=8 CONFIG_NET_MAX_CONTEXTS=8 CONFIG_NET_PKT_TX_COUNT=42 CONFIG_NET_PKT_RX_COUNT=42 CONFIG_NET_BUF_DATA_SIZE=256
This works fine and stable in the field. I added two log files that show the TSL handshake in that case (not complete) - one with MBED TLS debug enabled, one with TCP debug enabled.
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
[00:00:15.971,343] <inf> socket_manager: DNS resolved successfully
[00:00:15.971,405] <inf> socket_manager: IP address of assets.yyyyyyy.xxxxxxxx.com is 18.159.121.71
[00:00:15.971,435] <inf> socket_manager: Trying to access 18.159.121.71 on port 443
[00:00:15.971,618] <dbg> net_sock_tls: tls_alloc: (xxxxxxxx_com): Allocated TLS context, 0x20018714
[00:00:15.971,893] <dbg> net_tcp: tcp_conn_ref: (xxxxxxxx_com): conn: 0x2003ad64, ref_count: 1
[00:00:15.971,923] <dbg> net_tcp: tcp_conn_alloc: (xxxxxxxx_com): conn: 0x2003ad64
[00:00:15.972,137] <dbg> net_sock: zsock_socket_internal: (xxxxxxxx_com): socket: ctx=0x200164e0, fd=4
[00:00:15.972,259] <inf> socket_manager: Set TLS socketopt successful
[00:00:15.972,503] <dbg> net_tcp: net_tcp_connect: (xxxxxxxx_com): context: 0x200164e0, local: 0.0.0.0, remote: 18.159.121.71
[00:00:15.972,900] <dbg> net_tcp: net_tcp_connect: (xxxxxxxx_com): conn: 0x2003ad64 src: 172.20.10.9, dst: 18.159.121.71
[00:00:15.973,052] <dbg> net_tcp: tcp_in: (xxxxxxxx_com): [LISTEN Seq=488095434 Ack=0]
[00:00:15.973,724] <dbg> net_tcp: tcp_send: (xxxxxxxx_com): SYN Seq=488095434 Len=0
[00:00:15.974,060] <dbg> net_tcp: tcp_in: (xxxxxxxx_com): LISTEN->SYN_SENT
[00:00:16.078,521] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN,ACK Seq=3671282458 Ack=488095435 Len=0 [SYN_SENT Seq=488095435 Ack=0]
[00:00:16.078,582] <dbg> net_tcp: tcp_options_check: (rx_q[0]): len=4
[00:00:16.078,613] <dbg> net_tcp: tcp_options_check: (rx_q[0]): opt: 2, opt_len: 4
[00:00:16.078,643] <dbg> net_tcp: tcp_options_check: (rx_q[0]): MSS=1410
[00:00:16.078,674] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 29200 to 1280
[00:00:16.078,704] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
[00:00:15.971,343] <inf> socket_manager: DNS resolved successfully [00:00:15.971,405] <inf> socket_manager: IP address of assets.yyyyyyy.xxxxxxxx.com is 18.159.121.71 [00:00:15.971,435] <inf> socket_manager: Trying to access 18.159.121.71 on port 443 [00:00:15.971,618] <dbg> net_sock_tls: tls_alloc: (xxxxxxxx_com): Allocated TLS context, 0x20018714 [00:00:15.971,893] <dbg> net_tcp: tcp_conn_ref: (xxxxxxxx_com): conn: 0x2003ad64, ref_count: 1 [00:00:15.971,923] <dbg> net_tcp: tcp_conn_alloc: (xxxxxxxx_com): conn: 0x2003ad64 [00:00:15.972,137] <dbg> net_sock: zsock_socket_internal: (xxxxxxxx_com): socket: ctx=0x200164e0, fd=4 [00:00:15.972,259] <inf> socket_manager: Set TLS socketopt successful [00:00:15.972,503] <dbg> net_tcp: net_tcp_connect: (xxxxxxxx_com): context: 0x200164e0, local: 0.0.0.0, remote: 18.159.121.71 [00:00:15.972,900] <dbg> net_tcp: net_tcp_connect: (xxxxxxxx_com): conn: 0x2003ad64 src: 172.20.10.9, dst: 18.159.121.71 [00:00:15.973,052] <dbg> net_tcp: tcp_in: (xxxxxxxx_com): [LISTEN Seq=488095434 Ack=0] [00:00:15.973,724] <dbg> net_tcp: tcp_send: (xxxxxxxx_com): SYN Seq=488095434 Len=0 [00:00:15.974,060] <dbg> net_tcp: tcp_in: (xxxxxxxx_com): LISTEN->SYN_SENT [00:00:16.078,521] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN,ACK Seq=3671282458 Ack=488095435 Len=0 [SYN_SENT Seq=488095435 Ack=0] [00:00:16.078,582] <dbg> net_tcp: tcp_options_check: (rx_q[0]): len=4 [00:00:16.078,613] <dbg> net_tcp: tcp_options_check: (rx_q[0]): opt: 2, opt_len: 4 [00:00:16.078,643] <dbg> net_tcp: tcp_options_check: (rx_q[0]): MSS=1410 [00:00:16.078,674] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 29200 to 1280 [00:00:16.078,704] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:16.078,887] <dbg> net_tcp: tcp_send_timer_cancel: (rx_q[0]): SYN Seq=488095434 Len=0 [00:00:16.079,223] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=488095435 Ack=3671282459 Len=0 [00:00:16.079,406] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=488095435 Ack=3671282459 Len=0 [00:00:16.079,620] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=488095435 Ack=3671282459 Len=0 [00:00:16.079,956] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN_SENT->ESTABLISHED [00:00:16.080,200] <dbg> net_tcp: net_tcp_connect: (xxxxxxxx_com): conn: 0x2003ad64, ret=0 [00:00:16.080,261] <dbg> net_tcp: net_tcp_recv: (xxxxxxxx_com): context: 0x200164e0, cb: 0x2f711, user_data: (nil) [00:00:16.099,700] <dbg> net_tcp: net_tcp_recv: (xxxxxxxx_com): context: 0x200164e0, cb: 0x2f711, user_data: (nil) [00:00:16.099,822] <dbg> net_tcp: tcp_window_full: (xxxxxxxx_com): conn: 0x2003ad64 window_full=0 [00:00:16.099,853] <dbg> net_tcp: net_tcp_queue_data: (xxxxxxxx_com): conn: 0x2003ad64 Queued 122 bytes (total 122) [00:00:16.099,884] <dbg> net_tcp: tcp_unsent_len: (xxxxxxxx_com): unsent_len=122 [00:00:16.100,311] <dbg> net_tcp: tcp_out_ext: (xxxxxxxx_com): ACK,PSH Seq=488095435 Ack=3671282459 Len=122 [00:00:16.100,524] <dbg> net_tcp: tcp_send_process_no_lock: (xxxxxxxx_com): ACK,PSH Seq=488095435 Ack=3671282459 Len=122 [00:00:16.100,769] <dbg> net_tcp: tcp_send: (xxxxxxxx_com): ACK,PSH Seq=488095435 Ack=3671282459 Len=122 [00:00:16.101,226] <dbg> net_tcp: tcp_send_data: (xxxxxxxx_com): conn: 0x2003ad64 total=122, unacked_len=122, send_win=1280, mss=1410 [00:00:16.101,257] <dbg> net_tcp: tcp_send_data: (xxxxxxxx_com): conn: 0x2003ad64 send_data_timer=0, send_data_retries=0 [00:00:16.101,287] <dbg> net_tcp: tcp_unsent_len: (xxxxxxxx_com): unsent_len=0 [00:00:16.101,318] <dbg> net_tcp: tcp_window_full: (xxxxxxxx_com): conn: 0x2003ad64 window_full=0 [00:00:16.132,873] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK Seq=3671282459 Ack=488095557 Len=0 [ESTABLISHED Seq=488095435 Ack=3671282459] [00:00:16.132,904] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 29200 to 1280 [00:00:16.132,965] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:16.132,995] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x2003ad64 len_acked=122 [00:00:16.133,056] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:16.133,087] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x2003ad64 total=0, unacked_len=0, send_win=1280, mss=1410 [00:00:16.133,117] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x2003ad64 send_data_timer=1, send_data_retries=0 [00:00:16.133,148] <dbg> net_tcp: tcp_unsent_len: (rx_q[0]): unsent_len=0 [00:00:16.133,178] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:16.133,850] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK,PSH Seq=3671282459 Ack=488095557 Len=90 [ESTABLISHED Seq=488095557 Ack=3671282459] [00:00:16.133,880] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 29200 to 1280 [00:00:16.133,911] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:16.134,246] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=488095557 Ack=3671282549 Len=0 [00:00:16.134,460] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=488095557 Ack=3671282549 Len=0 [00:00:16.134,674] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=488095557 Ack=3671282549 Len=0 [00:00:16.134,979] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x200164e0, pkt=0x200391e8, st=0, user_data=(nil) [00:00:16.138,214] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK Seq=3671282549 Ack=488095557 Len=1410 [ESTABLISHED Seq=488095557 Ack=3671282549] [00:00:16.138,244] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 29200 to 1280 [00:00:16.138,305] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:16.138,641] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=488095557 Ack=3671283959 Len=0 [00:00:16.138,854] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=488095557 Ack=3671283959 Len=0 [00:00:16.139,099] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=488095557 Ack=3671283959 Len=0 [00:00:16.139,770] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x200164e0, pkt=0x200391e8, st=0, user_data=(nil) [00:00:16.140,472] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK,PSH Seq=3671283959 Ack=488095557 Len=1410 [ESTABLISHED Seq=488095557 Ack=3671283959] [00:00:16.140,502] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 29200 to 1280 [00:00:16.140,533] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:16.140,655] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x200164e0, pkt=0x2003922c, st=0, user_data=(nil) [00:00:16.141,479] <dbg> net_tcp: tcp_out_ext: (xxxxxxxx_com): ACK Seq=488095557 Ack=3671285369 Len=0 [00:00:16.141,693] <dbg> net_tcp: tcp_send_process_no_lock: (xxxxxxxx_com): ACK Seq=488095557 Ack=3671285369 Len=0 [00:00:16.141,906] <dbg> net_tcp: tcp_send: (xxxxxxxx_com): ACK Seq=488095557 Ack=3671285369 Len=0 [00:00:16.172,302] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK Seq=3671285369 Ack=488095557 Len=1410 [ESTABLISHED Seq=488095557 Ack=3671285369] [00:00:16.172,363] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 29200 to 1280 [00:00:16.172,393] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:16.172,729] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=488095557 Ack=3671286779 Len=0 [00:00:16.172,943] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=488095557 Ack=3671286779 Len=0 [00:00:16.173,187] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=488095557 Ack=3671286779 Len=0 [00:00:16.173,492] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x200164e0, pkt=0x2003922c, st=0, user_data=(nil) [00:00:16.203,430] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK,PSH Seq=3671286779 Ack=488095557 Len=788 [ESTABLISHED Seq=488095557 Ack=3671286779] [00:00:16.203,460] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 29200 to 1280 [00:00:16.203,491] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:16.203,857] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=488095557 Ack=3671287567 Len=0 [00:00:16.204,071] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=488095557 Ack=3671287567 Len=0 [00:00:16.204,284] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=488095557 Ack=3671287567 Len=0 [00:00:16.204,620] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x200164e0, pkt=0x2003922c, st=0, user_data=(nil) [00:00:16.346,618] <dbg> net_tcp: net_tcp_recv: (xxxxxxxx_com): context: 0x200164e0, cb: 0x2f711, user_data: (nil) [00:00:16.346,923] <dbg> net_tcp: tcp_window_full: (xxxxxxxx_com): conn: 0x2003ad64 window_full=0 [00:00:16.346,954] <dbg> net_tcp: net_tcp_queue_data: (xxxxxxxx_com): conn: 0x2003ad64 Queued 988 bytes (total 988) [00:00:16.346,984] <dbg> net_tcp: tcp_unsent_len: (xxxxxxxx_com): unsent_len=988 [00:00:16.347,686] <dbg> net_tcp: tcp_out_ext: (xxxxxxxx_com): ACK,PSH Seq=488095557 Ack=3671287567 Len=988 [00:00:16.347,900] <dbg> net_tcp: tcp_send_process_no_lock: (xxxxxxxx_com): ACK,PSH Seq=488095557 Ack=3671287567 Len=988 [00:00:16.348,144] <dbg> net_tcp: tcp_send: (xxxxxxxx_com): ACK,PSH Seq=488095557 Ack=3671287567 Len=988 [00:00:16.349,609] <dbg> net_tcp: tcp_send_data: (xxxxxxxx_com): conn: 0x2003ad64 total=988, unacked_len=988, send_win=1280, mss=1410 [00:00:16.349,639] <dbg> net_tcp: tcp_send_data: (xxxxxxxx_com): conn: 0x2003ad64 send_data_timer=0, send_data_retries=0 [00:00:16.349,670] <dbg> net_tcp: tcp_unsent_len: (xxxxxxxx_com): unsent_len=0 [00:00:16.349,731] <dbg> net_tcp: tcp_window_full: (xxxxxxxx_com): conn: 0x2003ad64 window_full=0 [00:00:16.377,288] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK Seq=3671287567 Ack=488096545 Len=0 [ESTABLISHED Seq=488095557 Ack=3671287567] [00:00:16.377,319] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 31616 to 1280 [00:00:16.377,380] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:16.377,410] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x2003ad64 len_acked=988 [00:00:16.377,471] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:16.377,532] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x2003ad64 total=0, unacked_len=0, send_win=1280, mss=1410 [00:00:16.377,563] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x2003ad64 send_data_timer=1, send_data_retries=0 [00:00:16.377,593] <dbg> net_tcp: tcp_unsent_len: (rx_q[0]): unsent_len=0 [00:00:16.377,624] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:16.443,847] <dbg> net_tcp: net_tcp_recv: (xxxxxxxx_com): context: 0x200164e0, cb: 0x2f711, user_data: (nil) [00:00:16.444,000] <dbg> net_tcp: tcp_window_full: (xxxxxxxx_com): conn: 0x2003ad64 window_full=0 [00:00:16.444,030] <dbg> net_tcp: net_tcp_queue_data: (xxxxxxxx_com): conn: 0x2003ad64 Queued 267 bytes (total 267) [00:00:16.444,061] <dbg> net_tcp: tcp_unsent_len: (xxxxxxxx_com): unsent_len=267 [00:00:16.444,519] <dbg> net_tcp: tcp_out_ext: (xxxxxxxx_com): ACK,PSH Seq=488096545 Ack=3671287567 Len=267 [00:00:16.444,763] <dbg> net_tcp: tcp_send_process_no_lock: (xxxxxxxx_com): ACK,PSH Seq=488096545 Ack=3671287567 Len=267 [00:00:16.444,976] <dbg> net_tcp: tcp_send: (xxxxxxxx_com): ACK,PSH Seq=488096545 Ack=3671287567 Len=267 [00:00:16.445,617] <dbg> net_tcp: tcp_send_data: (xxxxxxxx_com): conn: 0x2003ad64 total=267, unacked_len=267, send_win=1280, mss=1410 [00:00:16.445,648] <dbg> net_tcp: tcp_send_data: (xxxxxxxx_com): conn: 0x2003ad64 send_data_timer=0, send_data_retries=0 [00:00:16.445,678] <dbg> net_tcp: tcp_unsent_len: (xxxxxxxx_com): unsent_len=0 [00:00:16.445,709] <dbg> net_tcp: tcp_window_full: (xxxxxxxx_com): conn: 0x2003ad64 window_full=0 [00:00:16.472,076] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK Seq=3671287567 Ack=488096812 Len=0 [ESTABLISHED Seq=488096545 Ack=3671287567] [00:00:16.472,106] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 33592 to 1280 [00:00:16.472,137] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:16.472,198] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x2003ad64 len_acked=267 [00:00:16.472,259] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:16.472,290] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x2003ad64 total=0, unacked_len=0, send_win=1280, mss=1410 [00:00:16.472,320] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x2003ad64 send_data_timer=1, send_data_retries=0 [00:00:16.472,351] <dbg> net_tcp: tcp_unsent_len: (rx_q[0]): unsent_len=0 [00:00:16.472,381] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:17.338,012] <dbg> net_tcp: net_tcp_recv: (xxxxxxxx_com): context: 0x200164e0, cb: 0x2f711, user_data: (nil) [00:00:17.338,134] <dbg> net_tcp: tcp_window_full: (xxxxxxxx_com): conn: 0x2003ad64 window_full=0 [00:00:17.338,165] <dbg> net_tcp: net_tcp_queue_data: (xxxxxxxx_com): conn: 0x2003ad64 Queued 84 bytes (total 84) [00:00:17.338,195] <dbg> net_tcp: tcp_unsent_len: (xxxxxxxx_com): unsent_len=84 [00:00:17.338,592] <dbg> net_tcp: tcp_out_ext: (xxxxxxxx_com): ACK,PSH Seq=488096812 Ack=3671287567 Len=84 [00:00:17.338,806] <dbg> net_tcp: tcp_send_process_no_lock: (xxxxxxxx_com): ACK,PSH Seq=488096812 Ack=3671287567 Len=84 [00:00:17.339,050] <dbg> net_tcp: tcp_send: (xxxxxxxx_com): ACK,PSH Seq=488096812 Ack=3671287567 Len=84 [00:00:17.339,447] <dbg> net_tcp: tcp_send_data: (xxxxxxxx_com): conn: 0x2003ad64 total=84, unacked_len=84, send_win=1280, mss=1410 [00:00:17.339,477] <dbg> net_tcp: tcp_send_data: (xxxxxxxx_com): conn: 0x2003ad64 send_data_timer=0, send_data_retries=0 [00:00:17.339,508] <dbg> net_tcp: tcp_unsent_len: (xxxxxxxx_com): unsent_len=0 [00:00:17.339,569] <dbg> net_tcp: tcp_window_full: (xxxxxxxx_com): conn: 0x2003ad64 window_full=0 [00:00:17.339,630] <dbg> net_tcp: net_tcp_recv: (xxxxxxxx_com): context: 0x200164e0, cb: 0x2f711, user_data: (nil) [00:00:17.339,752] <dbg> net_tcp: tcp_window_full: (xxxxxxxx_com): conn: 0x2003ad64 window_full=0 [00:00:17.339,782] <dbg> net_tcp: net_tcp_queue_data: (xxxxxxxx_com): conn: 0x2003ad64 Queued 6 bytes (total 90) [00:00:17.339,813] <dbg> net_tcp: tcp_unsent_len: (xxxxxxxx_com): unsent_len=6 [00:00:17.339,843] <dbg> net_tcp: tcp_unsent_len: (xxxxxxxx_com): unsent_len=6 [00:00:17.339,874] <dbg> net_tcp: tcp_window_full: (xxxxxxxx_com): conn: 0x2003ad64 window_full=0 [00:00:17.341,796] <dbg> net_tcp: net_tcp_recv: (xxxxxxxx_com): context: 0x200164e0, cb: 0x2f711, user_data: (nil) [00:00:17.341,888] <dbg> net_tcp: tcp_window_full: (xxxxxxxx_com): conn: 0x2003ad64 window_full=0 [00:00:17.341,949] <dbg> net_tcp: net_tcp_queue_data: (xxxxxxxx_com): conn: 0x2003ad64 Queued 45 bytes (total 135) [00:00:17.341,979] <dbg> net_tcp: tcp_unsent_len: (xxxxxxxx_com): unsent_len=51 [00:00:17.342,010] <dbg> net_tcp: tcp_unsent_len: (xxxxxxxx_com): unsent_len=51 [00:00:17.342,041] <dbg> net_tcp: tcp_window_full: (xxxxxxxx_com): conn: 0x2003ad64 window_full=0 [00:00:17.393,554] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK Seq=3671287567 Ack=488096896 Len=0 [ESTABLISHED Seq=488096812 Ack=3671287567] [00:00:17.393,585] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 33592 to 1280 [00:00:17.393,646] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:17.393,676] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x2003ad64 len_acked=84 [00:00:17.393,737] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:17.393,768] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x2003ad64 total=51, unacked_len=0, send_win=1280, mss=1410 [00:00:17.393,798] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x2003ad64 send_data_timer=1, send_data_retries=0 [00:00:17.393,829] <dbg> net_tcp: tcp_unsent_len: (rx_q[0]): unsent_len=51 [00:00:17.394,256] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK,PSH Seq=488096896 Ack=3671287567 Len=51 [00:00:17.394,470] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK,PSH Seq=488096896 Ack=3671287567 Len=51 [00:00:17.394,714] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK,PSH Seq=488096896 Ack=3671287567 Len=51 [00:00:17.395,080] <dbg> net_tcp: tcp_send_data: (rx_q[0]): conn: 0x2003ad64 total=51, unacked_len=51, send_win=1280, mss=1410 [00:00:17.395,111] <dbg> net_tcp: tcp_send_data: (rx_q[0]): conn: 0x2003ad64 send_data_timer=0, send_data_retries=0 [00:00:17.395,141] <dbg> net_tcp: tcp_unsent_len: (rx_q[0]): unsent_len=0 [00:00:17.395,202] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:17.417,083] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK Seq=3671287567 Ack=488096947 Len=0 [ESTABLISHED Seq=488096896 Ack=3671287567] [00:00:17.417,114] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 33592 to 1280 [00:00:17.417,144] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:17.417,205] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x2003ad64 len_acked=51 [00:00:17.417,266] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:17.417,297] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x2003ad64 total=0, unacked_len=0, send_win=1280, mss=1410 [00:00:17.417,327] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x2003ad64 send_data_timer=1, send_data_retries=0 [00:00:17.417,388] <dbg> net_tcp: tcp_unsent_len: (rx_q[0]): unsent_len=0 [00:00:17.417,419] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:17.423,248] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK,PSH Seq=3671287567 Ack=488096947 Len=6 [ESTABLISHED Seq=488096947 Ack=3671287567] [00:00:17.423,278] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 33592 to 1280 [00:00:17.423,309] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:17.423,675] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=488096947 Ack=3671287573 Len=0 [00:00:17.423,889] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=488096947 Ack=3671287573 Len=0 [00:00:17.424,102] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=488096947 Ack=3671287573 Len=0 [00:00:17.424,438] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x200164e0, pkt=0x2003922c, st=0, user_data=(nil) [00:00:17.426,391] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK,PSH Seq=3671287573 Ack=488096947 Len=45 [ESTABLISHED Seq=488096947 Ack=3671287573] [00:00:17.426,422] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 33592 to 1280 [00:00:17.426,452] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:17.426,818] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=488096947 Ack=3671287618 Len=0 [00:00:17.427,032] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=488096947 Ack=3671287618 Len=0 [00:00:17.427,246] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=488096947 Ack=3671287618 Len=0 [00:00:17.427,551] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x200164e0, pkt=0x2003922c, st=0, user_data=(nil) [00:00:17.429,107] <inf> xxxxxxxx_cloud_client: HTTP GET request on assets.yyyyyyy.xxxxxxxx.com/v1 [00:00:17.429,809] <dbg> net_tcp: net_tcp_recv: (xxxxxxxx_com): context: 0x200164e0, cb: 0x2f711, user_data: (nil) [00:00:17.429,901] <dbg> net_tcp: tcp_window_full: (xxxxxxxx_com): conn: 0x2003ad64 window_full=0 [00:00:17.429,962] <dbg> net_tcp: net_tcp_queue_data: (xxxxxxxx_com): conn: 0x2003ad64 Queued 133 bytes (total 133) [00:00:17.429,992] <dbg> net_tcp: tcp_unsent_len: (xxxxxxxx_com): unsent_len=133 [00:00:17.430,389] <dbg> net_tcp: tcp_out_ext: (xxxxxxxx_com): ACK,PSH Seq=488096947 Ack=3671287618 Len=133 [00:00:17.430,633] <dbg> net_tcp: tcp_send_process_no_lock: (xxxxxxxx_com): ACK,PSH Seq=488096947 Ack=3671287618 Len=133 [00:00:17.430,847] <dbg> net_tcp: tcp_send: (xxxxxxxx_com): ACK,PSH Seq=488096947 Ack=3671287618 Len=133 [00:00:17.431,304] <dbg> net_tcp: tcp_send_data: (xxxxxxxx_com): conn: 0x2003ad64 total=133, unacked_len=133, send_win=1280, mss=1410 [00:00:17.431,365] <dbg> net_tcp: tcp_send_data: (xxxxxxxx_com): conn: 0x2003ad64 send_data_timer=0, send_data_retries=0 [00:00:17.431,396] <dbg> net_tcp: tcp_unsent_len: (xxxxxxxx_com): unsent_len=0 [00:00:17.431,427] <dbg> net_tcp: tcp_window_full: (xxxxxxxx_com): conn: 0x2003ad64 window_full=0 [00:00:17.519,226] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK Seq=3671287618 Ack=488097080 Len=0 [ESTABLISHED Seq=488096947 Ack=3671287618] [00:00:17.519,256] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 35568 to 1280 [00:00:17.519,287] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:17.519,348] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x2003ad64 len_acked=133 [00:00:17.519,378] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:17.519,409] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x2003ad64 total=0, unacked_len=0, send_win=1280, mss=1410 [00:00:17.519,439] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x2003ad64 send_data_timer=1, send_data_retries=0 [00:00:17.519,500] <dbg> net_tcp: tcp_unsent_len: (rx_q[0]): unsent_len=0 [00:00:17.519,531] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:17.624,298] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK,PSH Seq=3671287618 Ack=488097080 Len=746 [ESTABLISHED Seq=488097080 Ack=3671287618] [00:00:17.624,328] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 35568 to 1280 [00:00:17.624,359] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x2003ad64 window_full=0 [00:00:17.624,725] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=488097080 Ack=3671288364 Len=0 [00:00:17.624,938] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=488097080 Ack=3671288364 Len=0 [00:00:17.625,152] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=488097080 Ack=3671288364 Len=0 [00:00:17.625,457] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x200164e0, pkt=0x2003922c, st=0, user_data=(nil) [00:00:17.629,516] <inf> xxxxxxxx_cloud_client: All response data received (717 bytes) [00:00:17.629,547] <inf> xxxxxxxx_cloud_client: Appending data to a total of 27. [00:00:17.629,577] <inf> xxxxxxxx_cloud_client: Response status OK [00:00:17.629,608] <inf> xxxxxxxx_cloud_client: Request finished. Sent 104, received (27/27). [00:00:17.629,669] <inf> xxxxxxxx_cloud_client: mTLS current_time: 1669638406
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
[00:00:27.729,858] <inf> socket_manager: DNS resolved successfully
[00:00:27.729,919] <inf> socket_manager: IP address of assets.yyyyyyy.xxxxxx.com is 18.159.99.150
[00:00:27.729,949] <inf> socket_manager: Trying to access 18.159.99.150 on port 443
[00:00:27.730,133] <dbg> net_sock_tls: tls_alloc: (xxxxxx_com): Allocated TLS context, 0x20017c70
[00:00:27.730,590] <dbg> net_sock: zsock_socket_internal: (xxxxxx_com): socket: ctx=0x20015a38, fd=4
[00:00:27.730,712] <inf> socket_manager: Set TLS socketopt successful
[00:00:27.788,787] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_tls.c:5312: |2| => handshake
[00:00:27.788,848] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1789: |2| => flush output
[00:00:27.788,940] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1801: |2| <= flush output
[00:00:27.789,001] <dbg> net_sock_tls:com): [00:00:27.789,062] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1789: |2| => flush output
[00:00:27.789,123] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1801: |2| <= flush output
[00:00:27.789,215] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:4192: |2| client state: 1
[00:00:27.789,276] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:0933: |2| => write client hello
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
[00:00:27.729,858] <inf> socket_manager: DNS resolved successfully [00:00:27.729,919] <inf> socket_manager: IP address of assets.yyyyyyy.xxxxxx.com is 18.159.99.150 [00:00:27.729,949] <inf> socket_manager: Trying to access 18.159.99.150 on port 443 [00:00:27.730,133] <dbg> net_sock_tls: tls_alloc: (xxxxxx_com): Allocated TLS context, 0x20017c70 [00:00:27.730,590] <dbg> net_sock: zsock_socket_internal: (xxxxxx_com): socket: ctx=0x20015a38, fd=4 [00:00:27.730,712] <inf> socket_manager: Set TLS socketopt successful [00:00:27.788,787] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_tls.c:5312: |2| => handshake [00:00:27.788,848] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1789: |2| => flush output [00:00:27.788,940] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1801: |2| <= flush output [00:00:27.789,001] <dbg> net_sock_tls:com): [00:00:27.789,062] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1789: |2| => flush output [00:00:27.789,123] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1801: |2| <= flush output [00:00:27.789,215] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:4192: |2| client state: 1 [00:00:27.789,276] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:0933: |2| => write client hello [00:00:27.789,520] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:0855: |3| client hello, current time: 1669639809 [00:00:27.789,855] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:0998: |3| dumping 'client hello, random bytes' (32 bytes) [00:00:27.790,313] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:0998: |3| 0000: 63 84 ae 81 d2 ee eb 8e d1 e9 99 c2 dd aa 4e 0a c.............N. [00:00:27.790,771] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:0998: |3| 0010: 43 e1 49 0d e3 9b d2 14 6b 70 8d 32 ba c0 c5 74 C.I.....kp.2...t [00:00:27.790,893] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:1058: |3| client hello, session id len.: 0 [00:00:27.790,985] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:1059: |3| dumping 'client hello, session id' (0 bytes) [00:00:27.791,137] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:1125: |3| client hello, add ciphersuite: 0x9d (TLS-RSA-WITH-AES-256-GCM-SHA384) [00:00:27.791,259] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:1125: |3| client hello, add ciphersuite: 0x3d (TLS-RSA-WITH-AES-256-CBC-SHA256) [00:00:27.791,412] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:1125: |3| client hello, add ciphersuite: 0x35 (TLS-RSA-WITH-AES-256-CBC-SHA) [00:00:27.791,534] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:1125: |3| client hello, add ciphersuite: 0x9c (TLS-RSA-WITH-AES-128-GCM-SHA256) [00:00:27.791,687] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:1125: |3| client hello, add ciphersuite: 0x3c (TLS-RSA-WITH-AES-128-CBC-SHA256) [00:00:27.791,839] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:1125: |3| client hello, add ciphersuite: 0x2f (TLS-RSA-WITH-AES-128-CBC-SHA) [00:00:27.791,931] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:1140: |3| client hello, got 6 ciphersuites (excluding SCSVs) [00:00:27.792,022] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:1150: |3| adding EMPTY_RENEGOTIATION_INFO_SCSV [00:00:27.792,114] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:1160: |3| client hello, compress len.: 1 [00:00:27.792,205] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:1161: |3| client hello, compress alg.: 0 [00:00:27.792,327] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:0107: |3| client hello, adding server name extension: assets.yyyyyyy.xxxxxx.com [00:00:27.792,419] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:0225: |3| client hello, adding signature_algorithms extension [00:00:27.792,541] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:1309: |3| client hello, total extension length: 58 [00:00:27.792,602] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:2218: |2| => write handshake message [00:00:27.792,785] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:2369: |2| => write record [00:00:27.792,968] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:2458: |3| output record: msgtype = 22, version = [3:3], msglen = 117 [00:00:27.793,029] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1789: |2| => flush output [00:00:27.793,151] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1807: |2| message length: 122, out_left: 122 [00:00:27.794,067] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1814: |2| ssl->f_send() returned 122 (-0xffffff86) [00:00:27.794,128] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1842: |2| <= flush output [00:00:27.794,219] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:2514: |2| <= write record [00:00:27.794,494] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:2346: |2| <= write handshake message [00:00:27.794,555] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:1346: |2| <= write client hello [00:00:27.794,647] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1789: |2| => flush output [00:00:27.794,708] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1801: |2| <= flush output [00:00:27.794,769] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:4192: |2| client state: 2 [00:00:27.794,860] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:1919: |2| => parse server hello [00:00:27.794,921] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:3546: |2| => read record [00:00:27.794,982] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1573: |2| => fetch input [00:00:27.795,104] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1728: |2| in_left: 0, nb_want: 5 [00:00:27.865,020] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x20015a38, pkt=0x20039284, st=0, user_data=(nil) [00:00:27.868,194] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x20015a38, pkt=0x20039240, st=0, user_data=(nil) [00:00:27.868,621] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x20015a38, pkt=0x200391fc, st=0, user_data=(nil) [00:00:27.868,927] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1753: |2| in_left: 0, nb_want: 5 [00:00:27.869,079] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1756: |2| ssl->f_recv(_timeout)() returned 5 (-0xfffffffb) [00:00:27.869,140] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1776: |2| <= fetch input [00:00:27.869,323] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:3281: |3| input record: msgtype = 22, version = [3:3], msglen = 85 [00:00:27.869,384] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1573: |2| => fetch input [00:00:27.869,476] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1728: |2| in_left: 5, nb_want: 90 [00:00:27.869,659] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1753: |2| in_left: 5, nb_want: 90 [00:00:27.869,812] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1756: |2| ssl->f_recv(_timeout)() returned 85 (-0xffffffab) [00:00:27.869,873] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1776: |2| <= fetch input [00:00:27.870,025] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:2662: |3| handshake message: msglen = 85, type = 2, hslen = 85 [00:00:27.870,574] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:3620: |2| <= read record [00:00:27.870,697] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:2002: |3| dumping 'server hello, version' (2 bytes) [00:00:27.870,880] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:2002: |3| 0000: 03 03 .. [00:00:27.871,002] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:2026: |3| server hello, current time: 2123527078 [00:00:27.871,124] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:2036: |3| dumping 'server hello, random bytes' (32 bytes) [00:00:27.871,582] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:2036: |3| 0000: 7e 92 73 a6 ef 8a cf 16 a1 6f 69 42 44 d8 ea 30 ~.s......oiBD..0 [00:00:27.872,070] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:2036: |3| 0010: cf 44 48 ef 26 e3 d3 84 b2 06 33 c6 32 65 43 1b .DH.&.....3.2eC. [00:00:27.872,161] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:2108: |3| server hello, session id len.: 32 [00:00:27.872,283] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:2109: |3| dumping 'server hello, session id' (32 bytes) [00:00:27.872,741] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:2109: |3| 0000: 92 f0 4c a3 03 67 3e 5e 65 ff 50 2c fb 1c 04 26 ..L..g>^e.P,...& [00:00:27.873,199] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:2109: |3| 0010: 4f 5a 71 95 96 ca 16 2d 71 a7 55 61 31 02 3b 42 OZq....-q.Ua1.;B [00:00:27.873,321] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:2148: |3| no session has been resumed [00:00:27.873,413] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:2151: |3| server hello, chosen ciphersuite: 009c [00:00:27.873,504] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:2152: |3| server hello, compress alg.: 0 [00:00:27.873,626] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:2191: |3| server hello, chosen ciphersuite: TLS-RSA-WITH-AES-128-GCM-SHA256 [00:00:27.873,718] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:2216: |2| server hello, total extension length: 9 [00:00:27.873,809] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:2367: |3| unknown extension found: 0 (ignoring) [00:00:27.873,901] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:2238: |3| found renegotiation extension [00:00:27.873,962] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:2428: |2| <= parse server hello [00:00:27.874,023] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1789: |2| => flush output [00:00:27.874,084] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1801: |2| <= flush output [00:00:27.874,176] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_cli.c:4192: |2| client state: 3 [00:00:27.874,237] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_tls.c:2291: |2| => parse certificate [00:00:27.874,298] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:3546: |2| => read record [00:00:27.874,359] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1573: |2| => fetch input [00:00:27.874,481] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1728: |2| in_left: 0, nb_want: 5 [00:00:27.874,633] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1753: |2| in_left: 0, nb_want: 5 [00:00:27.874,786] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1756: |2| ssl->f_recv(_timeout)() returned 5 (-0xfffffffb) [00:00:27.874,847] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1776: |2| <= fetch input [00:00:27.875,000] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:3281: |3| input record: msgtype = 22, version = [3:3], msglen = 4968 [00:00:27.875,061] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1573: |2| => fetch input [00:00:27.875,183] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1728: |2| in_left: 5, nb_want: 4973 [00:00:27.875,976] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1753: |2| in_left: 5, nb_want: 4973 [00:00:27.876,373] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1756: |2| ssl->f_recv(_timeout)() returned 1405 (-0xfffffa83) [00:00:27.876,770] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1753: |2| in_left: 1410, nb_want: 4973 [00:00:27.876,953] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1756: |2| ssl->f_recv(_timeout)() returned 1410 (-0xfffffa7e) [00:00:27.925,933] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x20015a38, pkt=0x200391fc, st=0, user_data=(nil) [00:00:27.926,330] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1753: |2| in_left: 2820, nb_want: 4973 [00:00:27.926,483] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1756: |2| ssl->f_recv(_timeout)() returned 1410 (-0xfffffa7e) [00:00:27.953,277] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x20015a38, pkt=0x200391fc, st=0, user_data=(nil) [00:00:27.953,552] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1753: |2| in_left: 4230, nb_want: 4973 [00:00:27.953,704] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1756: |2| ssl->f_recv(_timeout)() returned 743 (-0xfffffd19) [00:00:27.953,765] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:1776: |2| <= fetch input [00:00:27.953,948] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:2662: |3| handshake message: msglen = 4968, type = 11, hslen = 4968 [00:00:27.961,456] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_msg.c:3620: |2| <= read record [00:00:27.963,439] <dbg> net_sock_tls: tls_debug: (xxxxxx_com): ssl_tls.c:1976: |3| peer certificate #1: ... ...
Now, we want to migrate from TFM using the following KConfig:
Fullscreen
1
2
3
4
5
6
7
8
9
10
CONFIG_BUILD_WITH_TFM=y
CONFIG_MBEDTLS_TLS_LIBRARY=y
CONFIG_MBEDTLS_X509_CSR_WRITE_C=y
CONFIG_MBEDTLS_X509_CREATE_C=y
CONFIG_MBEDTLS_PK_WRITE_C=y
CONFIG_MBEDTLS_ECP_C=y
CONFIG_BASE64=y
CONFIG_MBEDTLS_ENABLE_HEAP=y
CONFIG_MBEDTLS_HEAP_SIZE=59000
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
CONFIG_BUILD_WITH_TFM=y CONFIG_MBEDTLS_TLS_LIBRARY=y CONFIG_MBEDTLS_X509_CSR_WRITE_C=y CONFIG_MBEDTLS_X509_CREATE_C=y CONFIG_MBEDTLS_PK_WRITE_C=y CONFIG_MBEDTLS_ECP_C=y CONFIG_BASE64=y CONFIG_MBEDTLS_ENABLE_HEAP=y CONFIG_MBEDTLS_HEAP_SIZE=59000
(Notworking KConfig stays the same)
I get a 'net_sock_tls: TLS handshake error: -4c' right at the beginning. I understand that enabling TFM will implicitly enable a custom nordic security backend that is substantially different to the MBED TLS backend used with SPM.
How can i understand the differences between the old MbedTLS config coming with SPM and the new one when using TFM?
Could you take a look at the logs andhelp me understand what part of the TLS handshake goes wrong? Which KConfig is needed to make it work again? Here are the logs with TFM
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
[00:01:46.739,746] <inf> socket_manager: DNS resolved successfully
[00:01:46.739,807] <inf> socket_manager: IP address of assets.yyyyyyyy.xxxxxxxx.com is 18.159.99.150
[00:01:46.739,837] <inf> socket_manager: Trying to access 18.159.99.150 on port 443
[00:01:46.739,990] <dbg> net_sock_tls: tls_alloc: (xxxxxxxx_com): Allocated TLS context, 0x20015b3c
[00:01:46.740,295] <dbg> net_tcp: tcp_conn_ref: (xxxxxxxx_com): conn: 0x20038634, ref_count: 1
[00:01:46.740,325] <dbg> net_tcp: tcp_conn_alloc: (xxxxxxxx_com): conn: 0x20038634
[00:01:46.740,905] <dbg> net_sock: zsock_socket_internal: (xxxxxxxx_com): socket: ctx=0x200136d8, fd=4
[00:01:46.741,027] <inf> socket_manager: Set TLS socketopt successful
[00:01:46.741,638] <dbg> net_tcp: net_tcp_connect: (xxxxxxxx_com): context: 0x200136d8, local: 0.0.0.0, remote: 18.159.99.150
[00:01:46.742,797] <dbg> net_tcp: net_tcp_connect: (xxxxxxxx_com): conn: 0x20038634 src: 172.20.10.9, dst: 18.159.99.150
[00:01:46.742,950] <dbg> net_tcp: tcp_in: (xxxxxxxx_com): [LISTEN Seq=3189679833 Ack=0]
[00:01:46.743,225] <dbg> net_tcp: tcp_out_ext: (xxxxxxxx_com): SYN Seq=3189679833 Len=0
[00:01:46.743,377] <dbg> net_tcp: tcp_send_process_no_lock: (xxxxxxxx_com): SYN Seq=3189679833 Len=0
[00:01:46.743,621] <dbg> net_tcp: tcp_send: (xxxxxxxx_com): SYN Seq=3189679833 Len=0
[00:01:46.743,957] <dbg> net_tcp: tcp_in: (xxxxxxxx_com): LISTEN->SYN_SENT
[00:01:46.911,926] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN,ACK Seq=602829136 Ack=3189679834 Len=0 [SYN_SENT Seq=3189679834 Ack=0]
[00:01:46.911,987] <dbg> net_tcp: tcp_options_check: (rx_q[0]): len=4
[00:01:46.912,017] <dbg> net_tcp: tcp_options_check: (rx_q[0]): opt: 2, opt_len: 4
[00:01:46.912,048] <dbg> net_tcp: tcp_options_check: (rx_q[0]): MSS=1410
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
[00:01:46.739,746] <inf> socket_manager: DNS resolved successfully [00:01:46.739,807] <inf> socket_manager: IP address of assets.yyyyyyyy.xxxxxxxx.com is 18.159.99.150 [00:01:46.739,837] <inf> socket_manager: Trying to access 18.159.99.150 on port 443 [00:01:46.739,990] <dbg> net_sock_tls: tls_alloc: (xxxxxxxx_com): Allocated TLS context, 0x20015b3c [00:01:46.740,295] <dbg> net_tcp: tcp_conn_ref: (xxxxxxxx_com): conn: 0x20038634, ref_count: 1 [00:01:46.740,325] <dbg> net_tcp: tcp_conn_alloc: (xxxxxxxx_com): conn: 0x20038634 [00:01:46.740,905] <dbg> net_sock: zsock_socket_internal: (xxxxxxxx_com): socket: ctx=0x200136d8, fd=4 [00:01:46.741,027] <inf> socket_manager: Set TLS socketopt successful [00:01:46.741,638] <dbg> net_tcp: net_tcp_connect: (xxxxxxxx_com): context: 0x200136d8, local: 0.0.0.0, remote: 18.159.99.150 [00:01:46.742,797] <dbg> net_tcp: net_tcp_connect: (xxxxxxxx_com): conn: 0x20038634 src: 172.20.10.9, dst: 18.159.99.150 [00:01:46.742,950] <dbg> net_tcp: tcp_in: (xxxxxxxx_com): [LISTEN Seq=3189679833 Ack=0] [00:01:46.743,225] <dbg> net_tcp: tcp_out_ext: (xxxxxxxx_com): SYN Seq=3189679833 Len=0 [00:01:46.743,377] <dbg> net_tcp: tcp_send_process_no_lock: (xxxxxxxx_com): SYN Seq=3189679833 Len=0 [00:01:46.743,621] <dbg> net_tcp: tcp_send: (xxxxxxxx_com): SYN Seq=3189679833 Len=0 [00:01:46.743,957] <dbg> net_tcp: tcp_in: (xxxxxxxx_com): LISTEN->SYN_SENT [00:01:46.911,926] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN,ACK Seq=602829136 Ack=3189679834 Len=0 [SYN_SENT Seq=3189679834 Ack=0] [00:01:46.911,987] <dbg> net_tcp: tcp_options_check: (rx_q[0]): len=4 [00:01:46.912,017] <dbg> net_tcp: tcp_options_check: (rx_q[0]): opt: 2, opt_len: 4 [00:01:46.912,048] <dbg> net_tcp: tcp_options_check: (rx_q[0]): MSS=1410 [00:01:46.912,078] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 29200 to 1280 [00:01:46.912,109] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x20038634 window_full=0 [00:01:46.912,292] <dbg> net_tcp: tcp_send_timer_cancel: (rx_q[0]): SYN Seq=3189679833 Len=0 [00:01:46.912,628] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=3189679834 Ack=602829137 Len=0 [00:01:46.912,841] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=3189679834 Ack=602829137 Len=0 [00:01:46.913,055] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=3189679834 Ack=602829137 Len=0 [00:01:46.913,360] <dbg> net_tcp: tcp_in: (rx_q[0]): SYN_SENT->ESTABLISHED [00:01:46.913,421] <dbg> net_tcp: net_tcp_connect: (xxxxxxxx_com): conn: 0x20038634, ret=0 [00:01:46.913,482] <dbg> net_tcp: net_tcp_recv: (xxxxxxxx_com): context: 0x200136d8, cb: 0x30cc5, user_data: (nil) [00:01:46.925,109] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_tls.c:3211: |4| The SSL configuration is tls12 only. [00:01:46.929,229] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_tls.c:5312: |2| => handshake [00:01:46.929,290] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:1964: |2| => flush output [00:01:46.929,351] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:1976: |2| <= flush output [00:01:46.929,412] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:4192: |2| client state: 0 [00:01:46.929,473] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:1964: |2| => flush output [00:01:46.929,534] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:1976: |2| <= flush output [00:01:46.929,626] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:4192: |2| client state: 1 [00:01:46.929,687] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:0933: |2| => write client hello [00:01:46.929,779] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:0988: |3| client hello, max version: [3:3] [00:01:46.930,938] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:0998: |3| dumping 'client hello, random bytes' (32 bytes) [00:01:46.931,427] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:0998: |3| 0000: 25 6d c5 70 e2 80 80 59 65 0d f2 58 d6 0f 5d d9 %m.p...Ye..X..]. [00:01:46.931,884] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:0998: |3| 0010: 77 0b 5c 8e b7 bc c1 55 f5 ad c2 7e 35 0c d4 08 w.\....U...~5... [00:01:46.931,976] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:1058: |3| client hello, session id len.: 0 [00:01:46.932,098] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:1059: |3| dumping 'client hello, session id' (0 bytes) [00:01:46.932,189] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:1140: |3| client hello, got 0 ciphersuites (excluding SCSVs) [00:01:46.932,281] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:1150: |3| adding EMPTY_RENEGOTIATION_INFO_SCSV [00:01:46.932,342] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:1160: |3| client hello, compress len.: 1 [00:01:46.932,434] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:1161: |3| client hello, compress alg.: 0 [00:01:46.932,525] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:0225: |3| client hello, adding signature_algorithms extension [00:01:46.932,617] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:0530: |3| client hello, adding max_fragment_length extension [00:01:46.932,708] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:0592: |3| client hello, adding extended_master_secret extension [00:01:46.932,800] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:1309: |3| client hello, total extension length: 27 [00:01:46.932,861] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:2393: |2| => write handshake message [00:01:46.932,983] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:2544: |2| => write record [00:01:46.933,135] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:2633: |3| output record: msgtype = 22, version = [3:3], msglen = 74 [00:01:46.933,258] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:2638: |4| dumping 'output record sent to network' (79 bytes) [00:01:46.933,715] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:2638: |4| 0000: 16 03 03 00 4a 01 00 00 46 03 03 25 6d c5 70 e2 ....J...F..%m.p. [00:01:46.934,173] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:2638: |4| 0010: 80 80 59 65 0d f2 58 d6 0f 5d d9 77 0b 5c 8e b7 ..Ye..X..].w.\.. [00:01:46.934,661] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:2638: |4| 0020: bc c1 55 f5 ad c2 7e 35 0c d4 08 00 00 02 00 ff ..U...~5........ [00:01:46.935,089] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:2638: |4| 0030: 01 00 00 1b 00 0d 00 0e 00 0c 06 03 06 01 05 03 ................ [00:01:46.935,546] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:2638: |4| 0040: 05 01 04 03 04 01 00 01 00 01 04 00 17 00 00 ............... [00:01:46.935,577] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:1964: |2| => flush output [00:01:46.935,699] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:1982: |2| message length: 79, out_left: 79 [00:01:46.935,760] <dbg> net_tcp: net_tcp_recv: (xxxxxxxx_com): context: 0x200136d8, cb: 0x30cc5, user_data: (nil) [00:01:46.935,852] <dbg> net_tcp: tcp_window_full: (xxxxxxxx_com): conn: 0x20038634 window_full=0 [00:01:46.935,882] <dbg> net_tcp: net_tcp_queue_data: (xxxxxxxx_com): conn: 0x20038634 Queued 79 bytes (total 79) [00:01:46.935,913] <dbg> net_tcp: tcp_unsent_len: (xxxxxxxx_com): unsent_len=79 [00:01:46.936,309] <dbg> net_tcp: tcp_out_ext: (xxxxxxxx_com): ACK,PSH Seq=3189679834 Ack=602829137 Len=79 [00:01:46.936,553] <dbg> net_tcp: tcp_send_process_no_lock: (xxxxxxxx_com): ACK,PSH Seq=3189679834 Ack=602829137 Len=79 [00:01:46.936,798] <dbg> net_tcp: tcp_send: (xxxxxxxx_com): ACK,PSH Seq=3189679834 Ack=602829137 Len=79 [00:01:46.937,194] <dbg> net_tcp: tcp_send_data: (xxxxxxxx_com): conn: 0x20038634 total=79, unacked_len=79, send_win=1280, mss=1410 [00:01:46.937,225] <dbg> net_tcp: tcp_send_data: (xxxxxxxx_com): conn: 0x20038634 send_data_timer=0, send_data_retries=0 [00:01:46.937,255] <dbg> net_tcp: tcp_unsent_len: (xxxxxxxx_com): unsent_len=0 [00:01:46.937,316] <dbg> net_tcp: tcp_window_full: (xxxxxxxx_com): conn: 0x20038634 window_full=0 [00:01:46.937,469] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:1989: |2| ssl->f_send() returned 79 (-0xffffffb1) [00:01:46.937,561] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:2017: |2| <= flush output [00:01:46.937,591] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:2689: |2| <= write record [00:01:46.937,683] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:2521: |2| <= write handshake message [00:01:46.937,744] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:1346: |2| <= write client hello [00:01:46.937,805] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:1964: |2| => flush output [00:01:46.937,866] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:1976: |2| <= flush output [00:01:46.937,927] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:4192: |2| client state: 2 [00:01:46.937,988] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:1919: |2| => parse server hello [00:01:46.938,049] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:3721: |2| => read record [00:01:46.938,110] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:1748: |2| => fetch input [00:01:46.938,446] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:1903: |2| in_left: 0, nb_want: 5 [00:01:46.999,023] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK Seq=602829137 Ack=3189679913 Len=0 [ESTABLISHED Seq=3189679834 Ack=602829137] [00:01:46.999,053] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 29200 to 1280 [00:01:46.999,084] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x20038634 window_full=0 [00:01:46.999,145] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x20038634 len_acked=79 [00:01:46.999,176] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x20038634 window_full=0 [00:01:46.999,237] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x20038634 total=0, unacked_len=0, send_win=1280, mss=1410 [00:01:46.999,267] <dbg> net_tcp: tcp_in: (rx_q[0]): conn: 0x20038634 send_data_timer=1, send_data_retries=0 [00:01:46.999,298] <dbg> net_tcp: tcp_unsent_len: (rx_q[0]): unsent_len=0 [00:01:46.999,328] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x20038634 window_full=0 [00:01:47.000,061] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK,PSH Seq=602829137 Ack=3189679913 Len=7 [ESTABLISHED Seq=3189679913 Ack=602829137] [00:01:47.000,091] <dbg> net_tcp: tcp_in: (rx_q[0]): Lowering send window from 29200 to 1280 [00:01:47.000,122] <dbg> net_tcp: tcp_window_full: (rx_q[0]): conn: 0x20038634 window_full=0 [00:01:47.000,488] <dbg> net_tcp: tcp_out_ext: (rx_q[0]): ACK Seq=3189679913 Ack=602829144 Len=0 [00:01:47.000,701] <dbg> net_tcp: tcp_send_process_no_lock: (rx_q[0]): ACK Seq=3189679913 Ack=602829144 Len=0 [00:01:47.000,915] <dbg> net_tcp: tcp_send: (rx_q[0]): ACK Seq=3189679913 Ack=602829144 Len=0 [00:01:47.001,342] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x200136d8, pkt=0x20036b40, st=0, user_data=(nil) [00:01:47.001,861] <dbg> net_tcp: tcp_in: (rx_q[0]): ACK,RST Seq=602829144 Ack=3189679913 Len=0 [ESTABLISHED Seq=3189679913 Ack=602829144] [00:01:47.001,892] <dbg> net_tcp: tcp_in: (rx_q[0]): ESTABLISHED->CLOSED [00:01:47.001,953] <dbg> net_tcp: tcp_conn_unref_debug: (rx_q[0]): conn: 0x20038634, ref_count=1 (tcp_in():2330) [00:01:47.001,983] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x200136d8, pkt=(nil), st=-104, user_data=(nil) [00:01:47.002,014] <dbg> net_sock: zsock_received_cb: (rx_q[0]): Set EOF flag on pkt 0x20036b40 [00:01:47.002,166] <err> net_tcp: context->tcp == NULL [00:01:47.002,288] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:1928: |2| in_left: 0, nb_want: 5 [00:01:47.002,441] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:1931: |2| ssl->f_recv(_timeout)() returned 5 (-0xfffffffb) [00:01:47.002,471] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:1951: |2| <= fetch input [00:01:47.002,807] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:3454: |4| dumping 'input record header' (5 bytes) [00:01:47.003,051] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:3454: |4| 0000: 15 03 03 00 02 ..... [00:01:47.003,204] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:3456: |3| input record: msgtype = 21, version = [3:3], msglen = 2 [00:01:47.003,265] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:1748: |2| => fetch input [00:01:47.003,356] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:1903: |2| in_left: 5, nb_want: 7 [00:01:47.003,479] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:1928: |2| in_left: 5, nb_want: 7 [00:01:47.003,601] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:1931: |2| ssl->f_recv(_timeout)() returned -76 (-0x004c) [00:01:47.003,723] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:4490: |1| mbedtls_ssl_fetch_input() returned -76 (-0x004c) [00:01:47.003,875] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:3754: |1| ssl_get_next_record() returned -76 (-0x004c) [00:01:47.003,997] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_cli.c:1924: |1| mbedtls_ssl_read_record() returned -76 (-0x004c) [00:01:47.004,058] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_tls.c:5323: |2| <= handshake [00:01:47.004,058] <err> net_sock_tls: TLS handshake error: -4c [00:01:47.008,209] <dbg> net_sock: z_impl_zsock_close: (xxxxxxxx_com): close: ctx=0x20015b3c, fd=3 [00:01:47.008,270] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:5553: |2| => write close notify [00:01:47.008,331] <dbg> net_sock_tls: tls_debug: (xxxxxxxx_com): ssl_msg.c:5569: |2| <= write close notify [00:01:47.012,878] <dbg> net_sock: z_impl_zsock_close: (xxxxxxxx_com): close: ctx=0x200136d8, fd=4 [00:01:47.012,908] <dbg> net_tcp: net_tcp_recv: (xxxxxxxx_com): context: 0x200136d8, cb: (nil), user_data: (nil) [00:01:47.012,969] <dbg> net_sock: zsock_flush_queue: (xxxxxxxx_com): discarding pkt 0x20036b40 [00:01:47.013,000] <dbg> net_tcp: net_tcp_unref: (xxxxxxxx_com): context: 0x200136d8, conn: (nil) [00:01:47.013,031] <err> socket_manager: Cannot connect to remote (-113)
Any help is highly appreciated!
