ESP32S3 SPI transactions assert failed: block_next tlsf_block_functions.h:94 (!block_is_last(block)) (IDFGH-13618)

[lekshith]

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.

5.1v

Espressif SoC revision.

ESP-IDF v5.1.4, chip revision: v0.1

Operating System used.

Windows

How did you build your project?

VS Code IDE

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

None

Development Kit.

ESP32S3

Power Supply used.

USB

What is the expected behavior?

This project Incorporates Ethernet SPI for hosting local web page and SD card for data logging in sdspi mode. Moreover, I have enabled SPIRAM and use it for other dynamic memory allocation. I have 4 RTOS tasks running in the background, 2 for UART operations while other task is the data logging (write to SD) and host a web page for configuration and control. The functionality works well most of the time. Expect it crashes at random times during the logging function dude to shared bus config. The bus is configured to the same host (SPI2_HOST) dude to limited GPIOs.
Initially, the program crashed with looping log meesages as follows:

E (17:36:06.791) w5500.mac: emac_w5500_read_phy_reg(387): read PHY register failed
E (17:36:06.792) w5500.phy: w5500_update_link_duplex_speed(65): read PHYCFG failed
E (17:36:06.795) w5500.phy: w5500_get_link(108): update link duplex speed failed
E (17:36:08.791) w5500.mac: emac_w5500_read_phy_reg(387): read PHY register failed
E (17:36:08.791) w5500.phy: w5500_update_link_duplex_speed(65): read PHYCFG failed
E (17:36:08.795) w5500.phy: w5500_get_link(108): update link duplex speed failed

To which I seeked the solution from #6624 and #8179, which stopped this looping errors.

What is the actual behavior?

However the patch for the spi_master.c works well for about 45 mins and then started failing with the error as follows:
E (5516841) w5500.mac: emac_w5500_read_phy_reg(335): read PHY register failed
E (5516841) w5500.phy: w5500_update_link_duplex_speed(69): read PHYCFG failed
E (5516841) w5500.phy: w5500_get_link(112): update link duplex speed failed
E (5516901) w5500.mac: w5500_get_rx_received_size(152): read RX RSR failed
E (5518051) w5500.mac: w5500_get_rx_received_size(152): read RX RSR failed

To which I tried a quick fix suggested in #11295 to replace the spi_device_transmit with spi_device_polling_transmit. Which has stopped all the looping error. However the system is now crashing after about hour or so runtime with assert failed: block_next tlsf_block_functions.h:94 (!block_is_last(block)).

Steps to reproduce.

