ProHoster > Blog > Administrácia > Falling Down the Rabbit Hole: Príbeh jednej chyby pri reštartovaní laku - časť 1

Falling Down the Rabbit Hole: Príbeh jednej chyby pri reštartovaní laku - časť 1

ghostinushanka20 minút klepal na gombíky, akoby na tom závisel jeho život, a obráti sa na mňa s polodivokým pohľadom v očiach a šibalským úškrnom - "Ty vole, myslím, že som to pochopil."

„Pozrite sa sem,“ hovorí a ukazuje na jeden zo symbolov na obrazovke, „stavím sa, že ak sem pridáme to, čo som vám práve poslal,“ ukazuje na inú časť kódu, „chyba už nebude sa zobrazí."

Trochu zmätený a unavený upravím výraz sed, na ktorom sme chvíľu pracovali, uložím súbor a spustím systemctl varnish reload. Chybové hlásenie zmizlo...

"E-maily, ktoré som si vymenil s kandidátom," pokračoval môj kolega, keď jeho úsmev prerástol do skutočného úsmevu radosti, "Zrazu mi došlo, že je to presne ten istý problém!"

Ako to všetko začalo

Článok predpokladá pochopenie toho, ako fungujú bash, awk, sed a systemd. Znalosť laku je preferovaná, nie však nutná.
Časové pečiatky v úryvkoch boli zmenené.
Napísané s ghostinushanka.
Tento text je prekladom originálu uverejneného v angličtine pred dvoma týždňami; preklad boikoden.

Slnko svieti cez panoramatické okná v ďalšie teplé jesenné ráno, šálka čerstvo pripraveného nápoja bohatého na kofeín odpočíva od klávesnice, v slúchadlách znie vaša obľúbená symfónia zvukov, ktorá prehluší šuchot mechanických klávesníc, a prvý vstup v zozname backlog tiketov na nástenke Kanban hravo žiari osudným názvom “Investigatelakreload” sh: echo: I/O error in staging” (Investigate “varnishreload sh: echo: I/O error” in staging). Pri lakoch je a nemôže byť priestor na chyby, aj keď nespôsobujú žiadne problémy ako v tomto prípade.

Pre tých, ktorí nie sú oboznámení lakreload, toto je jednoduchý shell skript používaný na opätovné načítanie konfigurácie lak - nazývaný aj VCL.

Ako už názov tiketu napovedá, chyba nastala na jednom zo serverov na pódiu a keďže som si bol istý, že smerovanie laku na pódiu funguje správne, predpokladal som, že pôjde o drobnú chybu. Takže len správa, ktorá skončila v už uzavretom výstupnom toku. Beriem si lístok pre seba, s plnou dôverou, že ho označím za pripravený za menej ako 30 minút, potľapkám sa po pleci, že som vyčistil tabuľu od ďalšieho odpadu a vraciam sa k dôležitejším veciam.

Náraz do steny v rýchlosti 200 km/h

Otváranie súboru varnishreload, na jednom zo serverov so systémom Debian Stretch som videl skript shellu dlhý menej ako 200 riadkov.

Po prejdení skriptu som si nevšimol nič, čo by mohlo spôsobiť problémy pri jeho viacnásobnom spustení priamo z terminálu.

Toto je predsa etapa, aj keď sa to zlomí, nikto sa nebude sťažovať, no... nie príliš. Spustím skript a uvidím, čo sa zapíše do terminálu, ale chyby už nie sú viditeľné.

Ešte pár spustení, aby som sa uistil, že chybu nemôžem reprodukovať bez ďalšieho úsilia, a začínam zisťovať, ako zmeniť tento skript, aby stále vyvolával chybu.

Môže skript prepísať STDOUT (pomocou > &-)? Alebo STDERR? Ani jedno z toho nakoniec nefungovalo.

Systemd zrejme nejakým spôsobom upravuje spúšťacie prostredie, ale ako a prečo?
Otvorím vim a upravím varnishreload, pridávajúc set -x priamo pod šebangom, dúfajúc, že ​​ladiaci výstup skriptu vrhne trochu svetla.

