Meu bot travou duas vezes e o log disse que ele tinha encerrado direitinho

Uma instância do bot MT5 que eu opero dentro do DT Dashboard travou duas vezes. Nas duas, o log terminou com a mesma sequência: início de shutdown, limpeza instrumento por instrumento, bar_store fechado com checkpoint de WAL, shutdown completo. É exatamente o que o processo escreve quando encerra de propósito no fim do pregão.

=== SHUTDOWN START ===
...
bar_store closed (WAL checkpointed)
=== SHUTDOWN COMPLETE ===

O traceback existia. Só que saiu pelo stderr, e o meu log capturava o stdout através de um redirecionador. A causa real, um timeout de lock do SQLite, apareceu quando a saída bruta do terminal foi colada numa conversa — não veio do arquivo que eu tinha montado justamente para esse tipo de situação.

Antes disso eu já tinha aberto uma ação para investigar um bug de virada de calendário na rotina de fim de dia. Era a hipótese que o log sustentava. Estava errada.

O problema não era o encerramento, era a classificação da saída

Nada da lógica de negócio estava quebrado. O que estava quebrado era a forma como o processo classificava a própria saída, ou melhor, a ausência de qualquer classificação.

SystemExit é levantada por um sys.exit(0) intencional e também por qualquer saída com código diferente de zero. Sozinha, ela não prova nada: não é sinônimo de crash nem de encerramento limpo. Quem lê o log recebe o resultado dessa ambiguidade já embrulhado em texto, sem nenhuma pista de qual dos dois casos gerou as linhas.

O erro contrário é igualmente fácil de escrever. Um handler de SIGTERM embrulhado num except BaseException captura o SystemExit(0) de um encerramento perfeitamente limpo e grava CRASH SHUTDOWN no arquivo. As duas direções, crash disfarçado de shutdown limpo e shutdown limpo disfarçado de crash, vêm da mesma raiz: ninguém decidiu em que categoria aquela saída cai antes de escrever a linha.

O que roda aqui é um processo longo, um SQLite e um log que via metade

O DT Dashboard é o motor de day trading que eu construí e opero. A decisão de trade é determinística e fica fora do loop de IA, a execução vai para a corretora, e a paridade entre backtest e produção é requisito de projeto. Nada disso tem relação com o bug, e é esse o ponto: a falha apareceu na operação, longe da parte que eu tinha cuidado de deixar previsível.

O componente afetado é uma instância do bot MT5, um processo de vida longa que abre de manhã e fecha depois do pregão. A persistência local é SQLite. A rotina de shutdown fecha o bar_store com checkpoint de WAL, e é essa a linha que, lida sozinha, passa a impressão de encerramento bem-comportado.

A parte frágil era o log. Um redirecionador levava o stdout para o arquivo e o stderr ficava de fora. Tudo que o Python escreve quando uma exceção sobe até o topo sem tratamento vai pelo stderr. O canal que carregava a única diferença entre os dois cenários era exatamente o que não estava sendo gravado.

Logar mais não resolveria nada

Duas falhas seguidas produziram um arquivo igual ao de um encerramento planejado. Não era um log incompleto no sentido de faltar detalhe: as linhas estavam todas lá, na ordem certa, com o conteúdo certo. Faltava o outro canal inteiro.

Enquanto a causa real não apareceu, a investigação seguiu a pista do calendário, a única que o arquivo oferecia. Um timeout de lock do SQLite não tem relação nenhuma com virada de data, e mesmo assim foi o rastro de fim de dia que ditou a hipótese. Log que descreve o cenário errado é pior do que log ausente, porque ele dirige o diagnóstico.

A conclusão tentadora seria aumentar o volume: mais linha, mais detalhe, nível de debug ligado. O contra-exemplo do except BaseException que grava CRASH SHUTDOWN para uma saída limpa mostra por que isso não basta. Aquele log é volumoso, é imediato e está errado. O que faltava nos dois casos não era quantidade de texto, era decidir a categoria antes de escrever a primeira linha.

Classifique o motivo da saída em três categorias

O padrão que ficou aqui tem três vias. SystemExit com código 0 é encerramento intencional e não merece barulho nenhum. SystemExit com código diferente de zero vira WARNING, com o código gravado junto. Qualquer outra BaseException é crash de verdade e vira CRITICAL.

try:
    main()
except SystemExit as exc:
    if exc.code in (0, None):
        pass                                    # encerramento intencional
    else:
        log.warning("saída com código %s", exc.code)
    raise
except BaseException:
    log.critical("crash não tratado", exc_info=True)
    raise

Recomendo esse desenho, e o preço dele aparece em todo lugar que captura exceção perto do topo. Cada handler de sinal e cada except de nível alto passa a precisar da mesma distinção entre SystemExit(0), SystemExit com código diferente de zero e o resto de BaseException. Escrever um except BaseException genérico sem essa distinção é mais rápido, e é justamente o que produz o erro inverso: um encerramento limpo marcado como crash, o mesmo estrago de diagnóstico com o sinal trocado.

Todo shutdown precisa dizer quem pediu

A segunda parte do conserto é mais barata e eu deveria ter feito antes: mandar stdout e stderr para o mesmo log. Uma linha de configuração. Sem ela, o traceback simplesmente não existe do ponto de vista de quem só tem o arquivo. Quem preferir não mexer no redirecionamento pode instalar um sys.excepthook apontando para o mesmo logger, com efeito prático equivalente para quem lê.

A terceira parte muda o que se grava, não onde. Todo shutdown passa a carregar um campo explícito de gatilho: fim de dia, sinal recebido, exceção não tratada. Deduzir o motivo a partir da sequência de linhas foi o que me levou para o lado errado duas vezes seguidas. Um campo obriga quem escreveu o caminho de saída a declarar qual caminho é.

Um log limpo só prova que o log estava olhando para um canal

Um encerramento de aparência limpa no arquivo não é evidência de encerramento limpo no processo. É evidência de que o log enxerga um dos canais de saída e não enxerga o outro. Enquanto essa diferença não estiver explícita, toda leitura do arquivo é um palpite com cara de fato.

A pergunta que eu faço hoje, antes de confiar em qualquer linha de encerramento, não é o que o log diz que aconteceu. É para qual das três categorias aquele código de saída aponta, e se o arquivo que estou lendo tem acesso ao canal onde a resposta mora.