A queda na toca do coelho: Uma história sobre um erro de reinicialização do varnish — parte 1

ghostinushanka, clicando nos botões por 20 minutos anteriores, como se sua vida dependesse disso, ele se vira para mim com uma expressão semi-selvagem nos olhos e um sorriso astuto — 'Cara, acho que entendi.'

‘Olha aqui,’ ele diz, apontando para um dos símbolos na tela — ‘Aposto o meu chapéu vermelho que se adicionarmos aqui o que acabei de te enviar’ — apontando para outra parte do código — ‘a mensagem de erro já não será exibida.’

Um pouco perplexo e cansado, eu modifico a expressão sed na qual já estávamos trabalhando há algum tempo, salvo o arquivo e executo systemctl varnish reload. A mensagem de erro desapareceu…

‘Os e-mails que troquei com o candidato,’ continuou meu colega, enquanto seu sorriso se transformava em um sorriso genuíno cheio de alegria, ‘de repente percebi que era exatamente o mesmo problema!’

Como tudo começou

Este artigo pressupõe compreensão dos princípios de funcionamento do bash, awk, sed e systemd. O conhecimento de varnish é benéfico, mas não é obrigatório.
Os timestamps nos snippets foram alterados.
Escrito em conjunto com ghostinushanka.
Este texto é uma tradução do original publicado em inglês há duas semanas; a tradução boikoden.

O sol brilha através das grandes janelas em mais uma manhã quente de outono, uma xícara de café recém-preparado repousa ao lado do teclado, a sinfonia de sons favorita toca nos fones de ouvido, abafando o clique das teclas mecânicas, e a primeira entrada na lista de tickets do backlog no quadro Kanban brilha de forma brincalhona com o título crucial 'Investigar varnishreload sh: echo: I/O error no staging'. Quando se trata de varnish, não há espaço para erros, mesmo que estes não resultem em problemas como neste caso.

Para aqueles que não estão familiarizados com varnishreload, é um simples script shell usado para recarregar a configuração do varnish — também chamado de VCL.

Como o título do ticket sugere, houve um erro em um dos servidores de staging. Como eu tinha certeza de que a roteirização do Varnish no staging estava funcionando corretamente, presumi que se tratava de um erro menor. Assim, apenas uma mensagem que havia caído em um thread de saída já fechado. Peguei o ticket para mim, confiante de que o marcaria como resolvido em menos de 30 minutos, me elogiando por limpar a board de mais um lixo e retornando a tarefas mais importantes.

Colisão com a parede a 200 km/h

Ao abrir o arquivo varnishreload, em um dos servidores executando Debian Stretch, encontrei um script shell com menos de 200 linhas.

Depois de percorrer o script, não notei nada que poderia representar problemas ao ser executado repetidamente diretamente do terminal.

No fim das contas, é um staging; mesmo que ele quebre, ninguém irá reclamar, bem… não muitas pessoas. Executando o script e observando o que sai no terminal, percebi que já não apareciam erros.

Mais algumas execuções para confirmar que não consigo reproduzir o erro sem qualquer esforço adicional, e começo a pensar em como modificar o script para que ele realmente apresente um erro.

Talvez eu deva redirecionar o STDOUT (usando > &-)? Ou STDERR? Nenhum dos dois acabou funcionando.

Obviamente, o systemd de alguma forma altera o ambiente de execução, mas como e por quê?
Eu ligo o vim e edito varnishreload, adicionando set -x logo abaixo do shebang, na esperança de que a saída de depuração do script ilumine um pouco a situação.

O arquivo foi ajustado, então eu reinicio o Varnish e vejo que a mudança quebrou tudo… A saída está uma bagunça total, com toneladas de código semelhantes ao C. Nem mesmo a rolagem no terminal é suficiente para descobrir onde tudo começa. Estou completamente confuso. O modo de depuração pode afetar o funcionamento dos programas executados no script? Não, besteira. Bug no shell? Vários cenários possíveis passam pela minha cabeça como baratas correndo em direções diferentes. Minha xícara de café está vazia, uma rápida viagem à cozinha para reabastecer e… vamos lá. Abro o script e olho para o shebang: #!/bin/sh.

/bin/sh — é apenas um symlink para o bash, então o script é interpretado em modo compatível com POSIX, certo? Não é bem assim! O shell padrão no Debian é o dash, e é isso que referencia /bin/sh.

# ls -l /bin/sh
lrwxrwxrwx 1 root root 4 Jan 24  2017 /bin/sh -> dash

Por experiência, mudei o shebang para #!/bin/bash, removi set -x e tentei novamente. Finalmente, na próxima reinicialização do Varnish, apareceu um erro decente na saída:

Jan 01 12:00:00 hostname varnishreload[32604]: /usr/sbin/varnishreload: line 124: echo: write error: Broken pipe
Jan 01 12:00:00 hostname varnishreload[32604]: VCL 'reload_20190101_120000_32604' compilado

Linha 124, aqui está!

