, furiously clicking the buttons for the past 20 minutes as if his life depended on it, turns to me with a half-wild look in his eyes and a sly grin — "Dude, I think I've got it."
“Look here,” he says, pointing to one of the symbols on the screen — “I bet my red hat that if we add what I just sent you here” — pointing to another section of the code — “the error won’t show up anymore.”
A bit puzzled and tired, I modify the sed expression we've been working on for a while, save the file, and run it systemctl varnish reload. The error message disappeared…
“The emails I exchanged with the candidate,” my colleague continued, as his smirk grew into a genuine smile full of joy, “I suddenly realized that this is exactly the same issue!”
How it all started
The article assumes an understanding of the principles of bash, awk, sed, and systemd. Knowledge of varnish is welcome but not mandatory.
Timestamps in snippets have been changed.
Written together with .
This text is a translation of the original published in English two weeks ago; translation .
The sun streams through the panoramic windows on yet another warm autumn morning, a cup of freshly brewed caffeine-rich drink rests beside the keyboard, my favorite symphony fills the headphones, drowning out the sound of mechanical keyboards, and the first entry on the backlog Kanban board playfully glows with the fateful title “Investigate varnishreload sh: echo: I/O error in staging.” When it comes to varnish, there is no room for errors, even if they don't lead to any problems, as in this case.
For those unfamiliar with , it is a simple shell script used to reload the configuration — also called VCL.
As the ticket name suggests, the error occurred on one of the servers on the staging environment, and since I was confident that the Varnish routing on staging was working properly, I assumed it would be a minor issue. Just a message caught in an already closed output stream. I take the ticket for myself, fully confident that I will mark it as resolved in less than 30 minutes, pat myself on the back for cleaning up the board from another piece of junk, and return to more important matters.
Crashing into a wall at 200 km/h
Opening the file varnishreload, on one of the servers running Debian Stretch, I saw a shell script of less than 200 lines.
Glancing through the script, I didn’t notice anything that could lead to issues when run multiple times directly from the terminal.
After all, it’s only staging; even if it breaks, no one will complain, well… not too much. I run the script and see what will be outputted to the terminal, but there are no errors to be seen.
A few more runs to make sure I can’t reproduce the error without any additional effort, and I start thinking about how to modify this script to make it produce the error.
Maybe the script should redirect STDOUT (using > &-)? Or STDERR? Neither worked in the end.
Clearly, systemd somehow alters the execution environment, but how, and why?
I fire up vim and edit varnishreload, adding set -x right under the shebang, hoping the debug output from the script will shed a little light.
The file is fixed, so I restart Varnish and see that the change has completely broken everything… The output is a complete mess, with tons of C-like code. Even the scroll in the terminal isn’t enough to find where it starts. I’m completely baffled. Could the debugging mode affect the operation of programs called in the script? No, that’s nonsense. A bug in the shell? Several possible scenarios buzz through my head like cockroaches scattering in different directions. My cup of caffeinated beverage is instantly emptied, a quick trip to the kitchen for a refill and… here we go. I open the script and take a closer look at the shebang: #!/bin/sh.
/bin/sh — it’s just a symlink to bash, so the script is interpreted in POSIX-compatible mode, right? Not so fast! The default shell in Debian is dash, and that’s exactly what /bin/sh.
# ls -l /bin/sh
lrwxrwxrwx 1 root root 4 Jan 24 2017 /bin/sh -> dashFor the sake of testing, I changed the shebang to #!/bin/bash, deleted set -x and tried again. Finally, upon the next reload of Varnish, a reasonable error appeared in the output:
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' compiledLine 124, there it is!
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 }But as it turns out, line 124 is quite empty and uninteresting. I could only assume that the error arose as part of a multiline statement beginning at line 116.
What ultimately gets written to the variable VCL_FILE as a result of the execution of the aforementioned subshell?
Initially, it sends the contents of the variable VLC_SHOW, created on line 115, to the following command through a pipe. And what happens there?
First of all, it uses varnishadm, which is part of the Varnish installation package, to configure Varnish without restarting.
The subcommand vcl.show -v is used to output the entire VCL configuration specified in ${VCL_NAME}, to STDOUT.
To display the current active VCL configuration, as well as several previous versions of Varnish's routing configurations that are still in memory, you can use the command varnishadm vcl.list, the output of which will be similar to what is shown below:
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_12587The variable value ${VCL_NAME} is set elsewhere in the script varnishreload to the name of the currently active VCL, if one exists. In this case, it will be “reload_20190101_120000_12397”.
Great, the variable ${VCL_SHOW} contains the complete configuration for Varnish, which is clear so far. Now I finally understood why the output of dash set -x was so broken — it included the contents of the resulting configuration.
It's important to understand that a complete VCL configuration can often be stitched together from multiple files. C-style comments are used to indicate where one configuration file has been included in another, and that is exactly what the entire code snippet below refers to.
The syntax for comments describing included files has the following format:
// VCL.SHOW <NUM> <NUM> <FILENAME>The numbers in this context are not important; what matters is the name of the file.
So what's going on in the swamp of commands starting on line 116?
Let's break it down.
The command consists of four parts:
- A simple
echo, which outputs the value of the variable${VCL_SHOW}echo "$VCL_SHOW" awk, which looks for a line (record) where the first field, after splitting the text, is ‘//’, and the second is ‘VCL.SHOW’.
Awk will print the first line that matches these patterns and then immediately stop processing.awk '$1 == "//" && $2 == "VCL.SHOW" {print; exit}'- A block of code that saves the values of fields separated by spaces into five variables. The fifth variable FILE takes the rest of the line. Finally, the last echo prints the contents of the variable
${FILE}.{ read -r DELIM VCL_SHOW INDEX SIZE FILE; echo "$FILE" } - Since all steps from 1 to 3 are enclosed in a subshell, the output value
$FILEwill be stored in a variable.VCL_FILE.
As mentioned in the comment on line 119, this serves a single purpose: to reliably handle cases where VCL refers to files with spaces in their names.
I commented out the original processing logic for ${VCL_FILE} and tried to change the sequence of commands, but it led to nothing. Everything worked fine for me, and when starting the service, it produced an error.
It seems that the error is simply not reproducible when running the script manually, while the supposed 30 minutes have already passed about six times, and on top of that, a higher-priority task pushed other matters aside. The rest of the week was filled with various tasks and was only slightly diluted with a report on sed and an interview with a candidate. The issue with the error in varnishreload was irrevocably lost in the sands of time.
Your so-called sed-fu… is actually… garbage.
Next week I had a rather free day, so I decided to tackle this ticket again. I hoped that in my brain, some background process had been searching for a solution to this issue all along and this time I would definitely understand what was going on.
Since the last time a simple code change didn't help, I decided to rewrite it starting from line 116. In any case, the existing code was rather convoluted. And there was absolutely no need to use write.
Looking at the error once more:
sh: echo: broken pipe — in this command, echo appears in two places, but I suspect that the first is the more likely culprit (or at least an accomplice). Awk also raises suspicions. And in case it really is awk | {read; echo} this construct leads to all these problems, why not replace it? This one-liner doesn't utilize all the capabilities of awk, not to mention this extra write crutch.
Since there was a talk last week about sed, I wanted to try out my newly acquired skills and simplify echo | awk | { read; echo} to a clearer echo | sed. Although this is definitely not the best approach to debugging, I thought at least I'd try my sed-fu and maybe learn something new about the issue. Along the way, I asked my colleague, the author of the sed talk, to help me devise a more efficient sed script.
I dropped the contents of varnishadm vcl.show -v "$VCL_NAME" into a file, so I could focus on writing the sed script without any worries related to service restarts.
A brief explanation of how sed handles input data can be found in . In the source code of sed, the character n is explicitly defined as the line delimiter.
After several passes and with recommendations from my colleague, we wrote a sed script that yielded the same result as the entire original line 116.
Below is a sample input file:
> 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 textThis may not be obvious from the description above, but we are only interested in the first comment // VCL.SHOW, and there can be several of these in the input data. That's why the original awk finishes its work after the first match.
# шаг первый, вывести только строки с комментариями
# используя возможности 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.vclSo, the contents of the varnishreload script will roughly look like this:
VCL_FILE="$(echo "$VCL_SHOW" | sed -En '#// VCL.SHOW#{s#.*[0-9]+ [0-9]+ (.*)$#1#p;q;};')"The logic above can be succinctly expressed as follows:
If the string matches the regular expression // VCL.SHOW, then greedily consume the text containing both numbers in this string, and save everything that remains after this operation. Output the saved value and end the program.
Simple, isn't it?
We were pleased with the sed script and the fact that it replaced the entire original code. All my tests yielded the desired results, so I changed “varnishreload” on the server and restarted systemctl reload varnish. A nasty error echo: write error: Broken pipe laughed in our face again. The blinking cursor awaited a new command in the dark void of the terminal...
Source: habr.com
