14.3.1. Logging

Een product dat in productie is genomen kan niet naar huis bellen met print(). print() schrijft naar de USB-stdout, die alleen bestaat wanneer de cam op de werkbank van een ontwikkelaar staat met een open terminal. In het veld leest niemand het; elke regel valt op de grond. De logging-bibliotheek is de vervanging – een niveaufilter, een bestemming naar keuze van de applicatie, en een formaat dat zegt wat er gebeurde en wanneer.

De logging-module op de cam is een uitgeklede port van die van CPython – hetzelfde mentale model, een kleiner oppervlak, een paar verschillen die ertoe doen bij het opzetten voor productie.

14.3.1.1. Het mentale model

Logging is opgebouwd uit vier onderdelen. Elk onderdeel heeft één taak; die scheiding is wat het mogelijk maakt dat één logger uitwaaiert naar meerdere bestemmingen, elk met zijn eigen formaat en niveau:

• Een Logger is wat de applicatie aanroept. De code zegt log.info("frame %d", n); de logger is het object waarop die aanroep terechtkomt. Loggers worden op naam opgezocht met logging.getLogger().

• Een Handler bepaalt waar een record naartoe gaat. Een StreamHandler schrijft naar een stream (standaard sys.stderr); een FileHandler voegt toe aan een bestand op schijf. Een logger kan een willekeurig aantal handlers hebben.

  Notitie

  Op de cam zijn sys.stdout en sys.stderr aan dezelfde USB-CDC-pijp gekoppeld – schrijfacties naar beide verschijnen op dezelfde terminal die een ontwikkelaar open heeft staan via USB. Een handler die naar sys.stderr schrijft, is in de praktijk een handler die naar dezelfde plek schrijft als waar print() naartoe schrijft. De handler-abstractie geeft je nog steeds filtering en opmaak per bestemming; het geeft je alleen geen fysiek apart kanaal.

• Een Formatter bepaalt hoe een record als tekst wordt weergegeven. Hij neemt een record en geeft de regel terug die wordt weggeschreven. Eén formaatstring per formatter; één formatter per handler.

• Een niveaufilter zit op elke logger en elke handler. Records dragen een niveau (DEBUG / INFO / WARNING / ERROR / CRITICAL). Alleen records op of boven het filterniveau komen erdoor.

Die scheiding doet ertoe omdat een typische productie-opzet meer dan één bestemming heeft: een bestand op de SD-kaart dat alles tot en met DEBUG bewaart voor post-mortemanalyse, en een stream naar USB die alleen WARNING en erger laat zien zodat een ontwikkelaar die op de cam is aangesloten de hoogtepunten ziet zonder in details te verdrinken. Dezelfde code, twee bestemmingen, twee filters.

14.3.1.2. Niveaus en wat elk ervan betekent

De vijf niveaus vormen een geordende schaal. Records dragen een niveau zodat het filter op elke handler degene kan laten vallen waar het niet om geeft.

• DEBUG – tracering, tellers per frame, dumps van interne toestand. Het laagste niveau; het volume is hoog.

• INFO – normale operationele gebeurtenissen. Wi-Fi verbonden, een model geladen, de watchdog gestart, een nieuw logbestand ingerouleerd.

• WARNING – iets onverwachts, maar de applicatie heeft het afgehandeld. Een gedropt frame, een opnieuw geprobeerd netwerkverzoek.

• ERROR – een operatie is mislukt en de applicatie kon hem niet voltooien. Een ontbrekend modelbestand, een geweigerde schrijfactie naar de SD-kaart.

• CRITICAL – de applicatie kan helemaal niet verder. Geheugen op, verplichte mount ontbreekt.

Eén belangrijke standaardinstelling om te onthouden: de logging-module van de cam start elke logger op WARNING. Records op DEBUG en INFO worden stilzwijgend gedropt tenzij Logger.setLevel() wordt aangeroepen – meestal als onderdeel van de basicConfig()-aanroep hieronder. Een veelvoorkomend eerste symptoom van een logging-opzet die “niet werkt” is dat de applicatie op INFO uitzond en het standaardfilter het record opat.

Notitie

