ESP-IDF SPIFFS fails to save files even with alot more bytes left (IDFGH-6974)

[Sjurinho]

Environment

Development Kit: ESP32-DevKitC
Kit version: v1
Module or chip used: ESP32-WROOM-32
IDF version (run git describe --tags to find it): v4.2.2
Build System: idf.py
Compiler version (run xtensa-esp32-elf-gcc --version to find it): 8.4.0
Operating System: Linux
Using an IDE?: VSCode with the ESP-IDF extension
Power Supply: External 5v

Problem Description

I am running a logger on my esp32 microcontroller. The logs are circular and thus consists of 6 files of size 16384 bytes which are deleted as the spiffs fill up. Additionally I have a small file (approx. 1000 bytes) of config values. After a while I saw that the spiffs wasn't able to save new logs, and turning on the debug logs showed that the gc in the spiffs couldn't erase certain memory addresses. This is shown in the attached logs (spiffs_erros.txt). I have tried to search around on the forums, but I have not been able to find the cause of this problem. It does not appear to be the spiffs running out of memory, as the esp_spiffs_info() api shows that only 38905 bytes are used out of 233681. My spiffs partition (see below) is set to be 256k bytes. I think the problem has something to do with the free blocks being equal to 0, but not sure why or how to fix it. To generate the spiffs I use the standard CMake api spiffs_create_partition_image(spiffs spiffs_image FLASH_IN_PROJECT), as shown in storage/examples. Correct me if I'm wrong, but I think this gives a page size of 256 bytes (as in the sdkconfig) and a 4 KiB erase block size.
Is anyone familiar with the issue and how to resolve/work around it?

Expected Behavior

Spiffs continue to work as long as there are bytes left (according to esp_spiffs_info), and the circular logs work.

Actual Behavior

Spiffs run out of blocks(?) and therefore stops being able to save new logs.

Steps to reproduce

1. Mount Spiffs
2. Write logs (approximately 95bytes per entry)
3. Wait for spiffs to fail at erasing blocks

Partition Table

# Name, Type, SubType, Offset, Size, Flags
nvs, data, nvs, 0x9000, 20k,
otadata, data, ota, , 8k,
factory, app, factory, , 1215k,
ota_0, app, ota_0, , 1215k,
ota_1, app, ota_1, , 1215k,
spiffs, data, spiffs, , 256k,
coredump, data, coredump, 0x3F0000, 64k

Initialization of spiffs

I initialize my spiffs accordingly

