Falling Down the Rabbit Hole: The Story of One Varnish Reload Failure - Del 1

ghostinushanka, efter att ha hamrat på knapparna de senaste 20 minuterna som om hans liv berodde på det, vänder sig mot mig med en halvvild blick i ögonen och ett lurigt flin - "Dude, I think I got it."

"Titta här", säger han och pekar på en av symbolerna på skärmen, "jag slår vad om min röda hatt att om vi lägger till här det jag just skickade till dig", pekar på en annan kodsektion, "kommer felet inte längre att vara kommer att visas."

Lite förbryllad och trött modifierar jag sed-uttrycket vi har jobbat med ett tag, sparar filen och kör systemctl varnish reload. Felmeddelandet har försvunnit...

"Mejlen jag utbytte med kandidaten," fortsatte min kollega, medan hans leende växte till ett äkta leende av glädje, "det gick plötsligt upp för mig att det här är exakt samma problem!"

Hur allt började

Artikeln förutsätter en förståelse för hur bash, awk, sed och systemd fungerar. Kunskaper i lack är meriterande, men inget krav.
Tidsstämplar i utdrag har ändrats.
Skrivet med ghostinushanka.
Denna text är en översättning av originalet som publicerades på engelska för två veckor sedan; översättning boikoden.

Solen skiner genom panoramafönstren en annan varm höstmorgon, en kopp nylagad koffeinrik dryck vilar bort från klaviaturen, din favoritsymfoni av ljud låter i dina hörlurar, dränker prasslet från mekaniska tangentbord och första inträdet i listan över backlog-biljetter på Kanban-tavlan lyser lekfullt med den ödesdigra titeln "Undersök varnishreload" sh: echo: I/O error in staging" (Undersök "varnishreload sh: echo: I/O error" i staging). När det kommer till lack så finns och kan det inte finnas något utrymme för fel även om de inte ger några problem som i det här fallet.

För de som inte är bekanta med fernishreload, detta är ett enkelt skalskript som används för att ladda om konfigurationen lack - även kallad VCL.

Som titeln på biljetten antyder så uppstod felet på en av servrarna på scenen, och eftersom jag var säker på att lackdirigeringen på scenen fungerade korrekt antog jag att detta skulle vara ett mindre fel. Så, bara ett meddelande som hamnade i en redan stängd utgångsström. Jag tar biljetten för mig själv, i full förtroende om att jag kommer att markera den klar om mindre än 30 minuter, klappa mig själv på axeln för att jag rensat tavlan från ännu ett skräp och återkommer till viktigare saker.

Krockar in i en vägg i 200 km/h

Öppnar filen varnishreload, på en av servrarna som körde Debian Stretch såg jag ett skalskript som var mindre än 200 rader långt.

Efter att ha gått igenom skriptet märkte jag inget som kunde resultera i problem när jag körde det flera gånger direkt från terminalen.

Det här är trots allt ett skede, även om det går sönder så kommer ingen att klaga, ja... inte för mycket. Jag kör skriptet och ser vad som kommer att skrivas till terminalen, men felen är inte längre synliga.

Ett par körningar till för att se till att jag inte kan återskapa felet utan ytterligare ansträngning, och jag börjar ta reda på hur man ändrar det här skriptet och gör att det fortfarande ger ett fel.

Kan skriptet åsidosätta STDOUT (med > &-)? Eller STDERR? Ingen av dessa fungerade till slut.

Tydligen modifierar systemd på något sätt startmiljön, men hur och varför?
Jag öppnar vim och redigerar varnishreload, tillägger set -x precis under shebang, i hopp om att skriptets felsökningsutdata kommer att kasta lite ljus.

Filen är rättad, så jag laddar om lack och ser att ändringen fullständigt slog sönder allt... Avgaserna är en hel röra, där det finns massor av C-liknande kod. Det räcker inte med att scrolla i terminalen för att hitta var det börjar. Jag är helt förvirrad. Kan felsökningsläget påverka driften av program som startas i ett skript? Nej, det är nonsens. Bugg i skalet? Flera möjliga scenarier rasar genom mitt huvud som kackerlackor åt olika håll. Bägaren med koffeindrycken töms omedelbart, en snabb tur till köket för att fylla på lagret och... iväg. Jag öppnar skriptet och tittar närmare på shebang: #!/bin/sh.

/bin/sh - det här är bara en symbollänk till bash, så skriptet tolkas i POSIX-kompatibelt läge, eller hur? Inte så! Standardskalet på Debian är bindestreck, och det är precis så det ser ut. hänvisar /bin/sh.

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

Som ett test bytte jag shebang till #!/bin/bash, raderade set -x och försökte igen. Slutligen, vid efterföljande omstart av lack, dök ett acceptabelt fel upp i utgången:

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

Linje 124, här är den!

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 }

Men som det visar sig är linje 124 ganska tom och inte intressant. Jag kunde bara anta att felet uppstod som en del av en flerradssträng som började på rad 116.
Vad skrivs i slutändan till variabeln? VCL_FILE som ett resultat av exekvering av ovanstående underskal?

I början skickar den innehållet i variabeln VLC_SHOW, skapad på rad 115, efter kommandot genom röret. Och vad händer där då?

För det första används det där varnishadm, som är en del av lackinstallationspaketet, för att installera lack utan att starta om.

Underlag vcl.show -v används för att mata ut hela VCL-konfigurationen som anges i ${VCL_NAME}, till STDOUT.

För att visa den aktuella aktiva VCL-konfigurationen, såväl som flera tidigare versioner av lackroutingkonfigurationer som fortfarande finns i minnet, kan du använda kommandot varnishadm vcl.list, vars utdata kommer att likna den nedan:

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

