14.3.1. Logowanie

Gotowy produkt nie może komunikować się ze światem za pomocą print(). print() zapisuje do standardowego wyjścia USB, które istnieje tylko wtedy, gdy kamera znajduje się na biurku programisty z otwartym terminalem. W terenie nikt tego nie odczytuje; każda linia trafia w próżnię. Zamiennikiem jest biblioteka logging – filtr poziomów, miejsce docelowe wybrane przez aplikację oraz format, który mówi, co się stało i kiedy.

Moduł logging w kamerze to odchudzony port wersji z CPython – ten sam model myślowy, mniejsza powierzchnia oraz kilka różnic istotnych przy konfiguracji produkcyjnej.

14.3.1.1. Model myślowy

Logowanie zbudowane jest z czterech elementów. Każdy z nich ma jedno zadanie; właśnie ten rozdział pozwala jednemu loggerowi rozesłać dane do wielu miejsc docelowych, z których każde ma własny format i poziom:

  • Logger to obiekt, który aplikacja wywołuje. Kod wykonuje log.info("frame %d", n); logger jest obiektem, na którym to wywołanie ląduje. Loggery wyszukuje się po nazwie za pomocą logging.getLogger().

  • Handler decyduje o tym, gdzie trafia rekord. StreamHandler zapisuje do strumienia (domyślnie sys.stderr); FileHandler dopisuje do pliku na dysku. Logger może mieć dowolną liczbę handlerów.

    Informacja

    W kamerze sys.stdout i sys.stderr są podłączone do tego samego potoku USB CDC – zapisy do dowolnego z nich pojawiają się w tym samym terminalu, który programista ma otwarty przez USB. Handler zapisujący do sys.stderr jest w praktyce handlerem zapisującym w to samo miejsce, w które zapisuje print(). Abstrakcja handlera nadal zapewnia filtrowanie i formatowanie per miejsce docelowe; po prostu nie daje fizycznie oddzielnego kanału.

  • Formatter decyduje o tym, jak rekord jest renderowany do tekstu. Pobiera rekord i zwraca linię, która zostanie zapisana. Jeden ciąg formatujący na formatter; jeden formatter na handler.

  • Filtr poziomu znajduje się na każdym loggerze i każdym handlerze. Rekordy niosą poziom (DEBUG / INFO / WARNING / ERROR / CRITICAL). Przepuszczane są tylko rekordy o poziomie równym lub wyższym niż poziom filtra.

Ten rozdział ma znaczenie, ponieważ typowa konfiguracja produkcyjna ma więcej niż jedno miejsce docelowe: plik na karcie SD, który przechowuje wszystko aż do poziomu DEBUG na potrzeby analizy powłamaniowej, oraz strumień do USB, który ujawnia tylko WARNING i poważniejsze, dzięki czemu programista podłączony do kamery widzi najważniejsze informacje, nie tonąc w szczegółach. Ten sam kod, dwa miejsca docelowe, dwa filtry.

14.3.1.2. Poziomy i znaczenie każdego z nich

Pięć poziomów stanowi uporządkowaną skalę. Rekordy niosą poziom, aby filtr na każdym handlerze mógł odrzucić te, którymi się nie interesuje.

  • DEBUG – śledzenie, liczniki per ramka, zrzuty stanu wewnętrznego. Najniższy poziom; objętość jest duża.

  • INFO – normalne zdarzenia operacyjne. Połączono z Wi-Fi, załadowano model, uruchomiono watchdoga, wprowadzono nowy plik dziennika podczas rotacji.

  • WARNING – coś nieoczekiwanego, ale aplikacja sobie z tym poradziła. Pominięta ramka, ponowiona próba żądania sieciowego.

  • ERROR – operacja zakończyła się niepowodzeniem i aplikacja nie mogła jej ukończyć. Brakujący plik modelu, odmowa zapisu na kartę SD.

  • CRITICAL – aplikacja w ogóle nie może kontynuować. Brak pamięci, brak obowiązkowego punktu montowania.

Jedno ważne ustawienie domyślne, o którym trzeba pamiętać: moduł logging kamery uruchamia każdy logger na poziomie WARNING. Rekordy na poziomach DEBUG i INFO są po cichu odrzucane, chyba że wywołano Logger.setLevel() – zwykle jako część poniższego wywołania basicConfig(). Częstym pierwszym objawem konfiguracji logowania, która „nie działa”, jest to, że aplikacja emitowała na poziomie INFO, a domyślny filtr pochłonął rekord.

