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

ghostinushanka, молотив по кнопкам в течение предыдущих 20 минут, как если бы от этого зависела его жизнь, поворачивается ко мне с полу-диким выражением в глазах и хитрой ухмылкой — "Чувак, я кажется понял."

"Посмотри вот сюда," — говорит, показывая на один из символов на экране — "Спорим на мою красную шляпу, что если мы добавим вот сюда то, что я тебе только что послал" — показывая на другой участок кода — "ошибка уже не будет выводиться."

Немного озадаченный и уставший, я изменяю sed выражение, над которым мы какое-то время уже работали, сохраняю файл и запускаю systemctl varnish reload. Сообщение об ошибке исчезло...

"Мейлы, которыми я обменивался с кандидатом," продолжил мой коллега, в то время как его ухмылка перерастает в неподдельную улыбку полную радости, "До меня вдруг дошло что это точно такая же проблема!"

С чего оно всё начиналось

Статья предполагает понимание принципов работы bash, awk, sed и systemd. Знание varnish приветствуется, но не является обязательным.
Временные метки в сниппетах изменены.
Написано вместе с ghostinushanka.
Этот текст является переводом оригинала, опубликованного на английском языке две недели назад; перевод boikoden.

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

Для тех, кто не знаком с varnishreload, это простой шелл скрипт, используемый для перезагрузки конфигурации varnish-а — также называемой VCL.

Как подсказывает название тикета, ошибка возникла на одном из серверов на стейдже, а так как я был уверен, что маршрутизация varnish-а на стейдже работает исправно, я предположил, что это будет мелкой ошибкой. Так, просто сообщение попавшее в уже закрытый выходной поток. Беру тикет себе, в полной уверенности, что я его отмечу готовым менее чем через 30 минут, похлопаю сам себя по плечу за очистку борды от очередного хлама и вернусь к более важным делам.

Врезаясь в стену на скорости 200 км/ч

Открыв файл varnishreload, на одном из серверов под управлением Debian Stretch, я увидел шелл скрипт длиной менее 200 строк.

Пробежавшись по скрипту, я не заметил ничего такого, что могло бы вылиться в проблемы при многократном его запуске прямо из терминала.

В конце концов, это стейдж, даже если оно и сломается, никто не будет жаловаться, ну… не слишком много. Запускаю скрипт и смотрю что будет выписываться на терминал, вот только ошибок уже и не видно.

Еще пару запусков, чтобы убедиться, что я не могу воспроизвести ошибку без каких-либо дополнительных усилий, и я начинаю придумывать как этот скрипт изменить и заставить его таки выдавать ошибку.

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

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

Файл поправлен, так что я перезагружаю varnish и вижу что изменение начисто всё сломало… Выхлоп — полный бардак, в котором тонны Си-подобного кода. Даже прокрутки в терминале недостаточно, чтобы найти где оно начинается. Я в полном замешательстве. Может ли режим отладки повлиять на работу программ запускаемых в скрипте? Нет, бред. Баг в шелле? Несколько возможных сценариев несутся в моей голове как тараканы в разные стороны. Чашка кофеино-полного напитка мгновенно опустошается, быстрое путешествие на кухню для пополнения запаса и… поехали. Я открываю скрипт и присматриваюсь к шебангу: #!/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' compiled

Строка 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                         # 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 }

Но как оказалось, строка 124 довольно пуста и интереса не представляет. Я мог лишь только предположить, что ошибка возникла как часть многострочника, начинающегося на 116-й строке.
Что в итоге записывается в переменную VCL_FILE в результате выполнения вышеупомянутого саб-шелла?

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

Во-первых, там используется varnishadm, который является частью установочного пакета varnish, для настройки varnish-а без перезапуска.

Подкоманда vcl.show -v используется для вывода всей конфигурации VCL, указанной в ${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 часто может быть слеплена из нескольких файлов. Комментарии в Си стиле используются для определения того, где одни файлы конфигурации были включены в другие, и это именно то, о чем, собственно, вся приведённая ниже строка фрагмента кода.
Синтаксис комментариев, описывающих включенные файлы, имеет следующий формат:

// 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. Хотя это определенно не лучший подход к выявлению ошибки, я подумал, что по крайней мере попробую свое 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 вновь смеялась нам в лицо. Подмигивающий курсор ожидал ввода новой команды в темной пустоте терминала...