114 find_vcl_file() {
115         VCL_SHOW=$(varnishadm vcl.show -v "$VCL_NAME" 2>&1) || :
116         VCL_FILE=$(
117                 echo "$VCL_SHOW" |
118                 awk '$1 == "//" && $2 == "VCL.SHOW" {print; exit}' | {
119                         # toda essa cerimônia para lidar com espaços em BRANCO no FILE
120                         read -r DELIM VCL_SHOW INDEX SIZE FILE
121                         echo "$FILE"
122                 }
123         ) || :
124
125         if [ -z "$VCL_FILE" ]
126         then
127                 echo "$VCL_SHOW" >&2
128                 fail "falha ao obter o nome do arquivo VCL"
129         fi
130
131         echo "$VCL_FILE"
132 }

Mas, como se viu, a linha 124 é bastante vazia e não apresenta interesse. Eu só poderia supor que o erro surgiu como parte de um multi-line que começa na linha 116.
O que é, no final, gravado na variável VCL_FILE como resultado da execução do sub-shell mencionado acima?

No início, ele envia o conteúdo da variável VLC_SHOW, criada na linha 115, para o próximo comando através do pipe. E o que acontece lá?

Primeiro, é utilizado varnishadm, que faz parte do pacote de instalação do Varnish, para configurar o Varnish sem reiniciar.

O subcomando vcl.show -v é usado para exibir toda a configuração VCL, especificada em ${VCL_NAME}, no STDOUT.

Para exibir a configuração VCL atual ativa, bem como várias versões anteriores das configurações de roteamento do Varnish que ainda estão na memória, pode-se usar o comando varnishadm vcl.list, cuja saída será semelhante ao abaixo:

discarded   cold/busy       1 reload_20190101_120000_11903
discarded   cold/busy       2 reload_20190101_120000_12068
discarded   cold/busy       16 reload_20190101_120000_12259
discarded   cold/busy       16 reload_20190101_120000_12299
discarded   cold/busy       28 reload_20190101_120000_12357
active      auto/warm       32 reload_20190101_120000_12397
available   auto/warm       0 reload_20190101_120000_12587

O valor da variável ${VCL_NAME} é definido em outra parte do script varnishreload como o nome do VCL ativo no momento, se existir. Neste caso, será “reload_20190101_120000_12397”.

Ótimo, a variável ${VCL_SHOW} contém a configuração completa para o Varnish, enquanto isso é claro. Agora, finalmente entendi por que a saída do dash com set -x estava tão corrompida — ela incluía o conteúdo da configuração resultante.

É importante entender que a configuração completa do VCL muitas vezes pode ser mesclada a partir de vários arquivos. Comentários no estilo C são usados para indicar onde um arquivo de configuração foi incluído em outro, e é exatamente isso que toda a linha do trecho de código abaixo descreve.
A sintaxe dos comentários que descrevem os arquivos incluídos tem o seguinte formato:

// VCL.SHOW <NUM> <NUM> <FILENAME>

Os números neste contexto não são importantes, o que nos interessa é o nome do arquivo.

O que está acontecendo no bloco de comandos, começando na linha 116?
Vamos esclarecer.
O comando consiste em quatro partes:

1. Simples echo, que exibe o valor da variável ${VCL_SHOW}

   echo "$VCL_SHOW"

2. awk, que procura uma linha (registro) onde o primeiro campo, após a divisão do texto, será “//”, e o segundo será “VCL.SHOW”.
   Awk imprimirá a primeira linha que corresponder a esses padrões e, em seguida, interromperá o processamento imediatamente.

   awk '$1 == "//" && $2 == "VCL.SHOW" {print; exit}'

3. Um bloco de código que salva em cinco variáveis os valores dos campos, separados por espaço. A quinta variável FILE recebe o restante da linha. Finalmente, o último echo imprime o conteúdo da variável ${FILE}.

   { read -r DELIM VCL_SHOW INDEX SIZE FILE; echo "$FILE" }

4. Como todos os passos de 1 a 3 estão encapsulados em um sub-shell, a saída do valor $FILE será registrada na variável VCL_FILE.

Como indicado pelo comentário na linha 119, isso serve a um único objetivo: tratar de forma confiável casos em que o VCL fará referência a arquivos com espaços no nome.

Eu comentei a lógica de processamento original para ${VCL_FILE} e tentei alterar a sequência de comandos, mas isso não levou a nada. Tudo funcionava perfeitamente, mas ao iniciar o serviço, gerava um erro.

Parece que o erro simplesmente não se reproduz ao executar o script manualmente, enquanto os supostos 30 minutos já passaram seis vezes e, além disso, surgiu uma tarefa mais prioritária, adiando as outras. O restante da semana foi preenchido com várias tarefas e foi apenas um pouco aliviado com uma apresentação sobre sed e uma entrevista com um candidato. O problema com o erro em varnishreload foi inexoravelmente perdido nas areias do tempo.

Seu chamado conhecimento do sed… na verdade… é uma porcaria

Na próxima semana, tive um dia bastante livre, então decidi retomar este ticket. Esperava que algum processo de fundo no meu cérebro estivesse buscando uma solução para esse problema todo esse tempo e que desta vez eu realmente entenderia do que se tratava.

