CORRUPT HEAP after reconnect
Posted: Wed Oct 12, 2022 12:30 am
Equipment:
ESP32-S2-WROVER with SDK ESP-IDF v5.0-beta1-641-gc321739074
Configuration:
WiFi in mode WIFI_MODE_APSTA
Heap corruption detection = Comprehensive
authmode of ESP-AP = WIFI_AUTH_WPA2_PSK
The Problem:
heap corruption after reconnect
Action:
- Smartphone connects to ESP32-AP (channel 1)
- ESP32 connects to external accesspoint (channel 3 .. 11)
- Smartphone is not capable to switch channel during a connection, so it disconnets
- The ESP32 doesn't recognise the disconnect
- The smartphone connects again to the ESP32-AP
-> CORRUPT HEAP: Invalid data at 0x3ffdd4a0. Expected 0xfefefefe got 0x00000000
Code:
Log:
The problem occurs if authmode of ESP32-AP is WIFI_AUTH_WPA2_PSK.
The problem doesn't occur if authmode of ESP32-AP is WIFI_AUTH_OPEN.
I tested with ESP32-S2-WROVER and ESP32-S3-WROOM-1-N8R8 and got similar results.
I tested with PSRAM enabled and disabled and got similar results.
The problem doesn't occur always.
The original application is much more complex but I reduced the code to the relevant functions. According to the documentation "Expected 0xfefefefe got 0x..." indicates the app has a use-after-free bug. As there is no dynamic allocation in the application code, I suppose there is a bug somewhere else in the IDE.
ESP32-S2-WROVER with SDK ESP-IDF v5.0-beta1-641-gc321739074
Configuration:
WiFi in mode WIFI_MODE_APSTA
Heap corruption detection = Comprehensive
authmode of ESP-AP = WIFI_AUTH_WPA2_PSK
The Problem:
heap corruption after reconnect
Action:
- Smartphone connects to ESP32-AP (channel 1)
- ESP32 connects to external accesspoint (channel 3 .. 11)
- Smartphone is not capable to switch channel during a connection, so it disconnets
- The ESP32 doesn't recognise the disconnect
- The smartphone connects again to the ESP32-AP
-> CORRUPT HEAP: Invalid data at 0x3ffdd4a0. Expected 0xfefefefe got 0x00000000
Code:
- #include "esp_log.h"
- #include "esp_wifi.h"
- #include "nvs_flash.h"
- #include "lwip/ip_addr.h"
- static const char* TAG = "main.c";
- static uint16_t connect_timer = 0;
- static void wifi_event_handler(void* arg, esp_event_base_t event_base, int32_t event_id, void* event_data)
- {
- ESP_LOGI(TAG, "event_base = %i, event_id = %i", (int16_t) *event_base, (int16_t) event_id);
- if ((event_base == WIFI_EVENT) && (event_id == WIFI_EVENT_STA_START))
- { connect_timer = 1; }
- else if ((event_base == WIFI_EVENT) && (event_id == WIFI_EVENT_STA_DISCONNECTED))
- { connect_timer = 1; }
- else if ((event_base == IP_EVENT) && (event_id == IP_EVENT_STA_GOT_IP))
- {
- ip_event_got_ip_t* event = (ip_event_got_ip_t*) event_data;
- ESP_LOGI(TAG, "got ip:" IPSTR, IP2STR(&event->ip_info.ip));
- }
- }
- void app_main(void)
- {
- esp_netif_t* wifiAP;
- esp_netif_t* wifiSTA;
- esp_err_t ret;
- wifi_config_t s_wifi_config_ap = \
- {
- .ap = \
- {
- .channel = 1,
- .authmode = WIFI_AUTH_WPA_WPA2_PSK,
- .max_connection = 4,
- },
- };
- wifi_config_t wifi_config_sta = \
- {
- .sta = \
- {
- .ssid = "externalSSID",
- .password = "sectretPASSWORD",
- },
- };
- ret = nvs_flash_init();
- if ((ret == ESP_ERR_NVS_NO_FREE_PAGES) || (ret == ESP_ERR_NVS_NEW_VERSION_FOUND))
- {
- // NVS partition was truncated and needs to be erased
- // retry nvs_flash_init
- ESP_ERROR_CHECK(nvs_flash_erase());
- ret = nvs_flash_init();
- }
- ESP_ERROR_CHECK(ret);
- ESP_ERROR_CHECK(esp_netif_init());
- ESP_ERROR_CHECK(esp_event_loop_create_default());
- wifi_init_config_t cfg = WIFI_INIT_CONFIG_DEFAULT();
- ret = esp_wifi_init(&cfg);
- if (ret != ESP_OK) { ESP_LOGE(TAG, "esp_wifi_init(&cfg): ret = %s", esp_err_to_name(ret)); }
- esp_wifi_set_mode(WIFI_MODE_NULL);
- ESP_ERROR_CHECK(esp_event_handler_instance_register(IP_EVENT, IP_EVENT_STA_GOT_IP, &wifi_event_handler, NULL, NULL));
- ESP_ERROR_CHECK(esp_event_handler_instance_register(WIFI_EVENT, ESP_EVENT_ANY_ID, &wifi_event_handler, NULL, NULL));
- esp_wifi_set_storage(WIFI_STORAGE_FLASH);
- wifiAP = esp_netif_create_default_wifi_ap();
- assert(wifiAP);
- wifiSTA = esp_netif_create_default_wifi_sta();
- assert(wifiSTA);
- ESP_LOGI(TAG, "start AP STA");
- ESP_ERROR_CHECK(esp_wifi_set_mode(WIFI_MODE_APSTA));
- // AP
- esp_netif_ip_info_t ipInfo;
- strcpy((char*) s_wifi_config_ap.ap.ssid, "test123");
- s_wifi_config_ap.ap.ssid_len = strlen((char*) s_wifi_config_ap.ap.ssid);
- strcpy((char*) s_wifi_config_ap.ap.password, "mypassword");
- IP4_ADDR(&ipInfo.ip, 192,168,4,1);
- IP4_ADDR(&ipInfo.gw, 192,168,4,1);
- IP4_ADDR(&ipInfo.netmask, 255,255,255,0);
- esp_netif_dhcps_stop(wifiAP);
- esp_netif_set_ip_info(wifiAP, &ipInfo);
- esp_netif_dhcps_start(wifiAP);
- ESP_LOGI(TAG, "IP: " IPSTR, IP2STR(&ipInfo.ip));
- ESP_LOGI(TAG, "GW: " IPSTR, IP2STR(&ipInfo.gw));
- ESP_LOGI(TAG, "Mask: " IPSTR, IP2STR(&ipInfo.netmask));
- // AP
- ESP_ERROR_CHECK(esp_wifi_set_config(ESP_IF_WIFI_AP, &s_wifi_config_ap));
- ESP_LOGI(TAG, "wifi_init_softap finished. SSID: %s password: %s", \
- (char*) s_wifi_config_ap.ap.ssid, (char*) s_wifi_config_ap.ap.password);
- // STA
- ESP_ERROR_CHECK(esp_wifi_set_config(ESP_IF_WIFI_STA, &wifi_config_sta));
- ESP_ERROR_CHECK(esp_wifi_start());
- while (true)
- {
- if (connect_timer >= 300)
- {
- connect_timer = 0;
- esp_wifi_connect();
- }
- else if (connect_timer > 0) { connect_timer++; }
- vTaskDelay(pdMS_TO_TICKS(10));
- }
- }
Log:
- Build:Oct 25 2019
- rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
- SPIWP:0xee
- mode:DIO, clock div:1
- load:0x3ffe6108,len:0x17a8
- load:0x4004c000,len:0xaa4
- load:0x40050000,len:0x3138
- entry 0x4004c1bc
- [0;32mI (21) boot: ESP-IDF v5.0-beta1-641-gc321739074 2nd stage bootloader[0m
- [0;32mI (21) boot: compile time 01:55:58[0m
- [0;32mI (22) boot: chip revision: V000[0m
- [0;32mI (26) boot.esp32s2: SPI Speed : 80MHz[0m
- [0;32mI (30) boot.esp32s2: SPI Mode : DIO[0m
- [0;32mI (35) boot.esp32s2: SPI Flash Size : 2MB[0m
- [0;32mI (40) boot: Enabling RNG early entropy source...[0m
- [0;32mI (45) boot: Partition Table:[0m
- [0;32mI (49) boot: ## Label Usage Type ST Offset Length[0m
- [0;32mI (56) boot: 0 nvs WiFi data 01 02 00009000 00006000[0m
- [0;32mI (64) boot: 1 phy_init RF data 01 01 0000f000 00001000[0m
- [0;32mI (71) boot: 2 factory factory app 00 00 00010000 00100000[0m
- [0;32mI (79) boot: End of partition table[0m
- [0;32mI (83) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=1d124h (119076) map[0m
- [0;32mI (115) esp_image: segment 1: paddr=0002d14c vaddr=3ffc5a00 size=02ecch ( 11980) load[0m
- [0;32mI (118) esp_image: segment 2: paddr=00030020 vaddr=40080020 size=71998h (465304) map[0m
- [0;32mI (213) esp_image: segment 3: paddr=000a19c0 vaddr=3ffc88cc size=0073ch ( 1852) load[0m
- [0;32mI (214) esp_image: segment 4: paddr=000a2104 vaddr=40022000 size=139fch ( 80380) load[0m
- [0;32mI (239) esp_image: segment 5: paddr=000b5b08 vaddr=50000000 size=00010h ( 16) load[0m
- [0;32mI (249) boot: Loaded app from partition at offset 0x10000[0m
- [0;32mI (250) boot: Disabling RNG early entropy source...[0m
- [0;32mI (262) cache: Instruction cache : size 8KB, 4Ways, cache line size 32Byte[0m
- [0;32mI (262) cpu_start: Pro cpu up.[0m
- [0;32mI (281) cpu_start: Pro cpu start user code[0m
- [0;32mI (281) cpu_start: cpu freq: 160000000 Hz[0m
- [0;32mI (281) cpu_start: Application information:[0m
- [0;32mI (284) cpu_start: Project name: wifi_test[0m
- [0;32mI (289) cpu_start: App version: 1[0m
- [0;32mI (293) cpu_start: Compile time: Oct 12 2022 01:55:50[0m
- [0;32mI (299) cpu_start: ELF file SHA256: d73d438bf07a0c2a...[0m
- [0;32mI (305) cpu_start: ESP-IDF: v5.0-beta1-641-gc321739074[0m
- [0;32mI (312) heap_init: Initializing. RAM available for dynamic allocation:[0m
- [0;32mI (320) heap_init: At 3FFCCD98 len 0002F268 (188 KiB): DRAM[0m
- [0;32mI (325) heap_init: At 3FFFC000 len 00003A10 (14 KiB): DRAM[0m
- [0;32mI (332) heap_init: At 3FF9E000 len 00002000 (8 KiB): RTCRAM[0m
- [0;32mI (339) spi_flash: detected chip: generic[0m
- [0;32mI (343) spi_flash: flash io: dio[0m
- [0;33mW (347) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.[0m
- [0;32mI (361) cpu_start: Starting scheduler on PRO CPU.[0m
- I (396) wifi:wifi driver task: 3ffd5730, prio:23, stack:6656, core=0
- [0;32mI (396) system_api: Base MAC address is not set[0m
- [0;32mI (396) system_api: read default base MAC address from EFUSE[0m
- I (406) wifi:wifi firmware version: 6ce7887
- I (406) wifi:wifi certification version: v7.0
- I (406) wifi:config NVS flash: enabled
- I (406) wifi:config nano formating: disabled
- I (416) wifi:Init data frame dynamic rx buffer num: 32
- I (416) wifi:Init management frame dynamic rx buffer num: 32
- I (426) wifi:Init management short buffer num: 32
- I (426) wifi:Init dynamic tx buffer num: 32
- I (436) wifi:Init static rx buffer size: 1600
- I (436) wifi:Init static rx buffer num: 10
- I (436) wifi:Init dynamic rx buffer num: 32
- [0;32mI (446) wifi_init: rx ba win: 6[0m
- [0;32mI (446) wifi_init: tcpip mbox: 32[0m
- [0;32mI (456) wifi_init: udp mbox: 6[0m
- [0;32mI (456) wifi_init: tcp mbox: 6[0m
- [0;32mI (456) wifi_init: tcp tx win: 5744[0m
- [0;32mI (466) wifi_init: tcp rx win: 5744[0m
- [0;32mI (466) wifi_init: tcp mss: 1440[0m
- [0;32mI (476) wifi_init: WiFi IRAM OP enabled[0m
- [0;32mI (476) wifi_init: WiFi RX IRAM OP enabled[0m
- [0;32mI (496) main.c: start AP STA[0m
- [0;32mI (496) main.c: IP: 192.168.4.1[0m
- [0;32mI (496) main.c: GW: 192.168.4.1[0m
- [0;32mI (496) main.c: Mask: 255.255.255.0[0m
- [0;32mI (496) main.c: wifi_init_softap finished. SSID: test123 password: mypassword[0m
- [0;32mI (526) phy_init: phy_version 2300,d67cf06,Feb 10 2022,10:03:07[0m
- I (566) wifi:mode : sta (68:67:25:29:7e:04) + softAP (68:67:25:29:7e:05)
- I (566) wifi:enable tsf
- I (566) wifi:Total power save buffer number: 16
- I (566) wifi:Init max length of beacon: 752/752
- I (576) wifi:Init max length of beacon: 752/752
- [0;32mI (576) main.c: event_base = 87, event_id = 2[0m
- [0;32mI (576) main.c: event_base = 87, event_id = 12[0m
- [0;32mI (6416) main.c: event_base = 87, event_id = 5[0m
- [0;32mI (12256) main.c: event_base = 87, event_id = 5[0m
- [0;32mI (18096) main.c: event_base = 87, event_id = 5[0m
- [0;32mI (23936) main.c: event_base = 87, event_id = 5[0m
- I (27826) wifi:new:<1,0>, old:<1,1>, ap:<1,1>, sta:<0,0>, prof:1
- I (27826) wifi:scan in process, ignore set current channel
- I (27826) wifi:station: a0:10:81:c2:d9:36 join, AID=1, bgn, 20
- [0;32mI (27966) main.c: event_base = 87, event_id = 14[0m
- [0;32mI (28276) esp_netif_lwip: DHCP server assigned IP to a client, IP is: 192.168.4.2[0m
- W (28576) wifi:<ba-add>idx:2 (ifx:1, a0:10:81:c2:d9:36), tid:0, ssn:3, winSize:64
- W (29356) wifi:<ba-del>idx
- W (29366) wifi:<ba-add>idx:2 (ifx:1, a0:10:81:c2:d9:36), tid:0, ssn:9, winSize:64
- W (29746) wifi:<ba-del>idx
- W (29746) wifi:<ba-add>idx:2 (ifx:1, a0:10:81:c2:d9:36), tid:0, ssn:12, winSize:64
- [0;32mI (29776) main.c: event_base = 87, event_id = 5[0m
- I (32776) wifi:primary chan differ, old=1, new=4, start CSA timer
- I (33176) wifi:switch to channel 4
- I (33176) wifi:ap channel adjust o:1,1 n:4,1
- I (33176) wifi:new:<4,0>, old:<1,0>, ap:<4,1>, sta:<0,0>, prof:1
- I (33186) wifi:new:<4,1>, old:<4,0>, ap:<4,1>, sta:<4,0>, prof:1
- I (34866) wifi:state: init -> auth (b0)
- I (34876) wifi:state: auth -> assoc (0)
- I (34886) wifi:state: assoc -> run (10)
- I (34946) wifi:connected with externalSSID, aid = 1, channel 4, BW20, bssid = 46:41:73:c6:ba:83
- I (34946) wifi:security: WPA2-PSK, phy: bgn, rssi: -45
- I (34956) wifi:pm start, type: 1
- [0;32mI (34956) main.c: event_base = 87, event_id = 4[0m
- I (34956) wifi:AP's beacon interval = 102400 us, DTIM period = 2
- W (34976) wifi:<ba-add>idx:0 (ifx:0, 46:41:73:c6:ba:83), tid:0, ssn:0, winSize:64
- [0;32mI (35856) main.c: event_base = 73, event_id = 0[0m
- [0;32mI (35856) main.c: got ip:192.168.195.159[0m
- [0;32mI (35856) esp_netif_handlers: sta ip: 192.168.195.159, mask: 255.255.255.0, gw: 192.168.195.250[0m
- [0;32mI (55036) main.c: event_base = 87, event_id = 15[0m
- W (55036) wifi:<ba-del>idx
- I (55036) wifi:new:<4,0>, old:<4,1>, ap:<4,1>, sta:<4,0>, prof:1
- I (55036) wifi:Send SA Query req with transaction id 280a
- I (55246) wifi:Send SA Query req with transaction id 9752
- I (55456) wifi:Send SA Query req with transaction id 12af
- I (55656) wifi:Send SA Query req with transaction id 3110
- I (55866) wifi:Send SA Query req with transaction id bb33
- I (56066) wifi:STA not responded to 5 SA Query attempts, Reset connection sending disassoc
- I (56066) wifi:station: a0:10:81:c2:d9:36 leave, AID = 1, bss_flags is 658531, bss:0x3ffdd1a0
- I (56076) wifi:new:<4,0>, old:<4,0>, ap:<4,1>, sta:<4,0>, prof:1
- [0;32mI (56076) main.c: event_base = 87, event_id = 15[0m
- I (56556) wifi:new:<4,0>, old:<4,0>, ap:<4,1>, sta:<4,0>, prof:1
- I (56556) wifi:station: a0:10:81:c2:d9:36 join, AID=1, bgn, 20
- CORRUPT HEAP: Invalid data at 0x3ffdd4a0. Expected 0xfefefefe got 0x00000000
- assert failed: multi_heap_malloc multi_heap_poisoning.c:256 (ret)
- Backtrace: 0x40023912:0x3ffd51c0 0x4002a045:0x3ffd51e0 0x400309ad:0x3ffd5200 0x4002e96e:0x3ffd5320 0x40023a7d:0x3ffd5340 0x40023adb:0x3ffd5360 0x40026535:0x3ffd5380 0x400efd81:0x3ffd53a0 0x400330e5:0x3ffd53d0 0x400ac729:0x3ffd5400 0x400ac24d:0x3ffd5420 0x400a042a:0x3ffd5440 0x400a19d6:0x3ffd5480 0x400ab312:0x3ffd54a0 0x40098596:0x3ffd5510 0x40098cd1:0x3ffd5620 0x400973f3:0x3ffd5680 0x40033cf9:0x3ffd56a0 0x400320ac:0x3ffd56c0 0x4002c9c1:0x3ffd56f0
- ELF file SHA256: d73d438bf07a0c2a
- Rebooting...
The problem occurs if authmode of ESP32-AP is WIFI_AUTH_WPA2_PSK.
The problem doesn't occur if authmode of ESP32-AP is WIFI_AUTH_OPEN.
I tested with ESP32-S2-WROVER and ESP32-S3-WROOM-1-N8R8 and got similar results.
I tested with PSRAM enabled and disabled and got similar results.
The problem doesn't occur always.
The original application is much more complex but I reduced the code to the relevant functions. According to the documentation "Expected 0xfefefefe got 0x..." indicates the app has a use-after-free bug. As there is no dynamic allocation in the application code, I suppose there is a bug somewhere else in the IDE.