Merge pull request doudar#319 from doudar/websockets-no-async

Websockets no async

CHANGELOG.md

@@ -11,6 +11,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 - Added Additional logging to the custom characteristic.
 - Added option to enable/disable UDP logging. Default is disabled.
 - Added Wiki links to most SS2K pages. [see #314](https://github.com/doudar/SmartSpin2k/issues/314)
+- Added WebSockets for logging [see #173](https://github.com/doudar/SmartSpin2k/issues/173)
+- Reworked logging to run log-appender outside the worker task (task no longer blocked by logger traffic).
 
 ### Changed
 - Refactored ERG.
@@ -25,6 +27,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 - Disabled shifter ISR while ERG is running. 
 - Fixed possible infinite loop in ERG when stepper never reached target position due to being past min or max position.
 - When UDP logging is enabled, html will no longer request logging info. 
+- Increased remote server minimum packet delay to 325ms and max to 700ms. 
 
 ### Hardware
 - Added Ultra Short Case mod which should allow as little as ~40mm from knob center to head tube. 

data/status.html

@@ -111,12 +111,18 @@ <h2>
 </body>
 
 <script>
+ let updatePending = false;
+ let updateTimer = undefined;
+
+ // logging
+ let websocket = undefined;
+ let logEntries = [];
+ const maxLogentries = 1000;
 
- var debugElement = document.getElementById("debug");
- var followElement = document.getElementById("follow");
- var updatePending = false;
- var updateTimer = undefined;
- var udpLogEnabled = true;
+ document.addEventListener("visibilitychange", onVisibilityChanged, false);
+ document.addEventListener("mozvisibilitychange", onVisibilityChanged, false);
+ document.addEventListener("webkitvisibilitychange", onVisibilityChanged, false);
+ document.addEventListener("msvisibilitychange", onVisibilityChanged, false);
 
  function onVisibilityChanged() {
  if (document.hidden || document.mozHidden || document.webkitHidden || document.msHidden) {
@@ -126,17 +132,15 @@ <h2>
  }
  }
 
- document.addEventListener("visibilitychange", onVisibilityChanged, false);
- document.addEventListener("mozvisibilitychange", onVisibilityChanged, false);
- document.addEventListener("webkitvisibilitychange", onVisibilityChanged, false);
- document.addEventListener("msvisibilitychange", onVisibilityChanged, false);
-
  function startUpdate() {
  //Update values on specified interval loading late because this tiny webserver hates frequent requests
  if (updateTimer === undefined) {
  updateTimer = setInterval(function () {
  requestRuntimeValues();
- }, 1500);
+ if (websocket == null|| websocket?.readyState != 1 /*OPEN*/ ) {
+ setupLogging();
+ }
+ }, 2500);
  }
  }
 
@@ -145,12 +149,6 @@ <h2>
  updateTimer = undefined;
  }
 
- function updateDebugView(newContent) {
- if (followElement.checked) {
- debugElement.scrollTop = debugElement.scrollHeight - debugElement.clientHeight
- }
- }
-
  function requestConfigValues() {
  if (!updatePending) {
  updatePending = true
@@ -166,9 +164,6 @@ <h2>
  document.getElementById("inclineMultiplier").value = obj.inclineMultiplier;
  //--- document.getElementById("ERGSensitivity").value = obj.ERGSensitivity; ---//
  document.getElementById("connectedPowerMeter").value = obj.connectedPowerMeter;
- if (obj.udpLogEnabled) {
- udpLogEnabled = obj.udpLogEnabled.value;
- }
  }
  };
  xhttp.open("GET", "/configJSON", true);
@@ -190,20 +185,9 @@ <h2>
  document.getElementById("simulatedWatts").value = obj.simulatedWatts;
  document.getElementById("targetWatts").value = obj.targetWatts;
  document.getElementById("simulatedCad").value = obj.simulatedCad;
- if (obj.debug != null || !udpLogEnabled) {
- if (debugElement.innerHTML == "Loading" && !udpLogEnabled) {
- document.getElementById("debug").innerHTML = obj.debug;
- } else if (!udpLogEnabled) {
- document.getElementById("debug").innerHTML = "UDP logging is enabled in settings.<p>Please see the <a href='https://github.com/doudar/SmartSpin2k/wiki/Viewing-logs-via-UDP' style='color:white;'>SS2K Wiki</a><p>for more information.";
- }
- else {
- document.getElementById("debug").innerHTML += obj.debug;
- }
- updateDebugView(obj.debug);
- }
  }
  };
