14.3.1. Loggning

En levererad produkt kan inte rapportera tillbaka med print(). print() skriver till USB stdout, vilket bara finns när kameran står på en utvecklares arbetsbänk med en terminal öppen. Ute i fält läser ingenting det; varje rad slängs bort. Biblioteket logging är ersättningen – ett nivåfilter, ett mål som applikationen själv väljer, och ett format som talar om vad som hände och när.

Modulen logging på kameran är en bantad portning av CPythons – samma mentala modell, mindre yta, och ett fåtal skillnader som spelar roll vid produktionskonfiguration.

14.3.1.1. Den mentala modellen

Loggning är uppbyggd av fyra delar. Varje del har en uppgift; det är separationen som gör att en logger kan grena ut till flera mål, vart och ett med eget format och egen nivå:

  • En Logger är det applikationen anropar. Koden säger log.info("frame %d", n); loggern är objektet som det anropet landar på. Loggers slås upp med namn via logging.getLogger().

  • En Handler avgör vart en post går. En StreamHandler skriver till en ström (sys.stderr som standard); en FileHandler lägger till i en fil på disken. En logger kan ha hur många handlers som helst.

    Anteckning

    På kameran är sys.stdout och sys.stderr kopplade till samma USB CDC-rör – skrivningar till någondera dyker upp på samma terminal som en utvecklare har öppen över USB. En handler som skriver till sys.stderr är i praktiken en handler som skriver till samma ställe som print() skriver till. Handler-abstraktionen ger dig fortfarande filtrering och formatering per mål; den ger dig bara inte en fysiskt separat kanal.

  • En Formatter avgör hur en post renderas till text. Den tar en post och returnerar raden som skrivs. En formatsträng per formatter; en formatter per handler.

  • Ett nivåfilter sitter på varje logger och varje handler. Poster bär en nivå (DEBUG / INFO / WARNING / ERROR / CRITICAL). Endast poster på eller över filternivån släpps igenom.

Den separationen spelar roll eftersom en typisk produktionskonfiguration har mer än ett mål: en fil på SD-kortet som behåller allt ned till DEBUG för efterhandsanalys, och en ström till USB som bara visar WARNING och värre så att en utvecklare som är ansluten till kameran ser höjdpunkterna utan att drunkna i detaljer. Samma kod, två mål, två filter.

14.3.1.2. Nivåer och vad var och en betyder

De fem nivåerna är en ordnad skala. Poster bär en nivå så att filtret på varje handler kan slänga dem den inte bryr sig om.

  • DEBUG – spårning, räknare per bildruta, dumpar av internt tillstånd. Den lägsta nivån; volymen är hög.

  • INFO – normala driftshändelser. Wi-Fi anslutet, en modell laddad, watchdog-funktionen startad, en ny loggfil rotated in.

  • WARNING – något oväntat men applikationen hanterade det. En tappad bildruta, ett återförsökt nätverksanrop.

  • ERROR – en operation misslyckades och applikationen kunde inte slutföra den. En modellfil som saknas, en SD-kortsskrivning som nekades.

  • CRITICAL – applikationen kan inte fortsätta alls. Slut på minne, obligatorisk montering saknas.

En viktig standard att komma ihåg: kamerans logging-modul startar varje logger på WARNING. Poster på DEBUG och INFO slängs tyst om inte Logger.setLevel() anropas – vanligtvis som en del av anropet basicConfig() nedan. Ett vanligt första symptom på en loggningskonfiguration som ”inte fungerar” är att applikationen sände på INFO och standardfiltret åt upp posten.

Anteckning

Nivå är det enda filtret som kamerans logging erbjuder. Det finns inga Filter-objekt för rikare regler per post; om en posts nivå passerar sänds den.

14.3.1.3. basicConfig: snabbstarten

logging.basicConfig() konfigurerar rotloggern i ett enda anrop. Två former dyker upp oftast:

En utvecklingskonfiguration, allt till USB stderr på INFO

import logging

logging.basicConfig(level=logging.INFO)

En produktionskonfiguration, allt till en fil på SD-kortet med ett tidsstämplat format:

import logging

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

Skicka antingen filename= för en FileHandler eller stream= för en StreamHandler; de två utesluter varandra i basicConfig().

Formatsträngen är en mall i %(field)s-stil. Fälten som kamerans formatter stöder:

  • %(asctime)s – tidsstämpel formaterad från time.localtime(). Standardformatet är %Y-%m-%d %H:%M:%S; skicka datefmt= för att åsidosätta.

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

  • %(name)s – loggerns namn (se nästa avsnitt).

  • %(message)s – postens formaterade meddelande.

  • %(msecs)d – millisekundsdelen av postens tidsstämpel.

Standardformatet om inget anges är %(levelname)s:%(name)s:%(message)s – vilket är tillräckligt för utvecklingskonfigurationen men otillräckligt för en fältlogg, där tidsstämpeln är det som gör filen användbar veckor senare.

basicConfig() gör ingenting vid efterföljande anrop om inte force=True skickas. Konfigurera en gång vid uppstart; anropa den inte igen för att ”byta mål” mitt under körning.

Anteckning

Kamerans logging har ingen dictConfig() eller fileConfig(). Konfigurationen är alltid programmatisk – en setup_logging()-hjälpfunktion som anropas en gång från main.py är konventionen.

14.3.1.4. Namngivna loggers per modul

Applikationskod bör inte anropa genvägarna på modulnivå (logging.info(), logging.warning() och så vidare). De trattar alla genom rotloggern, och de resulterande loggposterna bär namnet root – värdelöst för att tala om var posten kom ifrån.

