Faldet ned i kaninhullet: En historie om en fejl ved genstart af varnish - del 1

ghostinushanka, mens han trykkede på knapperne i de sidste 20 minutter, som om hans liv hang på det, vender han sig mod mig med et halvvildt blik og et listigt smil - «Mand, jeg tror, jeg har forstået det.»

«Se lige her,» siger han og peger på et af symbolerne på skærmen - «Vi satser på min røde hat, at hvis vi tilføjer det, jeg lige har sendt dig» - pegede på et andet stykke kode - «vil fejlen ikke længere vises.»

Lidt forvirret og træt ændrer jeg sed-udtrykket, som vi har arbejdet på i et stykke tid, gemmer filen og kører systemctl varnish reload. Fejlmeddelelsen forsvandt…

«Mailene, jeg udvekslede med kandidaten,» fortsatte min kollega, mens hans smil udvikler sig til et ægte smil fyldt med glæde, «går det pludselig op for mig, at det præcist er det samme problem!»

Hvordan det hele begyndte

Artiklen forudsætter en forståelse af principperne bag bash, awk, sed og systemd. Kendskab til varnish er velkomment, men ikke påkrævet.
Tidsstemplerne i snippets er ændret.
Skrevet sammen med ghostinushanka.
Den tekst er en oversættelse af originalen, der blev udgivet på engelsk for to uger siden; oversættelsen boikoden.

Solen skinner gennem panoramavinduerne på endnu en varm efterårs morgen, en kop nydelsesfuld koffeinholdig drik hviler ved siden af tastaturet, yndlingssymfonien spiller i hovedtelefonerne, som overdøver lyden af mekaniske tastaturer, og den første post på listen over tickets i backloggen på kanban-tavlen lyser legende op med den skæbnetitel “Undersøg varnishreload sh: echo: I/O error in staging” (Undersøg “varnishreload sh: echo: I/O error” i staging). Når det kommer til varnish, er der ikke plads til fejl, selvom de ikke resulterer i problemer, som i dette tilfælde.

For dem, der ikke er bekendt med varnishreload, det er et simpelt shell-script, der bruges til at genstarte konfigurationen varnish — også kaldet VCL.

Som navnet på ticketen antyder, opstod fejlen på en af serverne på stagen, og da jeg var sikker på, at routing af varnish på stagen fungerede korrekt, antog jeg, at det ville være en mindre fejl. Så bare en melding, der kom ind i en allerede lukket output-strøm. Jeg tager ticketen for mig selv, i fuld tillid til, at jeg ville markere den som færdig på mindre end 30 minutter, klappe mig selv på skulderen for at rense boardet for endnu en klump og vende tilbage til vigtigere opgaver.

Kollision med en væg ved 200 km/t

Da jeg åbnede filen varnishreload, på en af serverne, der kører Debian Stretch, så jeg et shell-script på mindre end 200 linjer.

Da jeg hurtigt gennemgik scriptet, fandt jeg ikke noget, der kunne føre til problemer ved gentagen udførelse direkte fra terminalen.

I sidste ende er det en stage; selv hvis det går i stykker, vil ingen klage, nå… ikke for meget. Jeg kører scriptet og ser hvad der skrives til terminalen, men der er ikke længere nogen fejl.

Bare et par kørsel for at sikre, at jeg ikke kan reproducere fejlen uden yderligere anstrengelser, og jeg begynder at tænke på, hvordan jeg kan ændre dette script og få det til at fejle.

Skal jeg nægte scriptet STDOUT (ved hjælp af > &-)? Eller STDERR? Ingen af delene virkede til sidst.

Åbenbart ændrer systemd på en eller anden måde runtime-miljøet, men hvordan, og hvorfor?
Jeg åbner vim og redigerer varnishreload, tilføjer set -x lige under shebang, i håbet om, at debug-outputtet fra scriptet vil kaste lidt lys.

Filen er rettet, så jeg genstarter varnish og ser, at ændringen fuldstændig har ødelagt alt... Output - en total rod, med tonsvis af C-lignende kode. Selv rullemulighederne i terminalen er ikke nok til at finde ud af, hvor det begynder. Jeg er helt forvirret. Kan debug-tilstand påvirke driften af programmer, der køres i scriptet? Nej, det er vanvittigt. En fejl i shellet? Flere mulige scenarier løber gennem mit hoved som kakerlakker i forskellige retninger. En kop kaffe-fyldt drik tømmes øjeblikkeligt, en hurtig tur til køkkenet for at fylde op, og... lad os gå. Jeg åbner scriptet og ser nærmere på shebang: #!/bin/sh.