Informacja

Poziom to jedyny filtr, jaki oferuje logging kamery. Nie istnieją obiekty Filter do bogatszych reguł per rekord; jeśli poziom rekordu przejdzie, rekord jest emitowany.

14.3.1.3. basicConfig: szybki start

logging.basicConfig() konfiguruje główny logger w jednym wywołaniu. Najczęściej pojawiają się dwa kształty:

Konfiguracja deweloperska, wszystko do stderr USB na poziomie INFO

import logging

logging.basicConfig(level=logging.INFO)

Konfiguracja produkcyjna, wszystko do pliku na karcie SD z formatem opatrzonym znacznikiem czasu:

import logging

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

Przekaż albo filename= dla FileHandler, albo stream= dla StreamHandler; te dwa wzajemnie się wykluczają w basicConfig().

Ciąg formatujący to szablon w stylu %(field)s. Pola obsługiwane przez formatter kamery:

  • %(asctime)s – znacznik czasu sformatowany na podstawie time.localtime(). Domyślny format to %Y-%m-%d %H:%M:%S; przekaż datefmt=, aby go nadpisać.

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

  • %(name)s – nazwa loggera (zobacz następną sekcję).

  • %(message)s – sformatowany komunikat rekordu.

  • %(msecs)d – ułamek milisekundowy znacznika czasu rekordu.

Domyślny format, jeśli żaden nie zostanie podany, to %(levelname)s:%(name)s:%(message)s – co jest w porządku dla konfiguracji deweloperskiej, ale niewystarczające dla dziennika z terenu, gdzie to znacznik czasu czyni plik użytecznym tygodnie później.

basicConfig() nie robi nic przy kolejnych wywołaniach, chyba że przekazano force=True. Skonfiguruj raz przy starcie; nie wywołuj jej ponownie, aby „przełączać miejsca docelowe” w trakcie działania.

Informacja

logging kamery nie ma dictConfig() ani fileConfig(). Konfiguracja jest zawsze programowa – konwencją jest jeden pomocnik setup_logging() wywoływany raz z main.py.

14.3.1.4. Nazwane loggery na moduł

Kod aplikacji nie powinien wywoływać skrótów na poziomie modułu (logging.info(), logging.warning() itd.). Wszystkie one przechodzą przez główny logger, a powstałe rekordy dziennika niosą nazwę root – bezużyteczną do określenia, skąd pochodzi rekord.

Konwencją jest jeden logger na moduł, nazwany według modułu:

# 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żdy rekord niesie wówczas app.detector w %(name)s, a linia dziennika mówi, kto go wyemitował.

logging kamery różni się od CPython w jeden istotny sposób: przestrzeń nazw loggerów jest płaska. getLogger('app') i getLogger('app.detector') to niezależne loggery bez relacji rodzic / dziecko – ustawienie poziomu na app nie propaguje się do app.detector. Mechanizm, który działa: nazwany logger bez własnych handlerów pożycza handlery i poziom głównego loggera. W ten sposób pojedyncze wywołanie basicConfig() na root konfiguruje każde wywołanie getLogger() w pozostałej części aplikacji.

14.3.1.5. Leniwe formatowanie argumentów %

Pisz:

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

Nie:

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

Forma z argumentami % pozwala loggerowi interpolować argumenty po tym, jak filtr poziomu zdecyduje, czy emitować rekord. Odfiltrowane wywołanie DEBUG w gorącej pętli nie ponosi żadnego kosztu związanego z ciągiem formatującym. F-string jest natomiast obliczany za każdym razem, zanim wywołanie w ogóle dotrze do loggera.

Słowo kluczowe extra= z CPython, służące do pól strukturalnych, nie jest obsługiwane w kamerze; zamiast tego przekaż wartości jako argumenty komunikatu.

14.3.1.6. Logowanie wyjątków

Wewnątrz bloku except metoda Logger.exception() loguje komunikat na poziomie ERROR oraz dołącza do rekordu traceback bieżącego wyjątku:

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

Traceback jest przechwytywany za pomocą sys.print_exception(), co nadaje dziennikowi wyjątku wielowierszowy blok Traceback (most recent call last):. To właściwe narzędzie do obsługi wyjątków na najwyższym poziomie – przechwyć, zaloguj i kontynuuj.

14.3.1.7. Wiele handlerów

Wspomniany na początku podział produkcyjny – wszystko do pliku na poziomie DEBUG, najważniejsze informacje do stderr na poziomie WARNING – to dwa handlery dołączone do tego samego loggera, każdy z własnym poziomem i 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)

