Debugging per Logging und für ESPs mit WLAN

https://oer-informatik.de/esp_logging

tl/dr; (ca. 10 min Lesezeit): Bei einfachen Projekten ist das Logging über die serielle Verbindung ein Segen beim Debugging: über die USB-Verbindung können am seriellen Monitor der Arduino-IDE Werte ausgegeben werden. Was aber tun, wenn die serielle Verbindung nicht besteht? Wie kann ich Logging am ESP komfortabel und einfach umsetzen? Ein Vorschlag.

Wir bauen in fünf Stufen ein per WLAN erreichbares Logging zusammen:

• Stufe eins: den seriellen Monitor nutzen

• Stufe zwei: den seriellen Monitor nur im Debug-Modus nutzen

• Stufe drei: LogLevel einfügen

• Stufe vier: Ausgabe mit Zeit/Datum (über WLAN und Zeitserver)

• Stufe fünf: Log-Ausgabe auf Website des ESP

Für eilige gibt es bei einigen Stufen auch Links zu fertigem Beispielcode

Stufe eins: den seriellen Monitor nutzen.

Der serielle Monitor bietet die Möglichkeit, Variableninhalte während der Programmausführung auf dem Microcontroller an den Computer auszugeben. Hierzu muss mit Serial.begin() eine serielle Verbindung zum Computer aufgebaut werden (über die RX/TX-Pins, sprich: per USB). Mit Serial.print() können dann Werte oder Zeichenketten an den seriellen Monitor übermittelt werden. Im folgenden Code ist dies einfach der Inhalt einer Laufvariablen:

int i;

void setup(){
  Serial.begin(115200); // Activate debugging via serial monitor
}

void loop(){
  i++;
  Serial.print("Logging No. ");
  Serial.println(i);
  delay(1000);
}

Der serielle Monitor lässt sich in der Arduino IDE öffnen über Tools/Serial Monitor oder über die Tastenkombination Strg+Shift+M

Wichtig ist, dass die Baud-Rate, die in dem Serial.begin()-Befehl übergeben wurde auch im seriellen Monitor eingestellt ist (hier: 115200 baud):

Stufe zwei: den seriellen Monitor nur im Debug-Modus nutzen.

Wenn das Programm erstmal läuft soll dieser ganze Debugging-Code gar nicht mehr ausgeführt werden und den Seriellen Anschluss benutzen. Ich möchte ihn auf einfache Weise aktivieren und deaktivieren können.

Ein Weg dies relativ komfortabel zu tun ist eine Präprozessor-Direktive. Bevor der Compiler den Quelltext verarbeitet werden Präprozessor-Direktiven ausgeführt. Dahinter verbirgt sich eigentlich nur eine Suchen/Ersetzen Funktionalität:

• mit #define NAME WERT deklariere ich ein Marko, eine Art Platzhalter. Dieser Platzhalter besagt: Wenn im folgenden Quellcode irgendwo NAME steht, dann ersetze das durch WERT. Es werden nur ganze Wörter ersetzt und nur ausserhalb der Präprozessor Direktiven.

• mit #ifdef NAME Codezeilen1 else Codezeilen2 endif überprüfe ich, ob ein Makro namens NAME existiert. Wurde dieses Makro deklariert, dann bleiben die Codezeilen1 im compilierten Code enthalten sind. Ist es nicht deklariert worden (oder wurde die Deklaration auskommentiert), dann bleibt nur Codezeilen2 vorhanden.

Wir nutzen beide Funktionalitäten kombiniert:

Für den Fall, dass DEBUG deklariert wurde, wird aus jedem DEBUG_PRINT(x) ein Serial.print(x) (also eine Debug-Ausgabe auf dem seriellen Monitor).

Für den Fall, dass DEBUG nicht deklariert wurde, wird jedes DEBUG_PRINT(x) ersetzt durch `` (nichts).

