From ba303da7424527db0448488b89d13ba38fccc7ea Mon Sep 17 00:00:00 2001 From: Bernhard Kirchen Date: Mon, 4 Sep 2023 14:07:48 +0200 Subject: [PATCH] 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 --- include/Configuration.h | 1 + include/defaults.h | 2 +- .../VeDirectFrameHandler.cpp | 89 +++++++++++++------ .../VeDirectFrameHandler.h | 13 ++- src/Configuration.cpp | 2 + src/WebApi_vedirect.cpp | 9 +- src/main.cpp | 7 +- webapp/src/locales/de.json | 3 +- webapp/src/locales/en.json | 3 +- webapp/src/locales/fr.json | 3 +- webapp/src/types/VedirectConfig.ts | 1 + webapp/src/types/VedirectStatus.ts | 1 + webapp/src/views/VedirectAdminView.vue | 8 +- webapp/src/views/VedirectInfoView.vue | 6 ++ 14 files changed, 108 insertions(+), 40 deletions(-) diff --git a/include/Configuration.h b/include/Configuration.h index 971d3de16..5c10e15bb 100644 --- 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; diff --git a/include/defaults.h b/include/defaults.h index 6ca25618e..051b0ba9c 100644 --- 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 diff --git a/lib/VeDirectFrameHandler/VeDirectFrameHandler.cpp b/lib/VeDirectFrameHandler/VeDirectFrameHandler.cpp index aa028ca53..4c026e67b 100644 --- a/lib/VeDirectFrameHandler/VeDirectFrameHandler.cpp +++ b/lib/VeDirectFrameHandler/VeDirectFrameHandler.cpp @@ -36,27 +36,33 @@ #include #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; } diff --git a/lib/VeDirectFrameHandler/VeDirectFrameHandler.h b/lib/VeDirectFrameHandler/VeDirectFrameHandler.h index 69b4cd488..db4345718 100644 --- a/lib/VeDirectFrameHandler/VeDirectFrameHandler.h +++ b/lib/VeDirectFrameHandler/VeDirectFrameHandler.h @@ -12,6 +12,7 @@ #pragma once #include +#include #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 @@ class VeDirectFrameHandler { 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 @@ class VeDirectFrameHandler { char _value[VE_MAX_VALUE_LEN]; // buffer for the field value veStruct _tmpFrame{}; // private struct for received name and value pairs MovingAverage _efficiency; - unsigned long _lastUpdate; + std::array _debugBuffer; + unsigned _debugIn; + uint32_t _lastByteMillis; + uint32_t _lastUpdate; }; extern VeDirectFrameHandler VeDirect; diff --git a/src/Configuration.cpp b/src/Configuration.cpp index 9f0c24f5e..909e64dd8 100644 --- 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"]; diff --git a/src/WebApi_vedirect.cpp b/src/WebApi_vedirect.cpp index 4b7e8e959..651e9e406 100644 --- 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(); + config.Vedirect_VerboseLogging = root[F("verbose_logging")].as(); config.Vedirect_UpdatesOnly = root[F("vedirect_updatesonly")].as(); Configuration.write(); + VeDirect.setVerboseLogging(config.Vedirect_VerboseLogging); + retMsg[F("type")] = F("success"); retMsg[F("message")] = F("Settings saved!"); retMsg[F("code")] = WebApiError::GenericSuccess; diff --git a/src/main.cpp b/src/main.cpp index fb2b4666e..50e1437f3 100644 --- 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(); diff --git a/webapp/src/locales/de.json b/webapp/src/locales/de.json index 8570fae78..458fd55c2 100644 --- 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" }, diff --git a/webapp/src/locales/en.json b/webapp/src/locales/en.json index 97c3e7f8d..72296e43a 100644 --- 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" }, diff --git a/webapp/src/locales/fr.json b/webapp/src/locales/fr.json index 032288958..a4088ea87 100644 --- 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" }, diff --git a/webapp/src/types/VedirectConfig.ts b/webapp/src/types/VedirectConfig.ts index 59a875221..8b2e356cf 100644 --- 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; } diff --git a/webapp/src/types/VedirectStatus.ts b/webapp/src/types/VedirectStatus.ts index 574e4a68f..a3dbed83b 100644 --- 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; } \ No newline at end of file diff --git a/webapp/src/views/VedirectAdminView.vue b/webapp/src/views/VedirectAdminView.vue index 1431ee1b8..02aa48b8b 100644 --- a/webapp/src/views/VedirectAdminView.vue +++ b/webapp/src/views/VedirectAdminView.vue @@ -12,8 +12,12 @@ + v-show="vedirectConfigList.vedirect_enabled"> + + + diff --git a/webapp/src/views/VedirectInfoView.vue b/webapp/src/views/VedirectInfoView.vue index 39a109cb7..14b7efa61 100644 --- a/webapp/src/views/VedirectInfoView.vue +++ b/webapp/src/views/VedirectInfoView.vue @@ -10,6 +10,12 @@ + + {{ $t('vedirectinfo.VerboseLogging') }} + + + + {{ $t('vedirectinfo.UpdatesOnly') }}