Caduta nella tana del coniglio: Storia di un errore di riavvio di varnish — parte 1

ghostinushanka, premendo i pulsanti per i precedenti 20 minuti come se la sua vita dipendesse da questo, si volta verso di me con un'espressione semi-selvaggia negli occhi e un sorriso astuto — «Amico, credo di aver capito.»

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

Un po' confuso e stanco, modifico l'espressione sed su cui stavamo già lavorando da un po', salvo il file e 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'autentica espressione di gioia, «Mi è improvvisamente chiaro che è esattamente lo stesso problema!»

Da dove è iniziato tutto

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

Il sole filtra attraverso le finestre panoramiche in un altro caldo mattino autunnale, una tazza di caffè appena preparato e ricco di caffeina riposa lontano dalla tastiera, nelle cuffie suona la mia sinfonia preferita, sovrapponendosi al fruscio delle tastiere meccaniche, e la prima voce nell'elenco dei ticket del backlog sulla bacheca kanban brilla giocosa con il titolo decisivo “Investigate varnishreload sh: echo: I/O error in staging”. Quando si parla di varnish, non c'è spazio per errori, anche se non si traducono in alcun problema come in questo caso.

Per coloro che non sono familiari con varnishreload, è un semplice script shell utilizzato per ricaricare la configurazione di varnish — anche chiamata VCL.

Come suggerisce il titolo del ticket, si è verificato un errore su uno dei server in stage, e poiché ero certo che il routing di varnish in stage funzionasse correttamente, ho ipotizzato che si trattasse di un errore banale. Così, semplicemente un messaggio finito in un flusso di output già chiuso. Prendo il ticket per me, sicuro di poterlo segnare come risolto in meno di 30 minuti, dandomi una pacca sulla spalla per aver ripulito la bacheca da un altro po' di spazzatura e tornando a cose più importanti.

Scontrandomi con il muro a una velocità di 200 km/h

Aprendo il file varnishreload, su uno dei server che girano Debian Stretch, ho visto uno script shell lungo meno di 200 righe.

Dopo aver dato un'occhiata allo script, non ho notato nulla che potesse causare problemi durante ripetute esecuzioni direttamente dal terminale.

Dopotutto, è uno stage, anche se dovesse rompersi, nessuno si lamenterà, beh... non troppo. Lancio lo script e vedo cosa viene stampato sul terminale, ma ora non si vedono nemmeno errori.

Altri due lanci, per essere sicuro di non poter riprodurre l'errore senza alcuno sforzo aggiuntivo, e inizio a pensare a come modificare questo script per costringerlo a generare un errore.

Forse posso reindirizzare STDOUT (con > &-)? O STDERR? Nessuna delle due cose alla fine ha funzionato.

Ovviamente, systemd modifica in qualche modo 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 possa gettare un po' di luce.

Il file è sistemato, così riavvio varnish e vedo che la modifica ha completamente rotto tutto... L'output è un vero pasticcio, con tonnellate di codice simile al C. Anche scorrere nel terminale non è sufficiente per trovare da dove inizia. Sono completamente confuso. Può la modalità di debug influenzare il funzionamento dei programmi avviati nello script? No, assurdo. Un bug nella shell? Diversi scenari possibili mi frullano in testa come scarafaggi in direzioni diverse. Una tazza di caffè piena viene svuotata in un istante, un rapido viaggio in cucina per rifornire le scorte e... si parte. Apro lo script e mi soffermo sullo shebang: #!/bin/sh.

/bin/sh — è solo un symlink su bash, quindi lo script viene interpretato in modalità compatibile con POSIX, giusto? Macché! La shell predefinita in Debian è dash, ed è proprio questo su cui è referenziata da /bin/sh.

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

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

Jan 01 12:00:00 hostname varnishreload[32604]: /usr/sbin/varnishreload: riga 124: echo: errore di scrittura: pipe rotta
Jan 01 12:00:00 hostname varnishreload[32604]: VCL 'reload_20190101_120000_32604' compilato

Riga 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                         # tutta questa cerimonia per gestire gli spazi nel 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 è rivelato, la riga 124 è piuttosto vuota e non rappresenta alcun interesse. Potevo solo supporre che l'errore fosse emerso come parte di un blocco di righe che inizia alla riga 116.
Cosa viene quindi registrato nella variabile VCL_FILE a seguito dell'esecuzione del sottosh shell sopra menzionato?

Innanzitutto, invia il contenuto della variabile VLC_SHOW, creata alla riga 115, al comando successivo tramite pipe. E cosa succede quindi?

In primo luogo, viene utilizzato varnishadm, che fa parte del pacchetto di installazione di varnish, per configurare varnish senza riavviarlo.

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

