Dois erros na fila agrupados como x2 no envio dos alertas adiados

A mensagem das 17:00 dizia que nosso job de coleta de dados tinha falhado duas vezes durante a noite (código de saída 2, cerca de 93 segundos por execução) e não tinha se recuperado desde então. A última execução do job, às 15:51, tinha terminado sem problemas.

O job coleta os dados da nossa infraestrutura a cada seis horas, e um agente conferiu isso para mim. A tarefa agendada aparecia como Ready, com último resultado 0. Os dados tinham cerca de 75 minutos, o que é normal para um job de seis horas. Ou seja, o alerta estava errado sobre “não se recuperou”. Também estava errado sobre “durante a noite”. As falhas aconteceram de dia: das 06:41 às 12:41, a conexão com o nosso servidor web ficou dando timeout, e às 15:48 uma execução falhou de vez. Uma nova tentativa três minutos depois funcionou.

A correção que errou o alvo

Na execução das 15:48, as conexões SSH deram timeout e o push então esbarrou em uma falha de consulta DNS, então desistiu depois de 93 segundos. A hipótese do agente era que o PC tinha ficado sem rede por um momento. Ele disse isso claramente como hipótese, já que ninguém registrou o estado da rede às 15:48. Ele também encontrou um bug no próprio alerta (Ler em inglês) e propôs duas correções: parar de tratar a perda total de rede como uma falha que merece alerta, e fazer o alerta checar a última execução antes de dizer “não se recuperou”.

Seguimos com as duas. O passo de push ganhou seu próprio código de saída 6 para erros de rede, e o script de agendamento passou a registrar isso como “push ignorado” em vez de falha. Os testes direcionados passaram (138). A suíte rápida completa rodou 15.276 testes e um falhou, um problema conhecido de commits anteriores naquele dia. Fizemos o commit e o push.

Depois rastreamos a mensagem das 17:00. O registro mostrou que ela veio da fila onde os alertas adiados esperam para ser enviados juntos. Havia dois erros nessa fila: um de 534 segundos e outro de 93 segundos. O envio agrupou os dois como uma única série, usou o título mais recente e acrescentou “(x2)”. O sucesso das 15:51 nunca foi escrito na fila. O envio já sabia descartar uma falha que tivesse uma entrada “recovered” correspondente, mas nada jamais escrevia essa entrada.

O veredito do próprio agente sobre a nossa correção foi que ela “consertou o caminho errado”. A mudança de rede não teria impedido aquela mensagem de qualquer jeito, porque as conexões com o servidor também tinham falhado naquela execução. A correção funcionou. O agente rodou o script real a partir de uma cópia temporária com etapas simuladas, e ele saiu com 0 para um endpoint inacessível e com 2 para um erro grave. Só que não era isso que enviava a mensagem. Gastei uma rodada completa de testes e um push nisso antes de checar o caminho que a mensagem realmente percorria.

A correção certeira

Quando qualquer job agendado volta de falhando para verde, agora ele escreve uma entrada “recovered” na fila de alertas, com o mesmo nome da falha. Aí o envio descarta a série inteira. Isso vale para todos os jobs agendados, não só este, e só escreve quando existe de fato uma falha esperando na fila, então um job saudável não adiciona nada.

Quatro testes novos cobrem isso:

• Falha, falha, recuperação não deixa nada para reportar.
• Falha sem recuperação ainda reporta “(x2)”.
• Nenhuma escrita acontece quando não há nada na fila.
• Um job recuperado não gera nenhum alerta.

A suíte completa terminou com 15.293 testes passando e 2 falhando, e nenhuma das falhas veio dessa mudança. Uma era o problema conhecido. A outra era um teste do registro de jobs que passa quando roda sozinho, em um arquivo onde outra sessão tinha edições não commitadas.

O que já foi visto e o que não foi

Na manhã seguinte, o agente informou que nada tinha me avisado durante a noite. A execução das 18:41 tinha dado timeout, mas rodou antes da correção de nova tentativa e foi tratada como primeira falha, então nunca gerou alerta. A execução das 00:41 foi limpa, com 141 segundos, e foi registrada como recuperada.

Uma segunda mudança, uma única nova tentativa após uma pausa de 30 segundos quando a conexão com o servidor trava, nunca precisou ser acionada. Nem ela nem a entrada “recovered” na fila foram vistas em uma trava real. As duas só foram testadas em execuções de teste temporárias, não em uma execução real.

A mensagem das 17:00 era uma falha antiga reportada depois que o job já tinha se recuperado às 15:51, e ela ficou na fila porque nada registrou a recuperação. O primeiro ciclo real de falha seguida de recuperação vai mostrar se a entrada “recovered” esvazia a fila.