Wifi: `assert failed multi_heap_malloc` when connecting to wifi AP (IDFGH-9608)

DCSBL commented 1 year 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.0

Operating System used.

macOS

How did you build your project?

Command line with idf.py

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

None

Development Kit.

ESP32-S3-WROOM-1 / MON16R8

Power Supply used.

USB

What is the expected behavior?

The device should connect to the ESP all the times

What is the actual behavior?

Instead the ESP crashes sometimes.

Steps to reproduce.

Hard to tell, it happens not very often. But when it happens is seems to be related with trying to connect to fast after boot.

E.g. The device (in this case a Macbook) is connected to the AP and has an IP. The ESP reboots/resets and the phone retries the connection. The ESP receives the connection request quite early.

Debug Logs.

ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce3810,len:0x1684
load:0x403c9700,len:0xbe8
load:0x403cc700,len:0x2ef0
entry 0x403c9904
I (25) boot: ESP-IDF v5.0 2nd stage bootloader
I (25) boot: compile time 14:10:33
I (25) boot: chip revision: v0.1
I (27) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (34) boot.esp32s3: Boot SPI Speed : 80MHz
I (39) boot.esp32s3: SPI Mode       : DIO
I (43) boot.esp32s3: SPI Flash Size : 16MB
I (48) boot: Enabling RNG early entropy source...
<redacted>
I (379) boot: Loaded app from partition at offset 0x30000
I (380) boot: Disabling RNG early entropy source...
I (393) octal_psram: vendor id    : 0x0d (AP)
I (393) octal_psram: dev id       : 0x02 (generation 3)
I (393) octal_psram: density      : 0x03 (64 Mbit)
I (398) octal_psram: good-die     : 0x01 (Pass)
I (403) octal_psram: Latency      : 0x01 (Fixed)
I (409) octal_psram: VCC          : 0x01 (3V)
I (414) octal_psram: SRF          : 0x01 (Fast Refresh)
I (419) octal_psram: BurstType    : 0x01 (Hybrid Wrap)
I (425) octal_psram: BurstLen     : 0x01 (32 Byte)
I (431) octal_psram: Readlatency  : 0x02 (10 cycles@Fixed)
I (437) octal_psram: DriveStrength: 0x00 (1/1)
W (442) PSRAM: DO NOT USE FOR MASS PRODUCTION! Timing parameters will be updated in future IDF version.
I (458) esp_psram: Found 8MB PSRAM device
I (458) esp_psram: Speed: 120MHz
I (536) mmu_psram: Instructions copied and mapped to SPIRAM
I (566) mmu_psram: Read only data copied and mapped to SPIRAM
I (566) cpu_start: Pro cpu up.
I (567) cpu_start: Starting app cpu, entry point is 0x40375878
0x40375878: call_start_cpu1 at ~/esp/esp-idf-v5.0/components/esp_system/port/cpu_start.c:142

