🥇Pád do králičí nory: Příběh o jedné chybě při restartování varnish — část 1

ghostinushanka, zatímco jsem po tlačítkách klepal posledních 20 minut, jako by mi na tom závisel život, otočil se ke mně s polodivokým výrazem v očích a mazaným úsměvem — „Člověče, myslím, že jsem to pochopil.“

„Podívej se sem,“ říká a ukazuje na jeden z symbolů na obrazovce — „Sázíme na mou červenou čepici, že když sem přidáme to, co jsem ti právě poslal“ — ukazuje na jinou část kódu — „tak se chyba už nezobrazí.“

Trochu zmatený a unavený, měním výraz sed, na kterém jsme už nějakou dobu pracovali, ukládám soubor a spouštím systemctl varnish reload. Chybové hlášení zmizelo…

„E-maily, kterými jsem si vyměňoval s kandidátem,“ pokračoval můj kolega, zatímco jeho úsměv se proměnil v upřímný úsměv plný radosti, „Najednou mi došlo, že to je úplně stejný problém!“

Jak to všechno začalo

Článek předpokládá porozumění principům fungování bash, awk, sed a systemd. Znalost varnish je vítaná, ale není nutná.
Časové razítka ve snippetech byla změněna.
Napsáno spolu s ghostinushanka.
Tento text je překlad originálu, publikovaného v angličtině před dvěma týdny; překlad boikoden.

Slunce svítí skrz panoramatická okna jednoho teplého podzimního rána, šálek čerstvě připraveného nápoje bohatého na kofein spočívá vedle klávesnice, v sluchátkách zní moje oblíbená symfonie zvuků, která přehlušuje šum mechanických klávesnic, a prvním záznamem na seznamu tiketů v backlogu na kanbanové desce se hravě leskne osudový titulek „Prozkoumat varnishreload sh: echo: I/O error in staging“. Když přijde na varnish, neexistují a nemohou existovat chyby, i když se neprojeví žádnými problémy, jako v tomto případě.

Pro ty, kdo nejsou obeznámeni s varnishreload, to je jednoduchý shell skript používaný k přeloadování konfigurace varnishu — také nazývané VCL.

Jak naznačuje název tiketu, došlo k chybě na jednom ze serverů na stagingu. Protože jsem byl přesvědčen, že směrování Varnish na stagingu funguje správně, předpokládal jsem, že to bude drobná chyba. Takže pouze zpráva, která se dostala do již zavřeného výstupního proudu. Beru si tiket a jsem si jistý, že ho vyřeším do méně než 30 minut, poplácám se po rameni za to, že jsem vyčistil desku od dalšího harampádí, a vrátím se k důležitějším věcem.

Narážející do zdi rychlostí 200 km/h

Otevřel jsem soubor varnishreload, na jednom ze serverů spravovaných Debianem Stretch, a uviděl shell skript o délce méně než 200 řádků.

Po prozkoumání skriptu jsem si nevšiml ničeho, co by mohlo způsobit problémy při opakovaném spuštění přímo z terminálu.

Nakonec je to staging, i kdyby to selhalo, nikdo si nebude stěžovat, no... ne příliš mnozí. Spouštím skript a sleduji, co se vypisuje na terminál, ale chyby už nejsou vidět.

Ještě pár spuštění, abych se ujistil, že nemohu chybu reprodukovat bez jakýchkoli dodatečných úsilí, a začínám vymýšlet, jak tento skript upravit, aby skutečně vyhazoval chybu.

Možná skriptu přesměrovat STDOUT (pomocí > &-)? Nebo STDERR? Ani jedno z toho nakonec nefungovalo.

Je jasné, že systemd nějakým způsobem mění prostředí spuštění, ale jak a proč?
Zapínám vim a upravuji varnishreload, přidávám set -x přímo pod shebang, doufajíc, že výstup debugu skriptu vrhne trochu světla.

Soubor je opraven, takže restartuji Varnish a vidím, že změna všechno naprosto rozbila... Výstup je kompletní chaos, ve kterém se nachází spousty C-podobného kódu. Ani posouvání v terminálu nestačí na to, abych našel, kde to začíná. Jsem v úplném zmatení. Může mít režim ladění vliv na práci programů spouštěných ve skriptu? Ne, to je nesmysl. Chyba v shellu? Několik možných scénářů se mi honí v hlavě jako švábi do různých stran. Šálek kofeinového nápoje je okamžitě prázdný, rychlá cesta do kuchyně pro doplnění zásob a... jdeme na to. Otevírám skript a pečlivě se dívám na shebang: #!/bin/sh.

