Merge pull request #496 from ZuluSCSI/dev_usb_msc_init2

Improve USB MSC initiator support

lib/ZuluSCSI_platform_RP2MCU/rp2040-template.ld

@@ -73,6 +73,8 @@ SECTIONS
         /* Put only non-timecritical code in flash
          * This includes e.g. floating point math routines.
          */
+        .pio/build/$project_name/src/ZuluSCSI_initiator.cpp.o(.text .text*)
+        .pio/build/$project_name/src/ZuluSCSI_msc_initiator.cpp.o(.text .text*)
         .pio/build/$project_name/src/ZuluSCSI_log.cpp.o(.text .text*)
         .pio/build/$project_name/src/ZuluSCSI_log_trace.cpp.o(.text .text*)
         .pio/build/$project_name/src/ZuluSCSI_settings.cpp.o(.text .text*)

lib/ZuluSCSI_platform_RP2MCU/scsiHostPhy.cpp

@@ -263,13 +263,27 @@ uint32_t scsiHostRead(uint8_t *data, uint32_t count)
     {
         for (uint32_t i = 0; i < count; i++)
         {
-            while (!SCSI_IN(REQ))
+            uint32_t start = millis();
+            while (!SCSI_IN(REQ) && (millis() - start) < 10000)
             {
-                if (g_scsiHostPhyReset || !SCSI_IN(IO) || SCSI_IN(CD) != cd_start || SCSI_IN(MSG) != msg_start)
-                {
-                    // Target switched out of DATA_IN mode
-                    count = i;
-                }
+                // Wait for REQ asserted
+            }
+
+            int io = SCSI_IN(IO);
+            int cd = SCSI_IN(CD);
+            int msg = SCSI_IN(MSG);
+
+            if (g_scsiHostPhyReset)
+            {
+                dbgmsg("sciHostRead: aborting due to reset request");
+                count = i;
+                break;
+            }
+            else if (!io || cd != cd_start || msg != msg_start)
+            {
+                dbgmsg("scsiHostRead: aborting because target switched transfer phase (IO: ", io, ", CD: ", cd, ", MSG: ", msg, ")");
+                count = i;
+                break;
             }
 
             data[i] = scsiHostReadOneByte(&parityError);

lib/ZuluSCSI_platform_RP2MCU/scsi_accel_host.cpp

@@ -105,15 +105,50 @@ uint32_t scsi_accel_host_read(uint8_t *buf, uint32_t count, int *parityError, vo
     uint8_t *dst = buf;
     uint8_t *end = buf + count;
     uint32_t paritycheck = 0;
+    uint32_t prev_rx_time = millis();
     while (dst < end)
     {
         uint32_t available = pio_sm_get_rx_fifo_level(SCSI_PIO, SCSI_SM);
 
         if (available == 0)
         {
-            if (*resetFlag || !SCSI_IN(IO) || SCSI_IN(CD) != cd_start || SCSI_IN(MSG) != msg_start)
+            // No new data has been received by PIO, check if there is a need to abort
+
+            bool abort = false;
+            if (*resetFlag)
+            {
+                dbgmsg("scsi_accel_host_read: Aborting due to reset request");
+                abort = true;
+            }
+            else if ((millis() - prev_rx_time) > 10000)
+            {
+                dbgmsg("scsi_accel_host_read: Aborting due to timeout");
+                abort = true;
+            }
+            else
+            {
+                // Some drives such as ST-296N may have glitches on phase signals in between
+                // byte transfers. This is allowed by SCSI spec, and officially we should only
+                // check the phase signals when REQ is active. However the PIO logic currently
+                // does not do this. Instead, when we detect a phase change, wait for 10 milliseconds
+                // to see if it is real.
+                int debounce = 100;
+                while (debounce > 0 && (!SCSI_IN(IO) || SCSI_IN(CD) != cd_start || SCSI_IN(MSG) != msg_start))
+                {
+                    debounce--;
+                    delayMicroseconds(100);
+                }
+
+                if (debounce == 0)
+                {
+                    dbgmsg("scsi_accel_host_read: aborting because target switched transfer phase (IO: ",
+                        (int)SCSI_IN(IO), ", CD: ", (int)SCSI_IN(CD), ", MSG: ", (int)SCSI_IN(MSG), ")");
+                    abort = true;
+                }
+            }
+
+            if (abort)
             {
-                // Target switched out of DATA_IN mode
                 count = dst - buf;
                 break;
             }
@@ -171,4 +206,4 @@ void scsi_accel_host_init()
     sm_config_set_in_shift(&g_scsi_host.pio_cfg_async_read, true, true, 32);
 }
 
-#endif // PLATFORM_HAS_INITIATOR_MODE
+#endif // PLATFORM_HAS_INITIATOR_MODE

src/ZuluSCSI_initiator.cpp

@@ -691,7 +691,7 @@ bool scsiInitiatorReadCapacity(int target_id, uint32_t *sectorcount, uint32_t *s
     {
         uint8_t sense_key;
         scsiRequestSense(target_id, &sense_key);
-        logmsg("READ CAPACITY on target ", target_id, " failed, sense key ", sense_key);
+        scsiLogInitiatorCommandFailure("READ CAPACITY", target_id, status, sense_key);
         return false;
     }
     else
@@ -748,7 +748,7 @@ bool scsiStartStopUnit(int target_id, bool start)
     {
         uint8_t sense_key;
         scsiRequestSense(target_id, &sense_key);
-        dbgmsg("START STOP UNIT on target ", target_id, " failed, sense key ", sense_key);
+        scsiLogInitiatorCommandFailure("START STOP UNIT", target_id, status, sense_key);
     }
 
     return status == 0;
@@ -790,13 +790,13 @@ bool scsiTestUnitReady(int target_id)
             uint8_t sense_key;
             scsiRequestSense(target_id, &sense_key);
 
-            if (sense_key == 6)
+            if (sense_key == UNIT_ATTENTION)
             {
                 uint8_t inquiry[36];
                 dbgmsg("Target ", target_id, " reports UNIT_ATTENTION, running INQUIRY");
                 scsiInquiry(target_id, inquiry);
             }
-            else if (sense_key == 2)
+            else if (sense_key == NOT_READY)
             {
                 dbgmsg("Target ", target_id, " reports NOT_READY, running STARTSTOPUNIT");
                 scsiStartStopUnit(target_id, true);
@@ -957,7 +957,7 @@ bool scsiInitiatorReadDataToFile(int target_id, uint32_t start_sector, uint32_t
         uint8_t sense_key;
         scsiRequestSense(target_id, &sense_key);
 
-        logmsg("scsiInitiatorReadDataToFile: READ failed: ", status, " sense key ", sense_key);
+        scsiLogInitiatorCommandFailure("scsiInitiatorReadDataToFile command phase", target_id, status, sense_key);
         scsiHostPhyRelease();
         return false;
     }
@@ -1033,7 +1033,36 @@ bool scsiInitiatorReadDataToFile(int target_id, uint32_t start_sector, uint32_t
 
     scsiHostPhyRelease();
 
-    return status == 0 && g_initiator_transfer.all_ok;
+    if (!g_initiator_transfer.all_ok)
+    {
+        dbgmsg("scsiInitiatorReadDataToFile: Incomplete transfer");
+        return false;
+    }
+    else if (status == 2)
+    {
+        uint8_t sense_key;
+        scsiRequestSense(target_id, &sense_key);
+
+        if (sense_key == RECOVERED_ERROR)
+        {
+            dbgmsg("scsiInitiatorReadDataToFile: RECOVERED_ERROR at ", (int)start_sector);
+            return true;
+        }
+        else if (sense_key == UNIT_ATTENTION)
+        {
+            dbgmsg("scsiInitiatorReadDataToFile: UNIT_ATTENTION");
+            return true;
+        }
+        else
+        {
+            scsiLogInitiatorCommandFailure("scsiInitiatorReadDataToFile data phase", target_id, status, sense_key);
+            return false;
+        }
+    }
+    else
+    {
+        return status == 0;
+    }
 }
 
 

src/ZuluSCSI_log_trace.cpp

@@ -331,3 +331,31 @@ void scsiLogDataOut(const uint8_t *buf, uint32_t length)
 
     g_OutByteCount += length;
 }
+
+static const char *get_sense_key_name(uint8_t sense_key)
+{
+    switch (sense_key)
+    {
+        case RECOVERED_ERROR:              return "RECOVERED_ERROR";
+        case NOT_READY      :              return "NOT_READY";
+        case MEDIUM_ERROR   :              return "MEDIUM_ERROR";
+        case HARDWARE_ERROR :              return "HARDWARE_ERROR";
+        case ILLEGAL_REQUEST:              return "ILLEGAL_REQUEST";
+        case UNIT_ATTENTION :              return "UNIT_ATTENTION";
+        case DATA_PROTECT   :              return "DATA_PROTECT";
+        case BLANK_CHECK    :              return "BLANK_CHECK";
+        case VENDOR_SPECIFIC:              return "VENDOR_SPECIFIC";
+        case COPY_ABORTED   :              return "COPY_ABORTED";
+        case ABORTED_COMMAND:              return "ABORTED_COMMAND";
+        case EQUAL          :              return "EQUAL";
+        case VOLUME_OVERFLOW:              return "VOLUME_OVERFLOW";
+        case MISCOMPARE     :              return "MISCOMPARE";
+        case RESERVED       :              return "RESERVED";
+        default: return "UNKNOWN";
+    }
+}
+
+void scsiLogInitiatorCommandFailure(const char *command_text, int target_id, int status, uint8_t sense_key)
+{
+    logmsg("-- ", command_text, " on target ", target_id, " failed with status ", status, " and sense_key ", sense_key, " (", get_sense_key_name(sense_key), ")");
+}

src/ZuluSCSI_log_trace.h

@@ -30,4 +30,5 @@
 void scsiLogPhaseChange(int new_phase);
 void scsiLogInitiatorPhaseChange(int new_phase);
 void scsiLogDataIn(const uint8_t *buf, uint32_t length);
-void scsiLogDataOut(const uint8_t *buf, uint32_t length);
+void scsiLogDataOut(const uint8_t *buf, uint32_t length);
+void scsiLogInitiatorCommandFailure(const char *command_text, int target_id, int status, uint8_t sense_key);

src/ZuluSCSI_msc_initiator.cpp

@@ -87,6 +87,7 @@ static int do_read6_or_10(int target_id, uint32_t start_sector, uint32_t sectorc
 
 static void scan_targets()
 {
+    int found_count = 0;
     int initiator_id = scsiInitiatorGetOwnID();
     uint8_t inquiry_data[36] = {0};
     g_msc_initiator_target_count = 0;
@@ -100,7 +101,8 @@ static void scan_targets()
 
             bool inquiryok =
                 scsiStartStopUnit(target_id, true) &&
-                scsiInquiry(target_id, inquiry_data) &&
+                scsiInquiry(target_id, inquiry_data);
+            bool readcapok =
                 scsiInitiatorReadCapacity(target_id, &sectorcount, &sectorsize);
 
             char vendor_id[9] = {0};
@@ -110,11 +112,24 @@ static void scan_targets()
 
             if (inquiryok)
             {
-                logmsg("Found SCSI drive with ID ", target_id, ": ", vendor_id, " ", product_id);
-                g_msc_initiator_targets[g_msc_initiator_target_count].target_id = target_id;
-                g_msc_initiator_targets[g_msc_initiator_target_count].sectorcount = sectorcount;
-                g_msc_initiator_targets[g_msc_initiator_target_count].sectorsize = sectorsize;
-                g_msc_initiator_target_count++;
+                if (readcapok)
+                {
+                    logmsg("Found SCSI drive with ID ", target_id, ": ", vendor_id, " ", product_id,
+                        " capacity ", (int)(((uint64_t)sectorcount * sectorsize) / 1024 / 1024), " MB");
+                    g_msc_initiator_targets[found_count].target_id = target_id;
+                    g_msc_initiator_targets[found_count].sectorcount = sectorcount;
+                    g_msc_initiator_targets[found_count].sectorsize = sectorsize;
+                    found_count++;
+                }
+                else
+                {
+                    logmsg("Found SCSI drive with ID ", target_id, ": ", vendor_id, " ", product_id,
+                           " but failed to read capacity. Assuming SCSI-1 drive up to 1 GB.");
+                    g_msc_initiator_targets[found_count].target_id = target_id;
+                    g_msc_initiator_targets[found_count].sectorcount = 2097152;
+                    g_msc_initiator_targets[found_count].sectorsize = 512;
+                    found_count++;
+                }
             }
             else
             {
@@ -122,6 +137,9 @@ static void scan_targets()
             }
         }
     }
+
+    // USB MSC requests can start processing after we set this
+    g_msc_initiator_target_count = found_count;
 }
 
 bool setup_msc_initiator()
@@ -153,7 +171,8 @@ void poll_msc_initiator()
     uint32_t time_since_scan = time_now - g_msc_initiator_state.last_scan_time;
     if (g_msc_initiator_target_count == 0 && time_since_scan > 5000)
     {
-        // Scan for targets until we find one
+        // Scan for targets until we find one - drive might be slow to start up.
+        // MSC lock is not required here because commands will early exit when target_count is 0.
         platform_reset_watchdog();
         scan_targets();
         g_msc_initiator_state.last_scan_time = time_now;
@@ -221,6 +240,16 @@ static int get_target(uint8_t lun)
 
 void init_msc_inquiry_cb(uint8_t lun, uint8_t vendor_id[8], uint8_t product_id[16], uint8_t product_rev[4])
 {
+    dbgmsg("-- MSC Inquiry");
+
+    if (g_msc_initiator_target_count == 0)
+    {
+        memset(vendor_id, 0, 8);
+        memset(product_id, 0, 8);
+        memset(product_rev, 0, 8);
+        return;
+    }
+
     LED_ON();
     g_msc_initiator_state.status_reqcount++;
 
@@ -246,6 +275,11 @@ uint8_t init_msc_get_maxlun_cb(void)
 
 bool init_msc_is_writable_cb (uint8_t lun)
 {
+    if (g_msc_initiator_target_count == 0)
+    {
+        return false;
+    }
+
     LED_ON();
     g_msc_initiator_state.status_reqcount++;
 
@@ -260,6 +294,8 @@ bool init_msc_is_writable_cb (uint8_t lun)
 
 bool init_msc_start_stop_cb(uint8_t lun, uint8_t power_condition, bool start, bool load_eject)
 {
+    dbgmsg("-- MSC Start Stop, start: ", (int)start, ", load_eject: ", (int)load_eject);
+
     if (g_msc_initiator_target_count == 0)
     {
         return false;
@@ -294,7 +330,7 @@ bool init_msc_start_stop_cb(uint8_t lun, uint8_t power_condition, bool start, bo
     {
         uint8_t sense_key;
         scsiRequestSense(target, &sense_key);
-        logmsg("START STOP UNIT on target ", target, " failed, sense key ", sense_key);
+        scsiLogInitiatorCommandFailure("START STOP UNIT", target, status, sense_key);
     }
 
     LED_OFF();
@@ -304,6 +340,8 @@ bool init_msc_start_stop_cb(uint8_t lun, uint8_t power_condition, bool start, bo
 
 bool init_msc_test_unit_ready_cb(uint8_t lun)
 {
+    dbgmsg("-- MSC Test Unit Ready");
+
     if (g_msc_initiator_target_count == 0)
     {
         return false;
@@ -315,8 +353,16 @@ bool init_msc_test_unit_ready_cb(uint8_t lun)
 
 void init_msc_capacity_cb(uint8_t lun, uint32_t *block_count, uint16_t *block_size)
 {
+    dbgmsg("-- MSC Get Capacity");
     g_msc_initiator_state.status_reqcount++;
 
+    if (g_msc_initiator_target_count == 0)
+    {
+        *block_count = 0;
+        *block_size = 0;
+        return;
+    }
+
     uint32_t sectorcount = 0;
     uint32_t sectorsize = 0;
     scsiInitiatorReadCapacity(get_target(lun), &sectorcount, &sectorsize);
@@ -326,6 +372,12 @@ void init_msc_capacity_cb(uint8_t lun, uint32_t *block_count, uint16_t *block_si
 
 int32_t init_msc_scsi_cb(uint8_t lun, const uint8_t scsi_cmd[16], void *buffer, uint16_t bufsize)
 {
+    if (g_msc_initiator_target_count == 0)
+    {
+        return -1;
+    }
+
+    dbgmsg("-- MSC Raw SCSI command ", bytearray(scsi_cmd, 16));
     LED_ON();
     g_msc_initiator_state.status_reqcount++;
 
@@ -386,6 +438,11 @@ static int do_read6_or_10(int target_id, uint32_t start_sector, uint32_t sectorc
 
 int32_t init_msc_read10_cb(uint8_t lun, uint32_t lba, uint32_t offset, void* buffer, uint32_t bufsize)
 {
+    if (g_msc_initiator_target_count == 0)
+    {
+        return -1;
+    }
+
     LED_ON();
     int status = 0;
 
@@ -437,8 +494,19 @@ int32_t init_msc_read10_cb(uint8_t lun, uint32_t lba, uint32_t offset, void* buf
         uint8_t sense_key;
         scsiRequestSense(target_id, &sense_key);
 
-        logmsg("SCSI Initiator read failed: ", status, " sense key ", sense_key);
-        return -1;
+        if (sense_key == RECOVERED_ERROR)
+        {
+            dbgmsg("SCSI Initiator read: RECOVERED_ERROR at ", (int)orig_lba);
+        }
+        else if (sense_key == UNIT_ATTENTION)
+        {
+            dbgmsg("SCSI Initiator read: UNIT_ATTENTION");
+        }
+        else
+        {
+            scsiLogInitiatorCommandFailure("SCSI Initiator read", target_id, status, sense_key);
+            return -1;
+        }
     }
 
     if (lba + total_sectorcount <= g_msc_initiator_targets[lun].sectorcount)
@@ -462,6 +530,11 @@ int32_t init_msc_read10_cb(uint8_t lun, uint32_t lba, uint32_t offset, void* buf
 
 int32_t init_msc_write10_cb(uint8_t lun, uint32_t lba, uint32_t offset, uint8_t *buffer, uint32_t bufsize)
 {
+    if (g_msc_initiator_target_count == 0)
+    {
+        return -1;
+    }
+
     int status = -1;
 
     int target_id = get_target(lun);
@@ -514,8 +587,19 @@ int32_t init_msc_write10_cb(uint8_t lun, uint32_t lba, uint32_t offset, uint8_t
         uint8_t sense_key;
         scsiRequestSense(target_id, &sense_key);
 
-        logmsg("SCSI Initiator write failed: ", status, " sense key ", sense_key);
-        return -1;
+        if (sense_key == RECOVERED_ERROR)
+        {
+            dbgmsg("SCSI Initiator write: RECOVERED_ERROR at ", (int)start_sector);
+        }
+        else if (sense_key == UNIT_ATTENTION)
+        {
+            dbgmsg("SCSI Initiator write: UNIT_ATTENTION");
+        }
+        else
+        {
+            scsiLogInitiatorCommandFailure("SCSI Initiator write", target_id, status, sense_key);
+            return -1;
+        }
     }
 
     return sectorcount * sectorsize;