Konventionen är en logger per modul, namngiven efter modulen:

# in app/detector.py
import logging

log = logging.getLogger(__name__)

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

Varje post bär då app.detector i %(name)s och loggraden talar om vem som sände den.

Kamerans logging skiljer sig från CPython på ett viktigt sätt: loggernamnrymden är platt. getLogger('app') och getLogger('app.detector') är oberoende loggers utan förälder/barn-relation – att sätta en nivå på app propagerar inte till app.detector. Mekanismen som fungerar: en namngiven logger utan egna handlers lånar rotloggerns handlers och nivå. Det är så ett enda anrop till basicConfig() på roten sätter upp varje getLogger()-anrop på andra håll i applikationen.

14.3.1.5. Lat %-arg-formatering

Skriv:

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

Inte:

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

%-arg-formen låter loggern interpolera argumenten efter att nivåfiltret har beslutat om posten ska sändas. Ett bortfiltrerat DEBUG-anrop i en het slinga kostar ingenting för sin formatsträng. En f-sträng utvärderas först, varje gång, redan innan anropet ens når loggern.

CPythons nyckelord extra= för strukturerade fält stöds inte på kameran; skicka värdena som meddelandeargument istället.

14.3.1.6. Logga undantag

Inuti ett except-block loggar Logger.exception() meddelandet på ERROR-nivå och lägger till det aktuella undantagets traceback till posten:

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

Tracebacken fångas via sys.print_exception(), vilket är det som ger en undantagslogg dess flerradiga Traceback (most recent call last):-block. Detta är rätt verktyg för undantagshantering på toppnivå – fånga, logga och fortsätt.

14.3.1.7. Flera handlers

Produktionsuppdelningen som nämndes överst – allt till en fil på DEBUG, höjdpunkter till stderr på WARNING – är två handlers kopplade till samma logger, vardera med egen nivå och 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)

Rotloggerns nivå är det första filtret varje post träffar. Sätt den till den lägsta nivån som någon handler vill se – DEBUG här – så att ingen handler svälts av loggern själv. Nivåerna per handler avgör sedan vilka poster som faktiskt sänds till vilket mål.

14.3.1.8. Roterande loggfiler

Kamerans logging har inte RotatingFileHandler eller TimedRotatingFileHandler. Rotering är applikationens uppgift.

Mönstret är att hålla den aktuella FileHandler på en känd plats, byta ut den mot en ny när rolloverkriteriet utlöses, och låta en datumstämplad sökväg ge den naturliga filgränsen. För en rollover varje timme till /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

Anropa rotate_if_needed() en gång per iteration i huvudslingan; sökvägskontrollen är billig och bytet sker bara vid timgränsen. Katalogträdet måste finnas innan FileHandler kan öppna filen.

14.3.1.9. Tömning vid strömkänsliga driftsättningar

Skrivningar via FileHandler går genom det underliggande filobjektets Python-buffring. Ett strömavbrott mellan en skrivning och en tömning förlorar de avslutande posterna. För batteridrivna driftsättningar eller sådana där man drar ur kontakten, anropa flush() på handlerns ström efter kritiska poster, eller på en timer.

En liten hjälpfunktion som tömmer varje handler kopplad till rotloggern:

import logging

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

Anropa flush_handlers() direkt efter en post som applikationen inte har råd att förlora:

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

För säkerhet i bakgrunden, anropa den från huvudslingan med vilken takt som än balanserar loggfärskhet mot flashslitage – en gång i sekunden räcker oftast gott. Logger.critical() utlöser inte en tömning av sig själv.

14.3.1.10. Diagnostik vid uppstart

En fältlogg utan sammanhang är nästan värdelös. De första posterna vid varje kallstart bör identifiera vilken kamera, vilket bygge som körs och hur kameran kom till denna uppstart. Tre källor på enheten täcker tillsammans allt det:

  • omv – OpenMV-versionen av den fasta programvaran.

  • os.uname() – MicroPython-version, kortnamn + MCU, samt git-taggen och byggdatumet för källan som den fasta programvaran byggdes från.

  • machine – MCU:ns unika kisel-ID och återställningsorsaken som utlöste denna uppstart.

  • os.listdir() mot varje monteringspunkt – de filsystem som faktiskt kom upp.

En hjälpfunktion som drar in vart och ett av dessa i loggens första poster:

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)

En typisk logg öppnar med något i stil med:

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

Åtta rader in i varje loggfil känner operatören till den fysiska enheten, härstamningen för den fasta programvaran, varför kameran startade och vilket lagringsmedium som kom upp. unique id är MCU:ns fabriksprogrammerade kiselserienummer; det är detsamma över omflashningar och över SD-kortsbyten. build är git-taggen och datumet för det träd av fast programvara som avbildningen byggdes från – det enda fält som säger ”detta är exakt den binär som levererades till denna enhet vid denna tidpunkt.”

14.3.1.11. Att sätta ihop det

En komplett produktionskonfiguration för loggning, faktoriserad till en hjälpfunktion som main.py anropar en gång vid uppstart:

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)

Sedan högst upp i main.py

from app.logging_setup import setup_logging, log_boot_diagnostics

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

Varje modul på andra håll i applikationen gör bara:

import logging

log = logging.getLogger(__name__)

och får den konfigurerade utdatan gratis – fil med full detalj, ström med varningar, namngivna poster, tidsstämplad formatter och en dokumenterad uppstart vid varje kallstart.