Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

TLS handshake fails for ESP32S3 in QEMU (IDFGH-14706) #15446

Open
3 tasks done
ShawnHymel opened this issue Feb 22, 2025 · 1 comment
Open
3 tasks done

TLS handshake fails for ESP32S3 in QEMU (IDFGH-14706) #15446

ShawnHymel opened this issue Feb 22, 2025 · 1 comment
Assignees
Labels
Status: Opened Issue is new Type: Bug bugs in IDF

Comments

@ShawnHymel
Copy link

ShawnHymel commented Feb 22, 2025

Answers checklist.

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

IDF version.

v5.4

Espressif SoC revision.

ESP32S3

Operating System used.

Linux

How did you build your project?

Command line with idf.py

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

None

Development Kit.

QEMU

Power Supply used.

USB

What is the expected behavior?

Complete TLS handshake using mbed-tls library and fetch https://www.howsmyssl.com/a/check.

What is the actual behavior?

The example connects to the QEMU network, gets an IP address, and then fails to connect to the provided website. Unhandled exception occurs (crash) and the processor resets. See log.

Steps to reproduce.

  1. Go into the https_mbedtls example.
  2. Set configs to enable OpenEth and debugging (idf.py menuconfig or sdkconfig.defaults):
CONFIG_EXAMPLE_CONNECT_WIFI=n
CONFIG_EXAMPLE_USE_OPENETH=y
CONFIG_LOG_DEFAULT_LEVEL_VERBOSE=y
  1. Set target to esp32s3:
idf.py set-target esp32s3
  1. Build and run in qemu:
idf.py qemu monitor

Debug Logs.

ELF file SHA256: 1bb5c5612

