ProHoster > Blog > administracja > Spadanie do króliczej nory: Historia jednego błędu ponownego uruchomienia lakieru – część 1

Spadanie do króliczej nory: Historia jednego błędu ponownego uruchomienia lakieru – część 1

Duchinuszanka, po wciskaniu przycisków przez ostatnie 20 minut, jakby od tego zależało jego życie, odwraca się do mnie z półdzikim wyrazem oczu i chytrym uśmiechem – „Stary, chyba rozumiem”.

„Spójrz tutaj” – mówi, wskazując na jedną z postaci na ekranie. „Założę się, że jeśli dodamy tutaj to, co Ci przed chwilą wysłałem” – wskazując na inną sekcję kodu – „błąd nie będzie już występował zostać wyświetlony.”

Trochę zdziwiony i zmęczony zmieniam instrukcję sed, nad którą pracowaliśmy od jakiegoś czasu, zapisuję plik i uruchamiam systemctl varnish reload. Komunikat o błędzie zniknął...

„E-maile, które wymieniłem z kandydatem” – kontynuował mój kolega, gdy jego uśmiech zmienił się w prawdziwy uśmiech pełen radości – „nagle dotarło do mnie, że to jest dokładnie ten sam problem!”

Jak to wszystko się zaczęło

W artykule założono zrozumienie działania bash, awk, sed i systemd. Znajomość lakierów mile widziana, ale nie wymagana.
Zmieniono znaczniki czasu we fragmentach.
Napisane z Duchinuszanka.
Ten tekst jest tłumaczeniem oryginału opublikowanego w języku angielskim dwa tygodnie temu; tłumaczenie boyikoden.

Słońce wpada przez panoramiczne okna w kolejny ciepły jesienny poranek, kubek świeżo zaparzonego napoju z kofeiną spoczywa z boku klawiatury, w słuchawkach gra ulubiona symfonia dźwięków nad szelestem mechanicznych klawiatur, a pierwsze wejście w lista zgłoszeń zaległości na tablicy Kanban żartobliwie świeci się pod fatalnym tytułem „Zbadaj lakierreload sh: echo: błąd we/wy podczas przemieszczania” (Zbadaj „varnishreload sh: echo: błąd we/wy” podczas przemieszczania). W przypadku lakieru nie ma i nie może być błędów, nawet jeśli nie powodują one żadnych problemów, jak w tym przypadku.

Dla tych, którzy nie znają ponowne załadowanie lakieru, jest to prosty skrypt powłoki używany do ponownego załadowania konfiguracji lakier - zwany także VCL.

Jak sugeruje tytuł zgłoszenia, błąd wystąpił na jednym z serwerów na scenie, a ponieważ miałem pewność, że routing lakieru na scenie działa prawidłowo, założyłem, że będzie to drobny błąd. A więc tylko wiadomość, która dostała się do już zamkniętego strumienia wyjściowego. Biorę bilet dla siebie, mając całkowitą pewność, że w niecałe 30 minut oznaczę go jako gotowy, klepnę się po ramieniu za oczyszczenie tablicy z kolejnych śmieci i wracam do ważniejszych spraw.

Uderzenie w ścianę przy prędkości 200 km/h

Otwieranie pliku varnishreload, na jednym z serwerów, na którym działa Debian Stretch, widziałem skrypt powłoki o długości mniejszej niż 200 linii.

Przeglądając skrypt, nie widziałem niczego, co mogłoby powodować problemy przy wielokrotnym uruchomieniu go bezpośrednio z terminala.

Przecież to jest etap, nawet jeśli się zepsuje, nikt nie będzie narzekał, cóż… nie za bardzo. Uruchamiam skrypt i zobaczę, co zostanie zapisane na terminalu, ale błędy nie są już widoczne.

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

Czy skrypt może blokować STDOUT (używając > &-)? Albo STDERR? Żadne z nich ostatecznie nie zadziałało.

Oczywiście system w jakiś sposób zmienia środowisko uruchomieniowe, ale w jaki sposób i dlaczego?
Włączam vima i edytuję varnishreload, dodając set -x tuż pod shebangiem, mając nadzieję, że debugowanie wyników skryptu rzuci trochę światła.

