14.3.1. Logging

Un prodotto distribuito non può comunicare con l’esterno tramite print(). print() scrive sullo stdout USB, che esiste solo quando la cam è sul banco di uno sviluppatore con un terminale aperto. Sul campo nessuno lo legge; ogni riga viene scartata. La libreria logging è la sostituzione – un filtro di livello, una destinazione a scelta dell’applicazione e un formato che dice cosa è successo e quando.

Il modulo logging sulla cam è un port ridotto di quello di CPython – stesso modello mentale, superficie più piccola, alcune differenze che contano per la configurazione in produzione.

14.3.1.1. Il modello mentale

Il logging è costruito a partire da quattro pezzi. Ogni pezzo ha un solo compito; è proprio questa separazione che permette a un singolo logger di diramarsi verso più destinazioni, ognuna con il proprio formato e livello:

  • Un Logger è ciò che l’applicazione richiama. Il codice scrive log.info("frame %d", n); il logger è l’oggetto su cui quella chiamata arriva. I logger vengono cercati per nome con logging.getLogger().

  • Un Handler decide dove va un record. Uno StreamHandler scrive su uno stream (sys.stderr per impostazione predefinita); un FileHandler accoda a un file su disco. Un logger può avere un numero qualsiasi di handler.

    Nota

    Sulla cam, sys.stdout e sys.stderr sono collegati alla stessa pipe USB CDC – le scritture su entrambi compaiono sullo stesso terminale che uno sviluppatore ha aperto tramite USB. Un handler che scrive su sys.stderr è, in pratica, un handler che scrive nello stesso posto in cui scrive print(). L’astrazione dell’handler ti offre comunque il filtraggio e la formattazione per destinazione; semplicemente non ti offre un canale fisicamente separato.

  • Un Formatter decide come un record viene reso in testo. Prende un record e restituisce la riga che viene scritta. Una stringa di formato per ciascun formatter; un formatter per ciascun handler.

  • Un filtro di livello è presente su ogni logger e su ogni handler. I record portano un livello (DEBUG / INFO / WARNING / ERROR / CRITICAL). Passano solo i record pari o superiori al livello del filtro.

Quella separazione conta perché una tipica configurazione di produzione ha più di una destinazione: un file sulla scheda SD che contiene tutto fino a DEBUG per l’analisi post-mortem, e uno stream verso USB che mostra solo WARNING e peggiori in modo che uno sviluppatore collegato alla cam veda i punti salienti senza affogare nei dettagli. Stesso codice, due destinazioni, due filtri.

14.3.1.2. I livelli e cosa significa ciascuno

I cinque livelli sono una scala ordinata. I record portano un livello in modo che il filtro su ciascun handler possa scartare quelli che non gli interessano.

  • DEBUG – tracciamento, contatori per frame, dump dello stato interno. Il livello più basso; il volume è elevato.

  • INFO – eventi operativi normali. Wi-Fi connesso, un modello caricato, il watchdog avviato, un nuovo file di log subentrato dopo una rotazione.

  • WARNING – qualcosa di inatteso ma che l’applicazione ha gestito. Un frame perso, una richiesta di rete ritentata.

  • ERROR – un’operazione è fallita e l’applicazione non è riuscita a completarla. Un file di modello mancante, una scrittura sulla scheda SD rifiutata.

  • CRITICAL – l’applicazione non può proseguire affatto. Memoria esaurita, mount obbligatorio mancante.

Un valore predefinito importante da ricordare: il modulo logging della cam avvia ogni logger a WARNING. I record a DEBUG e INFO vengono scartati silenziosamente a meno che non venga chiamato Logger.setLevel() – di solito come parte della chiamata a basicConfig() più sotto. Un primo sintomo comune di una configurazione di logging che «non funziona» è che l’applicazione ha emesso a INFO e il filtro predefinito ha mangiato il record.

Nota

