Improve logging & add crash handler

lib/AzulSCSI_platform_GD32F205/AzulSCSI_platform.cpp

@@ -1,10 +1,13 @@
 #include "AzulSCSI_platform.h"
 #include "gd32f20x_spi.h"
 #include "AzulSCSI_log.h"
+#include "AzulSCSI_config.h"
 #include <SdFat.h>
 
 extern "C" {
 
+const char *g_azplatform_name = "GD32F205 AzulSCSI v1.x";
+
 static volatile uint32_t g_millisecond_counter;
 
 unsigned long millis()
@@ -102,16 +105,24 @@ void azplatform_init()
     // SWO trace pin on PB3
     gpio_init(GPIOB, GPIO_MODE_AF_PP, GPIO_OSPEED_50MHZ, GPIO_PIN_3);
 
-    azlogn("GPIO init complete");
-
     if (gpio_input_bit_get(DIP_PORT, DIPSW3_PIN))
     {
-        azlogn("DIPSW3 is ON: Enabling SCSI termination");
+        azlog("DIPSW3 is ON: Enabling SCSI termination");
         gpio_bit_reset(SCSI_TERM_EN_PORT, SCSI_TERM_EN_PIN);
     }
     else
     {
-        azlogn("DIPSW3 is OFF: SCSI termination disabled");
+        azlog("DIPSW3 is OFF: SCSI termination disabled");
+    }
+
+    if (gpio_input_bit_get(DIP_PORT, DIPSW2_PIN))
+    {
+        azlog("DIPSW2 is ON: enabling debug messages");
+        g_azlog_debug = true;
+    }
+    else
+    {
+        g_azlog_debug = false;
     }
 }
 
@@ -141,24 +152,96 @@ void SCSI_RST_IRQ (void)
 /* Crash handlers                        */
 /*****************************************/
 
+extern SdFs SD;
+
+void azplatform_emergency_log_save()
+{
+    FsFile crashfile = SD.open(CRASHFILE, O_WRONLY | O_CREAT | O_TRUNC);
+
+    if (!crashfile.isOpen())
+    {
+        // Try to reinitialize
+        int max_retry = 10;
+        while (max_retry-- > 0 && !SD.begin(SD_CONFIG));
+
+        crashfile = SD.open(CRASHFILE, O_WRONLY | O_CREAT | O_TRUNC);
+    }
+
+    uint32_t startpos = 0;
+    crashfile.write(azlog_get_buffer(&startpos));
+    crashfile.write(azlog_get_buffer(&startpos));
+    crashfile.flush();
+    crashfile.close();
+}
+
+__attribute__((noinline))
+void show_hardfault(uint32_t *sp)
+{
+    uint32_t pc = sp[6];
+    uint32_t lr = sp[5];
+    uint32_t cfsr = SCB->CFSR;
+    
+    azlog("--------------");
+    azlog("CRASH!");
+    azlog("Platform: ", g_azplatform_name);
+    azlog("FW Version: ", g_azlog_firmwareversion);
+    azlog("CFSR: ", cfsr);
+    azlog("PC: ", pc);
+    azlog("LR: ", lr);
+    azlog("R0: ", sp[0]);
+    azlog("R1: ", sp[1]);
+    azlog("R2: ", sp[2]);
+    azlog("R3: ", sp[3]);
+
+    azplatform_emergency_log_save();
+
+    while (1)
+    {
+        // Flash the crash address on the LED
+        // Short pulse means 0, long pulse means 1
+        int base_delay = 500000;
+        for (int i = 31; i >= 0; i--)
+        {
+            LED_OFF();
+            for (int j = 0; j < base_delay; j++) delay_100ns();
+            
+            int delay = (pc & (1 << i)) ? (3 * base_delay) : base_delay;
+            LED_ON();
+            for (int j = 0; j < delay; j++) delay_100ns();
+            LED_OFF();
+        }
+
+        for (int j = 0; j < base_delay * 10; j++) delay_100ns();
+    }
+}
+
+__attribute__((naked))
 void HardFault_Handler(void)
 {
-    while (1);
+    // Copies stack pointer into first argument
+    asm("mrs r0, msp\n"
+        "b show_hardfault": : : "r0");
 }
 
