diff --git a/README.md b/README.md index 3e8878a..e395a03 100644 --- a/README.md +++ b/README.md @@ -85,7 +85,7 @@ The LoRa Scanner (docs/milestones/M3.md) listens with the Cap's radio and **neve | `irc say ` | Types into a Buffer, commands included (`irc say 0 /join #test`) | | `irc dump` | Prints IRC status, memory, and the last lines of each Buffer | | `wifi status` | Prints Wi-Fi state, network, signal, clock and free heap | -| `info` | Firmware, uptime, last start reason, memory, Wi-Fi, and both app slots with their versions and OTA states | +| `info` | Firmware, uptime, last start reason, memory, Wi-Fi, the SD card and its write faults since boot, and both app slots with their versions and OTA states | | `tasks` | FreeRTOS tasks: state, priority, lowest free stack, CPU share | | `reboot` / `boot other` | Restart, or restart into the other app slot (a manual Rollback) | | `log level <0-5>` | ESP-IDF log level | diff --git a/docs/adr/0007-own-copy-of-the-sd-driver.md b/docs/adr/0007-own-copy-of-the-sd-driver.md new file mode 100644 index 0000000..1b1e552 --- /dev/null +++ b/docs/adr/0007-own-copy-of-the-sd-driver.md @@ -0,0 +1,20 @@ +# Our own copy of the SD driver, for one missing byte + +Arduino-ESP32's `SD` library talks to the card over SPI through `sd_diskio.cpp`. That driver gives up on a write without saying why, and about once in 2,000 multi-block writes it gave up on one that had worked (issue #21). A 1.7 MB upload failed about three times in ten; before M3, the retry on top of it then filled the gap with zeros. + +The cause, measured with a driver that records where it stops: after the "Stop Tran" token that ends a multi-block write, a card takes about a byte of clock to signal busy. The driver deselects, selects again, and reads one byte to see whether the card is ready. Read too early, that byte is 0xFF, "ready"; the status check (CMD13) then goes out while the card is still programming, and its answer (0xFF, 0x1F) is taken for an error. Every failure seen was this one: all blocks accepted, then a status that isn't one. ChaN's reference driver, which FatFs ships as its example, sends a dummy byte after selecting the card for this reason. Arduino's doesn't. + +PlatformIO links the framework's library objects directly, so one file can't be replaced from `src`. A project library with the same name takes its place: **`lib/SD` is Arduino-ESP32 3.3.12's SD library (Apache-2.0), with `sd_diskio.cpp` changed** and the other files as they came. The changes are marked `roro:`: + +- A dummy byte after selecting the card, before the ready test, and one after Stop Tran. +- Each place a write gives up records the step and the card's answer (`sd_fault.h`): `info` shows the count, and the Debug Console's `put` prints the detail. + +Halving the SPI clock to 10 MHz didn't change the failure rate, so the card stays at 20 MHz. + +## Consequences + +- 30 uploads of 1.7 MB in a row, each read back and compared by SHA-256, ten of them with the LoRa radio listening on the same bus: no write fault. Before: 3 failures in 10. +- Every writer gains: Logs, Tracks, Gemini pages, Saved Pages, Captures and Update Files installed from the card all go through this driver, and none of them checked. +- **The copy has to follow the framework.** When the platform is updated, compare `lib/SD` with the new `libraries/SD` and carry the `roro:` changes over. If upstream fixes the ready test, drop the copy. +- One more defect was read in the code and left alone, because nothing here exercises it: the driver tests the card's answer to a data block against 0x0A and 0x0C, values it can't take (accepted is 0x05, CRC error 0x0B, write error 0x0D), so a block rejected for a CRC error is never resent. No such rejection was seen in any failure. If `DataToken` faults ever show in `info`, that's the next fix. +- A fault is now counted and explained instead of silent, so the next cause, if there is one, starts with evidence. diff --git a/lib/SD/src/sd_diskio.cpp b/lib/SD/src/sd_diskio.cpp index 538f453..7d003a6 100644 --- a/lib/SD/src/sd_diskio.cpp +++ b/lib/SD/src/sd_diskio.cpp @@ -1,3 +1,8 @@ +// roro9stack's copy of the SD-over-SPI driver from Arduino-ESP32 3.3.12 (libraries/SD/src/ +// sd_diskio.cpp), linked instead of the framework's: defining every function the SD class needs +// keeps the library's file out of the link. Changes are marked "roro:". Why (issue #21): the +// original gives up on a write without saying why, and never resends a block the card rejects. +// // Copyright 2015-2016 Espressif Systems (Shanghai) PTE LTD // // Licensed under the Apache License, Version 2.0 (the "License"); @@ -28,10 +33,25 @@ extern "C" { #endif //#include "esp_vfs.h" #include "esp_vfs_fat.h" + char CRC7(const char *data, int length); unsigned short CRC16(const char *data, int length); } +// roro: why the last write failed. +#include "sd_fault.h" +static roro::SdFault s_fault; +static bool sdFault(roro::SdFault::Step step, uint8_t token = 0, uint32_t resp = 0) { + s_fault.step = step; + s_fault.token = token; + s_fault.resp = resp; + s_fault.count++; + return false; +} +namespace roro { +SdFault sdLastFault() { return s_fault; } +} // namespace roro + typedef enum { GO_IDLE_STATE = 0, SEND_OP_COND = 1, @@ -128,6 +148,11 @@ void sdDeselectCard(uint8_t pdrv) { bool sdSelectCard(uint8_t pdrv) { ardu_sdcard_t *card = s_cards[pdrv]; digitalWrite(card->ssPin, LOW); + // roro: one dummy byte before asking whether the card is ready, as ChaN's reference driver does. + // A card that has just been given a write takes about a byte of clock to signal busy; without + // this, that first byte reads 0xFF, "ready", and the next command (the status check after a + // write) goes out while the card is still programming and comes back as garbage (#21). + card->spi->transfer(0xFF); bool s = sdWait(pdrv, 500); if (!s) { log_e("Select Failed"); @@ -308,9 +333,10 @@ bool sdReadSectors(uint8_t pdrv, char *buffer, unsigned long long sector, int co } bool sdWriteSector(uint8_t pdrv, const char *buffer, unsigned long long sector) { + using roro::SdFault; for (int f = 0; f < 3; f++) { if (!sdSelectCard(pdrv)) { - return false; + return sdFault(SdFault::Select); // roro: say why } if (!sdCommand(pdrv, WRITE_BLOCK_SINGLE, (s_cards[pdrv]->type == CARD_SDHC) ? sector : sector << 9, NULL)) { char token = sdWriteBytes(pdrv, buffer, 0xFE); @@ -319,12 +345,13 @@ bool sdWriteSector(uint8_t pdrv, const char *buffer, unsigned long long sector) if (token == 0x0A) { continue; } else if (token == 0x0C) { - return false; + return sdFault(SdFault::DataToken, token); } unsigned int resp; - if (sdTransaction(pdrv, SEND_STATUS, 0, &resp) || resp) { - return false; + char status = sdTransaction(pdrv, SEND_STATUS, 0, &resp); + if (status || resp) { + return token != 0x05 ? sdFault(SdFault::DataToken, token, resp) : sdFault(SdFault::Status, status, resp); } return true; } else { @@ -332,25 +359,29 @@ bool sdWriteSector(uint8_t pdrv, const char *buffer, unsigned long long sector) } } sdDeselectCard(pdrv); - return false; + return sdFault(SdFault::Command); } bool sdWriteSectors(uint8_t pdrv, const char *buffer, unsigned long long sector, int count) { + using roro::SdFault; char token; const char *currentBuffer = buffer; unsigned long long currentSector = sector; int currentCount = count; ardu_sdcard_t *card = s_cards[pdrv]; + SdFault::Step why = SdFault::Command; // roro: what stopped it, for the last return + uint8_t whyToken = 0; for (int f = 0; f < 3;) { if (card->type != CARD_MMC) { - if (sdTransaction(pdrv, SET_WR_BLK_ERASE_COUNT, currentCount, NULL)) { - return false; + char refused = sdTransaction(pdrv, SET_WR_BLK_ERASE_COUNT, currentCount, NULL); + if (refused) { + return sdFault(SdFault::EraseCount, refused); } } if (!sdSelectCard(pdrv)) { - return false; + return sdFault(SdFault::Select); } if (!sdCommand(pdrv, WRITE_BLOCK_MULTIPLE, (card->type == CARD_SDHC) ? currentSector : currentSector << 9, NULL)) { @@ -365,20 +396,25 @@ bool sdWriteSectors(uint8_t pdrv, const char *buffer, unsigned long long sector, } while (--currentCount); if (!sdWait(pdrv, 500)) { + why = SdFault::BusyAfter; break; } if (currentCount == 0) { sdStop(pdrv); + card->spi->transfer(0xFF); // roro: the byte the card takes to go busy after Stop Tran (#21) sdDeselectCard(pdrv); unsigned int resp; - if (sdTransaction(pdrv, SEND_STATUS, 0, &resp) || resp) { - return false; + char status = sdTransaction(pdrv, SEND_STATUS, 0, &resp); + if (status || resp) { + return sdFault(SdFault::Status, status, resp); } return true; } else { if (sdCommand(pdrv, STOP_TRANSMISSION, 0, NULL)) { + why = SdFault::StopCommand; + whyToken = token; break; } @@ -402,6 +438,8 @@ bool sdWriteSectors(uint8_t pdrv, const char *buffer, unsigned long long sector, currentCount = count - writtenBlocks; continue; } else { + why = SdFault::DataToken; + whyToken = token; break; } } @@ -410,7 +448,7 @@ bool sdWriteSectors(uint8_t pdrv, const char *buffer, unsigned long long sector, } } sdDeselectCard(pdrv); - return false; + return sdFault(why, whyToken); } unsigned long sdGetSectorsCount(uint8_t pdrv) { diff --git a/lib/SD/src/sd_fault.h b/lib/SD/src/sd_fault.h new file mode 100644 index 0000000..347f892 --- /dev/null +++ b/lib/SD/src/sd_fault.h @@ -0,0 +1,29 @@ +#pragma once + +#include + +namespace roro { + +// Why the SD driver last gave up on a write (see sd_diskio.cpp, issue #21). The framework's driver +// fails without saying why; ours records it. +struct SdFault { + enum Step : uint8_t { + None, + EraseCount, // ACMD23 before a multi-block write was refused + Select, // the card stayed busy for 500 ms + Command, // the write command itself was refused + DataToken, // the card's answer to a data block: 0x0B CRC error, 0x0D write error + BusyAfter, // still busy 500 ms after the last block + Status, // CMD13 after the write reported an error (resp) + StopCommand, // CMD12 after a rejected block was refused + }; + Step step = None; + uint8_t token = 0; // the driver's or the card's answer at that step + uint32_t resp = 0; // CMD13's status bits, for Status + uint32_t count = 0; // failed writes since boot + uint32_t retried = 0; // blocks resent after a CRC error, since boot +}; + +SdFault sdLastFault(); + +} // namespace roro diff --git a/src/main.cpp b/src/main.cpp index c71a078..c492b66 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -23,6 +23,7 @@ #include "platform/crash_report.h" #include "platform/nvs_store.h" #include "platform/system_info.h" +#include "sd_fault.h" #include "service_manager.h" #include "platform/identity.h" #include "services/battery_service.h" @@ -400,8 +401,8 @@ static void runCommand(String line) { if (line == "help") console.print(kHelp); if (line == "info") { system_info::printSystem(console); - console.printf("wifi: %s, ip %s, rssi %d | sd: %s\n", wifi->ssid().c_str(), wifi->ip().c_str(), wifi->rssi(), - storageService->state().present ? "present" : "none"); + console.printf("wifi: %s, ip %s, rssi %d | sd: %s, %u write faults\n", wifi->ssid().c_str(), wifi->ip().c_str(), + wifi->rssi(), storageService->state().present ? "present" : "none", (unsigned)sdLastFault().count); console.printf("update: %s\n", update->onProbation() ? "on probation" : "confirmed"); system_info::printSlots(console, nvs); } diff --git a/src/services/debug_console.cpp b/src/services/debug_console.cpp index dddce6b..e2ebaca 100644 --- a/src/services/debug_console.cpp +++ b/src/services/debug_console.cpp @@ -17,6 +17,7 @@ #include "file_receiver.h" #include "sha256.h" #include "platform/console.h" +#include "sd_fault.h" #include "version.h" namespace roro { @@ -232,7 +233,16 @@ void DebugConsole::put(NetworkClient& client, const std::string& args) { while (r.state() == S::Receiving || r.state() == S::Writing) { if (r.state() == S::Writing) { const auto& c = r.chunk(); + uint32_t t0 = millis(); bool ok = f.write(c.data(), c.size()) == c.size(); + uint32_t took = millis() - t0; + // Why, from our copy of the SD driver (lib/SD, #21): the step that gave up and what + // the card answered. How long it took tells a 500 ms busy timeout from a refusal. + if (!ok) { + SdFault sd = sdLastFault(); + console.printf("put: write failed at %u after %u ms: SD step %u, answer 0x%02X, status 0x%04X (%u so far)\n", + (unsigned)r.received(), (unsigned)took, sd.step, sd.token, (unsigned)sd.resp, (unsigned)sd.count); + } // A card can fail one write and take the next. FATFS keeps a failed file in error, // so: close, cut back to the last good byte, reopen, try again. Earlier chunks may // have been lost with the write buffer (M3: 3 KB came back as zeros): never extend diff --git a/src/services/storage_service.cpp b/src/services/storage_service.cpp index 3a400fd..c8c9929 100644 --- a/src/services/storage_service.cpp +++ b/src/services/storage_service.cpp @@ -166,7 +166,7 @@ void StorageService::format() { mounted_ = false; bool ok = false; - uint8_t pdrv = sdcard_init(pins::kSdCs, &sharedSpi(), 20000000); + uint8_t pdrv = sdcard_init(pins::kSdCs, &sharedSpi(), kSdHz); if (pdrv != 0xFF) { constexpr size_t kWorkSize = 4096; // FF_MAX_SS std::unique_ptr work(new uint8_t[kWorkSize]); @@ -182,7 +182,7 @@ void StorageService::format() { } bool StorageService::mount() { - return SD.begin(pins::kSdCs, sharedSpi(), 20000000, "/sd", 5, false); + return SD.begin(pins::kSdCs, sharedSpi(), kSdHz, "/sd", 5, false); } void StorageService::poll() { diff --git a/src/services/storage_service.h b/src/services/storage_service.h index 6836d28..c9d0312 100644 --- a/src/services/storage_service.h +++ b/src/services/storage_service.h @@ -56,6 +56,7 @@ class StorageService : public Service { static constexpr uint32_t kWakeMs = 1000; static constexpr uint32_t kPollEvery = 15; // wake-ups between usage checks static constexpr size_t kMaxPendingBytes = 16 * 1024; + static constexpr uint32_t kSdHz = 20000000; // the card's SPI clock; 10 MHz changed nothing (ADR 0007) static void taskEntry(void* self); void loop();