_cmd() hangs waiting for 0xfe after large write

[dhalbert]

This forum thread provoked this issue: https://forums.adafruit.com/viewtopic.php?f=60&t=141707. The poster had this problem with all the SD cards they tried and I had trouble with the one I tried as well. The failures are not consistently at the same place across different cards or even multiple trials, so it appears to be timing-related (probably due to something the SD card is doing).

After the second or so writeblocks() of a 7168-byte buffer, a readblocks() follows, which calls
_cmd(12, wait=False). This hangs in _cmd() in the loop below; it never receives a 0xfe.

                            # Wait for the start block byte
                            while buf[1] != 0xfe:
                                spi.readinto(buf, start=1, end=2, write_value=0xff)

I tried setting wait=True and it made no difference.

Attached is an instrumented version of adafruit_sdcard.py, which produces the output below. Notice that a 0x7 is received first, which doesn't show up anywhere else, followed by 0xff indefinitely. Also attached is the test program (test.py).
adafruit_sdcard.py.txt
test.py.txt

Output:

>>> import test




waiting for 0xfe 0x0 
readblocks 512
waiting for 0xfe 0x0 0xff 
readblocks 512
waiting for 0xfe 0x0 0xff 
readblocks 512
waiting for 0xfe 0x0 0xff 
readblocks 512
waiting for 0xfe 0x0 0xff 
readblocks 512
waiting for 0xfe 0x0 0xff 
WRITE 10
readblocks 512
waiting for 0xfe 0x0 0xff 
writeblocks 512
readblocks 512
waiting for 0xfe 0x0 0xff 
writeblocks 512
readblocks 512
waiting for 0xfe 0x0 0xff 
WRITE 10
readblocks 512
waiting for 0xfe 0x0 0xff 
writeblocks 512
readblocks 512
waiting for 0xfe 0x0 0xff 
writeblocks 512
readblocks 512
waiting for 0xfe 0x0 0xff 
WRITE 4106
readblocks 512
waiting for 0xfe 0x0 0xff 
writeblocks 512
writeblocks 3584
writeblocks 512
readblocks 512
waiting for 0xfe 0x0 0xff 
writeblocks 512
readblocks 512
waiting for 0xfe 0x0 0xff 
WRITE 4106
readblocks 512
waiting for 0xfe 0x0 0xff 
writeblocks 512
writeblocks 3072
readblocks 512
waiting for 0xfe 0x0 0xff 
writeblocks 512
writeblocks 512
writeblocks 512
writeblocks 512
readblocks 512
waiting for 0xfe 0x0 0xff 
writeblocks 512
writeblocks 512
readblocks 512
waiting for 0xfe 0x0 0xff 
readblocks 512
waiting for 0xfe 0x0 0xff 
WRITE 8202
readblocks 512
waiting for 0xfe 0x0 0xff 
writeblocks 512
writeblocks 7168
readblocks 512
waiting for 0xfe 0x0 0xff 
writeblocks 512
writeblocks 512
writeblocks 512
writeblocks 512
readblocks 512
waiting for 0xfe 0x0 0xff 
writeblocks 512
writeblocks 512
readblocks 512
waiting for 0xfe 0x0 0xff 
readblocks 512
waiting for 0xfe 0x0 0xff 
WRITE 8202
readblocks 512
waiting for 0xfe 0x0 0xff 
writeblocks 512
writeblocks 7168
readblocks 512
waiting for 0xfe 0x0 0x7 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff [[[typed ctrl-c here]]] Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "test.py", line 20, in <module>
  File "test.py", line 20, in <module>
OSError: [Errno 5] Input/output error
>>> 

[0x1d00ffff]

Hello, I am seeing the same issue on the ItsyBitsy M4 Express.

I captured a few data points using the SDcards I have and the results are different but repeatable for each card type:

Lexmark 4gb class 10 card:

This one is interesting. Writing up to 16384 bytes at a time to a file is OK, but only if it is the first write to the file. Sample code:

This completes OK every time (truncate file and write):

with open('/sd/test.bin', 'w') as output:
    bytes_out =output.write(bytearray([1] * 16384))
    print('WROTE', bytes_out)

This fails every time (write to a file already containing 10 bytes):

with open('/sd/test.bin', 'w') as output:
    output.write(bytearray([1] * 10))
with open('/sd/test.bin', 'a') as output:
    bytes_out =output.write(bytearray([1] * 16384))
    print('WROTE', bytes_out)

Unbranded 8gb class 10 card:

Fails on a 1024 byte write, infinite 1023-byte writes are fine. Interestingly, it appears that it is the second 1024 byte write that fails, the first is successful.

Unbranded 8gb log:

...
WROTE 1022
waiting for 0xfe: 0x0 0xff 
waiting for 0xfe: 0x0 0xff 
waiting for 0xfe: 0x0 0xff 
waiting for 0xfe: 0x0 0xff 
waiting for 0xfe: 0x0 0xff 
WROTE 1022
waiting for 0xfe: 0x0 0xff 
waiting for 0xfe: 0x0 0xff 
waiting for 0xfe: 0x0 0xff 
waiting for 0xfe: 0x0 0xff 
waiting for 0xfe: 0x0 0xff 
WROTE 1022
waiting for 0xfe: 0x0 0xff 
waiting for 0xfe: 0x0 0xff 
waiting for 0xfe: 0x0 0xff 
waiting for 0xfe: 0x0 0xff 
waiting for 0xfe: 0x0 0xff 
WROTE 1024
waiting for 0xfe: 0x0 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff 0xff [[[ctrl+c here]]] Traceback (most recent call last):

[devoh747]

I modified the test program and added "print('MemFree: ', gc.mem_free())" to the last line..
I just tested this on my GrandCentral using my Pullrequest #19 (Samsung EVO 32GB fix)
using a SanDisk 16GB MicroSD

...
WRITE 28682
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
MemFree: 67520
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
WRITE 28682
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
MemFree: 67664
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
WRITE 32778
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
MemFree: 46528
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
WRITE 32778
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
MemFree: 46528
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
WRITE 36874
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
MemFree: 25392
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
WRITE 36874
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
MemFree: 25536
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
WRITE 40970
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
MemFree: 4544
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
WRITE 40970
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
MemFree: 4400
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
waiting for 0xfe: 0x0 0xff 0xff
WRITE 45066
Traceback (most recent call last):
File "code.py", line 27, in
File "code.py", line 26, in
MemoryError: memory allocation failed, allocating 45066 bytes

I did three runs and each time (SanDisk Ultra 16GB) it died in the same spot "MemoryError: memory allocation failed, allocating 45066 bytes" while using my SanDisk 16GB card..

I got the hang when using my Samsung EVO 32GB card in different spots like others report above. I find the different behaviors interesting.. both are using _init_card_v2() which I changed (Pullrequest #19) to include crc values for all card commands to get the Samsung EVO 32GB working. It looks to me that the SanDisk ran out of memory for some reason.. something not being released or maybe the gc not cleaning up properly. I thought maybe the difference in the Samsung EVO 32GB was possibly around being sensitive to the SPI baudrate(maybe that is why they use the CRC on commands.. just a stab in the dark.. but I noticed no difference bringing the baudrate down from 1.32M hz to 400k or even 250k.

[dhalbert]

Should be fixed by #20. Others have reported success.