14.3.1. ロギング

出荷された製品は print() で状態を報告することはできません。print() は USB の標準出力に書き込みますが、これはカメラが開発者のベンチ上にあり、ターミナルが開いているときにしか存在しません。フィールドでは何もそれを読み取らず、すべての行は捨てられてしまいます。logging ライブラリがその代替手段です。レベルフィルタ、アプリケーションが選択した出力先、そして何がいつ起きたのかを伝える書式を提供します。

カメラ上の logging モジュールは CPython のものをスリム化して移植したものです。考え方は同じで、機能は小さくまとまっていますが、本番環境のセットアップで重要となるいくつかの違いがあります。

14.3.1.1. 考え方

ロギングは 4 つの要素から構成されています。各要素は 1 つの仕事だけを担い、この分離こそが 1 つのロガーを複数の出力先（それぞれが独自の書式とレベルを持つ）へ振り分けることを可能にしています。

  • Logger はアプリケーションが呼び出すものです。コードは log.info("frame %d", n) のように記述し、その呼び出しが着地するオブジェクトがロガーです。ロガーは logging.getLogger() で名前によって取得します。

  • Handler はレコードが どこへ 行くかを決定します。StreamHandler はストリーム（デフォルトでは sys.stderr）に書き込み、FileHandler はディスク上のファイルに追記します。1 つのロガーは任意の数のハンドラを持つことができます。

    注釈

    カメラ上では sys.stdout と sys.stderr は同じ USB CDC パイプに接続されており、どちらに書き込んでも、開発者が USB 経由で開いている同じターミナルに表示されます。sys.stderr に書き込むハンドラは、実際には print() が書き込むのと同じ場所に書き込むハンドラなのです。ハンドラという抽象化は、依然として出力先ごとのフィルタリングと書式設定を提供しますが、物理的に分離されたチャンネルは提供しません。

  • Formatter はレコードが どのように テキストにレンダリングされるかを決定します。レコードを受け取り、書き込まれる行を返します。1 つのフォーマッタにつき書式文字列は 1 つ、1 つのハンドラにつきフォーマッタは 1 つです。

  • レベルフィルタ はすべてのロガーとすべてのハンドラに備わっています。レコードはレベル（DEBUG / INFO / WARNING / ERROR / CRITICAL）を持ち、フィルタレベル以上のレコードだけが通過します。

この分離が重要なのは、典型的な本番環境のセットアップが複数の出力先を持つからです。事後分析のために DEBUG まですべてを保持する SD カード上のファイルと、WARNING 以上のみを表面化させて、カメラに接続している開発者が細部に溺れることなく要点を把握できるようにする USB へのストリームです。同じコード、2 つの出力先、2 つのフィルタです。

14.3.1.2. レベルとそれぞれの意味

5 つのレベルは順序付けられた尺度です。レコードがレベルを持つことで、各ハンドラのフィルタが関心のないものを捨てられるようになっています。

  • DEBUG -- トレース、フレームごとのカウンタ、内部状態のダンプ。最も低いレベルで、量が多くなります。

  • INFO -- 通常の運用イベント。Wi-Fi 接続、モデルの読み込み、ウォッチドッグの起動、新しいログファイルへのローテーションなど。

  • WARNING -- 予期しないことが起きたが、アプリケーションがそれを処理したもの。ドロップされたフレーム、再試行されたネットワークリクエストなど。

  • ERROR -- 操作が失敗し、アプリケーションがそれを完了できなかったもの。モデルファイルの欠落、SD カードへの書き込み拒否など。

  • CRITICAL -- アプリケーションがまったく継続できないもの。メモリ不足、必須マウントの欠落など。

覚えておくべき重要なデフォルトが 1 つあります。カメラの logging モジュールは、すべてのロガーを WARNING で開始します。DEBUG と INFO のレコードは、Logger.setLevel() が呼び出されない限り（通常は下記の basicConfig() 呼び出しの一部として）、黙って捨てられます。ロギングのセットアップが「機能していない」場合のよくある最初の症状は、アプリケーションが INFO で出力したのに、デフォルトのフィルタがそのレコードを食べてしまったというものです。

注釈

レベルは、カメラの logging が提供する唯一のフィルタです。レコードごとのより細かいルールのための Filter オブジェクトはありません。レコードのレベルが通過すれば、それは出力されます。

14.3.1.3. basicConfig: クイックスタート

logging.basicConfig() は 1 回の呼び出しでルートロガーを設定します。最もよく登場するのは 2 つの形です。

開発時のセットアップ。すべてを INFO で USB の stderr へ出力します:

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',
)

FileHandler 用に filename= を、または StreamHandler 用に stream= を渡します。この 2 つは basicConfig() では相互に排他的です。

書式文字列は %(field)s スタイルのテンプレートです。カメラのフォーマッタがサポートするフィールドは次のとおりです。

  • %(asctime)s -- time.localtime() から書式化されたタイムスタンプ。デフォルトの書式は %Y-%m-%d %H:%M:%S で、上書きするには datefmt= を渡します。

  • %(levelname)s -- DEBUG / INFO / WARNING / ERROR / CRITICAL。

  • %(name)s -- ロガーの名前（次のセクションを参照）。

  • %(message)s -- レコードの書式化されたメッセージ。

  • %(msecs)d -- レコードのタイムスタンプのミリ秒部分。

何も指定しない場合のデフォルトの書式は %(levelname)s:%(name)s:%(message)s です。これは開発時のセットアップには適していますが、フィールドログには不十分です。フィールドログでは、数週間後にそのファイルを役立つものにするのはタイムスタンプだからです。