Rebooting...
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0xc (RTC_SW_CPU_RST),boot:0x4 (SPI_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce2810,len:0x15a0
load:0x403c8700,len:0x4
load:0x403c8704,len:0xd20
load:0x403cb700,len:0x2ee4
entry 0x403c8928
I (1681) boot: ESP-IDF v5.4 2nd stage bootloader
I (1682) boot: compile time Feb 22 2025 02:13:46
I (1682) boot: Multicore bootloader
I (1685) boot: chip revision: v0.3
I (1685) boot: efuse block revision: v0.0
I (1686) boot.esp32s3: Boot SPI Speed : 80MHz
I (1687) boot.esp32s3: SPI Mode       : DIO
I (1687) boot.esp32s3: SPI Flash Size : 2MB
I (1689) boot: Enabling RNG early entropy source...
I (1691) boot: Partition Table:
I (1691) boot: ## Label            Usage          Type ST Offset   Length
I (1692) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (1692) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (1693) boot:  2 factory          factory app      00 00 00010000 00100000
I (1694) boot: End of partition table
I (1695) esp_image: segment 0: paddr=00010020 vaddr=3c060020 size=2cbbch (183228) map
I (1717) esp_image: segment 1: paddr=0003cbe4 vaddr=3fc93600 size=02de0h ( 11744) load
I (1720) esp_image: segment 2: paddr=0003f9cc vaddr=40374000 size=0064ch (  1612) load
I (1723) esp_image: segment 3: paddr=00040020 vaddr=42000020 size=58c00h (363520) map
I (1761) esp_image: segment 4: paddr=00098c28 vaddr=4037464c size=0ef48h ( 61256) load
I (1779) esp_image: segment 5: paddr=000a7b78 vaddr=600fe100 size=0001ch (    28) load
I (1781) boot: Loaded app from partition at offset 0x10000
I (1781) boot: Disabling RNG early entropy source...
D (1786) rtcinit: core voltage not decided in efuse, use default value.
V (1787) mmap: after coalescing, 1 regions are left
I (1787) cpu_start: Multicore app
D (1787) cpu_start: Pro cpu up
D (1788) cpu_start: Starting app cpu, entry point is 0x403752e0
--- 0x403752e0: call_start_cpu1 at /opt/toolchains/esp-idf/components/esp_system/port/cpu_start.c:196

D (1579) cpu_start: App cpu up
V CACHE_ERR: illegal error intr clr & ena mask is: 0x3f
V CACHE_ERR: core 1 access error intr clr & ena mask is: 0x1f
D (1797) clk: RTC_SLOW_CLK calibration value: 3855053
V CACHE_ERR: illegal error intr clr & ena mask is: 0x3f
V CACHE_ERR: core 0 access error intr clr & ena mask is: 0x1f
D (1798) cpu_start: calling init function: 0x420030d8 on core: 0
--- 0x420030d8: __esp_system_init_fn_init_efuse_check at /opt/toolchains/esp-idf/components/efuse/src/esp_efuse_startup.c:36

D (1798) cpu_start: calling init function: 0x42003530 on core: 0
--- 0x42003530: __esp_system_init_fn_init_show_cpu_freq at /opt/toolchains/esp-idf/components/esp_system/startup_funcs.c:58

I (1798) cpu_start: Pro cpu start user code
I (1798) cpu_start: cpu freq: 160000000 Hz
D (1798) cpu_start: calling init function: 0x42003008 on core: 0
--- 0x42003008: __esp_system_init_fn_init_show_app_info at /opt/toolchains/esp-idf/components/esp_app_format/esp_app_desc.c:123

I (1798) app_init: Application information:
I (1798) app_init: Project name:     app
I (1798) app_init: App version:      1
I (1798) app_init: Compile time:     Feb 22 2025 02:13:33
I (1798) app_init: ELF file SHA256:  1bb5c5612...
I (1798) app_init: ESP-IDF:          v5.4
D (1798) cpu_start: calling init function: 0x420030ec on core: 0
--- 0x420030ec: __esp_system_init_fn_init_efuse_show_app_info at /opt/toolchains/esp-idf/components/efuse/src/esp_efuse_startup.c:46

I (1798) efuse_init: Min chip rev:     v0.0
I (1798) efuse_init: Max chip rev:     v0.99 
I (1798) efuse_init: Chip rev:         v0.3
D (1798) cpu_start: calling init function: 0x420053b0 on core: 0
--- 0x420053b0: __esp_system_init_fn_init_heap at /opt/toolchains/esp-idf/components/heap/heap_caps_init.c:25

V (1798) memory_layout: reserved range is 0x3c08cb04 - 0x3c08cb2c
D (1798) memory_layout: Checking 6 reserved memory ranges:
D (1798) memory_layout: Reserved memory range 0x3fc84000 - 0x3fc93600
D (1798) memory_layout: Reserved memory range 0x3fc93600 - 0x3fc97da8
D (1798) memory_layout: Reserved memory range 0x3fceee34 - 0x3fcf0000
D (1798) memory_layout: Reserved memory range 0x40374000 - 0x40383600
--- 0x40374000: _WindowOverflow4 at /opt/toolchains/esp-idf/components/xtensa/xtensa_vectors.S:2027

D (1798) memory_layout: Reserved memory range 0x600fe000 - 0x600fe11c
D (1798) memory_layout: Reserved memory range 0x600fffe8 - 0x60100000
D (1799) memory_layout: Building list of available memory regions:
V (1799) memory_layout: Examining memory region 0x3fc88000 - 0x3fc90000
V (1799) memory_layout: Region 0x3fc88000 - 0x3fc90000 inside of reserved 0x3fc84000 - 0x3fc93600
V (1799) memory_layout: Examining memory region 0x3fc90000 - 0x3fca0000
V (1799) memory_layout: Start of region 0x3fc90000 - 0x3fca0000 overlaps reserved 0x3fc84000 - 0x3fc93600
V (1799) memory_layout: Start of region 0x3fc93600 - 0x3fca0000 overlaps reserved 0x3fc93600 - 0x3fc97da8
D (1799) memory_layout: Available memory region 0x3fc97da8 - 0x3fca0000
V (1799) memory_layout: Examining memory region 0x3fca0000 - 0x3fcb0000
D (1799) memory_layout: Available memory region 0x3fca0000 - 0x3fcb0000
V (1799) memory_layout: Examining memory region 0x3fcb0000 - 0x3fcc0000
D (1799) memory_layout: Available memory region 0x3fcb0000 - 0x3fcc0000
V (1799) memory_layout: Examining memory region 0x3fcc0000 - 0x3fcd0000
D (1799) memory_layout: Available memory region 0x3fcc0000 - 0x3fcd0000
V (1799) memory_layout: Examining memory region 0x3fcd0000 - 0x3fce0000
D (1799) memory_layout: Available memory region 0x3fcd0000 - 0x3fce0000
V (1799) memory_layout: Examining memory region 0x3fce0000 - 0x3fce9710
D (1799) memory_layout: Available memory region 0x3fce0000 - 0x3fce9710
V (1799) memory_layout: Examining memory region 0x3fce9710 - 0x3fcf0000
V (1799) memory_layout: End of region 0x3fce9710 - 0x3fcf0000 overlaps reserved 0x3fceee34 - 0x3fcf0000
D (1799) memory_layout: Available memory region 0x3fce9710 - 0x3fceee34
V (1799) memory_layout: Examining memory region 0x3fcf0000 - 0x3fcf8000
D (1799) memory_layout: Available memory region 0x3fcf0000 - 0x3fcf8000
V (1799) memory_layout: Examining memory region 0x600fe000 - 0x60100000
V (1800) memory_layout: Start of region 0x600fe000 - 0x60100000 overlaps reserved 0x600fe000 - 0x600fe11c
V (1800) memory_layout: End of region 0x600fe11c - 0x60100000 overlaps reserved 0x600fffe8 - 0x60100000
D (1800) memory_layout: Available memory region 0x600fe11c - 0x600fffe8
I (1800) heap_init: Initializing. RAM available for dynamic allocation:
D (1800) heap_init: New heap initialised at 0x3fc97da8
I (1800) heap_init: At 3FC97DA8 len 00051968 (326 KiB): RAM
I (1800) heap_init: At 3FCE9710 len 00005724 (21 KiB): RAM
D (1800) heap_init: New heap initialised at 0x3fcf0000
I (1800) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
D (1800) heap_init: New heap initialised at 0x600fe11c
I (1800) heap_init: At 600FE11C len 00001ECC (7 KiB): RTCRAM
D (1800) cpu_start: calling init function: 0x420089dc on core: 0
--- 0x420089dc: __esp_system_init_fn_esp_timer_init_nonos at /opt/toolchains/esp-idf/components/esp_timer/src/esp_timer_init.c:28

D (1800) cpu_start: calling init function: 0x42008428 on core: 0
--- 0x42008428: __esp_system_init_fn_init_newlib at /opt/toolchains/esp-idf/components/newlib/newlib_init.c:157

D (1801) cpu_start: calling init function: 0x4200357c on core: 0
--- 0x4200357c: __esp_system_init_fn_init_brownout at /opt/toolchains/esp-idf/components/esp_system/startup_funcs.c:67

V (1801) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1801) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E
D (1801) intr_alloc: Connected src 39 to int 1 (cpu 0)
D (1801) cpu_start: calling init function: 0x42003588 on core: 0
--- 0x42003588: __esp_system_init_fn_init_newlib_time at /opt/toolchains/esp-idf/components/esp_system/startup_funcs.c:81