- xhttp.open("GET", !udpLogEnabled ? "/runtimeConfigJSON" : "/runtimeConfigJSON?includeDebugLog=true", true);
+ xhttp.open("GET", "/runtimeConfigJSON", true);
  xhttp.send();
  }
  }
@@ -221,9 +205,41 @@ <h2>
  window.addEventListener('load', function () {
  setTimeout(loadCss, 100);
  requestConfigValues();
- setTimeout(requestRuntimeValues(),200);
+ setupLogging();
+ setTimeout(requestRuntimeValues(), 200);
  startUpdate();
  }, false);
+
+ function setupLogging() {
+ var debugElement = document.getElementById("debug");
+ var followElement = document.getElementById("follow");
+ var wsAddress = `ws://${document.location.host}:8080`;
+ try {
+ websocket = new WebSocket(wsAddress);
+ websocket.onmessage = (evt) => {
+ if (evt?.data == null) {
+ return;
+ }
+
+ logEntries.push(event.data);
+ if (logEntries.length > maxLogentries) {
+ logEntries = logEntries.slice(1, logEntries.length - 10);
+ }
+
+ debugElement.innerHTML = logEntries.join("<br>");
+ if (followElement.checked) {
+ debugElement.scrollTop = debugElement.scrollHeight - debugElement.clientHeight
+ }
+ }
+ } catch (e) {
+ console.error("Could not connect to Websocket.", e);
+ if (websocket != null) {
+ websocket.close();
+ }
+ websocket = undefined;
+ }
+ }
+
 </script>
 
 </html>

include/LogAppender.h

@@ -0,0 +1,14 @@
+/*
+ * Copyright (C) 2020 Anthony Doud & Joel Baranick
+ * All rights reserved
+ *
+ * SPDX-License-Identifier: GPL-2.0-only
+ */
+
+#pragma once
+
+class ILogAppender {
+ public:
+ virtual void Initialize() = 0;
+ virtual void Log(const char* message) = 0;
+};

include/SS2KLog.h

@@ -15,12 +15,16 @@
 #include <stdarg.h>
 #include <FS.h>
 #include <freertos/semphr.h>
+#include <freertos/message_buffer.h>
+#include "LogAppender.h"
+#include <vector>
 
-#define SS2K_LOG_TAG  "SS2K"
-#define DEBUG_INFO_LOG_TAG "DebugInfo"
+#define SS2K_LOG_TAG "SS2K"
+#define LOG_HANDLER_TAG "Log_Handler"
 
 #ifndef DEBUG_LOG_BUFFER_SIZE
-#define DEBUG_LOG_BUFFER_SIZE 1500
+#define DEBUG_LOG_BUFFER_SIZE 0
+// #define DEBUG_LOG_BUFFER_SIZE 1500
 #endif
 
 #ifndef DEBUG_FILE_CHARS_PER_LINE
@@ -32,78 +36,57 @@
 #endif
 
 #if CORE_DEBUG_LEVEL >= 4
-#define SS2K_LOGD(tag, format, ...) SS2K_MODLOG_DFLT(ERROR, "D %lu %s: " #format "\n", millis(), tag, ##__VA_ARGS__)
+#define SS2K_LOGD(tag, format, ...) ss2k_log_write(ESP_LOG_DEBUG, tag, format, ##__VA_ARGS__);
 #else
 #define SS2K_LOGD(tag, format, ...) (void)tag
 #endif
 
 #if CORE_DEBUG_LEVEL >= 3
-#define SS2K_LOGI(tag, format, ...) SS2K_MODLOG_DFLT(ERROR, "I %lu %s: " #format "\n", millis(), tag, ##__VA_ARGS__)
+#define SS2K_LOGI(tag, format, ...) ss2k_log_write(ESP_LOG_INFO, tag, format, ##__VA_ARGS__);
 #else
 #define SS2K_LOGI(tag, format, ...) (void)tag
 #endif
 
 #if CORE_DEBUG_LEVEL >= 2
-#define SS2K_LOGW(tag, format, ...) SS2K_MODLOG_DFLT(ERROR, "W %lu %s: " #format "\n", millis(), tag, ##__VA_ARGS__)
+#define SS2K_LOGW(tag, format, ...) ss2k_log_write(ESP_LOG_WARN, tag, format, ##__VA_ARGS__);
 #else
 #define SS2K_LOGW(tag, format, ...) (void)tag
 #endif
 
 #if CORE_DEBUG_LEVEL >= 1