Wenn jetzt im Quelltext für Debugging anstelle des Funktionsaufrufs (Serial.print(x)) immer DEBUG_PRINT(x) angegeben wird, dann kann mit Hilfe #define DEBUG debugging aktiviert, mit einem auskommentierten //#define DEBUG deaktiviert werden. Es muss nur noch der Code für Serial.begin(115200) ebenso in die #ifdef DEBUG Bereiche eingefasst werden. Im Ganzen sieht das beispielhaft so aus:

//-------------------------------------------------------------------------------------
// Logging to serial console?
// If following line is commentet ("//#define DEBUG") all logging-operations will be
// replaced by "", otherwise if "#define DEBUG" is present logging will be sent to serial
//-------------------------------------------------------------------------------------

#define DEBUG  //Flag to activate logging to serial console (i.e. serial monitor in arduino ide)

#ifdef DEBUG
#define DEBUG_PRINT(x) Serial.print(x)
#define DEBUG_PRINTLN(x) Serial.println(x)
#else
#define DEBUG_PRINT(x)
#define DEBUG_PRINTLN(x)
#endif

int i; // iterating numbers in example sketch... can be deleted...

void setup(){
  #ifdef DEBUG
   Serial.begin(115200); // Activate debugging via serial monitor
   #endif
}

void loop(){
  i++;
  DEBUG_PRINT("Logging No. ");
  DEBUG_PRINTLN(i);
  delay(1000);
}

Der compilierte Code enthält diesen ganzen Hokuspokus nicht mehr. Die Präprozessor-Direktiven entfernen einfach unnötige Passagen aus dem Code. (Interesse geweckt? Hier und hier finden sich weitere Infos dazu.)

Stufe drei: LogLevel einfügen

Wer’s eilig hat: der fertige Code ist hier.

Bei größeren Projekten will man häufig genauer aufschlüsseln, welche Informationen ausgegeben werden sollen. Sowohl beim Lesen als auch bereits beim Logging kann man also filtern, ab welcher Wichtigkeit man Informationen erhalten will

Die Nummerierung ist angelehnt an die LogLevel des Linux Kernel (im .Net-Kontext wird häufig eine umgekehrte Nummerierung gewählt). Höhere Stufen beinhalten immer auch die Infos der unteren Stufen (DEBUG enthält also z.B. auch INFO-Nachrichten).

Für den Quellcode heißt das: Es muss ein Array mit den LogLevel-Namen erstellt werden (und darüber die Nummern-Zuordnung umgesetzt sein). Zudem muss ein MIN_LOG_LEVEL für die momentane Ausführung festgelegt werden. Als Default-Einstellung wähle ich immer INFO, das nur wesentliche Nachrichten des regulären Betriebs ausgeben sollte. In diesem Beispiel steht es aus Anschauungszwecken auf DEBUG.

//-------------------------------------------------------------------------------------
// LogLevels used in this example. Only entries bigger than LOG_LEVEL will be written
//-------------------------------------------------------------------------------------

String LOG_LEVEL_NAMES[] = {"OFF", "FATAL", "ERROR", "WARN", "INFO", "DEBUG", "TRACE", "ALL"};
const int MIN_LOG_LEVEL = 5;

Das Logging selbst übernimmt eine neue Funktion, die den LogLevel jeder Nachricht voranstellt (und wieder über die Präprozessor-Direktiven deaktiviert wird):

void debugOutput(String text, int logLevel) {
  if (MIN_LOG_LEVEL >= logLevel) {
    DEBUG_PRINTLN("["+LOG_LEVEL_NAMES[logLevel]+ "] " + text);
  }
}

Der Log-Aufruf selbst erfolgt jetzt über die neue Funktion, wobei als letztes Argument das LogLevel der jeweiligen Nachricht übergeben wird:

void loop(){
  i++;
  debugOutput("Logging No. "+String(i), 4);
  delay(1000);
}

Stufe vier: Ausgabe mit Zeit/Datum (über WLAN und Zeitserver)

Wer’s eilig hat: der fertige Code ist hier.

Für die folgenden Schritte ist eine stabile WiFi-Verbindung (Tutorial) Voraussetzung. Die einzelnen Codeblöcke, die ergänzt werden müssen stelle ich kurz Schritt für Schritt vor:

