0.8.23

* heuristics fix #1269 #1270
* moved `sendInterval` in settings, **important:** *will be reseted to 15s after update to this version*
* try to prevent access to radio classes if they are not activated
* fixed millis in serial log
* changed 'print whole trace' = `false` as default
* added communication loop duration in [ms] to serial console
* don't print Hex-Payload if 'print whole trace' == `false`

src/CHANGES.md

@@ -1,5 +1,14 @@
 # Development Changes
 
+## 0.8.23 - 2023-12-14
+* heuristics fix #1269 #1270
+* moved `sendInterval` in settings, **important:** *will be reseted to 15s after update to this version*
+* try to prevent access to radio classes if they are not activated
+* fixed millis in serial log
+* changed 'print whole trace' = `false` as default
+* added communication loop duration in [ms] to serial console
+* don't print Hex-Payload if 'print whole trace' == `false`
+
 ## 0.8.22 - 2023-12-13
 * fix communication state-machine regarding zero export #1267
 

src/app.cpp

@@ -123,7 +123,7 @@ void app::onNetwork(bool gotIp) {
     mNetworkConnected = gotIp;
     ah::Scheduler::resetTicker();
     regularTickers(); //reinstall regular tickers
-    every(std::bind(&app::tickSend, this), mConfig->nrf.sendInterval, "tSend");
+    every(std::bind(&app::tickSend, this), mConfig->inst.sendInterval, "tSend");
     mMqttReconnect = true;
     mSunrise = 0;  // needs to be set to 0, to reinstall sunrise and ivComm tickers!
     once(std::bind(&app::tickNtpUpdate, this), 2, "ntp2");
@@ -275,7 +275,7 @@ void app::tickIVCommunication(void) {
         onceAt(std::bind(&app::tickIVCommunication, this), nxtTrig, "ivCom");
 
     if (zeroValues) // at least one inverter
-        once(std::bind(&app::tickZeroValues, this), mConfig->nrf.sendInterval, "tZero");
+        once(std::bind(&app::tickZeroValues, this), mConfig->inst.sendInterval, "tZero");
 }
 
 //-----------------------------------------------------------------------------
@@ -334,6 +334,16 @@ void app::tickMidnight(void) {
 
 //-----------------------------------------------------------------------------
 void app::tickSend(void) {
+    uint8_t fill = mCommunication.getFillState();
+    uint8_t max = mCommunication.getMaxFill();
+    if((max-MAX_NUM_INVERTERS) <= fill) {
+        DPRINT(DBG_WARN, F("send queue almost full, consider to increase interval, "));
+        DBGPRINT(String(fill));
+        DBGPRINT(F(" of "));
+        DBGPRINT(String(max));
+        DBGPRINTLN(F("entries used"));
+    }
+
     for (uint8_t i = 0; i < MAX_NUM_INVERTERS; i++) {
         Inverter<> *iv = mSys.getInverterByPos(i);
         if(NULL == iv)

src/app.h

@@ -91,7 +91,11 @@ class app : public IApp, public ah::Scheduler {
         }
 
         uint32_t getTimestamp() {
-            return Scheduler::getTimestamp();
+            return Scheduler::mTimestamp;
+        }
+
+        uint64_t getTimestampMs() {
+            return ((uint64_t)Scheduler::mTimestamp * 1000) + (uint64_t)Scheduler::mTsMillis;
         }
 
         bool saveSettings(bool reboot) {

src/appInterface.h

@@ -41,6 +41,7 @@ class IApp {
 
         virtual uint32_t getUptime() = 0;
         virtual uint32_t getTimestamp() = 0;
+        virtual uint64_t getTimestampMs() = 0;
         virtual uint32_t getSunrise() = 0;
         virtual uint32_t getSunset() = 0;
         virtual void setTimestamp(uint32_t newTime) = 0;

src/config/settings.h

@@ -30,7 +30,7 @@
  * https://arduino-esp8266.readthedocs.io/en/latest/filesystem.html#flash-layout
  * */
 
-#define CONFIG_VERSION      4
+#define CONFIG_VERSION      5
 
 
 #define PROT_MASK_INDEX     0x0001
@@ -80,7 +80,6 @@ typedef struct {
 
 typedef struct {
     bool enabled;
-    uint16_t sendInterval;
     uint8_t pinCs;
     uint8_t pinCe;
     uint8_t pinIrq;
@@ -150,6 +149,7 @@ typedef struct {
     bool enabled;
     cfgIv_t iv[MAX_NUM_INVERTERS];
 
+    uint16_t sendInterval;
     bool rstYieldMidNight;
     bool rstValsNotAvail;
     bool rstValsCommStop;
@@ -388,7 +388,6 @@ class settings {
 
             snprintf(mCfg.sys.deviceName,  DEVNAME_LEN, DEF_DEVICE_NAME);
 
-            mCfg.nrf.sendInterval      = SEND_INTERVAL;
             mCfg.nrf.pinCs             = DEF_NRF_CS_PIN;
             mCfg.nrf.pinCe             = DEF_NRF_CE_PIN;
             mCfg.nrf.pinIrq            = DEF_NRF_IRQ_PIN;
@@ -433,6 +432,7 @@ class settings {
             snprintf(mCfg.mqtt.topic,  MQTT_TOPIC_LEN, "%s", DEF_MQTT_TOPIC);
             mCfg.mqtt.interval = 0; // off
 
+            mCfg.inst.sendInterval     = SEND_INTERVAL;
             mCfg.inst.rstYieldMidNight = false;
             mCfg.inst.rstValsNotAvail  = false;
             mCfg.inst.rstValsCommStop  = false;
@@ -478,11 +478,15 @@ class settings {
                     mCfg.inst.iv[i].add2Total   = true;
                 }
                 if(mCfg.configVersion < 3) {
-                    mCfg.serial.printWholeTrace = true;
+                    mCfg.serial.printWholeTrace = false;
                 }
                 if(mCfg.configVersion < 4) {
                     mCfg.inst.gapMs = 2000;
                 }
+                if(mCfg.configVersion < 5) {
+                    mCfg.inst.sendInterval = SEND_INTERVAL;
+                    mCfg.serial.printWholeTrace = false;
+                }
             }
         }
 
@@ -539,7 +543,6 @@ class settings {
 
         void jsonNrf(JsonObject obj, bool set = false) {
             if(set) {
-                obj[F("intvl")]     = mCfg.nrf.sendInterval;
                 obj[F("cs")]        = mCfg.nrf.pinCs;
                 obj[F("ce")]        = mCfg.nrf.pinCe;
                 obj[F("irq")]       = mCfg.nrf.pinIrq;
@@ -548,7 +551,6 @@ class settings {
                 obj[F("miso")]      = mCfg.nrf.pinMiso;
                 obj[F("en")]        = (bool) mCfg.nrf.enabled;
             } else {
-                getVal<uint16_t>(obj, F("intvl"), &mCfg.nrf.sendInterval);
                 getVal<uint8_t>(obj, F("cs"), &mCfg.nrf.pinCs);
                 getVal<uint8_t>(obj, F("ce"), &mCfg.nrf.pinCe);
                 getVal<uint8_t>(obj, F("irq"), &mCfg.nrf.pinIrq);
@@ -707,6 +709,7 @@ class settings {
 
         void jsonInst(JsonObject obj, bool set = false) {
             if(set) {
+                obj[F("intvl")]          = mCfg.inst.sendInterval;
                 obj[F("en")] = (bool)mCfg.inst.enabled;
                 obj[F("rstMidNight")]    = (bool)mCfg.inst.rstYieldMidNight;
                 obj[F("rstNotAvail")]    = (bool)mCfg.inst.rstValsNotAvail;
@@ -717,6 +720,7 @@ class settings {
                 obj[F("gap")]            = mCfg.inst.gapMs;
             }
             else {
+                getVal<uint16_t>(obj, F("intvl"), &mCfg.inst.sendInterval);
                 getVal<bool>(obj, F("en"), &mCfg.inst.enabled);
                 getVal<bool>(obj, F("rstMidNight"), &mCfg.inst.rstYieldMidNight);
                 getVal<bool>(obj, F("rstNotAvail"), &mCfg.inst.rstValsNotAvail);

src/defines.h

@@ -13,7 +13,7 @@
 //-------------------------------------
 #define VERSION_MAJOR       0
 #define VERSION_MINOR       8
-#define VERSION_PATCH       22
+#define VERSION_PATCH       23
 
 //-------------------------------------
 typedef struct {

src/hm/CommQueue.h

@@ -9,6 +9,7 @@
 #include <array>
 #include <functional>
 #include "hmInverter.h"
+#include "../utils/dbg.h"
 
 template <uint8_t N=100>
 class CommQueue {
@@ -29,6 +30,14 @@ class CommQueue {
             mQueue[mWrPtr] = queue_s(iv, cmd, delOnPop, false);
         }
 
+        uint8_t getFillState(void) {
+            return abs(mRdPtr - mWrPtr);
+        }
+
+        uint8_t getMaxFill(void) {
+            return N;
+        }
+
     protected:
         struct queue_s {
             Inverter<> *iv;

src/hm/Communication.h

@@ -45,8 +45,19 @@ class Communication : public CommQueue<> {
 
         void loop() {
             get([this](bool valid, const queue_s *q) {
-                if(!valid)
+                if(!valid) {
+                    if(mPrintSequenceDuration) {
+                        mPrintSequenceDuration = false;
+                        DPRINT(DBG_INFO, F("com loop duration: "));
+                        DBGPRINT(String(millis() - mLastEmptyQueueMillis));
+                        DBGPRINTLN(F("ms"));
+                        DBGPRINTLN(F("-----"));
+                    }
                     return; // empty
+                }
+                if(!mPrintSequenceDuration) // entry was added to the queue
+                    mLastEmptyQueueMillis = millis();
+                mPrintSequenceDuration = true;
 
                 uint16_t timeout     = (q->iv->ivGen == IV_MI) ? MI_TIMEOUT : ((q->iv->mGotFragment && q->iv->mGotLastMsg) || mIsRetransmit) ? SINGLEFR_TIMEOUT : DEFAULT_TIMEOUT;
                 uint16_t timeout_min = (q->iv->ivGen == IV_MI) ? MI_TIMEOUT : ((q->iv->mGotFragment || mIsRetransmit)) ? SINGLEFR_TIMEOUT : FRSTMSG_TIMEOUT;
@@ -151,7 +162,6 @@ class Communication : public CommQueue<> {
                         mIsRetransmit = false;
                         mFirstTry = false; // for correct reset
 
-                        States nextState = States::RESET;
                         while(!q->iv->radio->mBufCtrl.empty()) {
                             packet_t *p = &q->iv->radio->mBufCtrl.front();
                             printRxInfo(q, p);
@@ -162,7 +172,6 @@ class Communication : public CommQueue<> {
                                 if (p->packet[0] == (TX_REQ_INFO + ALL_FRAMES)) {  // response from get information command
                                     if(parseFrame(p))
                                         q->iv->curFrmCnt++;
-                                    nextState = States::CHECK_PACKAGE;
                                 } else if (p->packet[0] == (TX_REQ_DEVCONTROL + ALL_FRAMES)) { // response from dev control command
                                     if(parseDevCtrl(p, q))
                                         closeRequest(q, true);
@@ -179,16 +188,16 @@ class Communication : public CommQueue<> {
                             yield();
                         }
 
-                        if(0 == q->attempts)
+                        if(0 == q->attempts) {
+                            DPRINT_IVID(DBG_INFO, q->iv->id);
+                            DBGPRINT(F("no attempts left"));
                             closeRequest(q, false);
-                        else {
+                        } else {
                             if(q->iv->ivGen != IV_MI) {
-                                mState = nextState;
+                                mState = States::CHECK_PACKAGE;
-                                if(States::RESET == nextState) // no valid package received
-                                    closeRequest(q, false);
                             } else {
                                 if(q->iv->miMultiParts < 6) {
-                                    nextState = States::WAIT;
+                                    mState = States::WAIT;
                                 } else {
                                     if(((q->cmd == 0x39) && (q->iv->type == INV_TYPE_4CH))
                                         || ((q->cmd == MI_REQ_CH2) && (q->iv->type == INV_TYPE_2CH))
@@ -237,7 +246,7 @@ class Communication : public CommQueue<> {
                                 DBGPRINT(String(q->attempts));
                                 DBGPRINTLN(F(" attempts left)"));
                             }
-                            sendRetransmit(q, framnr-1);
+                            sendRetransmit(q, (framnr-1));
                             mIsRetransmit = true;
                             mlastTO_min = timeout_min;
                             return;
@@ -425,8 +434,11 @@ class Communication : public CommQueue<> {
             DPRINT_IVID(DBG_INFO, q->iv->id);
             DBGPRINT(F("Payload ("));
             DBGPRINT(String(len));
+            if(*mPrintWholeTrace) {
                 DBGPRINT(F("): "));
                 ah::dumpBuf(mPayload, len);
+            } else
+                DBGPRINTLN(F(")"));
 
             record_t<> *rec = q->iv->getRecordStruct(q->cmd);
             if(NULL == rec) {
@@ -496,7 +508,7 @@ class Communication : public CommQueue<> {
             mIsRetransmit           = false;
             mFirstTry           = false; // for correct reset
             mState              = States::RESET;
-            DBGPRINTLN("-----");
+            DBGPRINTLN(F("-----"));
         }
 
         inline void miHwDecode(packet_t *p, const queue_s *q) {
@@ -852,6 +864,8 @@ class Communication : public CommQueue<> {
         payloadListenerType mCbPayload = NULL;
         alarmListenerType mCbAlarm = NULL;
         Heuristic mHeu;
+        uint32_t mLastEmptyQueueMillis = 0;
+        bool mPrintSequenceDuration = false;
 
         //States mDebugState = States::START;
 };

src/hm/Heuristic.h

@@ -54,7 +54,7 @@ class Heuristic {
                     ih->txRfQuality[ih->testChId] = ih->txRfQuality[ih->txRfChId];
                     ih->txRfChId = ih->testChId;
                     ih->testChId = RF_TX_TEST_CHAN_1ST_USE; // mark the chan as a test and as 1st use during new test period
-                    DPRINTLN(DBG_INFO, "Test CH " + String(id2Ch(ih->txRfChId)));
+                    DPRINTLN(DBG_INFO, F("Test CH ") + String(id2Ch(ih->txRfChId)));
                 }
 
                 // start new test period
@@ -72,18 +72,30 @@ class Heuristic {
         void evalTxChQuality(Inverter<> *iv, bool crcPass, uint8_t retransmits, uint8_t rxFragments) {
             HeuristicInv *ih = &iv->heuristics;
 
+            #if (DBG_DEBUG == DEBUG_LEVEL)
+            DPRINT(DBG_DEBUG, "eval ");
+            DBGPRINT(String(crcPass));
+            DBGPRINT(", ");
+            DBGPRINT(String(retransmits));
+            DBGPRINT(", ");
+            DBGPRINT(String(rxFragments));
+            DBGPRINT(", ");
+            DBGPRINTLN(String(ih->lastRxFragments));
+            #endif
+
             if(ih->lastRxFragments == rxFragments) {
-                // nothing received: send probably lost
+                if(crcPass)
-                if(!retransmits || isNewTxCh(ih)) {
+                    updateQuality(ih, RF_TX_CHAN_QUALITY_GOOD);
+                else if(!retransmits || isNewTxCh(ih)) { // nothing received: send probably lost
                     if(RF_TX_TEST_CHAN_1ST_USE == ih->testChId) {
                         // switch back to original quality
+                        DPRINTLN(DBG_INFO, F("Test failed (-2)"));
                         ih->txRfQuality[ih->txRfChId] = ih->saveOldTestQuality;
-
+                    }
                     updateQuality(ih, RF_TX_CHAN_QUALITY_BAD);
                     if(ih->testPeriodFailCnt < 0xff)
                         ih->testPeriodFailCnt++;
                 }
-                }
             } else if(!ih->lastRxFragments && crcPass) {
                 if(!retransmits || isNewTxCh(ih)) {
                     // every fragment received successfull immediately
@@ -103,8 +115,9 @@ class Heuristic {
                     // graceful evaluation for big inverters that have to send 4 answer packets
                     updateQuality(ih, RF_TX_CHAN_QUALITY_OK);
                 } else if((rxFragments - ih->lastRxFragments) < 2) {
-                    if(RF_TX_TEST_CHAN_1ST_USE == ih->txRfChId) {
+                    if(RF_TX_TEST_CHAN_1ST_USE == ih->testChId) {
                         // switch back to original quality
+                        DPRINTLN(DBG_INFO, F("Test failed (-1)"));
                         ih->txRfQuality[ih->txRfChId] = ih->saveOldTestQuality;
                     }
                     updateQuality(ih, RF_TX_CHAN_QUALITY_LOW);

src/utils/helper.cpp

@@ -70,12 +70,14 @@ namespace ah {
         return String(str);
     }
 
-    String getTimeStrMs(time_t t) {
+    String getTimeStrMs(uint64_t t) {
         char str[13];
         if(0 == t)
             sprintf(str, "n/a");
-        else
+        else {
+            t = (t + (millis() % 1000)) / 1000;
             sprintf(str, "%02d:%02d:%02d.%03d", hour(t), minute(t), second(t), millis() % 1000);
+        }
         return String(str);
     }
 

src/utils/helper.h

@@ -44,7 +44,7 @@ namespace ah {
     String getDateTimeStrShort(time_t t);
     String getDateTimeStrFile(time_t t);
     String getTimeStr(time_t t);
-    String getTimeStrMs(time_t t);
+    String getTimeStrMs(uint64_t t);
     uint64_t Serial2u64(const char *val);
     void dumpBuf(uint8_t buf[], uint8_t len, uint8_t firstRepl = 0, uint8_t lastRepl = 0);
 }

src/utils/scheduler.h

@@ -34,6 +34,7 @@ namespace ah {
             void setup(bool directStart) {
                 mUptime     = 0;
                 mTimestamp  = (directStart) ? 1 : 0;
+                mTsMillis   = 0;
                 mMax        = 0;
                 mPrevMillis = millis();
                 resetTicker();
@@ -59,8 +60,10 @@ namespace ah {
                 }
 
                 mUptime += mDiffSeconds;
-                if(0 != mTimestamp)
+                if(0 != mTimestamp) {
                     mTimestamp += mDiffSeconds;
+                    mTsMillis  = mMillis % 1000;
+                }
                 checkTicker();
 
             }
@@ -77,6 +80,7 @@ namespace ah {
 
             virtual void setTimestamp(uint32_t ts) {
                 mTimestamp = ts;
+                mTsMillis  = millis() % 1000;
             }
 
             bool resetEveryById(uint8_t id) {
@@ -90,10 +94,6 @@ namespace ah {
                 return mUptime;
             }
 
-            uint32_t getTimestamp(void) {
-                return mTimestamp;
-            }
-
             inline void resetTicker(void) {
                 for (uint8_t i = 0; i < MAX_NUM_TICKER; i++)
                     mTickerInUse[i] = false;
@@ -118,6 +118,7 @@ namespace ah {
         protected:
             uint32_t mTimestamp;
             uint32_t mUptime;
+            uint16_t mTsMillis;
 
         private:
             inline uint8_t addTicker(scdCb c, uint32_t timeout, uint32_t reload, bool isTimestamp, const char *name) {

src/web/RestApi.h

@@ -389,7 +389,7 @@ class RestApi {
                     obj2[F("ch_max_pwr")][j]   = iv->config->chMaxPwr[j];
                 }
             }
-            obj[F("interval")]          = String(mConfig->nrf.sendInterval);
+            obj[F("interval")]          = String(mConfig->inst.sendInterval);
             obj[F("max_num_inverters")] = MAX_NUM_INVERTERS;
             obj[F("rstMid")]            = (bool)mConfig->inst.rstYieldMidNight;
             obj[F("rstNotAvail")]       = (bool)mConfig->inst.rstValsNotAvail;
@@ -556,17 +556,21 @@ class RestApi {
 
         void getRadioCmtInfo(JsonObject obj) {
             obj[F("en")] = (bool) mConfig->cmt.enabled;
+            if(mConfig->cmt.enabled) {
                 obj[F("isconnected")] = mRadioCmt->isChipConnected();
                 obj[F("sn")]          = String(mRadioCmt->getDTUSn(), HEX);
             }
+        }
         #endif
 
         void getRadioNrf(JsonObject obj) {
             obj[F("en")] = (bool) mConfig->nrf.enabled;
+            if(mConfig->nrf.enabled) {
                 obj[F("isconnected")] = mRadioNrf->isChipConnected();
                 obj[F("dataRate")]    = mRadioNrf->getDataRate();
                 obj[F("sn")]          = String(mRadioNrf->getDTUSn(), HEX);
             }
+        }
 
         void getSerial(JsonObject obj) {
             obj[F("show_live_data")] = mConfig->serial.showIv;
@@ -639,8 +643,6 @@ class RestApi {
             JsonArray warn = obj.createNestedArray(F("warnings"));
             if(!mRadioNrf->isChipConnected() && mConfig->nrf.enabled)
                 warn.add(F("your NRF24 module can't be reached, check the wiring, pinout and enable"));
-            else if(!mRadioNrf->isPVariant() && mConfig->nrf.enabled)
-                warn.add(F("your NRF24 module isn't a plus version(+), maybe incompatible"));
             if(!mApp->getSettingsValid())
                 warn.add(F("your settings are invalid"));
             if(mApp->getRebootRequestState())
@@ -674,7 +676,7 @@ class RestApi {
 
         void getLive(AsyncWebServerRequest *request, JsonObject obj) {
             getGeneric(request, obj.createNestedObject(F("generic")));
-            obj[F("refresh")] = mConfig->nrf.sendInterval;
+            obj[F("refresh")] = mConfig->inst.sendInterval;
 
             for (uint8_t fld = 0; fld < sizeof(acList); fld++) {
                 obj[F("ch0_fld_units")][fld] = String(units[fieldUnits[acList[fld]]]);

src/web/web.h

@@ -210,7 +210,7 @@ class Web {
             if (mSerialAddTime) {
                 if ((13 + mSerialBufFill) < WEB_SERIAL_BUF_SIZE) {
                     if (mApp->getTimestamp() > 0) {
-                        strncpy(&mSerialBuf[mSerialBufFill], ah::getTimeStrMs(mApp->getTimestamp() + mApp->getTimezoneOffset()).c_str(), 12);
+                        strncpy(&mSerialBuf[mSerialBufFill], ah::getTimeStrMs(mApp->getTimestampMs() + mApp->getTimezoneOffset() * 1000).c_str(), 12);
                         mSerialBuf[mSerialBufFill+12] = ' ';
                         mSerialBufFill += 13;
                     }
@@ -496,7 +496,7 @@ class Web {
             ah::ip2Arr(mConfig->sys.ip.gateway, buf);
 
             if (request->arg("invInterval") != "")
-                mConfig->nrf.sendInterval = request->arg("invInterval").toInt();
+                mConfig->inst.sendInterval = request->arg("invInterval").toInt();
             mConfig->inst.rstYieldMidNight = (request->arg("invRstMid") == "on");
             mConfig->inst.rstValsCommStop = (request->arg("invRstComStop") == "on");
             mConfig->inst.rstValsNotAvail = (request->arg("invRstNotAvail") == "on");
@@ -529,8 +529,6 @@ class Web {
             }
 
             mConfig->nrf.enabled = (request->arg("nrfEnable") == "on");
-
-            // cmt
             mConfig->cmt.enabled = (request->arg("cmtEnable") == "on");
 
             // ntp