La discesa nella tana del coniglio: Una storia su un errore di riavvio di Varnish - parte 1

ghostinushanka, premendo i tasti per i 20 minuti precedenti come se la sua vita dipendesse da questo, si gira verso di me con uno sguardo semi selvaggio e un sorriso furbo — «Ehi, credo di aver capito.»

«Guarda qui,» dice, indicando uno dei simboli sullo schermo — «Scommettiamo sul mio cappello rosso che se aggiungiamo qui quello che ti ho appena mandato» — indicando un'altra parte del codice — «l'errore non verrà più visualizzato.»

Un po' confuso e stanco, modifico l'espressione sed su cui avevamo lavorato per un po’, salvo il file e lo avvio systemctl varnish reload. Il messaggio di errore è scomparso…

«Le email che ho scambiato con il candidato,» continua il mio collega, mentre il suo sorriso si trasforma in un sorriso autentico pieno di gioia, «mi sono reso conto che è proprio lo stesso problema!»

Da dove è tutto iniziato

L'articolo presuppone una comprensione dei principi di funzionamento di bash, awk, sed e systemd. La conoscenza di varnish è gradita, ma non è obbligatoria.
Le timestamp nei frammenti sono state modificate.
Scritto insieme a ghostinushanka.
Questo testo è una traduzione dell'originale pubblicato in inglese due settimane fa; la traduzione boikoden.

Il sole filtra attraverso le finestre panoramiche in un'altra calda mattina d'autunno, una tazza di bevanda ricca di caffeina è posata a lato della tastiera, i miei brani preferiti risuonano nelle cuffie coprendo il fruscio delle tastiere meccaniche, e il primo elemento nella lista dei ticket del backlog sulla bacheca kanban brilla con il fatidico titolo “Investigate varnishreload sh: echo: I/O error in staging”. Quando si parla di varnish, non c'è posto per errori, anche se non si manifestano come problemi in questo caso.

Per chi non è familiare con varnishreload, è un semplice script shell usato per ricaricare la configurazione di varnish — nota anche come VCL.

Come suggerisce il titolo del ticket, l’errore è apparso su uno dei server in staging, e poiché ero sicuro che il routing di varnish in staging funzionasse correttamente, ho supposto che si trattasse di un errore minore. Quindi, solo un messaggio finito in un flusso di output già chiuso. Prendo il ticket per me, sicuro di poterlo contrassegnare come completato in meno di 30 minuti, battermi sulla spalla per liberare la board da un'altra spazzatura e tornare a faccende più importanti.

Scontrandomi con un muro a 200 km/h

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

Scorrendo lo script, non ho notato nulla che potesse causare problemi se venisse eseguito più volte direttamente dal terminale.

Dopotutto, si tratta di staging, anche se si rompe, nessuno si lamenterà, beh… non troppo. Eseguo lo script e vedo cosa viene visualizzato nel terminale, ma non ci sono errori da vedere.

Altre due esecuzioni, per assicurarmi di non poter riprodurre l'errore senza alcuno sforzo aggiuntivo, e inizio a pensare a come modificare questo script per fargli restituire effettivamente un errore.

Potrebbe essere utile accorciare STDOUT (utilizzando >&-)? O STDERR? Nessuna delle due ha funzionato.

Ovviamente, systemd in qualche modo modifica l'ambiente di esecuzione, ma come e perché?
Apro vim e modifico varnishreload, aggiungendo set -x proprio sotto lo shebang, sperando che l'output di debug dello script faccia luce.

Il file è stato corretto, quindi riavvio varnish e vedo che la modifica ha completamente rotto tutto... L'output è un disastro totale, con tonnellate di codice in stile C. Anche lo scorrimento nel terminale non è sufficiente per trovare dove inizia. Sono completamente confuso. Può la modalità di debug influenzare l'esecuzione dei programmi avviati nello script? No, assurdità. Un bug nella shell? Diversi scenari possibili scorrono nella mia mente come scarafaggi in direzioni diverse. La mia tazza di bevanda ricca di caffeina si svuota immediatamente, rapido viaggio in cucina per rifornire e… andiamo. Apro lo script e controllo lo shebang: #!/bin/sh.