Stufe 4a: WiFi…

Die relevanten Imports (Abschnitt 1; der Code ist etwas komplizierter, weil für ESP32 und ESP8266 gleichermaßen gültig):

//-------------------------------------------------------------------------------------
// Load WiFi-Libraries depending on Hardware (ESP32/ESP8266) using preprocessor directives
//-------------------------------------------------------------------------------------

#if defined(ESP8266)
#pragma message "Compiling Libraries for ESP8266-based boards"
#include <ESP8266WiFiMulti.h> // aktivieren für ESP8266
ESP8266WiFiMulti wifiMulti;
#elif defined(ESP32)
#pragma message "Compiling Libraries for ESP32-based boards"
#include <WiFi.h>
#include <WiFiMulti.h>
WiFiMulti wifiMulti;
#else
#error "Nor ESP32 or ESP8266 recognized - you have to choose the libraries manually"
#endif

Es müssen die Zugangsdaten geladen werden. Ich lese diese aus einer externen Datei ein, die nicht im Versionscontrollsystem erfasst wird:

//-------------------------------------------------------------------------------------
// All Credentials are stored in file secrets.h (must be created using secrets_EXAMPLE.h)
// => add line "*secrets.h" to .gitignore to prevent publishing credentials to repository
//-------------------------------------------------------------------------------------

#include "secrets.h"             // Passwords saved in this file to be hidden from versioncontrol and sharing


//-------------------------------------------------------------------------------------
// WiFi-Settings (if not defined in secrets.h replace your SSID/PW here)
//-------------------------------------------------------------------------------------

const char*    WIFI_SSID             = SECRET_WIFI_SSID;     // Wifi network name (SSID)
const char*    WIFI_PASSWORD         = SECRET_WIFI_PASSWORD; // Wifi network password

const uint32_t CONNECTION_TIMEOUT_MS = 10000;               // WiFi connect timeout per AP.
const uint32_t MAX_CONNECTION_RETRY  = 20;                  // Reboot ESP after __ times connection errors

Eine Datei secrets.h muss erstellt werden, die (möglichst) nicht in die Versionskontrolle aufgenommen wird. Sie könnte z.B. so aussehen´(natürlich individualisiert auf das eigene WLAN):

#pragma once  // Only run once, even if included multiple times

#define SECRET_WIFI_SSID     "meinWLAN";         // Wifi network name (SSID)
#define SECRET_WIFI_PASSWORD "1234567890123456"; // Wifi network password

Die relevanten Einträge in die setup() (Abschnitt 3):

 void setup(){
   #ifdef DEBUG
   Serial.begin(115200); // Activate debugging via serial monitor
   #endif

   WiFi.mode(WIFI_STA);                       // Connectmode Station: as client on accesspoint
   wifiMulti.addAP(WIFI_SSID, WIFI_PASSWORD); // multpile networks possible
   ensureWIFIConnection();                    // Call connection-function for the first time
 }

In der loop() wird nur noch geprüft, ob eine WLAN-Verbindung besteht und diese ggf. erneuert:

void loop(){
  ensureWIFIConnection();                  // make sure, WiFi is still alive, reboot if necessary
}

Die neue Funktion stellt die WLAN-Verbindung sicher (und loggt direkt mit der neuen Funktion debugOutput()):

void ensureWIFIConnection() {
    if (WiFi.status() != WL_CONNECTED) {
       debugOutput("No WIFI Connection found. Re-establishing...", 3, true);
      int connectionRetry = 0;
      while ((wifiMulti.run(CONNECTION_TIMEOUT_MS) != WL_CONNECTED)) {
        delay(1000);
        connectionRetry++;
         debugOutput("WLAN Connection attempt number " + String(connectionRetry), 4, true);
        if (connectionRetry > MAX_CONNECTION_RETRY) {
           debugOutput("Connection Failed! Rebooting...", 4, true);
          delay(5000);
          ESP.restart();
        }
      }
      debugOutput("WiFi is connected", 4, true);
      debugOutput("IP address: " + (WiFi.localIP().toString()), 4, true);
      debugOutput("Connected to (SSID): " + String(WiFi.SSID()), 5, true);
      debugOutput("Signal strength (RSSI): " + String(WiFi.RSSI()) + "(-50 = perfect / -100 no signal)", 5, true);
    }
  }