D (1801) cpu_start: calling init function: 0x42009ab8 on core: 0
--- 0x42009ab8: __esp_system_init_fn_init_vfs_uart at /opt/toolchains/esp-idf/components/esp_driver_uart/src/uart_vfs.c:1097

D (1801) cpu_start: calling init function: 0x4200aa6c on core: 0
--- 0x4200aa6c: __esp_system_init_fn_init_vfs_usj_sec at /opt/toolchains/esp-idf/components/esp_driver_usb_serial_jtag/src/usb_serial_jtag_vfs.c:628

D (1801) cpu_start: calling init function: 0x4200bf70 on core: 0
--- 0x4200bf70: __esp_system_init_fn_init_vfs_nullfs at /opt/toolchains/esp-idf/components/vfs/nullfs.c:322

D (1801) cpu_start: calling init function: 0x4200ac90 on core: 0
--- 0x4200ac90: __esp_system_init_fn_init_vfs_console at /opt/toolchains/esp-idf/components/esp_vfs_console/vfs_console.c:247

D (1801) cpu_start: calling init function: 0x42008490 on core: 0
--- 0x42008490: __esp_system_init_fn_init_newlib_stdio at /opt/toolchains/esp-idf/components/newlib/newlib_init.c:202

D (1801) cpu_start: calling init function: 0x42003594 on core: 0
--- 0x42003594: __esp_system_init_fn_init_flash at /opt/toolchains/esp-idf/components/esp_system/startup_funcs.c:88

V (1802) memspi: raw_chip_id: 1530EF

V (1802) memspi: chip_id: EF3015

V (1803) memspi: raw_chip_id: 1530EF

V (1803) memspi: chip_id: EF3015

D (1803) spi_flash: trying chip: issi
D (1803) spi_flash: trying chip: gd
D (1803) spi_flash: trying chip: mxic
D (1803) spi_flash: trying chip: winbond
I (1803) spi_flash: detected chip: winbond
I (1803) spi_flash: flash io: dio
D (1803) cpu_start: calling init function: 0x42003188 on core: 0
--- 0x42003188: __esp_system_init_fn_init_efuse at /opt/toolchains/esp-idf/components/efuse/src/esp_efuse_startup.c:142

