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)을 가집니다. 필터 레벨 이상의 레코드만 통과합니다.

이 분리가 중요한 이유는 일반적인 프로덕션 설정에 둘 이상의 대상이 있기 때문입니다: 사후 분석을 위해 DEBUG 까지 모든 것을 보관하는 SD 카드의 파일, 그리고 카메라에 연결된 개발자가 세부 사항에 파묻히지 않고 핵심만 볼 수 있도록 WARNING 이상만 노출하는 USB로의 스트림입니다. 동일한 코드, 두 개의 대상, 두 개의 필터입니다.

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

FileHandler 를 위한 filename= 또는 StreamHandler 를 위한 stream= 중 하나를 전달합니다. 이 둘은 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() 가 없습니다. 구성은 항상 프로그래밍 방식입니다 – main.py 에서 한 번 호출되는 하나의 setup_logging() 헬퍼가 관례입니다.

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

구성된 출력을 거저 얻습니다 – 전체 세부 정보가 담긴 파일, 경고가 담긴 스트림, 이름이 지정된 레코드, 타임스탬프가 찍힌 포매터, 그리고 모든 콜드 부팅 시 문서화된 부트입니다.