Caindo na toca do coelho: a história de uma falha na recarga do verniz - Parte 1

fantasmainushanka, tendo martelado botões nos últimos 20 minutos como se sua vida dependesse disso, se vira para mim com um olhar semi-selvagem e um sorriso malicioso - “Cara, acho que entendi”.

“Olha aqui”, diz ele, apontando para um dos símbolos na tela, “aposto meu chapéu vermelho que se adicionarmos aqui o que acabei de enviar para você”, apontando para outra seção do código, “o erro não será mais será exibido."

Um pouco confuso e cansado, modifico a expressão sed na qual estamos 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 de alegria, “de repente me dei conta de que este é exatamente o mesmo problema!”

Como tudo começou

O artigo pressupõe uma compreensão de como bash, awk, sed e systemd funcionam. Conhecimento de verniz é preferível, mas não obrigatório.
Os carimbos de data e hora nos snippets foram alterados.
Escrito com fantasmainushanka.
Este texto é uma tradução do original publicado em inglês há duas semanas; tradução boikoden.

O sol brilha pelas janelas panorâmicas em outra manhã quente de outono, uma xícara de bebida recém-preparada rica em cafeína repousa longe do teclado, sua sinfonia de sons favorita soa em seus fones de ouvido, abafando o farfalhar dos teclados mecânicos, e a primeira entrada na lista de tickets de pendências no quadro Kanban brilha divertidamente com o título fatídico “Investigar vernizreload” sh: echo: erro de I/O no teste” (Investigar “varnishreload sh: echo: erro de I/O” no teste). Quando se trata de verniz, há e não pode haver margem para erros, mesmo que não resultem em problemas como neste caso.

Para quem não está familiarizado vernizreload, este é um script de shell simples usado para recarregar a configuração verniz - também chamado de VCL.

Como o título do ticket sugere, o erro ocorreu em um dos servidores do palco e, como eu tinha certeza de que o roteamento do verniz no palco estava funcionando corretamente, presumi que seria um erro menor. Então, apenas uma mensagem que acabou em um fluxo de saída já fechado. Pego o ingresso para mim, com plena confiança de que o marcarei como pronto em menos de 30 minutos, dou tapinhas nas costas por limpar o tabuleiro de mais um lixo e volto a assuntos mais importantes.

Batendo em uma parede a 200 km/h

Abrindo o arquivo varnishreload, em um dos servidores executando o Debian Stretch, vi um script de shell com menos de 200 linhas.

Após analisar o script, não notei nada que pudesse resultar em problemas ao executá-lo várias vezes diretamente do terminal.

Afinal, isso é uma fase, mesmo que quebre ninguém vai reclamar, bom... não muito. Eu executo o script e vejo o que será gravado no terminal, mas os erros não são mais visíveis.

Mais algumas execuções para ter certeza de que não consigo reproduzir o erro sem nenhum esforço adicional e estou começando a descobrir como alterar esse script e fazer com que ele ainda gere um erro.

O script pode substituir STDOUT (usando > &-)? Ou STDERR? Nenhum deles funcionou no final.

Aparentemente, o systemd modifica de alguma forma o ambiente de inicialização, mas como e por quê?
Eu abro o vim e edito varnishreload, adicionando set -x logo abaixo do shebang, esperando que a saída de depuração do script esclareça alguma luz.

O arquivo está corrigido, então recarrego o verniz e vejo que a mudança quebrou tudo completamente... O escapamento é uma bagunça completa, na qual há toneladas de código tipo C. Mesmo rolar no terminal não é suficiente para descobrir onde ele começa. Estou completamente confuso. O modo de depuração pode afetar a operação de programas iniciados em um script? Não, é um absurdo. Bug na casca? Vários cenários possíveis passam pela minha cabeça como baratas em diferentes direções. O copo da bebida com cafeína é esvaziado instantaneamente, uma rápida ida até a cozinha para reabastecer o estoque e... pronto. Abro o script e dou uma olhada mais de perto na coisa: #!/bin/sh.

/bin/sh - este é apenas um link simbólico para o bash, então o script é interpretado no modo compatível com POSIX, certo? Não tão! O shell padrão no Debian é dash, e é exatamente assim que parece. refere-se a /bin/sh.

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

Como teste, mudei o shebang para #!/bin/bash, excluído set -x e tentei novamente. Finalmente, após a reinicialização subsequente do verniz, um erro tolerável apareceu 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' compiled

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                         # all this ceremony to handle blanks in 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 "failed to get the VCL file name"
129         fi
130
131         echo "$VCL_FILE"
132 }

Mas acontece que a linha 124 está bastante vazia e sem interesse. Eu só poderia presumir que o erro ocorreu como parte de uma string multilinha começando na linha 116.
O que é finalmente escrito na variável? VCL_FILE como resultado da execução do subshell acima?

No início, ele envia o conteúdo da variável VLC_SHOW, criado na linha 115, seguindo o comando pelo pipe. E então o que acontece lá?

Em primeiro lugar, é usado lá varnishadm, que faz parte do pacote de instalação do verniz, para configurar o verniz sem reiniciar.

Subequipe vcl.show -v usado para gerar toda a configuração VCL especificada em ${VCL_NAME}, para STDOUT.

Para exibir a configuração VCL ativa atual, bem como várias versões anteriores de configurações de roteamento de verniz que ainda estão na memória, você pode usar o comando varnishadm vcl.list, cuja saída será semelhante à 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

Valor variável ${VCL_NAME} está instalado em outra parte do script varnishreload ao nome da VCL atualmente ativa, se houver. Neste caso será “reload_20190101_120000_12397”.

Ótimo, variável ${VCL_SHOW} contém configuração completa para verniz, transparente por enquanto. Agora finalmente entendo por que a saída do painel é set -x acabou por ser tão quebrado - incluiu o conteúdo da configuração resultante.

