14.3.1. Logging

Um produto em produção não pode comunicar com o exterior através de print(). print() escreve para o stdout USB, que só existe quando a câmara está na bancada de um programador com um terminal aberto. No campo, nada lê essa saída; cada linha é descartada. A biblioteca logging é a substituta – um filtro de nível, um destino à escolha da aplicação, e um formato que descreve o que aconteceu e quando.

O módulo logging na câmara é uma versão reduzida do do CPython – mesmo modelo mental, superfície menor, algumas diferenças relevantes para configuração em produção.

14.3.1.1. O modelo mental

O logging é composto por quatro peças. Cada peça tem uma função; a separação é o que permite que um logger envie para múltiplos destinos, cada um com o seu próprio formato e nível:

  • Um Logger é o que a aplicação chama. O código escreve log.info("frame %d", n); o logger é o objeto em que essa chamada aterra. Os loggers são obtidos por nome com logging.getLogger().

  • Um Handler decide para onde um registo vai. Um StreamHandler escreve para um stream (sys.stderr por omissão); um FileHandler acrescenta a um ficheiro em disco. Um logger pode ter qualquer número de handlers.

    Nota

    Na câmara, sys.stdout e sys.stderr estão ligados ao mesmo canal USB CDC – escritas em qualquer um aparecem no mesmo terminal que um programador tem aberto via USB. Um handler que escreve para sys.stderr é, na prática, um handler que escreve para o mesmo lugar que print() escreve. A abstração do handler ainda oferece filtragem e formatação por destino; simplesmente não oferece um canal fisicamente separado.

  • Um Formatter decide como um registo é apresentado como texto. Recebe um registo e devolve a linha que é escrita. Uma string de formato por formatter; um formatter por handler.

  • Um filtro de nível existe em cada logger e em cada handler. Os registos têm um nível (DEBUG / INFO / WARNING / ERROR / CRITICAL). Apenas os registos com nível igual ou superior ao nível do filtro passam.

Essa separação é importante porque uma configuração típica de produção tem mais de um destino: um ficheiro no cartão SD que guarda tudo até DEBUG para análise post-mortem, e um stream para USB que expõe apenas WARNING e acima, para que um programador ligado à câmara veja os pontos principais sem se afogar em detalhes. O mesmo código, dois destinos, dois filtros.

14.3.1.2. Níveis e o que cada um significa

Os cinco níveis formam uma escala ordenada. Os registos têm um nível para que o filtro em cada handler possa descartar os que não lhe interessam.

  • DEBUG – rastreio, contadores por fotograma, dumps de estado interno. O nível mais baixo; o volume é elevado.

  • INFO – eventos operacionais normais. Wi-Fi ligado, um modelo carregado, o watchdog iniciado, um novo ficheiro de log rodado.

  • WARNING – algo inesperado mas que a aplicação tratou. Um fotograma perdido, um pedido de rede repetido.

  • ERROR – uma operação falhou e a aplicação não conseguiu concluí-la. Um ficheiro de modelo em falta, uma escrita no cartão SD recusada.

  • CRITICAL – a aplicação não pode continuar de forma alguma. Sem memória, montagem obrigatória em falta.

Um comportamento padrão importante a lembrar: o módulo logging da câmara inicia todos os loggers em WARNING. Os registos em DEBUG e INFO são silenciosamente descartados a menos que Logger.setLevel() seja chamado – normalmente como parte da chamada basicConfig() abaixo. Um primeiro sintoma comum de uma configuração de logging que «não está a funcionar» é que a aplicação emitiu em INFO e o filtro padrão engoliu o registo.

Nota

O nível é o único filtro que o logging da câmara oferece. Não existem objetos Filter para regras mais ricas por registo; se o nível de um registo passar, ele é emitido.

14.3.1.3. basicConfig: o arranque rápido

logging.basicConfig() configura o logger raiz numa única chamada. Dois formatos são os mais comuns:

Uma configuração de desenvolvimento, tudo para o stderr USB em INFO

import logging

logging.basicConfig(level=logging.INFO)

Uma configuração de produção, tudo para um ficheiro no cartão SD com um formato com timestamp:

import logging

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

Passe filename= para um FileHandler ou stream= para um StreamHandler; os dois são mutuamente exclusivos em basicConfig().

A string de formato é um template do estilo %(field)s. Os campos que o formatter da câmara suporta:

  • %(asctime)s – timestamp formatado a partir de time.localtime(). O formato padrão é %Y-%m-%d %H:%M:%S; passe datefmt= para substituir.

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

  • %(name)s – o nome do logger (ver a secção seguinte).

  • %(message)s – a mensagem formatada do registo.

  • %(msecs)d – a fração em milissegundos do timestamp do registo.

O formato padrão, quando não é especificado nenhum, é %(levelname)s:%(name)s:%(message)s – adequado para a configuração de desenvolvimento e insuficiente para um log de campo, onde o timestamp é o que torna o ficheiro útil semanas depois.

basicConfig() não tem efeito em chamadas subsequentes a menos que force=True seja passado. Configure uma vez no arranque; não volte a chamá-lo para «mudar destinos» a meio da execução.

Nota

O logging da câmara não tem dictConfig() nem fileConfig(). A configuração é sempre programática – um helper setup_logging() chamado uma vez em main.py é a convenção.

14.3.1.4. Loggers com nome por módulo

