14.3.1. Logging

Ein ausgeliefertes Produkt kann sich nicht über print() melden. print() schreibt auf USB-stdout, das nur existiert, wenn die Kamera auf dem Tisch eines Entwicklers mit einem geöffneten Terminal liegt. Im Feld liest niemand mit; jede Zeile fällt einfach auf den Boden. Die logging-Bibliothek ist der Ersatz dafür – ein Level-Filter, ein vom Anwendungscode gewähltes Ziel und ein Format, das festhält, was wann passiert ist.

Das logging-Modul auf der Kamera ist eine abgespeckte Portierung von CPython – dasselbe mentale Modell, eine kleinere Oberfläche und ein paar Unterschiede, die für die Produktionseinrichtung von Bedeutung sind.

14.3.1.1. Das mentale Modell

Logging besteht aus vier Bausteinen. Jeder Baustein hat eine Aufgabe; erst diese Trennung erlaubt es einem Logger, an mehrere Ziele zu verteilen, jeweils mit eigenem Format und Level:

  • Ein Logger ist das, was der Anwendungscode aufruft. Der Code sagt log.info("frame %d", n); der Logger ist das Objekt, bei dem dieser Aufruf landet. Logger werden über ihren Namen mit logging.getLogger() nachgeschlagen.

  • Ein Handler entscheidet, wohin ein Datensatz geht. Ein StreamHandler schreibt in einen Stream (standardmäßig sys.stderr); ein FileHandler hängt an eine Datei auf dem Datenträger an. Ein Logger kann beliebig viele Handler haben.

    Bemerkung

    Auf der Kamera sind sys.stdout und sys.stderr mit derselben USB-CDC-Leitung verdrahtet – Schreibvorgänge auf beide erscheinen im selben Terminal, das ein Entwickler über USB geöffnet hat. Ein Handler, der nach sys.stderr schreibt, ist in der Praxis ein Handler, der an dieselbe Stelle schreibt wie print(). Die Handler-Abstraktion bietet dir weiterhin zielspezifisches Filtern und Formatieren; sie verschafft dir nur keinen physisch getrennten Kanal.

  • Ein Formatter entscheidet, wie ein Datensatz als Text dargestellt wird. Er nimmt einen Datensatz entgegen und liefert die Zeile zurück, die geschrieben wird. Ein Formatstring pro Formatter; ein Formatter pro Handler.

  • Ein Level-Filter sitzt auf jedem Logger und jedem Handler. Datensätze tragen ein Level (DEBUG / INFO / WARNING / ERROR / CRITICAL). Nur Datensätze auf oder über dem Filter-Level kommen durch.

Diese Trennung ist wichtig, weil eine typische Produktionseinrichtung mehr als ein Ziel hat: eine Datei auf der SD-Karte, die alles bis hinunter zu DEBUG für die Post-mortem-Analyse aufbewahrt, und einen Stream nach USB, der nur WARNING und Schlimmeres anzeigt, damit ein an die Kamera angeschlossener Entwickler die wichtigsten Punkte sieht, ohne in Details zu ertrinken. Derselbe Code, zwei Ziele, zwei Filter.

14.3.1.2. Level und was jedes einzelne bedeutet

Die fünf Level bilden eine geordnete Skala. Datensätze tragen ein Level, damit der Filter auf jedem Handler die ausblenden kann, die ihn nicht interessieren.

  • DEBUG – Ablaufverfolgung, Zähler pro Einzelbild, Dumps des internen Zustands. Das niedrigste Level; das Volumen ist hoch.

  • INFO – normale Betriebsereignisse. WLAN verbunden, ein Modell geladen, der Watchdog gestartet, eine neue Logdatei rotiert.

  • WARNING – etwas Unerwartetes, aber der Anwendungscode hat es bewältigt. Ein verworfenes Einzelbild, eine wiederholte Netzwerkanfrage.

  • ERROR – eine Operation ist fehlgeschlagen und der Anwendungscode konnte sie nicht abschließen. Eine fehlende Modelldatei, ein verweigerter Schreibvorgang auf die SD-Karte.

  • CRITICAL – der Anwendungscode kann überhaupt nicht weiterlaufen. Speicher erschöpft, ein zwingend erforderlicher Mountpunkt fehlt.

Eine wichtige Voreinstellung, die man sich merken sollte: Das logging-Modul der Kamera startet jeden Logger auf WARNING. Datensätze auf DEBUG und INFO werden stillschweigend verworfen, sofern nicht Logger.setLevel() aufgerufen wird – in der Regel als Teil des weiter unten gezeigten basicConfig()-Aufrufs. Ein häufiges erstes Symptom einer Logging-Einrichtung, die „nicht funktioniert“, ist, dass der Anwendungscode auf INFO ausgegeben hat und der Standardfilter den Datensatz geschluckt hat.

