[BUG] Marlin Reboot on (First) SD Access

felixstorm commented 4 years ago

Description When accessing the SD card (i.e. refresh, create folder etc.) through the web UI for the first time after Marlin starts, Marlin's task watchdog triggers and causes a reboot.

To Reproduce

Power up (or hard reset) printer with SD card inserted
Open web UI (e.g. http://marlinesp.local/)
In the SD Files panel, click on "Refresh" or create a new folder
See Marlin rebooting (on the printer's LC display or on a serial terminal)

Marlin Firmware:

Marlin Branch/Version: bugfix-2.0.x
Changes: nothing special, primarily config and pins - see https://github.com/MarlinFirmware/Marlin/compare/899db41...felixstorm:559d065 (click on "Files changed" to get a better overview)

ESP3DLib :

ESP3DLib Branch/Version: devt (https://github.com/luc-github/ESP3DLib/commit/6cc1b250cfa31129c207860adf3ad07bb44c89f4)
Web UI Version: 2.1b56
Wifi mode: STA

Board used (please complete the following information):

BOARD: ESP32
Flash size: 4M?
partitions: default

Additional context After the reboot, the call e.g. to http://marlinesp.local/upload?path=/&PAGEID=0 seems to complete, but sometimes Marlin responds with SD init fail before then reporting SD card ok. Thereafter SD card access seems to be fine for the session - both from ESP3D (create folder) as well as from Marlin itself. But after the next reboot (power cycle or hard reset) any SD access will again trigger a reboot.
My guess would be that it has something to do with concurrent SD card access - if Marlin gets access first, then ESP3DLib will timeout (and the task wdt triggers a reboot), but if ESP3DLib gets access first, then Marlin seems to get access a bit later and both seem to be happy...

Decoded stack trace:

0x4008c9e0: invoke_abort at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp32/panic.c line 155
0x4008cc11: abort at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp32/panic.c line 170
0x40101f7c: task_wdt_isr at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp32/task_wdt.c line 174
0x4008a295: vTaskExitCritical at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/freertos/tasks.c line 4274
0x40088b65: xQueueGenericSend at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/freertos/queue.c line 828
0x400ff745: spiEndTransaction at ...\.platformio\packages\framework-arduinoespressif32\cores\esp32\esp32-hal-spi.c line 765
0x400edd56: SPIClass::endTransaction() at ...\.platformio\packages\framework-arduinoespressif32\libraries\SPI\src\SPI.cpp line 143
0x400d338f: spiRec() at Marlin\src\HAL\HAL_ESP32\HAL_SPI.cpp line 86
0x400eb139: Sd2Card::readData(unsigned char*, unsigned short) at Marlin\src\sd\Sd2Card.cpp line 431
0x400eb389: Sd2Card::readBlock(unsigned int, unsigned char*) at Marlin\src\sd\Sd2Card.cpp line 349
0x400ec4d1: SdVolume::cacheRawBlock(unsigned int, bool) at Marlin\src\sd\SdVolume.cpp line 138
0x400ec72e: SdVolume::freeClusterCount() at Marlin\src\sd\SdVolume.cpp line 284
0x400f55f4: ESP_SD::card_used_space() at ...\ESP3DLib\src\sd_ESP32.cpp line 312
0x400f71d1: Web_Server::handle_direct_SDFileList() at ...\ESP3DLib\src\web_server.cpp line 1378
0x4018c2b5: std::_Function_handler ::_M_invoke(std::_Any_data const&) at ...\.platformio\packages\toolchain-xtensa32\xtensa-esp32-elf\include\c++\5.2.0/functional line 1871
0x40173383: std::function ::operator()() const at ...\.platformio\packages\toolchain-xtensa32\xtensa-esp32-elf\include\c++\5.2.0/functional line 2271
0x40173429: FunctionRequestHandler::handle(WebServer&, HTTPMethod, String) at ...\.platformio\packages\framework-arduinoespressif32\libraries\WebServer\src\detail/RequestHandlersImpl.h line 81
0x40173496: WebServer::_handleRequest() at ...\.platformio\packages\framework-arduinoespressif32\libraries\WebServer\src\WebServer.cpp line 620
0x401735ff: WebServer::handleClient() at ...\.platformio\packages\framework-arduinoespressif32\libraries\WebServer\src\WebServer.cpp line 309
0x400f8a2d: Web_Server::handle() at ...\ESP3DLib\src\web_server.cpp line 1520
0x400f0318: WiFiServices::handle() at ...\ESP3DLib\src\wifiservices.cpp line 160
0x400efe22: WiFiConfig::handle() at ...\ESP3DLib\src\wificonfig.cpp line 434
0x400ee754: WiFiTaskfn(void*) at ...\ESP3DLib\src\esp3dlib.cpp line 42
0x40089129: vPortTaskWrapper at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/freertos/port.c line 143

If there is anything else that I can do to help you trace this down please let me know!

Thanks,
Felix

github-actions[bot] commented 4 years ago

Thank your for submiting, please be sure you followed template or your issue may be dismissed.

felixstorm commented 4 years ago

More info: I just now did have more reboots when uploading a file to the SD card (although refresh, create folder etc. had already worked without issues in the same session). After commenting out the part that checks the free space in Web_Server::SDFile_direct_upload (src/web_server.cpp lines 1438-1448) uploading did work fine, so it seems to be connected with ESP_SD::card_used_space.

The SD card is a standard 8GB card (it might even be the one that originally came with the Ender 3 printer) and it is empty (I formatted it just before testing this).

felixstorm commented 4 years ago

Just tried with two different SD cards (16GB & 32GB), but the reboot does happen as well when refreshing.

luc-github commented 4 years ago

Marlin SD lib is limited and the ESP_SD::card_used_space and ESP_SD::card_total_space code is not used in normal Marlin usage, I am thinking to try to move to ESP32 SD Lib or even better SDFat for this and a proper support of long name. That said I do not reproduce it I only have 2GB/4GB/16G and this will follow SD response time I think

@felixstorm How did you formated your SD ? Do you use https://www.sdcard.org/downloads/formatter/ ?

Just tried with two different SD cards (16GB & 32GB), but the reboot does happen as well when refreshing.

@felixstorm does this happen even you comment ESP_SD::card_used_space or if your return hardcoded value in these 2 functions : https://github.com/luc-github/ESP3DLib/blob/master/src/sd_ESP32.cpp#L305-L313

felixstorm commented 4 years ago

I did format the cards from Windows with a default cluster size, I had not tried a different formatter yet.

And I hadn't even thought of just returning a fixed value yet, but always returning 0 from ESP_SD::card_used_space() does indeed work very well for me - no issues anymore during any SD card operation (refresh, up- and download of a 10 MB file etc.).
Support for long file names seems like a very good idea (this would have been one of my first feature requests anyway :wink:), so if that's best accomplished by using a differnt SD/FAT library then returning "0 bytes used" in the meantime is a very feasible workaround for me. So IMHO this issue may very well be closed then - just do as you like.

A bit off topic, but maybe you know the answer anyway: SD card access seems to be a bit slow (I get around 100 kBit/s on downloads). Is that just how much it is in this setup or should I try to tweak my SPI speed a bit (100 kBit/s sound like only ~1MHz SPI speed)? If so, do you know by heart which settings I would have to change in the Marlin config to tune SPI speed?

Thanks, Felix

luc-github commented 4 years ago

Please do not use windows for SD card formating, better use link I gave

ok so I will disable theses functions until proper fix is implemented. need also to comment for upload to avoid not enough space failure

About SD card speed: Marlin SD lib is not really optimised for esp32, also webserver is not best currently to upload, I did not test download performance to be honest. Here some bench I did on ESP3D 3.0 and SD lib and FTP server instead of webserver https://github.com/luc-github/ESP3D/issues/383#issuecomment-548695909

about speed setting, all depend of sdcard reader and also SDCard itself

luc-github commented 4 years ago

I just bought a new 16GB / 32GB/ 64GB SD cards today - will try to do some tests during my vacations free time

felixstorm commented 4 years ago

@luc-github No real need to worry about this one anymore, I did some more debugging and filed a PR to properly fix it inside Marlin: https://github.com/MarlinFirmware/Marlin/pull/16690
My guess is that it largely depends on cluster size (the smaller the cluster size, the more FAT sectors/entries need to be read to calculate free cluster count) and on the speed of the SD card used. If the formatter you linked uses a larger clusters size than Windows, it may work ok but if all sums up to more than 5 seconds, the watchdog will trigger.

About SD card speed: I did an upload test now (around 30 kBit/s) and looking at the other issue you had linked this seems to be pretty much ok for the setup.

luc-github commented 4 years ago

thank you - I like such kind of issue ^_^

stale[bot] commented 4 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

stale[bot] commented 4 years ago

This stale issue has been automatically closed. Thank you for your contributions.

luc-github / ESP3DLib

[BUG] Marlin Reboot on (First) SD Access #7