I (0) cpu_start: App cpu up.
I (833) esp_psram: SPI SRAM memory test OK
I (842) cpu_start: Pro cpu start user code
I (842) cpu_start: cpu freq: 240000000 Hz
I (842) cpu_start: Application information:
I (845) cpu_start: Project name:     <redacted>
I (850) cpu_start: App version:      0.1-89-g534e684-dirty
I (856) cpu_start: Compile time:     Mar  9 2023 14:17:15
I (862) cpu_start: ELF file SHA256:  750a12b008e3784e...
I (868) cpu_start: ESP-IDF:          v5.0
I (873) heap_init: Initializing. RAM available for dynamic allocation:
I (881) heap_init: At 3FCA2D38 len 000469D8 (282 KiB): D/IRAM
I (887) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
I (894) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (900) heap_init: At 600FE010 len 00001FF0 (7 KiB): RTCRAM
I (1054) esp_psram: Adding pool of 7092K of PSRAM memory to heap allocator
I (1054) spi_flash: detected chip: gd
I (1054) spi_flash: flash io: dio
I (1059) sleep: Configure to isolate all GPIO pins in sleep state
I (1065) sleep: Enable automatic switching of GPIO sleep configuration
I (1072) esp_core_dump_uart: Init core dump to UART
I (1078) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1094) esp_psram: Reserving pool of 32K of internal memory for DMA/internal allocations
<redacted, not relevant>
I (1456) pp: pp rom version: e7ae62f
I (1460) net80211: net80211 rom version: e7ae62f
I (1466) wifi:wifi driver task: 3fceeb5c, prio:23, stack:6656, core=0
I (1484) wifi:wifi firmware version: 0d470ef
I (1484) wifi:wifi certification version: v7.0
I (1484) wifi:config NVS flash: enabled
I (1484) wifi:config nano formating: disabled
I (1489) wifi:Init data frame dynamic rx buffer num: 32
I (1494) wifi:Init management frame dynamic rx buffer num: 32
I (1499) wifi:Init management short buffer num: 32
I (1504) wifi:Init static tx buffer num: 16
I (1509) wifi:Init tx cache buffer num: 32
I (1511) wifi:Init static tx FG buffer num: 2
I (1515) wifi:Init static rx buffer size: 1600
I (1520) wifi:Init static rx buffer num: 16
I (1523) wifi:Init dynamic rx buffer num: 32
I (1528) wifi_init: rx ba win: 16
I (1531) wifi_init: tcpip mbox: 32
I (1535) wifi_init: udp mbox: 6
I (1539) wifi_init: tcp mbox: 6
I (1543) wifi_init: tcp tx win: 5744
I (1547) wifi_init: tcp rx win: 5744
I (1552) wifi_init: tcp mss: 1440
I (1556) wifi_init: WiFi/LWIP prefer SPIRAM
I (1560) wifi_init: WiFi IRAM OP enabled
I (1565) wifi_init: WiFi RX IRAM OP enabled
<starting APSTA>
I (3668) phy_init: phy_version 503,13653eb,Jun  1 2022,17:47:08
I (3709) wifi:mode : sta (<redacted>) + softAP (<redacted>)
I (3709) wifi:enable tsf
I (3711) wifi:Total power save buffer number: 8
I (3711) wifi:Init max length of beacon: 752/752
I (3715) wifi:Init max length of beacon: 752/752
I (13311) wifi:new:<1,0>, old:<1,1>, ap:<1,1>, sta:<0,0>, prof:1
I (13312) wifi:station: 14:7d:da:2a:b8:cf join, AID=1, bgn, 20
I (17315) wifi:station: 14:7d:da:2a:b8:cf leave, AID = 1, bss_flags is 134242, bss:0x3c203dcc
I (17315) wifi:new:<1,0>, old:<1,0>, ap:<1,1>, sta:<0,0>, prof:1
I (26208) wifi:new:<1,0>, old:<1,0>, ap:<1,1>, sta:<0,0>, prof:1
I (26208) wifi:station: 14:7d:da:2a:b8:cf join, AID=1, bgn, 20
I (30210) wifi:station: 14:7d:da:2a:b8:cf leave, AID = 1, bss_flags is 134242, bss:0x3c203f3c
I (30210) wifi:new:<1,0>, old:<1,0>, ap:<1,1>, sta:<0,0>, prof:1
I (30499) wifi:new:<1,0>, old:<1,0>, ap:<1,1>, sta:<0,0>, prof:1
I (30500) wifi:station: 14:7d:da:2a:b8:cf join, AID=1, bgn, 20
I (34501) wifi:station: 14:7d:da:2a:b8:cf leave, AID = 1, bss_flags is 134242, bss:0x3c203f3c
I (34501) wifi:new:<1,0>, old:<1,0>, ap:<1,1>, sta:<0,0>, prof:1
I (35148) wifi:new:<1,0>, old:<1,0>, ap:<1,1>, sta:<0,0>, prof:1
I (35148) wifi:station: 14:7d:da:2a:b8:cf join, AID=1, bgn, 20
I (35407) wifi:new:<1,0>, old:<1,0>, ap:<1,1>, sta:<0,0>, prof:1
I (35407) wifi:Send SA Query req with transaction id 6e0b
I (35612) wifi:Send SA Query req with transaction id 757e
I (35817) wifi:Send SA Query req with transaction id 68e7
I (36022) wifi:Send SA Query req with transaction id f62e
I (36226) wifi:Send SA Query req with transaction id 6324
I (36431) wifi:STA not responded to 5 SA Query attempts, Reset connection sending disassoc
I (36432) wifi:station: 14:7d:da:2a:b8:cf leave, AID = 1, bss_flags is 134242, bss:0x3c203f3c
I (36437) wifi:new:<1,0>, old:<1,0>, ap:<1,1>, sta:<0,0>, prof:1
CORRUPT HEAP: Invalid data at 0x3c20423c. Expected 0xfefefefe got 0x00000000

