Upadek w króliczą norę: historia jednej błędnej ponownej konfiguracji varnish — część 1

ghostinushanka, naciskając przyciski przez ostatnie 20 minut, jakby od tego zależało jego życie, obraca się w moją stronę z półdzikim wyrazem w oczach i przebiegłym uśmieszkiem — „Stary, chyba to zrozumiałem.”

„Spójrz tutaj,” mówi, pokazując na jeden z symboli na ekranie — „Zakładam moją czerwoną czapkę, że jeśli dodamy to, co właśnie ci wysłałem” — pokazując na inny fragment kodu — „błąd już się nie pojawi.”

Trochę zdezorientowany i zmęczony, zmieniam wyrażenie sed, nad którym już pewien czas pracowaliśmy, zapisuję plik i uruchamiam systemctl varnish reload. Komunikat o błędzie zniknął...

„E-maile, którymi wymieniałem się z kandydatem,” kontynuował mój kolega, podczas gdy jego uśmieszek przeradzał się w szczery uśmiech pełen radości, „Nagle dotarło do mnie, że to dokładnie ten sam problem!”

Od czego to wszystko się zaczęło

Artykuł zakłada znajomość zasad działania bash, awk, sed i systemd. Znajomość varnish jest mile widziana, ale nieobowiązkowa.
Znaki czasowe w snippetach zostały zmienione.
Napisano wspólnie z ghostinushanka.
Ten tekst jest tłumaczeniem oryginału, opublikowanego w języku angielskim dwa tygodnie temu; tłumaczenie boikoden.

Słońce przebija się przez panoramiczne okna w kolejnym ciepłym, jesiennym poranku, filiżanka świeżo przygotowanego, mocno kofeinowego napoju leży obok klawiatury, w słuchawkach słychać ulubioną symfonię dźwięków, zagłuszającą szum mechanicznych klawiatur, a pierwszym wpisem na liście zgłoszeń w backlogu na tablicy kanban w figlarny sposób mieni się przełomowy tytuł „Investigate varnishreload sh: echo: I/O error in staging” (Zbadaj „varnishreload sh: echo: I/O error” na etapie). Kiedy mowa o varnish, nie ma miejsca na błędy, nawet jeśli nie prowadzą do żadnych problemów, jak w tym przypadku.

Dla tych, którzy nie są zaznajomieni z varnishreload, to prosty skrypt shell, używany do przeładowania konfiguracji varnish-a — również nazywanego VCL.

Jak sugeruje nazwa ticketu, błąd wystąpił na jednym z serwerów na stagi, a ponieważ byłem pewien, że routowanie varnisha na stagi działa poprawnie, założyłem, że to będzie drobny błąd. Po prostu wiadomość trafiła do już zamkniętego wyjściowego strumienia. Biorę tiket dla siebie, w pełni przekonany, że oznaczę go jako gotowy w mniej niż 30 minut, poklepję się po plecach za oczyszczenie tablicy z kolejnego śmiecia i wrócę do ważniejszych spraw.

Wjeżdżając w ścianę z prędkością 200 km/h

Otwierając plik varnishreload, na jednym z serwerów działających na Debian Stretch, zobaczyłem skrypt powłoki o długości mniej niż 200 linii.

Przeglądając skrypt, nie zauważyłem niczego, co mogłoby prowadzić do problemów przy wielokrotnym uruchamianiu go bezpośrednio z terminala.

W końcu to stagi, nawet jeśli się zepsuje, nikt się nie będzie skarżyć, no… nie za bardzo. Uruchamiam skrypt i patrzę, co wyświetli się na terminalu, tylko że błędów już nie widać.

Jeszcze kilka uruchomień, aby upewnić się, że nie mogę odtworzyć błędu bez dodatkowego wysiłku, i zaczynam wymyślać, jak ten skrypt zmienić, aby jednak wygenerował błąd.

Może warto by skryptowi zablokować STDOUT (przy pomocy > &-)? A może STDERR? Żadne z tych rozwiązań ostatecznie nie zadziałało.

Jasne, systemd w jakiś sposób modyfikuje środowisko uruchomieniowe, ale w jaki sposób i dlaczego?
Włączam vim i edytuję varnishreload, dodając set -x tuż pod shebang, mając nadzieję, że wyjście debugowania skryptu rzuci trochę światła.

