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

ghostinushanka, efter at have hamret løs på knapperne i de foregående 20 minutter, som om hans liv afhang af det, vender han sig mod mig med et halvvildt blik i øjnene og et snedigt grin - "Dude, I think I got it."

"Se her," siger han og peger på et af symbolerne på skærmen, "jeg vil vædde med min røde hat, at hvis vi tilføjer her, hvad jeg lige har sendt dig," og peger på en anden kodesektion, "vil fejlen ikke længere være vil blive vist."

Lidt forundret og træt ændrer jeg det sed-udtryk, vi har arbejdet på i et stykke tid, gemmer filen og kører systemctl varnish reload. Fejlmeddelelsen er forsvundet...

"De e-mails, jeg udvekslede med kandidaten," fortsatte min kollega, mens hans grin voksede til et ægte smil af glæde, "det gik pludselig op for mig, at det er præcis det samme problem!"

Hvordan det hele begyndte

Artiklen forudsætter en forståelse af, hvordan bash, awk, sed og systemd fungerer. Kendskab til lak er at foretrække, men ikke et krav.
Tidsstempler i uddrag er blevet ændret.
Skrevet med ghostinushanka.
Denne tekst er en oversættelse af originalen udgivet på engelsk for to uger siden; oversættelse boikoden.

Solen skinner gennem panoramavinduerne en anden varm efterårsmorgen, en kop frisklavet koffeinrig drik hviler væk fra tastaturet, din yndlingssymfoni af lyde lyder i dine hovedtelefoner, overdøver raslen fra mekaniske keyboards, og den første indgang i listen over backlog-billetter på Kanban-tavlen lyser legendeligt med den skæbnesvangre titel "Investigate varnishreload" sh: echo: I/O error in staging" (Undersøg "varnishreload sh: echo: I/O error" i staging). Når det kommer til lak, er der og kan ikke være plads til fejl, selvom de ikke giver problemer som i dette tilfælde.

For dem, der ikke er bekendt med fernishreload, dette er et simpelt shell-script, der bruges til at genindlæse konfigurationen lak - også kaldet VCL.

Som titlen på billetten antyder, opstod fejlen på en af ​​serverne på scenen, og da jeg var sikker på, at lakrutingen på scenen fungerede korrekt, gik jeg ud fra, at dette ville være en mindre fejl. Altså bare en besked, der endte i en allerede lukket outputstrøm. Jeg tager billetten for mig selv, i fuld tillid til, at jeg vil markere den klar om mindre end 30 minutter, klapper mig selv på skulderen for at rydde tavlen for endnu et vrøvl og vender tilbage til vigtigere sager.

Kørte ind i en mur med 200 km/t

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

Efter at have gennemgået scriptet, bemærkede jeg ikke noget, der kunne resultere i problemer, når jeg kørte det flere gange direkte fra terminalen.

Det er jo en etape, selvom den går i stykker, vil ingen brokke sig, ja... ikke for meget. Jeg kører scriptet og ser, hvad der bliver skrevet til terminalen, men fejlene er ikke længere synlige.

Et par kørsler mere for at sikre, at jeg ikke kan genskabe fejlen uden yderligere indsats, og jeg er begyndt at finde ud af, hvordan jeg ændrer dette script og får det til at give en fejl.

Kan scriptet tilsidesætte STDOUT (ved hjælp af > &-)? Eller STDERR? Ingen af ​​disse virkede i sidste ende.

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

Filen er rettet, så jeg genindlæser lak og ser at ændringen fuldstændig knækkede alt... Udstødningen er et komplet rod, hvori der er tonsvis af C-lignende kode. Selv scrollning i terminalen er ikke nok til at finde, hvor den starter. Jeg er fuldstændig forvirret. Kan fejlretningstilstand påvirke driften af ​​programmer, der startes i et script? Nej, det er noget sludder. Fejl i skallen? Flere mulige scenarier suser gennem mit hoved som kakerlakker i forskellige retninger. Koffein-drikkoppen tømmes øjeblikkeligt, en hurtig tur i køkkenet for at fylde lageret op og... så er vi i gang. Jeg åbner scriptet og ser nærmere på shebang: #!/bin/sh.

/bin/sh - dette er blot et symbollink til bash, så scriptet fortolkes i POSIX-kompatibel tilstand, ikke? Ikke så! Standardskallen på Debian er bindestreg, og det er præcis, hvad det ser ud. henviser /bin/sh.

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

Som en test ændrede jeg shebang til #!/bin/bash, slettet set -x og prøvede igen. Endelig, ved efterfølgende genstart af lak, dukkede en acceptabel fejl op i outputtet:

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, her er 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 viser sig, er linje 124 ret tom og uden interesse. Jeg kunne kun antage, at fejlen opstod som en del af en flerlinjestreng, der startede på linje 116.
Hvad skrives i sidste ende til variablen? VCL_FILE som et resultat af at udføre ovenstående sub-shell?

I begyndelsen sender den indholdet af variablen VLC_SHOW, oprettet på linje 115, efter kommandoen gennem røret. Og hvad sker der så der?

For det første bruges det der varnishadm, som er en del af lakinstallationspakken, til opsætning af lak uden genstart.

Underhold vcl.show -v bruges til at udlæse hele VCL-konfigurationen specificeret i ${VCL_NAME}, til STDOUT.

For at vise den aktuelle aktive VCL-konfiguration, samt flere tidligere versioner af lak-routing-konfigurationer, der stadig er i hukommelsen, kan du bruge kommandoen varnishadm vcl.list, hvis output vil ligne nedenstående:

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

Variabel værdi ${VCL_NAME} er installeret i en anden del af scriptet varnishreload til navnet på den aktuelt aktive VCL, hvis der er en. I dette tilfælde vil det være "reload_20190101_120000_12397".