assert failed: multi_heap_malloc multi_heap_poisoning.c:256 (ret)

Backtrace: 0x403764a6:0x3fcf7930 0x4037f5b5:0x3fcf7950 0x40386aea:0x3fcf7970 0x40385025:0x3fcf7a90 0x4037664a:0x3fcf7ac0 0x403767cd:0x3fcf7af0 0x4037a6e6:0x3fcf7b50 0x4206e559:0x3fcf7b70 0x4205ad31:0x3fcf7ba0 0x4205b989:0x3fcf7bd0 0x4205c5b1:0x3fcf7ce0 0x4205acb9:0x3fcf7d40 0x4003f4dd:0x3fcf7d60 |<-CORRUPTED
0x403764a6: panic_abort at ~/esp/esp-idf-v5.0/components/esp_system/panic.c:412

0x4037f5b5: esp_system_abort at ~/esp/esp-idf-v5.0/components/esp_system/esp_system.c:135

0x40386aea: __assert_func at ~/esp/esp-idf-v5.0/components/newlib/assert.c:78

0x40385025: multi_heap_malloc at ~/esp/esp-idf-v5.0/components/heap/multi_heap_poisoning.c:256
 (inlined by) multi_heap_malloc at ~/esp/esp-idf-v5.0/components/heap/multi_heap_poisoning.c:238

0x4037664a: heap_caps_malloc_base at ~/esp/esp-idf-v5.0/components/heap/heap_caps.c:146

0x403767cd: heap_caps_calloc_base at ~/esp/esp-idf-v5.0/components/heap/heap_caps.c:458
 (inlined by) heap_caps_calloc_prefer at ~/esp/esp-idf-v5.0/components/heap/heap_caps.c:307

0x4037a6e6: wifi_calloc at ~/esp/esp-idf-v5.0/components/esp_wifi/esp32s3/esp_adapter.c:92
 (inlined by) wifi_zalloc_wrapper at ~/esp/esp-idf-v5.0/components/esp_wifi/esp32s3/esp_adapter.c:100

0x4206e559: cnx_node_alloc at ??:?

0x4205ad31: hostap_auth_open at ??:?

0x4205b989: hostap_recv_mgmt at ??:?

0x4205c5b1: hostap_input at ??:?

0x4205acb9: ap_rx_cb at ??:?

More Information.

SPIRAM is used

CONFIG_SPIRAM=y
CONFIG_SPIRAM_MODE_OCT=y
CONFIG_SPIRAM_FETCH_INSTRUCTIONS=y
CONFIG_SPIRAM_RODATA=y
CONFIG_SPIRAM_SPEED_120M=y
CONFIG_MBEDTLS_EXTERNAL_MEM_ALLOC=y
CONFIG_SPIRAM_TRY_ALLOCATE_WIFI_LWIP=y
CONFIG_SPIRAM_ALLOW_BSS_SEG_EXTERNAL_MEMORY=y
CONFIG_SPIRAM_MALLOC_ALWAYSINTERNAL=8192

Heap poisoning is enabled during early development of the product

CONFIG_HEAP_POISONING_COMPREHENSIVE=y
CONFIG_HEAP_ABORT_WHEN_ALLOCATION_FAILS=y

DCSBL commented 1 year ago

Something I also notice is that this issue only happens when the macbook failed to connect just before that.

ESP starts, network is available
Macbook does not see the AP in the network list, after a few seconds the macbook rescans and connects to the AP
It connects, but is not able to get an IP. It reconnects and 'crash'

nachiketkukade commented 1 year ago

This issue is same as #9973 , fix is merged on master and will be available on v5.0 in couple of days

DCSBL commented 1 year ago

Ah yes. Searching is hard. Thanks!

espressif / esp-idf