Падане в зайчата дупка: История за една грешка при рестартиране на varnish — част 1

гостинг, натискайки копчета през последните 20 минути, сякаш животът му зависеше от това, се обръща към мен с полудив поглед и хитра усмивка — „Човече, изглежда, че разбрах.“

„Погледни тук,“ — казва, посочвайки един от символите на екрана — „Залагам ти червена шапка, че ако добавим това, което ти изпратих току-що“ — посочвайки друга част от кода — „грешката вече няма да се появи.“

Малко объркан и уморен, променям sed израза, с който вече работим известно време, записвам файла и стартирам systemctl varnish reload. Съобщението за грешка изчезна…

„Имейлите, които обменях с кандидата,“ продължи колегата ми, докато усмивката му прераства в искрена усмивка, изпълнена с радост, „изведнъж разбрах, че това е точно същият проблем!“

Как всичко започна

Статията предполага разбиране на принципите на работа на bash, awk, sed и systemd. Познанията за varnish са желателни, но не са задължителни.
Временните маркировки в фрагментите са променени.
Написано съвместно с гостинг.
Текстът е превод на оригинална статия, публикувана на английски преди две седмици; превод boikoden.

Слънцето пробива през панорамните прозорци в още един топъл есенен сутрин, чаша прясно приготвено кафе стои встрани от клавиатурата, любимата ми симфония звучи в слушалките, заглушаваща шума на механичните клавиатури, а първият запис в списъка на тикетите в беклога на канбан дъската бляскаво светва със съдбовния заглавие “Изследвайте varnishreload sh: echo: I/O error in staging” (Разследвайте “varnishreload sh: echo: I/O error” в стейджа). Когато става въпрос за varnish, грешки няма и не може да има, дори ако те не водят до никакви проблеми, както в този случай.

За тези, които не са запознати с varnishreload, това е прост shell скрипт, използван за перезареждане на конфигурацията на varnish — също наречен VCL.

Както подсказва името на тикета, грешката възникна на един от сървърите на стейджа и тъй като бях убеден, че маршрутизацията на varnish на стейджа работи правилно, предположих, че ще е нещо дребно. Просто съобщение, попаднало в вече затворен изходен поток. Взимам тикета за себе си, напълно уверен, че ще го отбележа за готов след по-малко от 30 минути, ще се похваля сам на себе си за освежаването на борда от още един боклук и ще се върна към по-важни неща.

Пресичайки стена на скорост 200 км/ч

Отваряйки файла varnishreload, на един от сървърите с Debian Stretch, видях шелл скрипт с дължина под 200 реда.

Разглеждайки скрипта, не забелязах нищо, което би могло да доведе до проблеми при многократното му пускане директно от терминала.

В крайна сметка, това е стейдж, дори и да се счупи, никой няма да се оплаче, ами... не прекалено много. Пускам скрипта и гледам какво ще излезе на терминала, но вече не виждам грешки.

Още няколко пускания, за да се уверя, че не мога да възпроизведа грешката без някакви допълнителни усилия, и започвам да се чудя как да променя този скрипт, за да го накарам да генерира грешка.

Може би да препиша STDOUT (с помощта на > &-)? Или STDERR? Нито едно от двете в крайна сметка не проработи.

Очевидно, systemd по някакъв начин променя средата на стартиране, но как и защо?
Включвам vim и редактирам varnishreload, добавяйки set -x точно под шебанг, надявайки се, че дебъг изходът на скрипта ще осветли малко.

Файлът е поправен, така че рестартирам varnish и виждам, че промените тотално разчупиха всичко... Изходът е пълен хаос, с тонове C-подобен код. Дори не е достатъчно скролването в терминала, за да намеря откъде започва. Във вътрешно объркване съм. Може ли режимът на дебъгинг да влияе на работата на програмите, стартирани в скрипта? Не, глупости. Бъг в шелла? Няколко възможни сценария препускат в главата ми като хлебарки в различни посоки. Чашата с кофеиново съдържание бързо се изпразва, бързо пътуване до кухнята за попълване на запасите и... напред. Отварям скрипта и се вглеждам в шебанга: #!/bin/sh.

/bin/sh — това е просто симлинк на bash, така че скриптът се интерпретира в POSIX-совместим режим, нали? Не така! Обвивката по подразбиране в Debian е dash и именно това е, се позовава /bin/sh.

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

Пробвайки, промених шебанга на #!/bin/bash, изтрих set -x и опитах отново. Най-сетне, при последващо перезареждане на varnish, в изхода се появи разбираема грешка:

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' компилиран

Ред 124, ето го!

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                         # всичко това е за да се обработят празните файлове
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 "неуспех при получаване на името на VCL файла"
129         fi
130
131         echo "$VCL_FILE"
132 }

Но както се оказа, ред 124 е доста празен и не представлява интерес. Можех само да предполагам, че грешката е възникнала като част от многострочник, започващ на ред 116.
Какво в крайна сметка се записва в променливата VCL_FILE в резултат на изпълнението на гореспоменатия саб-шел?

В началото той изпраща съдържанието на променливата VLC_SHOW, създадена на ред 115, на следната команда чрез пайп. А какво се случва там?

Първо, там се използва varnishadm, който е част от инсталационния пакет varnish, за конфигуриране на varnish без рестартиране.

Подкомандата vcl.show -v се използва за извеждане на цялата конфигурация VCL, указанa в ${VCL_NAME}, в STDOUT.

За да се отрази текущата активна конфигурация VCL, както и няколко предишни версии на конфигурации за маршрутизация на varnish, които все още са в паметта, можете да използвате командата varnishadm vcl.list, изходът на която ще бъде подобен на показания по-долу:

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

