search

ZuluSCSI / ZuluSCSI-firmware

Firmware for the ZuluSCSI advanced SCSI emulator
https://zuluscsi.com
Other
187 stars 20 forks source link

SD Card IO errors when imaging a large drive in initiator mode (ZuluSCSI RP2040) #458

Open agillen opened 2 months ago

agillen commented 2 months ago

I've successfully imaged several smaller drives (2-10GB) in initiator mode, but when trying to image a larger drive (70GB 73GB Seagate Cheetah) the process consistently fails with SD card write errors. Notably, once this occurs nothing - including logs - are written to the card.

I've used nearly a dozen different ExFAT-formatted SD cards - new, older, faster, slower, tested with f3, etc. - all produce the result described below (i.e. doesn't seem to be an SD card issue).

First, my zuluscsi.ini:

zuluscsi.ini ```SCSI] Quirks = 0 EnableSCSI2 = 1 MaxSyncSpeed = 0 ```

The logs start normally, identifying the drive and beginning the transfer:

zululog.txt (Start) ``` [12ms] Platform: ZuluSCSI RP2040 [12ms] FW Version: 24.08.22-release Aug 22 2024 23:23:49 [13ms] DIP switch settings: debug log 1, termination 1 [13ms] SCSI termination is enabled [14ms] Flash chip size: 4096 kB [14ms] SCSI initiator mode selected by DIP switch, expecting SCSI disks on the bus [20ms] SD card detected, FAT64 volume size: 118048 MB [20ms] SD MID: 0x27, OID: 0x50 0x48 [20ms] SD Name: MTG1b [21ms] SD Date: 10/2022 [21ms] SD Serial: 0x0148E3F8 [296ms] InitiatorID set to ID 0x07 [801ms] Initialization complete! [1801ms] DBG -- BUS_BUSY [1801ms] DBG ---- SELECTION [1802ms] DBG ------ SELECTING 0 with initiator ID 7 [2055ms] DBG ------ Target 0 did not respond [2055ms] DBG -- BUS_FREE [2055ms] DBG Failed to connect to SCSI ID 0 [3058ms] DBG -- BUS_BUSY [3058ms] DBG ---- SELECTION [3058ms] DBG ------ SELECTING 1 with initiator ID 7 [3311ms] DBG ------ Target 1 did not respond [3312ms] DBG -- BUS_FREE [3312ms] DBG Failed to connect to SCSI ID 1 [4314ms] DBG -- BUS_BUSY [4314ms] DBG ---- SELECTION [4314ms] DBG ------ SELECTING 2 with initiator ID 7 [4568ms] DBG ------ Target 2 did not respond [4568ms] DBG -- BUS_FREE [4568ms] DBG Failed to connect to SCSI ID 2 [5571ms] DBG -- BUS_BUSY [5571ms] DBG ---- SELECTION [5571ms] DBG ------ SELECTING 3 with initiator ID 7 [5824ms] DBG ------ Target 3 did not respond [5824ms] DBG -- BUS_FREE [5825ms] DBG Failed to connect to SCSI ID 3 [6827ms] DBG -- BUS_BUSY [6827ms] DBG ---- SELECTION [6827ms] DBG ------ SELECTING 4 with initiator ID 7 [6828ms] DBG ---- COMMAND: TestUnitReady [6828ms] DBG ------ OUT: 0x00 0x00 0x00 0x00 0x00 0x00 [6829ms] DBG ---- STATUS [6829ms] DBG ------ IN: 0x02 [6829ms] DBG ------ STATUS: 0x02 [6830ms] DBG ---- MESSAGE_IN [6830ms] DBG ------ IN: 0x00 [6830ms] DBG -- BUS_FREE [6831ms] DBG -- BUS_BUSY [6831ms] DBG ---- SELECTION [6831ms] DBG ------ SELECTING 4 with initiator ID 7 [6832ms] DBG ---- COMMAND: RequestSense [6832ms] DBG ------ OUT: 0x03 0x00 0x00 0x00 0x12 0x00 [6833ms] DBG ---- DATA_IN [6833ms] DBG ---- Total IN: 18 OUT: 0 CHECKSUM: 31429 [6833ms] DBG ---- STATUS [6834ms] DBG ------ IN: 0x00 [6834ms] DBG ------ STATUS: 0x00 [6834ms] DBG ---- MESSAGE_IN [6835ms] DBG ------ IN: 0x00 [6835ms] DBG -- BUS_FREE [6835ms] DBG RequestSense response: 0x70 0x00 0x06 0x00 0x00 0x00 0x00 0x0A 0x00 0x00 0x00 0x00 0x29 0x01 0x01 0x00 0x00 0x00 [6836ms] DBG Target 4 reports UNIT_ATTENTION, running INQUIRY [6837ms] DBG -- BUS_BUSY [6837ms] DBG ---- SELECTION [6838ms] DBG ------ SELECTING 4 with initiator ID 7 [6838ms] DBG ---- COMMAND: Inquiry [6839ms] DBG ------ OUT: 0x12 0x00 0x00 0x00 0x24 0x00 [6840ms] DBG ---- DATA_IN [6840ms] DBG ---- Total IN: 36 OUT: 0 CHECKSUM: 62309 [6840ms] DBG ---- STATUS [6840ms] DBG ------ IN: 0x00 [6841ms] DBG ------ STATUS: 0x00 [6841ms] DBG ---- MESSAGE_IN [6841ms] DBG ------ IN: 0x00 [6842ms] DBG -- BUS_FREE [6842ms] DBG -- BUS_BUSY [6842ms] DBG ---- SELECTION [6842ms] DBG ------ SELECTING 4 with initiator ID 7 [6843ms] DBG ---- COMMAND: TestUnitReady [6843ms] DBG ------ OUT: 0x00 0x00 0x00 0x00 0x00 0x00 [6844ms] DBG ---- STATUS [6844ms] DBG ------ IN: 0x02 [6844ms] DBG ------ STATUS: 0x02 [6845ms] DBG ---- MESSAGE_IN [6845ms] DBG ------ IN: 0x00 [6845ms] DBG -- BUS_FREE [6846ms] DBG -- BUS_BUSY [6846ms] DBG ---- SELECTION [6846ms] DBG ------ SELECTING 4 with initiator ID 7 [6847ms] DBG ---- COMMAND: RequestSense [6847ms] DBG ------ OUT: 0x03 0x00 0x00 0x00 0x12 0x00 [6848ms] DBG ---- DATA_IN [6848ms] DBG ---- Total IN: 18 OUT: 0 CHECKSUM: 29372 [6849ms] DBG ---- STATUS [6849ms] DBG ------ IN: 0x00 [6849ms] DBG ------ STATUS: 0x00 [6849ms] DBG ---- MESSAGE_IN [6850ms] DBG ------ IN: 0x00 [6850ms] DBG -- BUS_FREE [6850ms] DBG RequestSense response: 0x70 0x00 0x02 0x00 0x00 0x00 0x00 0x0A 0x00 0x00 0x00 0x00 0x04 0x01 0x02 0x00 0x00 0x00 [6852ms] DBG Target 4 reports NOT_READY, running STARTSTOPUNIT [6852ms] DBG -- BUS_BUSY [6853ms] DBG ---- SELECTION [6853ms] DBG ------ SELECTING 4 with initiator ID 7 [6853ms] DBG ---- COMMAND: StartStopUnit [6854ms] DBG ------ OUT: 0x1B 0x00 0x00 0x00 0x01 0x00 [13945ms] DBG ---- STATUS [13945ms] DBG ------ IN: 0x00 [13946ms] DBG ------ STATUS: 0x00 [13946ms] DBG ---- MESSAGE_IN [13946ms] DBG ------ IN: 0x00 [13947ms] DBG -- BUS_FREE [13947ms] DBG Failed to connect to SCSI ID 4 [14951ms] DBG -- BUS_BUSY [14951ms] DBG ---- SELECTION [14951ms] DBG ------ SELECTING 5 with initiator ID 7 [15204ms] DBG ------ Target 5 did not respond [15204ms] DBG -- BUS_FREE [15205ms] DBG Failed to connect to SCSI ID 5 [16207ms] DBG -- BUS_BUSY [16207ms] DBG ---- SELECTION [16207ms] DBG ------ SELECTING 6 with initiator ID 7 [16460ms] DBG ------ Target 6 did not respond [16460ms] DBG -- BUS_FREE [16460ms] DBG Failed to connect to SCSI ID 6 [17463ms] DBG -- BUS_BUSY [17463ms] DBG ---- SELECTION [17463ms] DBG ------ SELECTING 0 with initiator ID 7 [17716ms] DBG ------ Target 0 did not respond [17717ms] DBG -- BUS_FREE [17717ms] DBG Failed to connect to SCSI ID 0 [18719ms] DBG -- BUS_BUSY [18719ms] DBG ---- SELECTION [18720ms] DBG ------ SELECTING 1 with initiator ID 7 [18973ms] DBG ------ Target 1 did not respond [18973ms] DBG -- BUS_FREE [18973ms] DBG Failed to connect to SCSI ID 1 [19976ms] DBG -- BUS_BUSY [19976ms] DBG ---- SELECTION [19976ms] DBG ------ SELECTING 2 with initiator ID 7 [20230ms] DBG ------ Target 2 did not respond [20230ms] DBG -- BUS_FREE [20230ms] DBG Failed to connect to SCSI ID 2 [21232ms] DBG -- BUS_BUSY [21232ms] DBG ---- SELECTION [21233ms] DBG ------ SELECTING 3 with initiator ID 7 [21486ms] DBG ------ Target 3 did not respond [21486ms] DBG -- BUS_FREE [21486ms] DBG Failed to connect to SCSI ID 3 [22489ms] DBG -- BUS_BUSY [22489ms] DBG ---- SELECTION [22490ms] DBG ------ SELECTING 4 with initiator ID 7 [22490ms] DBG ---- COMMAND: TestUnitReady [22491ms] DBG ------ OUT: 0x00 0x00 0x00 0x00 0x00 0x00 [22493ms] DBG ---- STATUS [22493ms] DBG ------ IN: 0x00 [22493ms] DBG ------ STATUS: 0x00 [22494ms] DBG ---- MESSAGE_IN [22494ms] DBG ------ IN: 0x00 [22494ms] DBG -- BUS_FREE [22495ms] DBG -- BUS_BUSY [22495ms] DBG ---- SELECTION [22495ms] DBG ------ SELECTING 4 with initiator ID 7 [22496ms] DBG ---- COMMAND: StartStopUnit [22496ms] DBG ------ OUT: 0x1B 0x00 0x00 0x00 0x01 0x00 [22497ms] DBG ---- STATUS [22497ms] DBG ------ IN: 0x00 [22497ms] DBG ------ STATUS: 0x00 [22498ms] DBG ---- MESSAGE_IN [22498ms] DBG ------ IN: 0x00 [22498ms] DBG -- BUS_FREE [22499ms] DBG -- BUS_BUSY [22499ms] DBG ---- SELECTION [22499ms] DBG ------ SELECTING 4 with initiator ID 7 [22500ms] DBG ---- COMMAND: ReadCapacity [22500ms] DBG ------ OUT: 0x25 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 [22501ms] DBG ---- DATA_IN [22501ms] DBG ---- Total IN: 8 OUT: 0 CHECKSUM: 29714 [22502ms] DBG ---- STATUS [22502ms] DBG ------ IN: 0x00 [22502ms] DBG ------ STATUS: 0x00 [22503ms] DBG ---- MESSAGE_IN [22503ms] DBG ------ IN: 0x00 [22503ms] DBG -- BUS_FREE [22504ms] DBG -- BUS_BUSY [22504ms] DBG ---- SELECTION [22504ms] DBG ------ SELECTING 4 with initiator ID 7 [22505ms] DBG ---- COMMAND: Inquiry [22505ms] DBG ------ OUT: 0x12 0x00 0x00 0x00 0x24 0x00 [22506ms] DBG ---- DATA_IN [22506ms] DBG ---- Total IN: 36 OUT: 0 CHECKSUM: 62309 [22507ms] DBG ---- STATUS [22507ms] DBG ------ IN: 0x00 [22507ms] DBG ------ STATUS: 0x00 [22508ms] DBG ---- MESSAGE_IN [22508ms] DBG ------ IN: 0x00 [22508ms] DBG -- BUS_FREE [22509ms] SCSI ID 4 capacity 143374744 sectors x 512 bytes [22509ms] Drive total size is 70007 MiB [22510ms] SCSI Version 3 [22510ms] [SCSI4] [22510ms] Vendor = "SEAGATE " [22510ms] Product = "ST373207LC " [22511ms] Version = "0002" [22511ms] Type = 0 [22585ms] Preallocating image file [22928ms] Starting to copy drive data to HD40_imaged.hda [22931ms] DBG -- BUS_BUSY [22931ms] DBG ---- SELECTION [22931ms] DBG ------ SELECTING 4 with initiator ID 7 [22932ms] DBG ---- COMMAND: Read10 [22932ms] DBG ------ OUT: 0x28 0x00 0x00 0x00 0x00 0x00 0x00 0x02 0x00 0x00 [22942ms] DBG ---- DATA_IN [23057ms] DBG ---- Total IN: 262144 OUT: 0 CHECKSUM: 38308 [23058ms] DBG ---- STATUS [23062ms] DBG ------ IN: 0x00 [23062ms] DBG ------ STATUS: 0x00 [23062ms] DBG ---- MESSAGE_IN [23062ms] DBG ------ IN: 0x00 [23063ms] DBG -- BUS_FREE [23065ms] SCSI read succeeded, sectors done: 512 / 143374744 speed 1956 kB/s - 0% [23067ms] DBG -- BUS_BUSY [23067ms] DBG ---- SELECTION [23068ms] DBG ------ SELECTING 4 with initiator ID 7 [23068ms] DBG ---- COMMAND: Read10 [23068ms] DBG ------ OUT: 0x28 0x00 0x00 0x00 0x02 0x00 0x00 0x02 0x00 0x00 [23071ms] DBG ---- DATA_IN [23186ms] DBG ---- Total IN: 262144 OUT: 0 CHECKSUM: 48187 [23186ms] DBG ---- STATUS [23190ms] DBG ------ IN: 0x00 [23190ms] DBG ------ STATUS: 0x00 [23191ms] DBG ---- MESSAGE_IN [23191ms] DBG ------ IN: 0x00 [23191ms] DBG -- BUS_FREE [23194ms] SCSI read succeeded, sectors done: 1024 / 143374744 speed 2064 kB/s - 0% [23196ms] DBG -- BUS_BUSY [23196ms] DBG ---- SELECTION [23196ms] DBG ------ SELECTING 4 with initiator ID 7 [23197ms] DBG ---- COMMAND: Read10 [23197ms] DBG ------ OUT: 0x28 0x00 0x00 0x00 0x04 0x00 0x00 0x02 0x00 0x00 [23200ms] DBG ---- DATA_IN [23315ms] DBG ---- Total IN: 262144 OUT: 0 CHECKSUM: 56418 [23315ms] DBG ---- STATUS [23322ms] DBG ------ IN: 0x00 [23322ms] DBG ------ STATUS: 0x00 [23322ms] DBG ---- MESSAGE_IN [23323ms] DBG ------ IN: 0x00 [23323ms] DBG -- BUS_FREE [23325ms] SCSI read succeeded, sectors done: 1536 / 143374744 speed 2032 kB/s - 0% ```

