14.3.1. Логирование

Готовый продукт не может «звонить домой» с помощью print(). print() выводит данные в USB stdout, который существует только тогда, когда камера стоит на столе разработчика с открытым терминалом. В полевых условиях это никто не читает; каждая строка попросту теряется. Библиотека logging – это замена: фильтр по уровню, выбираемое приложением место назначения и формат, который сообщает, что произошло и когда.

Модуль logging на камере – это облегчённый порт модуля из CPython: та же ментальная модель, меньший набор возможностей и несколько отличий, важных для настройки в продакшене.

14.3.1.1. Ментальная модель

Логирование строится из четырёх частей. У каждой части одна задача; именно это разделение позволяет одному логгеру направлять вывод в несколько мест назначения, каждое со своим форматом и уровнем:

  • 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, загружена модель, запущен watchdog, начат новый файл журнала после ротации.

  • WARNING – произошло что-то неожиданное, но приложение справилось с этим. Пропущенный кадр, повторно отправленный сетевой запрос.

  • ERROR – операция не удалась, и приложение не смогло её завершить. Отсутствует файл модели, отказано в записи на SD-карту.

  • CRITICAL – приложение вообще не может продолжать работу. Закончилась память, не примонтирован обязательный том.

Один важный момент по умолчанию, который стоит помнить: модуль logging на камере запускает каждый логгер с уровня WARNING. Записи уровней DEBUG и INFO молча отбрасываются, пока не будет вызван Logger.setLevel() – обычно в составе вызова basicConfig(), описанного ниже. Распространённый первый симптом настройки логирования, которая «не работает», – это то, что приложение выводило на уровне INFO, а фильтр по умолчанию проглотил запись.

Примечание

Уровень – единственный фильтр, который предлагает logging на камере. Нет объектов Filter для более гибких правил для отдельных записей; если уровень записи проходит, она выводится.

14.3.1.3. basicConfig: быстрый старт

logging.basicConfig() настраивает корневой логгер одним вызовом. Чаще всего встречаются две формы:

Настройка для разработки, всё в 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. Поля, которые поддерживает форматтер на камере:

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

Тогда каждая запись несёт app.detector в %(name)s, и строка журнала сообщает, кто её вывел.

Модуль 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-строка вычисляется первой, каждый раз, ещё до того, как вызов достигнет логгера.

Ключевое слово extra= из CPython для структурированных полей на камере не поддерживается; передавайте значения как аргументы сообщения.

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, важное в stderr на уровне WARNING – это два обработчика, подключённые к одному логгеру, каждый со своим уровнем и форматтером:

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 – уникальный кремниевый 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 – это заводски запрограммированный кремниевый серийный номер микроконтроллера; он одинаков при перепрошивках и при заменах 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__)

и бесплатно получает настроенный вывод – файл с полной детализацией, поток с предупреждениями, именованные записи, форматтер с временными метками и задокументированную загрузку при каждом холодном старте.