+__attribute__((naked))
 void MemManage_Handler(void)
 {
-    while (1);
+    asm("mrs r0, msp\n"
+        "b show_hardfault": : : "r0");
 }
 
+__attribute__((naked))
 void BusFault_Handler(void)
 {
-    while (1);
+    asm("mrs r0, msp\n"
+        "b show_hardfault": : : "r0");
 }
 
+__attribute__((naked))
 void UsageFault_Handler(void)
 {
-    while (1);
+    asm("mrs r0, msp\n"
+        "b show_hardfault": : : "r0");
 }
 
 } /* extern "C" */

lib/AzulSCSI_platform_GD32F205/AzulSCSI_platform.h

@@ -15,6 +15,8 @@ extern SdSpiConfig g_sd_spi_config;
 extern "C" {
 #endif
 
+extern const char *g_azplatform_name;
+
 // GPIO definitions
 
 // SCSI output port.
@@ -109,7 +111,11 @@ void delay(unsigned long ms);
 // Precise nanosecond delays
 static inline void delay_100ns()
 {
-    asm("nop"); asm("nop"); asm("nop"); asm("nop"); asm("nop");
+#if HXTAL_VALUE==8000000
+    asm("nop"); asm("nop"); asm("nop");
+#else
+    asm("nop"); asm("nop"); asm("nop"); asm("nop"); asm("nop"); asm("nop"); asm("nop");
+#endif
 }
 
 // Initialize SPI and GPIO configuration
@@ -118,6 +124,10 @@ void azplatform_init();
 // Set callback for when SCSI_RST pin goes low
 void azplatform_set_rst_callback(void (*callback)());
 
+// Reinitialize SD card connection and save log from interrupt context.
+// This can be used in crash handlers.
+void azplatform_emergency_log_save();
+
 // Write a single SCSI pin.
 // Example use: SCSI_OUT(ATN, 1) sets SCSI_ATN to low (active) state.
 #define SCSI_OUT(pin, state) \

src/AzulSCSI.cpp

@@ -59,7 +59,7 @@ SdFs SD;
 
 void blinkStatus(int count)
 {
-  azlogn("Blinking status code: ", count);
+  azlog("Blinking status code: ", count);
   for (int i = 0; i < count; i++)
   {
     LED_ON();
@@ -157,7 +157,7 @@ bool hddimageOpen(HDDIMG *h,const char *image_name,int id,int lun,int blocksize)
   if(h->m_file.isOpen())
   {
     h->m_fileSize = h->m_file.size();
-    azlogn("Opened image file ", image_name, " fileSize: ", (int)h->m_fileSize, " bytes");
+    azlog("Opened image file ", image_name, " fileSize: ", (int)h->m_fileSize, " bytes");
     
     if(h->m_fileSize > 0)
     {
@@ -167,7 +167,7 @@ bool hddimageOpen(HDDIMG *h,const char *image_name,int id,int lun,int blocksize)
     {
       h->m_file.close();
       h->m_fileSize = h->m_blocksize = 0; // no file
-      azlogn("Error: image is empty");
+      azlog("Error: image is empty");
     }
   }
   return false;
@@ -201,9 +201,13 @@ void findHDDImages()
         if(file_name_length > 2) { // HD[N]
           int tmp_id = name[HDIMG_ID_POS] - '0';
 
-          if(tmp_id > -1 && tmp_id < 8) {
+          if(tmp_id > -1 && tmp_id < 8)
+          {
             id = tmp_id; // If valid id, set it, else use default
-            usedDefaultId++;
+          }
+          else
+          {
+            id = usedDefaultId++;
           }
         }
         if(file_name_length > 3) { // HD0[N]
@@ -231,57 +235,57 @@ void findHDDImages()
 
         if(id < NUM_SCSIID && lun < NUM_SCSILUN) {
           HDDIMG *h = &g_hddimg[id][lun];
-          azlogn("Trying to open ", name, " for id:", id, " lun:", lun);
+          azlog("Trying to open ", name, " for id:", id, " lun:", lun);
           imageReady = hddimageOpen(h,name,id,lun,blk);
           if(imageReady) { // Marked as a responsive ID
             g_scsi_id_mask |= 1<<id;
           }
         } else {
-          azlogn("Invalid lun or id for image ", name);
+          azlog("Invalid lun or id for image ", name);
         }
       } else {
-        azlogn("Skipping file ", name);
+        azlog("Skipping file ", name);
       }
     }
   }
 
   if(usedDefaultId > 0) {
-    azlogn("!! More than one image did not specify a SCSI ID. Last file will be used at ID 1. !!");
+    azlog("Some images did not specify a SCSI ID. Last file will be used at ID ", usedDefaultId);
   }
   root.close();
 
   // Error if there are 0 image files
   if(g_scsi_id_mask==0) {
-    azlogn("ERROR: No valid images found!");
+    azlog("ERROR: No valid images found!");
     blinkStatus(BLINK_ERROR_NO_IMAGES);
   }
 
   // Print SCSI drive map
-  azlogn("SCSI drive map:");
-  azlog("ID");
+  azlog("SCSI drive map:");
+  azlog_raw("ID");
   for (int lun = 0; lun < NUM_SCSILUN; lun++)
   {
-    azlog(":LUN", lun);
+    azlog_raw(":LUN", lun);
   }
-  azlogn(":");
+  azlog_raw(":\n");
 
   for (int id = 0; id < NUM_SCSIID; id++)
   {
-    azlog(" ", id);
+    azlog_raw(" ", id);
     for (int lun = 0; lun < NUM_SCSILUN; lun++)
     {
       HDDIMG *h = &g_hddimg[id][lun];
       if (h->m_file)
       {
-        azlog((h->m_blocksize<1000) ? ": " : ":");
-        azlog((int)h->m_blocksize);
+        azlog_raw((h->m_blocksize<1000) ? ": " : ":");
+        azlog_raw((int)h->m_blocksize);
       }
       else
       {
-        azlog(":----");
+        azlog_raw(":----");
       }
     }
-    azlogn(":");
+    azlog_raw(":\n");
   }
 }
 
@@ -442,7 +446,7 @@ uint8_t onReadCapacityCommand(uint8_t pmi)
 // READ6 / 10 Command processing.
 uint8_t onReadCommand(uint32_t adds, uint32_t len)
 {
-  azlogn("R ", adds, " ", (int)len);
+  azdbg("Read at ", adds, " ", (int)len, " blocks");
   
   if(!g_currentimg) return 0x02; // Image file absent
   
@@ -455,7 +459,7 @@ uint8_t onReadCommand(uint32_t adds, uint32_t len)
 // WRITE6 / 10 Command processing.
 uint8_t onWriteCommand(uint32_t adds, uint32_t len)
 {
-  azlogn("W ", adds, " ", (int)len);
+  azdbg("Write at ", adds, " ", (int)len, " blocks");
   
   if(!g_currentimg) return 0x02; // Image file absent
   
@@ -530,7 +534,7 @@ uint8_t onModeSenseCommand_NEC_PC98(uint8_t dbd, int cmd2, uint32_t len)
   }
   case 0x04:  // drive parameters
   {
-      azlogn("AddDrive");
+      azdbg("onModeSenseCommand_NEC_PC98: AddDrive");
       buf[a + 0] = 0x04; // Page code
       buf[a + 1] = 0x12; // Page length
       buf[a + 2] = (cylinders >> 16);// Cylinder length
@@ -642,14 +646,14 @@ static uint8_t dtc510b_setDriveparameter(void)
     (DriveParameter.LowCylinderAddressuint8_t);
   numLAD = maxCylinder * (DriveParameter.MaximumHeadAdress+1);
   // StepPeriodMsec = DriveParameter.StepPeriod*50;
-  azlogn(" StepPlusWidth      : ",DriveParameter.StepPlusWidth);
-  azlogn(" StepPeriod         : ",DriveParameter.StepPeriod   );
-  azlogn(" StepMode           : ",DriveParameter.StepMode     );
-  azlogn(" MaximumHeadAdress  : ",DriveParameter.MaximumHeadAdress);
-  azlogn(" CylinderAddress    : ",maxCylinder);
-  azlogn(" ReduceWrietCurrent : ",DriveParameter.ReduceWrietCurrent);
-  azlogn(" DriveType/SeekCompleteOption : ",DriveParameter.DriveType_SeekCompleteOption);
-  azlogn(" Maximum LAD        : ",numLAD-1);
+  azdbg(" StepPlusWidth      : ",DriveParameter.StepPlusWidth);
+  azdbg(" StepPeriod         : ",DriveParameter.StepPeriod   );
+  azdbg(" StepMode           : ",DriveParameter.StepMode     );
+  azdbg(" MaximumHeadAdress  : ",DriveParameter.MaximumHeadAdress);
+  azdbg(" CylinderAddress    : ",maxCylinder);
+  azdbg(" ReduceWriteCurrent : ",DriveParameter.ReduceWrietCurrent);
+  azdbg(" DriveType/SeekCompleteOption : ",DriveParameter.DriveType_SeekCompleteOption);
+  azdbg(" Maximum LAD        : ",numLAD-1);
   return  0;
 }
 
@@ -672,6 +676,8 @@ int readSCSICommand(uint8_t cmd[12])
     if (g_busreset) return 0;
   }
 
+  azdbg("Got command (", cmdlen, " bytes): ", bytearray(cmd, cmdlen));
+
   return cmdlen;
 }
 
@@ -709,30 +715,30 @@ bool onATNMessage()
     return false;
   }
 