This proceeds with no unusual logging until the log eventually stops abruptly anywhere from <1% into the transfer to ~30%, always ending with a successful read cycle:

zululog.txt (End) ``` [8605570ms] SCSI read succeeded, sectors done: 34009600 / 143374744 speed 1149 kB/s - 23% [8605612ms] DBG -- BUS_BUSY [8605612ms] DBG ---- SELECTION [8605613ms] DBG ------ SELECTING 4 with initiator ID 7 [8605613ms] DBG ---- COMMAND: Read10 [8605613ms] DBG ------ OUT: 0x28 0x00 0x02 0x06 0xF2 0x00 0x00 0x02 0x00 0x00 [8605614ms] DBG ---- DATA_IN [8605775ms] DBG ---- Total IN: 262144 OUT: 0 CHECKSUM: 28132 [8605775ms] DBG ---- STATUS [8605789ms] DBG ------ IN: 0x00 [8605789ms] DBG ------ STATUS: 0x00 [8605790ms] DBG ---- MESSAGE_IN [8605790ms] DBG ------ IN: 0x00 [8605790ms] DBG -- BUS_FREE [8605832ms] SCSI read succeeded, sectors done: 34010112 / 143374744 speed 1191 kB/s - 23% [8605888ms] DBG -- BUS_BUSY [8605888ms] DBG ---- SELECTION [8605888ms] DBG ------ SELECTING 4 with initiator ID 7 [8605889ms] DBG ---- COMMAND: Read10 [8605889ms] DBG ------ OUT: 0x28 0x00 0x02 0x06 0xF4 0x00 0x00 0x02 0x00 0x00 [8605890ms] DBG ---- DATA_IN [8606059ms] DBG ---- Total IN: 262144 OUT: 0 CHECKSUM: 61070 [8606059ms] DBG ---- STATUS [8606084ms] DBG ------ IN: 0x00 [8606084ms] DBG ------ STATUS: 0x00 [8606085ms] DBG ---- MESSAGE_IN [8606085ms] DBG ------ IN: 0x00 [8606086ms] DBG -- BUS_FREE [8606161ms] SCSI read succeeded, sectors done: 34010624 / 143374744 speed 960 kB/s - 23% ```