/bin/sh — det er jo bare et symbolsk link til bash, så scriptet fortolkes i POSIX-kompatibel mode, ikke? Ikke rigtigt! Standard shell i Debian er dash, og det er præcis det, som refereres der til /bin/sh.

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

For sjov skyld ændrede jeg shebang til #!/bin/bash, slettede set -x og prøvede igen. Endelig, ved den efterfølgende genstart af varnish, dukkede der en fornuftig fejl op i outputtet:

Jan 01 12:00:00 hostname varnishreload[32604]: /usr/sbin/varnishreload: linje 124: echo: skrivefejl: Broken pipe
Jan 01 12:00:00 hostname varnishreload[32604]: VCL 'reload_20190101_120000_32604' blev kompilert

Linje 124, dér er 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                         # alt dette ceremonielle for at håndtere mellemrum i FIL
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 "fejl ved at hente VCL filnavn"
129         fi
130
131         echo "$VCL_FILE"
132 }

Men som det viste sig, er linje 124 ret tom og uden interesse. Jeg kunne kun forudsige, at fejlen opstod som del af en multiline, der begyndte på linje 116.
Hvad bliver så gemt i variablen VCL_FILE som resultatet af ovenstående undershell udførelse?

I starten sender den indholdet af variablen VLC_SHOW, der blev oprettet på linje 115, til den næste kommando gennem en pipe. Hvad sker der der?

For det første bruges varnishadm, som er en del af installationspakken varnish, til at konfigurere varnish uden genstart.

Subkommandoen vcl.show -v bruges til at udskrive hele VCL-konfigurationen angivet i ${VCL_NAME}, i STDOUT.

For at vise den aktuelle aktive VCL-konfiguration samt nogle tidligere versioner af varnish routingkonfigurationer, der stadig er i hukommelsen, kan man bruge kommandoen varnishadm vcl.list, hvis output vil være lig det nedenfor:

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ærdien af variablen ${VCL_NAME} sættes i en anden del af scriptet varnishreload til navnet på det aktive VCL lige nu, hvis nogen. I dette tilfælde vil det være “reload_20190101_120000_12397”.

Fint, variablen ${VCL_SHOW} indeholder den samlede konfiguration for varnish, hvilket er klart nu. Nu forstår jeg endelig, hvorfor dash-uddataene med set -x var så ødelagte — de inkluderede indholdet af den resulterende konfiguration.

Det er vigtigt at forstå, at den fulde VCL-konfiguration ofte kan blive sammensat af flere filer. Komentarer i C-stil bruges til at angive, hvor nogle konfigurationsfiler er inkluderet i andre, og det er netop det, som den følgende kodefragment handler om.
Syntaksen for kommentarer, der beskriver inkluderede filer, har følgende format:

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

Tallene er ikke vigtige i denne kontekst, det er filnavnet, vi er interesserede i.

Hvad foregår der så i bunden af kommandoerne, der starter på linje 116?
Lad os finde ud af det.
Kommandoen består af fire dele:

1. Simpel echo, som viser værdien af variablen ${VCL_SHOW}

   echo "$VCL_SHOW"

2. awk, som leder efter en linje (post), hvor det første felt, efter opdeling af teksten, vil være “//”, og det andet vil være „VCL.SHOW“.
   Awk vil udskrive den første linje, der matcher disse mønstre, og derefter straks stoppe behandlingen.

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

3. Kodeblokken, der gemmer værdierne fra felter, adskilt af mellemrum, i fem variabler. Den femte variabel FILE får resten af linjen. Til sidst udskriver den sidste echo indholdet af variablen ${FILE}.

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

4. Da alle trin fra 1 til 3 er indkapslet i en subshell, bliver værdien af $FILE gemt i variablen. VCL_FILE.

Som det fremgår af kommentaren på linje 119, tjener dette kun ét formål: pålideligt at håndtere tilfælde, hvor VCL henviser til filer med mellemrum i navnet.

