14.3.1. תיעוד (Logging)

מוצר שנשלח ללקוח אינו יכול לדווח הביתה באמצעות print(). print() כותב ל-USB stdout, שקיים רק כאשר המצלמה נמצאת על שולחן העבודה של מפתח עם טרמינל פתוח. בשטח שום דבר לא קורא אותו; כל שורה נזרקת לרצפה. ספריית logging היא התחליף – מסנן רמות, יעד לבחירת היישום, ופורמט שמספר מה קרה ומתי.

מודול logging במצלמה הוא העברה מצומצמת של זה של CPython – אותו מודל מחשבתי, משטח קטן יותר, וכמה הבדלים שחשובים להגדרת ייצור.

14.3.1.1. המודל המחשבתי

התיעוד בנוי מארבעה חלקים. לכל חלק יש תפקיד אחד; ההפרדה היא מה שמאפשר ל-logger יחיד להתפצל למספר יעדים, כל אחד עם הפורמט והרמה שלו:

  • Logger הוא מה שהיישום קורא לו. הקוד אומר log.info("frame %d", n); ה-logger הוא האובייקט שעליו נוחתת הקריאה. logger-ים נמצאים לפי שם באמצעות logging.getLogger().

  • Handler מחליט לאן רשומה הולכת. StreamHandler כותב לזרם (sys.stderr כברירת מחדל); FileHandler מצרף לקובץ בדיסק. ל-logger יכול להיות כל מספר של handler-ים.

    הערה

    במצלמה, sys.stdout ו-sys.stderr מחוברים לאותו צינור USB CDC – כתיבות לכל אחד מהם מופיעות באותו טרמינל שמפתח פתח מעל USB. handler שכותב ל-sys.stderr הוא, למעשה, handler שכותב לאותו מקום ש-print() כותב אליו. ההפשטה של ה-handler עדיין נותנת לך סינון ועיצוב לכל יעד; היא פשוט אינה נותנת לך ערוץ נפרד פיזית.

  • Formatter מחליט כיצד רשומה מעובדת לטקסט. הוא לוקח רשומה ומחזיר את השורה שנכתבת. מחרוזת פורמט אחת לכל formatter; formatter אחד לכל handler.

  • מסנן רמות יושב על כל logger וכל handler. רשומות נושאות רמה (DEBUG / INFO / WARNING / ERROR / CRITICAL). רק רשומות ברמת המסנן או מעליה עוברות.

ההפרדה הזו חשובה משום שהגדרת ייצור טיפוסית כוללת יותר מיעד אחד: קובץ בכרטיס ה-SD שמחזיק הכול עד DEBUG לניתוח לאחר תקלה, וזרם ל-USB שחושף רק WARNING וחמור ממנו כך שמפתח המחובר למצלמה רואה את העיקר בלי לטבוע בפרטים. אותו קוד, שני יעדים, שני מסננים.

14.3.1.2. הרמות ומשמעות כל אחת מהן

חמש הרמות הן סולם מסודר. רשומות נושאות רמה כך שהמסנן בכל handler יכול לזרוק את אלה שלא אכפת לו מהן.

  • DEBUG – מעקב, מוני פריימים, השלכות מצב פנימי. הרמה הנמוכה ביותר; הנפח גבוה.

  • INFO – אירועים תפעוליים רגילים. Wi-Fi מחובר, מודל נטען, ה-watchdog התחיל, קובץ יומן חדש הוחלף.

  • WARNING – משהו לא צפוי אך היישום טיפל בו. פריים שנשמט, בקשת רשת שנוסתה שוב.

  • ERROR – פעולה נכשלה והיישום לא יכל להשלים אותה. קובץ מודל חסר, כתיבה לכרטיס SD שנדחתה.

  • CRITICAL – היישום אינו יכול להמשיך כלל. אזל הזיכרון, נקודת עיגון חובה חסרה.

ברירת מחדל חשובה אחת שכדאי לזכור: מודול logging של המצלמה מתחיל כל logger ב-WARNING. רשומות ב-DEBUG וב-INFO נזרקות בשקט אלא אם Logger.setLevel() נקראת – בדרך כלל כחלק מקריאת basicConfig() שלהלן. סימפטום ראשון נפוץ של הגדרת תיעוד ש“לא עובדת“ הוא שהיישום פלט ב-INFO ומסנן ברירת המחדל אכל את הרשומה.

הערה

רמה היא המסנן היחיד ש-logging של המצלמה מציע. אין אובייקטים מסוג Filter לכללים עשירים יותר לכל רשומה; אם רמת הרשומה עוברת, היא נפלטת.