Here is the complete Ethernet Initialisation
void init_ethernet(void)
{
// Initialize the SPI mutex
init_spi_mutex();
esp_netif_config_t netif_cfg_DHCP_client = ESP_NETIF_DEFAULT_ETH();
esp_netif_t *eth_netif = esp_netif_new(&netif_cfg_DHCP_client);

spi_bus_config_t buscfg = {
    .miso_io_num = SPI_MISO_GPIO,
    .mosi_io_num = SPI_MOSI_GPIO,
    .sclk_io_num = SPI_SCLK_GPIO,
    .quadwp_io_num = -1,
    .quadhd_io_num = -1,
};
ESP_ERROR_CHECK(spi_bus_initialize(ETH_SPI_HOST, &buscfg, SPI_DMA_CH_AUTO));
/* w5500 ethernet driver is based on spi driver */
spi_device_interface_config_t spi_devcfg = {
    .mode = 0,
    .clock_speed_hz = ETH_SPI_CLOCK_MHZ * 1000 * 1000,
    .spics_io_num = ETH_SPI_CS_GPIO,
    .queue_size = 20,
    .cs_ena_posttrans = 2,
};

eth_w5500_config_t w5500_config = ETH_W5500_DEFAULT_CONFIG(ETH_SPI_HOST, &spi_devcfg);
w5500_config.int_gpio_num = ETH_SPI_INT_GPIO; // Set GPIO number for ethernet interrupt
eth_mac_config_t mac_config = ETH_MAC_DEFAULT_CONFIG();
mac_config.rx_task_stack_size = KILOBYTE * 16; // Set task size
esp_eth_mac_t *mac = esp_eth_mac_new_w5500(&w5500_config, &mac_config);

eth_phy_config_t phy_config = ETH_PHY_DEFAULT_CONFIG();
phy_config.reset_gpio_num = -1;
esp_eth_phy_t *phy = esp_eth_phy_new_w5500(&phy_config);

esp_eth_config_t eth_config = ETH_DEFAULT_CONFIG(mac, phy);
esp_err_t err = esp_eth_driver_install(&eth_config, &eth_handle);
if (err != ESP_OK)
{
    ESP_LOGE(TAG, "Failed to install ethernet w5500 driver %u", err);
}
else
{
    uint8_t mac_addr[6];
    esp_read_mac(mac_addr, ESP_MAC_ETH);
    mac->set_addr(mac, mac_addr); /* Set mac address */
    ESP_LOGI(TAG, "--->> Set mac" MACSTR, MAC2STR(mac_addr));

    /* Attach Ethernet driver to TCP/IP stack */
    ESP_ERROR_CHECK(esp_netif_attach(eth_netif, esp_eth_new_netif_glue(eth_handle)));
    /* Register user defined event handers */
    ESP_ERROR_CHECK(esp_event_handler_register(ETH_EVENT, ESP_EVENT_ANY_ID, &eth_event_handler, NULL));
    ESP_ERROR_CHECK(esp_event_handler_register(IP_EVENT, IP_EVENT_ETH_GOT_IP, &got_ip_event_handler, NULL));

    /* Start Ethernet driver state machine */
    ESP_ERROR_CHECK(esp_eth_start(eth_handle));
}

}
Clock speed is set to 20Mhz, while same shared bus config initialises the sd card as follows:
esp_err_t sd_init(void) {
esp_err_t ret;
// Options for mounting the filesystem.
esp_vfs_fat_sdmmc_mount_config_t mount_config = {
.format_if_mount_failed = true,
.max_files = 5,
.allocation_unit_size = 32 * KILOBYTE
};

ESP_LOGI(TAG, "Initializing SD card");

// Initialize the SD card host
sdmmc_host_t host = SDSPI_HOST_DEFAULT();
host.slot = ETH_SPI_HOST;

// Set the GPIO level for the SD card CS pin
gpio_set_level(ETH_SPI_CS_GPIO, 1);

// Initialize the slot configuration for the SD card
sdspi_device_config_t slot_config = SDSPI_DEVICE_CONFIG_DEFAULT();
slot_config.gpio_cs = PIN_NUM_CS_SD;
slot_config.host_id = host.slot;

ESP_LOGI(TAG, "Mounting filesystem");

// Mount the filesystem using the specified host, slot, and mount configuration
ret = esp_vfs_fat_sdspi_mount(SD_MOUNT_POINT, &host, &slot_config, &mount_config, &card);

if (ret != ESP_OK) {
    if (ret == ESP_FAIL) {
        ESP_LOGE(TAG, "Failed to mount filesystem.");
    } else {
        ESP_LOGE(TAG, "Failed to initialize the card (%s).", esp_err_to_name(ret));
    }
    return ret;
}

// Store the SPI device handle
//spi_handle = slot_config.spi_handle;

ESP_LOGI(TAG, "Filesystem mounted");

// Card has been initialized, print its properties
sdmmc_card_print_info(stdout, card);

return ESP_OK;

}

Debug Logs.

Here is the crash logs after 50 mins of runtime with expected behaviour,
I (3285847) DATALOGGER: Logged data for fan 2

assert failed: block_next tlsf_block_functions.h:94 (!block_is_last(block))