Jeg har kommenteret den oprindelige behandlingslogik for ${VCL_FILE} og har forsøgt at ændre rækkefølgen af kommandoerne, men det førte ingen vegne. Alt fungerede fint, men ved servicekørslen opstod der en fejl.

Det ser ud til, at fejlen simpelthen ikke kan reproduceres ved manuel kørselsafvikling af scriptet; de påståede 30 minutter er allerede blevet til seks gange, og derudover kom der en mere presserende opgave, som skubbede de andre opgaver til side. Den resterende del af ugen var fyldt med forskellige opgaver og blev kun let afvekslet med en præsentation om sed og et interview med en kandidat. Problemet med fejlen i varnishreload blev uigenkaldeligt tabt i tidens sand.

Din såkaldte sed-fu... er i virkeligheden... skrammel.

I næste uge havde jeg en dag med ret god tid, så jeg besluttede mig for at tage fat på denne ticket igen. Jeg håbede, at min hjerne havde haft en baggrundsproces kørende, der hele tiden søgte efter en løsning på dette problem, og at jeg denne gang virkelig ville forstå, hvad problemet var.

Da det sidste simple kodeændring ikke hjalp, besluttede jeg mig for at gen skrive det fra linje 116. Uanset hvad, var den eksisterende kode ret klodset. Og der var overhovedet ingen grund til at bruge write.

Når jeg ser på fejlen igen:
sh: echo: broken pipe – i denne kommando er echo nævnt to gange, men jeg mistænker, at den første er den mest sandsynlige skyldige (eller i det mindste en medskyldig). Awk giver mig heller ikke tillid. Og i tilfælde af at det virkelig er awk | {read; echo} konstruktionen der fører til alle disse problemer, hvorfor så ikke erstatte den? Denne linje-kommando bruger ikke alle mulighederne i awk, og så er der den unødvendige write tilføjelse.

Da der var en præsentation i sidste uge om sed, ville jeg prøve mine nyerhvervede færdigheder og forenkle echo | awk | { read; echo} til en mere forståelig echo | sed. Selvom det bestemt ikke er den bedste tilgang til at finde fejlen, tænkte jeg, at jeg i det mindste ville prøve mit sed-fu og måske lære noget nyt om problemet. Undervejs bad jeg min kollega, som var forfatter til præsentationen om sed, om hjælp til at finde et mere effektivt sed-script.

Jeg sendte indholdet af varnishadm vcl.show -v "$VCL_NAME" til en fil, så jeg kunne fokusere på at skrive sed-scriptet uden at bekymre mig om service genstarter.

En kort beskrivelse af, hvordan sed præcist behandler inputdata, findes i dets GNU-håndbog. I kildeteksterne er symbolet n klart angivet som en linjeskille.

Gennem flere forsøg og med anbefalinger fra min kollega skrev vi et sed-script, der gav samme resultat som hele den oprindelige række 116.

Nedenfor er et eksempel på en fil med inputdata:

> cat vcl-example.vcl
Text
// VCL.SHOW 0 1578 fil med 3 mellemrum.vcl
Mere tekst
// VCL.SHOW 0 1578 fil.vcl
Endnu mere tekst
// VCL.SHOW 0 1578 fil med TOmellemrum.vcl
Afsluttende tekst

Det er måske ikke åbenlyst ud fra den ovenstående beskrivelse, men vi er kun interesseret i den første kommentar // VCL.SHOW, og i inputdataene kan der være flere. Derfor afslutter den originale awk sit arbejde efter det første match.

# шаг первый, вывести только строки с комментариями
# используя возможности 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å indholdet af scriptet varnishreload vil se nogenlunde sådan her ud:

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

Den ovenstående logik kan kort udtrykkes som følger:
Hvis strengen matcher regulært udtryk // VCL.SHOW, så fortær grådigt teksten, der inkluderer begge tal i denne streng, og gem alt, hvad der er tilbage efter denne operation. Returnér den gemte værdi og afslut programmet.

Simpelt, ikke sandt?

Vi var tilfredse med sed-scriptet og det faktum, at det erstatter hele den originale kode. Alle mine tests gav de ønskede resultater, så jeg ændrede "varnishreload" på serveren og genstartede systemctl reload varnish. En elendig fejl echo: skrivefejl: Broken pipe lo alle grinede i vores ansigt. Den blinkende cursor ventede på input af ny kommando i den mørke tomhed af terminalen…

Kilde: habr.com