Monitoring the serial console shows the following errors begining right after logging stops:

[8985817ms] DBG -- BUS_BUSY
[8985817ms] DBG ---- SELECTION
[8985817ms] DBG ------ SELECTING 4 with initiator ID 7
[8985818ms] DBG ---- COMMAND: Read10
[8985818ms] DBG ------ OUT: 0x28 0x00 0x02 0x06 0xF6 0xB5 0x00 0x00 0x01 0x00 
[8985819ms] DBG ---- DATA_IN
[8985820ms] DBG ---- Total IN: 512 OUT: 0 CHECKSUM: 60972
[8985820ms] DBG ---- STATUS
[8985823ms] DBG Timeout waiting for response in rp2040_sdio_command_R1(16), PIO PC: 14 RXF: 0 TXF: 0
[8985823ms] SDIO SD card error on line 354, error code 2
[8985824ms] scsiInitiatorReadDataToFile: SD card write failed
[8985824ms] DBG ------ IN: 0x00 
[8985825ms] DBG ------ STATUS: 0x00
[8985825ms] DBG ---- MESSAGE_IN
[8985825ms] DBG ------ IN: 0x00 
[8985826ms] DBG -- BUS_FREE
[8985826ms] Failed to transfer 1 sectors starting at 34010805
[8985827ms] Retrying.. 1/5

I'd be inclined to try increasing the timeout given the error, but considering that nothing is written to the SD card once this starts (not even logs) I suspect that's futile.

Any suggestions?

aperezbios commented 1 month ago

Thanks for the report, @agillen, and apologies for the lack of response.

Can you specify the exact model number of the Cheetah? I may have something identical or similar that we can test against on our end.

agillen commented 1 month ago

Thanks for the reply, @aperezbios - it's a 73GB Cheetah 10K.7 model # ST373207LC. Pulled from a working SGI O2.

Forgot to note in the original issue, but for completeness: this drive has an 80-pin SCA connector, so I'm using a generic SCA-to-50 pin adapter with the ZuluSCSI.

dranch commented 1 month ago

If I remember correctly, SCA-attached SCSI drives are LVD (low voltage differential) signals which is NOT compatible with classic SCSI-II.

aperezbios commented 1 month ago

If I remember correctly, SCA-attached SCSI drives are LVD (low voltage differential) signals which is NOT compatible with classic SCSI-II.

SCA drives can still fall back to single-ended SCSI, in nearly all cases. I've never encountered an SCA drive that can't do SE.