Variabelt värde ${VCL_NAME} är installerat i en annan del av skriptet varnishreload till namnet på den för närvarande aktiva VCL, om det finns en. I det här fallet blir det "reload_20190101_120000_12397".

Jättebra, varierande ${VCL_SHOW} innehåller komplett konfiguration för lack, klar för nu. Nu förstår jag äntligen varför streckutgången är set -x visade sig vara så trasig - det inkluderade innehållet i den resulterande konfigurationen.

Det är viktigt att förstå att en komplett VCL-konfiguration ofta kan klippas ihop från flera filer. Kommentarer i C-stil används för att identifiera var vissa konfigurationsfiler har inkluderats i andra, och det är vad följande rad med kodavsnitt handlar om.
Syntaxen för kommentarer som beskriver inkluderade filer är i följande format:

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

Siffrorna är inte viktiga i detta sammanhang, vi är intresserade av filnamnet.

Vad händer i slutändan i träsket av kommandon som börjar på linje 116?
Låt oss räkna ut det.
Teamet består av fyra delar:

1. enkel echo, som skriver ut variabelns värde ${VCL_SHOW}

   echo "$VCL_SHOW"

2. awk, som letar efter en rad (post) där det första fältet, efter att ha brutit texten, är "//", och det andra är "VCL.SHOW".
   Awk skriver ut den första raden som matchar dessa mönster och slutar sedan bearbetningen omedelbart.

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

3. Ett kodblock som lagrar fältvärden i fem variabler, separerade med mellanslag. Den femte FILE-variabeln tar emot resten av raden. Slutligen skriver det sista ekot ut innehållet i variabeln ${FILE}.

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

4. Eftersom alla steg 1 till 3 är inneslutna i ett subshell, matar värdet ut $FILE kommer att skrivas till en variabel VCL_FILE.

Som kommentaren på rad 119 antyder, tjänar detta det enda syftet att på ett tillförlitligt sätt hantera fall där VCL kommer att referera till filer med mellanslag i deras namn.

Jag har kommenterat den ursprungliga bearbetningslogiken för ${VCL_FILE} och försökte ändra kommandosekvensen, men det ledde inte till något. Allt fungerade bra för mig, men när jag startade tjänsten gav det ett fel.

Det verkar som att felet helt enkelt inte går att reproducera när man kör skriptet manuellt, medan de förmodade 30 minuterna redan har gått ut sex gånger och dessutom har en högre prioriterad uppgift dykt upp som skjutit andra saker åt sidan. Resten av veckan var fylld med en mängd olika uppgifter och späddes bara lite på av ett reportage om sed och en intervju med en kandidat. Problem med fel i varnishreload var oåterkalleligt förlorad i tidens sand.

Din så kallade sed-fu... är faktiskt... skräp

Nästa vecka hade jag en ganska ledig dag, så jag bestämde mig för att ta itu med den här biljetten igen. Jag hoppades att i min hjärna hade någon bakgrundsprocess letat efter en lösning på det här problemet hela tiden, och den här gången skulle jag definitivt förstå vad som pågick.

Eftersom att bara ändra koden inte hjälpte förra gången, bestämde jag mig för att skriva om den från rad 116. Den befintliga koden var i alla fall dum. Och det finns absolut inget behov av att använda det read.

Tittar på felet igen:
sh: echo: broken pipe — echo förekommer på två ställen i det här kommandot, men jag misstänker att den första är den mer troliga boven (eller åtminstone en medbrottsling). Awk inger inte heller förtroende. Och om det verkligen är det awk | {read; echo} designen leder till alla dessa problem, varför inte byta ut den? Detta enradskommando använder inte alla funktionerna i awk, och även denna extra read dessutom.

Sedan förra veckan kom en rapport om sed, jag ville prova mina nyvunna färdigheter och förenkla echo | awk | { read; echo} till ett mer begripligt echo | sed. Även om detta definitivt inte är det bästa sättet att identifiera felet, tänkte jag att jag åtminstone skulle prova min sed-fu och kanske lära mig något nytt om problemet. Längs vägen bad jag min kollega, författaren till sed talk, att hjälpa mig att komma på ett mer effektivt sed-manus.

Jag tappade innehållet varnishadm vcl.show -v "$VCL_NAME" till en fil, så att jag kunde fokusera på att skriva sed-skriptet utan krångel med omstarter av tjänsten.

En kort beskrivning av exakt hur sed bearbetar input kan hittas i hans GNU-manual. I sed-källorna symbolen n uttryckligen anges som en radavgränsare.

I flera omgångar och med rekommendationer från min kollega skrev vi ett sed-manus som gav samma resultat som hela den ursprungliga rad 116.

Nedan är en exempelfil med indata:

> 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

Detta kanske inte framgår av beskrivningen ovan, men vi är bara intresserade av den första kommentaren // VCL.SHOW, och det kan finnas flera av dem i indata. Det är därför den ursprungliga awk slutar efter den första matchen.

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

Så, innehållet i varnishreload-skriptet kommer att se ut ungefär så här:

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

Ovanstående logik kan kort uttryckas på följande sätt:
Om strängen matchar ett reguljärt uttryck // VCL.SHOW, slukar sedan girigt texten som innehåller båda siffrorna på den här raden, och spara allt som återstår efter denna operation. Skicka ut det lagrade värdet och avsluta programmet.

Enkelt, eller hur?

Vi var nöjda med sed-skriptet och det faktum att det ersatte all originalkod. Alla mina tester gav önskat resultat, så jag ändrade "varnishreload" på servern och körde den igen systemctl reload varnish. Dåligt misstag echo: write error: Broken pipe skrattade oss i ansikten igen. Den blinkande markören väntade på att ett nytt kommando skulle skrivas in i terminalens mörka tomhet...

Källa: will.com