CORRUPT HEAP after reconnect

[marclee]

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:

Code: Untitled.c Select all

#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:

Code: Untitled.txt Select all

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.

[Sprite]

Fyi, you may have a quicker answer if you file this as a Github issue.

[marclee]

Fyi, you may have a quicker answer if you file this as a Github issue.

Thank you for the hint. I have just posted the issue at github: https://github.com/espressif/esp-idf/issues/9973

[marclee]

Can anybody confirm that bug?

[mbratch]

Have you run the backtrace decoder (`xtensa-esp32-elf-addr2line.exe`) on the backtrace to see what functions are involved in the corruption? That might help provide some clues.

[marclee]

Is there any documentation about "backtrace decoder"? We use Linux.

[mbratch]

Is there any documentation about "backtrace decoder"? We use Linux.

Just search for `xtensa-esp32-elf-addr2line`. The documentation doesn't say that it's specific to Windows, but I don't think it is automatically added to your PATH. Check under the tools in your ESP-IDF installation.

[marclee]

Just search for `xtensa-esp32-elf-addr2line`. The documentation doesn't say that it's specific to Windows, but I don't think it is automatically added to your PATH. Check under the tools in your ESP-IDF installation.

Now I understand what you mean. Address decoding has always been activated and usually it works. But in this case it does not seem to work.

[mbratch]

Now I understand what you mean. Address decoding has always been activated and usually it works. But in this case it does not seem to work.

The manual execution of the command doesn't work either? I've seen many cases where the console doesn't decode but the command will. If you haven't tried manually executing the decode, give it a try!

[marclee]

The manual execution of the command doesn't work either? I've seen many cases where the console doesn't decode but the command will. If you haven't tried manually executing the decode, give it a try!

I got the back trace, not from the same application, but it's the same error.

Code: Untitled.txt Select all

I (102239) wifi:Send SA Query req with transaction id ef6f

I (102449) wifi:Send SA Query req with transaction id 8ac9

I (102649) wifi:Send SA Query req with transaction id 487a

I (102859) wifi:Send SA Query req with transaction id 541e

I (103059) wifi:Send SA Query req with transaction id 7e04

I (103269) wifi:STA not responded to 5 SA Query attempts, Reset connection sending disassoc

I (103269) wifi:station: 11:22:33:44:55:66 leave, AID = 1, bss_flags is 134259, bss:0x3f81c638

I (103279) wifi:new:<4,0>, old:<4,1>, ap:<4,1>, sta:<4,0>, prof:2



CORRUPT HEAP: Invalid data at 0x3f81c938. Expected 0xfefefefe got 0x00000000



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



Backtrace: 0x40025e1a:0x3ffe94f0 0x4002ff0d:0x3ffe9510 0x4003773d:0x3ffe9530 0x400356fe:0x3ffe9650 0x40025f85:0x3ffe9670 0x4002603b:0x3ffe9690 0x4003774d:0x3ffe96b0 0x400bc4a4:0x3ffe96d0 0x400bd624:0x3ffe96f0 0x400c2ef5:0x3ffe9720 0x400c34ca:0x3ffe9740 0x400ce3da:0x3ffe97b0 0x400cf0fc:0x3ffe97d0 0x400bc1c1:0x3ffe97f0 0x400bc264:0x3ffe9810 0x400328bd:0x3ffe9840

0x40025e1a: panic_abort at /home/xxxx/esp/esp-idf_v5.0-beta1-742-g7bd5af7f1e/components/esp_system/panic.c:412



0x4002ff0d: esp_system_abort at /home/xxxx/esp/esp-idf_v5.0-beta1-742-g7bd5af7f1e/components/esp_system/esp_system.c:135

0x4003773d: __assert_func at /home/xxxx/esp/esp-idf_v5.0-beta1-742-g7bd5af7f1e/components/newlib/assert.c:78

0x400356fe: multi_heap_malloc at /home/xxxx/esp/esp-idf_v5.0-beta1-742-g7bd5af7f1e/components/heap/multi_heap_poisoning.c:256 (discriminator 1)

0x40025f85: heap_caps_malloc_base at /home/xxxx/esp/esp-idf_v5.0-beta1-742-g7bd5af7f1e/components/heap/heap_caps.c:146

0x4002603b: heap_caps_malloc_default at /home/xxxx/esp/esp-idf_v5.0-beta1-742-g7bd5af7f1e/components/heap/heap_caps.c:201

0x4003774d: malloc at /home/xxxx/esp/esp-idf_v5.0-beta1-742-g7bd5af7f1e/components/newlib/heap.c:24

0x400bc4a4: mem_malloc at /home/xxxx/esp/esp-idf_v5.0-beta1-742-g7bd5af7f1e/components/lwip/lwip/src/core/mem.c:209

0x400bd624: pbuf_alloc at /home/xxxx/esp/esp-idf_v5.0-beta1-742-g7bd5af7f1e/components/lwip/lwip/src/core/pbuf.c:284

0x400c2ef5: tcp_pbuf_prealloc at /home/xxxx/esp/esp-idf_v5.0-beta1-742-g7bd5af7f1e/components/lwip/lwip/src/core/tcp_out.c:263 (discriminator 2)

0x400c34ca: tcp_write at /home/xxxx/esp/esp-idf_v5.0-beta1-742-g7bd5af7f1e/components/lwip/lwip/src/core/tcp_out.c:610

0x400ce3da: lwip_netconn_do_writemore at /home/xxxx/esp/esp-idf_v5.0-beta1-742-g7bd5af7f1e/components/lwip/lwip/src/api/api_msg.c:1774

0x400cf0fc: lwip_netconn_do_write at /home/xxxx/esp/esp-idf_v5.0-beta1-742-g7bd5af7f1e/components/lwip/lwip/src/api/api_msg.c:1901 (discriminator 2)

0x400bc1c1: tcpip_thread_handle_msg at /home/xxxx/esp/esp-idf_v5.0-beta1-742-g7bd5af7f1e/components/lwip/lwip/src/api/tcpip.c:162

0x400bc264: tcpip_thread at /home/xxxx/esp/esp-idf_v5.0-beta1-742-g7bd5af7f1e/components/lwip/lwip/src/api/tcpip.c:148

0x400328bd: vPortTaskWrapper at /home/xxxx/esp/esp-idf_v5.0-beta1-742-g7bd5af7f1e/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:151



ELF file SHA256: 7e73a0577994eb81



Rebooting...