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

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

ghostinushanka, etter å ha hamret løs på knappene de siste 20 minuttene som om livet hans var avhengig av det, snur han seg mot meg med et halvvillt blikk i øynene og et lurt glis - "Dude, I think I got it."

"Se her," sier han og peker på et av symbolene på skjermen, "jeg vedder på at hvis vi legger til det jeg nettopp sendte deg her," og peker på en annen kodedel, "vil feilen ikke lenger være vil vises."

Litt rådvill og sliten endrer jeg sed-uttrykket vi har jobbet med en stund, lagrer filen og kjører systemctl varnish reload. Feilmeldingen har forsvunnet...

"E-postene jeg utvekslet med kandidaten," fortsatte min kollega, mens smilet hans vokste til et ekte smil av glede, "det gikk plutselig opp for meg at dette er akkurat det samme problemet!"

Hvordan det hele begynte

Artikkelen forutsetter en forståelse av hvordan bash, awk, sed og systemd fungerer. Kunnskap om lakk er foretrukket, men ikke nødvendig.
Tidsstempler i utdrag er endret.
Skrevet med ghostinushanka.
Denne teksten er en oversettelse av originalen publisert på engelsk for to uker siden; oversettelse boikoden.

Solen skinner gjennom panoramavinduene en annen varm høstmorgen, en kopp nylaget koffeinrik drikke hviler borte fra tastaturet, favorittsymfonien av lyder høres i hodetelefonene, overdøver suset fra mekaniske tastaturer, og den første inngangen i listen over backlog-billetter på Kanban-tavlen gløder lekende med den skjebnesvangre tittelen "Undersøk varnishreload" sh: echo: I/O error in staging" (Undersøk "varnishreload sh: echo: I/O error" i staging). Når det gjelder lakk er det og kan ikke være rom for feil, selv om de ikke gir noen problemer som i dette tilfellet.

For de som ikke er kjent med lakkering, dette er et enkelt shell-skript som brukes til å laste inn konfigurasjonen på nytt lakk - også kalt VCL.

Som tittelen på billetten antyder, oppsto feilen på en av serverne på scenen, og siden jeg var sikker på at lakkrutingen på scenen fungerte som den skulle, antok jeg at dette ville være en mindre feil. Så, bare en melding som havnet i en allerede lukket utgangsstrøm. Jeg tar lappen for meg selv, i full tillit til at jeg skal merke den klar om mindre enn 30 minutter, klappe meg selv på skulderen for å ha ryddet brettet for enda et søppel og kommer tilbake til viktigere saker.

Kræsjer inn i en vegg i 200 km/t

Åpner filen varnishreload, på en av serverne som kjører Debian Stretch, så jeg et skallskript på mindre enn 200 linjer.

Etter å ha gått gjennom skriptet, la jeg ikke merke til noe som kunne resultere i problemer når jeg kjørte det flere ganger direkte fra terminalen.

Dette er tross alt en etappe, selv om den går i stykker vil ingen klage, vel... ikke for mye. Jeg kjører skriptet og ser hva som blir skrevet til terminalen, men feilene er ikke lenger synlige.

Et par kjøringer til for å sikre at jeg ikke kan gjenskape feilen uten ekstra innsats, og jeg begynner å finne ut hvordan jeg kan endre dette skriptet og få det til å gi en feil.

Kan skriptet overstyre STDOUT (ved å bruke > &-)? Eller STDERR? Ingen av disse fungerte til slutt.

Tilsynelatende modifiserer systemd oppstartsmiljøet på en eller annen måte, men hvordan og hvorfor?
Jeg åpner vim og redigerer varnishreload, legger til set -x rett under shebang, i håp om at feilsøkingsutgangen til skriptet vil kaste lys.

