sdmmc: improve error handling during SPI mode init

- In SPI mode, the card will respond to the initial SDIO reset (done
using CMD52) with “invalid command” error. Handle this correctly.

- sdmmc_card_init had a hack where GO_IDLE_STATE (CMD0) command was
sent twice. Add explanation why this is done, and don’t expect
correct response from the card on first CMD0.

- improve logs printed at debug level by adding CMD index

components/driver/sdspi_host.c

@@ -394,7 +394,7 @@ esp_err_t sdspi_host_start_command(int slot, sdspi_hw_cmd_t *cmd, void *data,
     release_bus(slot);
 
     if (ret != ESP_OK) {
-        ESP_LOGE(TAG, "%s: cmd=%d error=0x%x", __func__, cmd_index, ret);
+        ESP_LOGD(TAG, "%s: cmd=%d error=0x%x", __func__, cmd_index, ret);
     } else {
         // Update internal state when some commands are sent successfully
         if (cmd_index == SD_CRC_ON_OFF) {
@@ -408,7 +408,8 @@ esp_err_t sdspi_host_start_command(int slot, sdspi_hw_cmd_t *cmd, void *data,
 static esp_err_t start_command_default(int slot, int flags, sdspi_hw_cmd_t *cmd)
 {
     size_t cmd_size = SDSPI_CMD_R1_SIZE;
-    if (flags & SDSPI_CMD_FLAG_RSP_R1) {
+    if ((flags & SDSPI_CMD_FLAG_RSP_R1) ||
+        (flags & SDSPI_CMD_FLAG_NORSP)) {
         cmd_size = SDSPI_CMD_R1_SIZE;
     } else if (flags & SDSPI_CMD_FLAG_RSP_R2) {
         cmd_size = SDSPI_CMD_R2_SIZE;
@@ -428,6 +429,11 @@ static esp_err_t start_command_default(int slot, int flags, sdspi_hw_cmd_t *cmd)
         /* response is a stuff byte from previous transfer, ignore it */
         cmd->r1 = 0xff;
     }
+    if (flags & SDSPI_CMD_FLAG_NORSP) {
+        /* no (correct) response expected from the card, so skip polling loop */
+        ESP_LOGV(TAG, "%s: ignoring response byte", __func__);
+        cmd->r1 = 0x00;
+    }
     int response_delay_bytes = SDSPI_RESPONSE_MAX_DELAY;
     while ((cmd->r1 & SD_SPI_R1_NO_RESPONSE) != 0 && response_delay_bytes-- > 0) {
         spi_transaction_t* t = get_transaction(slot);

components/driver/sdspi_private.h

@@ -89,6 +89,7 @@ typedef struct {
 #define SDSPI_CMD_FLAG_RSP_R2   BIT(3)  //!< Response format R2 (2 bytes)
 #define SDSPI_CMD_FLAG_RSP_R3   BIT(4)  //!< Response format R3 (5 bytes)
 #define SDSPI_CMD_FLAG_RSP_R7   BIT(5)  //!< Response format R7 (5 bytes)
+#define SDSPI_CMD_FLAG_NORSP    BIT(6)  //!< Don't expect response (used when sending CMD0 first time).
 
 #define SDSPI_MAX_DATA_LEN      512     //!< Max size of single block transfer
 

components/driver/sdspi_transaction.c

@@ -51,22 +51,22 @@ void make_hw_cmd(uint32_t opcode, uint32_t arg, int timeout_ms, sdspi_hw_cmd_t *
     hw_cmd->timeout_ms = timeout_ms;
 }
 
-static void r1_response_to_err(uint8_t r1, esp_err_t *out_err)
+static void r1_response_to_err(uint8_t r1, int cmd, esp_err_t *out_err)
 {
     if (r1 & SD_SPI_R1_NO_RESPONSE) {
-        ESP_LOGD(TAG, "R1 response not found");
+        ESP_LOGD(TAG, "cmd=%d, R1 response not found", cmd);
         *out_err = ESP_ERR_TIMEOUT;
     } else if (r1 & SD_SPI_R1_CMD_CRC_ERR) {
-        ESP_LOGD(TAG, "R1 response: command CRC error");
+        ESP_LOGD(TAG, "cmd=%d, R1 response: command CRC error", cmd);
         *out_err = ESP_ERR_INVALID_CRC;
     } else if (r1 & SD_SPI_R1_ILLEGAL_CMD) {
-        ESP_LOGD(TAG, "R1 response: command not supported");
+        ESP_LOGD(TAG, "cmd=%d, R1 response: command not supported", cmd);
         *out_err = ESP_ERR_NOT_SUPPORTED;
     } else if (r1 & SD_SPI_R1_ADDR_ERR) {
-        ESP_LOGD(TAG, "R1 response: alignment error");
+        ESP_LOGD(TAG, "cmd=%d, R1 response: alignment error", cmd);
         *out_err = ESP_ERR_INVALID_ARG;
     } else if (r1 & SD_SPI_R1_PARAM_ERR) {
-        ESP_LOGD(TAG, "R1 response: size error");
+        ESP_LOGD(TAG, "cmd=%d, R1 response: size error", cmd);
         *out_err = ESP_ERR_INVALID_SIZE;
     } else if ((r1 & SD_SPI_R1_ERASE_RST) ||
                (r1 & SD_SPI_R1_ERASE_SEQ_ERR)) {
@@ -74,7 +74,7 @@ static void r1_response_to_err(uint8_t r1, esp_err_t *out_err)
     } else if (r1 & SD_SPI_R1_IDLE_STATE) {
         // Idle state is handled at command layer
     } else if (r1 != 0) {
-        ESP_LOGD(TAG, "R1 response: unexpected value 0x%02x", r1);
+        ESP_LOGD(TAG, "cmd=%d, R1 response: unexpected value 0x%02x", cmd, r1);
         *out_err = ESP_ERR_INVALID_RESPONSE;
     }
 }
@@ -107,6 +107,10 @@ esp_err_t sdspi_host_do_transaction(int slot, sdmmc_command_t *cmdinfo)
         flags |= SDSPI_CMD_FLAG_RSP_R3;
     } else if (s_app_cmd && cmdinfo->opcode == SD_APP_SD_STATUS) {
         flags |= SDSPI_CMD_FLAG_RSP_R2;
+    } else if (!s_app_cmd && cmdinfo->opcode == MMC_GO_IDLE_STATE &&
+            !(cmdinfo->flags & SCF_RSP_R1)) {
+        /* used to send CMD0 without expecting a response */
+        flags |= SDSPI_CMD_FLAG_NORSP;
     } else {
         flags |= SDSPI_CMD_FLAG_RSP_R1;
     }
@@ -121,11 +125,11 @@ esp_err_t sdspi_host_do_transaction(int slot, sdmmc_command_t *cmdinfo)
         // Some errors should be reported using return code
         if (flags & SDSPI_CMD_FLAG_RSP_R1) {
             cmdinfo->response[0] = hw_cmd.r1;
-            r1_response_to_err(hw_cmd.r1, &ret);
+            r1_response_to_err(hw_cmd.r1, cmdinfo->opcode, &ret);
         } else if (flags & SDSPI_CMD_FLAG_RSP_R2) {
             cmdinfo->response[0] = (((uint32_t)hw_cmd.r1) << 8) | (hw_cmd.response[0] >> 24);
         } else if (flags & (SDSPI_CMD_FLAG_RSP_R3 | SDSPI_CMD_FLAG_RSP_R7)) {
-            r1_response_to_err(hw_cmd.r1, &ret);
+            r1_response_to_err(hw_cmd.r1, cmdinfo->opcode, &ret);
             cmdinfo->response[0] = __builtin_bswap32(hw_cmd.response[0]);
         }
     }

components/sdmmc/sdmmc_cmd.c

@@ -37,6 +37,12 @@
 #define SDMMC_DEFAULT_CMD_TIMEOUT_MS  1000   // Max timeout of ordinary commands
 #define SDMMC_WRITE_CMD_TIMEOUT_MS    5000   // Max timeout of write commands
 
+/* Maximum retry/error count for SEND_OP_COND (CMD1).
+ * These are somewhat arbitrary, values originate from OpenBSD driver.
+ */
+#define SDMMC_SEND_OP_COND_MAX_RETRIES  100
+#define SDMMC_SEND_OP_COND_MAX_ERRORS   3
+
 static const char* TAG = "sdmmc_cmd";
 
 static esp_err_t sdmmc_send_cmd(sdmmc_card_t* card, sdmmc_command_t* cmd);
@@ -97,11 +103,13 @@ esp_err_t sdmmc_card_init(const sdmmc_host_t* config, sdmmc_card_t* card)
     /* ----------- standard initialization process starts here ---------- */
 
     /* Reset SDIO (CMD52, RES) before re-initializing IO (CMD5).
-     * Non-IO cards are allowed to time out.
+     * Non-IO cards are allowed to time out (in SD mode) or
+     * return "invalid command" error (in SPI mode).
      */
     uint8_t sdio_reset = CCCR_CTL_RES;
     err = sdmmc_io_rw_direct(card, 0, SD_IO_CCCR_CTL, SD_ARG_CMD52_WRITE, &sdio_reset);
-    if (err != ESP_OK && err != ESP_ERR_TIMEOUT) {
+    if (err != ESP_OK && err != ESP_ERR_TIMEOUT
+            && !(is_spi && err == ESP_ERR_NOT_SUPPORTED)) {
         ESP_LOGE(TAG, "%s: sdio_reset: unexpected return: 0x%x", __func__, err );
         return err;
     }
@@ -112,12 +120,6 @@ esp_err_t sdmmc_card_init(const sdmmc_host_t* config, sdmmc_card_t* card)
         ESP_LOGE(TAG, "%s: go_idle_state (1) returned 0x%x", __func__, err);
         return err;
     }
-
-    /* FIXME: we should check card status to wait until it is out of idle
-     * state, instead of using a delay.
-     */
-    vTaskDelay(SDMMC_GO_IDLE_DELAY_MS / portTICK_PERIOD_MS);
-    sdmmc_send_cmd_go_idle_state(card);
     vTaskDelay(SDMMC_GO_IDLE_DELAY_MS / portTICK_PERIOD_MS);
 
     /* SEND_IF_COND (CMD8) command is used to identify SDHC/SDXC cards.
@@ -454,7 +456,7 @@ static esp_err_t sdmmc_send_cmd(sdmmc_card_t* card, sdmmc_command_t* cmd)
             slot, cmd->opcode, cmd->arg, cmd->flags, cmd->data, cmd->blklen, cmd->datalen, cmd->timeout_ms);
     esp_err_t err = (*card->host.do_transaction)(slot, cmd);
     if (err != 0) {
-        ESP_LOGD(TAG, "sdmmc_req_run returned 0x%x", err);
+        ESP_LOGD(TAG, "cmd=%d, sdmmc_req_run returned 0x%x", cmd->opcode, err);
         return err;
     }
     int state = MMC_R1_CURRENT_STATE(cmd->response);
@@ -494,7 +496,21 @@ static esp_err_t sdmmc_send_cmd_go_idle_state(sdmmc_card_t* card)
         .opcode = MMC_GO_IDLE_STATE,
         .flags = SCF_CMD_BC | SCF_RSP_R0,
     };
-    return sdmmc_send_cmd(card, &cmd);
+    esp_err_t err = sdmmc_send_cmd(card, &cmd);
+    if (host_is_spi(card)) {
+        /* To enter SPI mode, CMD0 needs to be sent twice (see figure 4-1 in
+         * SD Simplified spec v4.10). Some cards enter SD mode on first CMD0,
+         * so don't expect the above command to succeed.
+         * SCF_RSP_R1 flag below tells the lower layer to expect correct R1
+         * response (in SPI mode).
+         */
+        (void) err;
+        vTaskDelay(SDMMC_GO_IDLE_DELAY_MS / portTICK_PERIOD_MS);
+
+        cmd.flags |= SCF_RSP_R1;
+        err = sdmmc_send_cmd(card, &cmd);
+    }
+    return err;
 }
 
 
@@ -525,11 +541,18 @@ static esp_err_t sdmmc_send_cmd_send_op_cond(sdmmc_card_t* card, uint32_t ocr, u
             .flags = SCF_CMD_BCR | SCF_RSP_R3,
             .opcode = SD_APP_OP_COND
     };
-    int nretries = 100;   // arbitrary, BSD driver uses this value
+    int nretries = SDMMC_SEND_OP_COND_MAX_RETRIES;
+    int err_cnt = SDMMC_SEND_OP_COND_MAX_ERRORS;
     for (; nretries != 0; --nretries)  {
         esp_err_t err = sdmmc_send_app_cmd(card, &cmd);
         if (err != ESP_OK) {
-            return err;
+            if (--err_cnt == 0) {
+                ESP_LOGD(TAG, "%s: sdmmc_send_app_cmd err=0x%x", __func__, err);
+                return err;
+            } else {
+                ESP_LOGV(TAG, "%s: ignoring err=0x%x", __func__, err);
+                continue;
+            }
         }
         // In SD protocol, card sets MEM_READY bit in OCR when it is ready.
         // In SPI protocol, card clears IDLE_STATE bit in R1 response.