SD driver: a dummy byte before the ready test; say why a write failed (#21)

The card "refused" a write about once in 2,000 multi-block writes: three
1.7 MB uploads in ten. Measured with a driver that records where it gives
up: every time, all blocks were accepted, and the status check after Stop
Tran came back as 0xFF or 0x1F. The driver tests for ready with the first
byte after selecting the card, which reads 0xFF before the card has
signalled busy, so CMD13 went out mid-programming. A dummy byte first, as
in ChaN's reference driver, and one after Stop Tran.

30 uploads in a row since, each read back by SHA-256, ten with the radio
listening: no fault. 10 MHz made no difference; the card stays at 20 MHz.

`info` shows the driver's write faults; `put` prints the step and the
card's answer when one happens. ADR 0007.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01EhqxQ49eCju4CzKYNjZzwT

README.md

@@ -85,7 +85,7 @@ The LoRa Scanner (docs/milestones/M3.md) listens with the Cap's radio and **neve
 | `irc say <buffer> <text>` | 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 |

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.

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) {

lib/SD/src/sd_fault.h

@@ -0,0 +1,29 @@
+#pragma once
+
+#include <cstdint>
+
+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

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);
     }

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

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<uint8_t[]> 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() {

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();