TinyUSB MSC FAT format fails, flooding log with errors (IDFGH-13691)

olicooper commented 1 month 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.3.0

Espressif SoC revision.

ESP32-S3

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.

Waveshare ESP32 S3 Nano

Power Supply used.

USB

What is the expected behavior?

The format/mount procedure should write the sector information in 512 chunks rather than failing or the procedure should fail gracefully.

What is the actual behavior?

Application fails here: https://github.com/espressif/esp-usb/blob/d32baca40a25966f274d190a71f508d33b799a71/device/esp_tinyusb/tusb_msc_storage.c#L199

With the following logs repeated until the device is rebooted:

...
E (25811) tinyusb_msc_storage: msc_storage_write_sector failed: 0x102
E (25821) tinyusb_msc_storage: Invalid Argument lba(0) offset(0) size(512) sector_size(4096)
...

Steps to reproduce.

Using the MSC demo with SPI flash: https://github.com/espressif/esp-idf/tree/master/examples/peripherals/usb/device/tusb_msc

const tinyusb_msc_spiflash_config_t config_spi = {
    .wl_handle = wl_handle,
    .mount_config = {
        .format_if_mount_failed = true,
        .max_files = 5,
        .allocation_unit_size = 0, //CONFIG_WL_SECTOR_SIZE,
        .disk_status_check_enable = false,
        .use_one_fat = false,
    },
};

With partition table (16MB flash in QIO mode @ 80Mhz):

# Name,   Type, SubType,    Offset, Size,   Flags
nvs,      data, nvs,        0x9000, 0x6000,
otadata,  data, ota,        0xF000, 0x2000,
phy_init, data, phy,       0x11000, 0x1000,
app0,      app, ota_0,     0x20000, 2M,
app1,      app, ota_1,            , 2M,
storage,  data, fat,              , 10M,

sdkconfig (using default values):

CONFIG_FATFS_SECTOR_4096=y
CONFIG_WL_SECTOR_SIZE=4096
CONFIG_TINYUSB_MSC_BUFSIZE=512

Debug Logs.

I (353) esp_psram: Found 8MB PSRAM device
I (357) esp_psram: Speed: 80MHz
I (361) cpu_start: Multicore app
I (817) esp_psram: SPI SRAM memory test OK
I (826) cpu_start: Pro cpu start user code
I (826) cpu_start: cpu freq: 240000000 Hz
I (826) app_init: Application information:
I (829) app_init: Project name:     TESTMSC
I (834) app_init: App version:      1
I (839) app_init: Compile time:     Sep 12 2024 20:00:00
I (845) app_init: ELF file SHA256:  xxxxxxxxx...
I (850) app_init: ESP-IDF:          5.3.0
I (855) efuse_init: Min chip rev:     v0.0
I (859) efuse_init: Max chip rev:     v0.99 
I (864) efuse_init: Chip rev:         v0.2
I (869) heap_init: Initializing. RAM available for dynamic allocation:
I (876) heap_init: At 3FC97BA0 len 00051B70 (326 KiB): RAM
I (883) heap_init: At 3FCE9710 len 00005724 (21 KiB): RAM
I (889) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (895) heap_init: At 600FE100 len 00001EE8 (7 KiB): RTCRAM
I (901) esp_psram: Adding pool of 8192K of PSRAM memory to heap allocator
I (909) spi_flash: detected chip: winbond
I (913) spi_flash: flash io: qio
I (917) sleep: Configure to isolate all GPIO pins in sleep state
I (924) sleep: Enable automatic switching of GPIO sleep configuration
I (931) main_task: Started on CPU0
I (951) esp_psram: Reserving pool of 32K of internal memory for DMA/internal allocations
I (951) main_task: Calling app_main()
I (951) main: Initializing wear levelling
I (3041) main: Mount storage...
W (3041) tinyusb_msc_storage: f_mount failed (13)
W (3041) tinyusb_msc_storage: formatting card, allocation unit size=4096
I (3811) main: Storage mounted to application: Yes
I (3811) main:
ls command output:
I (3821) main: USB MSC initialization
I (3821) tusb_desc:
┌─────────────────────────────────┐
│  USB Device Descriptor Summary  │
├───────────────────┬─────────────┤
│bDeviceClass       │ 8           │
├───────────────────┼─────────────┤
│bDeviceSubClass    │ 2           │
├───────────────────┼─────────────┤
│bDeviceProtocol    │ 1           │
├───────────────────┼─────────────┤
│bMaxPacketSize0    │ 64          │
├───────────────────┼─────────────┤
│idVendor           │ 0x303a      │
├───────────────────┼─────────────┤
│idProduct          │ 0x4002      │
├───────────────────┼─────────────┤
│bcdDevice          │ 0x100       │
├───────────────────┼─────────────┤
│iManufacturer      │ 0x1         │
├───────────────────┼─────────────┤
│iProduct           │ 0x2         │
├───────────────────┼─────────────┤
│iSerialNumber      │ 0x3         │
├───────────────────┼─────────────┤
│bNumConfigurations │ 0x1         │
└───────────────────┴─────────────┘
I (3991) TinyUSB: TinyUSB Driver installed
I (3991) main: USB MSC initialization DONE
I (3991) main_task: Returned from app_main()
I (4341) main: Storage mounted to application: No
E (4611) tinyusb_msc_storage: Invalid Argument lba(65) offset(0) size(512) sector_size(4096)
E (4611) tinyusb_msc_storage: msc_storage_write_sector failed: 0x102
E (4611) tinyusb_msc_storage: Invalid Argument lba(65) offset(0) size(512) sector_size(4096)
E (4621) tinyusb_msc_storage: msc_storage_write_sector failed: 0x102
E (4631) tinyusb_msc_storage: Invalid Argument lba(65) offset(0) size(512) sector_size(4096)
E (4641) tinyusb_msc_storage: msc_storage_write_sector failed: 0x102
...

