14.3.1. Ghi nhật ký

Một sản phẩm đã xuất xưởng không thể gửi dữ liệu về máy chủ bằng print(). print() ghi vào stdout USB, chỉ tồn tại khi cam đang trên bàn của nhà phát triển với một terminal đang mở. Ở thực địa, không có gì đọc nó; mỗi dòng đều bị bỏ qua. Thư viện logging là sự thay thế -- một bộ lọc mức độ, một đích đến do ứng dụng lựa chọn, và một định dạng cho biết điều gì đã xảy ra và khi nào.

Module logging trên cam là một bản port thu gọn từ CPython -- cùng mô hình tư duy, bề mặt nhỏ hơn, một vài điểm khác biệt quan trọng cho việc thiết lập môi trường sản xuất.

14.3.1.1. Mô hình tư duy

Ghi nhật ký được xây dựng từ bốn thành phần. Mỗi thành phần có một nhiệm vụ; sự tách biệt này cho phép một logger phân nhánh đến nhiều đích, mỗi đích có định dạng và mức độ riêng:

  • Logger là thứ ứng dụng gọi. Code viết log.info("frame %d", n); logger là đối tượng mà lệnh gọi đó đến. Các logger được tra cứu theo tên bằng logging.getLogger().

  • Handler quyết định nơi một bản ghi đến. StreamHandler ghi vào một luồng (sys.stderr mặc định); FileHandler thêm vào một tệp trên đĩa. Một logger có thể có bất kỳ số lượng handler nào.

    Ghi chú

    Trên cam, sys.stdout và sys.stderr được nối vào cùng một đường ống USB CDC -- các lần ghi vào một trong hai đều hiển thị trên cùng terminal mà nhà phát triển đang mở qua USB. Một handler ghi vào sys.stderr thực chất là một handler ghi vào cùng nơi print() ghi vào. Sự trừu tượng hóa handler vẫn cho phép lọc và định dạng theo từng đích; chỉ là nó không cung cấp một kênh vật lý riêng biệt.

  • Formatter quyết định cách một bản ghi được hiển thị thành văn bản. Nó nhận một bản ghi và trả về dòng được ghi. Một chuỗi định dạng mỗi formatter; một formatter mỗi handler.

  • Bộ lọc mức độ nằm trên mỗi logger và mỗi handler. Các bản ghi mang một mức độ (DEBUG / INFO / WARNING / ERROR / CRITICAL). Chỉ các bản ghi ở mức độ bằng hoặc cao hơn mức lọc mới được thông qua.

Sự tách biệt đó quan trọng vì một thiết lập sản xuất điển hình có nhiều hơn một đích: một tệp trên thẻ SD chứa tất cả mọi thứ từ DEBUG trở xuống cho phân tích sau sự cố, và một luồng đến USB chỉ hiển thị WARNING và nghiêm trọng hơn để nhà phát triển kết nối với cam thấy được điểm nổi bật mà không bị chìm trong chi tiết. Cùng một code, hai đích, hai bộ lọc.

14.3.1.2. Các mức độ và ý nghĩa của từng mức

Năm mức độ là một thang đo có thứ tự. Các bản ghi mang một mức độ để bộ lọc trên mỗi handler có thể loại bỏ những bản ghi nó không quan tâm.

  • DEBUG -- theo dõi, bộ đếm theo khung hình, kết xuất trạng thái nội bộ. Mức thấp nhất; khối lượng cao.

  • INFO -- các sự kiện vận hành bình thường. Wi-Fi đã kết nối, mô hình đã tải, watchdog đã khởi động, một tệp nhật ký mới đã được xoay vòng.

  • WARNING -- điều gì đó không mong đợi nhưng ứng dụng đã xử lý được. Một khung hình bị bỏ, một yêu cầu mạng đã thử lại.

  • ERROR -- một thao tác đã thất bại và ứng dụng không thể hoàn thành nó. Một tệp mô hình bị thiếu, một lần ghi thẻ SD bị từ chối.

  • CRITICAL -- ứng dụng hoàn toàn không thể tiếp tục. Hết bộ nhớ, thiếu điểm gắn kết bắt buộc.

Một mặc định quan trọng cần nhớ: module logging của cam khởi động mỗi logger ở mức WARNING. Các bản ghi ở DEBUG và INFO bị âm thầm loại bỏ trừ khi Logger.setLevel() được gọi -- thường là trong lệnh gọi basicConfig() bên dưới. Triệu chứng đầu tiên phổ biến của một thiết lập ghi nhật ký "không hoạt động" là ứng dụng phát ở INFO và bộ lọc mặc định đã loại bỏ bản ghi.

