🥇Palež u zečju rupu: Priča o jednoj grešci s ponovnim pokretanjem varnisha — dio 1

ghostinushanka, udarajući po tipkama posljednjih 20 minuta kao da mu o tome ovisi život, okreće se prema meni s poludivljim izrazom u očima i lukavim osmijehom — „Čovječe, mislim da sam shvatio.”

„Pogledaj ovdje,” — kaže, pokazujući na jedan od simbola na ekranu — „Kladim se da ako dodamo ovdje ono što sam ti upravo poslao” — pokazujući na drugi dio koda — „greška više neće biti prikazana.”

Pomalo zbunjen i umoran, mijenjam sed izraze na kojima smo već neko vrijeme radili, spremam datoteku i pokrećem systemctl varnish reload. Poruka o grešci je nestala…

„E-mailovi koje sam razmjenjivao s kandidatom,” nastavila je moja kolegica, dok se njezin osmijeh pretvara u iskren osmeh pun radosti, „Odjednom sam shvatio da je to točno isti problem!”

Kako je sve počelo

Članak pretpostavlja razumijevanje principa rada bash, awk, sed i systemd. Poznavanje varnish-a je dobrodošlo, ali nije obavezno.
Vremenske oznake u isječcima su izmijenjene.
Napisano zajedno s ghostinushanka.
Ovaj tekst je prijevod originala objavljenog na engleskom jeziku prije dva tjedna; prijevod boikoden.

Sunce proviruje kroz panoramske prozore na još jednom toplom jesenskom jutru, šalica svježe pripremljenog napitka bogatog kofeinom odlaže se sa strane od tipkovnice, u slušalicama svira omiljena simfonija zvukova, prikrivajući šum mehaničkih tipkovnica, a prvi unos u popisu ticket-a na kanban ploči razigrano svijetli sudbonosni naslov “Investigate varnishreload sh: echo: I/O error in staging” (Istražite “varnishreload sh: echo: I/O greška” u stagingu). Kada je riječ o varnishu, za greške nema mjesta, čak i ako se ne očituju kao problemi poput ovog slučaja.

Za one koji nisu upoznati s varnishreload, to je jednostavni shell skript koji se koristi za ponovnu učitavanje konfiguracije varnish-a — također poznate kao VCL.

Kako sugerira naziv tiketa, greška se dogodila na jednom od servera u stagingu, a budući da sam bio siguran da routing varnisha na stagingu radi ispravno, pretpostavio sam da će ovo biti sitna greška. Tako, jednostavno poruka koja je pokrenuta u već zatvorenoj izlaznoj nit. Uzimam tiket za sebe, s punim uvjerenjem da ću ga označiti kao gotov za manje od 30 minuta, tapšem se po ramenu zbog čišćenja boarda od još jednog smeća i vraćam se važnijim stvarima.

Zabijajući se u zid brzinom od 200 km/h

Otvarajući datoteku varnishreload, na jednom od servera koji radi na Debian Stretchu, vidio sam shell skriptu dugu manje od 200 redaka.

Pogledavši skriptu, nisam primijetio ništa što bi moglo prouzročiti probleme pri višestrukom pokretanju iz terminala.

Na kraju, ovo je staging, čak i ako se pokvari, nitko neće prigovarati, pa… ne previše. Pokrećem skriptu i gledam što će se ispisivati na terminalu, ali greške više nema.

Još nekoliko pokretanja kako bih se uvjerio da ne mogu reproducirati grešku bez dodatnih napora, i počinjem razmišljati kako da izmijenim ovu skriptu i natjeram je da zapravo prouzroči grešku.

Možda da skriptu preusmjerim STDOUT (uz pomoć > &-)? Ili STDERR? Ni to ni drugo nije na kraju upalilo.

Očigledno je da systemd na neki način mijenja okolinu pokretanja, ali kako i zašto?
Upalio sam vim i uređujem varnishreload, dodajući set -x odmah ispod shebanga, nadajući se da će debug ispis skripte donijeti malo svjetla.