Stufe 4b: Zeitserver

Für den Zeitserver müssen folgende Imports ergänzt und konfiguriert werden:

//-------------------------------------------------------------------------------------
// Configuration of the NTP-Server
//-------------------------------------------------------------------------------------

#include "time.h"
const char* NTP_SERVER = "pool.ntp.org";
const long GMT_OFFSET_SEC = 3600;
const int DAYLIGHT_OFFSET_SEC = 3600;

Am Ende der setup() (nachdem die WiFi-Verbindung mit ensureWIFIConnection(); erstellt wurde, wird der Zeitserver konfiguriert:

// Init and get the time
configTime(GMT_OFFSET_SEC, DAYLIGHT_OFFSET_SEC, NTP_SERVER);

Schließlich muss nur noch die Funktion debugOutput() um das formatierte Datum ergänzt werden (für den Fall, dass schon Kontakt zum Zeitserver besteht)

void debugOutput(String text, int logLevel) {
  if (LOG_LEVEL >= logLevel) {
    String timeAsString = "";    
    struct tm timeinfo;
    if (!getLocalTime(&timeinfo)) {
      timeAsString = "[no NTP]";
    }else{
      char timeAsChar[20];
      strftime(timeAsChar, 20, "%Y-%m-%d_%H:%M:%S", &timeinfo);
      timeAsString = String(timeAsChar);
    }
    DEBUG_PRINTLN("["+timeAsString + "] ["+LOG_LEVEL_NAMES[logLevel]+ "] " + text);
  }
}

Stufe fünf: Log-Ausgabe auf Website des ESP

Wer’s eilig hat: der fertige Code ist hier. Wir wollen jetzt auf einer Website die Log-Dateien zur Verfügung stellen - schließlich soll der ESP nicht dauerhaft per USB verbunden blieben.

Ein erster Schritt ist es, die nötigen Bibliotheken zu importieren und Variablen zu schaffen, in denen wir die Log-Infos zwischenspeichern können. Die Logs sollen für die Startphase (setup()) und das laufende Programm loop() getrennt gespeichert werden. Die 8085 ist der Port, unter der die Logs später erreichbar sein werden (Teil der URL).

//-------------------------------------------------------------------------------------
// Set Route and Port for the Logpage-Webserver
//-------------------------------------------------------------------------------------

#include <WebServer.h>
const int WEBSERVER_PORT = 8085;
const char* WEBSERVER_ROUTE_TO_DEBUG_OUTPUT = "/log";

WebServer server(WEBSERVER_PORT);
String setupLogText = "";
String loopLogText = "";

Am Ende der setup() muss nun der Server gestartet werden. Es wird festgelegt, auf welchem Pfad die Log-Dateien erreichbar sind (/log - ein weiterer Teil der URL) und welche Funktion die Ausgabe generiert, die dann an den Browser gesendet wird (respondRequestWithLogEntries(): diese Funktion folgt unten).

void setup(){
   ...
   debugOutput("Starting Webserver...", 6, true);
   server.on(WEBSERVER_ROUTE_TO_DEBUG_OUTPUT, respondRequestWithLogEntries);
   String log_address = "http://"+WiFi.localIP().toString() + ":" + String(WEBSERVER_PORT) + WEBSERVER_ROUTE_TO_DEBUG_OUTPUT;
   debugOutput("Logging will be published on: "+log_address , 6, true);
   server.begin();
   debugOutput("Finished startup.", 6, true);
 }

Bei jedem Aufruf der loop() wird zu Beginn geprüft, ob die Logfile-Internetseite aufgerufen wird. Sinnvollerweise erfolgt diese Abfrage zu Beginn direkt nach ensureWIFIConnection();.

void loop(){
  ensureWIFIConnection();
  server.handleClient();
  ...
}

Die beiden Variabeln für die Logtexte müssen noch befüllt werden. Da es zwei verschiedene sind (setup/loop) wird mit einer Flag unterschieden, wohin der jeweilige Logtext landen soll (setupLog):

void debugOutput(String text, int logLevel, bool setupLog) {
  if (MIN_LOG_LEVEL >= logLevel) {
    String timeAsString = "";    
    struct tm timeinfo;
    if (!getLocalTime(&timeinfo)) {
        timeAsString = "[no NTP]";
    }else{
      char timeAsChar[20];
      strftime(timeAsChar, 20, "%Y-%m-%d_%H:%M:%S", &timeinfo);
      timeAsString = String(timeAsChar);
    }
    if (setupLog) {
      setupLogText = setupLogText + "[" +  timeAsString + "] " + " ["+LOG_LEVEL_NAMES[logLevel]+ "] " + text + "<br/>\n";
    } else {
      loopLogText = loopLogText + "[" +  timeAsString + "] " + " ["+LOG_LEVEL_NAMES[logLevel]+ "] "+ text + "<br/>\n";
    }
    DEBUG_PRINTLN("["+timeAsString + "] ["+LOG_LEVEL_NAMES[logLevel]+ "] " + text);
  }
}

Zwei überladene Funktionen mit abweichenden Parametern sind eine Abkürzung, falls wir mal nicht Loglevel oder die neue Flag mitgeben wollen:

void debugOutput(String text, int logLevel) {
  debugOutput(text, logLevel, false); // log to loopLogText is default
}


void debugOutput(String text) {
  debugOutput(text, 4); // no loglevel present? use "INFO"
}

Schließlich benötigen wir noch die Funktion, die die Logdateien zurückgibt sowie eine Hilfsfunktion, die eine einfache HTML-Seite drumrum baut:

String renderHtml(String header, String body) {
  // HTML & CSS contents which display on web server
  String html = "";
  html = html + "<!DOCTYPE html>\n<html>\n"+"<html lang='de'>\n<head>\n<meta charset='utf-8'>\n<title>"+header+"</title>\n</head><body>\n<h1>";
  html = html + header + "</h1>\n";
  html = html + body + "\n</body>\n</html>\n";
  return html;
}

void respondRequestWithLogEntries() {
  String header = "Debugging-Log-Entries";
  String body = "";
  body = "<h2>Logging on Startup / during configuration (Setup-Log)</h2>\n";
  body = body + setupLogText;
  body = body + "<h2>Logging during operation (Loop-Log)</h2>\n";
  body = body + loopLogText;
  server.send(200, "text/html; charset=utf-8", renderHtml(header, body));
}

Wie sieht das ganze aus? Erstmal brauchen wir die IP-Adresse des ESP. Die finden wir z.B. im seriellen Monitor:

In meinem Fall steht da die 192.168.43.43. Zusammen mit den beiden URL-Bestandteilen, die wir oben konfiguriert hatten (Port: 8085 und Pfad: /log) ergibt sich daraus die URL, die wir im Browser eingeben können, um die Log-Datei anzuschauen.

http://192.168.43.43:8080/log

Wie weiter?

Natürlich muss man aufpassen: diese Seite ist für alle im lokalen WLAN ohne Passwort einsehbar. Es sollten daher keine Daten geloggt werden, die niemanden etwas angehen. Mittelfristig muss also noch ein Zugriffsschutz kommen.

Dazu aber an anderer Stelle mehr.

Quellen und offene Ressourcen (OER)

Die Ursprungstexte (als Markdown), Grafiken und zugrunde liegende Diagrammquelltexte finden sich (soweit möglich in weiterbearbeitbarer Form) in folgendem git-Repository:

https://gitlab.com/oer-informatik/mcu/arduino-esp.

Sofern nicht explizit anderweitig angegeben sind sie zur Nutzung als Open Education Resource (OER) unter Namensnennung (H. Stein, oer-informatik.de) freigegeben gemäß der Creative Commons Namensnennung 4.0 International Lizenz (CC BY 4.0).