Falling Down the Rabbit Hole: La storia di un errore di riavvio della vernice - Parte 1

ghostinushanka, dopo aver martellato i pulsanti negli ultimi 20 minuti come se la sua vita dipendesse da questo, si gira verso di me con uno sguardo semi-selvaggio negli occhi e un sorriso sornione: "Amico, penso di aver capito."

“Guarda qui”, dice, indicando uno dei simboli sullo schermo, “scommetto il mio cappello rosso che se aggiungiamo qui quello che ti ho appena inviato”, indicando un'altra sezione di codice, “l'errore non sarà più sarà mostrato."

Un po' perplesso e stanco modifico l'espressione sed su cui stiamo lavorando da un po', salvo il file ed eseguo systemctl varnish reload. Il messaggio di errore è scomparso...

"Le e-mail che ho scambiato con il candidato", ha continuato il mio collega, mentre il suo sorriso si trasformava in un autentico sorriso di gioia, "all'improvviso mi sono reso conto che questo è esattamente lo stesso problema!"

Come tutto cominciò

L'articolo presuppone la comprensione di come funzionano bash, awk, sed e systemd. Preferibile ma non obbligatoria la conoscenza delle vernici.
I timestamp negli snippet sono stati modificati.
Scritto con ghostinushanka.
Questo testo è una traduzione dell'originale pubblicato in inglese due settimane fa; traduzione boikoden.

Il sole splende attraverso le finestre panoramiche in un'altra calda mattina autunnale, una tazza di bevanda ricca di caffeina appena preparata riposa lontano dalla tastiera, la tua sinfonia di suoni preferita risuona nelle tue cuffie, soffocando il fruscio delle tastiere meccaniche, e la prima voce nell’elenco dei ticket arretrati sul tabellone Kanban si illumina scherzosamente con il fatidico titolo “Investigate paintreload” sh: echo: I/O error in staging” (Investiga “vernishreload sh: echo: I/O error” in staging). Quando si tratta di vernici c'è e non può esserci spazio per errori, anche se non comportano problemi come in questo caso.

Per coloro che non hanno familiarità con vernice ricarica, questo è un semplice script di shell utilizzato per ricaricare la configurazione vernice - chiamato anche VCL.

Come suggerisce il titolo del ticket, l'errore si è verificato su uno dei server sul palco e poiché ero sicuro che il routing della vernice sul palco funzionasse correttamente, ho pensato che si sarebbe trattato di un errore minore. Quindi, solo un messaggio finito in un flusso di output già chiuso. Prendo il biglietto per me, nella piena fiducia che lo segnerò pronto in meno di 30 minuti, mi do una pacca sulla spalla per aver ripulito il tabellone dall'ennesima spazzatura e torno a questioni più importanti.

Schiantarsi contro un muro a 200 km/h

Apertura del file varnishreload, su uno dei server che esegue Debian Stretch, ho visto uno script di shell lungo meno di 200 righe.

Dopo aver esaminato lo script, non ho notato nulla che potesse causare problemi durante l'esecuzione più volte direttamente dal terminale.

Dopotutto questa è una tappa, anche se dovesse rompersi nessuno si lamenterà, beh... neanche troppo. Eseguo lo script e vedo cosa verrà scritto sul terminale, ma gli errori non sono più visibili.

Ancora un paio di esecuzioni per assicurarmi di non poter riprodurre l'errore senza ulteriori sforzi e sto iniziando a capire come modificare questo script e far sì che continui a generare un errore.

Lo script può sovrascrivere STDOUT (utilizzando > &-)? O STDERR? Nessuno di questi ha funzionato alla fine.

Apparentemente systemd modifica in qualche modo l'ambiente di avvio, ma come e perché?
Apro vim e modifico varnishreload, aggiungendo set -x proprio sotto la lente, sperando che l'output di debug dello script faccia un po' di luce.