O código da aplicação não deve chamar os atalhos a nível de módulo (logging.info(), logging.warning(), etc.). Todos eles passam pelo logger raiz, e os registos resultantes têm o nome root – inútil para identificar de onde veio o registo.

A convenção é um logger por módulo, com o nome do módulo:

# in app/detector.py
import logging

log = logging.getLogger(__name__)

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

Cada registo passa então a ter app.detector em %(name)s e a linha de log indica quem a emitiu.

O logging da câmara difere do CPython de uma forma importante: o espaço de nomes dos loggers é plano. getLogger('app') e getLogger('app.detector') são loggers independentes sem relação pai/filho – definir um nível em app não se propaga para app.detector. O mecanismo que funciona: um logger com nome sem handlers próprios herda os handlers e o nível do logger raiz. É assim que uma única chamada basicConfig() na raiz configura todas as chamadas getLogger() no resto da aplicação.

14.3.1.5. Formatação lazy com %-args

Escreva:

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

Em vez de:

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

A forma com %-args permite ao logger interpolar os argumentos após o filtro de nível ter decidido se emite o registo. Uma chamada DEBUG filtrada num ciclo intenso não paga nada pela sua string de formato. Uma f-string é avaliada primeiro, sempre, antes de a chamada chegar ao logger.

A palavra-chave extra= do CPython para campos estruturados não é suportada na câmara; passe os valores como argumentos da mensagem.

14.3.1.6. Registo de exceções

Dentro de um bloco except, Logger.exception() regista a mensagem ao nível ERROR e acrescenta o traceback da exceção atual ao registo:

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

O traceback é capturado via sys.print_exception(), que é o que dá a um log de exceção o seu bloco Traceback (most recent call last): multilinha. Esta é a ferramenta correta para o tratamento de exceções de alto nível – capturar, registar e continuar.

14.3.1.7. Múltiplos handlers

A divisão de produção mencionada no início – tudo para um ficheiro em DEBUG, pontos principais para stderr em WARNING – são dois handlers ligados ao mesmo logger, cada um com o seu próprio nível e formatter:

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)

O nível do logger raiz é o primeiro filtro que cada registo atravessa. Defina-o para o nível mais baixo que qualquer handler queira ver – DEBUG aqui – para que nenhum handler seja privado pelo próprio logger. Os níveis por handler decidem então quais os registos que são efetivamente emitidos para cada destino.

14.3.1.8. Rotação de ficheiros de log

O logging da câmara não tem RotatingFileHandler nem TimedRotatingFileHandler. A rotação é da responsabilidade da aplicação.

O padrão é manter o FileHandler atual num local conhecido, substituí-lo por um novo quando o critério de rotação dispara, e deixar um caminho datado fornecer a fronteira natural do ficheiro. Para uma rotação horária para /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

Chame rotate_if_needed() uma vez por iteração do ciclo principal; a verificação do caminho é barata e a substituição só acontece na fronteira da hora. A árvore de diretórios deve existir antes de FileHandler poder abrir o ficheiro.

14.3.1.9. Flush em implementações sensíveis à alimentação

As escritas de FileHandler passam pelo buffering Python do objeto ficheiro subjacente. Uma perda de alimentação entre uma escrita e um flush perde os registos finais. Para implementações a bateria ou com corte de alimentação abrupto, chame flush() no stream do handler após registos críticos, ou com base num temporizador.

Um pequeno helper que faz flush de todos os handlers ligados ao logger raiz:

import logging

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

Chame flush_handlers() imediatamente após um registo que a aplicação não pode perder:

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

Para segurança em segundo plano, chame-o a partir do ciclo principal com a cadência que equilibrar a atualidade dos logs com o desgaste do flash – uma vez por segundo é geralmente suficiente. Logger.critical() não desencadeia um flush por si só.

14.3.1.10. Diagnóstico no arranque

Um log de campo sem contexto é quase inútil. Os primeiros registos em cada arranque a frio devem identificar qual câmara, que build está a correr, e como a câmara chegou a este arranque. Três fontes no dispositivo cobrem tudo isso em conjunto:

  • omv – a versão do firmware OpenMV.

  • os.uname() – versão do MicroPython, nome da placa + MCU, e a tag git e data de compilação do código fonte a partir do qual o firmware foi construído.

  • machine – o ID de silício único do MCU e a causa de reset que desencadeou este arranque.

  • os.listdir() em cada ponto de montagem – os sistemas de ficheiros que efetivamente subiram.

Um helper que reúne todos esses dados nos primeiros registos do log:

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)

Um log típico abre com algo como:

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

Oito linhas em cada ficheiro de log, o operador sabe a unidade física, a linhagem do firmware, por que razão a câmara arrancou, e qual o armazenamento que subiu. unique id é o número de série de silício programado em fábrica no MCU; é o mesmo após reflashes e trocas de cartão SD. build é a tag git e a data da árvore do firmware a partir da qual a imagem foi construída – o único campo que diz «este é exatamente o binário que foi enviado para esta unidade neste momento.»

14.3.1.11. Pondo tudo junto

Uma configuração completa de logging de produção, organizada num helper que main.py chama uma vez no arranque:

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)

Depois, no topo de main.py

from app.logging_setup import setup_logging, log_boot_diagnostics

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

Cada módulo no resto da aplicação apenas faz:

import logging

log = logging.getLogger(__name__)

e obtém a saída configurada gratuitamente – ficheiro com detalhe completo, stream com avisos, registos com nome, formatter com timestamp, e um arranque documentado em cada início a frio.