D (1803) cpu_start: calling init function: 0x42045cf0
--- 0x42045cf0: _GLOBAL__sub_I__ZN17__eh_globals_init7_S_initE at /builds/idf/crosstool-NG/.build/xtensa-esp-elf/src/gcc/libstdc++-v3/libsupc++/eh_globals.cc:162

D (1803) cpu_start: calling init function: 0x420149f8
--- 0x420149f8: _GLOBAL__sub_I__ZN3nvs4PageC2Ev at /opt/toolchains/esp-idf/components/nvs_flash/src/nvs_page.cpp:1158

D (1803) cpu_start: calling init function: 0x4037a288
--- 0x4037a288: enable_timer_group0_for_calibration at /opt/toolchains/esp-idf/components/esp_hw_support/port/esp32s3/rtc_time.c:199

D (1804) cpu_start: calling init function: 0x42004928
--- 0x42004928: esp_ipc_init at /opt/toolchains/esp-idf/components/esp_system/esp_ipc.c:113

D (1804) cpu_start: calling init function: 0x42003b2c
--- 0x42003b2c: esp_reset_reason_init at /opt/toolchains/esp-idf/components/esp_system/port/soc/esp32s3/reset_reason.c:63

D (1804) cpu_start: calling init function: 0x420133c0 on core: 0
--- 0x420133c0: __esp_system_init_fn_esp_timer_init_os at /opt/toolchains/esp-idf/components/esp_timer/src/esp_timer.c:566

V (1804) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1804) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xC02
D (1804) intr_alloc: Connected src 59 to int 2 (cpu 0)
D (1804) cpu_start: calling init function: 0x420535a8 on core: 0
--- 0x420535a8: __esp_system_init_fn_esp_security_init at /opt/toolchains/esp-idf/components/esp_security/src/init.c:36

D (1804) cpu_start: calling init function: 0x42006410 on core: 0
--- 0x42006410: __esp_system_init_fn_esp_sleep_startup_init at /opt/toolchains/esp-idf/components/esp_hw_support/sleep_gpio.c:192

I (1804) sleep_gpio: Configure to isolate all GPIO pins in sleep state
I (1804) sleep_gpio: Enable automatic switching of GPIO sleep configuration
D (1804) cpu_start: calling init function: 0x420035bc on core: 0
--- 0x420035bc: __esp_system_init_fn_init_apb_dma at /opt/toolchains/esp-idf/components/esp_system/startup_funcs.c:125

D (1804) cpu_start: calling init function: 0x4200a3f8 on core: 0
--- 0x4200a3f8: __esp_system_init_fn_usb_serial_jtag_conn_status_init at /opt/toolchains/esp-idf/components/esp_driver_usb_serial_jtag/src/usb_serial_jtag_connection_monitor.c:75

D (1804) cpu_start: calling init function: 0x420035c8 on core: 0
--- 0x420035c8: __esp_system_init_fn_init_disable_rtc_wdt at /opt/toolchains/esp-idf/components/esp_system/startup_funcs.c:143

V (1805) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1805) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E
D (1805) intr_alloc: Connected src 79 to int 3 (cpu 0)
D (1805) app_start: Starting scheduler on CPU0
V (1805) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1805) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x402
D (1805) intr_alloc: Connected src 57 to int 5 (cpu 0)
V (1805) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args
V (1805) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E
I (1805) main_task: Started on CPU0
D (1805) intr_alloc: Connected src 80 to int 0 (cpu 1)
D (1805) app_start: Starting scheduler on CPU1
V (1805) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args
V (1805) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x402
D (1805) intr_alloc: Connected src 58 to int 1 (cpu 1)
D (1805) heap_init: New heap initialised at 0x3fce9710
V (1805) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1805) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (1805) intr_alloc: Connected src 52 to int 8 (cpu 0)
I (1805) main_task: Calling app_main()
V (1805) partition: Loading the partition table
V (1805) mmap: actual_mapped_len is 0x10000
V (1805) calculated md5: 0x3fc9b688   f4 ad 4f 45 38 56 4b 5d  74 35 b6 2c 75 b6 95 24  |..OE8VK]t5.,u..$|
V (1805) stored md5: 0x3c098070   f4 ad 4f 45 38 56 4b 5d  74 35 b6 2c 75 b6 95 24  |..OE8VK]t5.,u..$|
V (1805) partition: Partition table MD5 verified
D (1825) esp_netif_lwip: LwIP stack has been initialized
D (1825) esp_netif_lwip: esp-netif has been successfully initialized
D (1825) event: running task for loop 0x3fc9e238
D (1825) event: created task for loop 0x3fc9e238
D (1825) event: created event loop 0x3fc9e238
D (1825) esp_netif_lwip: check: remote, if=0x3fc9b710 fn=0x42015e6c
--- 0x42015e6c: esp_netif_new_api at /opt/toolchains/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:712