Filen er rettet, så jeg laster inn lakk på nytt og ser at endringen brøt alt fullstendig... Eksosen er et komplett rot, der det er tonnevis med C-lignende kode. Selv rulling i terminalen er ikke nok til å finne hvor den starter. Jeg er helt forvirret. Kan feilsøkingsmodus påvirke driften av programmer som lanseres i et skript? Nei, det er tull. Feil i skallet? Flere mulige scenarier raser gjennom hodet mitt som kakerlakker i forskjellige retninger. Koffeinbegeret tømmes øyeblikkelig, en kjapp tur til kjøkkenet for å fylle på lageret og... så drar vi. Jeg åpner manuset og ser nærmere på shebang: #!/bin/sh.

/bin/sh - dette er bare en symbolkobling til bash, så skriptet tolkes i POSIX-kompatibel modus, ikke sant? Ikke så! Standardskallet på Debian er bindestrek, og det er akkurat slik det ser ut. refererer /bin/sh.

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

Som en test endret jeg shebang til #!/bin/bash, slettet set -x og prøvde igjen. Til slutt, ved påfølgende omstart av lakk, dukket det opp en tolerabel feil i utdataene:

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 seg, er linje 124 ganske tom og uten interesse. Jeg kunne bare anta at feilen oppstod som en del av en flerlinjestreng som startet på linje 116.
Hva skrives til slutt til variabelen? VCL_FILE som et resultat av å utføre underskallet ovenfor?

I begynnelsen sender den innholdet i variabelen VLC_SHOW, opprettet på linje 115, etter kommandoen gjennom røret. Og hva skjer der da?

For det første brukes det der varnishadm, som er en del av lakkinstallasjonspakken, for å sette opp lakk uten å starte på nytt.

Underlag vcl.show -v brukes til å sende ut hele VCL-konfigurasjonen spesifisert i ${VCL_NAME}, til STDOUT.

For å vise gjeldende aktive VCL-konfigurasjon, samt flere tidligere versjoner av lakkrutingskonfigurasjoner som fortsatt er i minnet, kan du bruke kommandoen varnishadm vcl.list, hvis utgang vil være lik den 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

Variabel verdi ${VCL_NAME} er installert i en annen del av skriptet varnishreload til navnet på den aktive VCL-en, hvis det er en. I dette tilfellet vil det være "reload_20190101_120000_12397".

Flott, variabel ${VCL_SHOW} inneholder komplett konfigurasjon for lakk, klar for nå. Nå forstår jeg endelig hvorfor dash-utgangen er set -x viste seg å være så ødelagt - det inkluderte innholdet i den resulterende konfigurasjonen.

Det er viktig å forstå at en komplett VCL-konfigurasjon ofte kan flettes sammen fra flere filer. Kommentarer i C-stil brukes til å identifisere hvor visse konfigurasjonsfiler har blitt inkludert i andre, og det er hva den følgende linjen med kodebit handler om.
Syntaksen for kommentarer som beskriver inkluderte filer er i følgende format:

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

Tallene er ikke viktige i denne sammenhengen, vi er interessert i filnavnet.

Hva skjer til slutt i sumpen av kommandoer som starter på linje 116?
La oss finne ut det.
Teamet består av fire deler:

  1. enkel echo, som skriver ut verdien til variabelen ${VCL_SHOW} 
    echo "$VCL_SHOW"
  2. awk, som ser etter en linje (post) der det første feltet, etter å ha brutt teksten, er "//", og det andre er "VCL.SHOW".
    Awk vil skrive ut den første linjen som samsvarer med disse mønstrene og deretter stoppe behandlingen umiddelbart.

    awk '$1 == "//" && $2 == "VCL.SHOW" {print; exit}'
  3. En kodeblokk som lagrer feltverdier i fem variabler, atskilt med mellomrom. Den femte FILE-variabelen mottar resten av linjen. Til slutt skriver det siste ekkoet ut innholdet i variabelen ${FILE}. 
    { read -r DELIM VCL_SHOW INDEX SIZE FILE; echo "$FILE" }
  4. Siden alle trinn 1 til 3 er omsluttet av et subshell, gir verdien $FILE vil bli skrevet til en variabel VCL_FILE.

Som kommentaren på linje 119 antyder, tjener dette det eneste formålet å pålitelig håndtere saker der VCL vil referere til filer med mellomrom i navnene deres.

