Merge pull request #258 from kivancsikert/logging/fixes

Logging fixes

main/devices/Device.hpp

@@ -18,12 +18,15 @@
 #include <kernel/Kernel.hpp>
 #include <kernel/Task.hpp>
 #include <kernel/drivers/RtcDriver.hpp>
+#include <kernel/mqtt/MqttDriver.hpp>
+#include <kernel/mqtt/MqttRoot.hpp>
 
 using namespace std::chrono;
 using namespace std::chrono_literals;
 using std::shared_ptr;
 using namespace farmhub::kernel;
 using namespace farmhub::kernel::drivers;
+using namespace farmhub::kernel::mqtt;
 
 #if defined(MK4)
 #include <devices/UglyDucklingMk4.hpp>
@@ -213,7 +216,7 @@ class MemoryTelemetryProvider : public TelemetryProvider {
 
 class MqttTelemetryPublisher : public TelemetryPublisher {
 public:
-    MqttTelemetryPublisher(shared_ptr<MqttDriver::MqttRoot> mqttRoot, TelemetryCollector& telemetryCollector)
+    MqttTelemetryPublisher(shared_ptr<MqttRoot> mqttRoot, TelemetryCollector& telemetryCollector)
         : mqttRoot(mqttRoot)
         , telemetryCollector(telemetryCollector) {
     }
@@ -223,7 +226,7 @@ class MqttTelemetryPublisher : public TelemetryPublisher {
     }
 
 private:
-    shared_ptr<MqttDriver::MqttRoot> mqttRoot;
+    shared_ptr<MqttRoot> mqttRoot;
     TelemetryCollector& telemetryCollector;
 };
 
@@ -248,12 +251,13 @@ class ConfiguredKernel {
             });
         }
 
-        LOGI("  ______                   _    _       _");
-        LOGI(" |  ____|                 | |  | |     | |");
-        LOGI(" | |__ __ _ _ __ _ __ ___ | |__| |_   _| |__");
-        LOGI(" |  __/ _` | '__| '_ ` _ \\|  __  | | | | '_ \\");
-        LOGI(" | | | (_| | |  | | | | | | |  | | |_| | |_) |");
-        LOGI(" |_|  \\__,_|_|  |_| |_| |_|_|  |_|\\__,_|_.__/ " FARMHUB_VERSION);
+        LOGD("   ______                   _    _       _");
+        LOGD("  |  ____|                 | |  | |     | |");
+        LOGD("  | |__ __ _ _ __ _ __ ___ | |__| |_   _| |__");
+        LOGD("  |  __/ _` | '__| '_ ` _ \\|  __  | | | | '_ \\");
+        LOGD("  | | | (_| | |  | | | | | | |  | | |_| | |_) |");
+        LOGD("  |_|  \\__,_|_|  |_| |_| |_|_|  |_|\\__,_|_.__/ " FARMHUB_VERSION);
+        LOGD("  ");
     }
 
     void registerShutdownListener(std::function<void()> listener) {
@@ -388,13 +392,21 @@ class Device {
                 if (record.level > deviceConfig.publishLogs.get()) {
                     return;
                 }
+                auto length = record.message.length();
+                // Remove the level prefix
+                auto messageStart = 2;
+                // Remove trailing newline
+                auto messageEnd = record.message.charAt(length - 1) == '\n'
+                    ? length - 1
+                    : length;
+                String message = record.message.substring(messageStart, messageEnd);
 
                 mqttDeviceRoot->publish(
                     "log", [&](JsonObject& json) {
                         json["level"] = record.level;
-                        json["message"] = record.message;
+                        json["message"] = message;
                     },
-                    MqttDriver::Retention::NoRetain, MqttDriver::QoS::AtLeastOnce, ticks::zero(), MqttDriver::LogPublish::Silent);
+                    Retention::NoRetain, QoS::AtLeastOnce, 2s, LogPublish::Silent);
             });
         });
 
@@ -444,7 +456,7 @@ class Device {
                 json["peripherals"].to<JsonArray>().set(peripheralsInitJson);
                 json["sleepWhenIdle"] = kernel.sleepManager.sleepWhenIdle;
             },