/bin/sh — è solo un symlink su bash, quindi lo script è interpretato in modalità compatibile con POSIX, giusto? Non così in fretta! La shell predefinita in Debian è dash, e questo è esattamente ciò che fa riferimento a /bin/sh.

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

Per provare, ho cambiato lo shebang in #!/bin/bash, ho rimosso set -x e ho provato di nuovo. Finalmente, durante il successivo riavvio di varnish, è apparso un errore decente nell'output:

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, eccolo!

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                         # tutto questo cerimoniale per gestire spazi 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 "impossibile ottenere il nome del file VCL"
129         fi
130
131         echo "$VCL_FILE"
132 }

Ma come si è scoperto, la riga 124 è piuttosto vuota e non suscita interesse. Non potevo che ipotizzare che l'errore fosse parte di un multi-line che inizia alla riga 116.
Cosa viene quindi registrato nella variabile VCL_FILE a seguito dell'esecuzione del sopra citato subshell?

Inizialmente, trasmette il contenuto della variabile VLC_SHOW, creata alla riga 115, al comando successivo tramite pipe. E cosa succede lì?

Prima di tutto, viene utilizzato varnishadm, parte del pacchetto installativo di varnish, per configurare varnish senza riavviare.

Il comando vcl.show -v viene utilizzato per mostrare l'intera configurazione VCL specificata in ${VCL_NAME}, in STDOUT.

Per visualizzare l'attuale configurazione VCL attiva, così come alcune versioni precedenti delle configurazioni di routing di varnish ancora in memoria, si può usare il comando varnishadm vcl.list, il cui output sarà simile a quello qui sotto:

dismesso   freddo/occupato       1 reload_20190101_120000_11903
dismesso   freddo/occupato       2 reload_20190101_120000_12068
dismesso   freddo/occupato       16 reload_20190101_120000_12259
dismesso   freddo/occupato       16 reload_20190101_120000_12299
dismesso   freddo/occupato       28 reload_20190101_120000_12357
attivo      auto/caldo       32 reload_20190101_120000_12397
disponibile   auto/caldo       0 reload_20190101_120000_12587

Valore della variabile ${VCL_NAME} viene impostato in un'altra parte dello script varnishreload sul nome del VCL attivo al momento, se presente. In questo caso sarà “reload_20190101_120000_12397”.

Ottimo, la variabile ${VCL_SHOW} contiene l'intera configurazione per varnish, fin qui chiaro. Ora ho finalmente capito perché l'output dash di set -x era così danneggiato — includeva il contenuto della configurazione risultante.

È importante capire che l'intera configurazione VCL può essere spesso assemblata da più file. I commenti in stile C vengono utilizzati per indicare dove un file di configurazione è stato incluso in un altro, ed è esattamente questo di cui tratta tutta la seguente riga di codice.
La sintassi dei commenti che descrivono i file inclusi ha il seguente formato:

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

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

Cosa succede quindi nel guazzabuglio dei comandi che inizia alla riga 116?
Analizziamo.
Il comando è composto da quattro parti:

1. Un semplice echo, che stampa il valore della variabile ${VCL_SHOW}

   echo "$VCL_SHOW"

2. awk, che cerca la riga (record) dove il primo campo, dopo aver diviso il testo, è “//”, e il secondo è «VCL.SHOW».
   Awk stamperà la prima riga che corrisponde a questi schemi e poi smetterà immediatamente di elaborare.

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

3. Un blocco di codice che salva in cinque variabili i valori dei campi divisi da spazi. La quinta variabile FILE ottiene il resto della riga. Infine, l'ultimo echo stampa 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 inclusi nel subshell, l'output del valore $FILE sarà registrato nella variabile VCL_FILE.

Come indicato dal commento alla riga 119, questo serve a uno scopo unico: gestire in modo affidabile i casi in cui il VCL fa riferimento a file con spazi nel nome.