Il file è stato corretto, quindi ricarico Paint e vedo che la modifica ha rotto completamente tutto... Lo scarico è un completo disastro, in cui ci sono tonnellate di codice C-like. Anche scorrere il terminale non è sufficiente per scoprire da dove inizia. Sono completamente confuso. La modalità debug può influire sul funzionamento dei programmi avviati in uno script? No, non ha senso. Bug nella shell? Diversi scenari possibili mi attraversano la testa come scarafaggi in direzioni diverse. La tazza della bevanda caffeinata si svuota all'istante, un salto in cucina per rifornire la scorta e... si parte. Apro la sceneggiatura e osservo più da vicino lo shebang: #!/bin/sh.

/bin/sh - questo è solo un collegamento simbolico a bash, quindi lo script viene interpretato in modalità compatibile con POSIX, giusto? Non così! La shell predefinita su Debian è dash, ed è esattamente quello che sembra. richiami /bin/sh.

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

Come prova, ho cambiato lo shebang in #!/bin/bash, cancellato set -x e riprovato. Alla fine, al successivo riavvio di Paint, nell'output è apparso un errore tollerabile:

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

Linea 124, eccola!

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 }

Ma a quanto pare, la riga 124 è piuttosto vuota e di nessun interesse. Potrei solo supporre che l'errore si sia verificato come parte di una stringa multilinea che inizia alla riga 116.
Cosa viene scritto in definitiva nella variabile? VCL_FILE come risultato dell'esecuzione della sub-shell di cui sopra?

All'inizio invia il contenuto della variabile VLC_SHOW, creato alla riga 115, seguendo il comando attraverso la pipe. E poi cosa succede lì?

Innanzitutto, viene utilizzato lì varnishadm, che fa parte del pacchetto di installazione di Paint, per impostare Paint senza riavviare.

Sottosquadra vcl.show -v utilizzato per restituire l'intera configurazione VCL specificata in ${VCL_NAME}, a STDOUT.

Per visualizzare la configurazione VCL attiva corrente, nonché diverse versioni precedenti delle configurazioni di routing verniciate che sono ancora in memoria, è possibile utilizzare il comando varnishadm vcl.list, il cui output sarà simile a quello seguente:

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

Valore variabile ${VCL_NAME} è installato in un'altra parte dello script varnishreload al nome della VCL attualmente attiva, se ce n'è una. In questo caso sarà “reload_20190101_120000_12397”.

Ottimo, variabile ${VCL_SHOW} contiene la configurazione completa per la vernice, per ora chiara. Ora finalmente capisco perché l'output del trattino è set -x si è rivelato così rotto: includeva il contenuto della configurazione risultante.

È importante comprendere che una configurazione VCL completa può spesso essere messa insieme da diversi file. I commenti in stile C vengono utilizzati per identificare dove determinati file di configurazione sono stati inclusi in altri, ed è di questo che tratta la seguente riga di frammento di codice.
La sintassi per i commenti che descrivono i file inclusi è nel seguente formato:

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

I numeri non sono importanti in questo contesto, a noi interessa il nome del file.

Cosa succede alla fine nella palude di comandi che iniziano alla riga 116?
Ammettiamolo.
La squadra è composta da quattro parti:

  1. semplice echo, che stampa il valore della variabile ${VCL_SHOW}
    echo "$VCL_SHOW"
  2. awk, che cerca una riga (record) in cui il primo campo, dopo aver suddiviso il testo, è “//”, e il secondo è “VCL.SHOW”.
    Awk scriverà la prima riga che corrisponde a questi modelli e poi interromperà immediatamente l'elaborazione.

    awk '$1 == "//" && $2 == "VCL.SHOW" {print; exit}'
  3. Un blocco di codice che memorizza i valori dei campi in cinque variabili, separate da spazi. La quinta variabile FILE riceve il resto della riga. Infine, l'ultimo eco scrive il contenuto della variabile ${FILE}.
    { read -r DELIM VCL_SHOW INDEX SIZE FILE; echo "$FILE" }
  4. Poiché tutti i passaggi da 1 a 3 sono racchiusi in una subshell, emettendo il valore $FILE verrà scritto in una variabile VCL_FILE.

Come suggerisce il commento alla riga 119, questo serve al solo scopo di gestire in modo affidabile i casi in cui VCL farà riferimento a file con spazi nei loro nomi.

