14.3.1. Logování

Hotový produkt se nemůže hlásit domů pomocí print(). print() zapisuje na USB stdout, který existuje pouze tehdy, když kamera leží na stole vývojáře s otevřeným terminálem. V terénu jej nikdo nečte; každý řádek skončí nepovšimnut. Náhradou je knihovna logging – filtr úrovní, cíl podle volby aplikace a formát, který říká, co se stalo a kdy.

Modul logging na kameře je odlehčený port z CPythonu – stejný mentální model, menší rozsah a několik rozdílů, které mají pro produkční nastavení význam.

14.3.1.1. Mentální model

Logování se skládá ze čtyř částí. Každá část má jeden úkol; právě toto oddělení umožňuje, aby jeden logger rozváděl výstup do více cílů, každý s vlastním formátem a úrovní:

  • Logger je to, co aplikace volá. Kód říká log.info("frame %d", n); logger je objekt, na kterém toto volání skončí. Loggery se vyhledávají podle názvu pomocí logging.getLogger().

  • Handler rozhoduje, kam záznam putuje. StreamHandler zapisuje do streamu (ve výchozím stavu sys.stderr); FileHandler připojuje záznamy do souboru na disku. Logger může mít libovolný počet handlerů.

    Poznámka

    Na kameře jsou sys.stdout a sys.stderr zapojeny do téže USB CDC roury – zápisy do kteréhokoli z nich se objeví ve stejném terminálu, který má vývojář otevřený přes USB. Handler, který zapisuje do sys.stderr, je v praxi handler, který zapisuje na stejné místo jako print(). Abstrakce handleru vám přesto poskytuje filtrování a formátování pro každý cíl zvlášť; jen vám nedává fyzicky oddělený kanál.

  • Formatter rozhoduje, jak se záznam vykreslí do textu. Vezme záznam a vrátí řádek, který se zapíše. Jeden formátovací řetězec na formatter; jeden formatter na handler.

  • Filtr úrovní sedí na každém loggeru a každém handleru. Záznamy nesou úroveň (DEBUG / INFO / WARNING / ERROR / CRITICAL). Projdou pouze záznamy na úrovni filtru nebo vyšší.

Toto oddělení má význam, protože typické produkční nastavení má více než jeden cíl: soubor na SD kartě, který uchovává vše až po DEBUG pro pozdější analýzu, a stream na USB, který vynáší na povrch jen WARNING a horší, aby vývojář připojený ke kameře viděl ty nejdůležitější věci, aniž by se utopil v detailech. Stejný kód, dva cíle, dva filtry.

14.3.1.2. Úrovně a co každá z nich znamená

Pět úrovní tvoří uspořádanou škálu. Záznamy nesou úroveň, aby filtr na každém handleru mohl zahodit ty, o které se nestará.

  • DEBUG – trasování, čítače na snímek, výpisy vnitřního stavu. Nejnižší úroveň; objem je vysoký.

  • INFO – běžné provozní události. Wi-Fi připojena, načten model, spuštěn watchdog, založen nový log soubor po rotaci.

  • WARNING – něco neočekávaného, ale aplikace to zvládla. Zahozený snímek, opakovaný síťový požadavek.

  • ERROR – operace selhala a aplikace ji nedokázala dokončit. Chybějící soubor s modelem, odmítnutý zápis na SD kartu.

  • CRITICAL – aplikace vůbec nemůže pokračovat. Došla paměť, chybí povinné připojení.

Jeden důležitý výchozí stav, který je třeba si zapamatovat: modul logging na kameře spouští každý logger na úrovni WARNING. Záznamy na úrovni DEBUG a INFO jsou tiše zahazovány, dokud není zavolána Logger.setLevel() – obvykle jako součást volání basicConfig() níže. Častým prvním příznakem nastavení logování, které „nefunguje“, je to, že aplikace odeslala záznam na úrovni INFO a výchozí filtr jej spolkl.

Poznámka

Úroveň je jediný filtr, který logging na kameře nabízí. Neexistují žádné objekty Filter pro bohatší pravidla na úrovni jednotlivých záznamů; pokud úroveň záznamu projde, je vydán.

