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?
Давайте разберемся.
Команда состоит из четырех частей:
- Простое
echo
, которое выводит значение переменной${VCL_SHOW}
echo "$VCL_SHOW"
awk
, который ищет строку (запись), где первым полем, после разбиения текста, будет “//”, а вторым — "VCL.SHOW".
Awk выпишет первую строку, соответствующую этим шаблонам, а затем немедленно прекратит обработку.
awk '$1 == "//" && $2 == "VCL.SHOW" {print; exit}'
- Блок кода, который сохраняет в пять переменных значения полей, разделенных пробелами. Пятая переменная FILE получает остаток строки. Наконец, последний echo выписывает содержимое переменной
${FILE}
.
{ read -r DELIM VCL_SHOW INDEX SIZE FILE; echo "$FILE" }
- Поскольку все шаги с 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
вновь смеялась нам в лицо. Подмигивающий курсор ожидал ввода новой команды в темной пустоте терминала...