Poziom głównego loggera to pierwszy filtr, na jaki trafia każdy rekord. Ustaw go na najniższy poziom, jaki chce widzieć którykolwiek handler – tutaj DEBUG – tak aby żaden handler nie był zagłodzony przez sam logger. Poziomy poszczególnych handlerów decydują następnie, które rekordy faktycznie zostaną wyemitowane do którego miejsca docelowego.

14.3.1.8. Rotacja plików dziennika

logging kamery nie ma RotatingFileHandler ani TimedRotatingFileHandler. Rotacja jest zadaniem aplikacji.

Wzorzec polega na utrzymywaniu bieżącego FileHandler w znanym miejscu, podmianie go na nowy, gdy wystąpi kryterium przełączenia, oraz pozwoleniu, by datowana ścieżka zapewniała naturalną granicę pliku. Dla godzinnego przełączania 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

Wywołuj rotate_if_needed() raz na iterację głównej pętli; sprawdzenie ścieżki jest tanie, a podmiana następuje tylko na granicy godziny. Drzewo katalogów musi istnieć, zanim FileHandler będzie mógł otworzyć plik.

14.3.1.9. Wymuszanie zapisu we wdrożeniach wrażliwych na zasilanie

Zapisy FileHandler przechodzą przez buforowanie Pythona w bazowym obiekcie pliku. Utrata zasilania między zapisem a opróżnieniem bufora powoduje utratę końcowych rekordów. W przypadku wdrożeń zasilanych z baterii lub takich, gdzie zasilanie bywa odcinane, wywołuj flush() na strumieniu handlera po krytycznych rekordach lub cyklicznie z licznika czasu (timer).

Mały pomocnik, który opróżnia każdy handler dołączony do głównego loggera:

import logging

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

Wywołaj flush_handlers() zaraz po rekordzie, na którego utratę aplikacja nie może sobie pozwolić:

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

Dla bezpieczeństwa w tle wywołuj go z głównej pętli z dowolną częstotliwością równoważącą świeżość dziennika ze zużyciem pamięci flash – raz na sekundę zwykle w zupełności wystarcza. Logger.critical() sama z siebie nie wyzwala opróżnienia bufora.

14.3.1.10. Diagnostyka przy starcie

Dziennik z terenu pozbawiony kontekstu jest niemal bezużyteczny. Pierwsze rekordy przy każdym zimnym starcie powinny identyfikować, która to kamera, jaki build działa oraz jak kamera dotarła do tego rozruchu. Trzy źródła na urządzeniu razem obejmują to wszystko:

  • omv – wersja oprogramowania układowego OpenMV.

  • os.uname() – wersja MicroPython, nazwa płytki + MCU oraz tag git i data buildu źródeł, z których zbudowano oprogramowanie układowe.

  • machine – unikalny krzemowy identyfikator MCU oraz przyczyna resetu, która wyzwoliła ten rozruch.

  • os.listdir() dla każdego punktu montowania – systemy plików, które faktycznie się uruchomiły.

Pomocnik, który wciąga każdy z tych elementów do pierwszych rekordów dziennika:

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)

Typowy dziennik otwiera się czymś w rodzaju:

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

Osiem linii na początku każdego pliku dziennika daje operatorowi wiedzę o fizycznej jednostce, rodowodzie oprogramowania układowego, przyczynie rozruchu kamery oraz o tym, która pamięć masowa się uruchomiła. unique id to zaprogramowany fabrycznie krzemowy numer seryjny MCU; jest taki sam po wielokrotnym przegrywaniu oprogramowania i po wymianie kart SD. build to tag git i data drzewa oprogramowania układowego, z którego zbudowano obraz – jedyne pole, które mówi „to jest dokładnie ten plik binarny, który trafił do tej jednostki w tym konkretnym momencie”.

14.3.1.11. Złożenie wszystkiego w całość

Kompletna produkcyjna konfiguracja logowania, ujęta w pomocniku, który main.py wywołuje raz przy starcie:

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)

Następnie na początku main.py

from app.logging_setup import setup_logging, log_boot_diagnostics

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

Każdy inny moduł w aplikacji wykonuje po prostu:

import logging

log = logging.getLogger(__name__)

i za darmo otrzymuje skonfigurowane wyjście – plik z pełnym szczegółem, strumień z ostrzeżeniami, nazwane rekordy, formatter ze znacznikiem czasu oraz udokumentowany rozruch przy każdym zimnym starcie.