Merge pull request #199 from ZuluSCSI/dev_usb_logging_fixes

RP2040: Fix USB log corruption

lib/ZuluSCSI_platform_RP2040/ZuluSCSI_platform.cpp

@@ -381,11 +381,11 @@ static void usb_log_poll()
     if (_SerialUSB.ready())
     {
         // Retrieve pointer to log start and determine number of bytes available.
-        uint32_t newlogpos = logpos;
-        const char *data = log_get_buffer(&newlogpos);
+        uint32_t available = 0;
+        const char *data = log_get_buffer(&logpos, &available);
 
         // Limit to CDC packet size
-        uint32_t len = (newlogpos - logpos);
+        uint32_t len = available;
         if (len == 0) return;
         if (len > CDC_MAX_PACKET_SIZE) len = CDC_MAX_PACKET_SIZE;
 
@@ -393,7 +393,7 @@ static void usb_log_poll()
         // If USB CDC buffer is full, this may be 0
         uint32_t actual = 0;
         _SerialUSB.send_nb((uint8_t*)data, len, &actual);
-        logpos += actual;
+        logpos -= available - actual;
     }
 }
 

src/ZuluSCSI_initiator.cpp

@@ -127,6 +127,16 @@ static void scsiInitiatorUpdateLed()
     }
 }
 
+void delay_with_poll(uint32_t ms)
+{
+    uint32_t start = millis();
+    while ((uint32_t)(millis() - start) < ms)
+    {
+        platform_poll();
+        delay(1);
+    }
+}
+
 // High level logic of the initiator mode
 void scsiInitiatorMainLoop()
 {
@@ -146,7 +156,7 @@ void scsiInitiatorMainLoop()
 
         if (!(g_initiator_state.drives_imaged & (1 << g_initiator_state.target_id)))
         {
-            delay(1000);
+            delay_with_poll(1000);
 
             uint8_t inquiry_data[36];
 
@@ -279,9 +289,9 @@ void scsiInitiatorMainLoop()
             if (g_initiator_state.retrycount < 5)
             {
                 logmsg("Retrying.. ", g_initiator_state.retrycount, "/5");
-                delay(200);
+                delay_with_poll(200);
                 scsiHostPhyReset();
-                delay(200);
+                delay_with_poll(200);
 
                 g_initiator_state.retrycount++;
                 g_initiator_state.target_file.seek((uint64_t)g_initiator_state.sectors_done * g_initiator_state.sectorsize);
@@ -719,6 +729,7 @@ bool scsiInitiatorReadDataToFile(int target_id, uint32_t start_sector, uint32_t
     // Write any remaining buffered data
     while (g_initiator_transfer.bytes_sd < g_initiator_transfer.bytes_scsi_done)
     {
+        platform_poll();
         scsiInitiatorWriteDataToSd(file, false);
     }
 

src/ZuluSCSI_log.cpp

@@ -143,7 +143,7 @@ uint32_t log_get_buffer_len()
     return g_logpos;
 }
 
-const char *log_get_buffer(uint32_t *startpos)
+const char *log_get_buffer(uint32_t *startpos, uint32_t *available)
 {
     uint32_t default_pos = 0;
     if (startpos == NULL)
@@ -152,28 +152,46 @@ const char *log_get_buffer(uint32_t *startpos)
     }
 
     // Check oldest data available in buffer
-    uint32_t margin = 16;
-    if (g_logpos + margin > LOGBUFSIZE)
+    uint32_t lag = (g_logpos - *startpos);
+    if (lag >= LOGBUFSIZE)
     {
-        uint32_t oldest = g_logpos + margin - LOGBUFSIZE;
-        if (*startpos < oldest)
+        // If we lose data, skip 512 bytes forward to give us time to transmit
+        // pending data before new log messages arrive. Also skip to next line
+        // break to keep formatting consistent.
+        uint32_t oldest = g_logpos - LOGBUFSIZE + 512;
+        while (oldest < g_logpos)
         {
-            *startpos = oldest;
+            char c = g_logbuffer[oldest & LOGBUFMASK];
+            if (c == '\r' || c == '\n') break;
+            oldest++;
         }
+
+        if (oldest > g_logpos)
+        {
+            oldest = g_logpos;
+        }
+
+        *startpos = oldest;
     }
 
     const char *result = &g_logbuffer[*startpos & LOGBUFMASK];
+
+    // Calculate number of bytes available
+    uint32_t len;
     if ((g_logpos & LOGBUFMASK) >= (*startpos & LOGBUFMASK))
     {
-        // Ok, everything has been read now
-        *startpos = g_logpos;
+        // Can read directly to g_logpos
+        len = g_logpos - *startpos;
     }
     else
     {
         // Buffer wraps, read to end of buffer now and start from beginning on next call.
-        *startpos = g_logpos & (~LOGBUFMASK);
+        len = LOGBUFSIZE - (*startpos & LOGBUFMASK);
     }
 
+    if (available) { *available = len; }
+    *startpos += len;
+
     return result;
 }
 

src/ZuluSCSI_log.h

@@ -31,7 +31,8 @@ uint32_t log_get_buffer_len();
 
 // Get log as a string.
 // If startpos is given, continues log reading from previous position and updates the position.
-const char *log_get_buffer(uint32_t *startpos);
+// If available is given, number of bytes available is written there.
+const char *log_get_buffer(uint32_t *startpos, uint32_t *available = nullptr);
 
 // Whether to enable debug messages
 extern bool g_log_debug;