Como uma edição de título de PR quebrou minha pipeline por algumas horas · aguillarops

Se liga nessa situação que rolou comigo há algum tempo... dia tranquilo até que a pipeline caiu "do nada" (sempre assim né? xD). O erro apontava para a VM, mas a causa real estava escondida em três mudanças de uma PR que ninguém tinha percebido.

O problema

Um dev me pingou: "Tá dando erro estranho na pipe, olha aí?" Parei o que eu estava fazendo e fui investigar.

Acessei o build e de primeira já verifiquei que falhou na etapa de instalação do Angular. Isso já me deu o palpite de que podia ser um problema na VM, pois essa pipeline usava um agente self-hosted (para contexto, nessa situação estamos falando de Azure DevOps e Bitbucket).

A investigação

Abri a task de instalação do Angular e a primeira mensagem que vi foi: ENOTEMPTY: directory not empty, rename '.../cli' -> '.../cli-Xuqet0PR'

Exatamente desse jeito, inclusive vou deixar o output aqui para ficar mais fácil de entender:

2000-00-00T13:00:57Z [command] npm install -g @angular/cli@XX.X.1
2000-00-00T13:01:15Z npm error code ENOTEMPTY
2000-00-00T13:01:15Z npm error syscall rename
2000-00-00T13:01:15Z npm error path   .../node_modules/@angular/cli
2000-00-00T13:01:15Z npm error dest   .../node_modules/@angular/.cli-Xuqet0PR
2000-00-00T13:01:15Z npm error errno  -39
2000-00-00T13:01:15Z npm error ENOTEMPTY: directory not empty, rename '.../cli' -> '.../cli-Xuqet0PR'
2000-00-00T13:01:16Z ##[error]Error: Npm failed with return code: 217

De primeira dá para notar que o npm tentou renomear uma pasta e não conseguiu... como eu não sabia a fundo como funcionava o processo de instalação, dei uma pesquisada rápida e descobri que ao instalar o Angular, o npm tenta renomear o diretório atual (cli) para um nome temporário (.cli-Xuqet0PR) e se der certo esse rename, ele faz a instalação do Angular na pasta /cli, esse processo é basicamente para liberar o caminho no diretório antes de escrever a nova versão. O problema é que de alguma forma já existia um temporário lá e já estava com conteúdo, então o rename falhou, o processo morreu, o build foi junto.

Agora a grande pergunta não era o que quebrou. Era o porquê esse diretório temporário estava ali.

Aqui começa a investigação de verdade... Fui na lista de builds no Azure DevOps, procurei o último lote de builds com sucesso e identifiquei o momento exato em que as falhas começaram. Abri o build correspondente, acessei a PR em andamento e encontrei uma alteração no YAML da pipeline: o dev tinha removido a etapa de instalação do Angular.

# trecho removido da pipeline pelo dev
- task: Npm@1
  inputs:
    command: 'custom'
    customCommand: 'install -g @angular/cli@XX.X.1'
  displayName: 'Install Angular CLI'

Esse tipo de mudança é estranho, mas como o dev é novato e está começando, eu relevei e entendi que talvez ele não soube como resolver o problema do ENOTEMPTY, e usou IA para resolver mas não passou contexto suficiente.

Antes de continuar investigando, preciso liberar o fluxo...

Pipeline parada é prioridade máxima. Como DevOps, minha função é acelerar o ciclo de entrega do time, e build travado é o oposto disso.

Dei um change request na PR, chamei o dev no privado para avisar sobre a alteração do YAML e comuniquei ao time no grupo que eu já estava verificando o problema com a pipeline. Com isso feito, ativei a VPN e acessei a VM via SSH.

Tava lá. O diretório temporário abandonado, exatamente como o erro dizia.

Como eu falei anteriormente, o fluxo do npm é renomear a pasta /cli para um nome temporário e processar o pacote. Se o processo é interrompido no meio, o diretório temporário fica para trás. Na próxima execução, quando o npm tenta renomear de novo, encontra um diretório não vazio e explode com ENOTEMPTY.

Para resolver eu simplesmente apaguei as pastas...

Rodei a pipeline de novo e passou. Problema resolvido, avisei o time no grupo que a pipe estava liberada. Agora preciso entender a causa raiz.

Quem interrompeu o processo?

Um princípio que carrego na minha carreira é: nada acontece do nada.

De cara, minha dedução foi que o problema estava na alteração do YAML que o novato fez. Mas fui checar o histórico da PR e notei que ele só removeu a instalação do Angular no terceiro commit. O erro já estava quebrando a pipeline antes disso.

Fui ver nos logs do agente na VM (aqui aprendi na marra algo que eu não tinha prestado atenção antes: a VM estava em UTC e eu estava em UTC-3) e os builds que via no Azure DevOps como falho às 08:53 correspondia a 11:53 na VM. Isso importa na hora de correlacionar logs, demorei uns minutos para lembrar disso xD

$ cat /home/vm-admin/myagent/_diag/Agent_*.log | grep "Running job"