Datoteka je ispravljena, pa ponovno pokrećem varnish i vidim da je promjena potpuno uništila sve… Ispis — potpuni nered, u kojem je tona C-sličnog koda. Čak ni skrolanje u terminalu nije dovoljno da pronađem gdje sve počinje. U potpunom sam očaju. Može li način debugiranja utjecati na rad programa pokretanih u skripti? Ne, besmisleno. Bug u shellu? Nekoliko mogućih scenarija jurca mi kroz glavu poput žohara u različitim smjerovima. Šalica napitka bogatog kofeinom odmah se ispraznila, brzo putovanje do kuhinje za dopunu i… idemo. Otvaram skriptu i pažljivo gledam shebang: #!/bin/sh.

/bin/sh — to je samo simbolička veza na bash, pa se skripta interpretira u POSIX-kompatibilnom načinu, zar ne? Nije tu! Zadana ljuska u Debianu je dash, i to je to na što se referira /bin/sh.

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

Zbog eksperimenta, promijenio sam shebang na #!/bin/bash, obrisao set -x i pokušao ponovo. Napokon, prilikom sljedećeg ponovnog pokretanja varnish-a, u izlazu se pojavila razumljiva greška:

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

Redak 124, evo ga!

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                         # cijela ova ceremonija za rukovanje prazninama u 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 }

Ali kako se ispostavilo, redak 124 je prilično prazan i ne predstavlja interes. Mogao sam samo pretpostaviti da je greška nastala kao dio višerednog komentara, koji počinje na 116. retku.
Što se u konačnici zapisuje u varijablu VCL_FILE kao rezultat izvršenja gore spomenutog sub-shell-a?

Na početku, šalje sadržaj varijable VLC_SHOW, stvorene na retku 115, sljedećoj komandi kroz cijev. A što se tada događa?

Prvo, koristi se varnishadm, koji je dio instalacijskog paketa varnish, za upravljanje varnish-om bez ponovnog pokretanja.

Podkomanda vcl.show -v koristi se za ispis cijele VCL konfiguracije navedene u ${VCL_NAME}, na STDOUT-u.

Za prikaz trenutne aktivne VCL konfiguracije, kao i nekoliko prethodnih verzija varnisheve konfiguracije koje su još uvijek u memoriji, može se koristiti komanda varnishadm vcl.list, čiji će izlaz biti sličan onome u nastavku:

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

Vrijednost varijable ${VCL_NAME} postavlja se u drugom dijelu skripte varnishreload na ime trenutno aktivnog VCL-a, ako takav postoji. U ovom slučaju, to će biti “reload_20190101_120000_12397”.

Odlično, varijabla ${VCL_SHOW} sadrži kompletnu konfiguraciju za varnish, što je sada jasno. Sada sam konačno shvatio zašto je izlaz dash-a set -x bio tako oštećen — uključivao je sadržaj dobivene konfiguracije.

Važno je razumjeti da cjelokupna VCL konfiguracija često može biti spojena iz više datoteka. Komentari u C stilu koriste se za označavanje gdje su jedne datoteke uključene u druge, i to je ono o čemu se zapravo radi u cijelom donjem fragmentu koda.
Sintaksa komentara koji opisuju uključene datoteke ima sljedeći format:

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

Brojevi u ovom kontekstu nisu važni, interesira nas naziv datoteke.

Što se zapravo događa u močvari komandi koje počinju na liniji 116?
Hajde da to raščistimo.
Komanda se sastoji od četiri dijela:

Jednostavno echo, koje ispisuje vrijednost varijable ${VCL_SHOW}
```
echo "$VCL_SHOW"
```
awk, koji traži redak (unos) gdje je prvo polje, nakon razdvajanja teksta, "//", a drugo – "VCL.SHOW".
Awk će ispisati prvi redak koji odgovara tim obrascima, a zatim odmah prekinuti obradu.
```
awk '$1 == "//" && $2 == "VCL.SHOW" {print; exit}'
```
Blok koda koji pohranjuje u pet varijabli vrijednosti polja, odvojenih razmacima. Peta varijabla FILE dobija ostatak retka. Na kraju, posljednji echo ispisuje sadržaj varijable ${FILE}.
```
{ read -r DELIM VCL_SHOW INDEX SIZE FILE; echo "$FILE" }
```
Budući da su svi koraci od 1 do 3 smješteni u podljusku, ispis vrijednosti $FILE bit će pohranjen u varijablu VCL_FILE.

Kao što se iz komentara na 119. liniji može zaključiti, to služi isključivo kao cilj: pouzdano obraditi slučajeve kada se VCL poziva na datoteke sa znakovima razmaka u nazivu.