Plik jest naprawiony, więc ładuję ponownie lakier i widzę, że zmiana całkowicie wszystko zepsuła… Wydech to kompletny bałagan, z tonami kodu w stylu C. Nawet przewijanie w terminalu nie wystarczy, aby znaleźć miejsce, w którym się zaczyna. Jestem całkowicie zdezorientowany. Czy tryb debugowania może wpływać na pracę programów uruchamianych w skrypcie? Nie, bzdura. Błąd w powłoce? Kilka możliwych scenariuszy fruwa mi po głowie niczym karaluchy w różnych kierunkach. Filiżanka napoju pełnego kofeiny opróżnia się natychmiast, szybki wypad do kuchni po uzupełnienie i… do dzieła. Otwieram skrypt i przyglądam się bliżej shebangowi: #!/bin/sh.

/bin/sh - to jest tylko dowiązanie symboliczne bash, więc skrypt jest interpretowany w trybie zgodnym z POSIX, prawda? Tego tam nie było! Domyślną powłoką w Debianie jest myślnik i właśnie o to chodzi odnosi się /bin/sh.

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

Na potrzeby procesu zmieniłem shebang na #!/bin/bash, REMOVED set -x i spróbowałem ponownie. Wreszcie, po ponownym załadowaniu lakieru, na wyjściu pojawił się akceptowalny 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 jest!

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 }

Jak się jednak okazało, linia 124 jest raczej pusta i nieciekawa. Mogłem tylko założyć, że błąd wystąpił w ramach multilinii zaczynającej się od linii 116.
Co ostatecznie zostanie zapisane w zmiennej VCL_FILE w wyniku wykonania powyższej podpowłoki?

Na początku wysyła zawartość zmiennej VLC_SHOW, utworzonego w linii 115, do następnego polecenia za pośrednictwem potoku. A co wtedy się tam dzieje?

Po pierwsze, używa varnishadm, który jest częścią pakietu instalacyjnego lakieru, aby skonfigurować lakier bez ponownego uruchamiania.

podpolecenie vcl.show -v służy do wyprowadzenia całej konfiguracji VCL określonej w ${VCL_NAME}, do STDOUT.

Aby wyświetlić aktualnie aktywną konfigurację VCL, a także kilka poprzednich wersji konfiguracji routingu lakieru, które są jeszcze w pamięci, możesz użyć polecenia varnishadm vcl.list, którego wynik będzie podobny do następującego:

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ść zmienna ${VCL_NAME} ustawiony w innej części skryptu varnishreload do nazwy aktualnie aktywnego VCL, jeśli istnieje. W tym przypadku będzie to „reload_20190101_120000_12397”.

OK, zmienne. ${VCL_SHOW} zawiera pełną konfigurację lakieru, dotychczas przejrzystą. Teraz w końcu rozumiem, dlaczego wyjście kreskowe jest wykonywane za pomocą set -x okazał się na tyle zepsuty - zawierał zawartość powstałej konfiguracji.

Ważne jest, aby zrozumieć, że pełną konfigurację VCL często można połączyć z wielu plików. Komentarze w stylu C służą do określenia, gdzie jeden plik konfiguracyjny został dołączony do innego i właśnie o to chodzi w poniższym fragmencie kodu.
Składnia komentarzy opisujących dołączone pliki ma następujący format:

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

Liczby w tym kontekście nie są istotne, interesuje nas nazwa pliku.

Co więc dzieje się na bagnie poleceń rozpoczynającym się w linii 116?
Zrozummy to.
Polecenie składa się z czterech części:

  1. Proste echo, który wyświetla wartość zmiennej ${VCL_SHOW} 
    echo "$VCL_SHOW"
  2. awk, który szuka linii (rekordu), gdzie pierwszym polem po podzieleniu tekstu będzie „//”, a drugim „VCL.SHOW”.
    Awk wypisze pierwszą linię pasującą do tych wzorców, a następnie natychmiast zatrzyma przetwarzanie.

    awk '$1 == "//" && $2 == "VCL.SHOW" {print; exit}'
  3. Blok kodu przechowujący wartości pól w pięciu zmiennych oddzielonych spacjami. Piąta zmienna FILE otrzymuje resztę linii. Na koniec ostatnie echo zapisuje 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 podpowłoce, wynikiem jest wartość $FILE zostanie zapisany do zmiennej VCL_FILE.