Pilník je opravený, tak znovu načítam lak a vidím, že výmena úplne všetko rozbila... Výfuk je úplný neporiadok, v ktorom sú tony céčkového kódu. Ani rolovanie v termináli nestačí na to, aby ste zistili, kde začína. Som úplne zmätený. Môže režim ladenia ovplyvniť činnosť programov spúšťaných v skripte? Nie, je to nezmysel. Chyba v škrupine? Ako šváby sa mi hlavou preháňa niekoľko možných scenárov rôznymi smermi. Šálka ​​kofeínového nápoja sa okamžite vyprázdni, rýchly výlet do kuchyne doplniť zásoby a... ideme. Otváram scenár a bližšie sa pozerám na shebang: #!/bin/sh.

/bin/sh - toto je len symbolický odkaz na bash, takže skript je interpretovaný v režime kompatibilnom s POSIX, však? Nie tak! Predvolený shell v Debiane je dash a presne tak to vyzerá. odkazuje /bin/sh.

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

Ako test som zmenil shebang na #!/bin/bash, vymazané set -x a skúsil to znova. Nakoniec sa po následnom reštarte laku objavila vo výstupe tolerovateľná chyba:

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

Linka 124, tu je!

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 }

Ako sa však ukázalo, linka 124 je celkom prázdna a bez záujmu. Mohol som len predpokladať, že chyba nastala ako súčasť viacriadkového reťazca začínajúceho na riadku 116.
Čo sa nakoniec zapíše do premennej? VCL_FILE v dôsledku vykonania vyššie uvedeného sub-shell?

Na začiatku odošle obsah premennej VLC_SHOW, vytvorený na riadku 115 po príkaze cez potrubie. A čo sa tam potom stane?

Po prvé, tam sa používa varnishadm, ktorý je súčasťou inštalačného balíka laku, na nastavenie laku bez reštartovania.

Sub-tím vcl.show -v používa sa na výstup celej konfigurácie VCL špecifikovanej v ${VCL_NAME}, do STDOUT.

Ak chcete zobraziť aktuálnu aktívnu konfiguráciu VCL, ako aj niekoľko predchádzajúcich verzií konfigurácií smerovania laku, ktoré sú stále v pamäti, môžete použiť príkaz varnishadm vcl.list, ktorého výstup bude podobný nižšie uvedenému:

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

Variabilná hodnota ${VCL_NAME} je nainštalovaný v inej časti skriptu varnishreload na názov aktuálne aktívneho VCL, ak existuje. V tomto prípade to bude „reload_20190101_120000_12397“.

Skvelé, variabilné ${VCL_SHOW} obsahuje kompletnú konfiguráciu pre lak, zatiaľ číra. Teraz konečne chápem, prečo je výstup pomlčky set -x sa ukázalo byť tak rozbité - zahŕňalo obsah výslednej konfigurácie.

Je dôležité pochopiť, že úplná konfigurácia VCL môže byť často zostavená z niekoľkých súborov. Komentáre v štýle C sa používajú na identifikáciu toho, kde boli určité konfiguračné súbory zahrnuté do iných, a o tom je celý nasledujúci riadok úryvku kódu.
Syntax komentárov popisujúcich zahrnuté súbory je v nasledujúcom formáte:

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

Čísla v tomto kontexte nie sú dôležité, nás zaujíma názov súboru.

Čo sa nakoniec stane v bažine príkazov začínajúcich na riadku 116?
Priznajme si to.
Tím sa skladá zo štyroch častí:

  1. prostý echo, ktorý vypíše hodnotu premennej ${VCL_SHOW} 
    echo "$VCL_SHOW"
  2. awk, ktorý hľadá riadok (záznam), kde prvé pole je po rozdelení textu „//“ a druhé je „VCL.SHOW“.
    Awk vypíše prvý riadok zodpovedajúci týmto vzorom a potom okamžite zastaví spracovanie.

    awk '$1 == "//" && $2 == "VCL.SHOW" {print; exit}'
  3. Blok kódu, ktorý ukladá hodnoty polí do piatich premenných oddelených medzerami. Piata premenná FILE prijíma zvyšok riadku. Nakoniec posledné echo vypíše obsah premennej ${FILE}. 
    { read -r DELIM VCL_SHOW INDEX SIZE FILE; echo "$FILE" }
  4. Pretože všetky kroky 1 až 3 sú uzavreté v subshell, výstup hodnoty $FILE sa zapíše do premennej VCL_FILE.

Ako naznačuje komentár na riadku 119, slúži to výlučne na spoľahlivé riešenie prípadov, keď VCL bude odkazovať na súbory s medzerami v ich názvoch.