V (1825) esp_netif_objects: esp_netif_add_to_list_unsafe 0x3fc9f220
D (1825) esp_netif_objects: esp_netif_add_to_list_unsafe netif added successfully (total netifs: 1)
D (1825) esp_netif_lwip: call api in lwip: ret=0x0, give sem
V (1825) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1825) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E
D (1825) intr_alloc: Connected src 0 to int 9 (cpu 0)
D (1825) efuse: BLK1 REG1 [8-15], len=8 bits
D (1825) efuse: BLK1 REG1 [0-7], len=8 bits
D (1825) efuse: BLK1 REG0 [24-31], len=8 bits
D (1825) efuse: BLK1 REG0 [16-23], len=8 bits
D (1825) efuse: BLK1 REG0 [8-15], len=8 bits
D (1825) efuse: BLK1 REG0 [0-7], len=8 bits
V (1825) opencores.emac: emac_opencores_set_addr: 00:00:00:00:00:03
V (1825) opencores.emac: emac_opencores_read_phy_reg: addr=1 reg=0x0 val=0x1000
V (1825) opencores.emac: emac_opencores_write_phy_reg: addr=1 reg=0x0 val=0x1000
V (1845) opencores.emac: emac_opencores_read_phy_reg: addr=1 reg=0x0 val=0x1000
V (1845) opencores.emac: emac_opencores_write_phy_reg: addr=1 reg=0x0 val=0x8000
V (1875) opencores.emac: emac_opencores_read_phy_reg: addr=1 reg=0x0 val=0x1000
V (1875) opencores.emac: emac_opencores_read_phy_reg: addr=1 reg=0x2 val=0x2000
V (1875) opencores.emac: emac_opencores_read_phy_reg: addr=1 reg=0x3 val=0x5c90
V (1875) opencores.emac: emac_opencores_read_phy_reg: addr=1 reg=0x3 val=0x5c90
V (1875) opencores.emac: emac_opencores_read_phy_reg: addr=1 reg=0x0 val=0x1000
D (1875) esp_eth: new ethernet driver @0x3fca1db0
V (1875) opencores.emac: emac_opencores_set_addr: 00:00:00:00:00:03
V (1875) opencores.emac: emac_opencores_get_addr: c8:e0:00:42:28:1e
I (1875) esp_eth.netif.netif_glue: 00:00:00:00:00:03
D (1875) esp_netif_lwip: check: remote, if=0x3fc9f220 fn=0x42015600
--- 0x42015600: esp_netif_set_mac_api at /opt/toolchains/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1018

D (1875) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (1875) esp_eth.netif.netif_glue: ethernet attached to netif
V (1875) opencores.emac: emac_opencores_read_phy_reg: addr=1 reg=0x0 val=0x1000
V (1875) opencores.emac: emac_opencores_write_phy_reg: addr=1 reg=0x0 val=0x1200
V (1975) opencores.emac: emac_opencores_read_phy_reg: addr=1 reg=0x1 val=0x786c
D (1975) event: running post ETH_EVENT:0 with handler 0x4200e1d8 and context 0x3fca1e80 on loop 0x3fc9e238
--- 0x4200e1d8: eth_action_start at /opt/toolchains/esp-idf/components/esp_eth/src/esp_eth_netif_glue.c:76

D (1975) esp_eth.netif.netif_glue: eth_action_start: 0x3fca1e28, 0x3c066a78, 0, 0x3fca1fe4, 0x3fca1db0
D (1975) esp_netif_handlers: esp_netif action has started with netif0x3fc9f220 from event_id=0
D (1975) esp_netif_lwip: check: remote, if=0x3fc9f220 fn=0x42016090
--- 0x42016090: esp_netif_start_api at /opt/toolchains/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1093