Bemerkung

Level ist der einzige Filter, den das logging der Kamera bietet. Es gibt keine Filter-Objekte für reichhaltigere Regeln pro Datensatz; wenn das Level eines Datensatzes durchkommt, wird er ausgegeben.

14.3.1.3. basicConfig: der Schnellstart

logging.basicConfig() konfiguriert den Root-Logger in einem einzigen Aufruf. Zwei Ausprägungen kommen am häufigsten vor:

Eine Entwicklungseinrichtung, alles auf USB-stderr mit INFO:

import logging

logging.basicConfig(level=logging.INFO)

Eine Produktionseinrichtung, alles in eine Datei auf der SD-Karte mit einem mit Zeitstempel versehenen Format:

import logging

logging.basicConfig(
    filename='/sdcard/logs/app.log',
    level=logging.INFO,
    format='%(asctime)s %(levelname)s %(name)s: %(message)s',
)

Übergib entweder filename= für einen FileHandler oder stream= für einen StreamHandler; die beiden schließen sich in basicConfig() gegenseitig aus.

Der Formatstring ist eine Vorlage im Stil von %(field)s. Die Felder, die der Formatter der Kamera unterstützt:

  • %(asctime)s – Zeitstempel, formatiert aus time.localtime(). Das Standardformat ist %Y-%m-%d %H:%M:%S; übergib datefmt=, um es zu überschreiben.

  • %(levelname)s – DEBUG / INFO / WARNING / ERROR / CRITICAL.

  • %(name)s – der Name des Loggers (siehe nächster Abschnitt).

  • %(message)s – die formatierte Nachricht des Datensatzes.

  • %(msecs)d – der Millisekundenanteil des Zeitstempels des Datensatzes.

Das Standardformat, wenn keines angegeben wird, ist %(levelname)s:%(name)s:%(message)s – was für die Entwicklungseinrichtung in Ordnung und für ein Feld-Log unzureichend ist, wo gerade der Zeitstempel die Datei Wochen später erst nützlich macht.

basicConfig() ist bei nachfolgenden Aufrufen wirkungslos, sofern nicht force=True übergeben wird. Konfiguriere einmal beim Start; rufe es nicht erneut auf, um mitten im Betrieb „die Ziele zu wechseln“.

Bemerkung

Das logging der Kamera hat kein dictConfig() und kein fileConfig(). Die Konfiguration erfolgt immer programmatisch – eine setup_logging()-Hilfsfunktion, die einmal aus main.py aufgerufen wird, ist die übliche Konvention.

14.3.1.4. Benannte Logger pro Modul

Anwendungscode sollte nicht die Abkürzungen auf Modulebene aufrufen (logging.info(), logging.warning() und so weiter). Diese leiten alle durch den Root-Logger, und die resultierenden Log-Datensätze tragen den Namen root – nutzlos, wenn es darum geht, festzustellen, woher der Datensatz kam.

Die Konvention lautet: ein Logger pro Modul, benannt nach dem Modul:

# in app/detector.py
import logging

log = logging.getLogger(__name__)

def detect(frame):
    log.info("detect on %dx%d frame", frame.width(), frame.height())

Jeder Datensatz trägt dann app.detector in %(name)s und die Logzeile sagt, wer ihn ausgegeben hat.

Das logging der Kamera unterscheidet sich in einem wichtigen Punkt von CPython: Der Logger-Namensraum ist flach. getLogger('app') und getLogger('app.detector') sind unabhängige Logger ohne Eltern-/Kind-Beziehung – das Setzen eines Levels auf app propagiert nicht zu app.detector. Der Mechanismus, der funktioniert: Ein benannter Logger ohne eigene Handler borgt sich die Handler und das Level des Root-Loggers. So richtet ein einziger basicConfig()-Aufruf auf dem Root jeden getLogger()-Aufruf an anderer Stelle im Anwendungscode mit ein.

14.3.1.5. Verzögerte %-Argument-Formatierung

Schreibe:

log.info("processed %d frames in %d ms", count, dt)

Nicht:

log.info(f"processed {count} frames in {dt} ms")

Die %-Argument-Form lässt den Logger die Argumente erst nachdem der Level-Filter entschieden hat, ob der Datensatz ausgegeben wird, interpolieren. Ein herausgefilterter DEBUG-Aufruf in einer heißen Schleife zahlt nichts für seinen Formatstring. Ein f-String wird dagegen jedes Mal zuerst ausgewertet, noch bevor der Aufruf den Logger überhaupt erreicht.

