ESP32S3 esp_http_client_open does not timeout (IDFGH-13279)

danfleck commented 1 month ago

Answers checklist.

[X] I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
[X] I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
[X] I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

v5.2.2

Espressif SoC revision.

ESP32-S3

Operating System used.

macOS

How did you build your project?

VS Code IDE

If you are using Windows, please specify command line type.

None

Development Kit.

Custom board

Power Supply used.

Battery

What is the expected behavior?

I expect the esp_http_client_open call to timeout within the timeout_ms milliseconds.

What is the actual behavior?

It does not timeout, so the watchdog is triggered.

Steps to reproduce.

This is happening due to unstable power supply on my board which is causing HTTP transmission errors. However, it should still timeout I believe within the timeout_ms time.

set timeout_ms = 5000 is_async = false

(Watchdog timeout is set to 10sec) Run the code and attempt to open an https connection.

Debug Logs.

Stacktrace from GDB when the watchdog timeout fires:

#0  0x400559e0 in ?? ()
#1  0x40384a76 in vPortClearInterruptMaskFromISR (prev_level=<optimized out>) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/include/freertos/portmacro.h:564
#2  vPortExitCritical (mux=0x3fcce92c) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:504
#3  0x4038432d in xQueueReceive (xQueue=0x3fcce8d8, pvBuffer=0x3fcb11e8 <processingTaskStack+22808>, xTicksToWait=<optimized out>) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:1632
#4  0x42064f5c in sys_arch_mbox_fetch (mbox=<optimized out>, msg=0x3fcb11e8 <processingTaskStack+22808>, timeout=5000) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/lwip/port/freertos/sys_arch.c:317
#5  0x420661ca in netconn_recv_data (conn=0x3c15605c, new_buf=0x3fcb1298 <processingTaskStack+22984>, apiflags=8 '\b') at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/lwip/lwip/src/api/api_lib.c:615
#6  0x42066301 in netconn_recv_data_tcp (conn=0x3c15605c, new_buf=0x3fcb1298 <processingTaskStack+22984>, apiflags=8 '\b') at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/lwip/lwip/src/api/api_lib.c:727
#7  0x420663ac in netconn_recv_tcp_pbuf_flags (conn=0x3c15605c, new_buf=0x3fcb1298 <processingTaskStack+22984>, apiflags=8 '\b') at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/lwip/lwip/src/api/api_lib.c:808
#8  0x420688d7 in lwip_recv_tcp (sock=0x3c138c4c, mem=0x3c1586c4, len=<optimized out>, flags=0) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/lwip/lwip/src/api/sockets.c:951
#9  0x42069c5b in lwip_recvfrom (s=54, mem=0x3c1586c4, len=5423, flags=0, from=0x0, fromlen=0x0) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/lwip/lwip/src/api/sockets.c:1218
#10 0x42069d25 in lwip_read (s=54, mem=0x3c1586c4, len=5423) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/lwip/lwip/src/api/sockets.c:1260
#11 0x420063e0 in esp_vfs_read (r=0x3fcb1938 <processingTaskBuffer+104>, fd=<optimized out>, dst=0x3c1586c4, size=5423) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/vfs/vfs.c:508
#12 0x420cc311 in read (fd=54, buf=0x3c1586c4, cnt=5423) at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin21.1/xtensa-esp-elf/src/newlib/newlib/libc/syscalls/sysread.c:11
#13 0x4207cebd in mbedtls_net_recv (ctx=0x3fcf103c, buf=0x3c1586c4 "", len=5423) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/mbedtls/port/net_sockets.c:351
#14 0x42073dfd in mbedtls_ssl_fetch_input (ssl=0x3fcf0cc4, nb_want=11003) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/mbedtls/mbedtls/library/ssl_msg.c:2310
#15 0x42074b43 in ssl_get_next_record (ssl=0x3fcf0cc4) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/mbedtls/mbedtls/library/ssl_msg.c:4937
#16 0x42074c45 in mbedtls_ssl_read_record (ssl=0x3fcf0cc4, update_hs_digest=1) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/mbedtls/mbedtls/library/ssl_msg.c:4214
#17 0x4207743b in mbedtls_ssl_parse_certificate (ssl=0x3fcf0cc4) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/mbedtls/mbedtls/library/ssl_tls.c:8203
#18 0x4207a276 in mbedtls_ssl_handshake_client_step (ssl=0x3fcf0cc4) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/mbedtls/mbedtls/library/ssl_tls12_client.c:3523
#19 0x42076461 in mbedtls_ssl_handshake_step (ssl=0x3fcf0cc4) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/mbedtls/mbedtls/library/ssl_tls.c:4546
#20 0x420764ee in mbedtls_ssl_handshake (ssl=0x3fcf0cc4) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/mbedtls/mbedtls/library/ssl_tls.c:4610
#21 0x4206ee59 in esp_mbedtls_handshake (tls=0x3fcf0cc4, cfg=0x3fcf0704) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/esp-tls/esp_tls_mbedtls.c:218
#22 0x4206e44c in esp_tls_handshake (tls=0x3fcf0cc4, cfg=0x3fcf0704) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/esp-tls/esp_tls.c:118
#23 0x4206e6cd in esp_tls_low_level_conn (hostname=<optimized out>, hostlen=39, port=443, cfg=0x3fcf0704, tls=0x3fcf0cc4) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/esp-tls/esp_tls.c:497
#24 0x4206e81c in esp_tls_conn_new_sync (hostname=0x3fcf0794 "us-central1-smartaed.cloudfunctions.net", hostlen=39, port=443, cfg=0x3fcf0704, tls=0x3fcf0cc4) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/esp-tls/esp_tls.c:528
#25 0x420c0cff in ssl_connect (t=0x3fcf0698, host=0x3fcf0794 "us-central1-smartaed.cloudfunctions.net", port=443, timeout_ms=5000) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/tcp_transport/transport_ssl.c:111
#26 0x420dfee4 in esp_transport_connect (t=0x3fcf0698, host=0x3fcf0794 "us-central1-smartaed.cloudfunctions.net", port=443, timeout_ms=5000) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/tcp_transport/transport.c:123
#27 0x420702e6 in esp_http_client_connect (client=<optimized out>) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/esp_http_client/esp_http_client.c:1402
#28 0x42070f66 in esp_http_client_open (client=<optimized out>, write_len=888) at /Users/MYHOMEDIR/esp/v5.2.2/esp-idf/components/esp_http_client/esp_http_client.c:1559
#29 0x4200ad13 in OpenClientConnection () at MY CODE

More Information.

No response

hmalpani commented 1 month ago

Hello @danfleck Could you please share a sample application with sdkconfig file that can be used to reproduce this issue. Thanks!

danfleck commented 1 month ago

Here is a modified example program that shows the problem. The timeouts are very short because on working hardware, the connection doesn't really timeout. The watchdog timeout is 500ms and the http_open timeout is 300ms. When I run this on an ESP dev board the watchdog timeout runs, not the http_open timeout. I'm not sure if this is representative of the exact problem I am seeing because on my board the timeouts are 10s and 5s.

(Make sure to not init the task watchdog on startup in sdkconfig.)

esp_http_client_example.c.txt

danfleck commented 1 month ago

SDKCONFIG sdkconfig.txt

espressif / esp-idf