search

espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.71k stars 7.3k forks source link

SDSPI Example not working properly (IDFGH-11213) #12379

Open dmglogowskiOS opened 1 year ago

dmglogowskiOS commented 1 year ago

Answers checklist.

General issue report

IDF Version

ESP-IDF v5.1.1-dirty

Operating System used

Docker Container under Windows

Project Build Type

Command Line -> Bash

Development Kit

Custom PCB

Power Supply used

Stepped down from 230V Mains via on board Transformers

Expected Behavior

Mounting the SD Card and writing to it

Actual Behavior

Upon running the example the following ouput occurs:


I (0) cpu_start: App cpu up.
I (228) cpu_start: Pro cpu start user code
I (228) cpu_start: cpu freq: 160000000 Hz
I (228) cpu_start: Application information:
I (231) cpu_start: Project name:     sd_card
I (236) cpu_start: App version:      v5.1.1-dirty
I (242) cpu_start: Compile time:     Oct 10 2023 13:05:25
I (248) cpu_start: ELF file SHA256:  59cd348f36d9b4f3...
I (254) cpu_start: ESP-IDF:          v5.1.1-dirty
I (259) cpu_start: Min chip rev:     v0.0
I (264) cpu_start: Max chip rev:     v0.99 
I (269) cpu_start: Chip rev:         v0.1
I (273) heap_init: Initializing. RAM available for dynamic allocation:
I (281) heap_init: At 3FC96560 len 000531B0 (332 KiB): DRAM
I (287) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
I (293) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (300) heap_init: At 600FE010 len 00001FD8 (7 KiB): RTCRAM
W (306) spi_flash: Octal flash chip is using but dio mode is selected, will automatically swich to Octal mode
I (317) spi_flash: detected chip: mxic (opi)
I (321) spi_flash: flash io: opi_str
W (326) spi_flash: Detected size(32768k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (339) sleep: Configure to isolate all GPIO pins in sleep state
I (346) sleep: Enable automatic switching of GPIO sleep configuration
I (353) app_start: Starting scheduler on CPU0
I (358) app_start: Starting scheduler on CPU1
I (358) main_task: Started on CPU0
I (368) main_task: Calling app_main()
I (368) example: Initializing SD card
I (378) example: Using SPI peripheral
I (378) example: Mounting filesystem
I (388) gpio: GPIO[7]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (438) sdspi_transaction: cmd=52, R1 response: command not supported
I (478) sdspi_transaction: cmd=5, R1 response: command not supported

Afterwards it hangs without any further info.

This behavior is observed when running various SD Cards, all of the same capacity (32GB, as that is all we have)

This issue does not occur with the example whilst running idf version 4.4.

Icarus113 commented 1 year ago

Which esp chip are you using?

dmglogowskiOS commented 1 year ago

ESP32S3

nopnop2002 commented 1 year ago

This README.md states that 10k PullUp is required for GPIO15 (MOSI). There were leaders that worked without PullUp resistance, and leaders that did not work without PullUp resistance.

https://github.com/espressif/esp-idf/tree/master/examples/storage/sd_card/sdspi

dmglogowskiOS commented 1 year ago

If that is the case, why would it work with IDF Version 4.4?

It is the same hardware.

But we can investigate that.

dmglogowskiOS commented 1 year ago

So, we added in PullUps for all traces (MISO, MOSI, SCLK, CS)

Behavior in idf version 4.4 stayed functional, with occasionally occurring timeouts. Behavior in idf version 5.1 had no change, the behavior is identical to the behavior originally described,

nopnop2002 commented 1 year ago

Behavior in idf version 4.4 stayed functional, with occasionally occurring timeouts.

MOSI only PullUp is required.

dmglogowskiOS commented 1 year ago

We have a PullUp on the MOSI and according to the Documentation it is supposed to be on all pins.

However, after some further attempts, and removing the only other device on that SPI Bus, we were able to get a different Error under idf version 5.1, which is at least somewhat encouraging.

I (378) example: Mounting filesystem
I (388) gpio: GPIO[7]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (398) sdspi_transaction: cmd=52, R1 response: command CRC error
E (398) sdmmc_io: sdmmc_io_reset: unexpected return: 0x109
E (408) vfs_fat_sdmmc: sdmmc_card_init failed (0x109).
I (408) gpio: GPIO[7]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
E (418) example: Failed to initialize the card (ESP_ERR_INVALID_CRC). Make sure SD card lines have pull-up resistors in place.
I (438) main_task: Returned from app_main()
dmglogowskiOS commented 1 year ago

We removed all the Pull Ups Except for the MOSI, the behavior did not change aside from totally removing the CRC failure and returning completely to the original behavior.

We decided to use a logic analyzer to see if the signals might be problematic and these are the results:

image image image image All of this is followed by 20 instances of this: image And ending on these: image image image

We are confused by the seemingly unneeded, and uncommanded, clocking (seen on the D0 line) without the CS being active (D1 line) but with Activity on the MISO line (D2)...

nopnop2002 commented 1 year ago

my environment:

$ idf.py --version
ESP-IDF v5.1.1-229-ga9aea676e7-dirty

I used this. https://github.com/espressif/esp-idf/tree/master/examples/storage/sd_card/sdspi

This is my log. CS connect to GPIO34.

I (0) cpu_start: App cpu up.
I (206) cpu_start: Pro cpu start user code
I (206) cpu_start: cpu freq: 160000000 Hz
I (206) cpu_start: Application information:
I (209) cpu_start: Project name:     sd_card
I (214) cpu_start: App version:      v5.1.1-229-ga9aea676e7-dirty
I (221) cpu_start: Compile time:     Oct 27 2023 09:25:26
I (227) cpu_start: ELF file SHA256:  fc207b6ee82e6d32...
I (233) cpu_start: ESP-IDF:          v5.1.1-229-ga9aea676e7-dirty
I (240) cpu_start: Min chip rev:     v0.0
I (244) cpu_start: Max chip rev:     v0.99
I (249) cpu_start: Chip rev:         v0.1
I (254) heap_init: Initializing. RAM available for dynamic allocation:
I (261) heap_init: At 3FC96540 len 000531D0 (332 KiB): DRAM
I (267) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
I (274) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (280) heap_init: At 600FE010 len 00001FD8 (7 KiB): RTCRAM
I (287) spi_flash: detected chip: gd
I (291) spi_flash: flash io: dio
W (295) spi_flash: Detected size(8192k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (308) sleep: Configure to isolate all GPIO pins in sleep state
I (315) sleep: Enable automatic switching of GPIO sleep configuration
I (322) app_start: Starting scheduler on CPU0
I (327) app_start: Starting scheduler on CPU1
I (327) main_task: Started on CPU0
I (337) main_task: Calling app_main()
I (337) example: Initializing SD card
I (347) example: Using SPI peripheral
I (347) example: Mounting filesystem
I (357) gpio: GPIO[34]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (367) sdspi_transaction: cmd=52, R1 response: command not supported
I (417) sdspi_transaction: cmd=5, R1 response: command not supported
I (457) example: Filesystem mounted
Name: SL32G
Type: SDHC/SDXC
Speed: 20.00 MHz (limit: 20.00 MHz)
Size: 30436MB
CSD: ver=2, sector_size=512, capacity=62333952 read_bl_len=9
SSR: bus_width=1

E (398) sdmmc_io: sdmmc_io_reset: unexpected return: 0x109

This error has been reported several times in the past. This error can be resolved by either:

dmglogowskiOS commented 1 year ago

Alright so:

What we can confirm tho is this:

load:0x403c9700,len:0x4 load:0x403c9704,len:0xc00 load:0x403cc700,len:0x2eb0 entry 0x403c9908 I (33) boot: ESP-IDF v5.1.1-dirty 2nd stage bootloader I (33) boot: compile time Oct 10 2023 13:05:33 I (34) boot: Multicore bootloader I (37) boot: chip revision: v0.1 I (41) boot.esp32s3: Boot SPI Speed : 80MHz I (45) boot.esp32s3: SPI Mode : SLOW READ I (51) boot.esp32s3: SPI Flash Size : 2MB I (55) boot: Enabling RNG early entropy source... I (61) boot: Partition Table: I (64) boot: ## Label Usage Type ST Offset Length I (72) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (79) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (87) boot: 2 factory factory app 00 00 00010000 00100000 I (94) boot: End of partition table I (98) esp_image: segment 0: paddr=00010020 vaddr=3c030020 size=0e820h ( 59424) map I (121) esp_image: segment 1: paddr=0001e848 vaddr=3fc93300 size=017d0h ( 6096) load I (123) esp_image: segment 2: paddr=00020020 vaddr=42000020 size=2b768h (178024) map I (169) esp_image: segment 3: paddr=0004b790 vaddr=3fc94ad0 size=011ach ( 4524) load I (171) esp_image: segment 4: paddr=0004c944 vaddr=40374000 size=0f258h ( 62040) load I (198) boot: Loaded app from partition at offset 0x10000 I (199) boot: Disabling RNG early entropy source... I (210) cpu_start: Multicore app I (210) cpu_start: Pro cpu up. I (210) cpu_start: Starting app cpu, entry point is 0x40375370 0x40375370: call_start_cpu1 at /opt/esp/idf/components/esp_system/port/cpu_start.c:154

I (0) cpu_start: App cpu up. I (228) cpu_start: Pro cpu start user code I (228) cpu_start: cpu freq: 160000000 Hz I (228) cpu_start: Application information: I (231) cpu_start: Project name: sd_card I (236) cpu_start: App version: v5.1.1-dirty I (241) cpu_start: Compile time: Oct 10 2023 13:05:25 I (248) cpu_start: ELF file SHA256: 708add7741626192... I (254) cpu_start: ESP-IDF: v5.1.1-dirty I (259) cpu_start: Min chip rev: v0.0 I (264) cpu_start: Max chip rev: v0.99 I (268) cpu_start: Chip rev: v0.1 I (273) heap_init: Initializing. RAM available for dynamic allocation: I (280) heap_init: At 3FC96560 len 000531B0 (332 KiB): DRAM I (287) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM I (293) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM I (299) heap_init: At 600FE010 len 00001FD8 (7 KiB): RTCRAM W (306) spi_flash: Octal flash chip is using but dio mode is selected, will automatically swich to Octal mode I (316) spi_flash: detected chip: mxic (opi) I (321) spi_flash: flash io: opi_str W (326) spi_flash: Detected size(32768k) larger than the size in the binary image header(2048k). Using the size in the binary image header. I (339) sleep: Configure to isolate all GPIO pins in sleep state I (346) sleep: Enable automatic switching of GPIO sleep configuration I (353) app_start: Starting scheduler on CPU0 I (358) app_start: Starting scheduler on CPU1 I (358) main_task: Started on CPU0 I (368) main_task: Calling app_main() I (368) example: Initializing SD card I (378) example: Using SPI peripheral I (378) example: Mounting filesystem I (388) gpio: GPIO[7]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 I (438) sdspi_transaction: cmd=5, R1 response: command not supported E (1438) sdmmc_common: sdmmc_init_ocr: send_op_cond (1) returned 0x107 E (1438) vfs_fat_sdmmc: sdmmc_card_init failed (0x107). I (1438) gpio: GPIO[7]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 E (1448) example: Failed to initialize the card (ESP_ERR_TIMEOUT). Make sure SD card lines have pull-up resistors in place. I (1458) main_task: Returned from app_main()



- We can observe this reproducably

![image](https://github.com/espressif/esp-idf/assets/135589766/9216c81d-1c6e-4875-80ce-bebf9240a2db)

- We know the Power Supply is stable
- TVS Diodes(D20) is 5V(No measurable signal distortion)
- The only difference between the schematic and the real world board is the 10kOhm resistor on CMD and DAT0 through 3, as described in the IDF Documentation
nopnop2002 commented 1 year ago

This is the only difference I can tell.

I (233) cpu_start: ESP-IDF:          v5.1.1-229-ga9aea676e7-dirty
I (254) cpu_start: ESP-IDF:          v5.1.1-dirty

I (357) gpio: GPIO[34]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (388) gpio: GPIO[7]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
dmglogowskiOS commented 1 year ago

We are genuinely stumped.

The error persists throughout all the versions of 5.X we tested:

We can't seem to track down v5.1.1-229-ga9aea676e7-dirty but honestly, we aren't willing to invest significantly more time into trying to find a version of v5.1.1 that works, when the error could still well be hardware related....

nopnop2002 commented 1 year ago

Although it may not apply to this case, there have been cases in the past where the GPIO mark on the ESP32 board was different from the actual one.

I connected all GPIOs and LEDs and changed them to the correct markings.

dmglogowskiOS commented 1 year ago

I doubt that is the case here at all as we run our own custom board with an ESP32-S3-WROOM-2 Module.

dmglogowskiOS commented 1 year ago

Alright so, we decided to dig deep into the sdmmc lib and traced the ESP_ERR_TIMEOUT occuring into the sdmmc_send_cmd_send_op_cond Function in the sdmmc_cmd.c file. This is likely intended behavior, however we would like to understand this a bit better, therefore we added in a bunch of Log Statemens:

esp_err_t sdmmc_send_cmd_send_op_cond(sdmmc_card_t* card, uint32_t ocr, uint32_t *ocrp)
{
    esp_err_t err;

    /* If the host supports this, keep card clock enabled
     * from the start of ACMD41 until the card is idle.
     * (Ref. SD spec, section 4.4 "Clock control".)
     */
    if (card->host.set_cclk_always_on != NULL) {
        ESP_LOGE(TAG, "host.set_cclk_always_on != NULL");
        err = card->host.set_cclk_always_on(card->host.slot, true);
        if (err != ESP_OK) {
            ESP_LOGE(TAG, "%s: set_cclk_always_on (1) err=0x%x", __func__, err);
            return err;
        }
        ESP_LOGV(TAG, "%s: keeping clock on during ACMD41", __func__);
    }

    sdmmc_command_t cmd = {
            .arg = ocr,
            .flags = SCF_CMD_BCR | SCF_RSP_R3,
            .opcode = SD_APP_OP_COND
    };
    int nretries = SDMMC_SEND_OP_COND_MAX_RETRIES;
    int err_cnt = SDMMC_SEND_OP_COND_MAX_ERRORS;
    for (; nretries != 0; --nretries)  {
        ESP_LOGE(TAG, "Retry Num : %i", nretries);
        bzero(&cmd, sizeof cmd);
        cmd.arg = ocr;
        cmd.flags = SCF_CMD_BCR | SCF_RSP_R3;
        if (!card->is_mmc) { /* SD mode */
            ESP_LOGE(TAG, "Card is SD");
            cmd.opcode = SD_APP_OP_COND;
            err = sdmmc_send_app_cmd(card, &cmd);
        } else { /* MMC mode */
            cmd.arg &= ~MMC_OCR_ACCESS_MODE_MASK;
            cmd.arg |= MMC_OCR_SECTOR_MODE;
            cmd.opcode = MMC_SEND_OP_COND;
            err = sdmmc_send_cmd(card, &cmd);
        }

        if (err != ESP_OK) {
            if (--err_cnt == 0) {
                ESP_LOGE(TAG, "%s: sdmmc_send_app_cmd err=0x%x", __func__, err);
                goto done;
            } else {
                ESP_LOGE(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.
        if (!host_is_spi(card)) {
            if ((MMC_R3(cmd.response) & MMC_OCR_MEM_READY) ||
                ocr == 0) {
                break;
            }
        } else {
            if ((SD_SPI_R1(cmd.response) & SD_SPI_R1_IDLE_STATE) == 0) {
                break;
            }
        }
        vTaskDelay(10 / portTICK_PERIOD_MS);
    }
    ESP_LOGE(TAG, "After Retries, Error : 0x%X", err);

    if (nretries == 0) {
        ESP_LOGE(TAG, "ESP_ERR_TIMOUT in %s", __func__ );
        err = ESP_ERR_TIMEOUT;
        goto done;
    }

    if (ocrp) {
        *ocrp = MMC_R3(cmd.response);
    }

    err = ESP_OK;
done:

    if (card->host.set_cclk_always_on != NULL) {
        esp_err_t err_cclk_dis = card->host.set_cclk_always_on(card->host.slot, false);
        if (err_cclk_dis != ESP_OK) {
            ESP_LOGE(TAG, "%s: set_cclk_always_on (2) err=0x%x", __func__, err);
            /* If we failed to disable clock, don't overwrite 'err' to return the original error */
        }
        ESP_LOGV(TAG, "%s: clock always-on mode disabled", __func__);
    }

    return err;
}

And this is the resulting output:

I (362) app_start: Starting scheduler on CPU1
I (362) main_task: Started on CPU0
I (372) main_task: Calling app_main()
I (372) example: Initializing SD card
I (382) example: Using SPI peripheral
I (382) example: Mounting filesystem
I (392) gpio: GPIO[7]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (402) sdspi_transaction: cmd=52, R1 response: command not supported
I (442) sdspi_transaction: cmd=5, R1 response: command not supported
E (442) sdmmc_cmd: Retry Num : 100
E (442) sdmmc_cmd: Card is SD
E (452) sdmmc_cmd: Retry Num : 99
E (452) sdmmc_cmd: Card is SD
E (462) sdmmc_cmd: Retry Num : 98
E (462) sdmmc_cmd: Card is SD
E (472) sdmmc_cmd: Retry Num : 97
E (472) sdmmc_cmd: Card is SD
E (482) sdmmc_cmd: Retry Num : 96
E (482) sdmmc_cmd: Card is SD
E (492) sdmmc_cmd: Retry Num : 95
E (492) sdmmc_cmd: Card is SD
E (502) sdmmc_cmd: Retry Num : 94
E (502) sdmmc_cmd: Card is SD
E (512) sdmmc_cmd: Retry Num : 93
E (512) sdmmc_cmd: Card is SD
E (522) sdmmc_cmd: Retry Num : 92
E (522) sdmmc_cmd: Card is SD
E (532) sdmmc_cmd: Retry Num : 91
E (532) sdmmc_cmd: Card is SD
E (542) sdmmc_cmd: Retry Num : 90
E (542) sdmmc_cmd: Card is SD
E (552) sdmmc_cmd: Retry Num : 89
E (552) sdmmc_cmd: Card is SD
E (562) sdmmc_cmd: Retry Num : 88
E (562) sdmmc_cmd: Card is SD
E (572) sdmmc_cmd: Retry Num : 87
E (572) sdmmc_cmd: Card is SD
E (582) sdmmc_cmd: Retry Num : 86
E (582) sdmmc_cmd: Card is SD
E (592) sdmmc_cmd: Retry Num : 85
E (592) sdmmc_cmd: Card is SD
E (602) sdmmc_cmd: Retry Num : 84
E (602) sdmmc_cmd: Card is SD
E (612) sdmmc_cmd: Retry Num : 83
E (612) sdmmc_cmd: Card is SD
E (622) sdmmc_cmd: Retry Num : 82
E (622) sdmmc_cmd: Card is SD
E (632) sdmmc_cmd: Retry Num : 81
E (632) sdmmc_cmd: Card is SD
E (642) sdmmc_cmd: Retry Num : 80
E (642) sdmmc_cmd: Card is SD
E (652) sdmmc_cmd: Retry Num : 79
E (652) sdmmc_cmd: Card is SD
E (662) sdmmc_cmd: Retry Num : 78
E (662) sdmmc_cmd: Card is SD
E (672) sdmmc_cmd: Retry Num : 77
E (672) sdmmc_cmd: Card is SD
E (682) sdmmc_cmd: Retry Num : 76
E (682) sdmmc_cmd: Card is SD
E (692) sdmmc_cmd: Retry Num : 75
E (692) sdmmc_cmd: Card is SD
E (702) sdmmc_cmd: Retry Num : 74
E (702) sdmmc_cmd: Card is SD
E (712) sdmmc_cmd: Retry Num : 73
E (712) sdmmc_cmd: Card is SD
E (722) sdmmc_cmd: Retry Num : 72
E (722) sdmmc_cmd: Card is SD
E (732) sdmmc_cmd: Retry Num : 71
E (732) sdmmc_cmd: Card is SD
E (742) sdmmc_cmd: Retry Num : 70
E (742) sdmmc_cmd: Card is SD
E (752) sdmmc_cmd: Retry Num : 69
E (752) sdmmc_cmd: Card is SD
E (762) sdmmc_cmd: Retry Num : 68
E (762) sdmmc_cmd: Card is SD
E (772) sdmmc_cmd: Retry Num : 67
E (772) sdmmc_cmd: Card is SD
E (782) sdmmc_cmd: Retry Num : 66
E (782) sdmmc_cmd: Card is SD
E (792) sdmmc_cmd: Retry Num : 65
E (792) sdmmc_cmd: Card is SD
E (802) sdmmc_cmd: Retry Num : 64
E (802) sdmmc_cmd: Card is SD
E (812) sdmmc_cmd: Retry Num : 63
E (812) sdmmc_cmd: Card is SD
E (822) sdmmc_cmd: Retry Num : 62
E (822) sdmmc_cmd: Card is SD
E (832) sdmmc_cmd: Retry Num : 61
E (832) sdmmc_cmd: Card is SD
E (842) sdmmc_cmd: Retry Num : 60
E (842) sdmmc_cmd: Card is SD
E (852) sdmmc_cmd: Retry Num : 59
E (852) sdmmc_cmd: Card is SD
E (862) sdmmc_cmd: Retry Num : 58
E (862) sdmmc_cmd: Card is SD
E (872) sdmmc_cmd: Retry Num : 57
E (872) sdmmc_cmd: Card is SD
E (882) sdmmc_cmd: Retry Num : 56
E (882) sdmmc_cmd: Card is SD
E (892) sdmmc_cmd: Retry Num : 55
E (892) sdmmc_cmd: Card is SD
E (902) sdmmc_cmd: Retry Num : 54
E (902) sdmmc_cmd: Card is SD
E (912) sdmmc_cmd: Retry Num : 53
E (912) sdmmc_cmd: Card is SD
E (922) sdmmc_cmd: Retry Num : 52
E (922) sdmmc_cmd: Card is SD
E (932) sdmmc_cmd: Retry Num : 51
E (932) sdmmc_cmd: Card is SD
E (942) sdmmc_cmd: Retry Num : 50
E (942) sdmmc_cmd: Card is SD
E (952) sdmmc_cmd: Retry Num : 49
E (952) sdmmc_cmd: Card is SD
E (962) sdmmc_cmd: Retry Num : 48
E (962) sdmmc_cmd: Card is SD
E (972) sdmmc_cmd: Retry Num : 47
E (972) sdmmc_cmd: Card is SD
E (982) sdmmc_cmd: Retry Num : 46
E (982) sdmmc_cmd: Card is SD
E (992) sdmmc_cmd: Retry Num : 45
E (992) sdmmc_cmd: Card is SD
E (1002) sdmmc_cmd: Retry Num : 44
E (1002) sdmmc_cmd: Card is SD
E (1012) sdmmc_cmd: Retry Num : 43
E (1012) sdmmc_cmd: Card is SD
E (1022) sdmmc_cmd: Retry Num : 42
E (1022) sdmmc_cmd: Card is SD
E (1032) sdmmc_cmd: Retry Num : 41
E (1032) sdmmc_cmd: Card is SD
E (1042) sdmmc_cmd: Retry Num : 40
E (1042) sdmmc_cmd: Card is SD
E (1052) sdmmc_cmd: Retry Num : 39
E (1052) sdmmc_cmd: Card is SD
E (1062) sdmmc_cmd: Retry Num : 38
E (1062) sdmmc_cmd: Card is SD
E (1072) sdmmc_cmd: Retry Num : 37
E (1072) sdmmc_cmd: Card is SD
E (1082) sdmmc_cmd: Retry Num : 36
E (1082) sdmmc_cmd: Card is SD
E (1092) sdmmc_cmd: Retry Num : 35
E (1092) sdmmc_cmd: Card is SD
E (1102) sdmmc_cmd: Retry Num : 34
E (1102) sdmmc_cmd: Card is SD
E (1112) sdmmc_cmd: Retry Num : 33
E (1112) sdmmc_cmd: Card is SD
E (1122) sdmmc_cmd: Retry Num : 32
E (1122) sdmmc_cmd: Card is SD
E (1132) sdmmc_cmd: Retry Num : 31
E (1132) sdmmc_cmd: Card is SD
E (1142) sdmmc_cmd: Retry Num : 30
E (1142) sdmmc_cmd: Card is SD
E (1152) sdmmc_cmd: Retry Num : 29
E (1152) sdmmc_cmd: Card is SD
E (1162) sdmmc_cmd: Retry Num : 28
E (1162) sdmmc_cmd: Card is SD
E (1172) sdmmc_cmd: Retry Num : 27
E (1172) sdmmc_cmd: Card is SD
E (1182) sdmmc_cmd: Retry Num : 26
E (1182) sdmmc_cmd: Card is SD
E (1192) sdmmc_cmd: Retry Num : 25
E (1192) sdmmc_cmd: Card is SD
E (1202) sdmmc_cmd: Retry Num : 24
E (1202) sdmmc_cmd: Card is SD
E (1212) sdmmc_cmd: Retry Num : 23
E (1212) sdmmc_cmd: Card is SD
E (1222) sdmmc_cmd: Retry Num : 22
E (1222) sdmmc_cmd: Card is SD
E (1232) sdmmc_cmd: Retry Num : 21
E (1232) sdmmc_cmd: Card is SD
E (1242) sdmmc_cmd: Retry Num : 20
E (1242) sdmmc_cmd: Card is SD
E (1252) sdmmc_cmd: Retry Num : 19
E (1252) sdmmc_cmd: Card is SD
E (1262) sdmmc_cmd: Retry Num : 18
E (1262) sdmmc_cmd: Card is SD
E (1272) sdmmc_cmd: Retry Num : 17
E (1272) sdmmc_cmd: Card is SD
E (1282) sdmmc_cmd: Retry Num : 16
E (1282) sdmmc_cmd: Card is SD
E (1292) sdmmc_cmd: Retry Num : 15
E (1292) sdmmc_cmd: Card is SD
E (1302) sdmmc_cmd: Retry Num : 14
E (1302) sdmmc_cmd: Card is SD
E (1312) sdmmc_cmd: Retry Num : 13
E (1312) sdmmc_cmd: Card is SD
E (1322) sdmmc_cmd: Retry Num : 12
E (1322) sdmmc_cmd: Card is SD
E (1332) sdmmc_cmd: Retry Num : 11
E (1332) sdmmc_cmd: Card is SD
E (1342) sdmmc_cmd: Retry Num : 10
E (1342) sdmmc_cmd: Card is SD
E (1352) sdmmc_cmd: Retry Num : 9
E (1352) sdmmc_cmd: Card is SD
E (1362) sdmmc_cmd: Retry Num : 8
E (1362) sdmmc_cmd: Card is SD
E (1372) sdmmc_cmd: Retry Num : 7
E (1372) sdmmc_cmd: Card is SD
E (1382) sdmmc_cmd: Retry Num : 6
E (1382) sdmmc_cmd: Card is SD
E (1392) sdmmc_cmd: Retry Num : 5
E (1392) sdmmc_cmd: Card is SD
E (1402) sdmmc_cmd: Retry Num : 4
E (1402) sdmmc_cmd: Card is SD
E (1412) sdmmc_cmd: Retry Num : 3
E (1412) sdmmc_cmd: Card is SD
E (1422) sdmmc_cmd: Retry Num : 2
E (1422) sdmmc_cmd: Card is SD
E (1432) sdmmc_cmd: Retry Num : 1
E (1432) sdmmc_cmd: Card is SD
E (1442) sdmmc_cmd: After Retries, Error : 0x0
E (1442) sdmmc_cmd: ESP_ERR_TIMOUT in sdmmc_send_cmd_send_op_cond
E (1442) sdmmc_common: sdmmc_init_ocr: send_op_cond (1) returned 0x107
E (1442) vfs_fat_sdmmc: sdmmc_card_init failed (0x107).
I (1452) gpio: GPIO[7]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
E (1462) example: Failed to initialize the card (ESP_ERR_TIMEOUT). Make sure SD card lines have pull-up resistors in place.
I (1472) main_task: Returned from app_main()

Mind you, this behaviour only occurs with the SL32G SD card, the Adata cards hang immedietly and irrecoverably.

igrr commented 1 year ago

Since you are using ESP32-S3-WROOM-2, one thing to check: you aren't using GPIO47 and GPIO48 for the SPI bus, right?

dmglogowskiOS commented 1 year ago

No that SPI Bus uses GPIO17, 18 and 8 for MOSI, MISO and SCLK respectively.

nopnop2002 commented 1 year ago

No that SPI Bus uses GPIO17, 18 and 8 for MOSI, MISO and SCLK respectively.

There is no problem with this GPIO.

CS's GPIO7 probably doesn't work properly.

dmglogowskiOS commented 1 year ago

CS's GPIO7 probably doesn't work properly.

Why would that be the case?

nopnop2002 commented 1 year ago

I connected GPIO17, 18, and 8 for MOSI, MISO, and SCLK.

And I changed the CS as follows.

I don't know why.

I found that an error occurs with certain SD-CARDs.

SDSPI-NONAME SDSPI-APPSD SDSPI-SA08G SDSPI-SD16G SDSPI-SL08G SDSPI-SL32G

dmglogowskiOS commented 1 year ago

That is certainly valuable information, for both future potential SD Cards to use and the potential pins we might want to use for the SD Card slot...

This however still makes me wonder, why do some SD Cards behave differently? Are there some weird vendor specifics that aren't working correctly with esp-idf?

It also makes me wonder what the breaking change was between idf v4.4 and 5.1.1 to cause the GPIO7 pin to not work correctly as a CS.

We might have to redesign part of the board, as we can't just move it to a different GPIO except for maybe a strapping pin.

We know it works with the SDMMC driver, however using that might cause an issue as we have an ethernet controller (W5500) on the same bus... can SDMMC and SPI Master run in paralell?

nopnop2002 commented 1 year ago

Are there some weird vendor specifics that aren't working correctly with esp-idf?

The current consumption of the SD-CARD may have an effect. Previously, in another project, I encountered a problem due to the current consumption of a specific SD-CARD.

however using that might cause an issue as we have an ethernet controller (W5500) on the same bus

This might help. https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-reference/peripherals/sdspi_share.html

can SDMMC and SPI Master run in paralell?

I have not tried it, but I think it would be difficult to operate SDMMC and SPI-MASTER on the same SPI-BUS.

dmglogowskiOS commented 1 year ago

In the mean time we tried using GPIO0, as that is one of the very few pins we don't actively use, and while the CS did trigger correctly the same timeout behavior occured while using that one:

I (381) example: Using SPI peripheral
I (381) example: Mounting filesystem
I (391) gpio: GPIO[0]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (401) sdspi_transaction: cmd=52, R1 response: command not supported
I (441) sdspi_transaction: cmd=5, R1 response: command not supported
E (1441) sdmmc_common: sdmmc_init_ocr: send_op_cond (1) returned 0x107
E (1441) vfs_fat_sdmmc: sdmmc_card_init failed (0x107).
I (1441) gpio: GPIO[0]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
E (1451) example: Failed to initialize the card (ESP_ERR_TIMEOUT). Make sure SD card lines have pull-up resistors in place.
I (1461) main_task: Returned from app_main()

The same behavior was also observable on GPIO38. We also captured this on our scope: DS1Z_QuickPrint1 This looks normal, as the rapid retries are about 1 every 10ms and that 100 times.

This also applies to GPIO39. We believe it is an issue with the SDSPI driver or maybe the drive strength of those pins?

dmglogowskiOS commented 1 year ago

Could you try running a configuration that worked for SDSPI with v5.1.1-229-ga9aea676e7-dirty on the 5.1.1 version that is most recent? @nopnop2002

nopnop2002 commented 1 year ago 
$ idf.py --version
ESP-IDF v5.1.1
I (0) cpu_start: App cpu up.
I (204) cpu_start: Pro cpu start user code
I (204) cpu_start: cpu freq: 160000000 Hz
I (204) cpu_start: Application information:
I (207) cpu_start: Project name:     sd_card
I (212) cpu_start: App version:      v5.1.1
I (217) cpu_start: Compile time:     Oct 31 2023 04:38:51
I (223) cpu_start: ELF file SHA256:  8541526641380c21...
I (229) cpu_start: ESP-IDF:          v5.1.1
I (234) cpu_start: Min chip rev:     v0.0
I (239) cpu_start: Max chip rev:     v0.99
I (243) cpu_start: Chip rev:         v0.1
I (248) heap_init: Initializing. RAM available for dynamic allocation:
I (255) heap_init: At 3FC96540 len 000531D0 (332 KiB): DRAM
I (262) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
I (268) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (274) heap_init: At 600FE010 len 00001FD8 (7 KiB): RTCRAM
I (282) spi_flash: detected chip: gd
I (285) spi_flash: flash io: dio
W (289) spi_flash: Detected size(8192k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (302) sleep: Configure to isolate all GPIO pins in sleep state
I (309) sleep: Enable automatic switching of GPIO sleep configuration
I (316) app_start: Starting scheduler on CPU0
I (321) app_start: Starting scheduler on CPU1
I (321) main_task: Started on CPU0
I (331) main_task: Calling app_main()
I (331) example: Initializing SD card
I (341) example: Using SPI peripheral
I (341) example: Mounting filesystem
I (351) gpio: GPIO[34]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (361) sdspi_transaction: cmd=52, R1 response: command not supported
I (401) sdspi_transaction: cmd=5, R1 response: command not supported
I (421) example: Filesystem mounted
Name: SD16G
Type: SDHC/SDXC
Speed: 20.00 MHz (limit: 20.00 MHz)
Size: 14804MB
CSD: ver=2, sector_size=512, capacity=30318592 read_bl_len=9
SSR: bus_width=1
I (421) example: Opening file /sdcard/hello.txt
I (461) example: File written
I (461) example: Renaming file /sdcard/hello.txt to /sdcard/foo.txt
I (471) example: Reading file /sdcard/foo.txt
I (471) example: Read from file: 'Hello SD16G!'
I (471) vfs_fat_sdmmc: Formatting card, allocation unit size=16384
I (6781) example: file doesnt exist, format done
I (6781) example: Opening file /sdcard/nihao.txt
I (6791) example: File written
I (6791) example: Reading file /sdcard/nihao.txt
I (6801) example: Read from file: 'Nihao SD16G!'
I (6801) gpio: GPIO[34]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (6811) example: Card unmounted
I (6811) gpio: GPIO[17]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (6821) gpio: GPIO[18]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (6831) gpio: GPIO[8]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (6841) main_task: Returned from app_main()
ginkgm commented 12 months ago

Seeing from the schematic you provided, not all data pins of the card are correctly pulled up, are they?

I mean ALL except clock, including unused pins, DAT1 and DAT2.

SD physical layer specification v3.0.1 chapter 6 have requirement for this. And it clearly states that this also applies for SPI mode. Violating this rule may cause unpredictable behavior, including CRC error or timeout. Cards' behavior may relates to model and vendor of the card. (Sorry because the spec is not public, I can't paste it here)

Suggest to make everything compliant to the spec to reduce waste of time.

And regarding to the PCB design, not only short cables are required, low impedance are also required. Not only for the data lines, but also for grounding. Jumping wires are very likely to cause unstable communications. It's highly recommended to provide grounding plate instead of grounding wire between ESP32 and the card.

dmglogowskiOS commented 12 months ago

Seeing from the schematic you provided, not all data pins of the card are correctly pulled up, are they?

I mean ALL except clock, including unused pins, DAT1 and DAT2.

SD physical layer specification v3.0.1 chapter 6 have requirement for this. And it clearly states that this also applies for SPI mode. Violating this rule may cause unpredictable behavior, including CRC error or timeout. Cards' behavior may relates to model and vendor of the card. (Sorry because the spec is not public, I can't paste it here)

We tried this on our board and it didn't make a difference, we haven't set up a seperate test board to test it in isolation yet, however the only device it shares the bus with has been physically disabled. However if it really is a proper Hardware Issue, it shouldn't work at all from what I can gather, even with sdmmc, however sdmmc does work with our setup.

Also the older Driver from v4.4 works, which also shouldn't be the case if there was an issue with the hardware.

And regarding to the PCB design, not only short cables are required, low impedance are also required. Not only for the data lines, but also for grounding. Jumping wires are very likely to cause unstable communications. It's highly recommended to provide grounding plate instead of grounding wire between ESP32 and the card.

This shouldn't be an issue on our PCB, the distance is only about 8cm of copper traces between the µc and the SD Card Slot, with a common ground plate between them, and every other low voltage device on that board.

dmglogowskiOS commented 12 months ago

We attempted it using an ESP32-S3-Korvo-2 Board where we simply soldered a CS Wire to GPIO3 and attempted using it with idf v.5.1.1 and the same behavior persisted, it worked using sdmmc, just like the custom board.

1000016021 The modified Corvo Board

As sdmmc and sdspi are electrically identical, except for the lack of a CS on sdmmc, we conclude that there is likely an issue in the currently available versions of IDF v5.1.1, we do not know why it seems that nopnop is unable to replicate it unless using GPIO7 as a CS however.

It seems likely that we have to redesign our custom board unless this issue is fixed.

nopnop2002 commented 11 months ago

@dmglogowskiOS

I'm not sure if this has anything to do with your problem.

https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-reference/peripherals/sd_pullup_requirements.html

dmglogowskiOS commented 11 months ago

@nopnop2002

We are pretty sure that isn't the issue as we have already added the necessary pullups and checked and rechecked their connection multiple times.

However we would like to know what dev board(s) you use to test so we can attempt to replicate your results.

nopnop2002 commented 11 months ago

This is my development board and card reader.

IMG_4903 IMG_4906

dmglogowskiOS commented 10 months ago

We decided to not use SD-SPI due to this issue and instead choose to use SD-MMC.

We will have to painstakingly modify more than a dozen Prototypes, but it is what it is I guess...

RathiSonika commented 10 months ago

Hello @dmglogowskiOS, Could you test below patch to inspect the pull-up connections and SD pin connections on your board? Apply the patch to idf version 5.1.1 and please confirm its effectiveness in debugging SD connections. sd_card-built-in-checks-for-sd-connections-to-v5.1.1.patch

JaimeAlbq commented 5 months ago

I'm facing the same issue.

Do you have any plan to release a fix for it?

I tried to use it with the following boards:

I am using a MicroSD CardAdapter like the following: image

I am using the PlatfmorIO.

I already tried to pull-up all pins, just MOSI, and I got just one of those two errors: ESP_ERR_INVALID_CRC or ESP_ERR_TIMEOUT.

The GPIOs used was: 12, 13, 15 and 2 in all possible configurations.

The Serial Clock was set to 400kHz.

One more thing: I already tried to bypass the CRC when I got the error ESP_ERR_INVALID_CRC into thefunction sdmmc_init_spi_crc(sdmmc_card_t* card), which can be found into the file sdmmc_sd.c.

Please, if there are any test which I can perform feel free to request me.

dmglogowskiOS commented 5 months ago

Sadly I haven't been able to test the patch @ RathiSonika provided yet, I have been too busy with more important work and we switched to using SDMMC rather than SDSPI for our project since SDMMC worked better at the time.

We probably won't be able to test the patch for a while still as we are working on other fundamental parts of our project that don't yet require access to the SD-Card for functionality.

nopnop2002 commented 5 months ago

@JaimeAlbq

I am using the PlatfmorIO.

The ESP-IDF provided by PlatfmorIO may not be exactly the same as the IDF provided by espressif.

JaimeAlbq commented 5 months ago

@nopnop2002

The ESP-IDF provided by PlatfmorIO may not be exactly the same as the IDF provided by espressif.

The PlatformIO which I use has the v5.1.2 of ESP-IDF, as you can see the release 6.7.0.

igrr commented 5 months ago

The issue has been fixed on release/v5.1 in https://github.com/espressif/esp-idf/commit/7ff2886c840653c2bee932c04741f4d5b4f181b2 and the subsequent commit. The fix was recently released in v5.1.4.