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.