Jeg har kommentert den opprinnelige behandlingslogikken for ${VCL_FILE} og prøvde å endre kommandosekvensen, men det førte ikke til noe. Alt fungerte bra for meg, men da jeg startet tjenesten ga det en feil.

Det ser ut til at feilen rett og slett ikke er reproduserbar når man kjører skriptet manuelt, mens de antatte 30 minuttene allerede har utløpt seks ganger, og i tillegg har en høyere prioritert oppgave dukket opp som skyver andre saker til side. Resten av uken var fylt med en rekke oppgaver og ble bare litt utvannet av en rapport om sed og et intervju med en kandidat. Problem med feil i varnishreload var uopprettelig tapt i tidens sand.

Din såkalte sed-fu... er faktisk... søppel

Neste uke hadde jeg en ganske ledig dag, så jeg bestemte meg for å takle denne billetten igjen. Jeg håpet at i hjernen min hadde en eller annen bakgrunnsprosess lett etter en løsning på dette problemet hele denne tiden, og denne gangen ville jeg definitivt forstå hva som foregikk.

Siden det å endre koden ikke hjalp sist, bestemte jeg meg for å skrive den om fra linje 116. I alle fall var den eksisterende koden dum. Og det er absolutt ingen grunn til å bruke det read.

Ser på feilen igjen:
sh: echo: broken pipe — ekko vises to steder i denne kommandoen, men jeg mistenker at den første er den mest sannsynlige skyldige (eller i det minste en medskyldig). Awk vekker heller ikke tillit. Og i tilfelle det virkelig er det awk | {read; echo} designet fører til alle disse problemene, hvorfor ikke erstatte det? Denne enlinjekommandoen bruker ikke alle funksjonene til awk, og til og med denne ekstra read i tillegg.

Siden forrige uke var det en rapport om sed, jeg ønsket å prøve mine nyervervede ferdigheter og forenkle echo | awk | { read; echo} til en mer forståelig echo | sed. Selv om dette definitivt ikke er den beste tilnærmingen til å identifisere feilen, tenkte jeg at jeg i det minste skulle prøve sed-fu og kanskje lære noe nytt om problemet. Underveis spurte jeg min kollega, forfatteren av sed-talen, om å hjelpe meg med å komme opp med et mer effektivt sed-manus.

Jeg droppet innholdet varnishadm vcl.show -v "$VCL_NAME" til en fil, slik at jeg kunne fokusere på å skrive sed-skriptet uten problemer med omstart av tjenesten.

En kort beskrivelse av nøyaktig hvordan sed behandler input kan finnes i hans GNU-manual. I sed-kildene symbolet n eksplisitt spesifisert som linjeskilletegn.

I flere omganger og med anbefalinger fra min kollega skrev vi et sed-manus som ga samme resultat som hele den originale linje 116.

Nedenfor er en eksempelfil med inndata:

> 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 kanskje ikke åpenbart fra beskrivelsen ovenfor, men vi er kun interessert i den første kommentaren // VCL.SHOW, og det kan være flere av dem i inndataene. Dette er grunnen til at den originale awk slutter etter den første kampen.

# шаг первый, вывести только строки с комментариями
# используя возможности 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å innholdet i varnishreload-skriptet vil se omtrent slik ut:

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

Logikken ovenfor kan kort uttrykkes som følger:
Hvis strengen samsvarer med et regulært uttrykk // VCL.SHOW, fortær deretter grådig teksten som inkluderer begge tallene på denne linjen, og lagre alt som gjenstår etter denne operasjonen. Send ut den lagrede verdien og avslutt programmet.

Enkelt, ikke sant?

Vi var fornøyd med sed-skriptet og det faktum at det erstattet all den originale koden. Alle testene mine ga de ønskede resultatene, så jeg endret "varnishreload" på serveren og kjørte den på nytt systemctl reload varnish. Dårlig feil echo: write error: Broken pipe lo oss opp i ansiktet igjen. Den blinkende markøren ventet på en ny kommando som skulle legges inn i terminalens mørke tomhet...

Kilde: www.habr.com

Legg til en kommentar