From cbbb96fd230fef96ee164eda78aa5ab9270db904 Mon Sep 17 00:00:00 2001 From: Petteri Aimonen Date: Fri, 5 May 2023 15:38:10 +0300 Subject: [PATCH] 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. --- .../ZuluSCSI_platform.cpp | 8 ++--- src/ZuluSCSI_initiator.cpp | 17 +++++++-- src/ZuluSCSI_log.cpp | 36 ++++++++++++++----- src/ZuluSCSI_log.h | 3 +- 4 files changed, 47 insertions(+), 17 deletions(-) diff --git a/lib/ZuluSCSI_platform_RP2040/ZuluSCSI_platform.cpp b/lib/ZuluSCSI_platform_RP2040/ZuluSCSI_platform.cpp index 7b4035e8..4274360e 100644 --- a/lib/ZuluSCSI_platform_RP2040/ZuluSCSI_platform.cpp +++ b/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; } } diff --git a/src/ZuluSCSI_initiator.cpp b/src/ZuluSCSI_initiator.cpp index 3809a0a5..b7bdd594 100644 --- a/src/ZuluSCSI_initiator.cpp +++ b/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); } diff --git a/src/ZuluSCSI_log.cpp b/src/ZuluSCSI_log.cpp index f1992b76..c5c14887 100644 --- a/src/ZuluSCSI_log.cpp +++ b/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; } diff --git a/src/ZuluSCSI_log.h b/src/ZuluSCSI_log.h index 63dfbc09..c039dcdf 100644 --- a/src/ZuluSCSI_log.h +++ b/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;