VE.Direct: Reset state machine on timeout, fix and extend logging (#416)

* VE.Direct: reset state machine on timeout there will never be a large gap between two bytes of the same frame. if such a large gap is observed, reset the state machine so it tries to decode a new frame once more data arrives. this is helpful in case of corrupted data that prevents the state machine of transitioning to the final state even though the VE.Direct data producer is done sending bytes that belong to the same frame. * VE.Direct: print problems to MessageOutput this includes the web console in particular, where many users have access to while the serial console is not attached or monitored. * VE.Direct: collect serial input into buffer and print should help debug issues for users. * VE.Direct: implement and use verbose logging switch
2023-09-04 14:07:48 +02:00 · 2023-09-04 14:07:48 +02:00 · ba303da742
commit ba303da742
parent a7a38e74a1
14 changed files with 108 additions and 40 deletions
--- a/include/Configuration.h
+++ b/include/Configuration.h
@ -127,6 +127,7 @@ struct CONFIG_T {
    char Mqtt_ClientKey[MQTT_MAX_CERT_STRLEN +1];

    bool Vedirect_Enabled;
+    bool Vedirect_VerboseLogging;
    bool Vedirect_UpdatesOnly;

    bool PowerMeter_Enabled;
--- a/include/defaults.h
+++ b/include/defaults.h
@ -96,8 +96,8 @@
 #define DISPLAY_LANGUAGE 0U

 #define VEDIRECT_ENABLED false
+#define VEDIRECT_VERBOSE_LOGGING false
 #define VEDIRECT_UPDATESONLY true
-#define VEDIRECT_POLL_INTERVAL 5

 #define POWERMETER_ENABLED false
 #define POWERMETER_INTERVAL 10
--- a/lib/VeDirectFrameHandler/VeDirectFrameHandler.cpp
+++ b/lib/VeDirectFrameHandler/VeDirectFrameHandler.cpp
@ -36,27 +36,33 @@
 #include <Arduino.h>
 #include "VeDirectFrameHandler.h"

-char MODULE[] = "VE.Frame";	// Victron seems to use this to find out where logging messages were generated
-
 // The name of the record that contains the checksum.
 static constexpr char checksumTagName[] = "CHECKSUM";

 // state machine
-enum States {                               
-	IDLE,
-	RECORD_BEGIN,
-	RECORD_NAME,
-	RECORD_VALUE,
-	CHECKSUM,
-	RECORD_HEX
+enum States {
+	IDLE = 1,
+	RECORD_BEGIN = 2,
+	RECORD_NAME = 3,
+	RECORD_VALUE = 4,
+	CHECKSUM = 5,
+	RECORD_HEX = 6
 };

 HardwareSerial VedirectSerial(1);

 VeDirectFrameHandler VeDirect;

+class Silent : public Print {
+    public:
+        size_t write(uint8_t c) final { return 0; }
+};
+
+static Silent MessageOutputDummy;
+
 VeDirectFrameHandler::VeDirectFrameHandler() :
 	//mStop(false),	// don't know what Victron uses this for, not using
+	_msgOut(&MessageOutputDummy),
 	_state(IDLE),
 	_checksum(0),
 	_textPointer(0),
@ -64,20 +70,53 @@ VeDirectFrameHandler::VeDirectFrameHandler() :
 	_name(""),
 	_value(""),
 	_tmpFrame(),
+	_debugIn(0),
+	_lastByteMillis(0),
 	_lastUpdate(0)
 {
 }

-void VeDirectFrameHandler::init(int8_t rx, int8_t tx)
+void VeDirectFrameHandler::setVerboseLogging(bool verboseLogging)
 {
-    VedirectSerial.begin(19200, SERIAL_8N1, rx, tx);
-    VedirectSerial.flush();
+	_verboseLogging = verboseLogging;
+}
+
+void VeDirectFrameHandler::init(int8_t rx, int8_t tx, Print* msgOut, bool verboseLogging)
+{
+	VedirectSerial.begin(19200, SERIAL_8N1, rx, tx);
+	VedirectSerial.flush();
+	_msgOut = msgOut;
+	setVerboseLogging(verboseLogging);
+}
+
+void VeDirectFrameHandler::dumpDebugBuffer() {
+	_msgOut->printf("[VE.Direct] serial input (%d Bytes):", _debugIn);
+	for (int i = 0; i < _debugIn; ++i) {
+		if (i % 16 == 0) {
+			_msgOut->printf("\r\n[VE.Direct]");
+		}
+		_msgOut->printf(" %02x", _debugBuffer[i]);
+	}
+	_msgOut->println("");
+	_debugIn = 0;
 }

 void VeDirectFrameHandler::loop()
 {
 	while ( VedirectSerial.available()) {
 		rxData(VedirectSerial.read());
+		_lastByteMillis = millis();
+	}
+
+	// there will never be a large gap between two bytes of the same frame.
+	// if such a large gap is observed, reset the state machine so it tries
+	// to decode a new frame once more data arrives.
+	if (IDLE != _state && _lastByteMillis + 500 < millis()) {
+		_msgOut->printf("[VE.Direct] Resetting state machine (was %d) after timeout\r\n", _state);
+		if (_verboseLogging) { dumpDebugBuffer(); }
+		_checksum = 0;
+		_state = IDLE;
+		_tmpFrame = { };
 	}
 }

@ -88,6 +127,12 @@ void VeDirectFrameHandler::loop()
 */
 void VeDirectFrameHandler::rxData(uint8_t inbyte)
 {
+	_debugBuffer[_debugIn] = inbyte;
+	_debugIn = (_debugIn + 1) % _debugBuffer.size();
+	if (0 == _debugIn) {
+		_msgOut->println("[VE.Direct] ERROR: debug buffer overrun!");
+	}
+
 	//if (mStop) return;
 	if ( (inbyte == ':') && (_state != CHECKSUM) ) {
 		_prevState = _state; //hex frame can interrupt TEXT
@ -162,8 +207,10 @@ void VeDirectFrameHandler::rxData(uint8_t inbyte)
 	case CHECKSUM:
 	{
 		bool valid = _checksum == 0;
-		if (!valid)
-			logE(MODULE,"[CHECKSUM] Invalid frame");
+		if (!valid) {
+			_msgOut->printf("[VE.Direct] checksum 0x%02x != 0, invalid frame\r\n", _checksum);
+		}
+		if (_verboseLogging) { dumpDebugBuffer(); }
 		_checksum = 0;
 		_state = IDLE;
 		frameEndEvent(valid);
@ -268,18 +315,6 @@ void VeDirectFrameHandler::frameEndEvent(bool valid) {
 	_tmpFrame = {};
 }

-/*
- *	logE
- *  This function included for continuity and possible future use.	
- */
-void VeDirectFrameHandler::logE(const char * module, const char * error) {
-	Serial.print("MODULE: ");
-    Serial.println(module);
-    Serial.print("ERROR: ");
-    Serial.println(error);
-	return;
-}
-
 /*
 *	hexRxEvent
 *  This function records hex answers or async messages	
@ -296,7 +331,7 @@ int VeDirectFrameHandler::hexRxEvent(uint8_t inbyte) {
 	default:
 		_hexSize++;
 		if (_hexSize>=VE_MAX_HEX_LEN) { // oops -buffer overflow - something went wrong, we abort
-			logE(MODULE,"hexRx buffer overflow - aborting read");
+			_msgOut->println("[VE.Direct] hexRx buffer overflow - aborting read");
 			_hexSize=0;
 			ret=IDLE;
 		}
--- a/lib/VeDirectFrameHandler/VeDirectFrameHandler.h
+++ b/lib/VeDirectFrameHandler/VeDirectFrameHandler.h
@ -12,6 +12,7 @@
 #pragma once

 #include <Arduino.h>
+#include <array>

 #ifndef VICTRON_PIN_TX
 #define VICTRON_PIN_TX 21      // HardwareSerial TX Pin
@ -87,7 +88,8 @@ class VeDirectFrameHandler {
 public:

    VeDirectFrameHandler();
-    void init(int8_t rx, int8_t tx);             // initialize HardewareSerial
+    void setVerboseLogging(bool verboseLogging);
+    void init(int8_t rx, int8_t tx, Print* msgOut, bool verboseLogging);
    void loop();                                 // main loop to read ve.direct data
    unsigned long getLastUpdate();               // timestamp of last successful frame read
    bool isDataValid();                          // return true if data valid and not outdated
@ -101,13 +103,15 @@ public:

 private:
    void setLastUpdate();                     // set timestampt after successful frame read
+    void dumpDebugBuffer();
    void rxData(uint8_t inbyte);              // byte of serial data
    void textRxEvent(char *, char *);
    void frameEndEvent(bool);                 // copy temp struct to public struct
-    void logE(const char *, const char *);    
    int hexRxEvent(uint8_t);

    //bool mStop;                               // not sure what Victron uses this for, not using
+    Print* _msgOut;
+    bool _verboseLogging;
    int _state;                                // current state
    int _prevState;                            // previous state
    uint8_t	_checksum;                         // checksum value
@ -117,7 +121,10 @@ private:
    char _value[VE_MAX_VALUE_LEN];             // buffer for the field value
    veStruct _tmpFrame{};                        // private struct for received name and value pairs
    MovingAverage<double, 5> _efficiency;
-    unsigned long _lastUpdate;
+    std::array<uint8_t, 512> _debugBuffer;
+    unsigned _debugIn;
+    uint32_t _lastByteMillis;
+    uint32_t _lastUpdate;
 };

 extern VeDirectFrameHandler VeDirect;
--- a/src/Configuration.cpp
+++ b/src/Configuration.cpp
@ -123,6 +123,7 @@ bool ConfigurationClass::write()

    JsonObject vedirect = doc.createNestedObject("vedirect");
    vedirect["enabled"] = config.Vedirect_Enabled;
+    vedirect["verbose_logging"] = config.Vedirect_VerboseLogging;
    vedirect["updates_only"] = config.Vedirect_UpdatesOnly;

    JsonObject powermeter = doc.createNestedObject("powermeter");
@ -341,6 +342,7 @@ bool ConfigurationClass::read()

    JsonObject vedirect = doc["vedirect"];
    config.Vedirect_Enabled = vedirect["enabled"] | VEDIRECT_ENABLED;
+    config.Vedirect_VerboseLogging = vedirect["verbose_logging"] | VEDIRECT_VERBOSE_LOGGING;
    config.Vedirect_UpdatesOnly = vedirect["updates_only"] | VEDIRECT_UPDATESONLY;

    JsonObject powermeter = doc["powermeter"];
--- a/src/WebApi_vedirect.cpp
+++ b/src/WebApi_vedirect.cpp
@ -37,6 +37,7 @@ void WebApiVedirectClass::onVedirectStatus(AsyncWebServerRequest* request)
    const CONFIG_T& config = Configuration.get();

    root[F("vedirect_enabled")] = config.Vedirect_Enabled;
+    root[F("verbose_logging")] = config.Vedirect_VerboseLogging;
    root[F("vedirect_updatesonly")] = config.Vedirect_UpdatesOnly;

    response->setLength();
@ -54,6 +55,7 @@ void WebApiVedirectClass::onVedirectAdminGet(AsyncWebServerRequest* request)
    const CONFIG_T& config = Configuration.get();

    root[F("vedirect_enabled")] = config.Vedirect_Enabled;
+    root[F("verbose_logging")] = config.Vedirect_VerboseLogging;
    root[F("vedirect_updatesonly")] = config.Vedirect_UpdatesOnly;

    response->setLength();
@ -99,7 +101,9 @@ void WebApiVedirectClass::onVedirectAdminPost(AsyncWebServerRequest* request)
        return;
    }

-    if (!(root.containsKey("vedirect_enabled") && root.containsKey("vedirect_updatesonly")) ) {
+    if (!root.containsKey("vedirect_enabled") ||
+            !root.containsKey("verbose_logging") ||
+            !root.containsKey("vedirect_updatesonly") ) {
        retMsg[F("message")] = F("Values are missing!");
        retMsg[F("code")] = WebApiError::GenericValueMissing;
        response->setLength();
@ -109,9 +113,12 @@ void WebApiVedirectClass::onVedirectAdminPost(AsyncWebServerRequest* request)

    CONFIG_T& config = Configuration.get();
    config.Vedirect_Enabled = root[F("vedirect_enabled")].as<bool>();
+    config.Vedirect_VerboseLogging = root[F("verbose_logging")].as<bool>();
    config.Vedirect_UpdatesOnly = root[F("vedirect_updatesonly")].as<bool>();
    Configuration.write();

+    VeDirect.setVerboseLogging(config.Vedirect_VerboseLogging);
+
    retMsg[F("type")] = F("success");
    retMsg[F("message")] = F("Settings saved!");
    retMsg[F("code")] = WebApiError::GenericSuccess;
--- a/src/main.cpp
+++ b/src/main.cpp
@ -165,7 +165,8 @@ void setup()
    MessageOutput.println(F("Initialize ve.direct interface... "));
    if (PinMapping.isValidVictronConfig()) {
        MessageOutput.printf("ve.direct rx = %d, tx = %d\r\n", pin.victron_rx, pin.victron_tx);
-        VeDirect.init(pin.victron_rx, pin.victron_tx);
+        VeDirect.init(pin.victron_rx, pin.victron_tx,
+                &MessageOutput, config.Vedirect_VerboseLogging);
        MessageOutput.println(F("done"));
    } else {
        MessageOutput.println(F("Invalid pin config"));
@ -203,9 +204,9 @@ void loop()
    yield();
    // Vedirect_Enabled is unknown to lib. Therefor check has to be done here
    if (Configuration.get().Vedirect_Enabled) {
-		VeDirect.loop();
+        VeDirect.loop();
        yield();
-	}
+    }
    MqttSettings.loop();
    yield();
    MqttHandleDtu.loop();
--- a/webapp/src/locales/de.json
+++ b/webapp/src/locales/de.json
@ -327,6 +327,7 @@
        "Status": "@:ntpinfo.Status",
        "Enabled": "@:mqttinfo.Enabled",
        "Disabled": "@:mqttinfo.Disabled",
+        "VerboseLogging": "@:base.VerboseLogging",
        "UpdatesOnly": "@:vedirectadmin.UpdatesOnly",
        "UpdatesEnabled": "@:mqttinfo.Enabled",
        "UpdatesDisabled": "@:mqttinfo.Disabled"
@ -499,7 +500,7 @@
        "VedirectConfiguration": "VE.Direct Konfiguration",
        "EnableVedirect": "Aktiviere VE.Direct",
        "VedirectParameter": "VE.Direct Parameter",
-        "Seconds": "Sekunden",
+        "VerboseLogging": "@:base.VerboseLogging",
        "UpdatesOnly": "Werte nur bei Änderung an MQTT broker senden",
        "Save": "@:dtuadmin.Save"
    },
--- a/webapp/src/locales/en.json
+++ b/webapp/src/locales/en.json
@ -329,6 +329,7 @@
        "Status": "@:ntpinfo.Status",
        "Enabled": "@:mqttinfo.Enabled",
        "Disabled": "@:mqttinfo.Disabled",
+        "VerboseLogging": "@:base.VerboseLogging",
        "UpdatesOnly": "@:vedirectadmin.UpdatesOnly",
        "UpdatesEnabled": "@:mqttinfo.Enabled",
        "UpdatesDisabled": "@:mqttinfo.Disabled"
@ -501,7 +502,7 @@
        "VedirectConfiguration": "VE.Direct Configuration",
        "EnableVedirect": "Enable VE.Direct",
        "VedirectParameter": "VE.Direct Parameter",
-        "Seconds": "seconds",
+        "VerboseLogging": "@:base.VerboseLogging",
        "UpdatesOnly": "Publish values to MQTT only when they change",
        "Save": "@:dtuadmin.Save"
    },
--- a/webapp/src/locales/fr.json
+++ b/webapp/src/locales/fr.json
@ -327,6 +327,7 @@
        "Status": "@:ntpinfo.Status",
        "Enabled": "@:mqttinfo.Enabled",
        "Disabled": "@:mqttinfo.Disabled",
+        "VerboseLogging": "@:base.VerboseLogging",
        "UpdatesOnly": "@:vedirectadmin.UpdatesOnly",
        "UpdatesEnabled": "@:mqttinfo.Enabled",
        "UpdatesDisabled": "@:mqttinfo.Disabled"
@ -499,7 +500,7 @@
        "VedirectConfiguration": "VE.Direct Configuration",
        "EnableVedirect": "Enable VE.Direct",
        "VedirectParameter": "VE.Direct Parameter",
-        "Seconds": "seconds",
+        "VerboseLogging": "@:base.VerboseLogging",
        "UpdatesOnly": "Publish values to MQTT only when they change",
        "Save": "@:dtuadmin.Save"
    },
--- a/webapp/src/types/VedirectConfig.ts
+++ b/webapp/src/types/VedirectConfig.ts
@ -1,4 +1,5 @@
 export interface VedirectConfig {
    vedirect_enabled: boolean;
+    verbose_logging: boolean;
    vedirect_updatesonly: boolean;
 }
--- a/webapp/src/types/VedirectStatus.ts
+++ b/webapp/src/types/VedirectStatus.ts
@ -1,4 +1,5 @@
 export interface VedirectStatus {
    vedirect_enabled: boolean;
+    verbose_logging: boolean;
    vedirect_updatesonly: boolean;
 }
--- a/webapp/src/views/VedirectAdminView.vue
+++ b/webapp/src/views/VedirectAdminView.vue
@ -12,8 +12,12 @@
            </CardElement>

            <CardElement :text="$t('vedirectadmin.VedirectParameter')" textVariant="text-bg-primary" add-space
-                         v-show="vedirectConfigList.vedirect_enabled"
-            >
+                         v-show="vedirectConfigList.vedirect_enabled">
+
+                <InputElement :label="$t('vedirectadmin.VerboseLogging')"
+                              v-model="vedirectConfigList.verbose_logging"
+                              type="checkbox" wide/>
+
                <InputElement :label="$t('vedirectadmin.UpdatesOnly')"
                              v-model="vedirectConfigList.vedirect_updatesonly"
                              type="checkbox" wide/>
--- a/webapp/src/views/VedirectInfoView.vue
+++ b/webapp/src/views/VedirectInfoView.vue
@ -10,6 +10,12 @@
                                <StatusBadge :status="vedirectDataList.vedirect_enabled" true_text="vedirectinfo.Enabled" false_text="vedirectinfo.Disabled" />
                            </td>
                        </tr>
+                        <tr>
+                            <th>{{ $t('vedirectinfo.VerboseLogging') }}</th>
+                            <td>
+                                <StatusBadge :status="vedirectDataList.verbose_logging" true_text="vedirectinfo.Enabled" false_text="vedirectinfo.Disabled" />
+                            </td>
+                        </tr>
                        <tr>
                            <th>{{ $t('vedirectinfo.UpdatesOnly') }}</th>
                            <td>