From b3f4a11a8e39ac8a5aad3ead02cf671a29dbad19 Mon Sep 17 00:00:00 2001 From: andreas Date: Sat, 13 Nov 2021 18:15:50 +0100 Subject: [PATCH] improve logging MT robustness --- lib/led/GwLeds.cpp | 1 + lib/log/GWLog.cpp | 16 ++++++++++++++- lib/log/GwLog.h | 2 ++ lib/serial/GwSerial.cpp | 13 ++++++------ lib/serial/GwSerial.h | 4 ++-- src/main.cpp | 44 ++++++++++++++++++++++++++++++++--------- 6 files changed, 62 insertions(+), 18 deletions(-) diff --git a/lib/led/GwLeds.cpp b/lib/led/GwLeds.cpp index d9c18c8..c8758a0 100644 --- a/lib/led/GwLeds.cpp +++ b/lib/led/GwLeds.cpp @@ -28,6 +28,7 @@ void handleLeds(void *param){ GwLog *logger=api->getLogger(); #ifndef GWLED_FASTLED LOG_DEBUG(GwLog::LOG,"currently only fastled handling"); + delay(50); vTaskDelete(NULL); return; #else diff --git a/lib/log/GWLog.cpp b/lib/log/GWLog.cpp index d7ff12a..0a62eb3 100644 --- a/lib/log/GWLog.cpp +++ b/lib/log/GWLog.cpp @@ -34,7 +34,11 @@ void GwLog::logDebug(int level,const char *fmt,...){ va_start(args,fmt); xSemaphoreTake(locker, portMAX_DELAY); vsnprintf(buffer,99,fmt,args); - if (! writer) return; + buffer[99]=0; + if (! writer) { + xSemaphoreGive(locker); + return; + } writer->write(prefix.c_str()); writer->write(buffer); writer->write("\n"); @@ -46,3 +50,13 @@ void GwLog::setWriter(GwLogWriter *writer){ this->writer=writer; xSemaphoreGive(locker); } + +void GwLog::flush(){ + xSemaphoreTake(locker, portMAX_DELAY); + if (! this->writer) { + xSemaphoreGive(locker); + return; + } + this->writer->flush(); + xSemaphoreGive(locker); +} diff --git a/lib/log/GwLog.h b/lib/log/GwLog.h index 205b503..5cb2c16 100644 --- a/lib/log/GwLog.h +++ b/lib/log/GwLog.h @@ -6,6 +6,7 @@ class GwLogWriter{ public: virtual ~GwLogWriter(){} virtual void write(const char *data)=0; + virtual void flush(){}; }; class GwLog{ private: @@ -25,6 +26,7 @@ class GwLog{ void logString(const char *fmt,...); void logDebug(int level, const char *fmt,...); int isActive(int level){return level <= logLevel;}; + void flush(); }; #define LOG_DEBUG(level,...){ if (logger != NULL && logger->isActive(level)) logger->logDebug(level,__VA_ARGS__);} diff --git a/lib/serial/GwSerial.cpp b/lib/serial/GwSerial.cpp index 41c5632..de97e67 100644 --- a/lib/serial/GwSerial.cpp +++ b/lib/serial/GwSerial.cpp @@ -46,23 +46,24 @@ int GwSerial::setup(int baud, int rxpin, int txpin) return 0; } bool GwSerial::isInitialized() { return initialized; } -size_t GwSerial::enqueue(const uint8_t *data, size_t len) +size_t GwSerial::enqueue(const uint8_t *data, size_t len, bool partial) { if (! isInitialized()) return 0; - return buffer->addData(data, len); + return buffer->addData(data, len,partial); } GwBuffer::WriteStatus GwSerial::write(){ if (! isInitialized()) return GwBuffer::ERROR; return buffer->fetchData(writer,-1,false); } -void GwSerial::sendToClients(const char *buf,int sourceId){ - if ( sourceId == id) return; +size_t GwSerial::sendToClients(const char *buf,int sourceId,bool partial){ + if ( sourceId == id) return 0; size_t len=strlen(buf); - size_t enqueued=enqueue((const uint8_t*)buf,len); - if (enqueued != len){ + size_t enqueued=enqueue((const uint8_t*)buf,len,partial); + if (enqueued != len && ! partial){ LOG_DEBUG(GwLog::DEBUG,"GwSerial overflow on channel %d",id); overflows++; } + return enqueued; } void GwSerial::loop(bool handleRead){ write(); diff --git a/lib/serial/GwSerial.h b/lib/serial/GwSerial.h index 97c3e71..220b501 100644 --- a/lib/serial/GwSerial.h +++ b/lib/serial/GwSerial.h @@ -16,7 +16,7 @@ class GwSerial{ GwBuffer::WriteStatus write(); int id=-1; int overflows=0; - size_t enqueue(const uint8_t *data, size_t len); + size_t enqueue(const uint8_t *data, size_t len,bool partial=false); HardwareSerial *serial; public: static const int bufferSize=200; @@ -24,7 +24,7 @@ class GwSerial{ ~GwSerial(); int setup(int baud,int rxpin,int txpin); bool isInitialized(); - void sendToClients(const char *buf,int sourceId); + size_t sendToClients(const char *buf,int sourceId,bool partial=false); void loop(bool handleRead=true); bool readMessages(GwBufferWriter *writer); void flush(); diff --git a/src/main.cpp b/src/main.cpp index a9b957a..afec2f3 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -171,10 +171,31 @@ GwSerial *serial1=NULL; class GwSerialLog : public GwLogWriter{ + static const size_t bufferSize=4096; + char *logBuffer=NULL; + int wp=0; public: + GwSerialLog(){ + logBuffer=new char[bufferSize]; + wp=0; + } virtual ~GwSerialLog(){} virtual void write(const char *data){ - usbSerial->sendToClients(data,-1); //ignore any errors + int len=strlen(data); + if ((wp+len) >= (bufferSize-1)) return; + strncpy(logBuffer+wp,data,len); + wp+=len; + logBuffer[wp]=0; + } + virtual void flush(){ + size_t handled=0; + while (handled < wp){ + usbSerial->flush(); + size_t rt=usbSerial->sendToClients(logBuffer+handled,-1,true); + handled+=rt; + } + wp=0; + logBuffer[0]=0; } }; @@ -214,12 +235,14 @@ public: } }; -void delayedRestart(){ - xTaskCreate([](void *p){ +bool delayedRestart(){ + return xTaskCreate([](void *p){ + GwLog *logRef=(GwLog *)p; + logRef->logDebug(GwLog::LOG,"delayed reset started"); delay(500); ESP.restart(); vTaskDelete(NULL); - },"reset",1000,NULL,0,NULL); + },"reset",1000,&logger,0,NULL) == pdPASS; } @@ -243,7 +266,9 @@ protected: { logger.logDebug(GwLog::LOG, "Reset Button"); result = JSON_OK; - delayedRestart(); + if (!delayedRestart()){ + logger.logDebug(GwLog::ERROR,"cannot initiate restart"); + } } }; @@ -463,10 +488,10 @@ void setup() { // Start TCP server socketServer.begin(); - usbSerial->flush(); + logger.flush(); logger.logDebug(GwLog::LOG,"usbRead: %s", usbReadFilter.toString().c_str()); - usbSerial->flush(); + logger.flush(); webserver.registerMainHandler("/api/reset", [](AsyncWebServerRequest *request)->GwRequestMessage *{ return new ResetRequest(); @@ -540,7 +565,7 @@ void setup() { preferences.end(); logger.logDebug(GwLog::LOG,"NodeAddress=%d", NodeAddress); - usbSerial->flush(); + logger.flush(); NMEA2000.SetMode(tNMEA2000::N2km_ListenAndNode, NodeAddress); NMEA2000.SetForwardOwnMessages(false); // Set the information for other bus devices, which messages we support @@ -549,7 +574,7 @@ void setup() { unsigned long *op=pgns; while (*op != 0){ logger.logDebug(GwLog::DEBUG,"add transmit pgn %ld",(long)(*op)); - usbSerial->flush(); + logger.flush(); op++; } } @@ -666,6 +691,7 @@ class NMEAMessageReceiver : public GwBufferWriter{ NMEAMessageReceiver receiver; unsigned long lastHeapReport=0; void loop() { + logger.flush(); gwWifi.loop(); unsigned long now=millis(); if (HEAP_REPORT_TIME > 0 && now > (lastHeapReport+HEAP_REPORT_TIME)){