Pôvodnú logiku spracovania som okomentoval ${VCL_FILE} a pokúsil sa zmeniť postupnosť príkazov, ale k ničomu to neviedlo. Všetko mi fungovalo dobre, ale keď som spustil službu, vyskytla sa chyba.

Zdá sa, že chyba pri manuálnom spustení skriptu jednoducho nie je reprodukovateľná, pričom predpokladaných 30 minút už šesťkrát uplynulo a navyše sa objavila úloha s vyššou prioritou, ktorá odsúva ostatné záležitosti bokom. Zvyšok týždňa bol naplnený rôznymi úlohami a bol len mierne preriedený reportážou o sed a pohovorom s kandidátom. Problém s chybou v varnishreload bol nenávratne stratený v piesku času.

Tvoje takzvané sed-fu... je vlastne... svinstvo

Ďalší týždeň som mal jeden celkom voľný deň, tak som sa rozhodol opäť riešiť tento lístok. Dúfal som, že v mojom mozgu nejaký proces na pozadí celý ten čas hľadal riešenie tohto problému a tentoraz už určite pochopím, čo sa deje.

Keďže minule jednoduchá zmena kódu nepomohla, rozhodol som sa ho prepísať od riadku 116. V každom prípade bol existujúci kód hlúpy. A vôbec nie je potrebné ho používať read.

Znova sa pozrite na chybu:
sh: echo: broken pipe — ozvena sa v tomto príkaze objavuje na dvoch miestach, ale mám podozrenie, že prvé je pravdepodobnejší vinník (alebo aspoň spolupáchateľ). Awk tiež nevzbudzuje dôveru. A v prípade, že to tak naozaj je awk | {read; echo} dizajn vedie k všetkým týmto problémom, prečo ho nenahradiť? Tento jednoriadkový príkaz nevyužíva všetky funkcie awk a dokonca ani túto navyše read navyše.

Od minulého týždňa tu bola správa o sed, chcel som si vyskúšať svoje novonadobudnuté zručnosti a zjednodušiť echo | awk | { read; echo} do zrozumiteľnejšieho echo | sed. Aj keď to rozhodne nie je najlepší prístup k identifikácii chyby, povedal som si, že aspoň vyskúšam svoje sed-fu a možno sa o probléme dozviem niečo nové. Cestou som požiadal kolegu, autora sed talku, aby mi pomohol vymyslieť efektívnejší sed scenár.

Vypustil som obsah varnishadm vcl.show -v "$VCL_NAME" do súboru, takže som sa mohol sústrediť na písanie skriptu sed bez akýchkoľvek problémov s reštartovaním služby.

Krátky popis toho, ako presne vstup sed procesov nájdete v jeho GNU manuál. V zdrojoch sed symbol n explicitne špecifikované ako oddeľovač riadkov.

V niekoľkých prechodoch a s odporúčaniami môjho kolegu sme napísali sed skript, ktorý dal rovnaký výsledok ako celý pôvodný riadok 116.

Nižšie je uvedený vzorový súbor so vstupnými údajmi:

> 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

Z vyššie uvedeného popisu to nemusí byť zrejmé, ale nás zaujíma len prvý komentár // VCL.SHOWa vo vstupných údajoch ich môže byť niekoľko. To je dôvod, prečo pôvodný awk končí po prvom zápase.

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

Takže obsah skriptu lakreload bude vyzerať asi takto:

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

Vyššie uvedená logika sa dá stručne vyjadriť takto:
Ak sa reťazec zhoduje s regulárnym výrazom // VCL.SHOW, potom hltavo zhltnite text, ktorý obsahuje obe čísla v tomto riadku, a uložte si všetko, čo po tejto operácii zostane. Vyšlite uloženú hodnotu a ukončite program.

Jednoduché, však?

Boli sme spokojní so skriptom sed a skutočnosťou, že nahradil celý pôvodný kód. Všetky moje testy poskytli požadované výsledky, takže som zmenil „varnishreload“ na serveri a znova som ho spustil systemctl reload varnish. Zlá chyba echo: write error: Broken pipe opäť sa nám vysmial do tváre. Žmurkajúci kurzor čakal v tmavej prázdnote terminálu na zadanie nového príkazu...

Zdroj: hab.com

Pridať komentár