Fantastisk, varierende ${VCL_SHOW} indeholder komplet konfiguration til lak, klar for nu. Nu forstår jeg endelig, hvorfor streg-output er set -x viste sig at være så ødelagt - det inkluderede indholdet af den resulterende konfiguration.

Det er vigtigt at forstå, at en komplet VCL-konfiguration ofte kan flettes sammen fra flere filer. Kommentarer i C-stil bruges til at identificere, hvor visse konfigurationsfiler er inkluderet i andre, og det er, hvad den følgende linje med kodestykke handler om.
Syntaksen for kommentarer, der beskriver inkluderede filer, er i følgende format:

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

Tallene er ikke vigtige i denne sammenhæng, vi er interesserede i filnavnet.

Hvad sker der i sidste ende i sumpen af ​​kommandoer, der starter på linje 116?
Lad os finde ud af det.
Teamet består af fire dele:

1. simpel echo, som udskriver værdien af ​​variablen ${VCL_SHOW}

   echo "$VCL_SHOW"

2. awk, som leder efter en linje (record), hvor det første felt, efter at have brudt teksten, er "//", og det andet er "VCL.SHOW".
   Awk vil udskrive den første linje, der matcher disse mønstre, og derefter stoppe behandlingen med det samme.

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

3. En kodeblok, der gemmer feltværdier i fem variable, adskilt af mellemrum. Den femte FILE-variabel modtager resten af ​​linjen. Til sidst skriver det sidste ekko indholdet af variablen ud ${FILE}.

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

4. Da alle trin 1 til 3 er indesluttet i en subshell, udsender værdien $FILE vil blive skrevet til en variabel VCL_FILE.

Som kommentaren på linje 119 antyder, tjener dette det ene formål med pålidelig håndtering af sager, hvor VCL vil referere til filer med mellemrum i deres navne.

Jeg har kommenteret den oprindelige behandlingslogik for ${VCL_FILE} og forsøgte at ændre kommandosekvensen, men det førte ikke til noget. Alt fungerede fint for mig, men da jeg startede tjenesten, gav den en fejl.

Det ser ud til, at fejlen simpelthen ikke kan reproduceres, når man kører scriptet manuelt, mens de formodede 30 minutter allerede er udløbet seks gange, og derudover er en højere prioriteret opgave dukket op, som har skubbet andre ting til side. Resten af ​​ugen var fyldt med en række opgaver og blev kun lidt udvandet af en rapport om sed og et interview med en kandidat. Problem med fejl i varnishreload var uigenkaldeligt tabt i tidens sand.

Din såkaldte sed-fu... er faktisk... vrøvl

Den næste uge havde jeg en ret fri dag, så jeg besluttede at tage fat på denne billet igen. Jeg håbede, at i min hjerne havde en eller anden baggrundsproces ledt efter en løsning på dette problem hele tiden, og denne gang ville jeg helt sikkert forstå, hvad der foregik.

Da blot at ændre koden ikke hjalp sidste gang, besluttede jeg bare at omskrive den fra linje 116. Under alle omstændigheder var den eksisterende kode dum. Og der er absolut ingen grund til at bruge det read.

Ser på fejlen igen:
sh: echo: broken pipe — echo vises to steder i denne kommando, men jeg formoder, at den første er den mest sandsynlige skyldige (eller i det mindste en medskyldig). Awk vækker heller ikke tillid. Og hvis det virkelig er awk | {read; echo} designet fører til alle disse problemer, hvorfor ikke erstatte det? Denne kommando på én linje bruger ikke alle funktionerne i awk, og endda denne ekstra read ud over.

Siden sidste uge var der en rapport vedr sed, jeg ville prøve mine nyerhvervede færdigheder og forenkle echo | awk | { read; echo} til en mere forståelig echo | sed. Selvom dette bestemt ikke er den bedste tilgang til at identificere fejlen, tænkte jeg, at jeg i det mindste ville prøve min sed-fu og måske lære noget nyt om problemet. Undervejs bad jeg min kollega, forfatteren af ​​sed-talen, om at hjælpe mig med at komme med et mere effektivt sed-manuskript.

Jeg tabte indholdet varnishadm vcl.show -v "$VCL_NAME" til en fil, så jeg kunne fokusere på at skrive sed-scriptet uden besvær med genstart af tjenesten.

En kort beskrivelse af præcis hvordan sed behandler input kan findes i hans GNU-manual. I sed-kilderne symbolet n eksplicit angivet som en linjeseparator.

I flere omgange og med anbefalinger fra min kollega skrev vi et sed-script, der gav det samme resultat som hele den originale linje 116.

Nedenfor er en eksempelfil med inputdata:

> 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

Dette er måske ikke indlysende fra beskrivelsen ovenfor, men vi er kun interesseret i den første kommentar // VCL.SHOW, og der kan være flere af dem i inputdataene. Det er derfor, den originale awk slutter efter den første kamp.

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

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

Ovenstående logik kan kort udtrykkes som følger:
Hvis strengen matcher et regulært udtryk // VCL.SHOW, fortær derefter grådigt teksten, der indeholder begge tal på denne linje, og gem alt, der er tilbage efter denne handling. Send den gemte værdi og afslut programmet.

Simpelt, er det ikke?

Vi var glade for sed-scriptet og det faktum, at det erstattede al den originale kode. Alle mine test gav de ønskede resultater, så jeg ændrede "varnishreload" på serveren og kørte den igen systemctl reload varnish. Dårlig fejl echo: write error: Broken pipe grinede os i ansigtet igen. Den blinkende markør ventede på, at en ny kommando skulle indtastes i terminalens mørke tomhed...

Kilde: www.habr.com