Fallet i kaninhålet: En berättelse om ett fel i omladdningen av varnish — del 1

spökande, tryckande på knapparna under de senaste 20 minuterna, som om hans liv hängde på det, vänder han sig mot mig med en halvvild blick och en lurig grimas — "Tja, jag tror att jag har förstått."

"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 det jag just skickade här" — pekande på ett annat kodavsnitt — "så kommer felet att försvinna."

Lite förbryllad och trött, ändrar jag det sed-uttryck som vi har jobbat med ett tag, sparar filen och kör systemctl varnish reload. Felmeddelandet är borta…

"E-mailen som jag utväxlade med kandidaten," fortsätter min kollega, medan hans grin övergår till en äkta leende fullt av glädje, "plötsligt insåg jag att det var exakt samma problem!"

Hur allt började

Artikeln förutsätter förståelse för principerna bakom bash, awk, sed och systemd. Kännedom om varnish är välkommen, men inte obligatorisk.
Tidsstämplarna i snuttarna har ändrats.
Skriven tillsammans med spökande.
Denna text är en översättning av originalverket, publicerat på engelska för två veckor sedan; översättning boikoden.

Solen strålar genom panoramafönstren på ännu en varm höstmorgon, en kopp nyligen bryggd koffeinhaltig dryck vilar vid sidan om tangentbordet, favorit symfonin hörs i hörlurarna, överröstande ljudet av mekaniska tangentbord, och den första posten på ticketlistan i backloggen på kanban-tavlan lysande framträder med den ödesdigra titeln “Investigate varnishreload sh: echo: I/O error in staging” (Utreder “varnishreload sh: echo: I/O error” i staging). När det gäller varnish finns det inga fel, och kan inte finnas, även om de inte ger upphov till några problem som i detta fall.

För dem som inte är bekanta med varnishreload, är detta ett enkelt shell-skript som används för att ladda om konfigurationen av varnish — även kallad VCL.

Som titeln på biljetten antyder, inträffade ett fel på en av servrarna på stagingserven, och eftersom jag var säker på att Varnish-routing på staging fungerade korrekt, antog jag att det skulle vara ett litet problem. Så, bara ett meddelande som kommit in i en redan stängd utgångsström. Jag tar biljetten för mig själv, helt övertygad om att jag kommer att markera den som klar på mindre än 30 minuter, klappa mig själv på axeln för att rensa brädan från ännu ett skräp och återgå till viktigare uppgifter.

Kollidera med en vägg i 200 km/h

När jag öppnade filen varnishreload, på en av servrarna som kör Debian Stretch, såg jag ett shell-skript som var mindre än 200 rader långt.

Efter att ha läst igenom skriptet såg jag inget som skulle kunna orsaka problem vid upprepade körningar direkt från terminalen.

I slutändan är detta staging, även om det skulle gå sönder, skulle ingen klaga, ja… inte så många. Jag kör skriptet och ser vad som skrivs ut i terminalen, men nu ser jag inga fel.

Ett par ytterligare körningar för att säkerställa att jag inte kan återskapa felet utan några extra ansträngningar, och jag börjar tänka på hur jag kan ändra skriptet för att få det att faktiskt ge ett fel.

Kanske kan jag stänga av STDOUT (med hjälp av > &-)? Eller STDERR? Ingen av dem fungerade till slut.

Uppenbarligen ändrar systemd på något sätt körmiljön, men hur och varför?
Jag slår på vim och redigerar varnishreload, lägger till set -x precis under shebang, i hopp om att debug-utskriften från skriptet ska ge lite insikt.

Filen är ändrad, så jag startar om Varnish och ser att ändringen förstör allt... Utskriften är en total röra, där massor av C-liknande kod finns. Inte ens rullningen i terminalen är tillräcklig för att hitta var det börjar. Jag är helt förvirrad. Kan debug-läget påverka hur programmen som körs i skriptet fungerar? Nej, nonsens. Buggen ligger i shellet? Flera möjliga scenarier snurrar i mitt huvud som kackerlackor i alla riktningar. En kopp koffeinrik dryck blir snabbt tömd, en snabb resa till köket för att fylla på och... här kör vi. Jag öppnar skriptet och granskar shebang: #!/bin/sh.