/bin/sh — je to přece jen symlink na bash, takže skript je interpretován v režimu kompatibilním s POSIX, že? Ale kdepak! Výchozí shell v Debianu je dash, a to je přesně to, na co Ticket_flights /bin/sh.

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

Pro zkoušku jsem změnil shebang na #!/bin/bash, smazal set -x a zkusil to znovu. Nakonec, při následném restartu varnish se v výstupu objevila smysluplná chyba:

Jan 01 12:00:00 hostname varnishreload[32604]: /usr/sbin/varnishreload: řádek 124: echo: chyba zápisu: Zlomená trubka
Jan 01 12:00:00 hostname varnishreload[32604]: VCL 'reload_20190101_120000_32604' zkompilováno

Řádek 124, to je ono!

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                         # celé toto ceremonií k vyřízení mezer ve 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 "nepodařilo se získat název VCL souboru"
129         fi
130
131         echo "$VCL_FILE"
132 }

Ale jak se ukázalo, řádek 124 je dost prázdný a nezajímavý. Mohu jen předpokládat, že chyba vznikla jako součást vícerozměrného obsahu, začínajícího na 116. řádku.
Co je nakonec zapsáno do proměnné VCL_FILE v důsledku provedení výše zmíněného sub-shellu?

Na začátku posílá obsah proměnné VLC_SHOW, vytvořené na řádku 115, následující příkazu přes pipe. A co se tam vlastně děje?

Za prvé, používá se varnishadm, který je součástí instalačního balíčku varnish, pro konfiguraci varnish bez restartu.

Podpříkaz vcl.show -v se používá k výpisu celé konfigurace VCL uvedené v ${VCL_NAME}, na STDOUT.

Aby se zobrazila aktuální aktivní konfigurace VCL, stejně jako několik předchozích verzí konfigurací routování varnish, které jsou stále v paměti, můžete použít příkaz varnishadm vcl.list, jehož výstup bude podobný následující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

Hodnota proměnné ${VCL_NAME} je nastaven v jiné části skriptu varnishreload na jméno aktuální VCL, pokud nějaká existuje. V tomto případě to bude “reload_20190101_120000_12397”.

Skvěle, proměnná ${VCL_SHOW} obsahuje úplnou konfiguraci pro varnish, teď je to jasné. Nyní jsem konečně pochopil, proč výstup dash s set -x byl tak poškozený — zahrnoval obsah výše zmíněné konfigurace.

Je důležité pochopit, že úplná konfigurace VCL může být často sestavena z několika souborů. Komentáře ve stylu C se používají k určení, kde byly jedny konfigurační soubory zahrnuty do jiných, a to je vlastně to, o čem celá uvedená část fragmentu kódu je.
Syntaxe komentářů popisujících zahrnuté soubory má následující formát:

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

Čísla v tomto kontextu nejsou důležitá, zajímá nás název souboru.

Co se tedy děje v bažině příkazů, která začíná na řádku 116?
Pojďme to rozebrat.
Příkaz se skládá ze čtyř částí:

Jednoduché echo, které vypisuje hodnotu proměnné ${VCL_SHOW}
```
echo "$VCL_SHOW"
```
awk, který hledá řádek (záznam), kde prvním polem, po rozdělení textu, bude “//”, a druhým — „VCL.SHOW“.
Awk vypíše první řádek, který odpovídá těmto vzorům, a poté okamžitě přestane zpracovávat.
```
awk '$1 == "//" && $2 == "VCL.SHOW" {print; exit}'
```
Blok kódu, který ukládá do pěti proměnných hodnoty polí oddělených mezerami. Pátá proměnná FILE získává zbytek řádku. Nakonec poslední echo vypisuje obsah proměnné ${FILE}.
```
{ read -r DELIM VCL_SHOW INDEX SIZE FILE; echo "$FILE" }
```
Protože všechny kroky od 1 do 3 jsou uzavřeny v podshellu, výstup hodnoty $FILE bude uložen do proměnné. VCL_FILE.

Jak vyplývá z komentáře na 119. řádku, to slouží jedinému účelu: spolehlivě zpracovávat případy, kdy VCL bude odkazovat na soubory s mezerami v názvu.