Das extra=-Schlüsselwort von CPython für strukturierte Felder wird auf der Kamera nicht unterstützt; übergib die Werte stattdessen als Nachrichtenargumente.

14.3.1.6. Ausnahmen protokollieren

Innerhalb eines except-Blocks protokolliert Logger.exception() die Nachricht auf dem Level ERROR und hängt den Traceback der aktuellen Ausnahme an den Datensatz an:

try:
    frame = csi0.snapshot()
    process(frame)
except Exception:
    log.exception("frame loop iteration failed")

Der Traceback wird über sys.print_exception() erfasst, was einem Ausnahme-Log seinen mehrzeiligen Traceback (most recent call last):-Block verleiht. Dies ist das richtige Werkzeug für die Ausnahmebehandlung auf oberster Ebene – abfangen, protokollieren und weitermachen.

14.3.1.7. Mehrere Handler

Die oben erwähnte Produktionsaufteilung – alles in eine Datei mit DEBUG, die wichtigsten Punkte nach stderr mit WARNING – besteht aus zwei Handlern, die an denselben Logger angehängt sind, jeder mit eigenem Level und eigenem Formatter:

import logging

fmt = '%(asctime)s %(levelname)s %(name)s: %(message)s'

file_handler = logging.FileHandler('/sdcard/logs/app.log')
file_handler.setLevel(logging.DEBUG)
file_handler.setFormatter(logging.Formatter(fmt))

stream_handler = logging.StreamHandler()
stream_handler.setLevel(logging.WARNING)
stream_handler.setFormatter(logging.Formatter(fmt))

root = logging.getLogger()
root.setLevel(logging.DEBUG)          # admit everything to the filters
root.addHandler(file_handler)
root.addHandler(stream_handler)

Das Level des Root-Loggers ist der erste Filter, auf den jeder Datensatz trifft. Setze es auf das niedrigste Level, das irgendein Handler sehen will – hier DEBUG –, damit kein Handler vom Logger selbst ausgehungert wird. Die handler-spezifischen Level entscheiden dann, welche Datensätze tatsächlich an welches Ziel ausgegeben werden.

14.3.1.8. Rotierende Logdateien

Das logging der Kamera hat keinen RotatingFileHandler und keinen TimedRotatingFileHandler. Die Rotation ist Aufgabe des Anwendungscodes.

Das Muster besteht darin, den aktuellen FileHandler an einer bekannten Stelle zu halten, ihn gegen einen neuen auszutauschen, wenn das Rollover-Kriterium ausgelöst wird, und einen mit Datum versehenen Pfad die natürliche Dateigrenze bilden zu lassen. Für ein stündliches Rollover nach /sdcard/logs/<year>/<month>/<day>/<hour>.log:

import logging
import time

_LOG_FMT = '%(asctime)s %(levelname)s %(name)s: %(message)s'
_current_path = None
_current_handler = None

def _hourly_path(now):
    return '/sdcard/logs/{:04d}/{:02d}/{:02d}/{:02d}.log'.format(
        now[0], now[1], now[2], now[3])

def rotate_if_needed():
    global _current_path, _current_handler

    path = _hourly_path(time.localtime())
    if path == _current_path:
        return

    root = logging.getLogger()
    if _current_handler is not None:
        root.removeHandler(_current_handler)
        _current_handler.close()

    _current_handler = logging.FileHandler(path)
    _current_handler.setFormatter(logging.Formatter(_LOG_FMT))
    root.addHandler(_current_handler)
    _current_path = path

Rufe rotate_if_needed() einmal pro Hauptschleifen-Durchlauf auf; die Pfadprüfung ist günstig und der Austausch findet nur an der Stundengrenze statt. Der Verzeichnisbaum muss existieren, bevor FileHandler die Datei öffnen kann.

14.3.1.9. Flushen bei stromempfindlichen Einsätzen

Schreibvorgänge von FileHandler laufen durch die Python-Pufferung des zugrunde liegenden Dateiobjekts. Ein Stromausfall zwischen einem Schreibvorgang und einem Flush verliert die letzten Datensätze. Rufe bei batteriebetriebenen oder Stecker-ziehen-Einsätzen nach kritischen Datensätzen flush() auf dem Stream des Handlers auf, oder zeitgesteuert.

Eine kleine Hilfsfunktion, die jeden an den Root-Logger angehängten Handler flusht:

import logging

def flush_handlers():
    for handler in logging.getLogger().handlers:
        if hasattr(handler, 'stream'):
            handler.stream.flush()

Rufe flush_handlers() direkt nach einem Datensatz auf, dessen Verlust sich der Anwendungscode nicht leisten kann:

log.critical("memory low: restarting")
flush_handlers()

Rufe es zur Hintergrundabsicherung aus der Hauptschleife in der Taktung auf, die die Aktualität des Logs gegen den Flash-Verschleiß abwägt – einmal pro Sekunde reicht in der Regel völlig. Logger.critical() löst von sich aus keinen Flush aus.

14.3.1.10. Diagnose beim Booten

Ein Feld-Log ohne Kontext ist nahezu nutzlos. Die ersten Datensätze bei jedem Kaltstart sollten festhalten, welche Kamera es ist, welcher Build läuft und wie die Kamera zu diesem Boot gelangt ist. Drei Quellen auf dem Gerät decken zusammen all das ab:

  • omv – die OpenMV-Firmware-Version.

  • os.uname() – MicroPython-Version, Board-Name + MCU sowie das Git-Tag und das Build-Datum der Quelle, aus der die Firmware erstellt wurde.

  • machine – die eindeutige Silizium-ID der MCU und die Reset-Ursache, die diesen Boot ausgelöst hat.

  • os.listdir() für jeden Mountpunkt – die Dateisysteme, die tatsächlich hochgekommen sind.

Eine Hilfsfunktion, die jede einzelne davon in die ersten Datensätze des Logs zieht:

import binascii
import logging
import machine
import omv
import os

log = logging.getLogger(__name__)

_RESET_NAMES = {
    machine.PWRON_RESET: "power-on",
    machine.HARD_RESET: "hard reset",
    machine.WDT_RESET: "watchdog timeout",
    machine.DEEPSLEEP_RESET: "wake from deep sleep",
    machine.SOFT_RESET: "soft reset",
}

def log_boot_diagnostics():
    uname = os.uname()

    log.info("machine: %s", uname.machine)
    log.info("unique id: %s",
             binascii.hexlify(machine.unique_id()).decode())
    log.info("firmware: openmv %s, micropython %s",
             omv.version_string(), uname.release)
    log.info("build: %s", uname.version)
    log.info("reset cause: %s",
             _RESET_NAMES.get(machine.reset_cause(), "unknown"))

    for mount in ('/flash', '/sdcard', '/rom'):
        try:
            os.listdir(mount)
            log.info("mount %s: ok", mount)
        except OSError as e:
            log.warning("mount %s: %s", mount, e)

Ein typisches Log beginnt mit etwas wie:

INFO machine: OPENMV4 with STM32H743
INFO unique id: 002C00543235501020373835
INFO firmware: openmv 5.0.0, micropython 1.28.0
INFO build: v1.28.0-101-gabc1234 on 2026-06-09
INFO reset cause: watchdog timeout
INFO mount /flash: ok
INFO mount /sdcard: ok
INFO mount /rom: ok

Acht Zeilen in jede Logdatei hinein kennt der Betreiber die physische Einheit, die Firmware-Abstammung, warum die Kamera gebootet hat und welcher Speicher hochgekommen ist. unique id ist die werkseitig programmierte Silizium-Seriennummer der MCU; sie bleibt über alle Neuflashs und alle SD-Karten-Wechsel hinweg gleich. build ist das Git-Tag und das Datum des Firmware-Baums, aus dem das Image erstellt wurde – das eine Feld, das sagt: „Dies ist genau das Binary, das zu diesem Zeitpunkt an diese Einheit ausgeliefert wurde.“

14.3.1.11. Alles zusammensetzen

Eine vollständige Produktions-Logging-Einrichtung, ausgelagert in eine Hilfsfunktion, die main.py einmal beim Start aufruft:

import logging

_LOG_FMT = '%(asctime)s %(levelname)s %(name)s: %(message)s'

def setup_logging(log_path):
    fh = logging.FileHandler(log_path)
    fh.setLevel(logging.DEBUG)
    fh.setFormatter(logging.Formatter(_LOG_FMT))

    sh = logging.StreamHandler()
    sh.setLevel(logging.WARNING)
    sh.setFormatter(logging.Formatter(_LOG_FMT))

    root = logging.getLogger()
    root.setLevel(logging.DEBUG)
    root.addHandler(fh)
    root.addHandler(sh)

Dann am Anfang von main.py:

from app.logging_setup import setup_logging, log_boot_diagnostics

setup_logging('/sdcard/logs/app.log')
log_boot_diagnostics()

Jedes andere Modul im Anwendungscode tut einfach:

import logging

log = logging.getLogger(__name__)

und erhält die konfigurierte Ausgabe gratis – Datei mit voller Detailtiefe, Stream mit Warnungen, benannte Datensätze, ein mit Zeitstempel versehener Formatter und ein dokumentierter Boot bei jedem Kaltstart.