Niveau is het enige filter dat de logging van de cam biedt. Er zijn geen Filter-objecten voor rijkere regels per record; als het niveau van een record erdoor komt, wordt het uitgezonden.

14.3.1.3. basicConfig: de snelstart

logging.basicConfig() configureert de root-logger in één aanroep. Twee vormen komen het meest voor:

Een ontwikkelopzet, alles naar USB-stderr op INFO

import logging

logging.basicConfig(level=logging.INFO)

Een productie-opzet, alles naar een bestand op de SD-kaart met een formaat met tijdstempel:

import logging

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

Geef ofwel filename= op voor een FileHandler ofwel stream= voor een StreamHandler; de twee sluiten elkaar wederzijds uit in basicConfig().

De formaatstring is een sjabloon in %(field)s-stijl. De velden die de formatter van de cam ondersteunt:

• %(asctime)s – tijdstempel geformatteerd vanuit time.localtime(). Het standaardformaat is %Y-%m-%d %H:%M:%S; geef datefmt= op om dit te overschrijven.

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

• %(name)s – de naam van de logger (zie de volgende sectie).

• %(message)s – het geformatteerde bericht van het record.

• %(msecs)d – het milliseconde-deel van het tijdstempel van het record.

Het standaardformaat als er geen wordt opgegeven is %(levelname)s:%(name)s:%(message)s – wat prima is voor de ontwikkelopzet en ontoereikend voor een veldlog, waar het tijdstempel is wat het bestand weken later bruikbaar maakt.

basicConfig() doet niets bij volgende aanroepen tenzij force=True wordt meegegeven. Configureer één keer bij het opstarten; roep het niet nogmaals aan om halverwege een run “van bestemming te wisselen”.

Notitie

De logging van de cam heeft geen dictConfig() of fileConfig(). Configuratie gebeurt altijd programmatisch – één setup_logging()-helper die één keer wordt aangeroepen vanuit main.py is de conventie.

14.3.1.4. Benoemde loggers per module

Applicatiecode zou de snelkoppelingen op moduleniveau niet moeten aanroepen (logging.info(), logging.warning(), enzovoort). Die lopen allemaal door de root-logger, en de resulterende logrecords dragen de naam root – nutteloos om te bepalen waar het record vandaan kwam.

De conventie is één logger per module, vernoemd naar de module:

# in app/detector.py
import logging

log = logging.getLogger(__name__)

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

Elk record draagt dan app.detector in %(name)s en de logregel zegt wie het uitzond.

De logging van de cam verschilt op één belangrijk punt van CPython: de logger-naamruimte is vlak. getLogger('app') en getLogger('app.detector') zijn onafhankelijke loggers zonder ouder-/kindrelatie – het instellen van een niveau op app propageert niet naar app.detector. Het mechanisme dat wel werkt: een benoemde logger zonder eigen handlers leent de handlers en het niveau van de root-logger. Zo zorgt een enkele basicConfig()-aanroep op root voor elke getLogger()-aanroep elders in de applicatie.

14.3.1.5. Luie %-argumentopmaak

Schrijf:

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

Niet:

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

De %-argumentvorm laat de logger de argumenten interpoleren nadat het niveaufilter heeft besloten of het record wordt uitgezonden. Een uitgefilterde DEBUG-aanroep in een hete lus betaalt niets voor zijn formaatstring. Een f-string wordt eerst geëvalueerd, elke keer, voordat de aanroep de logger zelfs maar bereikt.

Het extra=-trefwoord van CPython voor gestructureerde velden wordt niet ondersteund op de cam; geef de waarden in plaats daarvan door als berichtargumenten.

14.3.1.6. Excepties loggen

Binnen een except-blok logt Logger.exception() het bericht op ERROR-niveau en voegt de traceback van de huidige exceptie toe aan het record:

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

De traceback wordt vastgelegd via sys.print_exception(), wat een exceptielog zijn meerregelige Traceback (most recent call last):-blok geeft. Dit is het juiste hulpmiddel voor afhandeling van excepties op het hoogste niveau – vangen, loggen en doorgaan.

14.3.1.7. Meerdere handlers

