14.3.1. Logging

Um produto entregue não pode reportar-se usando print(). print() escreve na stdout USB, que só existe quando a câmera está na bancada de um desenvolvedor com um terminal aberto. Em campo, nada o lê; cada linha é simplesmente descartada. A biblioteca logging é a substituta – um filtro de nível, um destino à escolha da aplicação e um formato que diz o que aconteceu e quando.

O módulo logging na câmera é uma porta enxuta da versão do CPython – mesmo modelo mental, superfície menor, algumas diferenças que importam na configuração de produção.

14.3.1.1. O modelo mental

O logging é construído a partir de quatro peças. Cada peça tem uma única função; é essa separação que permite a um único logger distribuir para múltiplos destinos, cada um com seu próprio formato e nível:

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

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

  Nota

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

• Um Formatter decide como um registro é renderizado em texto. Ele recebe um registro e retorna a linha que será 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 registros carregam um nível (DEBUG / INFO / WARNING / ERROR / CRITICAL). Apenas os registros no nível do filtro ou acima dele passam.

Essa separação importa porque uma configuração típica de produção tem mais de um destino: um arquivo no cartão SD que guarda tudo até DEBUG para análise post-mortem, e um stream para USB que mostra apenas WARNING e pior, de modo que um desenvolvedor conectado à câmera veja os destaques sem se afogar em detalhes. Mesmo código, dois destinos, dois filtros.

14.3.1.2. Os níveis e o que cada um significa

Os cinco níveis formam uma escala ordenada. Os registros carregam um nível para que o filtro de cada handler possa descartar aqueles com os quais não se importa.

• DEBUG – rastreamento, contadores por quadro, despejos de estado interno. O nível mais baixo; o volume é alto.

• INFO – eventos operacionais normais. Wi-Fi conectado, um modelo carregado, o watchdog iniciado, um novo arquivo de log rotacionado.

• WARNING – algo inesperado, mas a aplicação tratou. Um quadro descartado, uma requisição de rede repetida.

• ERROR – uma operação falhou e a aplicação não conseguiu completá-la. Um arquivo de modelo ausente, uma escrita no cartão SD recusada.

• CRITICAL – a aplicação não pode continuar de jeito nenhum. Sem memória, montagem obrigatória ausente.

Um padrão importante a lembrar: o módulo logging da câmera inicia todo logger em WARNING. Registros em DEBUG e INFO são descartados silenciosamente, 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 funciona” é que a aplicação emitiu em INFO e o filtro padrão consumiu o registro.

Nota

O nível é o único filtro que o logging da câmera oferece. Não há objetos Filter para regras mais ricas por registro; se o nível de um registro passa, ele é emitido.

14.3.1.3. basicConfig: o início rápido

logging.basicConfig() configura o logger raiz em uma única chamada. Duas formas aparecem com mais frequência:

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

import logging

logging.basicConfig(level=logging.INFO)

Uma configuração de produção, tudo para um arquivo 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 no estilo %(field)s. Os campos que o formatter da câmera suporta:

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

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

• %(name)s – o nome do logger (veja a próxima seção).

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

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

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

basicConfig() não faz nada em chamadas subsequentes, a menos que force=True seja passado. Configure uma vez na inicialização; não o chame novamente para “trocar de destino” no meio da execução.

Nota

O logging da câmera não tem dictConfig() ou fileConfig(). A configuração é sempre programática – a convenção é um auxiliar setup_logging() chamado uma vez a partir do main.py.

14.3.1.4. Loggers nomeados por módulo

O código da aplicação não deve chamar os atalhos no nível do módulo (logging.info(), logging.warning() e assim por diante). Todos eles passam pelo logger raiz, e os registros de log resultantes carregam o nome root – inútil para dizer de onde o registro veio.

A convenção é um logger por módulo, nomeado segundo o 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 registro então carrega app.detector em %(name)s e a linha de log diz quem o emitiu.