É importante entender que uma configuração VCL completa muitas vezes pode ser montada a partir de vários arquivos. Comentários no estilo C são usados ​​para identificar onde determinados arquivos de configuração foram incluídos em outros, e é disso que trata a linha de trecho de código a seguir.
A sintaxe para comentários que descrevem os arquivos incluídos está no seguinte formato:

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

Os números não são importantes neste contexto, estamos interessados ​​no nome do arquivo.

O que acontece no final das contas no pântano de comandos que começa na linha 116?
Vamos enfrentá-lo.
A equipe consiste em quatro partes:

  1. Simples echo, que imprime o valor da variável ${VCL_SHOW}
    echo "$VCL_SHOW"
  2. awk, que procura uma linha (registro) onde o primeiro campo, após a quebra do texto, é “//”, e o segundo é “VCL.SHOW”.
    O Awk escreverá a primeira linha que corresponda a esses padrões e interromperá o processamento imediatamente.

    awk '$1 == "//" && $2 == "VCL.SHOW" {print; exit}'
  3. Um bloco de código que armazena valores de campos em cinco variáveis, separadas por espaços. A quinta variável FILE recebe o resto da linha. Finalmente, o último eco escreve o conteúdo da variável ${FILE}.
    { read -r DELIM VCL_SHOW INDEX SIZE FILE; echo "$FILE" }
  4. Como todas as etapas 1 a 3 estão incluídas em um subshell, a saída do valor $FILE será escrito em uma variável VCL_FILE.

Como sugere o comentário na linha 119, isso serve ao único propósito de lidar de forma confiável com casos em que a VCL fará referência a arquivos com espaços em seus nomes.

Comentei a lógica de processamento original para ${VCL_FILE} e tentei alterar a sequência de comandos, mas não deu em nada. Tudo funcionou bem para mim, mas quando iniciei o serviço deu um erro.

Parece que o erro simplesmente não é reproduzível ao executar o script manualmente, enquanto os supostos 30 minutos já expiraram seis vezes e, além disso, apareceu uma tarefa de maior prioridade, deixando outros assuntos de lado. O resto da semana foi preenchido com uma variedade de tarefas e foi apenas ligeiramente diluído por um relatório sobre sed e uma entrevista com um candidato. Problema com erro em varnishreload estava irremediavelmente perdido nas areias do tempo.

Seu chamado sed-fu... é na verdade... lixo

Na semana seguinte, tive um dia bastante livre, então decidi enfrentar esse ticket novamente. Eu esperava que em meu cérebro algum processo em segundo plano estivesse procurando uma solução para esse problema todo esse tempo, e desta vez eu definitivamente entenderia o que estava acontecendo.

Como simplesmente alterar o código não ajudou da última vez, decidi reescrevê-lo a partir da linha 116. De qualquer forma, o código existente era estúpido. E não há absolutamente nenhuma necessidade de usá-lo read.

Olhando para o erro novamente:
sh: echo: broken pipe - echo aparece em dois lugares neste comando, mas suspeito que o primeiro seja o culpado mais provável (ou pelo menos um cúmplice). Awk também não inspira confiança. E caso realmente seja awk | {read; echo} o design leva a todos esses problemas, por que não substituí-lo? Este comando de uma linha não usa todos os recursos do awk, e mesmo este extra read além disso.

Desde a semana passada houve um relatório sobre sed, eu queria testar minhas habilidades recém-adquiridas e simplificar echo | awk | { read; echo} em uma forma mais compreensível echo | sed. Embora esta definitivamente não seja a melhor abordagem para identificar o bug, pensei em pelo menos tentar meu sed-fu e talvez aprender algo novo sobre o problema. Ao longo do caminho, pedi ao meu colega, o autor da palestra sobre sed, que me ajudasse a criar um script sed mais eficiente.

deixei cair o conteúdo varnishadm vcl.show -v "$VCL_NAME" para um arquivo, para que eu pudesse me concentrar em escrever o script sed sem qualquer incômodo de reinicializações de serviço.

Uma breve descrição de exatamente como o sed processa a entrada pode ser encontrada em seu manual GNU. Nas fontes sed o símbolo n especificado explicitamente como um separador de linha.

Em várias passagens e com as recomendações do meu colega, escrevemos um script sed que deu o mesmo resultado de toda a linha original 116.

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

> cat vcl-example.vcl
Text
// VCL.SHOW 0 1578 file with 3 spaces.vcl
More text
// VCL.SHOW 0 1578 file.vcl
Even more text
// VCL.SHOW 0 1578 file with TWOspaces.vcl
Final text

Isso pode não ser óbvio pela descrição acima, mas estamos interessados ​​apenas no primeiro comentário // VCL.SHOW, e pode haver vários deles nos dados de entrada. É por isso que o awk original termina após a primeira partida.

# шаг первый, вывести только строки с комментариями
# используя возможности 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

Portanto, o conteúdo do script vernizreload será mais ou menos assim:

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

A lógica acima pode ser brevemente expressa da seguinte forma:
Se a string corresponder a uma expressão regular // VCL.SHOW, devore avidamente o texto que inclui os dois números nesta linha e salve tudo o que resta após esta operação. Emita o valor armazenado e finalize o programa.

Simples, não é?

Ficamos felizes com o script sed e com o fato de ele ter substituído todo o código original. Todos os meus testes deram os resultados desejados, então mudei o “varnishreload” no servidor e executei novamente systemctl reload varnish. Erro grave echo: write error: Broken pipe riu na nossa cara novamente. O cursor piscante aguardava que um novo comando fosse digitado no vazio escuro do terminal...

Fonte: habr.com

Adicionar um comentário