14.3.1.3. basicConfig: rychlý start

logging.basicConfig() nakonfiguruje kořenový logger jediným voláním. Nejčastěji se objevují dvě podoby:

Vývojové nastavení, vše na USB stderr na úrovni INFO

import logging

logging.basicConfig(level=logging.INFO)

Produkční nastavení, vše do souboru na SD kartě s formátem opatřeným časovým razítkem:

import logging

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

Předejte buď filename= pro FileHandler, nebo stream= pro StreamHandler; tyto dvě možnosti se v basicConfig() vzájemně vylučují.

Formátovací řetězec je šablona ve stylu %(field)s. Pole, která formatter na kameře podporuje:

  • %(asctime)s – časové razítko zformátované z time.localtime(). Výchozí formát je %Y-%m-%d %H:%M:%S; pro přepsání předejte datefmt=.

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

  • %(name)s – název loggeru (viz následující oddíl).

  • %(message)s – zformátovaná zpráva záznamu.

  • %(msecs)d – milisekundová část časového razítka záznamu.

Výchozí formát, pokud není žádný zadán, je %(levelname)s:%(name)s:%(message)s – což je v pořádku pro vývojové nastavení a nedostatečné pro terénní log, kde je to právě časové razítko, co dělá soubor užitečným i o týdny později.

basicConfig() při dalších voláních nedělá nic, pokud není předáno force=True. Nakonfigurujte jednou při startu; nevolejte ji znovu kvůli „přepnutí cílů“ během běhu.

Poznámka

logging na kameře nemá dictConfig() ani fileConfig(). Konfigurace je vždy programová – konvencí je jeden pomocník setup_logging() volaný jednou z main.py.

14.3.1.4. Pojmenované loggery pro každý modul

Kód aplikace by neměl volat zkratky na úrovni modulu (logging.info(), logging.warning() a tak dále). Ty všechny ústí přes kořenový logger a výsledné log záznamy nesou název root – k ničemu, když chcete zjistit, odkud záznam pochází.

Konvencí je jeden logger na modul, pojmenovaný podle modulu:

# in app/detector.py
import logging

log = logging.getLogger(__name__)

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

Každý záznam pak nese app.detector v %(name)s a log řádek říká, kdo jej vydal.

logging na kameře se od CPythonu liší v jednom důležitém ohledu: jmenný prostor loggerů je plochý. getLogger('app') a getLogger('app.detector') jsou nezávislé loggery bez vztahu rodič / potomek – nastavení úrovně na app se nepropaguje na app.detector. Mechanismus, který funguje: pojmenovaný logger bez vlastních handlerů si vypůjčí handlery a úroveň kořenového loggeru. Tak jediné volání basicConfig() na kořenovém loggeru nastaví každé volání getLogger() jinde v aplikaci.

14.3.1.5. Líné formátování argumentů přes %

Pište:

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

Ne:

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

Forma s argumenty přes % umožňuje loggeru interpolovat argumenty až poté, co filtr úrovní rozhodne, zda záznam vydat. Odfiltrované volání DEBUG v horké smyčce nestojí za svůj formátovací řetězec nic. F-string se vyhodnocuje jako první, pokaždé, ještě než se volání vůbec dostane k loggeru.

Klíčové slovo CPythonu extra= pro strukturovaná pole není na kameře podporováno; předejte hodnoty místo toho jako argumenty zprávy.

14.3.1.6. Logování výjimek

Uvnitř bloku except Logger.exception() zaloguje zprávu na úrovni ERROR a zároveň připojí k záznamu traceback aktuální výjimky:

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

Traceback je zachycen prostřednictvím sys.print_exception(), což je to, co dává logu výjimky jeho víceřádkový blok Traceback (most recent call last):. Toto je správný nástroj pro zpracování výjimek na nejvyšší úrovni – zachytit, zalogovat a pokračovat dál.

14.3.1.7. Více handlerů

