Add back Serial USB logging with SRAM optimizations.

This commit is derived from code from @morio across the following
commits plus my own adjustments for the BlueSCSI platform:
Output log over serial USB
https://github.com/ZuluSCSI/ZuluSCSI-firmware/commit/573dc60ca91c54363a0bdad20ba37e3029807c6e
Fix out SRAM compile time issue
https://github.com/ZuluSCSI/ZuluSCSI-firmware/commit/30df3aae306da34df292fc7ce5278a2a891e9f66
Adjust prefetch buffer to fix SRAM overflow
https://github.com/ZuluSCSI/ZuluSCSI-firmware/commit/9f61b3cdfbdda92359c23fd0fc12a0b7ccffc486
Get PlatformIO debug to work on RP2040 MCUs
https://github.com/ZuluSCSI/ZuluSCSI-firmware/commit/d72012b3bc91539bbcea2c25ad1dec41d94f98a5

Co-authored-by: Morio <morio.earth@gmail.com>

lib/BlueSCSI_platform_RP2040/BlueSCSI_platform.cpp

@@ -17,11 +17,18 @@
 #include <hardware/flash.h>
 #include <hardware/structs/xip_ctrl.h>
 #include <hardware/structs/usb.h>
-#ifdef MBED
-#include <platform/mbed_error.h>
-#include <USB/PluggableUSBSerial.h>
+#ifdef ENABLE_AUDIO_OUTPUT
 #include "audio.h"
 #endif
+
+#ifndef __MBED__
+# include <SerialUSB.h>
+# include <class/cdc/cdc_device.h>
+#else
+# include <platform/mbed_error.h>
+# include <USB/PluggableUSBSerial.h>
+#endif // __MBED__
+
 #include <pico/multicore.h>
 #include "scsi_accel_rp2040.h"
 #include "hardware/i2c.h"
@@ -282,6 +289,11 @@ void platform_late_init()
         gpio_conf(scsi_pins.IN_ATN,    GPIO_FUNC_SIO, false, false, false, true, false);
         gpio_conf(scsi_pins.IN_RST,    GPIO_FUNC_SIO, true, false, false, true, false);
 
+
+#ifndef __MBED__
+    Serial.begin();
+#endif // __MBED__
+
 #ifdef ENABLE_AUDIO_OUTPUT
         // one-time control setup for DMA channels and second core
         audio_setup();
@@ -416,11 +428,27 @@ void mbed_error_hook(const mbed_error_ctx * error_context)
 // also starts calling this after 2 seconds.
 // This ensures that log messages get passed even if code hangs,
 // but does not unnecessarily delay normal execution.
-#ifdef MBED
 static void usb_log_poll()
 {
     static uint32_t logpos = 0;
+#ifndef __MBED__
+    if (Serial.availableForWrite())
+    {
+        // Retrieve pointer to log start and determine number of bytes available.
+        uint32_t available = 0;
+        const char *data = log_get_buffer(&logpos, &available);
+                // Limit to CDC packet size
+        uint32_t len = available;
+        if (len == 0) return;
+        if (len > CFG_TUD_CDC_EP_BUFSIZE) len = CFG_TUD_CDC_EP_BUFSIZE;
 
+        // Update log position by the actual number of bytes sent
+        // If USB CDC buffer is full, this may be 0
+        uint32_t actual = 0;
+        actual = Serial.write(data, len);
+        logpos -= available - actual;
+    }
+#else
     if (_SerialUSB.ready())
     {
         // Retrieve pointer to log start and determine number of bytes available.
@@ -438,8 +466,8 @@ static void usb_log_poll()
         _SerialUSB.send_nb((uint8_t*)data, len, &actual);
         logpos -= available - actual;
     }
+#endif // __MBED__
 }
-#endif
 
 // Use ADC to implement supply voltage monitoring for the +3.0V rail.
 // This works by sampling the temperature sensor channel, which has
