Um e-mail de lembrete, três cópias, com sete segundos de diferença
Um e-mail de lembrete agendado chegou três vezes na nossa caixa de entrada na mesma manhã: uma vez às 4:14 e duas vezes às 10:06. A primeira cópia chegou no horário. As outras duas, não.
O que mudou
Por dois anos e meio, a tarefa por trás desse e-mail rodou exatamente uma vez por dia. Então, a partir de 17/09, começaram a aparecer dias com execuções extras: os dias 17, 22, 23, 24, 25, 26, 28 e 29, e depois 01/10. Antes disso, já tínhamos contado 161 envios duplicados.
Nada nesse histórico parecia uma única manhã ruim. Parecia um hábito novo.
A proteção que já tínhamos
Em 22/09 e 23/09 adicionamos uma proteção, depois de duplicatas anteriores. Ela impede que duas execuções aconteçam ao mesmo tempo.
Em 01/10 o problema foi uma segunda execução começando depois da primeira. A proteção nunca foi feita para impedir isso, então não fez nada aqui. Tínhamos corrigido um problema real, só que não o que estava diante de nós.
Por que só um e-mail foi triplicado
A tarefa também tenta não enviar e-mail para a mesma pessoa duas vezes no mesmo dia. Ela verifica se aquela pessoa já recebeu a mensagem do dia.
Esse lembrete vai para um destinatário fictício, “Support Staff”, sem nenhum cadastro de pessoa por trás. Sem uma pessoa para consultar, a verificação nunca se aplica, e o lembrete saiu de novo a cada execução da tarefa.
De onde vieram as execuções extras
O log de requisições recebidas do servidor mostrou duas, às 10:05:53 e às 10:06:00. São sete segundos de diferença, e cada uma iniciou de novo a tarefa da madrugada. Essa tarefa envia e-mails de verdade.
O log não conseguiu dizer qual ferramenta as fez. Uma anotação nos nossos registros diz que uma aba restaurada do navegador executou a tarefa de novo e reenviou e-mails em 01/10.
Os números, lado a lado
Chegaram três cópias de um e-mail. A primeira veio às 4:14 e era a agendada. As duas das 10:06 foram repetições.
Duas requisições chegaram com sete segundos de diferença, às 10:05:53 e às 10:06:00, e cada uma iniciou a tarefa de novo. Os 161 envios duplicados foram contados antes, antes de 01/10. O histórico de execuções mostra uma execução por dia durante dois anos e meio, e dias com mais de uma execução de 17/09 a 01/10.
A proteção entrou em 22/09 e 23/09, e os dias com execuções extras continuaram aparecendo: 24, 25, 26, 28 e 29, e também 01/10. Uma proteção contra execuções simultâneas não tinha como mudar essa contagem, porque as execuções extras eram de outro tipo.
O que nos resta
Um e-mail, três cópias, duas requisições com sete segundos de diferença e uma proteção voltada para o tipo errado de repetição. O lembrete para o destinatário fictício foi triplicado porque era o único que a verificação de “já enviado” não conseguia enxergar.