V (1975) opencores.emac: emac_opencores_read_phy_reg: addr=1 reg=0x1 val=0x786c
V (1975) opencores.emac: emac_opencores_read_phy_reg: addr=1 reg=0x5 val=0x01e1
D (1975) esp_netif_lwip: esp_netif_start_api 0x3fc9f220
D (1975) esp_netif_lwip: esp_netif_get_hostname esp_netif:0x3fc9f220
D (1975) esp_netif_lwip: call api in lwip: ret=0x0, give sem
V (1975) opencores.emac: emac_opencores_read_phy_reg: addr=1 reg=0x10 val=0x0017
V (1975) opencores.emac: emac_opencores_set_link: up
D (1975) event: running post ETH_EVENT:2 with handler 0x4200e140 and context 0x3fca1ee0 on loop 0x3fc9e238
--- 0x4200e140: eth_action_connected at /opt/toolchains/esp-idf/components/esp_eth/src/esp_eth_netif_glue.c:96

D (1975) esp_eth.netif.netif_glue: eth_action_connected: 0x3fca1e28, 0x3c066a78, 2, 0x3fca1fe4, 0x3fca1db0
D (1975) esp_netif_handlers: esp_netif action connected with netif0x3fc9f220 from event_id=2
D (1975) esp_netif_lwip: check: remote, if=0x3fc9f220 fn=0x420162b0
--- 0x420162b0: esp_netif_up_api at /opt/toolchains/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1723

D (1975) esp_netif_lwip: esp_netif_up_api esp_netif:0x3fc9f220
I (1975) ethernet_connect: Waiting for IP(s).
D (1975) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (1975) esp_netif_lwip: check: remote, if=0x3fc9f220 fn=0x42015a94
--- 0x42015a94: esp_netif_dhcpc_start_api at /opt/toolchains/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1515

D (1985) esp_netif_lwip: esp_netif_dhcpc_start_api esp_netif:0x3fc9f220
D (1985) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3fc9f220
D (1985) esp_netif_lwip: if0x3fc9f220 start ip lost tmr: interval=120
D (1985) esp_netif_lwip: starting dhcp client
V (1985) opencores.emac: emac_opencores_transmit: len=350
V (1985) opencores.emac: emac_opencores_transmit: desc 0 (0x600cd400) len=350 wr=1
V (1985) opencores.emac: emac_opencores_receive: desc 0 (0x600cd408) e=0 len=594 wr=0
D (1985) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (1985) event: running post ETH_EVENT:2 with handler 0x4200c8a4 and context 0x3fca1f94 on loop 0x3fc9e238
--- 0x4200c8a4: on_eth_event at /opt/toolchains/esp-idf/examples/common_components/protocol_examples_common/eth_connect.c:65

I (1985) ethernet_connect: Ethernet Link Up
D (1985) esp_netif_lwip: check: remote, if=0x3fc9f220 fn=0x42015bd4
--- 0x42015bd4: esp_netif_create_ip6_linklocal_api at /opt/toolchains/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:2186

V (1985) opencores.emac: emac_opencores_receive: desc 1 (0x600cd410) e=1 len=0 wr=0
V (1985) opencores.emac: emac_opencores_transmit: len=350
V (1985) opencores.emac: emac_opencores_transmit: desc 0 (0x600cd400) len=350 wr=1
V (1985) opencores.emac: emac_opencores_receive: desc 1 (0x600cd410) e=0 len=594 wr=0
V (1985) esp_netif_lwip: esp_netif_create_ip6_linklocal_api esp-netif:0x3fc9f220
D (1985) esp_netif_lwip: call api in lwip: ret=0x0, give sem
V (1985) opencores.emac: emac_opencores_receive: desc 2 (0x600cd418) e=1 len=0 wr=0
V (1985) opencores.emac: emac_opencores_transmit: len=42
V (1985) opencores.emac: emac_opencores_transmit: desc 0 (0x600cd400) len=42 wr=1
V (2485) opencores.emac: emac_opencores_transmit: len=42
V (2485) opencores.emac: emac_opencores_transmit: desc 0 (0x600cd400) len=42 wr=1
V (2825) opencores.emac: emac_opencores_transmit: len=42
V (2825) opencores.emac: emac_opencores_transmit: desc 0 (0x600cd400) len=42 wr=1
V (2825) opencores.emac: emac_opencores_transmit: len=86
V (2825) opencores.emac: emac_opencores_transmit: desc 0 (0x600cd400) len=86 wr=1
V (2825) opencores.emac: emac_opencores_transmit: len=78
V (2825) opencores.emac: emac_opencores_transmit: desc 0 (0x600cd400) len=78 wr=1
V (2825) opencores.emac: emac_opencores_transmit: len=62
V (2825) opencores.emac: emac_opencores_transmit: desc 0 (0x600cd400) len=62 wr=1
V (2825) opencores.emac: emac_opencores_receive: desc 2 (0x600cd418) e=0 len=114 wr=0
V (2825) opencores.emac: emac_opencores_receive: desc 3 (0x600cd420) e=1 len=0 wr=1
V (2935) opencores.emac: emac_opencores_transmit: len=86
V (2935) opencores.emac: emac_opencores_transmit: desc 0 (0x600cd400) len=86 wr=1
D (2995) esp_netif_lwip: esp_netif_internal_dhcpc_cb lwip-netif:0x3fc9f2ac
D (2995) esp_netif_lwip: check: local, if=0x3fc9f220 fn=0x42016718
--- 0x42016718: esp_netif_update_default_netif_lwip at /opt/toolchains/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:313