Jak sugeruje komentarz do linii 119, służy to wyłącznie niezawodnej obsłudze przypadków, w których VCL będzie odnosić się do plików zawierających białe znaki w ich nazwach.

Skomentowałem oryginalną logikę przetwarzania dla ${VCL_FILE} i próbowałem zmienić kolejność poleceń, ale to do niczego nie doprowadziło. U mnie wszystko działało czysto, a w przypadku uruchomienia usługi wywalał błąd.

Wygląda na to, że błąd jest po prostu nie do odtworzenia przy ręcznym uruchomieniu skryptu, choć szacunkowe 30 minut skończyło się już sześć razy, a w dodatku pojawiło się zadanie o wyższym priorytecie, odsuwając inne rzeczy na bok. Pozostała część tygodnia wypełniona była różnorodnymi zadaniami i tylko nieznacznie została rozmyta rozmową na sedzie i rozmową kwalifikacyjną z kandydatem. Problem z błędem w varnishreload bezpowrotnie zagubiony w piaskach czasu.

Twoje tak zwane sed-fu... właściwie... bzdury

Następny tydzień miał jeden w miarę wolny dzień, więc zdecydowałem się ponownie sięgnąć po ten bilet. Miałem nadzieję, że w moim mózgu jakiś proces w tle przez cały ten czas szukał rozwiązania tego problemu i tym razem na pewno zrozumiem co jest nie tak.

Ponieważ ostatnim razem sama zmiana kodu nie pomogła, zdecydowałem się po prostu przepisać go, zaczynając od 116 linii. W każdym razie istniejący kod był głupi. I absolutnie nie ma potrzeby korzystania read.

Ponownie patrząc na błąd:
sh: echo: broken pipe - w tym poleceniu echo występuje w dwóch miejscach, ale podejrzewam, że bardziej prawdopodobnym winowajcą (no cóż, a przynajmniej wspólnikiem) jest to pierwsze. Awk też nie budzi zaufania. I jeśli rzeczywiście tak jest awk | {read; echo} projekt prowadzi do wszystkich tych problemów, dlaczego więc go nie zastąpić? To jednowierszowe polecenie nie wykorzystuje wszystkich funkcji awk, a nawet tych dodatkowych read w dodatku.

Od zeszłego tygodnia pojawił się raport nt sedChciałem spróbować swoich nowo nabytych umiejętności i uprościć echo | awk | { read; echo} w bardziej zrozumiały echo | sed. Chociaż zdecydowanie nie jest to najlepsze podejście do wyłapania błędu, pomyślałem, że przynajmniej spróbuję mojego sed-fu i może dowiem się czegoś nowego o problemie. Po drodze poprosiłem kolegę, autora rozmów sed, o pomoc w opracowaniu bardziej wydajnego skryptu sed.

Upuściłem zawartość varnishadm vcl.show -v "$VCL_NAME" do pliku, dzięki czemu mogę skupić się na pisaniu skryptu sed bez kłopotów związanych z ponownym uruchamianiem usług.

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

W kilku przejściach, za radą mojego kolegi, napisaliśmy skrypt sed, który dał taki sam wynik, jak cała oryginalna linia 116.

Poniżej przykładowy plik z danymi wejściowymi:

> 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 powyższego opisu może nie wynika to jasno, ale nas interesuje tylko pierwszy komentarz // VCL.SHOW, a w danych wejściowych może ich być kilka. To dlatego oryginalny awk kończy się 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

Zatem zawartość skryptu lakieru 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ższą logikę można podsumować w następujący sposób:
Jeśli ciąg pasuje do wyrażenia regularnego // VCL.SHOW, następnie zachłannie pochłoń tekst zawierający obie liczby w tym wierszu i zapisz wszystko, co pozostało po tej operacji. Wydaj zapisaną wartość i zakończ program.

Proste, prawda?

Byliśmy zadowoleni ze skryptu sed i faktu, że zastępuje on cały oryginalny kod. Wszystkie moje testy dały oczekiwane rezultaty, więc zmieniłem „varnishreload” na serwerze i uruchomiłem ponownie systemctl reload varnish. Brudny błąd echo: write error: Broken pipe znowu zaśmiał nam się w twarz. Mrugający kursor czekał na wprowadzenie nowego polecenia w ciemnej pustce terminala...

Źródło: www.habr.com

Dodaj komentarz