-#define SS2K_LOGE(tag, format, ...) SS2K_MODLOG_DFLT(ERROR, "E %lu %s: " #format "\n", millis(), tag, ##__VA_ARGS__)
+#define SS2K_LOGE(tag, format, ...) ss2k_log_write(ESP_LOG_ERROR, tag, format, ##__VA_ARGS__);
 
 #else
 #define SS2K_LOGE(tag, format, ...) (void)tag
 #endif
-#define SS2K_LOGC(tag, format, ...) SS2K_MODLOG_DFLT(CRITICAL, "C %lu %s: " #format "\n", millis(), tag, ##__VA_ARGS__)
-#define SS2K_LOG(tag, format, ...) SS2K_MODLOG_DFLT(CRITICAL, "N %lu %s: " #format "\n", millis(), tag, ##__VA_ARGS__)
+#define SS2K_LOG(tag, format, ...) ss2k_log_write(ESP_LOG_ERROR, tag, format, ##__VA_ARGS__);
 
-class DebugInfo {
+#define LOG_BUFFER_SIZE_BYTES 6000
+class LogHandler {
  public:
- static void append_logv(const char *format, va_list args);
-
- static const std::string get_and_clear_logs();
+ LogHandler();
+ void writev(esp_log_level_t level, const char *module, const char *format, va_list args);
+ void addAppender(ILogAppender *appender);
+ void initialize();
+ void writeLogs();
 
  private:
- static DebugInfo INSTANCE;
-#if DEBUG_LOG_BUFFER_SIZE > 0
- DebugInfo() : logBufferLength(0), logBufferMutex(xSemaphoreCreateMutex()) { logBuffer[0] = '\0'; }
- int logBufferLength;
- char logBuffer[DEBUG_LOG_BUFFER_SIZE];
- SemaphoreHandle_t logBufferMutex;
- void append_logv_internal(const char *format, va_list args);
- const std::string get_and_clear_logs_internal();
-#else
- DebugInfo() {}
-#endif
-};
-
-#define SS2K_MODLOG_ESP_LOCAL(level, ml_msg_, ...) \
- do { \
- if (LOG_LOCAL_LEVEL >= level) ss2k_log_write(level, ml_msg_, ##__VA_ARGS__); \
- } while (0)
-
-#define SS2K_MODLOG_DEBUG(ml_mod_, ml_msg_, ...) SS2K_MODLOG_ESP_LOCAL(ESP_LOG_DEBUG, ml_msg_, ##__VA_ARGS__)
+ static uint8_t _messageBuffer[];
+ StaticMessageBuffer_t _messageBufferStruct;
+ MessageBufferHandle_t _messageBufferHandle;
+ SemaphoreHandle_t _logBufferMutex;
+ std::vector<ILogAppender *> _appenders;
 
-#define SS2K_MODLOG_INFO(ml_mod_, ml_msg_, ...) SS2K_MODLOG_ESP_LOCAL(ESP_LOG_INFO, ml_msg_, ##__VA_ARGS__)
-
-#define SS2K_MODLOG_WARN(ml_mod_, ml_msg_, ...) SS2K_MODLOG_ESP_LOCAL(ESP_LOG_WARN, ml_msg_, ##__VA_ARGS__)
-
-#define SS2K_MODLOG_ERROR(ml_mod_, ml_msg_, ...) SS2K_MODLOG_ESP_LOCAL(ESP_LOG_ERROR, ml_msg_, ##__VA_ARGS__)
-
-#define SS2K_MODLOG_CRITICAL(ml_mod_, ml_msg_, ...) SS2K_MODLOG_ESP_LOCAL(ESP_LOG_ERROR, ml_msg_, ##__VA_ARGS__)
-
-#define SS2K_MODLOG(ml_lvl_, ml_mod_, ...) SS2K_MODLOG_##ml_lvl_((ml_mod_), __VA_ARGS__)
+ char _logLevelToLetter(esp_log_level_t level);
+};
 
-#define SS2K_MODLOG_DFLT(ml_lvl_, ...) SS2K_MODLOG(ml_lvl_, LOG_MODULE_DEFAULT, __VA_ARGS__);
+extern LogHandler logHandler;
 
 void ss2k_remove_newlines(std::string *str);
 
 int ss2k_log_hex_to_buffer(const byte *data, const size_t data_length, char *buffer, const int buffer_offset, const size_t buffer_length);
 
-void ss2k_log_write(esp_log_level_t level, const char *format, ...);
-
-void ss2k_log_writev(esp_log_level_t level, const char *format, va_list args);
+void ss2k_log_write(esp_log_level_t level, const char *module, const char *format, ...);
 
 #else
 

include/SmartSpin_parameters.h

@@ -90,7 +90,7 @@ class RuntimeParameters {
  void setMaxStep(int ms) { maxStep = ms; }
  int getMaxStep() { return maxStep; }
 
- String returnJSON(bool includeDebugLog = false);
+ String returnJSON();
 };
 
 class userParameters {
@@ -154,7 +154,7 @@ class userParameters {
  void setFoundDevices(String fdev) { foundDevices = fdev; }
  const char* getFoundDevices() { return foundDevices.c_str(); }
 
- String returnJSON(bool includeDebugLog = false);
+ String returnJSON();
  void saveToSPIFFS();
  void loadFromSPIFFS();
  void printFile();

include/UdpLogger.h → include/UdpAppender.h

@@ -9,16 +9,13 @@
 
 #include <WiFi.h>
 #include <WiFiUdp.h>
-
-#define UDP_LOGGER_TAG "UdpLogger"
-
-class UdpLogger {
+#include "LogAppender.h"
+class UdpAppender : public ILogAppender {
  public:
- static void log(const char *format, va_list args);
+ void Log(const char *message);
+ void Initialize();
 
  private:
- static UdpLogger INSTANCE;
  static const uint16_t port = 10000;
  WiFiUDP udp;
- void log_internal(const char *format, va_list args);
 };

include/WebsocketAppender.h

@@ -0,0 +1,27 @@
+/*
+ * Copyright (C) 2020 Anthony Doud & Joel Baranick
+ * All rights reserved
+ *
+ * SPDX-License-Identifier: GPL-2.0-only
+ */
+
+#pragma once
+
+#include <ArduinoWebsockets.h>
+#include "LogAppender.h"
+
+using namespace websockets;
+
+class WebSocketAppender : public ILogAppender {
+ public:
+ void Log(const char *message);
+ void Loop();
+
+ private:
+ static const uint16_t port = 8080;
+
+ void Initialize();
+
+ WebsocketsServer _webSocketsServer;
+ WebsocketsClient _client;
+};

platformio.ini

@@ -11,7 +11,7 @@
 default_envs = debug
 
 [esp32doit]
-lib_ldf_mode = chain+
+lib_ldf_mode = chain
 lib_compat_mode = strict
 platform = https://github.com/platformio/platform-espressif32.git#feature/arduino-upstream
 board = esp32doit-devkit-v1
@@ -31,6 +31,7 @@ lib_deps =
  bblanchon/ArduinoJson@^6.18.5
  https://github.com/witnessmenow/Universal-Arduino-Telegram-Bot.git#master
  https://github.com/gin66/FastAccelStepper/archive/refs/tags/0.24.0.zip
+ https://github.com/gilmaimon/ArduinoWebsockets/archive/refs/tags/0.5.3.zip
 
 [env:release]
 extends = esp32doit

src/BLE_Client.cpp

@@ -206,7 +206,7 @@ bool SpinBLEClient::connectToServer() {
  SS2K_LOG(BLE_CLIENT_LOG_TAG, " - Created client");
  pClient->setClientCallbacks(new MyClientCallback(), true);
  // Connect to the remove BLE Server.
- pClient->setConnectionParams(60, 200, 0, 1000);
+ pClient->setConnectionParams(240, 560, 1, 1000);
  /** Set how long we are willing to wait for the connection to complete (seconds), default is 30. */
  pClient->setConnectTimeout(5);
  pClient->connect(myDevice->getAddress()); // if you pass BLEAdvertisedDevice instead of address, it will be recognized type of peer device address (public or private)

src/BLE_Common.cpp

@@ -58,7 +58,7 @@ void BLECommunications(void *pvParameters) {
 
  const int kLogBufMaxLength = 250;
  char logBuf[kLogBufMaxLength];
- SS2K_LOGD(BLE_COMMON_LOG_TAG, "Data length: %d", data.length());
+ SS2K_LOGD(BLE_COMMON_LOG_TAG, "Data length: %d", length);
  int logBufLength = ss2k_log_hex_to_buffer(pData, length, logBuf, 0, kLogBufMaxLength);
 
  logBufLength += snprintf(logBuf + logBufLength, kLogBufMaxLength - logBufLength, "<- %.8s | %.8s", myAdvertisedDevice.serviceUUID.toString().c_str(),