/bin/sh — det är ju bara en symlink till bash, så skriptet tolkas i POSIX-kompatibelt läge, eller hur? Inte så enkelt! Standard-skalet i Debian är dash, och det är just vad som refererar till /bin/sh.

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

För testets skull ändrade jag shebang till #!/bin/bash, tog bort set -x och försökte igen. Äntligen, vid nästa omstart av varnish, dök en rimlig felkod upp i utfallet:

Jan 01 12:00:00 värdnamn varnishreload[32604]: /usr/sbin/varnishreload: rad 124: echo: skrivfel: trasig rör
Jan 01 12:00:00 värdnamn varnishreload[32604]: VCL 'reload_20190101_120000_32604' kompilerad

Rad 124, där har vi det!

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                         # allt detta för att hantera tomma rader i 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                 misslyckas "kunde inte hämta VCL-filnamnet"
129         fi
130
131         echo "$VCL_FILE"
132 }

Men som det visade sig, är rad 124 ganska tom och oinspirerande. Jag kunde bara anta att felet uppstod som en del av fleradrig kod som började på rad 116.
Vad som slutligen sparas i variabeln VCL_FILE som ett resultat av att ovanstående subt-shell körs?

I början skickar den innehållet i variabeln VLC_SHOW, skapad på rad 115, till nästa kommando genom en pipe. Och vad händer där?

Först och främst används varnishadm, som är en del av installationspaketet varnish, för att konfigurera varnish utan omstart.

Underkommandot vcl.show -v används för att visa hela VCL-konfigurationen angiven i ${VCL_NAME}, i STDOUT.

För att visa den aktuella aktiva VCL-konfigurationen samt några tidigare versioner av varnish-routingkonfigurationer som fortfarande finns i minnet, kan man använda kommandot varnishadm vcl.list, vars utdata kommer att likna följande:

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

Värdet av variabeln ${VCL_NAME} inställs på en annan del av skriptet varnishreload till namnet på den aktuella aktiva VCL, om sådan finns. I detta fall blir det “reload_20190101_120000_12397”.

Bra, variabeln ${VCL_SHOW} innehåller hela konfigurationen för varnish, vilket är tydligt. Nu förstår jag äntligen varför dashs utdata med set -x var så trasig — det inkluderade innehållet i den resulterande konfigurationen.

Det är viktigt att förstå att den fullständiga VCL-konfigurationen ofta kan bestå av flera filer. Kommentarer i C-stil används för att ange var en konfigurationsfil har inkluderats i en annan, och det är precis vad den följande kodsnutten handlar om.
Syntaxen för kommentarer som beskriver inkluderade filer har följande format:

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

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

Vad händer egentligen i träsket av kommandon som börjar på rad 116?
Låt oss reda ut det.
Kommandot består av fyra delar:

1. En enkel echo, som visar värdet av variabeln ${VCL_SHOW}

   echo "$VCL_SHOW"

2. awk, som letar efter en rad (post) där det första fältet, efter att texten har delats upp, är “//”, och det andra är ”VCL.SHOW”.
   Awk kommer att skriva ut den första raden som matchar dessa mönster och stoppa bearbetningen omedelbart.

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

3. Kodblocket som sparar värdena från fälten, separerade med mellanslag, i fem variabler. Den femte variabeln FILE får resten av raden. Slutligen skriver det sista echo ut innehållet i variabeln ${FILE}.

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

4. Eftersom alla steg från 1 till 3 är inneslutna i en sub-shell, kommer värdet av $FILE att skrivas till variabeln. VCL_FILE.