Per visualizzare la configurazione VCL attiva attuale e alcune versioni precedenti delle configurazioni di instradamento di varnish ancora in memoria, è possibile utilizzare il comando varnishadm vcl.list, il cui output sarà simile al 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

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

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

È importante comprendere che la configurazione completa di VCL può spesso essere assemblata da più file. I commenti in stile C vengono utilizzati per indicare dove un file di configurazione è stato incluso in un altro, ed è proprio di questo che tratta la riga di codice che segue.
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 sta succedendo nel blocco di comandi che inizia alla riga 116?
Cerchiamo di capirlo.
Il comando è composto da quattro parti:

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

   echo "$VCL_SHOW"

2. awk, che cerca la riga (registro) in cui il primo campo, dopo la divisione del testo, sarà “//”, e il secondo sarà “VCL.SHOW”.
   Awk stamperà la prima riga che corrisponde a questi modelli, 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 separati da spazi. La quinta variabile FILE riceve 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 racchiusi in una sub-shell, l'output del valore $FILE verrà salvato in una variabile. VCL_FILE.

Come si evince dal commento sulla riga 119, questo ha un'unica finalità: gestire in modo affidabile i casi in cui VCL si riferisce a file con spazi nel nome.

Ho commentato la logica originale di elaborazione per ${VCL_FILE} e ho cercato di modificare la sequenza dei comandi, ma questo non ha portato a nulla. Tutto funzionava perfettamente, mentre durante l'esecuzione del servizio dava un errore.

Sembra che l'errore non sia riproducibile durante l'esecuzione manuale dello script, con i presunti 30 minuti già conclusi circa sei volte, e in aggiunta è emersa un'attività più prioritaria che ha messo in secondo piano altre questioni. Il resto della settimana è stato occupato da una serie di compiti vari, con solo un leggero intervento dedicato a una relazione su sed e un colloquio con un candidato. Il problema dell'errore in varnishreload è andato irrimediabilmente perso nei meandri del tempo.

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

La settimana prossima ho avuto un giorno piuttosto libero, quindi ho deciso di dedicarmi di nuovo a questo ticket. Speravo che nel mio cervello un qualche processo in background stesse cercando una soluzione a questo problema e che questa volta capissi finalmente di cosa si trattava.

Poiché l'ultima volta una semplice modifica del codice non ha funzionato, ho deciso di riscriverlo a partire dalla riga 116. In ogni caso, il codice esistente era piuttosto confuso e non c'era assolutamente bisogno di usarlo. read.

Guardando di nuovo l'errore:
sh: echo: broken pipe — in questo comando l'echo si trova in due posti, ma sospetto che il primo sia il colpevole più probabile (o almeno un complice). Anche awk non è molto affidabile. E se davvero questo awk | {read; echo} costrutto sta causando tutti questi problemi, perché non sostituirlo? Questo comando su una riga non utilizza tutte le potenzialità di awk, e c'è anche questo extra read in più.

Poiché la settimana scorsa c'è stata una presentazione su sed, volevo provare le mie abilità recentemente acquisite e semplificare echo | awk | { read; echo} in una forma più comprensibile echo | sed. Anche se questo non è sicuramente il miglior approccio per individuare l'errore, ho pensato che almeno avrei provato il mio sed-fu e forse avrei imparato qualcosa di nuovo sul problema. Nel frattempo, ho chiesto al mio collega, autore della presentazione su sed, di aiutarmi a creare uno script sed più efficiente.

Ho inviato il contenuto di varnishadm vcl.show -v "$VCL_NAME" a un file, in modo da potermi concentrare sulla scrittura dello script sed senza problemi legati al riavvio del servizio.

Una breve descrizione di come sed elabora i dati in ingresso si trova in la sua guida GNU. Nei sorgenti di sed il carattere n è esplicitamente specificato come delimitatore di righe.

Con più passaggi e con i suggerimenti del mio collega, abbiamo scritto uno script sed che dava lo stesso risultato della riga originale 116.

Ecco un esempio di file con dati in ingresso:

> 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 ovvio dalla descrizione sopra, ma ci interessa solo il primo commento // VCL.SHOW, e nel dati in ingresso potrebbero essercene più di uno. Ed è 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 avrà un aspetto simile a questo:

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

La logica sopra esposta può essere espressa brevemente come segue:
Se la stringa corrisponde all'espressione regolare // VCL.SHOW, allora consuma avidamente il testo che include entrambi i numeri in questa stringa, e conserva tutto ciò che rimane dopo quest'operazione. Restituisci il valore conservato 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 modificato “varnishreload” sul server e ho riavviato di nuovo systemctl reload varnish. Un errore orribile echo: write error: Broken pipe ci sorrideva di nuovo in faccia. Il cursore lampeggiante aspettava un nuovo comando nel buio del terminale...

Fonte: habr.com