Merge branch 'contrib/github_pr_10532' into 'master'

[SDMMC Mount] fix infinite loop when SD card is not responsive (GitHub PR)

Closes IDFGH-9132, IDFGH-9131, and IDFGH-582

See merge request espressif/esp-idf!22081

components/driver/sdmmc/sdmmc_host.c

@@ -9,6 +9,8 @@
 #include <sys/param.h>
 #include "esp_log.h"
 #include "esp_intr_alloc.h"
+#include "esp_timer.h"
+#include "esp_check.h"
 #include "soc/soc_caps.h"
 #include "soc/soc_pins.h"
 #include "soc/gpio_periph.h"
@@ -25,7 +27,6 @@
 
 #define SDMMC_EVENT_QUEUE_LENGTH 32
 
-
 static void sdmmc_isr(void* arg);
 static void sdmmc_host_dma_init(void);
 
@@ -68,16 +69,23 @@ static void configure_pin_iomux(uint8_t gpio_num);
 
 static esp_err_t sdmmc_host_pullup_en_internal(int slot, int width);
 
-void sdmmc_host_reset(void)
+esp_err_t sdmmc_host_reset(void)
 {
     // Set reset bits
     SDMMC.ctrl.controller_reset = 1;
     SDMMC.ctrl.dma_reset = 1;
     SDMMC.ctrl.fifo_reset = 1;
+
     // Wait for the reset bits to be cleared by hardware
+    int64_t t0 = esp_timer_get_time();
     while (SDMMC.ctrl.controller_reset || SDMMC.ctrl.fifo_reset || SDMMC.ctrl.dma_reset) {
-        ;
+        if (esp_timer_get_time() - t0 > SDMMC_HOST_RESET_TIMEOUT_US) {
+            return ESP_ERR_TIMEOUT;
         }
+        vTaskDelay(1);
+    }
+
+    return ESP_OK;
 }
 
 /* We have two clock divider stages:
@@ -142,7 +150,7 @@ static void sdmmc_host_input_clk_disable(void)
     SDMMC.clock.val = 0;
 }
 
-static void sdmmc_host_clock_update_command(int slot)
+static esp_err_t sdmmc_host_clock_update_command(int slot)
 {
     // Clock update command (not a real command; just updates CIU registers)
     sdmmc_hw_cmd_t cmd_val = {
@@ -152,8 +160,16 @@ static void sdmmc_host_clock_update_command(int slot)
     };
     bool repeat = true;
     while(repeat) {
-        sdmmc_host_start_command(slot, cmd_val, 0);
+
+        ESP_RETURN_ON_ERROR(sdmmc_host_start_command(slot, cmd_val, 0), TAG, "sdmmc_host_start_command returned 0x%x", err_rc_);
+
+        int64_t t0 = esp_timer_get_time();
         while (true) {
+
+            if (esp_timer_get_time() - t0 > SDMMC_HOST_CLOCK_UPDATE_CMD_TIMEOUT_US) {
+                return ESP_ERR_TIMEOUT;
+            }
+
             // Sending clock update command to the CIU can generate HLE error.
             // According to the manual, this is okay and we must retry the command.
             if (SDMMC.rintsts.hle) {
@@ -167,8 +183,12 @@ static void sdmmc_host_clock_update_command(int slot)
                 repeat = false;
                 break;
             }
+
+            vTaskDelay(1);
         }
     }
+
+    return ESP_OK;
 }
 
 void sdmmc_host_get_clk_dividers(const uint32_t freq_khz, int *host_div, int *card_div)
@@ -215,7 +235,12 @@ esp_err_t sdmmc_host_set_card_clk(int slot, uint32_t freq_khz)
 
     // Disable clock first
     SDMMC.clkena.cclk_enable &= ~BIT(slot);
-    sdmmc_host_clock_update_command(slot);
+    esp_err_t err = sdmmc_host_clock_update_command(slot);
+    if (err != ESP_OK) {
+        ESP_LOGE(TAG, "disabling clk failed");
+        ESP_LOGE(TAG, "%s: sdmmc_host_clock_update_command returned 0x%x", __func__, err);
+        return err;
+    }
 
     int host_div = 0;   /* clock divider of the host (SDMMC.clock) */
     int card_div = 0;   /* 1/2 of card clock divider (SDMMC.clkdiv) */
@@ -236,12 +261,22 @@ esp_err_t sdmmc_host_set_card_clk(int slot, uint32_t freq_khz)
             break;
     }
     sdmmc_host_set_clk_div(host_div);