basicConfig() は、force=True が渡されない限り、2 回目以降の呼び出しでは何もしません。起動時に一度だけ設定してください。実行中に「出力先を切り替える」ために再度呼び出してはいけません。

注釈

カメラの logging には dictConfig() や fileConfig() はありません。設定は常にプログラムによって行います。main.py から一度だけ呼び出される setup_logging() ヘルパー 1 つが慣例です。

14.3.1.4. モジュールごとの名前付きロガー

アプリケーションコードは、モジュールレベルのショートカット（logging.info()、logging.warning() など）を呼び出すべきではありません。それらはすべてルートロガーを通り抜け、結果として生成されるログレコードは root という名前を持ちます。これではレコードが どこから 来たのかを伝えるのに役立ちません。

慣例は、モジュールごとに 1 つのロガーを、そのモジュールにちなんだ名前で用意することです:

# in app/detector.py
import logging

log = logging.getLogger(__name__)

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

そうすれば、すべてのレコードが %(name)s に app.detector を持ち、ログ行はそれを出力したのが誰かを示します。

カメラの logging は、1 つの重要な点で CPython と異なります。ロガーの名前空間が フラット であることです。getLogger('app') と getLogger('app.detector') は親子関係を持たない独立したロガーであり、app にレベルを設定しても app.detector には 伝播しません。機能する仕組みは次のとおりです。自分自身のハンドラを持たない名前付きロガーは、ルートロガーのハンドラとレベルを借用します。これが、ルートに対する単一の 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")

% 引数形式は、レベルフィルタがレコードを出力するかどうかを決定した 後で ロガーに引数を埋め込ませることができます。ホットループ内でフィルタによって除外された DEBUG 呼び出しは、その書式文字列に対して何のコストも払いません。一方、f-string は呼び出しがロガーに届く前に、毎回最初に評価されます。

構造化フィールドのための CPython の extra= キーワードはカメラではサポートされていません。代わりにそれらの値をメッセージの引数として渡してください。

14.3.1.6. 例外のロギング

except ブロック内で、Logger.exception() はメッセージを ERROR レベルでログに記録し、さらに 現在の例外のトレースバックをレコードに追加します:

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

トレースバックは sys.print_exception() を介して取得され、これが例外ログに複数行の Traceback (most recent call last): ブロックを与えるものです。これはトップレベルの例外処理のための適切なツールです。捕捉し、ログに記録し、処理を続行します。

14.3.1.7. 複数のハンドラ

冒頭で述べた本番環境での分割（すべてを DEBUG でファイルへ、要点を WARNING で stderr へ）は、同じロガーに接続された 2 つのハンドラであり、それぞれが独自のレベルとフォーマッタを持ちます:

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)

ルートロガーのレベルは、すべてのレコードが最初に当たる 最初の フィルタです。いずれかのハンドラが見たいと思う最も低いレベル（ここでは DEBUG）に設定して、ロガー自身によってどちらのハンドラも飢えさせられないようにします。その後、ハンドラごとのレベルが、実際にどのレコードがどの出力先に出力されるかを決定します。

14.3.1.8. ログファイルのローテーション

カメラの logging には RotatingFileHandler や TimedRotatingFileHandler はありません。ローテーションはアプリケーションの仕事です。

そのパターンは、現在の FileHandler を既知の場所に保持し、ロールオーバー条件が発生したときに新しいものと入れ替え、日付入りのパスに自然なファイルの境界を提供させるというものです。/sdcard/logs/<year>/<month>/<day>/<hour>.log への 1 時間ごとのロールオーバーの場合は次のようになります:

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. 電源に敏感なデプロイメントでのフラッシュ

FileHandler の書き込みは、基盤となるファイルオブジェクトの Python バッファリングを経由します。書き込みとフラッシュの間に電源が失われると、末尾のレコードが失われます。バッテリー駆動や電源を引き抜くようなデプロイメントでは、重要なレコードの後やタイマーで、ハンドラのストリームに対して flush() を呼び出してください。

ルートロガーに接続されたすべてのハンドラをフラッシュする小さなヘルパーは次のとおりです:

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()

バックグラウンドでの安全のためには、ログの新鮮さとフラッシュの摩耗のバランスを取れる任意の頻度でメインループから呼び出してください。通常は 1 秒に 1 回で十分です。Logger.critical() はそれ自体ではフラッシュをトリガしません。

14.3.1.10. 起動時の診断

コンテキストのないフィールドログはほとんど役に立ちません。コールドブートのたびに最初に記録されるレコードは、どの カメラなのか、どのビルド が動作しているのか、そしてカメラが どのように このブートに至ったのかを特定すべきです。デバイス上の 3 つの情報源が、それらすべてをカバーします。

  • omv -- OpenMV ファームウェアのバージョン。

  • os.uname() -- MicroPython のバージョン、ボード名 + MCU、そしてファームウェアのビルド元となったソースの git タグとビルド日時。

  • machine -- MCU の固有シリコン ID と、このブートをトリガしたリセット要因。

  • 各マウントポイントに対する 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

すべてのログファイルの最初の 8 行で、オペレーターは物理ユニット、ファームウェアの系譜、カメラがブートした理由、そしてどのストレージが立ち上がったのかを知ることができます。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__)

それだけで設定済みの出力を無償で得られます。完全な詳細を持つファイル、警告を持つストリーム、名前付きレコード、タイムスタンプ付きのフォーマッタ、そしてコールドブートのたびに文書化されるブート情報です。