Стойността на променливата ${VCL_NAME} се задава в друга част от скрипта varnishreload на името на активното в момента VCL, ако такова съществува. В този случай, това ще бъде “reload_20190101_120000_12397”.

Отлично, променливата ${VCL_SHOW} съдържа пълната конфигурация за varnish, докато е ясно. Сега най-накрая разбрах, защо изхода на dash set -x се оказа толкова повреден — включваше съдържанието на получената конфигурация.

Важно да се разбере, че пълната конфигурация на VCL често може да бъде сглобена от няколко файла. Коментарите в стил C се използват за определяне на местата, където един конфигурационен файл е включен в друг, и именно за това става въпрос във фрагмента от кода по-долу.
Синтаксисът на коментарите, описващи включените файлове, има следния формат:

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

Числата в този контекст не са важни, нас интересува името на файла.

Какво всъщност се случва в блатото от команди, които започват на ред 116?
Нека разберем.
Командата се състои от четири части:

1. Просто echo, което извежда стойността на променливата ${VCL_SHOW}

   echo "$VCL_SHOW"

2. awk, която търси ред (запис), където първото поле, след разделяне на текста, е “//”, а второто — «VCL.SHOW».
   Awk ще отпечата първия ред, отговарящ на тези шаблони, и след това незабавно ще спре обработката.

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

3. Блок от код, който запазва в пет променливи стойностите на полетата, разделени с интервал. Петата променлива FILE получава остатъка от реда. Накрая, последният echo отпечатва съдържанието на променливата ${FILE}.

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

4. Тъй като всичките стъпки от 1 до 3 са поставени в саб-шел, изходът на стойността $FILE ще бъде записан в променливата. VCL_FILE.

Както е посочено в коментара на ред 119, това служи на единствената цел: надеждно да обработва случаи, когато VCL ще се отнася до файлове със символи за интервал в името си.

Закоментирах първоначалната логика на обработка за ${VCL_FILE} и се опитах да променя последователността на командите, но това не доведе до нищо. Успехът ми беше хванат в момента, а в случай на стартиране на услугата се появяваха грешки.

Похоже, че грешката просто не се възпроизвежда при стартиране на скрипта ръчно, като предполагаемите 30 минути вече са изтекли поне шест пъти и, в добавка, се появи по-важна задача, която изтласка другите на заден план. Останалата част от седмицата беше запълнена с най-разнообразни задачи и беше само леко разредена от доклад за sed и интервю с кандидат. Проблемът с грешката в varnishreload бе загубен завинаги в пясъците на времето.

Вашето така наречено sed-фу… всъщност… е боклук.

Следната седмица имаше един доста свободен ден, така че отново реших да се занимавам с този тикет. Надявах се, че в мозъка ми, някакъв фонов процес през цялото време е търсил решение на този проблем и този път със сигурност ще разбера каква е работата.

Тъй като миналия път простото изменение на кода не помогна, реших просто да го пренапиша, започвайки от 116-та линия. Във всеки случай съществуващият код беше нещо като глупост. И в него не е нужно абсолютно никакво да се използва read.

Гледайки грешката още веднъж:
sh: echo: broken pipe — в тази команда echo присъства на два места, но предполагам, че първото е по-вероятния виновник (или поне съучастник). Awk също не вдъхва доверие. И в случай, че наистина това е awk | {read; echo} конструкцията, която води до всичките тези проблеми, защо да не я заменим? Тази едноредна команда не използва всичките възможности на awk, а и този излишен read в добавка.

Тъй като миналата седмица имаше доклад за sed, исках да опитам моите наскоро придобити умения и да опростя echo | awk | { read; echo} в по-разбираем echo | sed. Въпреки че това определено не е най-добрият подход за идентифициране на грешки, помислих, че поне ще опитам своя сед-fu и може би ще науча нещо ново за проблема. В хода на работата помолих колегата си, автора на доклада за sed, да ми помогне да измисля по-ефективен sed скрипт.

Изпратих съдържанието на varnishadm vcl.show -v "$VCL_NAME" в файл, за да мога да се съсредоточа върху написването на sed скрипт без никакви главоболия, свързани с рестартиране на услугата.

Кратко описание на начина, по който sed обработва входните данни, може да се намери в неговото GNU ръководство. В изходния код на sed символът n е явен като разделител на редовете.

След няколко преминавания и с насоките на моят колега написахме sed скрипт, който даваше същия резултат, както и цялата оригинална ред 116.

По-долу е показан пример на файл със входни данни:

> 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

Може да не е очевидно от приведеното по-горе описание, но ни интересува само първият коментар // VCL.SHOW, като в входните данни може да има няколко от тях. Точно затова оригиналният awk спира да работи след първото съвпадение.

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

И така, съдържанието на скрипта varnishreload ще изглежда приблизително така:

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

По-горе представената логика може да бъде кратко изразена по следния начин:
Ако низът отговаря на регулярното изражение // VCL.SHOW, тогава жадно изяж текста, включващ и двете числа в този низ, и запази всичко, което остава след тази операция. Изведи запазената стойност и завърши програмата.

Просто, нали?

Бяхме доволни от скрипта на sed и от факта, че той заменя целия оригинален код. Всички мои тестове дадоха желаните резултати, затова промених “varnishreload” на сървера и отново стартирах systemctl reload varnish. Проклетата грешка echo: write error: Broken pipe отново се присмиваше в лицето ни. Мигащият курсор очакваше въвеждане на нова команда в тъмната пустота на терминала…

Източник: habr.com