D (2995) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fc9f220
V (2995) esp_netif_lwip: esp_netif_is_netif_up esp_netif:0x3fc9f220
D (2995) esp_netif_lwip: if0x3fc9f220 ip changed=1
D (2995) event: running post IP_EVENT:4 with handler 0x4200e0c8 and context 0x3fca1f54 on loop 0x3fc9e238
--- 0x4200e0c8: eth_action_got_ip at /opt/toolchains/esp-idf/components/esp_eth/src/esp_eth_netif_glue.c:119

D (2995) esp_eth.netif.netif_glue: eth_action_got_ip: 0x3fca1e28, 0x3c06af88, 4, 0x3fca2144, 0x3fc9f220
D (2995) esp_netif_handlers: esp_netif action got_ip with netif0x3fc9f220 from event_id=4
I (2995) esp_netif_handlers: example_netif_eth ip: 10.0.2.15, mask: 255.255.255.0, gw: 10.0.2.2
D (2995) event: running post IP_EVENT:4 with handler 0x4200c9ec and context 0x3fca1f74 on loop 0x3fc9e238
--- 0x4200c9ec: eth_on_got_ip at /opt/toolchains/esp-idf/examples/common_components/protocol_examples_common/eth_connect.c:37

I (2995) ethernet_connect: Got IPv4 event: Interface "example_netif_eth" address: 10.0.2.15
V (3825) opencores.emac: emac_opencores_transmit: len=42
V (3825) opencores.emac: emac_opencores_transmit: desc 0 (0x600cd400) len=42 wr=1
D (3825) esp_netif_lwip: esp_netif_internal_nd6_cb lwip-netif:0x3fc9f2ac
D (3825) esp_netif_lwip: check: local, if=0x3fc9f220 fn=0x42016718
--- 0x42016718: esp_netif_update_default_netif_lwip at /opt/toolchains/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:313

D (3825) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fc9f220
V (3825) esp_netif_lwip: esp_netif_is_netif_up esp_netif:0x3fc9f220
V (3825) esp_netif_lwip: esp_netif_is_netif_up esp_netif:0x3fc9f220
D (3825) event: running post IP_EVENT:3 with handler 0x4200c8e0 and context 0x3fca1fc4 on loop 0x3fc9e238
--- 0x4200c8e0: eth_on_got_ipv6 at /opt/toolchains/esp-idf/examples/common_components/protocol_examples_common/eth_connect.c:50

I (3825) ethernet_connect: Got IPv6 event: Interface "example_netif_eth" address: fe80:0000:0000:0000:0200:00ff:fe00:0003, type: ESP_IP6_ADDR_IS_LINK_LOCAL
V (3825) opencores.emac: emac_opencores_transmit: len=78
D (3825) esp_netif_lwip: check: remote, if=0x4200c5a0 fn=0x42053c78
--- 0x4200c5a0: print_all_ips_tcpip at /opt/toolchains/esp-idf/examples/common_components/protocol_examples_common/connect.c:57
0x42053c78: tcpip_exec_api at /opt/toolchains/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:702

