14.3.1. 日志记录

已经出货的产品无法通过 print() 向开发者回传信息。print() 写入的是 USB 标准输出，而它只在摄像头还在开发者工位上、终端处于打开状态时才存在。在现场环境中没有任何东西会去读取它；每一行输出都被直接丢弃。logging 库正是它的替代品——提供级别过滤、由应用自行选择的输出目标，以及一种能说明发生了什么、何时发生的格式。

摄像头上的 logging 模块是 CPython 版本的精简移植——心智模型相同，接口更小，并有几处在生产环境配置中至关重要的差异。

14.3.1.1. 心智模型

日志记录由四个部分构成。每个部分各司其职；正是这种职责分离，才使得一个日志记录器（logger）能够分发到多个输出目标，每个目标都有各自的格式和级别：

  • Logger（日志记录器）是应用调用的对象。代码写 log.info("frame %d", n) 时，这个调用就落在该日志记录器上。日志记录器通过 logging.getLogger() 按名称查找。

  • Handler（处理器）决定一条记录去哪里。StreamHandler 写入一个流（默认是 sys.stderr）；FileHandler 则追加到磁盘上的文件。一个日志记录器可以拥有任意数量的处理器。

    备注

    在摄像头上，sys.stdout 和 sys.stderr 都连到同一条 USB CDC 管道——写入二者中的任何一个，都会显示在开发者通过 USB 打开的同一个终端上。因此，一个写入 sys.stderr 的处理器，实际上就是一个写入 print() 所写位置的处理器。处理器这层抽象仍然为你提供了按目标进行的过滤和格式化能力；只是它并不能提供一条物理上独立的通道。

  • Formatter（格式化器）决定一条记录如何渲染成文本。它接收一条记录，返回最终写出的那一行。每个格式化器一个格式字符串；每个处理器一个格式化器。

  • 级别过滤器位于每一个日志记录器和每一个处理器上。记录携带一个级别（DEBUG / INFO / WARNING / ERROR / CRITICAL）。只有级别等于或高于过滤器级别的记录才能通过。

这种分离之所以重要，是因为典型的生产环境配置往往不止一个输出目标：一个写到 SD 卡上的文件，保存一直到 DEBUG 的全部内容以供事后分析；以及一个通往 USB 的流，只呈现 WARNING 及更严重的记录，让连接到摄像头的开发者既能看到要点，又不会被细节淹没。同样的代码，两个目标，两个过滤器。

14.3.1.2. 各个级别的含义

这五个级别构成一个有序的等级体系。记录携带级别，使得每个处理器上的过滤器能够丢弃它不关心的那些记录。

  • DEBUG——跟踪、逐帧计数、内部状态转储。最低级别；数量很大。

  • INFO——正常的运行事件。Wi-Fi 已连接、模型已加载、看门狗已启动、轮换出了一个新的日志文件。

  • WARNING——发生了意料之外的情况，但应用已经处理了。丢失一帧、重试了一次网络请求。

  • ERROR——某个操作失败了，应用无法完成它。模型文件缺失、SD 卡写入被拒绝。

  • CRITICAL——应用完全无法继续运行。内存耗尽、必需挂载的存储缺失。

有一个重要的默认值需要牢记：摄像头的 logging 模块会把每个日志记录器都初始化为 WARNING 级别。除非调用 Logger.setLevel()——通常作为下文 basicConfig() 调用的一部分——否则 DEBUG 和 INFO 级别的记录会被悄无声息地丢弃。日志配置“不起作用”的一个常见首发症状，就是应用以 INFO 级别输出，而默认过滤器把这条记录吃掉了。

备注

级别是摄像头的 logging 所提供的唯一过滤器。它没有 Filter 对象来实现更丰富的逐记录规则；只要一条记录的级别通过了，它就会被输出。

14.3.1.3. basicConfig：快速上手

logging.basicConfig() 在一次调用中配置根日志记录器。最常见的有两种形态：

开发环境配置，所有内容以 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',
)

传入 filename= 以使用 FileHandler，或传入 stream= 以使用 StreamHandler；在 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。请在启动时配置一次；不要在运行中再次调用它来“切换输出目标”。

备注

摄像头的 logging 没有 dictConfig() 或 fileConfig()。配置始终通过编程方式完成——惯例是用一个 setup_logging() 辅助函数，从 main.py 中调用一次。

14.3.1.4. 每个模块使用具名日志记录器

应用代码不应调用模块级别的快捷方式（logging.info()、logging.warning() 等）。它们全都汇入根日志记录器，由此产生的日志记录都带着名称 root——对于判断记录来自何处毫无用处。

惯例是每个模块一个日志记录器，并以该模块命名:

# 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 与 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——就是把两个处理器附加到同一个日志记录器上，每个处理器各有自己的级别和格式化器:

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:

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

为了后台安全，可从主循环中按某种在日志新鲜度与闪存磨损之间取得平衡的节奏来调用它——通常每秒一次就足够了。Logger.critical() 本身不会触发刷新。

14.3.1.10. 启动时诊断

没有上下文的现场日志几乎毫无用处。每次冷启动时的最初几条记录，应当标明是哪一台摄像头、运行的是什么版本，以及摄像头是如何走到这次启动的。设备上的三个来源加在一起就能涵盖所有这些信息：

  • 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

在每个日志文件最初的八行里，操作员就能知道物理设备、固件谱系、摄像头为何启动，以及哪些存储成功挂载。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__)

便可免费获得已配置好的输出——文件中含完整细节、流中含警告、具名记录、带时间戳的格式化器，以及每次冷启动都有一份有据可查的启动记录。