14.3.1.3. basicConfig: ההתחלה המהירה

logging.basicConfig() מגדיר את ה-logger השורשי בקריאה אחת. שתי צורות מופיעות לרוב:

הגדרת פיתוח, הכול ל-USB stderr ב-INFO

import logging

logging.basicConfig(level=logging.INFO)

הגדרת ייצור, הכול לקובץ בכרטיס ה-SD עם פורמט בעל חותמת זמן:

import logging

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

העבר או filename= עבור FileHandler או stream= עבור StreamHandler; השניים אינם יכולים לדור בכפיפה אחת ב-basicConfig().

מחרוזת הפורמט היא תבנית בסגנון %(field)s. השדות שה-formatter של המצלמה תומך בהם:

  • %(asctime)s – חותמת זמן מעוצבת מ-time.localtime(). פורמט ברירת המחדל הוא %Y-%m-%d %H:%M:%S; העבר datefmt= כדי לעקוף.

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

  • %(name)s – שם ה-logger (ראה את הסעיף הבא).

  • %(message)s – ההודעה המעוצבת של הרשומה.

  • %(msecs)d – החלק של אלפית השנייה בחותמת הזמן של הרשומה.

פורמט ברירת המחדל אם לא ניתן אף אחד הוא %(levelname)s:%(name)s:%(message)s – שמספיק להגדרת הפיתוח ובלתי מספק ליומן שטח, שבו חותמת הזמן היא מה שהופך את הקובץ לשימושי שבועות מאוחר יותר.

basicConfig() אינו עושה דבר בקריאות שלאחר מכן אלא אם מועבר force=True. הגדר פעם אחת בעת ההפעלה; אל תקרא לו שוב כדי ”להחליף יעדים“ באמצע הריצה.

הערה

ל-logging של המצלמה אין dictConfig() או fileConfig(). ההגדרה תמיד תכנותית – פונקציית עזר אחת setup_logging() הנקראת פעם אחת מ-main.py היא המוסכמה.

14.3.1.4. logger-ים בעלי שם לכל מודול

קוד יישום לא צריך לקרוא לקיצורי הדרך ברמת המודול (logging.info(), logging.warning(), וכן הלאה). כל אלה מנותבים דרך ה-logger השורשי, ורשומות היומן שמתקבלות נושאות את השם root – חסר תועלת לזיהוי מהיכן הרשומה הגיעה.

המוסכמה היא logger אחד לכל מודול, הנקרא על שם המודול:

# in app/detector.py
import logging

log = logging.getLogger(__name__)

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

כל רשומה נושאת אז את app.detector ב-%(name)s ושורת היומן אומרת מי פלט אותה.

logging של המצלמה שונה מ-CPython בדרך חשובה אחת: מרחב השמות של ה-logger הוא שטוח. getLogger('app') ו-getLogger('app.detector') הם logger-ים עצמאיים ללא קשר הורה / ילד – הגדרת רמה על app אינה מתפשטת ל-app.detector. המנגנון שכן עובד: logger בעל שם ללא handler-ים משלו שואל את ה-handler-ים והרמה של ה-logger השורשי. כך קריאת basicConfig() יחידה על השורש מגדירה כל קריאת getLogger() במקום אחר ביישום.

14.3.1.5. עיצוב עצל של ארגומנטים בסגנון %

כתוב:

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

לא:

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

צורת ארגומנט ה-% מאפשרת ל-logger לשלב את הארגומנטים לאחר שמסנן הרמות החליט אם לפלוט את הרשומה. קריאת DEBUG שסוננה החוצה בלולאה חמה אינה משלמת דבר עבור מחרוזת הפורמט שלה. מחרוזת f מוערכת תחילה, בכל פעם, עוד לפני שהקריאה מגיעה ל-logger.

מילת המפתח extra= של CPython לשדות מובנים אינה נתמכת במצלמה; העבר את הערכים כארגומנטים של ההודעה במקום זאת.

14.3.1.6. תיעוד חריגות

בתוך בלוק except, Logger.exception() מתעד את ההודעה ברמת ERROR וגם מצרף את ה-traceback של החריגה הנוכחית לרשומה:

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

ה-traceback נלכד באמצעות sys.print_exception(), שזה מה שנותן ליומן חריגה את הבלוק רב-השורות Traceback (most recent call last):. זהו הכלי הנכון לטיפול בחריגות ברמה העליונה – לכוד, תעד, והמשך.

14.3.1.7. מספר handler-ים