Il livello è l’unico filtro che il logging della cam offre. Non ci sono oggetti Filter per regole più ricche per singolo record; se il livello di un record passa, viene emesso.

14.3.1.3. basicConfig: l’avvio rapido

logging.basicConfig() configura il root logger in una sola chiamata. Due forme compaiono più spesso:

Una configurazione di sviluppo, tutto verso lo stderr USB a INFO

import logging

logging.basicConfig(level=logging.INFO)

Una configurazione di produzione, tutto verso un file sulla scheda SD con un formato dotato di timestamp:

import logging

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

Passa filename= per un FileHandler oppure stream= per uno StreamHandler; i due si escludono a vicenda in basicConfig().

La stringa di formato è un template in stile %(field)s. I campi che il formatter della cam supporta:

  • %(asctime)s – timestamp formattato a partire da time.localtime(). Il formato predefinito è %Y-%m-%d %H:%M:%S; passa datefmt= per sovrascriverlo.

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

  • %(name)s – il nome del logger (vedi la sezione successiva).

  • %(message)s – il messaggio formattato del record.

  • %(msecs)d – la frazione in millisecondi del timestamp del record.

Il formato predefinito, se non ne viene fornito uno, è %(levelname)s:%(name)s:%(message)s – che va bene per la configurazione di sviluppo ed è inadeguato per un log sul campo, dove è il timestamp a rendere il file utile a distanza di settimane.

basicConfig() non fa nulla nelle chiamate successive a meno che non venga passato force=True. Configura una volta all’avvio; non chiamarla di nuovo per «cambiare destinazione» a metà esecuzione.

Nota

Il logging della cam non ha dictConfig() né fileConfig(). La configurazione è sempre programmatica – la convenzione è un singolo helper setup_logging() chiamato una volta da main.py.

14.3.1.4. Logger con nome per modulo

Il codice dell’applicazione non dovrebbe chiamare le scorciatoie a livello di modulo (logging.info(), logging.warning(), e così via). Quelle confluiscono tutte attraverso il root logger, e i record di log risultanti portano il nome root – inutile per capire da dove è arrivato il record.

La convenzione è un logger per modulo, denominato come il modulo:

# in app/detector.py
import logging

log = logging.getLogger(__name__)

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

Ogni record porta quindi app.detector in %(name)s e la riga di log dice chi l’ha emesso.

Il logging della cam differisce da CPython in un aspetto importante: lo spazio dei nomi dei logger è piatto. getLogger('app') e getLogger('app.detector') sono logger indipendenti senza alcuna relazione padre / figlio – impostare un livello su app non si propaga a app.detector. Il meccanismo che invece funziona: un logger con nome privo di handler propri prende in prestito gli handler e il livello del root logger. È così che una singola chiamata a basicConfig() su root configura ogni chiamata a getLogger() altrove nell’applicazione.

14.3.1.5. Formattazione lazy degli argomenti con %

Scrivi:

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

Non:

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

La forma con argomenti % consente al logger di interpolare gli argomenti dopo che il filtro di livello ha deciso se emettere il record. Una chiamata DEBUG filtrata in un ciclo critico non paga nulla per la sua stringa di formato. Una f-string viene valutata per prima, ogni volta, prima ancora che la chiamata raggiunga il logger.

La parola chiave extra= di CPython per i campi strutturati non è supportata sulla cam; passa invece i valori come argomenti del messaggio.

14.3.1.6. Logging delle eccezioni

All’interno di un blocco except, Logger.exception() registra il messaggio al livello ERROR e aggiunge al record il traceback dell’eccezione corrente:

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

Il traceback viene catturato tramite sys.print_exception(), che è ciò che dà a un log di eccezione il suo blocco multiriga Traceback (most recent call last):. Questo è lo strumento giusto per la gestione delle eccezioni di livello superiore – cattura, registra e prosegui.

14.3.1.7. Più handler