Ghi chú

Mức độ là bộ lọc duy nhất mà logging của cam cung cấp. Không có đối tượng Filter cho các quy tắc phong phú hơn theo từng bản ghi; nếu mức độ của bản ghi vượt qua, nó sẽ được phát ra.

14.3.1.3. basicConfig: bước khởi đầu nhanh

logging.basicConfig() cấu hình root logger trong một lệnh gọi. Hai dạng thường xuất hiện nhất:

Thiết lập phát triển, tất cả ra USB stderr ở mức INFO

import logging

logging.basicConfig(level=logging.INFO)

Thiết lập sản xuất, tất cả vào một tệp trên thẻ SD với định dạng có dấu thời gian:

import logging

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

Truyền filename= cho FileHandler hoặc stream= cho StreamHandler; hai tùy chọn này loại trừ lẫn nhau trong basicConfig().

Chuỗi định dạng là một mẫu kiểu %(field)s. Các trường mà formatter của cam hỗ trợ:

  • %(asctime)s -- dấu thời gian được định dạng từ time.localtime(). Định dạng mặc định là %Y-%m-%d %H:%M:%S; truyền datefmt= để ghi đè.

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

  • %(name)s -- tên của logger (xem phần tiếp theo).

  • %(message)s -- thông điệp được định dạng của bản ghi.

  • %(msecs)d -- phần mili-giây của dấu thời gian bản ghi.

Định dạng mặc định nếu không có định dạng nào được cung cấp là %(levelname)s:%(name)s:%(message)s -- phù hợp cho thiết lập phát triển và không đủ cho nhật ký thực địa, nơi dấu thời gian là thứ làm cho tệp hữu ích vài tuần sau.

basicConfig() là một lệnh không làm gì ở các lần gọi tiếp theo trừ khi force=True được truyền. Cấu hình một lần khi khởi động; không gọi lại để "chuyển đích" trong khi chạy.

Ghi chú

Cam's logging không có dictConfig() hay fileConfig(). Cấu hình luôn theo chương trình -- một helper setup_logging() được gọi một lần từ main.py là quy ước.

14.3.1.4. Logger được đặt tên theo module

Code ứng dụng không nên gọi các phím tắt cấp module (logging.info(), logging.warning(), và các hàm tương tự). Tất cả chúng đều đi qua root logger, và các bản ghi nhật ký kết quả mang tên root -- vô dụng khi muốn biết bản ghi đến từ đâu.

Quy ước là một logger mỗi module, đặt tên theo module:

# in app/detector.py
import logging

log = logging.getLogger(__name__)

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

Mỗi bản ghi sau đó mang app.detector trong %(name)s và dòng nhật ký cho biết ai đã phát ra nó.

Cam's logging khác với CPython ở một điểm quan trọng: không gian tên logger là phẳng. getLogger('app') và getLogger('app.detector') là các logger độc lập không có quan hệ cha / con -- đặt mức độ trên app không lan truyền đến app.detector. Cơ chế hoạt động được: một logger được đặt tên không có handler của riêng nó sẽ mượn handler và mức độ của root logger. Đó là cách một lệnh gọi basicConfig() duy nhất trên root thiết lập mọi lệnh gọi getLogger() ở nơi khác trong ứng dụng.

14.3.1.5. Định dạng %-arg lười biếng

Viết:

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

Không viết:

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

Dạng %-arg cho phép logger nội suy các đối số sau khi bộ lọc mức độ đã quyết định có phát bản ghi hay không. Một lệnh gọi DEBUG bị lọc ra trong một vòng lặp nóng không tốn chi phí nào cho chuỗi định dạng của nó. Một f-string được đánh giá trước, mỗi lần, trước khi lệnh gọi ngay cả đến logger.

Từ khóa extra= của CPython cho các trường có cấu trúc không được hỗ trợ trên cam; thay vào đó hãy truyền các giá trị dưới dạng đối số thông điệp.

14.3.1.6. Ghi nhật ký ngoại lệ

Bên trong một khối except, Logger.exception() ghi thông điệp ở mức ERROR và thêm traceback của ngoại lệ hiện tại vào bản ghi:

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

Traceback được thu thập qua sys.print_exception(), đó là thứ tạo ra khối Traceback (most recent call last): nhiều dòng của nhật ký ngoại lệ. Đây là công cụ phù hợp cho xử lý ngoại lệ cấp cao nhất -- bắt, ghi nhật ký, và tiếp tục.

14.3.1.7. Nhiều handler