O logging da câmera difere do CPython em um aspecto importante: o namespace de 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 propaga para app.detector. O mecanismo que funciona: um logger nomeado sem handlers próprios pega emprestados os handlers e o nível do logger raiz. É assim que uma única chamada basicConfig() na raiz configura cada chamada getLogger() em qualquer outro lugar da aplicação.

14.3.1.5. Formatação preguiçosa de argumentos com %

Escreva:

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

Não:

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

A forma de argumentos com % permite que o logger interpole os argumentos depois que o filtro de nível decidiu se deve emitir o registro. Uma chamada DEBUG filtrada em um laço quente não paga nada por sua string de formato. Uma f-string é avaliada primeiro, toda vez, antes mesmo de a chamada chegar ao logger.

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

14.3.1.6. Logging de exceções

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

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 seu bloco multilinhas Traceback (most recent call last):. Esta é a ferramenta certa para o tratamento de exceções de nível superior – capture, registre e siga em frente.

14.3.1.7. Múltiplos handlers

A divisão de produção mencionada no início – tudo para um arquivo em DEBUG, destaques para stderr em WARNING – são dois handlers conectados ao mesmo logger, cada um com 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 todo registro encontra. 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 registros são de fato emitidos para qual destino.

14.3.1.8. Rotação de arquivos de log

O logging da câmera não tem RotatingFileHandler ou TimedRotatingFileHandler. A rotação é tarefa da aplicação.

O padrão é manter o FileHandler atual em um lugar conhecido, trocá-lo por um novo quando o critério de rollover for atingido e deixar um caminho com data fornecer a fronteira natural do arquivo. Para um rollover por hora em /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 laço principal; a verificação do caminho é barata e a troca só acontece na fronteira da hora. A árvore de diretórios deve existir antes que FileHandler possa abrir o arquivo.

14.3.1.9. Flush em implantações sensíveis à energia

As escritas do FileHandler passam pelo buffering Python do objeto de arquivo subjacente. Uma perda de energia entre uma escrita e um flush perde os registros finais. Para implantações alimentadas por bateria ou do tipo “puxe o cabo”, chame flush() no stream do handler após registros críticos, ou em um timer.

Um pequeno auxiliar que faz flush de cada handler conectado ao logger raiz:

import logging

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

Chame flush_handlers() logo após um registro que a aplicação não pode se dar ao luxo de perder:

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

Para segurança em segundo plano, chame-o a partir do laço principal na cadência que equilibra a atualidade do log contra o desgaste do flash – uma vez por segundo costuma ser suficiente. Logger.critical() não dispara um flush por si só.

14.3.1.10. Diagnóstico de inicialização

Um log de campo sem contexto é quase inútil. Os primeiros registros em cada boot a frio devem identificar qual câmera, qual build está rodando e como a câmera chegou a este boot. Três fontes no dispositivo cobrem tudo isso entre si:

• omv – a versão do firmware OpenMV.

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

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

• os.listdir() em cada ponto de montagem – os sistemas de arquivos que realmente subiram.

Um auxiliar que coloca cada um deles nos primeiros registros 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 começa 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 após o início de cada arquivo de log, o operador conhece a unidade física, a linhagem do firmware, por que a câmera deu boot e qual armazenamento subiu. unique id é o número de série de silício programado de fábrica do MCU; ele é o mesmo entre reflashes e entre trocas de cartão SD. build é a tag git e a data da árvore de firmware a partir da qual a imagem foi compilada – o único campo que diz “este é exatamente o binário que foi entregue a esta unidade neste ponto no tempo.”

14.3.1.11. Juntando tudo

Uma configuração completa de logging de produção, organizada em um auxiliar que o main.py chama uma vez na inicialização:

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)

Então, no topo do main.py

from app.logging_setup import setup_logging, log_boot_diagnostics

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

Cada módulo em qualquer outro lugar da aplicação simplesmente faz:

import logging

log = logging.getLogger(__name__)

e obtém a saída configurada de graça – arquivo com detalhe completo, stream com avisos, registros nomeados, formatter com timestamp e um boot documentado a cada partida a frio.