La suddivisione di produzione menzionata all’inizio – tutto verso un file a DEBUG, i punti salienti verso stderr a WARNING – consiste in due handler collegati allo stesso logger, ognuno con il proprio livello e 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)

Il livello del root logger è il primo filtro che ogni record incontra. Impostalo al livello più basso che qualsiasi handler voglia vedere – qui DEBUG – in modo che nessun handler venga privato dei record dal logger stesso. I livelli per singolo handler decidono poi quali record vengono effettivamente emessi verso quale destinazione.

14.3.1.8. Rotazione dei file di log

Il logging della cam non ha RotatingFileHandler né TimedRotatingFileHandler. La rotazione è compito dell’applicazione.

Il pattern consiste nel tenere il FileHandler corrente in un posto noto, sostituirlo con uno nuovo quando scatta il criterio di rollover, e lasciare che un percorso con data fornisca il confine naturale tra i file. Per un rollover orario in /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

Chiama rotate_if_needed() una volta per iterazione del ciclo principale; il controllo del percorso è poco costoso e lo scambio avviene solo al confine dell’ora. L’albero delle directory deve esistere prima che FileHandler possa aprire il file.

14.3.1.9. Flush nelle distribuzioni sensibili all’alimentazione

Le scritture di FileHandler passano attraverso il buffering Python dell’oggetto file sottostante. Una perdita di alimentazione tra una scrittura e un flush perde i record finali. Per distribuzioni alimentate a batteria o in cui si stacca la spina, chiama flush() sullo stream dell’handler dopo i record critici, oppure su un timer.

Un piccolo helper che esegue il flush di ogni handler collegato al root logger:

import logging

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

Chiama flush_handlers() subito dopo un record che l’applicazione non può permettersi di perdere:

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

Per sicurezza in background, chiamalo dal ciclo principale con la cadenza che bilancia la freschezza del log rispetto all’usura della flash – una volta al secondo è di solito più che sufficiente. Logger.critical() non attiva di per sé un flush.

14.3.1.10. Diagnostica all’avvio

Un log sul campo privo di contesto è pressoché inutile. I primi record a ogni avvio a freddo dovrebbero identificare quale cam, quale build è in esecuzione e come la cam è arrivata a questo avvio. Tre sorgenti sul dispositivo coprono insieme tutto questo:

  • omv – la versione del firmware OpenMV.

  • os.uname() – la versione di MicroPython, il nome della scheda + MCU, e il tag git e la data di build del sorgente da cui è stato compilato il firmware.

  • machine – l’ID univoco del silicio dell’MCU e la causa di reset che ha innescato questo avvio.

  • os.listdir() su ciascun punto di mount – i filesystem che si sono effettivamente attivati.

Un helper che inserisce tutte queste informazioni nei primi record del log:

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)

Un tipico log si apre con qualcosa come:

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

Otto righe dopo l’inizio di ogni file di log, l’operatore conosce l’unità fisica, la discendenza del firmware, perché la cam si è avviata e quale storage si è attivato. unique id è il numero di serie del silicio programmato in fabbrica nell’MCU; è lo stesso tra una riprogrammazione e l’altra e tra uno scambio di scheda SD e l’altro. build è il tag git e la data dell’albero del firmware da cui è stata compilata l’immagine – l’unico campo che dice «questo è esattamente il binario distribuito a questa unità in questo preciso momento.»

14.3.1.11. Mettere tutto insieme

Una configurazione completa di logging per la produzione, fattorizzata in un helper che main.py chiama una volta all’avvio:

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)

Poi all’inizio di main.py

from app.logging_setup import setup_logging, log_boot_diagnostics

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

Ogni altro modulo nell’applicazione fa semplicemente:

import logging

log = logging.getLogger(__name__)

e ottiene gratuitamente l’output configurato – file con dettaglio completo, stream con i warning, record con nome, formatter con timestamp e un avvio documentato a ogni accensione a freddo.