Som nämnts i kommentaren på rad 119, har detta ett enda syfte: att på ett tillförlitligt sätt hantera fall där VCL hänvisar till filer med mellanslag i namnet.

Jag kommenterade ut den ursprungliga logiken för behandling av ${VCL_FILE} och försökte ändra kommandosekvensen, men det ledde ingenstans. Allt fungerade bra för mig, men när tjänsten kördes gav den ett fel.

Det verkar som att felet helt enkelt inte är reproducerbart när skriptet körs manuellt, med de föreslagna 30 minuterna har redan passerat sex gånger, och dessutom har en mer prioriterad uppgift dykt upp som sköt undan de andra arbetsuppgifterna. Den återstående delen av veckan var full av olika uppgifter och endast lite avbruten av en presentation om sed och en intervju med en kandidat. Problemet med felet i varnishreload har oåterkalleligt gått förlorad i tidens sand.

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

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

Eftersom den senaste gången en enkel kodändring inte hjälpte, bestämde jag mig för att skriva om den från och med rad 116. I vilket fall som helst var den befintliga koden ganska bristfällig. Och det finns absolut inget behov av att använda läs.

Ser på felet igen:
sh: echo: broken pipe — i det här kommandot finns echo på två ställen, men jag misstänker att det första är den mest troliga skyldige (eller åtminstone medbrottslingen). Awk verkar också tveksamt. Och om det verkligen är awk | {read; echo} konstruktionen som orsakar alla dessa problem, varför inte ersätta den? Detta enradiga kommando utnyttjar inte alla möjligheter med awk, och dessutom är det denna överflödiga läs som tillägg.

Eftersom det förra veckan var en presentation om sed, ville jag försöka mina nyligen förvärvade färdigheter och förenkla echo | awk | { read; echo} till en mer begriplig echo | sed. Även om detta definitivt inte är den bästa metoden för att identifiera felet, tänkte jag att jag i alla fall skulle prova mitt sed-fu och kanske lära mig något nytt om problemet. Under arbetets gång bad jag min kollega, som är författare till presentationen om sed, att hjälpa mig att komma på ett mer effektivt sed-skript.

Jag skickade innehållet varnishadm vcl.show -v "$VCL_NAME" till en fil, så att jag kunde fokusera på att skriva sed-skriptet utan några störningar relaterade till omstart av tjänsten.

En kort beskrivning av hur sed hanterar indata finns i hans GNU-guide. I sed:s källkod anges symbolen n uttryckligt som avskiljare för rader.

Genom flera iterationer och med rekommendationer från min kollega skrev vi ett sed-skript som gav samma resultat som hela den ursprungliga raden 116.

Nedan följer ett exempel på en fil med indata:

> cat vcl-example.vcl
Text
// VCL.SHOW 0 1578 file with 3 spaces.vcl
Mer text
// VCL.SHOW 0 1578 file.vcl
Ännu mer text
// VCL.SHOW 0 1578 file with TWOspaces.vcl
Sluttext

Detta kanske inte är uppenbart från beskrivningen ovan, men vi är endast intresserade av den första kommentaren // VCL.SHOW, och i indata kan det finnas flera. Just därför avslutar den ursprungliga awk sin körning efter den första matchningen.

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

Den ovan nämnda logiken kan kort uttryckas på följande sätt:
Om strängen matchar det reguljära uttrycket // VCL.SHOW, då, girigt konsumera texten som inkluderar båda siffrorna i denna sträng och spara allt som återstår efter denna operation. Återge det sparade värdet och avsluta programmet.

Enkelt, eller hur?

Vi var nöjda med sed-skriptet och det faktum att det ersätter hela den ursprungliga koden. Alla mina tester gav önskat resultat, så jag ändrade "varnishreload" på servern och startade om igen systemctl reload varnish. En elak fel echo: skrivfel: Brott X pipen skrattade återigen oss i ansiktet. Den blinkande markören väntade på att få en ny kommando i den mörka tomheten av terminalen…

Källa: habr.com