-            MqttDriver::Retention::NoRetain, MqttDriver::QoS::AtLeastOnce, ticks::max());
+            Retention::NoRetain, QoS::AtLeastOnce, ticks::max());
 
         Task::loop("telemetry", 8192, [this](Task& task) {
             publishTelemetry();
@@ -496,7 +508,7 @@ class Device {
     TDeviceDefinition& deviceDefinition = configuredKernel.deviceDefinition;
     TDeviceConfiguration& deviceConfig = deviceDefinition.config;
 
-    shared_ptr<MqttDriver::MqttRoot> mqttDeviceRoot = kernel.mqtt.forRoot(locationPrefix() + "devices/ugly-duckling/" + deviceConfig.instance.get());
+    shared_ptr<MqttRoot> mqttDeviceRoot = kernel.mqtt.forRoot(locationPrefix() + "devices/ugly-duckling/" + deviceConfig.instance.get());
     PeripheralManager peripheralManager { kernel.i2c, deviceDefinition.pcnt, deviceDefinition.pwm, kernel.sleepManager, kernel.switches, mqttDeviceRoot };
 
     TelemetryCollector deviceTelemetryCollector;

main/kernel/Component.hpp

@@ -1,20 +1,20 @@
 #pragma once
 
 #include <kernel/Named.hpp>
-#include <kernel/drivers/MqttDriver.hpp>
+#include <kernel/mqtt/MqttRoot.hpp>
 
-using namespace farmhub::kernel::drivers;
+using namespace farmhub::kernel::mqtt;
 
 namespace farmhub::kernel {
 
 class Component : public Named {
 protected:
-    Component(const String& name, shared_ptr<MqttDriver::MqttRoot> mqttRoot)
+    Component(const String& name, shared_ptr<MqttRoot> mqttRoot)
         : Named(name)
         , mqttRoot(mqttRoot) {
     }
 
-    shared_ptr<MqttDriver::MqttRoot> mqttRoot;
+    shared_ptr<MqttRoot> mqttRoot;
 };
 
 }    // namespace farmhub::kernel

main/kernel/Console.hpp

@@ -42,11 +42,7 @@ class ConsoleProvider {
 
     int processLog(const char* format, va_list args) {
         Level level = getLevel(format[0]);
-        if (level <= recordedLevel) {
-            std::lock_guard<std::mutex> lock(bufferMutex);
-            vsnprintf(buffer, BUFFER_SIZE, format, args);
-            logRecords.offer(level, buffer);
-        }
+        recordLog(level, format, args);
 
         int count = 0;
 #ifdef FARMHUB_DEBUG
@@ -87,6 +83,31 @@ class ConsoleProvider {
         return count;
     }
 
+    void recordLog(Level level, const char* format, va_list args) {
+        if (level > recordedLevel) {
+            return;
+        }
+
+        int length;
+        {
+            std::lock_guard<std::mutex> lock(bufferMutex);
+            length = vsnprintf(buffer, BUFFER_SIZE, format, args);
+            if (length < 0) {
+                printf("Encountered an encoding error");
+            } else if (length < BUFFER_SIZE) {
+                logRecords.offer(level, buffer);
+                return;
+            }
+        }
+
+        // The buffer was too small, try again with a heap-allocated buffer instead, but still limit length
+        length = std::min(length, 2048);
+        char* heapBuffer = new char[length + 1];
+        vsnprintf(heapBuffer, length + 1, format, args);
+        logRecords.offer(level, String(heapBuffer, length));
+        delete[] heapBuffer;
+    }
+
     static inline Level getLevel(char c) {
         switch (c) {
             case 'E':

main/kernel/Kernel.hpp

@@ -19,14 +19,15 @@
 #include <kernel/StateManager.hpp>
 #include <kernel/drivers/LedDriver.hpp>
 #include <kernel/drivers/MdnsDriver.hpp>
-#include <kernel/drivers/MqttDriver.hpp>
 #include <kernel/drivers/RtcDriver.hpp>
 #include <kernel/drivers/SwitchManager.hpp>
 #include <kernel/drivers/WiFiDriver.hpp>
+#include <kernel/mqtt/MqttDriver.hpp>
 
 using namespace std::chrono;
 using namespace std::chrono_literals;
 using namespace farmhub::kernel::drivers;
+using namespace farmhub::kernel::mqtt;
 
 namespace farmhub::kernel {
 

main/kernel/Log.hpp

@@ -9,12 +9,13 @@
 namespace farmhub::kernel {
 
 enum class Level {
-    None = ESP_LOG_NONE,
-    Error = ESP_LOG_ERROR,
-    Warning = ESP_LOG_WARN,
-    Info = ESP_LOG_INFO,
-    Debug = ESP_LOG_DEBUG,
-    Verbose = ESP_LOG_VERBOSE,
+    None = 0,
+    // Fatal = 1,
+    Error = 2,
+    Warning = 3,
+    Info = 4,
+    Debug = 5,
+    Verbose = 6,
 };
 
 #define FARMHUB_LOG(level, format, ...) \

main/kernel/drivers/RtcDriver.hpp

@@ -7,10 +7,11 @@
 #include "esp_netif_sntp.h"
 #include "esp_sntp.h"
 
+#include <kernel/Configuration.hpp>
 #include <kernel/State.hpp>
 #include <kernel/Task.hpp>
-
 #include <kernel/drivers/MdnsDriver.hpp>
+#include <kernel/drivers/WiFiDriver.hpp>
 
 using namespace std::chrono;
 using namespace std::chrono_literals;