FW: resolve error reporting for NMEA0183 channels to avoid stalling event-loop

LoggerFirmware/include/N0183Logger.h

@@ -114,8 +114,31 @@ class MessageAssembler {
         STATE_CAPTURING     ///< In the middle of a sentence, looking for the end character(s)
     };
 
+    class ErrorCount {
+    public:
+        ErrorCount(void);
+        enum ErrorType {
+            NON_START = 0,
+            RX_INVERSION,
+            RESTART,
+            OVERLONG,
+            MAX_ERRORS
+        };
+        void Note(ErrorType event);
+        void ReportCounts(logger::Manager *manager, int channel);
+
+    private:
+        unsigned int m_counts[ErrorCount::MAX_ERRORS];
+        unsigned long m_nextReport;
+        const unsigned long report_interval = 5000;
+        bool reportable(void);
+        bool timeout(void);
+        void reset(void);
+    };
+
     static const int RingBufferLength = 10; ///< Maximum number of sentences we'll attempt to buffer
     logger::Manager *m_logManager;          ///< Log manager to use for console logging, if required
+    ErrorCount m_errors;                    ///< Object to count errors during assembly (for later report)
     State     m_state;                      ///< Current state of the message being assembled
     Sentence  m_current;                    ///< Sentence currently being assembled
     int       m_readPoint;                  ///< Ring buffer read position
@@ -125,6 +148,7 @@ class MessageAssembler {
     bool      m_debugAssembly;              ///< Flag for debug message construction
     int       m_badStartCount;              ///< Count of the number of bad start characters since last inversion reset
     int       m_lastInvertResetTime;        ///< Elapsed time when we last tried inverting the input to get good data
+    bool      m_inverted;                   ///< Indicator that RX inversion has been attempted
 };
 
 /// \class Logger

LoggerFirmware/src/LogManager.cpp

@@ -783,7 +783,7 @@ void Manager::Record(PacketIDs pktID, Serialisable const& data)
 void Manager::Syslog(String const& message)
 {
     unsigned long now = millis();
-    m_consoleLog.println(String(now) + ": " + message);
+    m_consoleLog.printf("%10d: %s\n", now, message.c_str());
     m_consoleLog.flush();
     RotateConsoleLogs(); // This is maybe a little much, but does ensure we don't exceed the max size.
 }

LoggerFirmware/src/N0183Logger.cpp