More Information.

This bug can be fixed by setting CONFIG_TINYUSB_MSC_BUFSIZE=4096 (because size % sector_size == 0).. but if the user formats the storage device using a larger sector size then it will still fail and I have no control over users formatting the drive.

It seems that the default sdkconfig is not compatible with the MSC demo and it is not clear how to fix the problem (I can't find any documentation about this restriction).

Even if this is expected behaviour, I am not sure why this doesn't fail gracefully? Instead it floods the log with the error seen above.

olicooper commented 1 month ago

The wear levelling docs state that the default WL sector size is 512 but also says that it is 4096 when used with FATFS?

The wear levelling component, together with the FAT FS component, uses FAT FS sectors of 4096 bytes, which is a standard size for flash memory

My project made CONFIG_FATFS_SECTOR_4096=y and CONFIG_WL_SECTOR_SIZE_4096=y by default which conflicts with what I see in the demo: https://github.com/espressif/esp-idf/blob/59e18382702b6986be3d3f55e9ac7763c1397cf7/examples/peripherals/usb/device/tusb_msc/sdkconfig.defaults#L10

roma-jam commented 1 month ago

Hi @olicooper,

Thanks for the information. I can see that the fs was mounted with error (based on the attached log). The USB MSC class provides only a transport layer here to read and write data from the storage. So, if the storage wasn't mounted then any read/write operation will end up with an error.

Have you tried to run the wear-leveling example itself? Does it have the same problem on desired settings?

olicooper commented 1 month ago

I haven't run the wear-levelling example but I can test that too. The code that causes the reboot loop is the MSC code, but maybe the partition is being corrupted by FATFS or wear-levelling, I'm not sure.

The mount fails because it fails to format the partition (I assume after writing the first 512 bytes), then panics and reboots. If I erase the whole flash and try the demo again it does not fail to mount (because there is nothing to mount) but I assume the format process corrupts the partition table after the first attempt.

StefanJo3107 commented 1 month ago

Currently experiencing same issue, ran the tinyusb msc example on the esp32 s3 devkit and got flooded with same errors. Any new info on the issue, or way to resolve it?

tore-espressif commented 5 days ago

Hello everyone, I'm sorry for the delay, we will try to investigate by end of November

espressif / esp-idf