[2000-00-00 01:00:39Z] Running job: Build Frontend
[2000-00-00 01:03:25Z] Running job: Build Frontend
[2000-00-00 01:05:58Z] Running job: Build Frontend
[2000-00-00 02:00:20Z] Running job: Job
[2000-00-00 02:10:37Z] Running job: Job
[2000-00-00 02:20:45Z] Running job: Job
[2000-00-00 11:49:37Z] Running job: Job  ← suspeito
[2000-00-00 11:50:35Z] Running job: Job  ← suspeito
[2000-00-00 11:53:12Z] Running job: Job  ← falhou

Ao ler o log, fui por eliminação... como eu sabia que tinha pipe que rodou de madrugada por schedule e o build que eu procurava era das 11:53, sobraram dois jobs que não apareciam na interface do Azure DevOps. Foi só nesse momento que notei o número do build que havia falhado: #20000000.3. Tava na minha cara o tempo todo. O sufixo (3) já indicava que era a terceira execução do dia. Não vi antes... mas acontece xD.

Lendo os logs dos Workers

Bom, agora que eu sei que tem dois builds que foram apagados e não aparecem na interface, e tenho informações de horário, vou até os logs de Workers. Lá é um arquivo por build, e o melhor, com o horário de início em UTC no próprio nome do arquivo.

$ ls /home/vm-admin/myagent/_diag/
Worker_20000000-114938-utc.log
Worker_20000000-115038-utc.log

Achei esses dois logs, e os minutos batem com o log que analisei anteriormente... Só podiam ser esses.

Log era enorme, então copiei, joguei para a IA e perguntei: "o que aconteceu com esse build? Foi deletado, cancelado, crashou?"

A IA respondeu:

Pipeline:     [empresa] - Dashboard (Staging)
Build:        20000000.1 | Motivo: PullRequest
Resultado:    Canceled
Momento:      durante o passo Cache npm
Consequência: todos os passos seguintes foram skipped

Nesse log não aparece quem cancelou.
O log mostra apenas que o agente recebeu um sinal de cancelamento.

Opa, agora sei que os dois builds foram cancelados. Não foi crash, não foi a VM. Receberam um sinal externo. Mas de quem?

O culpado

Builds cancelados podem não aparecer na interface gráfica do Azure DevOps, mas da API não tem como, ela expõe isso. Montei a URL com ajuda de IA, já autenticado no portal, e o JSON retornou:

"deletedBy": "Microsoft.VisualStudio.Services.TFS",
"deletedReason": "The build was manually deleted.",
"pr.autoCancel": "true"

Aí o culpado... Não foi o dev. Não foi ninguém do time. Foi o próprio Azure DevOps, pelo pr.autoCancel que cancela automaticamente qualquer build em andamento toda vez que a PR é atualizada.

Fui até a PR no Bitbucket para tirar a prova real, e reconstruí a sequência, olha que dahora:

Dev abriu a PR → build 20000000.1 inicia
Dev marcou como DRAFT → auto-cancel derruba o build .1 → build 20000000.2 inicia
Dev editou o título da PR → auto-cancel derruba o build .2 durante o npm install → .cli-Xuqet0PR fica incompleto na VM → build 20000000.3 inicia → ENOTEMPTY → todos os builds seguintes quebram.

Insight: Olha que massa, eu realmente não sabia que editar o título de uma PR também disparava um novo build. E na verdade qualquer atualização na PR com um build em andamento aciona o pr.autoCancel. Se o cancelamento ocorre no meio de um processo com estado em disco, como o npm install, o rastro fica na VM e quebra todos os builds seguintes até alguém limpar manualmente.

Caraca, fiquei de cara quando entendi o problema pela raiz... e qual foi o aprendizado? Só crie a PR quando ela estiver 100% pronta. xD

Obviamente que esse problema não podemos colocar na conta do novato... nem eu sabia que podia dar problema... mas uma boa prática é você abrir a PR tendo a certeza que ela está pronta... ou já abrir ela como draft.

E é isso, basicamente essas 3 mudanças rápidas que o dev fez (literalmente uma em seguida da outra) foi matando os builds com o autocancel e na última alteração deu ruim.

Bom, isso ocorreu há um tempo atrás... mas conhecimento nunca ocupa espaço, então ficou de aprendizado haha

Já tinha visto esse B.O antes? Conta aí

Ficou em aberto

Por que o npm não faz cleanup ao receber o sinal de cancelamento? Dependendo de como o sinal é entregue e em que ponto do rename o processo estava, o cleanup pode não acontecer. Não investiguei a fundo.

O pr.autoCancel tem configuração granular? Não verifiquei se é possível desativar por pipeline específica ou se é global.

Dá para tornar o step idempotente? Uma limpeza antes do npm install -g eliminaria o problema independentemente de cancelamentos futuros:

- script: |
    rm -rf $(node_modules_path)/@angular/cli
    rm -rf $(node_modules_path)/@angular/.cli-*
  displayName: 'Clean Angular'

Não implementei ainda. Não sei se gera efeito colateral em builds paralelos no mesmo agente.

Referências

Vinicius Aguilar — DevOps Engineer