RP2040: Fix USB log corruption

USB logging did not handle log buffer overruns correctly, resulting
in log corruption after the serial port was opened. Usually this
fixed itself quickly enough, but not always.

Fixed by adding a separate parameter to log_get_buffer() to indicate
number of available bytes in log buffer.

Also improves initiator mode USB log performance by calling
platform_poll() during retry waits.

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;