@@ -37,8 +37,8 @@ namespace nmea {
 namespace N0183 {
 
 const int SoftwareVersionMajor = 1; ///< Software major version for the logger
-const int SoftwareVersionMinor = 0; ///< Software minor version for the logger
-const int SoftwareVersionPatch = 1; ///< Software patch version for the logger
+const int SoftwareVersionMinor = 1; ///< Software minor version for the logger
+const int SoftwareVersionPatch = 0; ///< Software patch version for the logger
 
 /// Validate the sentence, making sure that it meets the requirements to be a NMEA0183 message.  For
 /// this, it has to contain only printable characters, it has to start with a "$", and end with a valid checksum
@@ -92,11 +92,74 @@ String Sentence::MessageID(void) const
     return s;
 }
 
+MessageAssembler::ErrorCount::ErrorCount(void)
+{
+    for (auto n = 0; n < ErrorCount::MAX_ERRORS; ++n) {
+        m_counts[n] = 0;
+    }
+    m_nextReport = millis() + report_interval;
+}
+
+bool MessageAssembler::ErrorCount::reportable(void)
+{
+    unsigned int total = 0;
+    for (auto n = 0; n < ErrorCount::MAX_ERRORS; ++n) {
+        total += m_counts[n];
+    }
+    return total > 0;
+}
+
+bool MessageAssembler::ErrorCount::timeout(void)
+{
+    unsigned long now = millis();
+    if (now < m_nextReport) {
+        return false;
+    }
+    m_nextReport = now + report_interval;
+    return true;
+}
+
+void MessageAssembler::ErrorCount::reset(void)
+{
+    for (auto n = 0; n < ErrorCount::MAX_ERRORS; ++n) {
+        m_counts[n] = 0;
+    }
+}
+
+void MessageAssembler::ErrorCount::Note(ErrorType event)
+{
+    ++m_counts[event];
+}
+
+void MessageAssembler::ErrorCount::ReportCounts(logger::Manager *manager, int channel)
+{
+    if (!timeout() || !reportable()) {
+        return;
+    }
+
+    char *buf = new char[512];
+
+    snprintf(buf, 512, "ERR: NMEA0183 ch %d (%d ms/report):", channel, report_interval);
+    manager->Syslog(buf);
+    snprintf(buf, 512, "  %d non-start characters while looking for start.", m_counts[0]);
+    manager->Syslog(buf);
+    snprintf(buf, 512, "  %d RX inversion calls.", m_counts[1]);
+    manager->Syslog(buf);
+    snprintf(buf, 512, "  %d sentence restarts during capture.", m_counts[2]);
+    manager->Syslog(buf);
+    snprintf(buf, 512, "  %d overlong sentences.", m_counts[3]);
+    manager->Syslog(buf);
+
+    delete [] buf;
+
+    reset();
+}
+
 /// Start the message assembler in the "searching" state, with a blank sentence and empty FIFO.
 
 MessageAssembler::MessageAssembler(void)
 : m_logManager(nullptr), m_state(STATE_SEARCHING), m_readPoint(0), m_writePoint(0), m_channel(-1),
-  m_debugAssembly(false), m_badStartCount(0), m_lastInvertResetTime(millis())
+  m_debugAssembly(false), m_badStartCount(0), m_lastInvertResetTime(millis()), m_inverted(false)
 {
 }
 
@@ -114,6 +177,7 @@ MessageAssembler::~MessageAssembler(void)
 void MessageAssembler::AddCharacter(const char in)
 {
     String message;
+    bool report = false;
 
     switch(m_state) {
         case STATE_SEARCHING:
@@ -125,26 +189,22 @@ void MessageAssembler::AddCharacter(const char in)
                 m_current.AddCharacter(in);
                 m_state = STATE_CAPTURING;
                 if (m_debugAssembly) {
-                    Serial.println(String("debug: sentence started with timestamp ") +
+                    Serial.println(String("DEBUG: sentence started with timestamp ") +
                                    m_current.Timestamp() + " on channel " + m_channel +
                                    "; changing to CAPTURING.");
                 }
             } else {
-                if (m_debugAssembly || m_logManager != nullptr) {
+                if (m_debugAssembly) {
                     message = "ERR: non-start character ";
                     if (std::isprint(in)) {
                         message += String("'") + in + "'";
                     } else {
                         message += "0x" + String(in, HEX);
                     }
                     message += " while searching for NMEA string (channel " + String(m_channel) + ").";
-                    if (m_debugAssembly) {
-                        Serial.println(message);
-                    }
-                    if (m_logManager != nullptr) {
-                        m_logManager->Syslog(message);
-                    }
+                    Serial.println(message);
                 }
+                m_errors.Note(ErrorCount::NON_START);
 
                 if ((in & 0x80) != 0) {
                     // Top bit should never be set in serial ASCII, so that's either a noise
@@ -159,15 +219,16 @@ void MessageAssembler::AddCharacter(const char in)
                     // got an inversion of the inputs, so we attempt to fix that.
                     m_lastInvertResetTime = millis();
                     m_badStartCount = 0;
-                    if (m_channel == 1)
-                        Serial1.setRxInvert(true);
-                    else if (m_channel == 2)
-                        Serial2.setRxInvert(true);
-                    message = "INFO: setting rx input inversion on channel "
-                                + String(m_channel) + " due to bad start characters.";
-                    Serial.println(message);
-                    if (m_logManager != nullptr) {
-                        m_logManager->Syslog(message);
+                    if (!m_inverted) {
+                        if (m_channel == 1)
+                            Serial1.setRxInvert(true);
+                        else if (m_channel == 2)
+                            Serial2.setRxInvert(true);
+                        message = "INFO: setting rx input inversion on channel "
+                                    + String(m_channel) + " due to bad start characters.";
+                        Serial.println(message);
+                        m_errors.Note(ErrorCount::RX_INVERSION);
+                        m_inverted = true;
                     }
                 }
             }
@@ -181,12 +242,12 @@ void MessageAssembler::AddCharacter(const char in)
                     m_buffer[m_writePoint] = m_current;
                     m_writePoint = (m_writePoint + 1) % RingBufferLength;
                     if (m_debugAssembly) {
-                        Serial.println(String("debug: LF on channel ") + m_channel +
+                        Serial.println(String("DEBUG: LF on channel ") + m_channel +
                                               " to complete sentence; moved to FIFO");
                     }
                     m_state = STATE_SEARCHING;
                     if (m_debugAssembly) {
-                        Serial.println(String("debug: changing to SEARCHING on channel ") +
+                        Serial.println(String("DEBUG: changing to SEARCHING on channel ") +
                                        m_channel + ".");
                     }
                     break;
@@ -203,14 +264,12 @@ void MessageAssembler::AddCharacter(const char in)
                     m_current.AddCharacter(in);
                     message = "WARN: sentence restarted before end of previous one?! (channel " + String(m_channel) + ").";
                     Serial.println(message);
-                    if (m_logManager != nullptr) {
-                        m_logManager->Syslog(message);
-                    }
                     if (m_debugAssembly) {
-                        Serial.println(String("debug: new sentence started with timestamp ") +
+                        Serial.println(String("DEBUG: new sentence started with timestamp ") +
                                        m_current.Timestamp() + " as reset on channel " +
                                        m_channel + ".");
                     }
+                    m_errors.Note(ErrorCount::RESTART);
                     break;
                 default:
                     // The next character of the current sentence
@@ -220,25 +279,27 @@ void MessageAssembler::AddCharacter(const char in)
                         m_state = STATE_SEARCHING;
                         message = "WARN: over-long sentence detected, and ignored (channel " + String(m_channel) + ").";
                         Serial.println(message);
-                        if (m_logManager != nullptr) {
-                            m_logManager->Syslog(message);
-                        }
                         if (m_debugAssembly) {
-                            Serial.println(String("debug: reset state to SEARCHING on channel ") +
+                            Serial.println(String("DEBUG: reset state to SEARCHING on channel ") +
                                            m_channel + " after over-long sentence.");
                         }
+                        m_errors.Note(ErrorCount::OVERLONG);
                     }
                     break;
             }
             break;
         default:
-            Serial.println("ERR: unknown state in message assembly! Resetting to SEARCHING.");
+            const char *msg = "ERR: unknown state in message assembly! Resetting to SEARCHING.";
+            Serial.println(msg);
             if (m_logManager != nullptr) {
-                m_logManager->Syslog("ERR: unknown state in message assembly! Resetting to SEARCHING.");
+                m_logManager->Syslog(msg);
             }
             m_state = STATE_SEARCHING;
             break;
     }
+    if (m_logManager != nullptr) {
+        m_errors.ReportCounts(m_logManager, m_channel);
+    }
 }
 
 /// Pull the next sentence out of the ring buffer (as a pointer to the location of the message),