Zakomentoval jsem původní logiku zpracování pro ${VCL_FILE} a pokusil jsem se změnit pořadí příkazů, ale to nijak nepomohlo. Mělo to fungovat bez problémů, a v případě spuštění služby to vyhodilo chybu.

Zdá se, že chyba se při spuštění skriptu ručně jednoduše nedá reprodukovat, přičemž předpokládaných 30 minut už skončilo asi šestkrát, a navíc se objevila priorita, která odsunula ostatní úkoly na vedlejší kolej. Zbytek týdne byl zaplněn různými úkoly a byl pouze trochu narušen prezentací o sed a pohovorem s kandidátem. Problém s chybou v varnishreload byl beznavrátově ztracen v čase.

Vaše takzvané sed-fu… ve skutečnosti… je špatné.

Příští týden jsem měl jeden docela volný den, a tak jsem se znovu rozhodl věnovat tomuto ticketu. Doufal jsem, že v mém mozku nějaký pozadový proces po celou tu dobu hledal řešení tohoto problému a tentokrát už určitě pochopím, o co jde.

Jelikož minule jednoduchá změna kódu nepomohla, rozhodl jsem se ho prostě přepsat od 116. řádku. V každém případě byl existující kód nedotažený. A není vůbec žádná potřeba použít read.

Podíval jsem se na chybu ještě jednou:
sh: echo: broken pipe — v tomto příkazu echo je na dvou místech, ale podezřívám, že první je pravděpodobnější viník (nebo alespoň spoluviník). Awk také nevzbuzuje důvěru. A pokud to skutečně je awk | {read; echo} konfigurace, která způsobuje všechny tyto problémy, proč ji nenahradit? Tento jednorázový příkaz nevyužívá všechny možnosti awk, a navíc tohle navíc read .

Jelikož minulý týden byla prezentace o sed, chtěl jsem vyzkoušet své nedávno získané dovednosti a zjednodušit echo | awk | { read; echo} na srozumitelnější echo | sed. Ačkoli to rozhodně není nejlepší přístup k odhalení chyby, pomyslel jsem si, že alespoň vyzkouším své sed-fu a možná se naučím něco nového o problému. Po cestě jsem požádal svého kolegu, autora prezentace o sed, aby mi pomohl vymyslet efektivnější sed skript.

Poslal jsem obsah varnishadm vcl.show -v "$VCL_NAME" do souboru, abych se mohl soustředit na psaní sed skriptu bez jakýchkoli problémů spojených s restartováním služby.

Krátký popis toho, jak sed zpracovává vstupní data, lze nalézt v jeho GNU příručce. V původních zdrojích sed je symbol n výslovně uveden jako oddělovač řádků.

V několika průchodech a s doporučeními mého kolegy jsme napsali sed skript, který dával stejný výsledek jako celý původní řádek 116.

Níže je uveden vzorek souboru se vstupními daty:

> cat vcl-example.vcl
Text
// VCL.SHOW 0 1578 soubor s 3 mezerami.vcl
Více textu
// VCL.SHOW 0 1578 soubor.vcl
Ještě více textu
// VCL.SHOW 0 1578 soubor s DVOUMezery.vcl
Konečný text

To nemusí být na základě výše uvedeného popisu zřejmé, ale zajímají nás pouze první komentář // VCL.SHOW, přičemž v vstupních datech jich může být několik. Právě proto originální awk končí svou práci po prvním shodě.

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

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

Výše uvedená logika může být stručně vyjádřena následujícím způsobem:
Pokud řetězec odpovídá regulárnímu výrazu // VCL.SHOW, pak hltavě zkonzumuj text, který zahrnuje obě čísla v tomto řetězci, a ulož vše, co zůstane po této operaci. Vrať uloženou hodnotu a ukonči program.

Jednoduché, že?

Byli jsme spokojeni se skryptem sed a s tím, že nahrazuje celý původní kód. Všechny mé testy daly požadované výsledky, takže jsem změnil „varnishreload“ na serveru a znovu spustil systemctl reload varnish. Ošklivá chyba echo: write error: Broken pipe se opět smála přímo do tváře. Mrkající kurzor čekal na zadání nového příkazu v temnotě terminálu…

Zdroj: habr.com

Pád do králičí nory: Příběh jedné chyby při restartování varnish – část 1

Jak to všechno začalo

Narážející do zdi rychlostí 200 km/h

Vaše takzvané sed-fu… ve skutečnosti… je špatné.