V (3825) opencores.emac: emac_opencores_transmit: desc 0 (0x600cd400) len=78 wr=1
V (3825) esp_netif_objects: esp_netif_next_unsafe 0x0
I (3825) example_common: Connected to example_netif_eth
D (3825) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fc9f220
I (3825) example_common: - IPv4 address: 10.0.2.15,
V (3825) esp_netif_lwip: esp_netif_get_all_ip6 esp-netif:0x3fc9f220
I (3825) example_common: - IPv6 address: fe80:0000:0000:0000:0200:00ff:fe00:0003, type: ESP_IP6_ADDR_IS_LINK_LOCAL
V (3825) esp_netif_objects: esp_netif_next_unsafe 0x3fc9f220
D (3825) esp_netif_lwip: call api in lwip: ret=0x0, give sem
V (3825) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (3825) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x420059a9  PS      : 0x00060333  A0      : 0x82005af9  A1      : 0x3fca3720  
--- 0x420059a9: find_desc_for_source at /opt/toolchains/esp-idf/components/esp_hw_support/intr_alloc.c:175

A2      : 0x00060d23  A3      : 0x00000000  A4      : 0x0000000c  A5      : 0x3fca374c  
A6      : 0x00000014  A7      : 0x00000000  A8      : 0x00000000  A9      : 0x00000004  
A10     : 0x0000004d  A11     : 0x00000008  A12     : 0x00000804  A13     : 0x00000045  
A14     : 0x00000000  A15     : 0x3fc98498  SAR     : 0x00000020  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x00060d23  LBEG    : 0x400570e8  LEND    : 0x400570f3  LCOUNT  : 0xffffffff  
--- 0x400570e8: memset in ROM
0x400570f3: memset in ROM



Backtrace: 0x420059a6:0x3fca3720 0x42005af6:0x3fca3740 0x42005d70:0x3fca3790 0x42005fd1:0x3fca37e0 0x4202beb3:0x3fca3810 0x42025ac7:0x3fca3830 0x4201e30e:0x3fca3850 0x4200bf97:0x3fca3870 0x4037b2c9:0x3fca3fc0
--- 0x420059a6: find_desc_for_source at /opt/toolchains/esp-idf/components/esp_hw_support/intr_alloc.c:174
0x42005af6: get_available_int at /opt/toolchains/esp-idf/components/esp_hw_support/intr_alloc.c:332
0x42005d70: esp_intr_alloc_intrstatus at /opt/toolchains/esp-idf/components/esp_hw_support/intr_alloc.c:553
0x42005fd1: esp_intr_alloc at /opt/toolchains/esp-idf/components/esp_hw_support/intr_alloc.c:677
0x4202beb3: esp_aes_intr_alloc at /opt/toolchains/esp-idf/components/mbedtls/port/aes/dma/esp_aes_dma_core.c:100
0x42025ac7: esp_aes_init at /opt/toolchains/esp-idf/components/mbedtls/port/aes/esp_aes_common.c:46
0x4201e30e: mbedtls_ctr_drbg_init at /opt/toolchains/esp-idf/components/mbedtls/mbedtls/library/ctr_drbg.c:80
0x4200bf97: https_get_task at /workspace/apps/https_mbedtls/main/https_mbedtls_example_main.c:74
0x4037b2c9: vPortTaskWrapper at /opt/toolchains/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:139

More Information.

Log file for ESP32S3

Here is the log file for the ESP32S3 not working under QEMU: esp32s3-https-qemu.log

Working example for other variants

If you change the target to something else (e.g. esp32, esp32c3), the example successfully builds and connects to the provided website.

idf.py set-target esp32
idf.py qemu monitor

As you can see from this log file, the connection process works as expected: esp32-https-qemu.log

Note that building for the esp32s2 with OpenEth fails. I will file a separate bug for that.

@ShawnHymel ShawnHymel added the Type: Bug bugs in IDF label Feb 22, 2025
@github-actions github-actions bot changed the title TLS handshake fails for ESP32S3 in QEMU TLS handshake fails for ESP32S3 in QEMU (IDFGH-14706) Feb 22, 2025
@espressif-bot espressif-bot added the Status: Opened Issue is new label Feb 22, 2025
@Harshal5
Copy link
Collaborator

Hello @ShawnHymel,

The command idf.py qemu uses the latest release of Espressif's QEMU package. Currently the latest release (esp-develop-9.0.0-20240606), and as mentioned in the release notes, adds just the initial support for ESP32-S3.

I am able to recreate the issue by running the example using the command idf.py qemu, but the issue seems to have been fixed in the development branch of QEMU. Probably until the next QEMU version is released, you could try out the ESP-IDF example by building the latest QEMU version manually using the steps mentioned here. Here are the logs for the same: https_mbedtls.log

Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Status: Opened Issue is new Type: Bug bugs in IDF
Projects
None yet
Development

No branches or pull requests

3 participants