Sự phân chia sản xuất đã đề cập ở đầu -- tất cả vào một tệp ở mức DEBUG, điểm nổi bật ra stderr ở mức WARNING -- là hai handler gắn vào cùng một logger, mỗi cái có mức độ và formatter riêng:

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)

Mức độ của root logger là bộ lọc đầu tiên mà mỗi bản ghi gặp phải. Đặt nó ở mức thấp nhất mà bất kỳ handler nào muốn thấy -- DEBUG ở đây -- để không handler nào bị bỏ đói bởi chính logger. Sau đó các mức độ per-handler quyết định bản ghi nào thực sự được phát ra đến đích nào.

14.3.1.8. Xoay vòng tệp nhật ký

Cam's logging không có RotatingFileHandler hay TimedRotatingFileHandler. Xoay vòng là công việc của ứng dụng.

Mẫu là giữ FileHandler hiện tại ở một nơi đã biết, hoán đổi nó với một cái mới khi tiêu chí xoay vòng kích hoạt, và để một đường dẫn có ngày tháng cung cấp ranh giới tệp tự nhiên. Cho xoay vòng hàng giờ vào /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

Gọi rotate_if_needed() một lần mỗi vòng lặp chính; kiểm tra đường dẫn rẻ và việc hoán đổi chỉ xảy ra tại ranh giới giờ. Cây thư mục phải tồn tại trước khi FileHandler có thể mở tệp.

14.3.1.9. Xả bộ đệm trên các triển khai nhạy cảm với nguồn điện

Các lần ghi FileHandler đi qua bộ đệm Python của đối tượng tệp bên dưới. Mất nguồn điện giữa một lần ghi và một lần xả bộ đệm sẽ mất các bản ghi cuối cùng. Đối với các triển khai dùng pin hoặc rút nguồn đột ngột, hãy gọi flush() trên luồng của handler sau các bản ghi quan trọng, hoặc theo bộ định thời.

Một helper nhỏ xả bộ đệm mọi handler gắn với root logger:

import logging

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

Gọi flush_handlers() ngay sau một bản ghi mà ứng dụng không thể để mất:

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

Để an toàn trong nền, hãy gọi nó từ vòng lặp chính theo nhịp cân bằng giữa độ tươi của nhật ký và độ hao mòn flash -- một lần mỗi giây thường là đủ. Logger.critical() không tự kích hoạt xả bộ đệm.

14.3.1.10. Chẩn đoán lúc khởi động

Một nhật ký thực địa không có ngữ cảnh gần như vô dụng. Các bản ghi đầu tiên mỗi lần khởi động lạnh nên xác định cam nào, bản build nào đang chạy, và cách cam đến lần khởi động này. Ba nguồn trên thiết bị cùng nhau bao gồm tất cả những điều đó:

  • omv -- phiên bản firmware OpenMV.

  • os.uname() -- phiên bản MicroPython, tên bo mạch + MCU, và tag git và ngày build của mã nguồn mà firmware được xây dựng từ đó.

  • machine -- ID silicon duy nhất của MCU và nguyên nhân reset đã kích hoạt lần khởi động này.

  • os.listdir() đối với từng điểm gắn kết -- các hệ thống tệp thực sự đã khởi động.

Một helper kéo tất cả những điều đó vào các bản ghi đầu tiên của nhật ký:

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)

Một nhật ký điển hình mở đầu với nội dung như:

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

Tám dòng đầu mỗi tệp nhật ký, người vận hành biết đơn vị vật lý, dòng dõi firmware, lý do cam khởi động, và bộ nhớ nào đã khởi động. unique id là số sê-ri silicon được lập trình tại nhà máy của MCU; nó giống nhau qua các lần nạp lại firmware và qua các lần đổi thẻ SD. build là tag git và ngày của cây firmware mà ảnh được xây dựng từ đó -- trường duy nhất nói rằng "đây chính xác là nhị phân được giao đến đơn vị này tại thời điểm này."

14.3.1.11. Kết hợp lại

Một thiết lập ghi nhật ký sản xuất hoàn chỉnh, được tổ chức vào một helper mà main.py gọi một lần khi khởi động:

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)

Sau đó ở đầu main.py

from app.logging_setup import setup_logging, log_boot_diagnostics

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

Mỗi module khác trong ứng dụng chỉ cần làm:

import logging

log = logging.getLogger(__name__)

và nhận được kết quả đầu ra đã cấu hình miễn phí -- tệp với chi tiết đầy đủ, luồng với các cảnh báo, bản ghi được đặt tên, formatter có dấu thời gian, và một lần khởi động được ghi lại mỗi lần khởi động lạnh.