if (!esp_spiffs_mounted(NULL)) {
        esp_vfs_spiffs_conf_t conf = {
            // Data partition name ("spiffs", "/spiffs") in file: custom_partitions_spiffs.csv
            .base_path = kBasePath.substr(0, kBasePath.length() - 1).c_str(),
            .partition_label = NULL,
            .max_files = 5,
            .format_if_mount_failed = false,
        };

        ESP_LOGI(TAG, ">> esp_vfs_spiffs_register(conf)");
        esp_err_t err_resp = esp_vfs_spiffs_register(&conf);

LogFiles

• The file spiffs_error.txt shows the debug logs of the spiffs write failure.
• The file spiffs_format_errors.txt shows the debug logs and errors when trying to format the spiffs partition.
  spiffs_error.txt
  spiffs_format_errors.txt

[Sjurinho]

I state more clearly that a format of the mounted spiffs did NOT fix the problem, as I have seen other forums mention as a solution. The logs of that is attached in spiffs_format_errors.txt

[igrr]

Thanks for the detailed issue description @Sjurinho!

It seems that first it would be nice to solve the issue with failed erase operations. I'm not sure if SPIFFS will continue working correctly after some erase operations fail.

If you run the spiffs example provided in ESP-IDF, do you get similar errors about failed erase operations? If not, do you think you could reduce your application to some bare minimum amount of code which still reproduces these erase errors?

Another question, could you please upload the sdkconfig file from your project and your partition table CSV file?

[Sjurinho]

Thanks for the quick reply @igrr.
I have tried the spiffs example as you suggested, and when I don't alter the size of the spiffs partition it works just fine. However, to replicate my situation I altered the partitions_table.csv to match the one I described in the problem description above, it started to report that it was unable to delete some addresses in the spiffs. After reaching approximately 10k bytes into Log1.txt (meaning after ~16384 bytes + 10k bytes) it gets the first erase failure.
E (79640) SPIFFS: failed to erase addr 00003000, size 00001000, err 258
Then, after a few thousand more bytes it is unable to open the file Log1.txt for appending, and it does not manage to remove it either.

I have attached a zip with a simple application that reproduces the error.
spiffs.zip

Error logs

E (80860) SPIFFS: failed to erase addr 00006000, size 00001000, err 258
D (80870) example: Json stored! 10317
D (81070) example: Json stored! 10384
D (81270) example: Json stored! 10451
D (81470) example: Json stored! 10518
D (81670) example: Json stored! 10585
E (81890) SPIFFS: failed to erase addr 0000b000, size 00001000, err 258
D (81900) example: Json stored! 10652
D (82100) example: Json stored! 10719
D (82300) example: Json stored! 10786
D (82500) example: Json stored! 10853
D (82700) example: Json stored! 10920
D (82900) example: Json stored! 10987
E (83120) SPIFFS: failed to erase addr 0000f000, size 00001000, err 258
D (83130) example: Json stored! 11054
D (83330) example: Json stored! 11121
D (83530) example: Json stored! 11188
D (83730) example: Json stored! 11255
D (83930) example: Json stored! 11322
D (84140) example: Json stored! 11389
W (84350) SPIFFS: Failed to update mtime (-10002)
D (84360) example: Json stored! 11389
W (84570) SPIFFS: Failed to update mtime (-10002)
D (84580) example: Json stored! 11389
W (84790) SPIFFS: Failed to update mtime (-10002)
D (84800) example: Json stored! 11389
W (85010) SPIFFS: Failed to update mtime (-10002)
D (85020) example: Json stored! 11389
E (85220) example: Failed to open file 'Log1.txt' for appending
E (85220) example: Failed to delete file '/spiffs/Log1.txt': I/O error - 5
E (85220) example: Storage failure! Failed to delete file

[igrr]

I'm sorry, clicking the above spiffs.zip link gives me "Not found" error, could you please try again?

[Sjurinho]

Ah, yes, hopefully it works now :)
spiffs.zip

[igrr]

The issue is that the spiffs partition in your partition table is not aligned to 4kB boundary. Currently it is at 0x39fc00.
Since the flash erase size is 4kB, any data partition which has to support erase operations needs to be aligned to 4kB.
We have recently added a warning about this in commit b56c9aa (part of v4.4 release), and starting from v5.0 unaligned data partitions won't be supported.
Please adjust your partition table to make all partitions aligned to 4kB, e.g. by changing the sizes of factory/ota partitions to 1216kB. Then all the partitions will be aligned:

nvs,data,nvs,0x9000,20K,
otadata,data,ota,0xe000,8K,
factory,app,factory,0x10000,1216K,
ota_0,app,ota_0,0x140000,1216K,
ota_1,app,ota_1,0x270000,1216K,
spiffs,data,spiffs,0x3a0000,256K,
coredump,data,coredump,0x3f0000,64K,

You can check the result by running idf.py partition_table command.

[Sjurinho]

@igrr, Indeed, changing the app partitions seems to have fixed my problem. That makes sense. Thank you very much for your help, you are a lifesaver! :)

That being said, I do miss some warning in the docs about this though.

[igrr]

Thanks for confirming the fix!

Indeed this is an easy mistake to make, and it's a simple thing to add a check/warning for.

We'll backport the commit I have linked to release/v4.3 and release/v4.4 and close this issue afterwards.