-    sdmmc_host_clock_update_command(slot);
+    err = sdmmc_host_clock_update_command(slot);
+    if (err != ESP_OK) {
+        ESP_LOGE(TAG, "setting clk div failed");
+        ESP_LOGE(TAG, "%s: sdmmc_host_clock_update_command returned 0x%x", __func__, err);
+        return err;
+    }
 
     // Re-enable clocks
     SDMMC.clkena.cclk_enable |= BIT(slot);
     SDMMC.clkena.cclk_low_power |= BIT(slot);
-    sdmmc_host_clock_update_command(slot);
+    err = sdmmc_host_clock_update_command(slot);
+    if (err != ESP_OK) {
+        ESP_LOGE(TAG, "re-enabling clk failed");
+        ESP_LOGE(TAG, "%s: sdmmc_host_clock_update_command returned 0x%x", __func__, err);
+        return err;
+    }
 
     // set data timeout
     const uint32_t data_timeout_ms = 100;
@@ -282,8 +317,12 @@ esp_err_t sdmmc_host_start_command(int slot, sdmmc_hw_cmd_t cmd, uint32_t arg) {
     if (cmd.data_expected && cmd.rw && (SDMMC.wrtprt.cards & BIT(slot)) != 0) {
         return ESP_ERR_INVALID_STATE;
     }
+    int64_t t0 = esp_timer_get_time();
     while (SDMMC.cmd.start_command == 1) {
-        ;
+        if (esp_timer_get_time() - t0 > SDMMC_HOST_START_CMD_TIMEOUT_US) {
+            return ESP_ERR_TIMEOUT;
+        }
+        vTaskDelay(1);
     }
     SDMMC.cmdarg = arg;
     cmd.card_num = slot;
@@ -305,7 +344,12 @@ esp_err_t sdmmc_host_init(void)
     sdmmc_host_set_clk_div(2);
 
     // Reset
-    sdmmc_host_reset();
+    esp_err_t err = sdmmc_host_reset();
+    if (err != ESP_OK) {
+        ESP_LOGE(TAG, "%s: sdmmc_host_reset returned 0x%x", __func__, err);
+        return err;
+    }
+
     ESP_LOGD(TAG, "peripheral version %"PRIx32", hardware config %08"PRIx32, SDMMC.verid, SDMMC.hcon);
 
     // Clear interrupt status and set interrupt mask to known state
@@ -512,6 +556,8 @@ esp_err_t sdmmc_host_init_slot(int slot, const sdmmc_slot_config_t* slot_config)
     // By default, set probing frequency (400kHz) and 1-bit bus
     esp_err_t ret = sdmmc_host_set_card_clk(slot, 400);
     if (ret != ESP_OK) {
+        ESP_LOGE(TAG, "setting probing freq and 1-bit bus failed");
+        ESP_LOGE(TAG, "%s: sdmmc_host_set_card_clk returned 0x%x", __func__, ret);
         return ret;
     }
     ret = sdmmc_host_set_bus_width(slot, 1);

components/driver/sdmmc/sdmmc_private.h

@@ -18,7 +18,11 @@ typedef struct {
     uint32_t dma_status;        ///< masked DMA interrupt status
 } sdmmc_event_t;
 
-void sdmmc_host_reset(void);
+#define SDMMC_HOST_CLOCK_UPDATE_CMD_TIMEOUT_US           1000 * 1000
+#define SDMMC_HOST_START_CMD_TIMEOUT_US                  1000 * 1000
+#define SDMMC_HOST_RESET_TIMEOUT_US                      5000 * 1000
+
+esp_err_t sdmmc_host_reset(void);
 
 esp_err_t sdmmc_host_start_command(int slot, sdmmc_hw_cmd_t cmd, uint32_t arg);
 

components/driver/sdmmc/sdmmc_transaction.c

@@ -17,6 +17,7 @@
 #include "driver/sdmmc_types.h"
 #include "driver/sdmmc_defs.h"
 #include "driver/sdmmc_host.h"
+#include "esp_timer.h"
 #include "sdmmc_private.h"
 
 

components/fatfs/test_apps/sdcard/pytest_fatfs_sdcard.py

@@ -1,4 +1,4 @@
-# SPDX-FileCopyrightText: 2022 Espressif Systems (Shanghai) CO LTD
+# SPDX-FileCopyrightText: 2022-2023 Espressif Systems (Shanghai) CO LTD
 # SPDX-License-Identifier: CC0-1.0
 
 import pytest
@@ -19,7 +19,7 @@ def test_fatfs_sdcard_generic_sdmmc(dut: Dut) -> None:
     dut.write('')
     dut.expect_exact('Enter test for running.')
     dut.write('[sdmmc]')
-    dut.expect_unity_test_output()
+    dut.expect_unity_test_output(timeout=120)
 
 
 @pytest.mark.esp32
@@ -38,7 +38,7 @@ def test_fatfs_sdcard_generic_sdspi(dut: Dut) -> None:
     dut.write('')
     dut.expect_exact('Enter test for running.')
     dut.write('[sdspi]')
-    dut.expect_unity_test_output()
+    dut.expect_unity_test_output(timeout=120)
 
 
 @pytest.mark.esp32
@@ -55,7 +55,7 @@ def test_fatfs_sdcard_psram_sdmmc(dut: Dut) -> None:
     dut.write('')
     dut.expect_exact('Enter test for running.')
     dut.write('[sdmmc]')
-    dut.expect_unity_test_output()
+    dut.expect_unity_test_output(timeout=120)
 
 
 @pytest.mark.esp32
@@ -72,4 +72,4 @@ def test_fatfs_sdcard_psram_sdspi(dut: Dut) -> None:
     dut.write('')
     dut.expect_exact('Enter test for running.')
     dut.write('[sdspi]')
-    dut.expect_unity_test_output()
+    dut.expect_unity_test_output(timeout=120)

components/fatfs/vfs/vfs_fat_sdmmc.c

@@ -88,7 +88,6 @@ static esp_err_t mount_prepare_mem(const char *base_path,
     if (ff_diskio_get_drive(&pdrv) != ESP_OK || pdrv == FF_DRV_NOT_USED) {
         ESP_LOGD(TAG, "the maximum count of volumes is already mounted");
         return ESP_ERR_NO_MEM;
-
     }
 
     // not using ff_memalloc here, as allocation in internal RAM is preferred

components/sdmmc/CMakeLists.txt

@@ -6,6 +6,6 @@ idf_component_register(SRCS "sdmmc_cmd.c"
                             "sdmmc_sd.c"
                     INCLUDE_DIRS include
                     REQUIRES driver
-                    PRIV_REQUIRES soc)
+                    PRIV_REQUIRES soc esp_timer)
 
 target_compile_options(${COMPONENT_LIB} PRIVATE "-Wno-format")

components/sdmmc/sdmmc_cmd.c

@@ -4,6 +4,7 @@
  * SPDX-License-Identifier: Apache-2.0
  */
 
+#include "esp_timer.h"
 #include "sdmmc_common.h"
 
 static const char* TAG = "sdmmc_cmd";
@@ -451,16 +452,22 @@ esp_err_t sdmmc_write_sectors_dma(sdmmc_card_t* card, const void* src,
     }
     uint32_t status = 0;
     size_t count = 0;
+    int64_t t0 = esp_timer_get_time();
     /* SD mode: wait for the card to become idle based on R1 status */
     while (!host_is_spi(card) && !(status & MMC_R1_READY_FOR_DATA)) {
-        // TODO: add some timeout here
+        if (esp_timer_get_time() - t0 > SDMMC_READY_FOR_DATA_TIMEOUT_US) {
+            ESP_LOGE(TAG, "write sectors dma - timeout");
+            return ESP_ERR_TIMEOUT;
+        }
         err = sdmmc_send_cmd_send_status(card, &status);
         if (err != ESP_OK) {
+            ESP_LOGE(TAG, "%s: sdmmc_send_cmd_send_status returned 0x%x", __func__, err);
             return err;
         }
         if (++count % 10 == 0) {
             ESP_LOGV(TAG, "waiting for card to become ready (%d)", count);
         }
+        vTaskDelay(1);
     }
     /* SPI mode: although card busy indication is based on the busy token,
      * SD spec recommends that the host checks the results of programming by sending
@@ -470,6 +477,7 @@ esp_err_t sdmmc_write_sectors_dma(sdmmc_card_t* card, const void* src,
     if (host_is_spi(card)) {
         err = sdmmc_send_cmd_send_status(card, &status);
         if (err != ESP_OK) {
+            ESP_LOGE(TAG, "%s: sdmmc_send_cmd_send_status returned 0x%x", __func__, err);
             return err;
         }
         if (status & SD_SPI_R2_CARD_LOCKED) {
@@ -551,15 +559,21 @@ esp_err_t sdmmc_read_sectors_dma(sdmmc_card_t* card, void* dst,
     }
     uint32_t status = 0;
     size_t count = 0;
+    int64_t t0 = esp_timer_get_time();
     while (!host_is_spi(card) && !(status & MMC_R1_READY_FOR_DATA)) {
-        // TODO: add some timeout here
+        if (esp_timer_get_time() - t0 > SDMMC_READY_FOR_DATA_TIMEOUT_US) {
+            ESP_LOGE(TAG, "read sectors dma - timeout");
+            return ESP_ERR_TIMEOUT;
+        }
         err = sdmmc_send_cmd_send_status(card, &status);
         if (err != ESP_OK) {
+            ESP_LOGE(TAG, "%s: sdmmc_send_cmd_send_status returned 0x%x", __func__, err);
             return err;
         }
         if (++count % 10 == 0) {
             ESP_LOGV(TAG, "waiting for card to become ready (%d)", count);
         }
+        vTaskDelay(1);
     }
     return ESP_OK;
 }
@@ -644,6 +658,7 @@ esp_err_t sdmmc_erase_sectors(sdmmc_card_t* card, size_t start_sector,
         uint32_t status;
         err = sdmmc_send_cmd_send_status(card, &status);
         if (err != ESP_OK) {
+            ESP_LOGE(TAG, "%s: sdmmc_send_cmd_send_status returned 0x%x", __func__, err);
             return err;
         }
         if (status != 0) {

components/sdmmc/sdmmc_common.h

@@ -30,6 +30,9 @@
 #define SDMMC_GO_IDLE_DELAY_MS              20
 #define SDMMC_IO_SEND_OP_COND_DELAY_MS      10
 
+#define SDMMC_INIT_WAIT_DATA_READY_TIMEOUT_US  5000 * 1000
+#define SDMMC_READY_FOR_DATA_TIMEOUT_US        5000 * 1000
+
 /* These delay values are mostly useful for cases when CD pin is not used, and
  * the card is removed. In this case, SDMMC peripheral may not always return
  * CMD_DONE / DATA_DONE interrupts after signaling the error. These timeouts work

components/sdmmc/sdmmc_io.c

@@ -321,6 +321,8 @@ esp_err_t sdmmc_io_read_bytes(sdmmc_card_t* card, uint32_t function,
         size_t size_aligned = size & (~3);
         size_t will_transfer = size_aligned > 0 ? size_aligned : size;
 
+        // Note: sdmmc_io_rw_extended has an internal timeout,
+        //  typically SDMMC_DEFAULT_CMD_TIMEOUT_MS
         esp_err_t err = sdmmc_io_rw_extended(card, function, addr,
                 SD_ARG_CMD53_READ | SD_ARG_CMD53_INCREMENT,
                 pc_dst, will_transfer);
@@ -344,6 +346,8 @@ esp_err_t sdmmc_io_write_bytes(sdmmc_card_t* card, uint32_t function,
         size_t size_aligned = size & (~3);
         size_t will_transfer = size_aligned > 0 ? size_aligned : size;
 
+        // Note: sdmmc_io_rw_extended has an internal timeout,
+        //  typically SDMMC_DEFAULT_CMD_TIMEOUT_MS
         esp_err_t err = sdmmc_io_rw_extended(card, function, addr,
                 SD_ARG_CMD53_WRITE | SD_ARG_CMD53_INCREMENT,
                 (void*) pc_src, will_transfer);

components/sdmmc/sdmmc_sd.c

@@ -15,6 +15,7 @@
  * OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
  */
 
+#include "esp_timer.h"
 #include "sdmmc_common.h"
 
 static const char* TAG = "sdmmc_sd";
@@ -138,8 +139,12 @@ esp_err_t sdmmc_init_sd_wait_data_ready(sdmmc_card_t* card)
     /* Wait for the card to be ready for data transfers */
     uint32_t status = 0;
     uint32_t count = 0;
+    int64_t t0 = esp_timer_get_time();
     while (!host_is_spi(card) && !(status & MMC_R1_READY_FOR_DATA)) {
-        // TODO: add some timeout here
+        if (esp_timer_get_time() - t0 > SDMMC_INIT_WAIT_DATA_READY_TIMEOUT_US) {
+            ESP_LOGE(TAG, "init wait data ready - timeout");
+            return ESP_ERR_TIMEOUT;
+        }
         esp_err_t err = sdmmc_send_cmd_send_status(card, &status);
         if (err != ESP_OK) {
             return err;
@@ -147,6 +152,7 @@ esp_err_t sdmmc_init_sd_wait_data_ready(sdmmc_card_t* card)
         if (++count % 16 == 0) {
             ESP_LOGV(TAG, "waiting for card to become ready (%d)", count);
         }
+        vTaskDelay(1);
     }
     return ESP_OK;
 }