🥇Lehullás a nyúllyukba: A varnish újraindításának hibájáról — 1. rész

szellemellenállás, miközben az előző 20 percben a gombokat nyomkodta, mintha az élete múlna rajta, félvad tekintettel néz rám és ravasz mosollyal — „Haver, úgy tűnik, rájöttem.”

„Nézd ide,” — mondja, mutatva a képernyő egyik szimbólumára — „Fogadj a piros kalapomra, hogyha ide hozzátesszük azt, amit most küldtem neked” — mutatva egy másik kód részletére — „a hiba már nem fog megjelenni.”

Kicsit zavarodottan és fáradtan megváltoztatom a sed kifejezést, amelyen egy ideje dolgozunk, elmentem a fájlt és elindítom systemctl varnish reload. A hibaüzenet eltűnt…

„Az emailek, amelyeket a jelölttel váltogattam,” folytatta a kollégám, miközben az mosolya őszinte, boldog mosollyá változik, „hirtelen rájöttem, hogy ez pontosan ugyanaz a probléma!”

Honnan indult minden

A cikk megértést feltételez a bash, awk, sed és systemd működéséről. A varnish ismerete ajánlott, de nem kötelező.
Az időbélyegek a snippetekben megváltoztak.
Írva együtt szellemellenállás.
Ez a szöveg a két héttel ezelőtt angol nyelven megjelent eredeti fordítása; fordítás boikoden.

A nap átsüt a panorámaablakokon egy újabb meleg őszi reggelen, egy csésze frissen főtt koffeintartalmú ital pihen a billentyűzet mellett, a fejhallgatómban kedvenc szimfóniám zúg, elnyomva a mechanikus billentyűzetek sercegését, és az első bejegyzés a backlog kanban tábláján játékosan ragyogó címmel világít: “Investigate varnishreload sh: echo: I/O error in staging” (Vizsgálja meg a “varnishreload sh: echo: I/O error” problémát a staging-en). Amikor a varnish-ról van szó, a hibáknak nincs helye, még akkor sem, ha azok nem okoznak semmiféle problémát, mint ebben az esetben.

Azok számára, akik nem ismerik varnishreload, ez egy egyszerű shell script, amely a konfiguráció újratöltésére szolgál varnish — más néven VCL.

Ahogy a jegy neve sugallja, a hiba egy szerveren keletkezett a tesztkörnyezetben, és mivel biztos voltam benne, hogy a Varnish irányítása a tesztkörnyezetben megfelelően működik, feltételeztem, hogy ez egy apró hiba lesz. Tehát csak egy üzenet, ami már egy lezárt kimeneti áramlatba került. Magamhoz veszem a jegyet, teljesen biztos abban, hogy kevesebb mint 30 percen belül készre jelölöm, megverem magam a vállamra, hogy megtisztítottam a táblát a következő szeméttől, és visszatérek a fontosabb dolgokhoz.

Belépve a falba 200 km/h sebességgel

A fájl megnyitásakor varnishreload, az egyik Debian Stretch operációs rendszert futtató szerveren egy 200 sorosnál rövidebb shell scriptet láttam.

Átfutva a scriptet, nem észleltem semmi olyat, ami problémákat okozhatna, ha többször futtatják a terminálból.

Végül is, ez egy tesztkörnyezet, még ha el is romlik, senki sem fog panaszkodni, nos... nem túl sokan. Futtatom a scriptet, és nézem, mi fog megjelenni a terminálon, csak azt látom, hogy már nem is látszanak hibák.

Még pár futtatás, hogy megbizonyosodjak arról, hogy nem tudom reprodukálni a hibát további erőfeszítések nélkül, és elkezdek gondolkodni, hogyan módosíthatnám ezt a scriptet, hogy tényleg hibát generáljon.

Talán letilthatnám a STDOUT-ot (segítségével > &-)? Vagy a STDERR-t? Egyik sem működött végül.

Nyilvánvaló, hogy a systemd valamilyen módon megváltoztatja a futási környezetet, de hogyan és miért?
Elindítom a vim-et, és szerkesztem varnishreload, hozzáadva set -x közvetlenül a shebang alá, remélve, hogy a script debug kimenete egy kis fényt derít a helyzetre.

A fájl javítva, ezért újraindítom a varnish-t, és látom, hogy a változtatás teljesen tönkretette... A kimenet - totális káosz, tonnányi C-szerű kód. Még a terminálban való görgetés sem elegendő ahhoz, hogy megtaláljam, hol kezdődik. Teljesen zavarban vagyok. Befolyásolhatja a debug mód a scriptben futó programok működését? Nem, ostobaság. Hiba a shellben? Számos lehetséges forgatókönyv rohan át az agyamon, mint a csótányok különböző irányokba. Egy csésze koffeinben gazdag ital azonnal kiürül, gyorsan elmegyek a konyhába, hogy feltöltsem a készletet és... megyünk. Megnyitom a scriptet és alaposan megnézem a shebang-t: #!/bin/sh.