-  azlogn("Received MSG, ", (int)msg_bytes, " bytes, first byte ", msg[0]);
+  azdbg("Received MSG ", (int)msg_bytes, " bytes: ", bytearray(msg, msg_bytes));
 
   for (int i = 0; i < msg_bytes; i++)
   {
     // ABORT
     if (msg[i] == 0x06) {
-      azlogn("MSG_ABORT");
+      azdbg("MSG_ABORT");
       return false;
     }
 
     // BUS DEVICE RESET
     if (msg[i] == 0x0C) {
-      azlogn("MSG_BUS_DEVICE_RESET");
+      azdbg("MSG_BUS_DEVICE_RESET");
       return false;
     }
 
     // IDENTIFY
     if (msg[i] >= 0x80) {
-      azlogn("MSG_IDENTIFY");
+      azdbg("MSG_IDENTIFY");
     }
 
     // Extended message
     if (msg[i] == 0x01) {
-      azlogn("MSG_EXTENDED");
+      azdbg("MSG_EXTENDED");
 
       // Check only when synchronous transfer is possible
       if (!syncenable || msg[i + 2] != 0x01) {
@@ -763,7 +769,7 @@ bool onATNMessage()
 
   if (responselen > 0)
   {
-    azlogn("Sending MSG response, ", (int)responselen, " bytes, first byte ", response[0]);
+    azdbg("Sending MSG response, ", (int)responselen, " bytes: ", bytearray(response, responselen));
     SCSI_OUT(MSG,  active);
     SCSI_OUT(CD ,  active);
     SCSI_OUT(IO ,  active);
@@ -804,7 +810,7 @@ void scsi_loop()
   
   // Set BSY to-when selected
   SCSI_OUT(BSY, active);
-  azlogn("SCSI device selected");
+  azdbg("SCSI device selected");
   
   // Ask for a TARGET-ID to respond
   g_scsi_id = 0;
@@ -859,59 +865,58 @@ void scsi_loop()
       g_currentimg = (HDDIMG *)0;       // Image absent
   }
   
-  azlog("CMD ", cmd[0], " (", cmdlen, " bytes): ");
-  azlog("ID", (int)g_scsi_id, ", LUN", (int)g_scsi_lun, " ");
+  azdbg("CMD ", cmd[0], " (", cmdlen, " bytes): ", "ID", (int)g_scsi_id, ", LUN", (int)g_scsi_lun);
   
   switch(cmd[0]) {
-    case 0x00: azlogn("[Test Unit]"); break;
-    case 0x01: azlogn("[Rezero Unit]"); break;
+    case 0x00: azdbg("[Test Unit]"); break;
+    case 0x01: azdbg("[Rezero Unit]"); break;
     case 0x03:
-      azlogn("[RequestSense]");
+      azdbg("[RequestSense]");
       onRequestSenseCommand(cmd[4]);
       break;
-    case 0x04: azlogn("[FormatUnit]"); break;
-    case 0x06: azlogn("[FormatUnit]"); break;
-    case 0x07: azlogn("[ReassignBlocks]"); break;
+    case 0x04: azdbg("[FormatUnit]"); break;
+    case 0x06: azdbg("[FormatUnit]"); break;
+    case 0x07: azdbg("[ReassignBlocks]"); break;
     case 0x08:
-      azlogn("[Read6]");
+      azdbg("[Read6]");
       g_scsi_sts |= onReadCommand((((uint32_t)cmd[1] & 0x1F) << 16) | ((uint32_t)cmd[2] << 8) | cmd[3], (cmd[4] == 0) ? 0x100 : cmd[4]);
       break;
     case 0x0A:
-      azlogn("[Write6]");
+      azdbg("[Write6]");
       g_scsi_sts |= onWriteCommand((((uint32_t)cmd[1] & 0x1F) << 16) | ((uint32_t)cmd[2] << 8) | cmd[3], (cmd[4] == 0) ? 0x100 : cmd[4]);
       break;
-    case 0x0B: azlogn("[Seek6]"); break;
+    case 0x0B: azdbg("[Seek6]"); break;
     case 0x12:
-      azlogn("[Inquiry]");
+      azdbg("[Inquiry]");
       g_scsi_sts |= onInquiryCommand(cmd[4]);
       break;
     case 0x1A:
-      azlogn("[ModeSense6]");
+      azdbg("[ModeSense6]");
       g_scsi_sts |= onModeSenseCommand(cmd[1]&0x80, cmd[2], cmd[4]);
       break;
-    case 0x1B: azlogn("[StartStopUnit]"); break;
-    case 0x1E: azlogn("[PreAllowMed.Removal]"); break;
+    case 0x1B: azdbg("[StartStopUnit]"); break;
+    case 0x1E: azdbg("[PreAllowMed.Removal]"); break;
     case 0x25:
-      azlogn("[ReadCapacity]");
+      azdbg("[ReadCapacity]");
       g_scsi_sts |= onReadCapacityCommand(cmd[8]);
       break;
     case 0x28:
-      azlogn("[Read10]");
+      azdbg("[Read10]");
       g_scsi_sts |= onReadCommand(((uint32_t)cmd[2] << 24) | ((uint32_t)cmd[3] << 16) | ((uint32_t)cmd[4] << 8) | cmd[5], ((uint32_t)cmd[7] << 8) | cmd[8]);
       break;
     case 0x2A:
-      azlogn("[Write10]");
+      azdbg("[Write10]");
       g_scsi_sts |= onWriteCommand(((uint32_t)cmd[2] << 24) | ((uint32_t)cmd[3] << 16) | ((uint32_t)cmd[4] << 8) | cmd[5], ((uint32_t)cmd[7] << 8) | cmd[8]);
       break;
-    case 0x2B: azlogn("[Seek10]"); break;
+    case 0x2B: azdbg("[Seek10]"); break;
     case 0x5A:
-      azlogn("[ModeSense10]");
+      azdbg("[ModeSense10]");
       onModeSenseCommand(cmd[1] & 0x80, cmd[2], ((uint32_t)cmd[7] << 8) | cmd[8]);
       break;
     case 0xc2:
       if (g_scsi_quirks == SCSI_QUIRKS_SHARP)
       {
-        azlogn("[DTC510B setDriveParameter]");
+        azdbg("[DTC510B setDriveParameter]");
         g_scsi_sts |= dtc510b_setDriveparameter();
       }
       else
@@ -922,7 +927,7 @@ void scsi_loop()
       break;
       
     default:
-      azlogn("[*Unknown]");
+      azdbg("[Unknown CMD: ", cmd[0], "]");
       g_scsi_sts |= 0x02;
       g_sensekey = 5;
       break;
@@ -933,7 +938,7 @@ void scsi_loop()
      return;
   }
 
-  azlogn("Status: ", g_scsi_sts);
+  azdbg("Status: ", g_scsi_sts);
   SCSI_OUT(MSG,inactive);
   SCSI_OUT(CD ,  active);
   SCSI_OUT(IO ,  active);
@@ -949,7 +954,7 @@ void scsi_loop()
   SCSI_OUT(IO ,  active);
   writeHandshake(0);
 
-  azlogn("Command complete");
+  azdbg("Command complete");
   SCSI_RELEASE_OUTPUTS();
 }
 
@@ -972,24 +977,22 @@ void onBusReset(void)
   }
 
   SCSI_RELEASE_OUTPUTS();
-  azlogn("BUSRESET");
+  azdbg("BUSRESET");
   g_busreset = true;
 }
 
 // Check for any new data in log buffer and save it to file
