Merge pull request #5624 from TD-er/bugfix/log_crash

[Log] Fix crashes processing logs from callback/SDK events

src/src/DataStructs/LogBuffer.cpp

@@ -3,11 +3,29 @@
 #include "../Helpers/ESPEasy_time_calc.h"
 #include "../Helpers/StringConverter.h"
 
+LogBuffer::LogBuffer()
+{
+  for (size_t i = 0; i < NR_LOG_TO_DESTINATIONS; ++i) {
+    cache_iterator_pos[i] = LogEntries.begin();
+  }
+}
+
 void LogBuffer::add(LogEntry_t&& logEntry) {
   clearExpiredEntries();
 
   if (logEntry) {
+    const auto oldEnd = LogEntries.end();
     LogEntries.emplace_back(std::move(logEntry));
+    {
+      auto newit = LogEntries.end();
+      --newit; // We don't have a function to get an iterator to the last element
+
+      for (size_t i = 0; i < NR_LOG_TO_DESTINATIONS; ++i) {
+        if (cache_iterator_pos[i] == oldEnd) {
+          cache_iterator_pos[i] = newit;
+        }
+      }
+    }
   }
 }
 
@@ -17,16 +35,16 @@ bool LogBuffer::getNext(LogDestination logDestination, uint32_t& timestamp, Stri
 
   lastReadTimeStamp[logDestination] = millis();
 
-  while (cache_iterator_pos[logDestination] < LogEntries.size())
+  while (cache_iterator_pos[logDestination] != LogEntries.end())
   {
     const auto pos = cache_iterator_pos[logDestination];
     ++cache_iterator_pos[logDestination];
 
-    if (LogEntries[pos].validForSubscriber(logDestination)) {
-      timestamp = LogEntries[pos].getTimestamp();
-      message   = LogEntries[pos].getMessage();
-      loglevel  = LogEntries[pos].getLogLevel();
-      LogEntries[pos].markReadBySubscriber(logDestination);
+    if (pos->validForSubscriber(logDestination)) {
+      timestamp = pos->getTimestamp();
+      message   = pos->getMessage();
+      loglevel  = pos->getLogLevel();
+      pos->markReadBySubscriber(logDestination);
       clearExpiredEntries();
       return true;
     }
@@ -40,10 +58,10 @@ bool LogBuffer::hasMessages(LogDestination logDestination)
 
   clearExpiredEntries(); // Cleanup the old stuff first
 
-  uint32_t pos = cache_iterator_pos[logDestination];
+  auto pos = cache_iterator_pos[logDestination];
 
-  for (; pos < LogEntries.size(); ++pos) {
-    if (LogEntries[pos].validForSubscriber(logDestination)) {
+  for (; pos != LogEntries.end(); ++pos) {
+    if (pos->validForSubscriber(logDestination)) {
       cache_iterator_pos[logDestination] = pos;
       return true;
     }
@@ -53,26 +71,43 @@ bool LogBuffer::hasMessages(LogDestination logDestination)
   return false;
 }
 
-bool LogBuffer::logActiveRead(LogDestination logDestination) {
+bool LogBuffer::logActiveRead(LogDestination logDestination) const {
   if (logDestination >= NR_LOG_TO_DESTINATIONS) { return false; }
   return timePassedSince(lastReadTimeStamp[logDestination]) < LOG_BUFFER_ACTIVE_READ_TIMEOUT;
 }
 
 void LogBuffer::clearExpiredEntries() {
+
+  #ifdef ESP32
+
+  if (xPortInIsrContext()) {
+    // When called from an ISR, you should not try to erase log entries
+    // Messing with memory from within an ISR is a big no-no.
+    return;
+  }
+  #endif // ifdef ESP32
+
+  static bool clearExpiredEntriesRunning{};
+
+  if (clearExpiredEntriesRunning) { return; }
+  clearExpiredEntriesRunning = true;
+
   for (auto it = LogEntries.begin(); it != LogEntries.end();)
   {
     it->updateSubscribers();
 
     if (it->isExpired()) {
+      auto next = LogEntries.erase(it);
+
       for (size_t i = 0; i < NR_LOG_TO_DESTINATIONS; ++i) {
-        if (cache_iterator_pos[i]) {
-          --cache_iterator_pos[i];
+        if (it == cache_iterator_pos[i]) {
+          cache_iterator_pos[i] = next;
         }
       }
-
-      it = LogEntries.erase(it);
+      it = next;
     } else {
-      return;
+      ++it;
     }
   }
+  clearExpiredEntriesRunning = false;
 }

src/src/DataStructs/LogBuffer.h

@@ -8,7 +8,7 @@
 
 #include "../DataTypes/LogLevels.h"
 
-#include <deque>
+#include <list>
 
 /*********************************************************************************************\
 * LogBuffer
@@ -33,12 +33,12 @@
   # define LOG_BUFFER_ACTIVE_READ_TIMEOUT 5000
 #endif // ifdef ESP32
 
-typedef std::deque<LogEntry_t> LogEntry_queue;
+typedef std::list<LogEntry_t> LogEntry_queue;
 
 
 struct LogBuffer {
 
-  LogBuffer() = default;
+  LogBuffer();
 
   void add(LogEntry_t&& logEntry);
 
@@ -47,24 +47,23 @@ struct LogBuffer {
   }
 
   // Returns whether a line was retrieved.
-  bool getNext(LogDestination   logDestination,
-               uint32_t& timestamp,
-               String  & message,
-               uint8_t & loglevel);
+  bool getNext(LogDestination logDestination,
+               uint32_t     & timestamp,
+               String       & message,
+               uint8_t      & loglevel);
 
   // Return true if messages available for given log destination.
   bool hasMessages(LogDestination logDestination);
 
-  bool logActiveRead(LogDestination logDestination);
+  bool logActiveRead(LogDestination logDestination) const;
 
   void clearExpiredEntries();
 
 private:
 
-  LogEntry_queue LogEntries;
-  uint32_t       lastReadTimeStamp[NR_LOG_TO_DESTINATIONS]{};
-
-  uint32_t cache_iterator_pos[NR_LOG_TO_DESTINATIONS]{};
+  LogEntry_queue           LogEntries{};
+  uint32_t                 lastReadTimeStamp[NR_LOG_TO_DESTINATIONS]{};
+  LogEntry_queue::iterator cache_iterator_pos[NR_LOG_TO_DESTINATIONS]{};
 
 };
 

src/src/DataStructs/LogEntry.cpp

@@ -108,7 +108,8 @@ void LogEntry_t::clear()
   if (!_isFlashString && (_message != nullptr)) {
     free(_message);
   }
-  _message = nullptr;
+  _message               = nullptr;
+  _subscriberPendingRead = 0; // TODO TD-er: Maybe better to do _flags = 0 ???
 
   //  _strLength = 0;
 }
@@ -130,13 +131,14 @@ void LogEntry_t::setSubscribers()
 void LogEntry_t::updateSubscribers()
 {
   if (isValid()) {
-    for (uint32_t i = 0; i < NR_LOG_TO_DESTINATIONS; ++i) {
+    for (uint32_t i = 0; _subscriberPendingRead && i < NR_LOG_TO_DESTINATIONS; ++i) {
       if (bitRead(_subscriberPendingRead, i)) {
         if (!loglevelActiveFor(static_cast<LogDestination>(i), _logLevel)) {
           bitClear(_subscriberPendingRead, i);
         }
       }
     }
+
     if (_subscriberPendingRead == 0) {
       clear();
     }

src/src/DataStructs/timer_id_couple.cpp

@@ -3,8 +3,10 @@
 #include "../Helpers/ESPEasy_time_calc.h"
 
 bool timer_id_couple::operator<(const timer_id_couple& other) const {
-  const unsigned long now(millis());
+  // timeDiff is positive when _timer is before other._timer
+  return timeDiff(_timer, other._timer) > 0;
+}
 
-  // timediff > 0, means timer has already passed
-  return timeDiff(_timer, now) > timeDiff(other._timer, now);
+bool timer_id_couple::operator()(const timer_id_couple& item) const {
+  return _id == item._id;
 }

src/src/DataStructs/timer_id_couple.h

@@ -17,8 +17,12 @@ struct timer_id_couple {
 
   bool operator<(const timer_id_couple& other) const;
 
-  unsigned long _id;
-  unsigned long _timer;
+  // Returns true when _id matches.
+  bool operator()(const timer_id_couple& item) const;
+
+
+  unsigned long _id{};
+  unsigned long _timer{};
 };
 
 

src/src/Helpers/ESPEasyStatistics.h

@@ -9,8 +9,6 @@
 #ifdef WEBSERVER_NEW_UI
 #include "../DataStructs/TimingStats.h"
 
-//void logStatistics(uint8_t loglevel, bool clearStats);
-
 void stream_json_timing_stats(const TimingStats& stats, long timeSinceLastReset);
 
 void jsonStatistics(bool clearStats);

src/src/Helpers/ESPEasy_time_calc.h

@@ -18,7 +18,8 @@ inline uint64_t getMicros64() {
  \*********************************************************************************************/
 
 // Return the time difference as a signed value, taking into account the timers may overflow.
-// Returned timediff is between -24.9 days and +24.9 days.
+// Returned timediff for millis() is between -24.9 days and +24.9 days.
+//          for micros() is between -35.79 and +35.79 minutes
 // Returned value is positive when "next" is after "prev"
 inline int32_t timeDiff(const unsigned long prev, const unsigned long next) {
   return ((int32_t) (next - prev));

src/src/Helpers/PeriodicalActions.cpp

@@ -495,23 +495,6 @@ void runPeriodicalMQTT() {
 
 
 void logTimerStatistics() {
-# ifndef BUILD_NO_DEBUG
-  const uint8_t loglevel = LOG_LEVEL_DEBUG;
-#else
-  const uint8_t loglevel = LOG_LEVEL_NONE;
-#endif
-  updateLoopStats_30sec(loglevel);
-#ifndef BUILD_NO_DEBUG
-//  logStatistics(loglevel, true);
-  if (loglevelActiveFor(loglevel)) {
-    String queueLog = F("Scheduler stats: (called/tasks/max_length/idle%) ");
-    queueLog += Scheduler.getQueueStats();
-    addLogMove(loglevel, queueLog);
-  }
-#endif
-}
-
-void updateLoopStats_30sec(uint8_t loglevel) {
   loopCounterLast = loopCounter;
   loopCounter = 0;
   if (loopCounterLast > loopCounterMax)
@@ -520,18 +503,18 @@ void updateLoopStats_30sec(uint8_t loglevel) {
   Scheduler.updateIdleTimeStats();
 
 #ifndef BUILD_NO_DEBUG
+  const uint8_t loglevel = LOG_LEVEL_DEBUG;
   if (loglevelActiveFor(loglevel)) {
-    String log = F("LoopStats: shortestLoop: ");
-    log += shortestLoop;
-    log += F(" longestLoop: ");
-    log += longestLoop;
-    log += F(" avgLoopDuration: ");
-    log += loop_usec_duration_total / loopCounter_full;
-    log += F(" loopCounterMax: ");
-    log += loopCounterMax;
-    log += F(" loopCounterLast: ");
-    log += loopCounterLast;
-    addLogMove(loglevel, log);
+    addLogMove(loglevel, strformat(
+      F("LoopStats: shortest: %u longest: %u avg: %.2f LC_Max: %u LC_Last: %u"),
+      shortestLoop, 
+      longestLoop, 
+      loop_usec_duration_total / loopCounter_full, 
+      loopCounterMax, 
+      loopCounterLast));
+    addLogMove(loglevel, concat(
+      F("Scheduler stats: (called/tasks/max_length/idle%) "), 
+      Scheduler.getQueueStats()));
   }
 #endif
   loop_usec_duration_total = 0;
@@ -539,6 +522,7 @@ void updateLoopStats_30sec(uint8_t loglevel) {
 }
 
 
+
 /********************************************************************************************\
    Clean up all before going to sleep or reboot.
  \*********************************************************************************************/

src/src/Helpers/PeriodicalActions.h

@@ -44,8 +44,6 @@ void runPeriodicalMQTT();
 
 void logTimerStatistics();
 
-void updateLoopStats_30sec(uint8_t loglevel);
-
 /********************************************************************************************\
    Clean up all before going to sleep or reboot.
  \*********************************************************************************************/

src/src/Helpers/Scheduler.cpp

@@ -97,10 +97,11 @@ void ESPEasy_Scheduler::handle_schedule() {
   }
   STOP_TIMER(HANDLE_SCHEDULER_TASK);
 }
-
+#ifndef BUILD_NO_DEBUG
 String ESPEasy_Scheduler::getQueueStats() {
   return msecTimerHandler.getQueueStats();
 }
+#endif
 
 void ESPEasy_Scheduler::updateIdleTimeStats() {
   msecTimerHandler.updateIdleTimeStats();

src/src/Helpers/Scheduler.h

@@ -310,8 +310,9 @@ void                 setPluginTaskTimer(unsigned long msecFromNow,
   /*********************************************************************************************\
   * Statistics
   \*********************************************************************************************/
-
+#ifndef BUILD_NO_DEBUG
   String getQueueStats();
+#endif
 
   void   updateIdleTimeStats();
 

src/src/Helpers/msecTimerHandlerStruct.cpp

@@ -4,10 +4,9 @@
 #include "../Helpers/ESPEasy_time_calc.h"
 
 
-#define MAX_SCHEDULER_WAIT_TIME 50 // Max delay used in the scheduler for passing idle time.
+#define MAX_SCHEDULER_WAIT_TIME 20 // Max delay used in the scheduler for passing idle time.
 
-  msecTimerHandlerStruct::msecTimerHandlerStruct() : get_called(0), get_called_ret_id(0), max_queue_length(0),
-    last_exec_time_usec(0), total_idle_time_usec(0),  idle_time_pct(0.0f), is_idle(false), eco_mode(true)
+  msecTimerHandlerStruct::msecTimerHandlerStruct() : eco_mode(true)
   {
     last_log_start_time = millis();
   }
@@ -30,17 +29,16 @@
   // Check if timeout has been reached and also return its set timer.
   // Return 0 if no item has reached timeout moment.
   unsigned long msecTimerHandlerStruct::getNextId(unsigned long& timer) {
+#ifndef BUILD_NO_DEBUG
     ++get_called;
+#endif
 
     if (_timer_ids.empty()) {
       recordIdle();
-
-      if (eco_mode) {
-        delay(MAX_SCHEDULER_WAIT_TIME); // Nothing to do, try save some power.
-      }
+      delay(eco_mode ? MAX_SCHEDULER_WAIT_TIME : 0); // Nothing to do, try save some power.
       return 0;
     }
-    timer_id_couple item = _timer_ids.front();
+    const timer_id_couple item = _timer_ids.front();
     const long passed    = timePassedSince(item._timer);
 
     if (passed < 0) {
@@ -61,12 +59,12 @@
       return 0;
     }
     recordRunning();
-    unsigned long size = _timer_ids.size();
 
-    if (size > max_queue_length) { max_queue_length = size; }
     _timer_ids.pop_front();
     timer = item._timer;
+#ifndef BUILD_NO_DEBUG
     ++get_called_ret_id;
+#endif
     return item._id;
   }
 
@@ -80,7 +78,7 @@
     }
     return false;
   }
-
+#ifndef BUILD_NO_DEBUG
   String msecTimerHandlerStruct::getQueueStats() {
     String result;
 
@@ -97,12 +95,15 @@
     // max_queue_length = 0;
     return result;
   }
+  #endif
 
   void msecTimerHandlerStruct::updateIdleTimeStats() {
-    const long duration = timePassedSince(last_log_start_time);
-
+    const long duration = timePassedSince(last_log_start_time) * 10;
+    if (duration == 0) return;
+    recordRunning();
     last_log_start_time  = millis();
-    idle_time_pct        = static_cast<float>(total_idle_time_usec) / duration / 10.0f;
+    idle_time_pct = static_cast<float>(total_idle_time_usec);
+    idle_time_pct /= static_cast<float>(duration);
     total_idle_time_usec = 0;
   }
 
@@ -110,38 +111,48 @@
     return idle_time_pct;
   }
 
-  struct match_id {
-    match_id(unsigned long id) : _id(id) {}
-
-    bool operator()(const timer_id_couple& item) {
-      return _id == item._id;
-    }
-
-    unsigned long _id;
-  };
-
   void msecTimerHandlerStruct::insert(const timer_id_couple& item) {
     if (item._id == 0) { return; }
 
     // Make sure only one is present with the same id.
-    _timer_ids.remove_if(match_id(item._id));
-    const bool mustSort = !_timer_ids.empty();
-    _timer_ids.push_front(item);
+    // Keep in mind: order is based on timer, uniqueness is based on id.
+    _timer_ids.remove_if(item);
 
-    if (mustSort) {
-      _timer_ids.sort(); // TD-er: Must check if this is an expensive operation.
+    // Insert into a sorted list, so find first pos which should be handled after this item.
+    auto prev = _timer_ids.begin();
+    if (_timer_ids.empty() || prev == _timer_ids.end() || item < *prev) {
+      _timer_ids.push_front(item);
+      return;
     }
 
-    // It should be a relative light operation, to insert into a sorted list.
-    // Perhaps it is better to use std::set ????
-    // Keep in mind: order is based on timer, uniqueness is based on id.
+//    _timer_ids.push_front(item);
+//    _timer_ids.sort();
+//    return;
+
+
+    auto it = prev;
+    ++it;
+    for (;it != _timer_ids.end() && *it < item; ++it, ++prev) {}
+
+
+//    auto stats_it = 
+    _timer_ids.insert_after(prev, item);
+#ifndef BUILD_NO_DEBUG
+    auto size = std::distance(_timer_ids.begin(), prev) + 1;
+
+    // TODO TD-er: No need to loop each time through the list.
+    // Stats are just some indication, don't need to be that exact.
+    // std::forward_list doesn't have size()
+//    for (; stats_it != _timer_ids.end(); ++stats_it, ++size) {}
+    if (size > max_queue_length) { max_queue_length = size; }    
+#endif
   }
 
   void msecTimerHandlerStruct::remove(const timer_id_couple& item) {
     if (item._id == 0) { return; }
 
     // Make sure only one is present with the same id.
-    _timer_ids.remove_if(match_id(item._id));
+    _timer_ids.remove_if(item);
   }
 
   void msecTimerHandlerStruct::recordIdle() {

src/src/Helpers/msecTimerHandlerStruct.h

@@ -3,7 +3,7 @@
 
 
 #include "../../ESPEasy_common.h"
-#include <list>
+#include <forward_list>
 
 #include "../DataStructs/timer_id_couple.h"
 
@@ -26,8 +26,9 @@ struct msecTimerHandlerStruct {
   // N.B. the ID is the mixed ID.
   bool   getTimerForId(unsigned long  id,
                        unsigned long& timer) const;
-
+#ifndef BUILD_NO_DEBUG
   String getQueueStats();
+#endif
 
   void   updateIdleTimeStats();
 
@@ -43,21 +44,23 @@ private:
 
   void recordRunning();
 
+#ifndef BUILD_NO_DEBUG
   // Statistics
-  unsigned long get_called;
-  unsigned long get_called_ret_id;
-  unsigned long max_queue_length;
+  unsigned long get_called{};
+  unsigned long get_called_ret_id{};
+  unsigned long max_queue_length{};
+#endif
 
   // Compute idle system time
-  uint32_t last_exec_time_usec;
-  uint32_t total_idle_time_usec;
-  uint32_t last_log_start_time;
-  float         idle_time_pct;
-  bool          is_idle;
-  bool          eco_mode;
+  uint32_t last_exec_time_usec{};
+  uint32_t total_idle_time_usec{};
+  uint32_t last_log_start_time{};
+  float         idle_time_pct{};
+  bool          is_idle{};
+  bool          eco_mode{};
 
   // The list of set timers
-  std::list<timer_id_couple>_timer_ids;
+  std::forward_list<timer_id_couple>_timer_ids;
 };
 
 #endif // HELPERS_MSECTIMERHANDLERSTRUCT_H