הפיצול לייצור שהוזכר בראש – הכול לקובץ ב-DEBUG, העיקר ל-stderr ב-WARNING – הוא שני handler-ים המחוברים לאותו logger, כל אחד עם הרמה וה-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)

הרמה של ה-logger השורשי היא המסנן הראשון שכל רשומה פוגשת. הגדר אותה לרמה הנמוכה ביותר שכל handler רוצה לראות – DEBUG כאן – כך שאף handler לא יורעב על ידי ה-logger עצמו. רמות ה-handler הבודדות מחליטות אז אילו רשומות באמת נפלטות לאיזה יעד.

14.3.1.8. סיבוב קבצי יומן

ל-logging של המצלמה אין RotatingFileHandler או TimedRotatingFileHandler. הסיבוב הוא תפקידו של היישום.

התבנית היא לשמור את ה-FileHandler הנוכחי במקום ידוע, להחליף אותו בחדש כאשר קריטריון ההחלפה מופעל, ולתת לנתיב מתוארך לספק את גבול הקובץ הטבעי. עבור החלפה שעתית ל-/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

קרא ל-rotate_if_needed() פעם אחת בכל איטרציה של הלולאה הראשית; בדיקת הנתיב זולה וההחלפה מתרחשת רק בגבול השעה. עץ הספריות חייב להתקיים לפני ש-FileHandler יכול לפתוח את הקובץ.

14.3.1.9. ריקון (flush) בפריסות רגישות לחשמל

כתיבות של FileHandler עוברות דרך החציצה (buffering) של Python של אובייקט הקובץ הבסיסי. אובדן חשמל בין כתיבה לריקון מאבד את הרשומות האחרונות. עבור פריסות המופעלות בסוללה או של ניתוק-מהשקע, קרא ל-flush() על הזרם של ה-handler לאחר רשומות קריטיות, או על טיימר.

פונקציית עזר קטנה שמרוקנת כל handler המחובר ל-logger השורשי:

import logging

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

קרא ל-flush_handlers() מיד לאחר רשומה שהיישום אינו יכול להרשות לעצמו לאבד:

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

לבטיחות ברקע, קרא לה מהלולאה הראשית בכל קצב שמאזן בין רעננות היומן לבין שחיקת זיכרון הפלאש (flash) – פעם בשנייה לרוב מספיקה. Logger.critical() אינו מפעיל ריקון בעצמו.

14.3.1.10. אבחון בזמן אתחול

יומן שטח ללא הקשר הוא כמעט חסר תועלת. הרשומות הראשונות בכל אתחול קר צריכות לזהות איזו מצלמה, איזה build רץ, וכיצד המצלמה הגיעה לאתחול הזה. שלושה מקורות במכשיר מכסים יחד את כל זה:

  • omv – גרסת הקושחה של OpenMV.

  • os.uname() – גרסת MicroPython, שם הלוח + MCU, ותג ה-git ותאריך ה-build של המקור שממנו נבנתה הקושחה.

  • machine – מזהה הסיליקון הייחודי של ה-MCU וסיבת האיפוס שהפעילה את האתחול הזה.

  • os.listdir() כנגד כל נקודת עיגון – מערכות הקבצים שעלו בפועל.

פונקציית עזר שמושכת כל אחד מאלה לתוך הרשומות הראשונות של היומן:

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)

יומן טיפוסי נפתח במשהו כמו:

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

שמונה שורות לתוך כל קובץ יומן, המפעיל יודע את היחידה הפיזית, את שושלת הקושחה, מדוע המצלמה אותחלה, ואיזה אחסון עלה. unique id הוא מספר הסידורי של הסיליקון שתוכנת במפעל ב-MCU; הוא זהה בין הבזקות מחדש ובין החלפות של כרטיס SD. build הוא תג ה-git והתאריך של עץ הקושחה שממנו נבנתה התמונה – השדה היחיד שאומר ”זהו בדיוק הקובץ הבינארי שנשלח ליחידה הזו בנקודת הזמן הזו.“

14.3.1.11. מחברים את הכול יחד

הגדרת תיעוד ייצור מלאה, מקובצת לפונקציית עזר ש-main.py קורא לה פעם אחת בעת ההפעלה:

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)

ואז בראש main.py

from app.logging_setup import setup_logging, log_boot_diagnostics

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

כל מודול במקום אחר ביישום פשוט עושה:

import logging

log = logging.getLogger(__name__)

ומקבל את הפלט המוגדר בחינם – קובץ עם פירוט מלא, זרם עם אזהרות, רשומות בעלות שם, formatter עם חותמת זמן, ואתחול מתועד בכל הפעלה קרה.