CYW43907: 5sec delay when ready reply of https request

Tip / Sign in to post questions, reply, level up, and achieve exciting badges. Know more

cross mob
cedric_roomz
Level 4
Level 4
50 replies posted 50 sign-ins 25 replies posted

Hi,

I'm trying to make a reasonably fast application on a CYW43907 and am getting a long 5sec delay when getting the reply to an https request.

 

I'm using cy_http_client.c which uses core_http_client.c

In receiveAndParseHttpResponse the call to   pTransport->recv takes 5secs.

Here is the uart log (I added a few outputs to see where it took some time.

 

2022-06-14 09:56:47,375,375 INFO COM10: b'[F4] : [L5] : 0042 00:00:07.105 cy_http_client_write_header(): END \r\n'
2022-06-14 09:56:47,375,375 INFO COM10: b'cy_http_client_send\r\n'
2022-06-14 09:56:47,377,377 INFO COM10: b'[F4] : [L5] : 0043 00:00:07.113 cy_http_client_send(): START \r\n'
2022-06-14 09:56:47,378,378 INFO COM10: b'[F4] : [L5] : 0044 00:00:07.118 Acquire object mutex : 0x4c07d8..!\r\n'
2022-06-14 09:56:47,379,379 INFO COM10: b'[F2] : [L4] : 0045 00:00:07.124 sendHttpRequest\r\n'
2022-06-14 09:56:47,383,383 INFO COM10: b'[F2] : [L5] : 0046 00:00:07.128 1F\x8d\xf8\x1f0BF\x16\x9b[F2] : [L5] : 0047 00:00:07.130 1F\x8d\xf8\x1f0BF\x16\x9b[F2] : [L5] : 0048 00:00:07.131 A request body was not sent: pRequestBodyBuf is NULL.[F2] : [L4] : 0049 00:00:07.131 receiveAndParseHttpResponse\r\n'
2022-06-14 09:56:52,435,435 INFO COM10: b'[F2] : [L4] : 0050 00:00:12.206 currentReceived\r\n'
2022-06-14 09:56:52,773,773 INFO COM10: b'[F2] : [L4] : 0051 00:00:12.210 parseHttpResponse\r\n'
2022-06-14 09:56:52,773,773 INFO COM10: b'[F2] : [L5] : 0052 00:00:12.214 Response parsing: Found the start of the response message.[F2] : [L5] : 0053 00:00:12.214 OK\r\n'

 

 

It seems it takes 5sec to get the output of: 

currentReceived = pTransport->recv( pTransport->pNetworkContext,
pResponse->pBuffer + totalReceived,
pResponse->bufferLen - totalReceived ); 

 

Here is the wireshark capture of the exact same exchange, we can see that the device did receive and ack very fast. So it's not a network issue but really a processing issue.

cedric_roomz_0-1655194155205.png

 

I would guess that there is some error conditions during reception + a 5sec timeout somewhere. But I have not yet digged deeper. 

What could cause this 5sec delay?

 

Thanks

Cédric

 

0 Likes
6 Replies
Rakesh_BG
Moderator
Moderator
Moderator
50 solutions authored 100 replies posted 100 sign-ins

Hi @cedric_roomz ,

We are verifying the problem . We will get back to you as soon as possible.

Thanks,

Rakesh B G

0 Likes
cedric_roomz
Level 4
Level 4
50 replies posted 50 sign-ins 25 replies posted

Hi Rakesh,

Ok, thank you.

Cédric

0 Likes
cedric_roomz
Level 4
Level 4
50 replies posted 50 sign-ins 25 replies posted

I digged a little deeper.

 

I tried to change the connection header, which does bypass the issue.

- Connection: keep-alive has the 5sec timeout

- Connection: close does not have the 5sec timeout

However we do not want to reopen the https connection every time as it is costly. 

 

 

I've added more logs, the issue seem to be in lwip. 

How should I configure lwip to have an https connection with keep-alive which does wait for the timeout to return each http request result?

See logs below.

 

 

 

2022-06-21 14:07:17,880 INFO COM10: b'(Socket handle 0x4c1710) sent 314 bytes.[F2] : [L5] : 0170 00:00:06.448 1F\x8d\xf8\x1f0BF\x16\x9b[F2] : [L5] : 0171 00:00:06.448 A request body wa
s not sent: pRequestBodyBuf is NULL.[F2] : [L4] : 0172 00:00:06.448 receiveAndParseHttpResponse\r\n'
2022-06-21 14:07:17,881 INFO COM10: b'[F4] : [L5] : 0173 00:00:06.467 \r\n'
2022-06-21 14:07:17,882 INFO COM10: b'(Socket handle 0x4c1710) requesting 2048 bytes.\r\n'
2022-06-21 14:07:17,883 INFO COM10: b'[F4] : [L5] : 0174 00:00:06.474 cy_socket_recv Start\r\n'
2022-06-21 14:07:17,887 INFO COM10: b'[F4] : [L5] : 0175 00:00:06.479 socket_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 3444\r\n
'
2022-06-21 14:07:17,890 INFO COM10: b'[F4] : [L5] : 0176 00:00:06.491 netconn_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 3457\r\
n'
2022-06-21 14:07:17,892 INFO COM10: b'[F4] : [L5] : 0177 00:00:06.438 internal_netconn_event_callback conn 0x4a1e88 event 2 length 343\r\n'
2022-06-21 14:07:17,894 INFO COM10: b'[F4] : [L5] : 0178 00:00:06.512 NETCONN_EVT_SENDPLUS ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1211\r\
n'
2022-06-21 14:07:17,895 INFO COM10: b'[F4] : [L5] : 0179 00:00:06.524 cy_process_send_plus_event Start\r\n'
2022-06-21 14:07:17,898 INFO COM10: b'[F4] : [L5] : 0180 00:00:06.530 socket_list_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 113
3\r\n'
2022-06-21 14:07:17,900 INFO COM10: b'[F4] : [L5] : 0181 00:00:06.542 socket_list_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1
145\r\n'
2022-06-21 14:07:17,901 INFO COM10: b'[F4] : [L5] : 0182 00:00:06.555 cy_process_send_plus_event End\r\n'
2022-06-21 14:07:18,272 INFO COM10: b'[F4] : [L5] : 0183 00:00:06.793 internal_netconn_event_callback conn 0x4a1e88 event 0 length 731\r\n'
2022-06-21 14:07:18,277 INFO COM10: b'[F4] : [L5] : 0184 00:00:06.801 NETCONN_EVT_RCVPLUS ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1186\r\n
'
2022-06-21 14:07:18,283 INFO COM10: b'[F4] : [L5] : 0185 00:00:06.794 internal_netconn_event_callback conn 0x4a1e88 event 1 length 731\r\n'
2022-06-21 14:07:18,288 INFO COM10: b'[F4] : [L5] : 0186 00:00:06.822 NETCONN_EVT_RCVMINUS ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1207\r\
n'
2022-06-21 14:07:18,291 INFO COM10: b'[F4] : [L5] : 0187 00:00:06.839 cy_process_receive_event Start \r\n'
2022-06-21 14:07:18,295 INFO COM10: b'[F4] : [L5] : 0188 00:00:06.844 accept_recv_event_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets
.c 871\r\n'
2022-06-21 14:07:18,298 INFO COM10: b'[F4] : [L5] : 0189 00:00:06.857 accept_recv_event_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_socke
ts.c 919\r\n'
2022-06-21 14:07:18,301 INFO COM10: b'[F4] : [L5] : 0190 00:00:06.871 socket_list_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 925
\r\n'
2022-06-21 14:07:18,303 INFO COM10: b'[F4] : [L5] : 0191 00:00:06.883 cy_process_receive_event_with_valid_context Start \r\n'
2022-06-21 14:07:18,305 INFO COM10: b'[F4] : [L5] : 0192 00:00:06.890 accept_recv_event_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets
.c 782\r\n'
2022-06-21 14:07:18,308 INFO COM10: b'[F4] : [L5] : 0193 00:00:06.903 accept_recv_event_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_socke
ts.c 857\r\n'
2022-06-21 14:07:18,309 INFO COM10: b'[F4] : [L5] : 0194 00:00:06.916 cy_process_receive_event_with_valid_context End \r\n'
2022-06-21 14:07:18,313 INFO COM10: b'[F4] : [L5] : 0195 00:00:06.923 socket_list_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 9
40\r\n'
2022-06-21 14:07:18,316 INFO COM10: b'[F4] : [L5] : 0196 00:00:06.936 cy_process_receive_event End \r\n'
2022-06-21 14:07:23,572 INFO COM10: b'[F4] : [L5] : 0197 00:00:11.839 netconn_recv_tcp_pbuf returned -3\r\n'
2022-06-21 14:07:23,577 INFO COM10: b'[F4] : [L5] : 0198 00:00:11.844 Timeout\r\n'

 

0 Likes
cedric_roomz
Level 4
Level 4
50 replies posted 50 sign-ins 25 replies posted

Any update on this issue?

0 Likes
cedric_roomz
Level 4
Level 4
50 replies posted 50 sign-ins 25 replies posted

Digging deeper...

 

See uart output below, we can see that it receives a 713 bytes packet. It reads its 5 bytes header, see that it has msglen = 708 but asks for nb_want: 713 as if it would receive another header on top of msglen. 

 

I'm not sure of the cleanest fix though. I would really appreciate some feedback here!

2022-07-19 08:28:32,018 INFO COM10: b'[F4] : [L2] : 0612 00:00:21.286 in_left: 0, nb_want: 5\r\n'
2022-07-19 08:28:32,018 INFO COM10: b'[F4] : [L2] : 0613 00:00:21.291 f_recv\r\n'
2022-07-19 08:28:32,018 INFO COM10: b'[F4] : [L5] : 0614 00:00:21.295 len: 5\r\n'
2022-07-19 08:28:32,018 INFO COM10: b'[F4] : [L5] : 0615 00:00:21.298 netconn_recv_tcp_pbuf\r\n'
2022-07-19 08:28:32,018 INFO COM10: b'[F4] : [L5] : 0616 00:00:21.303 internal_netconn_event_callback conn 0x4a1810 event 1 length 713\r\n'
2022-07-19 08:28:32,018 INFO COM10: b'[F4] : [L5] : 0617 00:00:21.311 NETCONN_EVT_RCVMINUS ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1209\r\n'
2022-07-19 08:28:32,018 INFO COM10: b'[F4] : [L5] : 0618 00:00:21.323 total_received: 5\r\n'
2022-07-19 08:28:32,018 INFO COM10: b'[F4] : [L4] : 0619 00:00:21.328 tls_network_receive_callback\r\n'
2022-07-19 08:28:32,018 INFO COM10: b'[F4] : [L2] : 0620 00:00:21.333 f_recv finished\r\n'
2022-07-19 08:28:32,030 INFO COM10: b'[F4] : [L2] : 0621 00:00:21.337 <= fetch input[F4] : [L2] : 0622 00:00:21.337 parse record\r\n'
2022-07-19 08:28:32,030 INFO COM10: b'[F4] : [L2] : 0623 00:00:21.345 input record: msgtype = 23, version = [3:3], msglen = 708[F4] : [L2] : 0624 00:00:21.345 dtls\r\n'
2022-07-19 08:28:32,030 INFO COM10: b'[F4] : [L2] : 0625 00:00:21.356 => fetch input\r\n'
2022-07-19 08:28:32,030 INFO COM10: b'[F4] : [L2] : 0626 00:00:21.360 => before dtls\r\n'
2022-07-19 08:28:32,030 INFO COM10: b'[F4] : [L2] : 0627 00:00:21.364 here\r\n'
2022-07-19 08:28:32,030 INFO COM10: b'[F4] : [L2] : 0628 00:00:21.367 in_left: 5, nb_want: 713\r\n'
2022-07-19 08:28:32,030 INFO COM10: b'[F4] : [L2] : 0629 00:00:21.372 f_recv\r\n'
2022-07-19 08:28:32,030 INFO COM10: b'[F4] : [L5] : 0630 00:00:21.375 len: 708\r\n'
2022-07-19 08:28:32,040 INFO COM10: b'[F4] : [L5] : 0631 00:00:21.379 total_received: 708\r\n'
2022-07-19 08:28:32,040 INFO COM10: b'[F4] : [L4] : 0632 00:00:21.384 tls_network_receive_callback\r\n'
2022-07-19 08:28:32,040 INFO COM10: b'[F4] : [L2] : 0633 00:00:21.389 f_recv finished\r\n'
2022-07-19 08:28:32,040 INFO COM10: b'[F4] : [L2] : 0634 00:00:21.393 <= fetch input[F4] : [L2] : 0635 00:00:21.393 prepare record content\r\n'
2022-07-19 08:28:32,040 INFO COM10: b'[F4] : [L2] : 0636 00:00:21.405 update in pointers\r\n'
2022-07-19 08:28:32,040 INFO COM10: b'[F4] : [L2] : 0637 00:00:21.410 zlib\r\n'
2022-07-19 08:28:32,040 INFO COM10: b'[F4] : [L2] : 0638 00:00:21.413 message type\r\n'
2022-07-19 08:28:32,040 INFO COM10: b'[F4] : [L2] : 0639 00:00:21.417 <= read record\r\n'
2022-07-19 08:28:32,040 INFO COM10: b'[F4] : [L2] : 0640 00:00:21.421 => end loop c\r\n'
2022-07-19 08:28:32,040 INFO COM10: b'[F4] : [L2] : 0641 00:00:21.425 => end loop c\r\n'
2022-07-19 08:28:32,050 INFO COM10: b'[F4] : [L2] : 0642 00:00:21.429 <= read[F4] : [L5] : 0643 00:00:21.429 returned from mbedtls_ssl_read\r\n'
2022-07-19 08:28:32,050 INFO COM10: b'[F4] : [L5] : 0644 00:00:21.438 calling mbedtls_ssl_read\r\n'
2022-07-19 08:28:32,050 INFO COM10: b'[F4] : [L2] : 0645 00:00:21.443 => read\r\n'
2022-07-19 08:28:32,050 INFO COM10: b'[F4] : [L2] : 0646 00:00:21.446 => loop\r\n'
2022-07-19 08:28:32,050 INFO COM10: b'[F4] : [L2] : 0647 00:00:21.450 => read record\r\n'
2022-07-19 08:28:32,050 INFO COM10: b'[F4] : [L2] : 0648 00:00:21.454 consume current\r\n'
2022-07-19 08:28:32,050 INFO COM10: b'[F4] : [L2] : 0649 00:00:21.458 get next record\r\n'
2022-07-19 08:28:32,060 INFO COM10: b'[F4] : [L2] : 0650 00:00:21.462 fetch input\r\n'
2022-07-19 08:28:32,060 INFO COM10: b'[F4] : [L2] : 0651 00:00:21.466 => fetch input\r\n'
2022-07-19 08:28:32,060 INFO COM10: b'[F4] : [L2] : 0652 00:00:21.470 => before dtls\r\n'
2022-07-19 08:28:32,060 INFO COM10: b'[F4] : [L2] : 0653 00:00:21.474 here\r\n'
2022-07-19 08:28:32,060 INFO COM10: b'[F4] : [L2] : 0654 00:00:21.477 in_left: 0, nb_want: 5\r\n'
2022-07-19 08:28:32,060 INFO COM10: b'[F4] : [L2] : 0655 00:00:21.482 f_recv\r\n'
2022-07-19 08:28:32,060 INFO COM10: b'[F4] : [L5] : 0656 00:00:21.485 len: 5\r\n'
2022-07-19 08:28:32,060 INFO COM10: b'[F4] : [L5] : 0657 00:00:21.488 netconn_recv_tcp_pbuf\r\n'
2022-07-19 08:28:32,060 INFO COM10: b'[F4] : [L5] : 0658 00:00:21.493 cy_process_send_plus_event Start\r\n'
2022-07-19 08:28:32,156 INFO COM10: b'[F4] : [L5] : 0659 00:00:21.499 socket_list_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1135\r\n'
2022-07-19 08:28:32,156 INFO COM10: b'[F4] : [L5] : 0660 00:00:21.511 socket_list_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1147\r\n'
2022-07-19 08:28:32,156 INFO COM10: b'[F4] : [L5] : 0661 00:00:21.524 cy_process_send_plus_event End\r\n'
2022-07-19 08:28:32,156 INFO COM10: b'[F4] : [L5] : 0662 00:00:21.530 cy_process_send_plus_event Start\r\n'
2022-07-19 08:28:32,166 INFO COM10: b'[F4] : [L5] : 0663 00:00:21.535 socket_list_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1135\r\n'
2022-07-19 08:28:32,166 INFO COM10: b'[F4] : [L5] : 0664 00:00:21.548 socket_list_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1147\r\n'
2022-07-19 08:28:32,166 INFO COM10: b'[F4] : [L5] : 0665 00:00:21.561 cy_process_send_plus_event End\r\n'
2022-07-19 08:28:32,166 INFO COM10: b'[F4] : [L5] : 0666 00:00:21.566 cy_process_receive_event Start \r\n'
2022-07-19 08:28:32,166 INFO COM10: b'[F4] : [L5] : 0667 00:00:21.572 accept_recv_event_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 873\r\n'
2022-07-19 08:28:32,176 INFO COM10: b'[F4] : [L5] : 0668 00:00:21.585 accept_recv_event_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 921\r\n'
2022-07-19 08:28:32,176 INFO COM10: b'[F4] : [L5] : 0669 00:00:21.598 socket_list_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 927\r\n'
2022-07-19 08:28:32,176 INFO COM10: b'[F4] : [L5] : 0670 00:00:21.610 cy_process_receive_event_with_valid_context Start \r\n'
2022-07-19 08:28:32,176 INFO COM10: b'[F4] : [L5] : 0671 00:00:21.618 accept_recv_event_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 784\r\n'
2022-07-19 08:28:32,176 INFO COM10: b'[F4] : [L5] : 0672 00:00:21.631 accept_recv_event_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 859\r\n'
2022-07-19 08:28:32,176 INFO COM10: b'[F4] : [L5] : 0673 00:00:21.644 cy_process_receive_event_with_valid_context End \r\n'
2022-07-19 08:28:32,186 INFO COM10: b'[F4] : [L5] : 0674 00:00:21.651 socket_list_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 942\r\n'
2022-07-19 08:28:32,186 INFO COM10: b'[F4] : [L5] : 0675 00:00:21.664 cy_process_receive_event End \r\n'
2022-07-19 08:28:37,386 INFO COM10: b'[F4] : [L5] : 0676 00:00:26.493 netconn_recv_tcp_pbuf returned -3\r\n'
2022-07-19 08:28:37,388 INFO COM10: b'[F4] : [L4] : 0677 00:00:26.498 tls_network_receive_callback\r\n'
2022-07-19 08:28:37,390 INFO COM10: b'[F4] : [L2] : 0678 00:00:26.503 f_recv finished\r\n'
2022-07-19 08:28:37,392 WARNING COM10: b'[F4] : [L2] : 0679 00:00:26.508 fetch input failed\r\n'
2022-07-19 08:28:37,395 WARNING COM10: b'[F4] : [L2] : 0680 00:00:26.512 get next record failed\r\n'
2022-07-19 08:28:37,398 INFO COM10: b'[F4] : [L2] : 0681 00:00:26.517 => end\r\n'
2022-07-19 08:28:37,401 INFO COM10: b'[F4] : [L5] : 0682 00:00:26.520 returned from mbedtls_ssl_read\r\n'
2022-07-19 08:28:37,403 INFO COM10: b'[F4] : [L5] : 0683 00:00:26.525 Timeout cy_tls\r\n'
2022-07-19 08:28:37,407 INFO COM10: b'[F4] : [L5] : 0684 00:00:26.529 netconn_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 3506\r\n'
2022-07-19 08:28:37,410 INFO COM10: b'[F4] : [L5] : 0685 00:00:26.542 socket_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 3509\r\n'
2022-07-19 08:28:37,412 INFO COM10: b'[F4] : [L5] : 0686 00:00:26.554 cy_socket_recv End\r\n'
2022-07-19 08:28:37,413 INFO COM10: b'[F4] : [L5] : 0687 00:00:26.559 \r\n'
2022-07-19 08:28:37,415 INFO COM10: b'(Socket handle 0x4c0670) received 684 bytes.[F4] : [L5] : 0688 00:00:26.562 HTTPClient_Send() API returned\r\n'
2022-07-19 08:28:37,418 INFO COM10: b'[F4] : [L5] : 0689 00:00:26.571 http client library : Received HTTP response from api.roomz.io/api/devices/046f7ce2c77480/logs...\r\n'
2022-07-19 08:28:37,419 INFO COM10: b'Response Headers:\r\n'
2022-07-19 08:28:37,419 INFO COM10: b'Date: Tue, 19 Jul 2022 06:28:32 GMT\r\n'
2022-07-19 08:28:37,420 INFO COM10: b'Content-Type: application/json\r\n'
2022-07-19 08:28:37,421 INFO COM10: b'Content-Length: 60\r\n'
2022-07-19 08:28:37,421 INFO COM10: b'Connection: keep-alive\r\n'
2022-07-19 08:28:37,422 INFO COM10: b'Server: Microsoft-IIS/10.0\r\n'
2022-07-19 08:28:37,424 INFO COM10: b'Set-Cookie: TiPMix=88.15252717820708; path=/; HttpOnly; Domain=roomz-io-api-devices.azurewebsites.net:443; Max-Age=3600; Secure; SameSite=None\r\n'
2022-07-19 08:28:37,425 INFO COM10: b'Set-Cookie: x-ms-routing-name=self; path=/; HttpOnly; Domain=roomz-io-api-devices.azurewebsites.net:443; Max-Age=3600; Secure; SameSite=None\r\n'
2022-07-19 08:28:37,427 INFO COM10: b'Request-Context: appId=cid-v1:0773415c-04ac-47d1-a927-af2c470d1fbc\r\n'
2022-07-19 08:28:37,428 INFO COM10: b'X-Frame-Options: DENY\r\n'
2022-07-19 08:28:37,430 INFO COM10: b'X-XSS-Protection: 1; mode=block\r\n'
2022-07-19 08:28:37,430 INFO COM10: b'Strict-Transport-Security: max-age=31536000\r\n'
2022-07-19 08:28:37,432 INFO COM10: b'Response Status:\r\n'
2022-07-19 08:28:37,432 INFO COM10: b'400\r\n'
2022-07-19 08:28:37,434 INFO COM10: b'[F4] : [L5] : 0690 00:00:26.636 buffer_len:[2048] headers_len:[594] header_count:[11] body_len:[60] content_len:[60]\r\n'
2022-07-19 08:28:37,434 INFO COM10: b'[F4] : [L5] : 0691 00:00:26.647 Release object mutex : 0x4bfde0..!\r\n'
2022-07-19 08:28:37,437 INFO COM10: b'[F4] : [L5] : 0692 00:00:26.652 cy_http_client_send(): END \r\n'
2022-07-19 08:28:37,438 WARNING COM10: b'ERROR: http_if.c:771:: Request returned: 400\r\n'
2022-07-19 08:28:37,439 WARNING COM10: b'{"reason":"An error occurred while reading a Json content."}\r\n'
2022-07-19 08:28:37,440 INFO COM10: b'[F4] : [L5] : 0693 00:00:26.667 cy_http_client_disconnect(): START \r\n'
2022-07-19 08:28:37,440 INFO COM10: b'[F4] : [L5] : 0694 00:00:26.672 Acquire object mutex : 0x4bfde0..!\r\n'
2022-07-19 08:28:37,441 INFO COM10: b'[F4] : [L5] : 0695 00:00:26.678 cy_socket_disconnect Start\r\n'
2022-07-19 08:28:37,445 INFO COM10: b'[F4] : [L5] : 0696 00:00:26.683 socket_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 3070\r\n'
2022-07-19 08:28:37,448 INFO COM10: b'[F4] : [L5] : 0697 00:00:26.695 netconn_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 3086\r\n'
2022-07-19 08:28:37,450 INFO COM10: b'[F4] : [L5] : 0698 00:00:26.710 internal_netconn_event_callback conn 0x4a1810 event 4 length 0\r\n'
2022-07-19 08:28:37,453 INFO COM10: b'[F4] : [L5] : 0699 00:00:26.719 unknown event 4\r\n'
2022-07-19 08:28:37,454 INFO COM10: b'[F4] : [L5] : 0700 00:00:26.723 internal_netconn_event_callback conn 0x4a1810 event 0 length 0\r\n'
2022-07-19 08:28:37,456 INFO COM10: b'[F4] : [L5] : 0701 00:00:26.731 NETCONN_EVT_RCVPLUS ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1188\r\n'
2022-07-19 08:28:37,458 INFO COM10: b'[F4] : [L5] : 0702 00:00:26.743 internal_netconn_event_callback conn 0x4a1810 event 2 length 0\r\n'
2022-07-19 08:28:37,460 INFO COM10: b'[F4] : [L5] : 0703 00:00:26.751 NETCONN_EVT_SENDPLUS ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1213\r\n'
2022-07-19 08:28:37,460 INFO COM10: b'[F4] : [L5] : 0704 00:00:26.764 internal_netconn_event_callback conn 0x4a1810 event 0 length 0\r\n'
2022-07-19 08:28:37,466 INFO COM10: b'[F4] : [L5] : 0705 00:00:26.772 NETCONN_EVT_RCVPLUS ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1188\r\n'
2022-07-19 08:28:37,466 INFO COM10: b'[F4] : [L5] : 0706 00:00:26.784 internal_netconn_event_callback conn 0x4a1810 event 2 length 0\r\n'
2022-07-19 08:28:37,466 INFO COM10: b'[F4] : [L5] : 0707 00:00:26.792 NETCONN_EVT_SENDPLUS ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1213\r\n'
2022-07-19 08:28:37,466 INFO COM10: b'[F4] : [L5] : 0708 00:00:26.804 netconn_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 3189\r\n'
2022-07-19 08:28:37,466 INFO COM10: b'[F4] : [L5] : 0709 00:00:26.817 socket_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 3192\r\n'
2022-07-19 08:28:37,727 INFO COM10: b'[F4] : [L5] : 0710 00:00:26.830 cy_socket_disconnect End\r\n'
2022-07-19 08:28:37,731 INFO COM10: b'[F4] : [L5] : 0711 00:00:26.835 cy_socket_delete Start\r\n'
2022-07-19 08:28:37,732 INFO COM10: b'[F4] : [L5] : 0712 00:00:26.840 cy_socket_disconnect Start\r\n'
2022-07-19 08:28:37,735 INFO COM10: b'[F4] : [L5] : 0713 00:00:26.845 socket_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 3070\r\n'
2022-07-19 08:28:37,738 INFO COM10: b'[F4] : [L5] : 0714 00:00:26.857 netconn_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 3086\r\n'
2022-07-19 08:28:37,740 INFO COM10: b'[F4] : [L5] : 0715 00:00:26.869 netconn_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 3107\r\n'
2022-07-19 08:28:37,741 INFO COM10: b'[F4] : [L5] : 0716 00:00:26.882 Socket not connected\r\n'
2022-07-19 08:28:37,744 INFO COM10: b'[F4] : [L5] : 0717 00:00:26.886 socket_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 3111\r\n'
2022-07-19 08:28:37,747 INFO COM10: b'[F4] : [L5] : 0718 00:00:26.899 socket_list_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 475\r\n'
2022-07-19 08:28:37,750 INFO COM10: b'[F4] : [L5] : 0719 00:00:26.911 socket_list_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 483\r\n'
2022-07-19 08:28:37,751 INFO COM10: b'[F4] : [L5] : 0720 00:00:26.924 cy_socket_delete End\r\n'
2022-07-19 08:28:37,753 INFO COM10: b'[F4] : [L5] : 0721 00:00:26.929 cy_process_connect_disconnect_notification_event Start\r\n'
2022-07-19 08:28:37,755 INFO COM10: b'[F4] : [L5] : 0722 00:00:26.936 accept_recv_event_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1094\r\n'
2022-07-19 08:28:37,757 INFO COM10: b'[F4] : [L5] : 0723 00:00:26.949 socket_list_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1096\r\n'
2022-07-19 08:28:37,762 INFO COM10: b'[F4] : [L5] : 0724 00:00:26.962 socket_list_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1106\r\n'
2022-07-19 08:28:37,765 INFO COM10: b'[F4] : [L5] : 0725 00:00:26.975 Callback function invoked on a deleted socket \r\n'
2022-07-19 08:28:37,768 INFO COM10: b'[F4] : [L5] : 0726 00:00:26.982 cy_process_send_plus_event Start\r\n'
2022-07-19 08:28:37,771 INFO COM10: b'[F4] : [L5] : 0727 00:00:26.987 socket_list_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1135\r\n'
2022-07-19 08:28:37,773 INFO COM10: b'[F4] : [L5] : 0728 00:00:27.000 socket_list_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1141\r\n'
2022-07-19 08:28:37,776 INFO COM10: b'[F4] : [L5] : 0729 00:00:27.013 context is NULL in cy_process_disconnect_event \r\n'
2022-07-19 08:28:37,780 INFO COM10: b'[F4] : [L5] : 0730 00:00:27.020 cy_process_connect_disconnect_notification_event Start\r\n'
2022-07-19 08:28:37,783 INFO COM10: b'[F4] : [L5] : 0731 00:00:27.027 accept_recv_event_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1094\r\n'
2022-07-19 08:28:37,786 INFO COM10: b'[F4] : [L5] : 0732 00:00:27.040 socket_list_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1096\r\n'
2022-07-19 08:28:37,788 INFO COM10: b'[F4] : [L5] : 0733 00:00:27.053 socket_list_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1106\r\n'
2022-07-19 08:28:37,790 INFO COM10: b'[F4] : [L5] : 0734 00:00:27.066 Callback function invoked on a deleted socket \r\n'
2022-07-19 08:28:37,796 INFO COM10: b'[F4] : [L5] : 0735 00:00:27.073 cy_process_send_plus_event Start\r\n'
2022-07-19 08:28:37,799 INFO COM10: b'[F4] : [L5] : 0736 00:00:27.078 socket_list_mutex locked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1135\r\n'
2022-07-19 08:28:37,802 INFO COM10: b'[F4] : [L5] : 0737 00:00:27.091 socket_list_mutex unlocked ../mtb_shared/secure-sockets/release-v2.5.0/source/COMPONENT_LWIP/cy_secure_sockets.c 1141\r\n'
2022-07-19 08:28:37,804 INFO COM10: b'[F4] : [L5] : 0738 00:00:27.104 context is NULL in cy_process_disconnect_event \r\n'
2022-07-19 08:28:37,804 INFO COM10: b'[F4] : [L5] : 0739 00:00:27.111 Release object mutex : 0x4bfde0..!\r\n'
2022-07-19 08:28:37,806 INFO COM10: b'[F4] : [L5] : 0740 00:00:27.116 cy_http_client_disconnect(): END \r\n'
2022-07-19 08:28:37,808 INFO COM10: b'[F4] : [L5] : 0741 00:00:27.122 cy_http_client_delete(): START \r\n'
2022-07-19 08:28:37,810 INFO COM10: b'[F4] : [L5] : 0742 00:00:27.127 Acquire global mutex : 0x4bfc60..!\r\n'
2022-07-19 08:28:37,812 INFO COM10: b'[F4] : [L5] : 0743 00:00:27.133 Deinit object mutex : 0x4bfde0..!\r\n'
2022-07-19 08:28:37,813 INFO COM10: b'[F4] : [L5] : 0744 00:00:27.139 Release Global mutex : 0x4bfc60..!\r\n'
2022-07-19 08:28:37,815 INFO COM10: b'[F4] : [L5] : 0745 00:00:27.145 cy_http_client_delete(): END \r\n'
2022-07-19 08:28:37,816 INFO COM10: b'[F4] : [L5] : 0746 00:00:27.150 cy_http_client_deinit(): START \r\n'
2022-07-19 08:28:37,817 INFO COM10: b'[F4] : [L5] : 0747 00:00:27.155 De-initialize http client library\r\n'
2022-07-19 08:28:37,818 INFO COM10: b'[F4] : [L5] : 0748 00:00:27.161 cy_socket_deinit Start\r\n'

 

 

 

0 Likes
cedric_roomz
Level 4
Level 4
50 replies posted 50 sign-ins 25 replies posted

Deeper still:

This time I think I have the root cause. 

cy_tls_recv waits until the buffer is full (2048 in my case) or until the connection closes before exiting. There is no handling of a smaller package without connection close.

For now I have just made it return after the first data read which is working fine for now, but I have to test the behavior with payload bigger than buffer size. 

 

0 Likes