Backtrace: 0x40375fae:0x3fccdff0 0x4037daa1:0x3fcce010 0x40386f61:0x3fcce030 0x403835c0:0x3fcce150 0x40383448:0x3fcce170 0x40376a6e:0x3fcce190 0x40386f91:0x3fcce1b0 0x40378982:0x3fcce1d0 0x40378f0c:0x3fcce1f0 0x40378f59:0x3fcce210 0x4202cc95:0x3fcce230 0x4202d00f:0x3fcce280 0x4202d5cd:0x3fcce360 0x4202d922:0x3fcce390 0x42068553:0x3fcce3d0 0x42017d17:0x3fcce3f0 0x42017ef4:0x3fcce470 0x42016477:0x3fcce4a0 0x420162f6:0x3fcce4c0 0x420129ee:0x3fcce4e0 0x42013445:0x3fcce500 0x420149cb:0x3fcce520 0x420149f1:0x3fcce550 0x42016a1c:0x3fcce580 0x42009231:0x3fcce5a0 0x4205a68a:0x3fcce5c0 0x420115be:0x3fcce5e0 0x42010e50:0x3fcce600 0x4200d908:0x3fcce620 0x4200dfed:0x3fcce6b0 0x403805e9:0x3fcce700
0x40375fae: panic_abort at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/esp_system/panic.c:466
0x4037daa1: esp_system_abort at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/esp_system/port/esp_system_chip.c:84
0x40386f61: __assert_func at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/newlib/assert.c:81
0x403835c0: block_next at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/heap/tlsf/tlsf_block_functions.h:94
 (inlined by) block_link_next at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/heap/tlsf/tlsf_block_functions.h:101
 (inlined by) block_mark_as_free at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/heap/tlsf/tlsf_block_functions.h:109
 (inlined by) tlsf_free at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/heap/tlsf/tlsf.c:1121
0x40383448: multi_heap_free_impl at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/heap/multi_heap.c:231
0x40376a6e: heap_caps_free at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/heap/heap_caps.c:388
0x40386f91: free at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/newlib/heap.c:39
0x40378982: uninstall_priv_desc at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/driver/spi/gpspi/spi_master.c:845
0x40378f0c: spi_device_polling_end at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/driver/spi/gpspi/spi_master.c:1107 (discriminator 15)
0x40378f59: spi_device_polling_transmit at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/driver/spi/gpspi/spi_master.c:1127
0x4202cc95: poll_busy at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/driver/spi/sdspi/sdspi_host.c:576
0x4202d00f: start_command_write_blocks at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/driver/spi/sdspi/sdspi_host.c:927
0x4202d5cd: sdspi_host_start_command at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/driver/spi/sdspi/sdspi_host.c:480
0x4202d922: sdspi_host_do_transaction at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/driver/spi/sdspi/sdspi_transaction.c:150
0x42068553: sdmmc_send_cmd at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/sdmmc/sdmmc_cmd.c:24
0x42017d17: sdmmc_write_sectors_dma at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/sdmmc/sdmmc_cmd.c:448
0x42017ef4: sdmmc_write_sectors at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/sdmmc/sdmmc_cmd.c:412
0x42016477: ff_sdmmc_write at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/fatfs/diskio/diskio_sdmmc.c:66
0x420162f6: ff_disk_write at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/fatfs/diskio/diskio.c:98
0x420129ee: sync_window at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/fatfs/src/ff.c:1065
0x42013445: sync_fs at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/fatfs/src/ff.c:1117
0x420149cb: f_sync at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/fatfs/src/ff.c:4199
0x420149f1: f_close at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/fatfs/src/ff.c:4226
0x42016a1c: vfs_fat_close at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/fatfs/vfs/vfs_fat.c:549
0x42009231: esp_vfs_close at C:/Users/lchandrashekar/esp/v5.1/esp-idf/components/vfs/vfs.c:512 (discriminator 3)
0x4205a68a: close at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s3-elf/src/newlib/newlib/libc/syscalls/sysclose.c:9
0x420115be: gzclose_w at C:/CompiledProject/SD-V2/main/zlib/gzwrite.c:661
0x42010e50: gzclose at C:/CompiledProject/SD-V2/main/zlib/gzclose.c:21 (discriminator 2)
0x4200d908: log_to_sd_card at C:/CompiledProject/SD-V2/main/sd_card/sd_card.c:788

More Information.

Clock speed is 20Mhz, there is 2 CS pin available, one for ETH and another for SD, logging speed (write to SD) is less than 200ms.
Any suggestions or workarounds are welcome. Thank you.