/bin/sh — hiszen ez csak egy szimbolikus hivatkozás a bash-re, így a scriptet POSIX-kompatibilis módban értelmezik, igaz? Nem itt! Az alapértelmezett shell a Debianban a dash, és ez az, amire Ticket_flights /bin/sh.

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

Kísérletképpen megváltoztattam a shebangot #!/bin/bash, eltávolítottam set -x és megpróbáltam még egyszer. Végre, a varnish újraindítása után egy érthető hiba jelent meg a kimenetben:

Jan 01 12:00:00 hostname varnishreload[32604]: /usr/sbin/varnishreload: 124. sor: echo: írási hiba: Törött cső
Jan 01 12:00:00 hostname varnishreload[32604]: VCL 'reload_20190101_120000_32604' lefordítva

124. sor, itt van!

114 find_vcl_file() {
115         VCL_SHOW=$(varnishadm vcl.show -v "$VCL_NAME" 2>&1) || :
116         VCL_FILE=$(
117                 echo "$VCL_SHOW" |
118                 awk '[1m$1 == "//" && $2 == "VCL.SHOW" {print; exit}' |
119                         # minden ez a ceremónia az üres fájlok kezelésére
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 "nem sikerült megszerezni a VCL fájl nevét"
129         fi
130
131         echo "$VCL_FILE"
132 }

De mint kiderült, a 124. sor eléggé üres és nem érdekes. Csak azt tudtam feltételezni, hogy a hiba a 116. soron kezdődő több soros idegen nyelvű fájl részeként keletkezett.
Ami végül a VCL_FILE változóba kerül a fent említett almappa végrehajtása után?

Kezdetben elküldi a VLC_SHOWváltozó tartalmát, amely a 115. sorban jött létre, a következő parancsnak egy pipe-on keresztül. És ott mi történik?

Először is, ott a varnishadm, amely a varnish telepítési csomag része, a varnish beállításához újraindítás nélkül.

Az alparancs vcl.show -v a VCL teljes konfigurációjának megjelenítésére szolgál, amely a ${VCL_NAME}, STDOUT-ban található.

A jelenlegi aktív VCL konfiguráció, valamint néhány korábbi VCL konfiguráció megjelenítésére, amelyek még mindig a memóriában vannak, használhatjuk a varnishadm vcl.listparancsot, amelynek kimenete hasonló lesz az alábbihoz:

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

A változó értéke ${VCL_NAME} más részén a szkriptnek van beállítva varnishreload az aktuálisan aktív VCL nevére, ha van ilyen. Ebben az esetben ez lesz a "reload_20190101_120000_12397".

Remek, a ${VCL_SHOW} változó tartalmazza a teljes varnish konfigurációt, ami világos. Most végre megértettem, miért volt a dash kimenete set -x ilyen törött — tartalmazta a létrejött konfiguráció tartalmát.

Fontos megérteni, hogy a VCL teljes konfigurációja gyakran több fájlból áll össze. A C-stílusú megjegyzések arra szolgálnak, hogy megjelöljék, hol lett beillesztve az egyik konfigurációs fájl a másikba, és pontosan erről szól az alábbi kódsor.
A beillesztett fájlokat leíró megjegyzések szintaxisa a következő formátumban van:

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

A számok ebben a kontextusban nem fontosak, minket a fájl neve érdekel.

Mi történik a 116. sorban kezdődő parancsok mentén?
Nézzük meg részletesen.
A parancs négy részből áll:

Egyszerű echo, amely a változó értékét jeleníti meg ${VCL_SHOW}
```
echo "$VCL_SHOW"
```
awk, amely megkeresi a sort (rekordot), ahol az első mező, a szöveg feldarabolása után, a "//", a második pedig a "VCL.SHOW".
Az awk kiírja az első sort, amely megfelel ezeknek a mintáknak, majd azonnal leállítja a feldolgozást.
```
awk '$1 == "//" && $2 == "VCL.SHOW" {print; exit}'
```
Egy kódrészlet, amely öt változóban tárolja a szóközökkel elválasztott mezők értékeit. Az ötödik változó, FILE, megkapja a sor hátralévő részét. Végül az utolsó echo kiírja a változó tartalmát ${FILE}.
```
{ read -r DELIM VCL_SHOW INDEX SIZE FILE; echo "$FILE" }
```
Mivel az 1-től 3-ig terjedő lépések egy alfolyamatban vannak, a $FILE érték kiírásra kerül a változóba. VCL_FILE.

Ahogyan a 119. sor megjegyzéséből is kiderül, ez egyetlen célt szolgál: megbízhatóan kezelni azokat az eseteket, amikor a VCL fájlokra hivatkozik, amelyek névből szóközöket tartalmaznak.

Kommentáltam az eredeti feldolgozási logikát a ${VCL_FILE} és próbáltam megváltoztatni a parancsok sorrendjét, de ez semmire sem vezetett. Minden működött rendben, de a szolgáltatás indításakor hibát adott.

Úgy tűnik, hogy a hiba egyszerűen nem reprodukálható a szkript kézi indításakor, és a feltételezett 30 perc már hatszor eltelt, plusz jött egy fontosabb feladat, amely minden mást háttérbe szorított. A hét hátralévő része különféle feladatokkal telt el, amelyeket csak kicsit tört meg egy sed előadás és egy interjú egy jelöltel. A probléma a hiba varnishreload -ben végleg elveszett az idő homokjában.

A híres sed-fu... valójában... vacak

A következő héten volt egy meglehetősen szabad napom, ezért újra foglalkozni akartam ezzel a tickettel. Reméltem, hogy a fejemben egy háttérfolyamat folyamatosan kereste a megoldást erre a problémára, és ezúttal biztosan megértem, miről van szó.

Mivel legutóbb a kód egyszerű módosítása nem segített, egyszerűen úgy döntöttem, hogy újra írom a 116. sorból kezdve. Mindenesetre a meglévő kód elég káros volt, és nincs is rá szükség, hogy read.

Még egyszer ránézve a hibára:
sh: echo: broken pipe — ebben a parancsban az echo két helyen található, de gyanítom, hogy az első a valószínűbb elkövető (vagy legalábbis bűnrészes). Az awk sem túl megbízható. Ha valóban ez awk | {read; echo} a szerkezet okozza ezeket a problémákat, miért ne cserélnénk le? Ez az egysoros parancs nem használja ki az awk összes lehetőségét, és még ez a felesleges read is az elmúlt.

Mivel a múlt héten volt egy előadás a sed, meg akartam próbálni az újonnan megszerzett készségeimet, és egyszerűsíteni a echo | awk | { read; echo} egy érthetőbb echo | sed. Bár ez határozottan nem a legjobb módszer a hiba feltárására, azt gondoltam, hogy legalább kipróbálom a sed-fu-t, és talán tanulok valami újat a problémáról. Közben elkértem a kollégám, a sed előadónak az ötletét, hogy segítsen nekem egy hatékonyabb sed szkript kitalálásában.

Elküldtem a tartalmát varnishadm vcl.show -v "$VCL_NAME" fájlba, így koncentrálhattam a sed szkript írására anélkül, hogy a szolgáltatás újraindításával kapcsolatos problémákkal kellett volna foglalkoznom.

A sed bemenetének feldolgozásáról rövid leírást található a GNU útmutatójában. A sed forrásaiban a karakter n kifejezetten sorválasztóként van megadva.

Több lépésben és a kollégám ajánlásával írtunk egy sed szkriptet, amely ugyanazt az eredményt adta, mint az eredeti 116. sor.

Íme egy példa a bemeneti fájlra:

> 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

Ez a fent említett leírásból talán nem nyilvánvaló, de minket csak az első megjegyzés érdekel, // VCL.SHOW, továbbá a bemenetekben több is lehet belőlük. Ezért az eredeti awk az első egyezés után befejezi a munkáját.

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

Tehát a varnishreload szkript tartalma körülbelül úgy fog kinézni:

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

A fenti logika röviden a következőképpen fejezhető ki:
Ha a sor megfelel a reguláris kifejezésnek // VCL.SHOW, akkor falj fel mindkét számot tartalmazó szöveget, és őrizd meg mindent, ami ennek a műveletnek a vége után marad. Add vissza a megőrzött értéket, és fejezd be a programot.

Egyszerű, igaz?

Elégedettek voltunk a sed script-tel és azzal a ténnyel, hogy ez helyettesíti az eredeti kódot. Minden tesztem kívánt eredményeket hozott, ezért megváltoztattam a "varnishreload"-ot a szerveren, és újra elindítottam systemctl reload varnish. Rémes hiba echo: írási hiba: Törött cső újra gúnyolódott ránk. A kacsintó kurzor új parancs bevitelét várta a terminál sötét ürességében…

Forrás: habr.com

Hullás a nyúllyukba: Egy újraindítási hiba története varnish — 1. rész

Honnan indult minden

Belépve a falba 200 km/h sebességgel

A híres sed-fu... valójában... vacak