UART-Logging mit Linux

Eine einfache aber blöde Problematik: Plasterouter stürzen ab und man kann nicht schnell hingehen.

In unseren Flüchtlingsunterkünften stehen Accesspoints mit Freifunk-Firmware herum, genauer gesagt handelt es sich um Xiaomi Mi Router 4A Gigabit Edition.

Gute Preis/Leistung, für um die 25 Euro (zumindest im Frühsommer 2022) bekommt man bei ffmuc zumindest theoretisch um die 90 Mbit/s durch. (Theoretisch, weil ich den Messwert hier via WLAN nicht bestätigen konnte).

Abgesehen von der etwas umständlichen Installation von zuerst OpenWrt (und dem etwas umständlichen jailbreak via OpenWRTInvasion, dem durchklickern durch ein chinesisches WebUI im Router und der Gefahr, dass man eine Version mit inkompatiblem SPI-Flash erwischt oder einer zu neuen Firmware erwischt oder sich das Teil beim Downgrade erst einmal brickt) und dann der Freifunk-Firmware, bei der dann erst einmal kein WiFi funktionierte und man die experimental-Version des images verwenden muss (Vielen Dank für die schnelle und tolle Unterstützung an die ffmuc-Community!) funktioniert das Teil recht gut, bis auf…

…tja, bis auf der Tatsache, dass die Plastikboxen ab und zu abschmieren. Mit crontab lässt sich ein Autoreboot in der Nacht einrichten, in anderen Situationen konnte ich mich über die anderen Knoten zu den teilabgeschmierten durchhangeln und rebooten. Manchmal – und dann natürlich vermehrt an den Standorten an denen sie hinter verschlossenen Türen stehen – knallen die Dinger aber so weg, dass man hinfahren und den Stecker ziehen muss. Noch blöder, wenn es beide machen.

Was macht man in diesem Fall? Natürlich herausfinden warum. Problem: Man kommt über Netzwerk nicht an die Konsole, weil tot. Also muss was externes ran.

Auf das Gehäuse und UART suchen – den es natürlich gibt. 4 Pins, beschriftet, fein:

Die Wege fürs Logging sind vielfältig, der Einfachheit halber wollte ich schon einen OpenLog bestellen – da muss man aber auch wieder fahren um die Daten zu holen und wenn’s dumm läuft ist etwas schief gegangen.

Auf der anderen Seite liegen mehr als genügend Raspberry Pis herum, die den Job übernehmen können.

Schritt 1 für sinnvolles Logging: Heartbeats. Auf dem Knoten kommt eine zusätzliche Zeile in crontab, die jede Minute die aktuelle Systemzeit ausgibt:

* * * * * echo "::Systime:: $(date)" > /dev/kmsg

Auf der Raspi-Seite ist es schon ein bisschen schwieriger – denke ich zumindest. Das Problem sollte eigentlich vorhanden und gelöst sein. Unter Windows kann das Putty super easy, aber es soll Linux und ohne Klickibunti sein. Ein Python-Script dafür zu schreiben ist mir zu blöd. Miniterm? Hm, scheint es nicht zu können. Nach längerer Suche stolpere ich (wieder) über screen – dem Schweizer Taschenmesser, wenn man zu blöd für services ist.

Und es hat auch hier eine Lösung parat, die man sich zusammenbasteln kann. Interaktiv wächst ein Befehl, der erst einmal überhaupt nicht funktioniert, bis die Erkenntnis kommt, dass zuerst die Parameter zur Konfiguration der Session und dann der Pfad zum TTY erfolgen muss. Mit der Zeit und nach einigen Tabs im Browser später ist folgender Kommandozeilenbefehl entstanden:

screen -S mimon -L -Logfile /home/pi/mimon/mimon_%Y.%m.%d_%c.log /dev/ttyUSB0 115200

Dieser startet eine Session namens mimon, aktiviert das Logging in die Logfile nur echt im py home directory mit aktuellem Datum und Uhrzeit für ttyUSB0 mit 115200 Baud.

Flutscht. Nur soll für jeden Tag eine neue Log entstehen. Bei dem Test inkl. Uhrzeit funktioniert das natürlich nicht, weil der String nur beim Start geparst wird.

Ein wenig Superuser-Browsing später ist die Erkenntnis erlangt, dass man die Session-Parameter auch zur Laufzeit ändern kann.

screen -XS mimon logfile /home/pi/mimon/mimon_%Y.%m.%d_%c.log

funktioniert auf der Konsole, als cronjob aber nicht. Zumindest nicht ganz – Datum und Uhrzeit fehlen. Eine Escaping-Runde später funktioniert auch das. Jetzt muss nur noch screen beim Reboot starten. der Befehl von oben – natürlich ebenfalls mit Escaping geht nicht, was vermutlich damit zusammenhängt, dass die Session direkt aufgeht und interaktiv wird. Wieder mit der Hilfe von Stackoverflow (wie entwickelt man heute eigentlich noch offline und wie hat man das früher geschafft?) landet folgende Zeile in crontab:

@reboot screen -dmS mimon -L -Logfile /home/pi/mimon/mimon_\%Y.\%m.\%d_\%c.log /dev/ttyUSB0 115200

…die natürlich wieder nicht funktioniert. Keine Typos, ohne das Escaping funktioniert interaktiv alles. Die erste Idee: Zeit. Keine Ahnung, wann im Bootprozess @reboot loslegt und für die Anwendung auch weniger relevant. Die Lösung: 30 Sekunden warten – das gibt dem System auch Gelegenheit, den NTP zu fragen, welche Stunde geschlagen hat.

Bereit für die finalen Crontab-Zeilen? Let’s go:

@reboot sleep 30 && screen -dmS mimon -L -Logfile /home/pi/mimon/mimon_\%Y.\%m.\%d_\%c.log /dev/ttyUSB0 115200
0 * * * * screen -XS mimon logfile /home/pi/mimon/mimon_\%Y.\%m.\%d_\%c.log

So wird jede Stunde eine neue Logdatei angelegt, wodurch man – auch dank des Graphana-Dashboards – die Crashes recht schnell eingrenzen können sollte.

Mal sehen, wann es wieder soweit ist und was die Logs sagen.

Allerdings könnte es sich erübrigt haben – da vor ein paar Tagen eine neue Firmware ausgerollt wurde.