Ho commentato la logica originale di gestione per ${VCL_FILE} e ho cercato di modificare la sequenza di comandi, ma non ha portato a nulla. Tutto funzionava perfettamente, e nel caso di avvio del servizio restituiva un errore.

Sembra che l'errore non sia semplicemente riproducibile quando si esegue lo script manualmente, mentre venti minuti presunti sono già scaduti sei volte e, in aggiunta, è emersa un'altra priorità che ha messo da parte le altre faccende. Il resto della settimana è stato pieno di vari compiti e solo un po' alleggerito da una presentazione su sed e un colloquio con un candidato. Il problema dell'errore in varnishreload è andato irreparabilmente perso nelle sabbie del tempo.

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

La settimana prossima ho avuto un giorno piuttosto libero, quindi ho deciso di tornare su questo ticket. Speravo che nella mia mente, un qualche processo in background avesse cercato una soluzione a questo problema tutto questo tempo e che stavolta avrei capito davvero di cosa si trattasse.

Poiché l'ultima volta una semplice modifica del codice non ha aiutato, ho deciso di riscriverlo a partire dalla riga 116. In ogni caso il codice esistente era goffo. E non c'era assolutamente bisogno di usare read.

Guardando di nuovo l'errore:
sh: echo: pipe rotta — in questo team, echo si trova in due posti, ma sospetto che il primo sia il colpevole più probabile (o almeno un complice). Anche Awk non ispira fiducia. E nel caso in cui davvero sia questo awk | {read; echo} costrutto che porta a tutti questi problemi, perché non sostituirlo? Questo comando su una sola riga non sfrutta tutte le capacità di awk, e c'è anche quella superflua read .

Poiché la settimana scorsa è stata fatta una Presentazione su sed, volevo provare le mie abilità appena acquisite e semplificare echo | awk | { read; echo} in un modo più chiaro echo | sed. Anche se questo non è certamente il miglior approccio per diagnosticare l'errore, ho pensato che almeno proverò il mio sed-fu e potrei scoprire qualcosa di nuovo sul problema. Durante il processo, ho chiesto al mio collega, l'autore della presentazione su sed, di aiutarmi a ideare uno script sed più efficace.

Ho inviato il contenuto varnishadm vcl.show -v "$VCL_NAME" in un file, così potevo concentrarmi sulla scrittura dello script sed senza preoccupazioni riguardo ai riavvii del servizio.

Una breve descrizione di come sed gestisce i dati in ingresso può essere trovata nel il suo manuale GNU. Nei sorgenti di sed, il simbolo n è esplicitamente indicato come delimitatore di righe.

Con alcuni passaggi e i consigli del mio collega, abbiamo scritto uno script sed che dava lo stesso risultato della stringa originale 116.

Ecco un esempio del file contenente i dati in ingresso:

> cat vcl-example.vcl
Text
// VCL.SHOW 0 1578 file con 3 spazi.vcl
More text
// VCL.SHOW 0 1578 file.vcl
Even more text
// VCL.SHOW 0 1578 file con DUEspazi.vcl
Final text

Questo potrebbe non essere ovvio dalla descrizione sopra, ma ci interessa solo il primo commento // VCL.SHOW, e nei dati in ingresso potrebbero essercene più. È per questo che l'originale awk termina la sua esecuzione 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 varnishreload apparirà all'incirca così:

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

La logica sopra può essere espressa brevemente come segue:
Se la stringa corrisponde a un'espressione regolare // VCL.SHOW, allora consuma avidamente il testo che include entrambi i numeri in quella stringa e salva tutto ciò che rimane dopo questa operazione. Restituisci il valore salvato e termina il programma.

Semplice, vero?

Eravamo soddisfatti dello script sed e del fatto che sostituisse l'intero codice originale. Tutti i miei test hanno dato i risultati desiderati, quindi ho cambiato "varnishreload" sul server e ho riavviato systemctl reload varnish. L'orribile errore echo: write error: Broken pipe sorrideva di nuovo in faccia a noi. Il cursore lampeggiante aspettava un nuovo comando nell'oscurità vuota del terminale...

Fonte: habr.com