Como da última vez uma simples alteração no código não resolveu, decidi reescrevê-lo a partir da linha 116. De qualquer forma, o código existente estava confuso. E não havia absolutamente nenhuma necessidade de usar write.

Olhando para o erro mais uma vez:
sh: echo: broken pipe — nesta linha de comando, echo aparece em dois lugares, mas suspeito que o primeiro seja o culpado mais provável (ou pelo menos um cúmplice). Awk também não parece confiável. E se é realmente isso awk | {read; echo} essa construção está causando todos esses problemas, por que não substituí-la? Esse comando de uma linha não utiliza todas as possibilidades do awk, além de ter esse extra write como sobrecarga.

Como na semana passada houve uma apresentação sobre sed, eu queria experimentar minhas habilidades recém-adquiridas e simplificar echo | awk | { read; echo} para algo mais claro echo | sed. Embora definitivamente não seja a melhor abordagem para identificar o erro, pensei que ao menos tentaria meu sed-fu e quem sabe aprendesse algo novo sobre o problema. Ao longo do caminho, pedi ajuda ao meu colega, autor da apresentação sobre sed, para criar um script sed mais eficiente.

Enviei o conteúdo de varnishadm vcl.show -v "$VCL_NAME" para um arquivo, assim poderia me concentrar em escrever o script sed sem me preocupar com reinicializações de serviço.

Uma breve descrição de como o sed processa os dados de entrada pode ser encontrada em seu guia GNU. Nos códigos fonte do sed, o símbolo n está claramente definido como delimitador de linhas.

Após várias tentativas e com as recomendações do meu colega, escrevemos um script sed que produzia o mesmo resultado que toda a linha original 116.

Abaixo está um exemplo do arquivo de dados de entrada:

> cat vcl-example.vcl
Text
// VCL.SHOW 0 1578 file com 3 spaces.vcl
Mais texto
// VCL.SHOW 0 1578 file.vcl
Ainda mais texto
// VCL.SHOW 0 1578 file com dois espaços.vcl
Texto final

Pode não ser evidente a partir da descrição acima, mas estamos interessadas apenas no primeiro comentário // VCL.SHOW, sendo que pode haver vários nos dados de entrada. É por isso que o awk original termina sua execução após a primeira correspondência.

# шаг первый, вывести только строки с комментариями
# используя возможности sed, определяется символ-разделитель с помощью конструкции '#' вместо обычно используемого '/', за счёт этого не придётся экранировать косые в искомом комментарии
# определяется регулярное выражение “// VCL.SHOW”, для поиска строк с определенным шаблоном
# флаг -n позаботится о том, чтобы sed не выводил все входные данные, как он это делает по умолчанию (см. ссылку выше)
# -E позволяет использовать расширенные регулярные выражения
> cat vcl-processor-1.sed
#// VCL.SHOW#p
> sed -En -f vcl-processor-1.sed vcl-example.vcl
// VCL.SHOW 0 1578 file with 3 spaces.vcl
// VCL.SHOW 0 1578 file.vcl
// VCL.SHOW 0 1578 file with TWOspaces.vcl

# шаг второй, вывести только имя файла
# используя команду “substitute”, с группами внутри регулярных выражений, отображается только нужная группa
# и это делается только для совпадений, ранее описанного поиска
> cat vcl-processor-2.sed
#// VCL.SHOW# {
    s#.* [0-9]+ [0-9]+ (.*)$#1#
    p
}
> sed -En -f vcl-processor-2.sed vcl-example.vcl
file with 3 spaces.vcl
file.vcl
file with TWOspaces.vcl

# шаг третий, получить только первый из результатов
# как и в случае с awk, добавляется немедленное завершения после печати первого найденного совпадения
> cat vcl-processor-3.sed
#// VCL.SHOW# {
    s#.* [0-9]+ [0-9]+ (.*)$#1#
    p
    q
}
> sed -En -f vcl-processor-3.sed vcl-example.vcl
file with 3 spaces.vcl

# шаг четвертый, схлопнуть всё в однострочник, используя двоеточия для разделения команд
> sed -En -e '#// VCL.SHOW#{s#.* [0-9]+ [0-9]+ (.*)$#1#p;q;}' vcl-example.vcl
file with 3 spaces.vcl

Então, o conteúdo do script varnishreload parecerá algo assim:

VCL_FILE="$(echo "$VCL_SHOW" | sed -En '#// VCL.SHOW#{s#.*[0-9]+ [0-9]+ (.*)$#1#p;q;};')"

A lógica acima pode ser resumida da seguinte forma:
Se a string corresponder à expressão regular // VCL.SHOW, então consuma avidamente o texto que inclui ambos os números nessa string e armazene tudo o que sobrar após essa operação. Retorne o valor armazenado e termine o programa.

Simples, não é?

Ficamos satisfeitos com o script sed e com o fato de que ele substituiu todo o código original. Todos os meus testes deram os resultados desejados, então eu mudei “varnishreload” no servidor e reiniciei systemctl reload varnish. Um erro miserável echo: erro de gravação: Broken pipe ríamos novamente na cara de nós mesmos. O cursor piscante aguardava um novo comando na escuridão do terminal...

Fonte: habr.com