Plik poprawiony, więc ponownie uruchamiam varnish i widzę, że zmiana po prostu wszystko zepsuła… Wyjście — pełny bałagan, w którym tony kodu przypominającego C. Nawet przewijanie w terminalu nie wystarcza, aby znaleźć, gdzie się to zaczyna. Jestem w pełnym osłupieniu. Czy tryb debugowania może wpływać na działanie programów uruchamianych w skrypcie? Nie, to bzdura. Błąd w powłoce? Kilka możliwych scenariuszy przelatuje mi przez głowę jak karaluchy w różnych kierunkach. Filiżanka napoju z kofeiną natychmiast się opróżnia, szybka podróż do kuchni po uzupełnienie zapasów i… jedziemy. Otwieram skrypt i przyglądam się shebangowi: #!/bin/sh.

/bin/sh — to przecież tylko symlink do bash, więc skrypt jest interpretowany w trybie zgodnym z POSIX, prawda? Nic z tego! Domyślną powłoką w Debianie jest dash, i to właśnie jest to, na co wskazuje /bin/sh.

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

Dla próby zmieniłem shebang na #!/bin/bash, usunąłem set -x i spróbowałem jeszcze raz. W końcu, przy następnej próbie ponownego załadowania varnish-a, w wynikach pojawił się znośny błąd:

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

Linia 124, oto to!

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                         # cała ta ceremonia, aby obsłużyć puste w 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 "nie udało się uzyskać nazwę pliku VCL"
129         fi
130
131         echo "$VCL_FILE"
132 }

Ale okazało się, że linia 124 jest dość pusta i nie ma w niej nic interesującego. Mogłem jedynie przypuszczać, że błąd pojawił się jako część wieloliniowego polecenia, które zaczyna się na linii 116.
Co ostatecznie jest zapisywane w zmiennej VCL_FILE w wyniku wykonania powyższego subshella?

Na początku wysyła zawartość zmiennej VLC_SHOW, utworzonej w linii 115, do następnego polecenia przez pipe. A co się tam dzieje?

Po pierwsze, używa varnishadm, który jest częścią pakietu instalacyjnego varnish, do konfigurowania varnish-a bez ponownego uruchamiania.

Podkomenda vcl.show -v jest używana do wyświetlenia całej konfiguracji VCL, określonej w ${VCL_NAME}, w STDOUT.

Aby wyświetlić bieżącą aktywną konfigurację VCL oraz kilka poprzednich wersji konfiguracji trasowania varnish-a, które wciąż znajdują się w pamięci, można użyć polecenia varnishadm vcl.list, którego wynik będzie podobny do poniższego:

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

Wartość zmiennej ${VCL_NAME} jest przypisywana w innej części skryptu varnishreload do bieżącego aktywnego VCL, jeśli taki istnieje. W tym przypadku będzie to "reload_20190101_120000_12397".

Świetnie, zmienna ${VCL_SHOW} zawiera pełną konfigurację dla varnish, podczas gdy już jasne. Teraz w końcu zrozumiałem, dlaczego wynik dash set -x był taki uszkodzony — zawierał treść powstałej konfiguracji.

Ważne jest, aby zrozumieć, że pełna konfiguracja VCL często może być sklejona z kilku plików. Komentarze w stylu C są używane do określenia, gdzie jeden plik konfiguracyjny został włączony do drugiego, i to właśnie opisuje poniższy fragment kodu.
Składnia komentarzy opisujących włączone pliki ma następujący format:

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

Liczby w tym kontekście nie mają znaczenia, interesuje nas nazwa pliku.

Co się dzieje w bałaganie poleceń, zaczynających się od linii 116?
Zróbmy to.
Komenda składa się z czterech części:

1. Proste echo, które wyświetla wartość zmiennej ${VCL_SHOW}

   echo "$VCL_SHOW"

2. awk, który szuka linii (rekordu), gdzie pierwszym polem, po rozbiciu tekstu, będzie "//", a drugim – „VCL.SHOW”.
   Awk wypisze pierwszą linię odpowiadającą tym wzorom, a następnie natychmiast przerwie przetwarzanie.

   awk '$1 == "//" && $2 == "VCL.SHOW" {print; exit}'

3. Blok kodu, który przechowuje w pięciu zmiennych wartości pól oddzielonych spacjami. Piąta zmienna FILE otrzymuje resztę linii. Na końcu ostatnie echo wypisuje zawartość zmiennej ${FILE}.

   { read -r DELIM VCL_SHOW INDEX SIZE FILE; echo "$FILE" }

4. Ponieważ wszystkie kroki od 1 do 3 są zamknięte w sub-shelu, wartość wyjściowa $FILE zostanie zapisana w zmiennej VCL_FILE.

Jak wynika z komentarza na 119. linii, służy to jedynemu celowi: niezawodnemu przetwarzaniu przypadków, gdy VCL odnosi się do plików z symbolami spacji w nazwie.