-void saveLog(void)
+void saveLog(FsFile &logfile)
 {
+  static uint32_t prev_log_pos = 0;
   static uint32_t prev_log_len = 0;
   uint32_t loglen = azlog_get_buffer_len();
 
   if (loglen != prev_log_len)
   {
-    FsFile file = SD.open(LOGFILE, O_WRONLY | O_CREAT | O_TRUNC);
-    file.write(azlog_get_buffer());
-    file.truncate();
-    file.flush();
-    file.close();
-
+    logfile.write(azlog_get_buffer(&prev_log_pos));
+    logfile.flush();
+    
     prev_log_len = loglen;
   }
 }
@@ -1001,22 +1004,27 @@ int main(void)
 
   if(!SD.begin(SD_CONFIG))
   {
-    azlogn("SD card init failed, sdErrorCode:", (int)SD.sdErrorCode(),
+    azlog("SD card init failed, sdErrorCode:", (int)SD.sdErrorCode(),
            "sdErrorData:", (int)SD.sdErrorData());
     blinkStatus(BLINK_ERROR_NO_SD_CARD);
   }
   else
   {
     uint64_t size = (uint64_t)SD.vol()->clusterCount() * SD.vol()->bytesPerCluster();
-    azlogn("SD card init succeeded, FAT", (int)SD.vol()->fatType(),
+    azlog("SD card init succeeded, FAT", (int)SD.vol()->fatType(),
            " volume size: ", (int)(size / 1024 / 1024), " MB");
   }
 
   readSCSIDeviceConfig();
   findHDDImages();
 
-  azlogn("Initialization complete!");
-  saveLog();
+  azlog("Initialization complete!");
+  azlog("Platform: ", g_azplatform_name);
+  azlog("FW Version: ", g_azlog_firmwareversion);
+
+  FsFile logfile;
+  logfile = SD.open(LOGFILE, O_WRONLY | O_CREAT | O_TRUNC);
+  saveLog(logfile);
 
   uint32_t prev_log_save = millis();
 
@@ -1024,10 +1032,10 @@ int main(void)
   {
     scsi_loop();
 
-    // Save log every 10 seconds, until the internal log buffer is full
-    if (millis() - prev_log_save > 10000)
+    // Save log once a second if there are new log messages
+    if ((uint32_t)(millis() - prev_log_save) > 1000)
     {
-      saveLog();
+      saveLog(logfile);
       prev_log_save = millis();
     }
   }

src/AzulSCSI_config.h

@@ -5,7 +5,11 @@
 
 // Configuration and log file paths
 #define CONFIGFILE  "azulscsi.ini"
-#define LOGFILE "azullog.txt"
+#define LOGFILE     "azullog.txt"
+#define CRASHFILE   "azulerr.txt"
+
+// Log buffer size in bytes, must be a power of 2
+#define LOGBUFSIZE 16384
 
 // HDD image file format
 #define HDIMG_ID_POS  2                 // Position to embed ID number

src/AzulSCSI_log.cpp

@@ -1,28 +1,127 @@
 #include "AzulSCSI_log.h"
+#include "AzulSCSI_config.h"
 #include "AzulSCSI_platform.h"
 
+const char *g_azlog_firmwareversion = __DATE__ " " __TIME__;
+
 // This memory buffer can be read by debugger and is also saved to azullog.txt
-char g_logbuffer[4096];
+#define LOGBUFMASK (LOGBUFSIZE - 1)
+char g_logbuffer[LOGBUFSIZE + 1];
 uint32_t g_logpos = 0;
+bool g_azlog_debug = true;
 
-void azlog(const char *str)
+void azlog_raw(const char *str)
 {
     const char *p = str;
-    while (*p && g_logpos < sizeof(g_logbuffer) - 1)
+    while (*p)
     {
-        g_logbuffer[g_logpos++] = *p++;
+        g_logbuffer[g_logpos & LOGBUFMASK] = *p++;
+        g_logpos++;
     }
 
+    // Keep buffer null-terminated
+    g_logbuffer[g_logpos & LOGBUFMASK] = '\0';
+
     azplatform_log(str);
 }
 
+// Log byte as hex
+void azlog_raw(uint8_t value)
+{
+    const char *nibble = "0123456789ABCDEF";
+    char hexbuf[5] = {
+        '0', 'x', 
+        nibble[(value >>  4) & 0xF], nibble[(value >>  0) & 0xF],
+        0
+    };
+    azlog_raw(hexbuf);
+}
+
+// Log integer as hex
+void azlog_raw(uint32_t value)
+{
+    const char *nibble = "0123456789ABCDEF";
+    char hexbuf[11] = {
+        '0', 'x', 
+        nibble[(value >> 28) & 0xF], nibble[(value >> 24) & 0xF],
+        nibble[(value >> 20) & 0xF], nibble[(value >> 16) & 0xF],
+        nibble[(value >> 12) & 0xF], nibble[(value >>  8) & 0xF],
+        nibble[(value >>  4) & 0xF], nibble[(value >>  0) & 0xF],
+        0
+    };
+    azlog_raw(hexbuf);
+}
+
+// Log integer as decimal
+void azlog_raw(int value)
+{
+    char decbuf[16] = {0};
+    char *p = &decbuf[14];
+    int remainder = (value < 0) ? -value : value;
+    do
+    {
+        *--p = '0' + (remainder % 10);
+        remainder /= 10;
+    } while (remainder > 0);
+    
+    if (value < 0)
+    {
+        *--p = '-';
+    }
+
+    azlog_raw(p);
+}
+
+void azlog_raw(bytearray array)
+{
+    for (size_t i = 0; i < array.len; i++)
+    {
+        azlog_raw(array.data[i]);
+        azlog_raw(" ");
+        if (i > 64)
+        {
+            azlog_raw("...");
+            break;
+        }
+    }
+}
+
 uint32_t azlog_get_buffer_len()
 {
     return g_logpos;
 }
 
-const char *azlog_get_buffer()
+const char *azlog_get_buffer(uint32_t *startpos)
 {
-    return g_logbuffer;
+    uint32_t default_pos = 0;
+    if (startpos == NULL)
+    {
+        startpos = &default_pos;
+    }
+
+    // Check oldest data available in buffer
+    uint32_t margin = 16;
+    if (g_logpos + margin > LOGBUFSIZE)
+    {
+        uint32_t oldest = g_logpos + margin - LOGBUFSIZE;
+        if (*startpos < oldest)
+        {
+            *startpos = oldest;
+        }
+    }
+
+    const char *result = &g_logbuffer[*startpos & LOGBUFMASK];
+    if ((g_logpos & LOGBUFMASK) >= (*startpos & LOGBUFMASK))
+    {
+        // Ok, everything has been read now
+        *startpos = g_logpos;
+    }
+    else
+    {
+        // Buffer wraps, read to end of buffer now and start from beginning on next call.
+        *startpos = g_logpos & (~LOGBUFMASK);
+    }
+
+    return result;
 }
 

src/AzulSCSI_log.h

@@ -3,79 +3,74 @@
 #pragma once
 
 #include <stdint.h>
+#include <stddef.h>
 
-// Retrieve stored log buffer
+// Get total number of bytes that have been written to log
 uint32_t azlog_get_buffer_len();
-const char *azlog_get_buffer();
+
+// Get log as a string.
+// If startpos is given, continues log reading from previous position and updates the position.
+const char *azlog_get_buffer(uint32_t *startpos);
+
+// Whether to enable debug messages
+extern bool g_azlog_debug;
+
+// Firmware version string
+extern const char *g_azlog_firmwareversion;
 
 // Log string
-void azlog(const char *str);
+void azlog_raw(const char *str);
 
 // Log byte as hex
-inline void azlog(uint8_t value)
-{
-    const char *nibble = "0123456789ABCDEF";
-    char hexbuf[5] = {
-        '0', 'x', 
-        nibble[(value >>  4) & 0xF], nibble[(value >>  0) & 0xF],
-        0
-    };
-    azlog(hexbuf);
-}
+void azlog_raw(uint8_t value);
 
 // Log integer as hex
-inline void azlog(uint32_t value)
-{
-    const char *nibble = "0123456789ABCDEF";
-    char hexbuf[11] = {
-        '0', 'x', 
-        nibble[(value >> 28) & 0xF], nibble[(value >> 24) & 0xF],
-        nibble[(value >> 20) & 0xF], nibble[(value >> 16) & 0xF],
-        nibble[(value >> 12) & 0xF], nibble[(value >>  8) & 0xF],
-        nibble[(value >>  4) & 0xF], nibble[(value >>  0) & 0xF],
-        0
-    };
-    azlog(hexbuf);
-}
+void azlog_raw(uint32_t value);
 
 // Log integer as decimal
-inline void azlog(int value)
-{
-    char decbuf[16] = {0};
-    char *p = &decbuf[14];
-    int remainder = (value < 0) ? -value : value;
-    do
-    {
-        *--p = '0' + (remainder % 10);
-        remainder /= 10;
-    } while (remainder > 0);
-    
-    if (value < 0)
-    {
-        *--p = '-';
-    }
+void azlog_raw(int value);
 
-    azlog(p);
-}
+// Log array of bytes
+struct bytearray {
+    bytearray(const uint8_t *data, size_t len): data(data), len(len) {}
+    const uint8_t *data;
+    size_t len;
+};
+void azlog_raw(bytearray array);
 
-inline void azlog()
+inline void azlog_raw()
 {
     // End of template recursion
 }
 
-// Variadic template for composing strings
+extern "C" unsigned long millis();
+
+// Variadic template for printing multiple items
 template<typename T, typename T2, typename... Rest>
-inline void azlog(T first, T2 second, Rest... rest)
+inline void azlog_raw(T first, T2 second, Rest... rest)
+{
+    azlog_raw(first);
+    azlog_raw(second);
+    azlog_raw(rest...);
+}
+
+// Format a complete log message
+template<typename... Params>
+inline void azlog(Params... params)
 {
-    azlog(first);
-    azlog(second);
-    azlog(rest...);
+    azlog_raw("[", (int)millis(), "ms] ");
+    azlog_raw(params...);
+    azlog_raw("\n");
 }
 
-// Append newline automatically
+// Format a complete debug message
 template<typename... Params>
-inline void azlogn(Params... params)
+inline void azdbg(Params... params)
 {
-    azlog(params...);
-    azlog("\n");
-}
+    if (g_azlog_debug)
+    {
+        azlog_raw("[", (int)millis(), "ms] DBG ");
+        azlog_raw(params...);
+        azlog_raw("\n");
+    }
+}