Ho commentato la logica di elaborazione originale per ${VCL_FILE} e ho provato a cambiare la sequenza dei comandi, ma non ha portato a nulla. Tutto ha funzionato bene per me, ma quando ho avviato il servizio ha dato un errore.

Sembra che l'errore semplicemente non sia riproducibile quando si esegue lo script manualmente, mentre i presunti 30 minuti sono già scaduti sei volte e, inoltre, è apparsa un'attività con priorità più alta, mettendo da parte altre questioni. Il resto della settimana è stato riempito con una serie di compiti ed è stato solo leggermente diluito da un rapporto su sed e da un colloquio con un candidato. Problema con errore in varnishreload era irrimediabilmente perso nelle sabbie del tempo.

Il tuo cosiddetto sed-fu... in realtà è... spazzatura

La settimana successiva ho avuto un giorno abbastanza libero, quindi ho deciso di affrontare di nuovo questo biglietto. Speravo che nel mio cervello qualche processo in background stesse cercando una soluzione a questo problema per tutto questo tempo, e questa volta avrei sicuramente capito cosa stava succedendo.

Dato che la semplice modifica del codice non ha aiutato l'ultima volta, ho deciso di riscriverlo iniziando dalla riga 116. In ogni caso, il codice esistente era stupido. E non c'è assolutamente bisogno di usarlo read.

Osservando di nuovo l'errore:
sh: echo: broken pipe — echo appare in due punti in questo comando, ma sospetto che il primo sia il più probabile colpevole (o almeno un complice). Anche Awk non ispira fiducia. E nel caso lo fosse davvero awk | {read; echo} il design porta a tutti questi problemi, perché non sostituirlo? Questo comando di una riga non utilizza tutte le funzionalità di awk e nemmeno questa extra read Inoltre.

Dalla settimana scorsa c'era una relazione su sed, volevo mettere alla prova le mie competenze appena acquisite e semplificarle echo | awk | { read; echo} in un modo più comprensibile echo | sed. Anche se questo non è sicuramente l'approccio migliore per identificare il bug, ho pensato almeno di provare il mio sed-fu e magari imparare qualcosa di nuovo sul problema. Lungo il percorso, ho chiesto al mio collega, l'autore del discorso su sed, di aiutarmi a elaborare uno script sed più efficiente.

Ho lasciato cadere il contenuto varnishadm vcl.show -v "$VCL_NAME" in un file, così ho potuto concentrarmi sulla scrittura dello script sed senza il fastidio di riavvii del servizio.

Una breve descrizione di come è possibile trovare esattamente l'input dei processi sed il suo manuale GNU. Nelle fonti sed il simbolo n esplicitamente specificato come separatore di riga.

In diversi passaggi e con le raccomandazioni del mio collega, abbiamo scritto uno script sed che ha dato lo stesso risultato dell'intera riga originale 116.

Di seguito è riportato un file di esempio con i dati di input:

> 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

Questo potrebbe non essere evidente dalla descrizione sopra, ma a noi interessa solo il primo commento // VCL.SHOWe potrebbero essercene diversi nei dati di input. Questo è il motivo per cui l'awk originale termina dopo la prima corrispondenza.

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

Quindi, il contenuto dello script paintreload sarà simile a questo:

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

La logica di cui sopra può essere brevemente espressa come segue:
Se la stringa corrisponde a un'espressione regolare // VCL.SHOW, quindi divora avidamente il testo che include entrambi i numeri in questa riga e salva tutto ciò che rimane dopo questa operazione. Emettere il valore memorizzato e terminare il programma.

Semplice, no?

Eravamo soddisfatti dello script sed e del fatto che sostituisse tutto il codice originale. Tutti i miei test hanno dato i risultati desiderati, quindi ho modificato il "varnishreload" sul server e l'ho eseguito di nuovo systemctl reload varnish. Brutto errore echo: write error: Broken pipe ci ha riso in faccia di nuovo. Il cursore ammiccante attendeva un nuovo comando da inserire nel buio buio del terminale...

Fonte: habr.com

Aggiungi un commento