Komentirao sam izvorne logike obrade za ${VCL_FILE} i pokušao promijeniti redoslijed komandi, ali to nije dovelo do ničega. Sve mi je radilo bez greške, a u slučaju pokretanja usluge javila se greška.

Izgleda da greška nije reproducibilna kada se skripta pokrene ručno, dok su predviđenih 30 minuta već prošlo šest puta, i uz to se pojavila prioritetnija zadaća koja je gurnula ostale poslove sa strane. Ostatak tjedna bio je ispunjen najrazličitijim zadacima, a bio je samo malo razdrman izvještajem o sedu i intervjuom s kandidatom. Problem s greškom u varnishreload bio je zauvijek izgubljen u pijesku vremena.

Vaša takozvana sed-fu… zapravo… je smeće

Sljedeći tjedan imao sam jedan prilično slobodan dan, pa sam ponovno odlučio raditi na toj tiket. Nadao sam se da će u mom mozgu neki pozadinski proces tijekom cijelog tog vremena tražiti rješenje ovog problema i ovog puta ću sigurno razumjeti u čemu je stvar.

Budući da jednostavna promjena koda prošli put nije pomogla, odlučio sam ga jednostavno prekucati počevši od 116. retka. U svakom slučaju, postojeći kod bio je prilično loš. I nije bilo apsolutno nikakve potrebe za korištenjem read.

Pogledajući grešku još jednom:
sh: echo: broken pipe — u ovoj komandi echo se nalazi na dva mjesta, ali sumnjam da je prva — vjerojatniji krivac (pa makar i suodgovornik). Awk također ne ulijeva povjerenje. I u slučaju da je to zaista awk | {read; echo} konstukcija koja dovodi do svih ovih problema, zašto je ne zamijeniti? Ova jednostavna komanda ne koristi sve mogućnosti awk-a, a uz to ima i tu suvišnu read dodanu.

Budući da je prošli tjedan bilo predavanje o sed, htio sam probati svoje nedavno stečene vještine i pojednostaviti echo | awk | { read; echo} u razumljivije echo | sed. Iako ovo definitivno nije najbolji pristup otkrivanju greške, pomislio sam da bih barem mogao isprobati svoje sed vještine i možda naučiti nešto novo o problemu. Usput sam zamolio svog kolegu, autora predavanja o sed-u, da mi pomogne smisliti učinkovitiji sed skript.

Poslao sam sadržaj varnishadm vcl.show -v "$VCL_NAME" u datoteku, tako da sam se mogao usredotočiti na pisanje sed skripta bez ikakvih briga oko ponovnog pokretanja usluge.

Kratak opis kako točno sed obrađuje ulazne podatke može se naći u njegovom GNU priručniku. U izvorima sed-a simbol n jasno je označen kao razdjelnik redaka.

U nekoliko prolaza i uz preporuke mog kolege napisali smo sed skript koji daje isti rezultat kao i cijeli izvorni redak 116.

U nastavku se nalazi uzorak datoteke s ulaznim podacima:

> 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

To možda nije očito iz gornjeg opisa, ali nas zanima samo prvi komentar // VCL.SHOW, a u ulaznim podacima ih može biti više. Zato originalni awk završava svoj rad nakon prvog podudaranja.

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

Dakle, sadržaj skripta varnishreload izgledat će otprilike ovako:

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

Gore navedena logika može se sažeti na sljedeći način:
Ako se niz poklapa s regularnim izrazom // VCL.SHOW, tada pohlepno pojedi tekst koji uključuje oba broja u ovoj liniji i sačuvaj sve što ostane nakon te operacije. Izdaj sačuvanu vrijednost i završi program.

Jednostavno, zar ne?

Bili smo zadovoljni sed skriptom i činjenicom da zamjenjuje cijeli izvorni kod. Testovi su dali željene rezultate, pa sam promijenio “varnishreload” na serveru i ponovno pokrenuo systemctl reload varnish. Užasna greška echo: write error: Broken pipe ponovno se smijala u naše lice. Treptajući kursor čekao je unos nove komande u tamnoj praznini terminala…

Izvor: habr.com

Padanje u zečju rupu: Priča o jednoj grešci pri ponovnom pokretanju varnisha — deo 1

Kako je sve počelo

Zabijajući se u zid brzinom od 200 km/h

Vaša takozvana sed-fu… zapravo… je smeće