Produkční rozdělení zmíněné na začátku – vše do souboru na úrovni DEBUG, to nejdůležitější na stderr na úrovni WARNING – jsou dva handlery připojené ke stejnému loggeru, každý s vlastní úrovní a formatterem:

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)

Úroveň kořenového loggeru je první filtr, na který každý záznam narazí. Nastavte ji na nejnižší úroveň, kterou chce vidět kterýkoli handler – zde DEBUG – aby žádný handler nebyl ochuzen samotným loggerem. Úrovně jednotlivých handlerů pak rozhodnou, které záznamy se skutečně vydají do kterého cíle.

14.3.1.8. Rotace log souborů

logging na kameře nemá RotatingFileHandler ani TimedRotatingFileHandler. Rotace je úkolem aplikace.

Vzorem je udržovat aktuální FileHandler na známém místě, vyměnit jej za nový, když se spustí kritérium pro přepnutí, a nechat datovanou cestu poskytnout přirozené rozhraní mezi soubory. Pro hodinové přepínání do /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

Volejte rotate_if_needed() jednou za každou iteraci hlavní smyčky; kontrola cesty je levná a výměna proběhne pouze na hranici hodiny. Stromová struktura adresářů musí existovat dříve, než FileHandler může soubor otevřít.

14.3.1.9. Vyprazdňování bufferu u nasazení citlivých na výpadek napájení

Zápisy FileHandler procházejí přes Pythonovo bufferování podkladového souborového objektu. Výpadek napájení mezi zápisem a vyprázdněním bufferu ztratí poslední záznamy. U nasazení napájených z baterie nebo s rizikem vytržení napájení volejte flush() na streamu handleru po kritických záznamech, nebo na časovač.

Malý pomocník, který vyprázdní buffer každého handleru připojeného ke kořenovému loggeru:

import logging

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

Volejte flush_handlers() hned po záznamu, který si aplikace nemůže dovolit ztratit:

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

Pro bezpečnost na pozadí jej volejte z hlavní smyčky v takovém rytmu, který vyvažuje čerstvost logu proti opotřebení flash paměti – jednou za sekundu obvykle bohatě stačí. Logger.critical() sama o sobě vyprázdnění bufferu nespustí.

14.3.1.10. Diagnostika při startu

Terénní log bez kontextu je téměř k ničemu. První záznamy při každém studeném startu by měly identifikovat, která kamera to je, jaká verze běží a jak se kamera k tomuto startu dostala. Tři zdroje na zařízení dohromady pokrývají všechno:

  • omv – verze firmwaru OpenMV.

  • os.uname() – verze MicroPythonu, název desky + MCU a git tag a datum sestavení zdroje, ze kterého byl firmware sestaven.

  • machine – jedinečné křemíkové ID MCU a příčina resetu, která tento start spustila.

  • os.listdir() proti každému přípojnému bodu – souborové systémy, které skutečně naběhly.

Pomocník, který natáhne každý z těchto údajů do prvních záznamů logu:

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)

Typický log začíná zhruba takto:

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

Osm řádků na začátku každého log souboru, a operátor zná fyzický kus, původ firmwaru, proč se kamera nabootovala a které úložiště naběhlo. unique id je z výroby naprogramované křemíkové sériové číslo MCU; je stejné napříč přeflashováními i napříč výměnami SD karty. build je git tag a datum stromu firmwaru, ze kterého byl image sestaven – jediné pole, které říká „toto je přesně ten binární soubor, který byl dodán do tohoto kusu v tomto okamžiku“.

14.3.1.11. Poskládání dohromady

Kompletní produkční nastavení logování, vyčleněné do pomocníka, kterého main.py zavolá jednou při startu:

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)

Pak na začátku main.py

from app.logging_setup import setup_logging, log_boot_diagnostics

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

Každý další modul v aplikaci pak jen udělá:

import logging

log = logging.getLogger(__name__)

a zdarma získá nakonfigurovaný výstup – soubor s úplnými detaily, stream s varováními, pojmenované záznamy, formatter s časovými razítky a zdokumentovaný start při každém studeném startu.