Skomentowałem pierwotną logikę przetwarzania dla ${VCL_FILE} i próbowałem zmienić kolejność poleceń, ale to nic nie dało. Wszystko działało czysto, a w przypadku uruchomienia serwisu występował błąd.

Wygląda na to, że błąd nie występuje przy ręcznym uruchamianiu skryptu; założone 30 minut minęło już sześć razy, a dodatkowo pojawiło się ważniejsze zadanie, które odsunęło inne na bok. Pozostała część tygodnia była wypełniona różnymi zadaniami i była tylko nieznacznie przerywana raportem o sed oraz rozmową z kandydatem. Problem z błędem w varnishreload został bezpowrotnie zagubiony w piaskach czasu.

Twoje tak zwane sed-fu… tak naprawdę… to dno

W przyszłym tygodniu miałem dość wolny dzień, więc postanowiłem zająć się tym ticketem. Miałem nadzieję, że w moim umyśle jakiś proces w tle przez cały ten czas szukał rozwiązania tego problemu i tym razem na pewno zrozumiem, o co chodzi.

Ponieważ ostatnim razem zwykła zmiana kodu nie pomogła, postanowiłem przepisać go zaczynając od 116. linii. Tak czy inaczej, istniejący kod był dość nieudany. Nie było zupełnie potrzeby używania read.

Patrząc na błąd jeszcze raz:
sh: echo: broken pipe — w tej komendzie echo występuje w dwóch miejscach, ale podejrzewam, że pierwsza z nich jest bardziej prawdopodobnym winowajcą (no, albo przynajmniej współwinowajcą). Awk również nie wzbudza zaufania. A jeśli rzeczywiście to jest awk | {read; echo} ta konstrukcja prowadzi do wszystkich tych problemów, to czemu by jej nie zmienić? Ta jednolinijkowa komenda nie wykorzystuje wszystkich możliwości awk, a do tego ten zbędny read dodatkowo.

Ponieważ w zeszłym tygodniu odbyła się prezentacja na temat sed, chciałem wypróbować swoje nowo nabyte umiejętności i uprościć echo | awk | { read; echo} na bardziej zrozumiałe echo | sed. Chociaż to zdecydowanie nie jest najlepsze podejście do ustalenia błędu, pomyślałem, że przynajmniej spróbuję swojego sed-fu i może dowiem się czegoś nowego o problemie. Po drodze poprosiłem mojego kolegę, autora prezentacji o sed, o pomoc w wymyśleniu bardziej efektywnego skryptu sed.

Przesłałem zawartość varnishadm vcl.show -v "$VCL_NAME" do pliku, aby móc skupić się na pisaniu skryptu sed bez żadnych problemów związanych z przeładowaniami usługi.

Krótki opis tego, jak dokładnie sed przetwarza dane wejściowe, można znaleźć w jego podręczniku GNU. W źródłach sed symbol n jest wyraźnie określony jako separator linii.

W kilku przejściach i z rekomendacjami mojego kolegi napisaliśmy skrypt sed, który dawał ten sam rezultat, co cała oryginalna linia 116.

Poniżej znajduje się przykład pliku z danymi wejściowymi:

> cat vcl-example.vcl
Text
// VCL.SHOW 0 1578 plik z 3 spacjami.vcl
Więcej tekstu
// VCL.SHOW 0 1578 plik.vcl
Jeszcze więcej tekstu
// VCL.SHOW 0 1578 plik z DWASPACJAMI.vcl
Ostateczny tekst

To może nie być oczywiste z powyższego opisu, ale interesuje nas tylko pierwszy komentarz // VCL.SHOW, przy czym w danych wejściowych może ich być wiele. Dlatego oryginalny awk kończy działanie po pierwszym dopasowaniu.

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

Więc zawartość skryptu varnishreload będzie wyglądać mniej więcej tak:

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

Powyższa logika może być krótko wyrażona w następujący sposób:
Jeśli ciąg pasuje do wyrażenia regularnego // VCL.SHOW, to żarłocznie zjedz tekst zawierający oba liczby w tym ciągu i zachowaj wszystko, co pozostanie po tej operacji. Zwróć zachowaną wartość i zakończ program.

Proste, prawda?

Byliśmy zadowoleni z skryptu sed i faktu, że zastępuje on cały oryginalny kod. Wszystkie moje testy dały pożądane wyniki, więc zmieniłem „varnishreload” na serwerze i ponownie uruchomiłem systemctl reload varnish. Zła pomyłka echo: błąd zapisu: Broken pipe znowu śmiała nam się w twarz. Mrugający kursor czekał na nową komendę w ciemnej pustce terminala…

Źródło: habr.com