@@ -520,13 +548,11 @@ static void watchdog_callback(unsigned alarm_num)
 {
     g_watchdog_timeout -= 1000;
 
-#ifdef MBED
     if (g_watchdog_timeout < WATCHDOG_CRASH_TIMEOUT - 1000)
     {
         // Been stuck for at least a second, start dumping USB log
         usb_log_poll();
     }
-#endif
 
     if (g_watchdog_timeout <= WATCHDOG_CRASH_TIMEOUT - WATCHDOG_BUS_RESET_TIMEOUT)
     {
@@ -573,9 +599,8 @@ static void watchdog_callback(unsigned alarm_num)
                 p += 4;
             }
 
-#ifdef MBED
             usb_log_poll();
-#endif
+
             platform_emergency_log_save();
 
             platform_boot_to_main_firmware();
@@ -613,20 +638,17 @@ void platform_reset_watchdog()
         g_watchdog_initialized = true;
     }
 
-#ifdef MBED
     // USB log is polled here also to make sure any log messages in fault states
     // get passed to USB.
     usb_log_poll();
-#endif
 }
 
 // Poll function that is called every few milliseconds.
 // Can be left empty or used for platform-specific processing.
 void platform_poll()
 {
-#ifdef MBED
     usb_log_poll();
-#endif
+
     adc_poll();
     
 #ifdef ENABLE_AUDIO_OUTPUT
@@ -692,15 +714,14 @@ bool platform_rewrite_flash_page(uint32_t offset, uint8_t buffer[PLATFORM_FLASH_
             return false;
         }
     }
-
-#ifdef MBED
+#ifdef __MBED__
     if (NVIC_GetEnableIRQ(USBCTRL_IRQn))
     {
         log("Disabling USB during firmware flashing");
         NVIC_DisableIRQ(USBCTRL_IRQn);
         usb_hw->main_ctrl = 0;
     }
-#endif
+#endif // __MBED__
 
     debuglog("Writing flash at offset ", offset, " data ", bytearray(buffer, 4));
     assert(offset % PLATFORM_FLASH_PAGE_SIZE == 0);

lib/BlueSCSI_platform_RP2040/rp2040.ld

@@ -1,7 +1,7 @@
 MEMORY
 {
     FLASH(rx) : ORIGIN = 0x10000000, LENGTH = 352k
-    RAM(rwx) : ORIGIN = 0x20000000, LENGTH = 240k  /* Leave space for pico-debug */
+    RAM(rwx) : ORIGIN = 0x20000000, LENGTH = 256k  /* Leave space for pico-debug */
     SCRATCH_X(rwx) : ORIGIN = 0x20040000, LENGTH = 4k
     SCRATCH_Y(rwx) : ORIGIN = 0x20041000, LENGTH = 4k
 }

lib/SCSI2SD/src/firmware/log.h

@@ -14,14 +14,32 @@
 //
 //	You should have received a copy of the GNU General Public License
 //	along with SCSI2SD.  If not, see <http://www.gnu.org/licenses/>.
+#ifndef SCSI2SD_LOG_H
+#define SCSI2SD_LOG_H
+#include <stdbool.h>
+
 
 #ifdef __cplusplus
 extern "C" {
 #endif
 
+extern bool g_log_debug;
+
 extern void log_buf(const unsigned char *buf, unsigned long size);
 extern void log_f(const char *format, ...);
 
+extern void dbgmsg_buf(const unsigned char *buf, unsigned long size);
+extern void dbgmsg_f(const char *format, ...);
+
+// check if debug is enabled before calling the logging function
+#define DBGMSG_BUF(buf, size) \
+	if (g_log_debug) {dbgmsg_buf(buf, size);}
+
+#define DBGMSG_F(format, ...) \
+	if (g_log_debug) {dbgmsg_f(format, __VA_ARGS__);}
+
 #ifdef __cplusplus
 }
-#endif
+#endif
+
+#endif // SCSI2SD_LOG_H

lib/SCSI2SD/src/firmware/network.c

@@ -22,8 +22,6 @@
 #include "config.h"
 #include "network.h"
 
-extern bool g_log_debug;
-
 static bool scsiNetworkEnabled = false;
 
 struct scsiNetworkPacketQueue {
@@ -104,10 +102,7 @@ int scsiNetworkCommand()
 	uint8_t command = scsiDev.cdb[0];
 	uint8_t cont = (scsiDev.cdb[5] == 0x80);
 
-	if (g_log_debug)
-	{
-		log_f("in scsiNetworkCommand with command 0x%02x (size %d)", command, size);
-	}
+	DBGMSG_F("------ in scsiNetworkCommand with command 0x%02x (size %d)", command, size);
 
 	switch (command) {
 	case 0x08:
@@ -140,10 +135,7 @@ int scsiNetworkCommand()
 				psize = size - 6;
 			}
 
-			if (g_log_debug)
-			{
-				log_f("%s: sending packet[%d] to host of size %zu + 6", __func__, scsiNetworkInboundQueue.readIndex, psize);
-			}
+			DBGMSG_F("%s: sending packet[%d] to host of size %zu + 6", __func__, scsiNetworkInboundQueue.readIndex, psize);
 
 			scsiDev.dataLen = psize + 6; // 2-byte length + 4-byte flag + packet
 			memcpy(scsiDev.data + 6, scsiNetworkInboundQueue.packets[scsiNetworkInboundQueue.readIndex], psize);
@@ -162,10 +154,7 @@ int scsiNetworkCommand()
 			// more data to read?
 			scsiDev.data[5] = (scsiNetworkInboundQueue.readIndex == scsiNetworkInboundQueue.writeIndex ? 0 : 0x10);
 
-			if (g_log_debug)
-			{
-				log_buf(scsiDev.data, scsiDev.dataLen);
-			}
+			DBGMSG_BUF(scsiDev.data, scsiDev.dataLen);
 		}
 
 		// DaynaPort driver needs a delay between reading the initial packet size and the data so manually do two transfers
@@ -217,10 +206,14 @@ int scsiNetworkCommand()
 		parityError = 0;
 		scsiRead(scsiDev.data, size, &parityError);
 
-		if (g_log_debug)
+		if (parityError)
 		{
-			log_f("%s: read packet from host of size %zu - %d (parity error %d)", __func__, size, (cont ? 4 : 0), parityError);
-			log_buf(scsiDev.data, size);
+			DBGMSG_F("%s: read packet from host of size %zu - %d (parity error %d)", __func__, size, (cont ? 4 : 0), parityError);
+			DBGMSG_F(scsiDev.data, size);
+		}
+		else
+		{
+			DBGMSG_F("------ %s: read packet from host of size %zu - %d", __func__, size, (cont ? 4 : 0));
 		}
 
 		if (cont)
@@ -253,11 +246,8 @@ int scsiNetworkCommand()
 		parityError = 0;
 		scsiRead(scsiDev.data, size, &parityError);
 
-		if (g_log_debug)
-		{
-			log_f("%s: adding multicast address %02x:%02x:%02x:%02x:%02x:%02x", __func__,
+		DBGMSG_F("%s: adding multicast address %02x:%02x:%02x:%02x:%02x:%02x", __func__,
 			  scsiDev.data[0], scsiDev.data[1], scsiDev.data[2], scsiDev.data[3], scsiDev.data[4], scsiDev.data[5]);
-		}
 
 		platform_network_add_multicast_address(scsiDev.data);
 
@@ -269,20 +259,16 @@ int scsiNetworkCommand()
 		// toggle interface
 		if (scsiDev.cdb[5] & 0x80)
 		{
-			if (g_log_debug)
-			{
-				log_f("%s: enable interface", __func__);
-			}
+
+			DBGMSG_F("%s: enable interface", __func__);
 			scsiNetworkEnabled = true;
 			memset(&scsiNetworkInboundQueue, 0, sizeof(scsiNetworkInboundQueue));
 			memset(&scsiNetworkOutboundQueue, 0, sizeof(scsiNetworkOutboundQueue));
 		}
 		else
 		{
-			if (g_log_debug)
-			{
-				log_f("%s: disable interface", __func__);
-			}
+
+			DBGMSG_F("%s: disable interface", __func__);
 			scsiNetworkEnabled = false;
 		}
 		break;
@@ -303,10 +289,7 @@ int scsiNetworkCommand()
 
 	// custom wifi commands all using the same opcode, with a sub-command in cdb[2]
 	case SCSI_NETWORK_WIFI_CMD:
-		if (g_log_debug)
-		{
-			log_f("in scsiNetworkCommand with wi-fi command 0x%02x (size %d)", scsiDev.cdb[1], size);
-		}
+		DBGMSG_F("in scsiNetworkCommand with wi-fi command 0x%02x (size %d)", scsiDev.cdb[1], size);
 
 		switch (scsiDev.cdb[1]) {
 		case SCSI_NETWORK_WIFI_CMD_SCAN:
@@ -404,11 +387,8 @@ int scsiNetworkCommand()
 			parityError = 0;
 			scsiRead((uint8_t *)&req, sizeof(req), &parityError);
 
-			if (g_log_debug)
-			{
-				log_f("%s: read join request from host:", __func__);
-				log_buf(scsiDev.data, size);
-			}
+			DBGMSG_F("%s: read join request from host:", __func__);
+			DBGMSG_BUF(scsiDev.data, size);
 
 			platform_network_wifi_join(req.ssid, req.key);
 
@@ -433,8 +413,7 @@ int scsiNetworkEnqueue(const uint8_t *buf, size_t len)
 
 	if (len + 4 > sizeof(scsiNetworkInboundQueue.packets[0]))
 	{
-		if (g_log_debug)
-			log_f("%s: dropping incoming network packet, too large (%zu > %zu)", __func__, len, sizeof(scsiNetworkInboundQueue.packets[0]));
+		DBGMSG_F("%s: dropping incoming network packet, too large (%zu > %zu)", __func__, len, sizeof(scsiNetworkInboundQueue.packets[0]));
 		return 0;
 	}
 
@@ -454,8 +433,7 @@ int scsiNetworkEnqueue(const uint8_t *buf, size_t len)
 
 	if (scsiNetworkInboundQueue.writeIndex == scsiNetworkInboundQueue.readIndex)
 	{
-		if (g_log_debug)
-			log_f("%s: dropping packets in ring, write index caught up to read index", __func__);
+		DBGMSG_F("%s: dropping packets in ring, write index caught up to read index", __func__);
 	}
 	
 	return 1;

platformio.ini

@@ -18,12 +18,22 @@ platform_packages = platformio/toolchain-gccarmnoneeabi@1.100301.220327
 framework = arduino
 board = rpipicow
 board_build.core = earlephilhower
+upload_protocol = picoprobe
+debug_tool = cmsis-dap ; new picoprobe.uf2's emulate cmsis-dap
+; extra_scripts = src/build_bootloader.py
+; ldscript_bootloader = lib/BlueSCSI_platform_RP2040/rp2040_btldr.ld
 lib_deps =
     SdFat=https://github.com/BlueSCSI/SdFat#2.2.0-gpt
     minIni
     BlueSCSI_platform_RP2040
     SCSI2SD
     CUEParser
+debug_build_flags =
+    -O2 -ggdb -g3
+; The values can be adjusted down to get a debug build to fit in to SRAM
+    -DLOGBUFSIZE=1024
+    -DSCSI2SD_BUFFER_SIZE=57344
+    -DPREFETCH_BUFFER_SIZE=6144
 build_flags =
     -O2 -Isrc -ggdb -g3
     -Wall -Wno-sign-compare -Wno-ignored-qualifiers
@@ -32,9 +42,11 @@ build_flags =
     -DENABLE_DEDICATED_SPI=1
     -DHAS_SDIO_CLASS
     -DUSE_ARDUINO=1
-    -DNO_USB=1
     -DPICO_DEFAULT_I2C_SDA_PIN=16
     -DPICO_DEFAULT_I2C_SCL_PIN=17
+    ; -DLOGBUFSIZE=8192
+    ; -DPREFETCH_BUFFER_SIZE=6144
+    ; -DSCSI2SD_BUFFER_SIZE=57344
 
 ; Experimental Audio build
 ; Rquires seperate hardware and overclock. 

src/BlueSCSI_log.cpp

@@ -222,3 +222,71 @@ const char *log_get_buffer(uint32_t *startpos, uint32_t *available)
     return result;
 }
 
+// TODO write directly global log buffer to save some memory
+static char shared_log_buf[1500 * 3];
+
+// core method for variadic printf like logging
+static void log_va(bool debug, const char *format, va_list ap)
+{
+    vsnprintf(shared_log_buf, sizeof(shared_log_buf), format, ap);
+    if (debug)
+    {
+        debuglog(shared_log_buf);
+    }
+    else
+    {
+        log(shared_log_buf);
+    }
+}
+
+void logmsg_f(const char *format, ...)
+{
+    va_list ap;
+    va_start(ap, format);
+    log_va(false, format, ap);
+    va_end(ap);
+}
+
+void dbgmsg_f(const char *format, ...)
+{
+    if (!g_log_debug)
+        return;
+    va_list ap;
+    va_start(ap, format);
+    log_va(true, format, ap);
+    va_end(ap);
+}
+
+// core method for logging a data buffer into a hex string
+void log_hex_buf(const unsigned char *buf, unsigned long size, bool debug)
+{
+    static char hex[] = "0123456789abcdef";
+    int o = 0;
+
+    for (int j = 0; j < size; j++) {
+        if (o + 3 >= sizeof(shared_log_buf))
+            break;
+
+        if (j != 0)
+            shared_log_buf[o++] = ' ';
+        shared_log_buf[o++] = hex[(buf[j] >> 4) & 0xf];
+        shared_log_buf[o++] = hex[buf[j] & 0xf];
+        shared_log_buf[o] = 0;
+    }
+    if (debug)
+        debuglog(shared_log_buf);
+    else
+        log(shared_log_buf);
+}
+
+void logmsg_buf(const unsigned char *buf, unsigned long size)
+{
+    log_hex_buf(buf, size, false);
+}
+
+void dbgmsg_buf(const unsigned char *buf, unsigned long size)
+{
+    if (!g_log_debug)
+        return;
+    log_hex_buf(buf, size, true);
+}

src/BlueSCSI_log.h

@@ -16,7 +16,7 @@ uint32_t log_get_buffer_len();
 const char *log_get_buffer(uint32_t *startpos, uint32_t *available = nullptr);
 
 // Whether to enable debug messages
-extern bool g_log_debug;
+extern "C" bool g_log_debug;
 
 // Enables output test mode
 extern bool g_test_mode;
@@ -102,3 +102,23 @@ inline void debuglog(Params... params)
         log_raw("\n");
     }
 }
+
+#ifdef __cplusplus
+extern "C" {
+#endif
+// Log long hex string
+void logmsg_buf(const unsigned char *buf, unsigned long size);
+
+// Log long hex string
+void dbgmsg_buf(const unsigned char *buf, unsigned long size);
+
+// Log formatted string
+void logmsg_f(const char *format, ...);
+
+// Log formatted string
+void dbgmsg_f(const char *format, ...);
+
+
+#ifdef __cplusplus
+}
+#endif