De productiesplitsing die bovenaan werd genoemd – alles naar een bestand op DEBUG, hoogtepunten naar stderr op WARNING – bestaat uit twee handlers die aan dezelfde logger zijn gekoppeld, elk met zijn eigen niveau en 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)

Het niveau van de root-logger is het eerste filter dat elk record raakt. Stel het in op het laagste niveau dat een handler wil zien – hier DEBUG – zodat geen enkele handler door de logger zelf wordt uitgehongerd. De niveaus per handler bepalen vervolgens welke records daadwerkelijk naar welke bestemming worden uitgezonden.

14.3.1.8. Logbestanden rouleren

De logging van de cam heeft geen RotatingFileHandler of TimedRotatingFileHandler. Rotatie is de taak van de applicatie.

Het patroon is om de huidige FileHandler op een bekende plek te houden, hem te verwisselen voor een nieuwe wanneer het rolleercriterium afgaat, en een gedateerd pad de natuurlijke bestandsgrens te laten leveren. Voor een uurlijkse rollering naar /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

Roep rotate_if_needed() één keer per iteratie van de hoofdlus aan; de padcontrole is goedkoop en de verwisseling gebeurt alleen op de uurgrens. De directorystructuur moet bestaan voordat FileHandler het bestand kan openen.

14.3.1.9. Doorspoelen bij stroomgevoelige implementaties

Schrijfacties van FileHandler gaan door de Python-buffering van het onderliggende bestandsobject. Een stroomuitval tussen een schrijfactie en een doorspoeling verliest de laatste records. Roep voor implementaties op batterij of waarbij de stekker eruit wordt getrokken flush() aan op de stream van de handler na kritieke records, of op een timer.

Een kleine helper die elke handler doorspoelt die aan de root-logger is gekoppeld:

import logging

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

Roep flush_handlers() aan direct na een record dat de applicatie zich niet kan veroorloven te verliezen:

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

Roep het voor veiligheid op de achtergrond aan vanuit de hoofdlus met welke frequentie ook de versheid van het log afweegt tegen slijtage van het flashgeheugen – één keer per seconde is meestal ruim voldoende. Logger.critical() veroorzaakt op zichzelf geen doorspoeling.

14.3.1.10. Diagnostiek bij het opstarten

Een veldlog zonder context is vrijwel nutteloos. De eerste records bij elke koude start zouden moeten identificeren welke cam het is, welke build draait en hoe de cam tot deze opstart is gekomen. Drie bronnen op het apparaat dekken dit samen allemaal:

• omv – de versie van de OpenMV-firmware.

• os.uname() – de MicroPython-versie, de bordnaam + MCU, en de git-tag en builddatum van de broncode waaruit de firmware is gebouwd.

• machine – de unieke silicon-ID van de MCU en de resetoorzaak die deze opstart heeft veroorzaakt.

• os.listdir() tegen elk mountpunt – de bestandssystemen die daadwerkelijk zijn opgestart.

Een helper die ieder van deze in de eerste records van het log haalt:

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)

Een typisch log opent met iets als:

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 regels diep in elk logbestand kent de operator de fysieke unit, de firmwarestamboom, waarom de cam is opgestart en welke opslag is opgekomen. unique id is het in de fabriek geprogrammeerde silicon-serienummer van de MCU; het is hetzelfde over herflashes heen en over SD-kaartwisselingen heen. build is de git-tag en datum van de firmwareboom waaruit de image is gebouwd – het enige veld dat zegt “dit is precies de binary die op dit punt in de tijd naar deze unit is verzonden.”

14.3.1.11. Alles samenvoegen

Een complete productie-logging-opzet, ondergebracht in een helper die main.py één keer bij het opstarten aanroept:

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)

Dan bovenaan in main.py

from app.logging_setup import setup_logging, log_boot_diagnostics

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

Elke module elders in de applicatie doet gewoon:

import logging

log = logging.getLogger(__name__)

en krijgt de geconfigureerde uitvoer gratis – bestand met volledige details, stream met waarschuwingen, benoemde records, formatter met tijdstempel, en een gedocumenteerde opstart bij elke koude start.