, terwijl hij de knoppen de afgelopen 20 minuten indrukte, alsof zijn leven ervan afhing, draait hij zich naar me om met een half-wilde blik in zijn ogen en een slimme grijns — "Hé, ik denk dat ik het snap."
"Kijk hier," zegt hij, wijzend naar een van de symbolen op het scherm — "Wedden om mijn rode hoed dat als we hier iets toevoegen, wat ik je net heb gestuurd" — wijzend naar een ander deel van de code — "de fout niet meer verschijnt."
Een beetje verward en moe, pas ik de sed-expressie aan waar we al een tijdje mee bezig zijn, sla het bestand op en voer het uit systemctl varnish reload. Het foutbericht is verdwenen…
"De e-mails die ik met de kandidaat heb uitgewisseld," ging mijn collega verder, terwijl zijn grijns overging in een oprechte glimlach vol vreugde, "Daar besefte ik ineens dat dit precies hetzelfde probleem is!"
Hoe het allemaal begon
Het artikel veronderstelt begrip van de principes van bash, awk, sed en systemd. Kennis van varnish is welkom, maar niet verplicht.
Tijdstempels in de snippets zijn gewijzigd.
Geschreven samen met .
Deze tekst is een vertaling van het origineel, gepubliceerd in het Engels twee weken geleden; vertaling .
De zon schijnt door de panoramische ramen op een warme herfstochtend, een kopje vers gezette cafeïne houdende drank ligt naast het toetsenbord, mijn favoriete symfonie klinkt in mijn oortjes, die het geluid van mechanische toetsenborden overstemt, en de eerste vermelding in de backlog-tickets op het kanban-bord schittert speels met de fatale titel “Investigate varnishreload sh: echo: I/O error in staging” (Onderzoek “varnishreload sh: echo: I/O error” in staging). Wanneer het gaat om varnish, is er geen plaats voor fouten, zelfs als die niet tot problemen leiden zoals in dit geval.
Voor degenen die niet bekend zijn met , dit is een eenvoudig shell-script dat wordt gebruikt om de configuratie te herladen — ook wel VCL genoemd.
Zoals de titel van het ticket aangeeft, deed de fout zich voor op een van de servers op de staging-omgeving. Aangezien ik er zeker van was dat de routing van Varnish op de staging-omgeving correct functioneerde, vermoedde ik dat het om een kleine fout ging. Gewoon een bericht dat was beland in een reeds gesloten uitvoerstroom. Ik neem het ticket op me, met de volle overtuiging dat ik het binnen 30 minuten als opgelost kan markeren, geef mezelf een schouderklopje voor het opruimen van de board en keer terug naar belangrijkere zaken.
Tegen een muur van 200 km/u botsen.
Bij het openen van het bestand varnishreload, op een van de servers die draaien op Debian Stretch, zag ik een shell-script van minder dan 200 regels lang.
Bij het snel doorleiden van het script, viel me niets op dat problemen zou kunnen veroorzaken bij meerdere uitvoeringen rechtstreeks vanuit de terminal.
Uiteindelijk is dit een staging-omgeving; zelfs als het kapotgaat, zal niemand klagen, nou ja... niet te veel. Ik voer het script uit en kijk wat er op de terminal verschijnt, maar fouten zijn niet te zien.
Nog een paar uitvoeringen om te bevestigen dat ik de fout niet kan reproduceren zonder enige extra inspanning, en ik begin ideeën te verzinnen over hoe ik het script kan aanpassen om het toch een fout te laten geven.
Misschien moet ik de STDOUT van het script onderdrukken (met behulp van > &-)? Of STDERR? Geen van beide werkte uiteindelijk.
Het is duidelijk dat systemd op de een of andere manier de runtime-omgeving verandert, maar hoe, en waarom?
Ik start vim en bewerk varnishreload, waarbij ik set -x direct onder de shebang toevoeg, hopend dat de debug-uitvoer van het script wat licht zal schijnen.
Het bestand is aangepast, dus ik herstart Varnish en zie dat de wijziging alles volledig heeft gebroken… De uitvoer is een complete chaos, met tonnen C-achtige code. Zelfs de scrollfunctie in de terminal is niet genoeg om te vinden waar het begint. Ik ben compleet in de war. Kan de debugmodus de uitvoering van programma's die in het script worden aangeroepen beïnvloeden? Nee, dat is onzin. Een bug in de shell? Verschillende mogelijke scenario's schieten door mijn hoofd als kakkerlakken in verschillende richtingen. Mijn kop koffie is in een oogwenk leeg, een snelle reis naar de keuken om mijn voorraad aan te vullen en… laten we gaan. Ik open het script en kijk goed naar de shebang: #!/bin/sh.
/bin/sh — dit is gewoon een symlink naar bash, dus het script wordt geïnterpreteerd in POSIX-compatibele modus, toch? Dat blijkt niet het geval te zijn! De standaard shell in Debian is dash, en dat is precies waar /bin/sh.
# ls -l /bin/sh
lrwxrwxrwx 1 root root 4 Jan 24 2017 /bin/sh -> dashVoor de proef heb ik de shebang veranderd in #!/bin/bash, verwijderd set -x en heb het nog een keer geprobeerd. Eindelijk, na de volgende herstart van varnish, verscheen er een acceptabele fout in de output:
Jan 01 12:00:00 hostname varnishreload[32604]: /usr/sbin/varnishreload: regel 124: echo: schrijf fout: Verbroken pijp
Jan 01 12:00:00 hostname varnishreload[32604]: VCL 'reload_20190101_120000_32604' gecompileerdRegel 124, daar is het!
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 # al deze ceremonie om lege bestanden in FILE te verwerken
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 "mislukt om de VCL-bestandsnaam te krijgen"
129 fi
130
131 echo "$VCL_FILE"
132 }Maar het bleek dat regel 124 behoorlijk leeg is en geen interesse wekt. Ik kon alleen maar aannemen dat de fout voortkwam uit een multi-line commentaar dat begon op regel 116.
Wat wordt er uiteindelijk opgeslagen in de variabele VCL_FILE als resultaat van de uitvoering van de bovengenoemde subshell?
Aan het begin stuurt het de inhoud van de variabele VLC_SHOW, gecreëerd op regel 115, naar de volgende opdracht via een pipe. En wat gebeurt daar dan?
Ten eerste wordt varnishadm, dat onderdeel is van het installatiepakket varnish, gebruikt om varnish te configureren zonder het opnieuw op te starten.
De subopdracht vcl.show -v wordt gebruikt om de volledige VCL-configuratie die is opgegeven in ${VCL_NAME}, naar STDOUT te schrijven.
Om de huidige actieve VCL-configuratie weer te geven, evenals enkele eerdere versies van de VCL-configuraties van varnish die nog in het geheugen zijn, kan de opdracht varnishadm vcl.listworden gebruikt, waarvan de uitvoer vergelijkbaar zal zijn met het onderstaande:
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_12587De waarde van de variabele ${VCL_NAME} wordt ingesteld in een ander deel van het script varnishreload op de naam van de momenteel actieve VCL, indien aanwezig. In dit geval is dat "reload_20190101_120000_12397."
Uitstekend, de variabele ${VCL_SHOW} bevat de volledige configuratie voor varnish, dat is nu duidelijk. Nu begrijp ik eindelijk waarom de output van dash set -x zo verbroken was -- het bevatte de inhoud van de resulterende configuratie.
Het is belangrijk te begrijpen dat een volledige VCL-configuratie vaak uit meerdere bestanden kan bestaan. C-style commentaar wordt gebruikt om aan te geven waar de ene configuratiebestanden in de andere zijn opgenomen, en dat is precies waar de onderstaande codefragment over gaat.
De syntaxis van de opmerkingen die de opgenomen bestanden beschrijven, heeft het volgende formaat:
// VCL.SHOW <NUM> <NUM> <FILENAME>De cijfers in deze context zijn niet belangrijk, we zijn geïnteresseerd in de bestandsnaam.
Wat gebeurt er nu in de moeras van commando's die beginnen op regel 116?
Laten we het uitzoeken.
Het commando bestaat uit vier delen:
- Eenvoudig
echo, dat de waarde van de variabele weergeeft${VCL_SHOW}echo "$VCL_SHOW" awk, dat zoekt naar een regel (record) waar het eerste veld, na het splitsen van de tekst, “//” is en het tweede veld “VCL.SHOW”.
Awk zal de eerste regel die aan deze patronen voldoet afdrukken en vervolgens onmiddellijk stoppen met verwerken.awk '$1 == "//" && $2 == "VCL.SHOW" {print; exit}'- Een codeblok dat de waarden van velden, gescheiden door spaties, opslaat in vijf variabelen. De vijfde variabele FILE ontvangt de rest van de regel. Ten slotte drukt de laatste echo de inhoud van de variabele
${FILE}.{ read -r DELIM VCL_SHOW INDEX SIZE FILE; echo "$FILE" } - Aangezien alle stappen van 1 tot 3 in een subshell zijn geplaatst, zal de uitvoer van de waarde
$FILEworden opgeslagen in de variabeleVCL_FILE.
Zoals blijkt uit de opmerking op regel 119, dient dit één doel: betrouwbaar omgaan met gevallen waarin VCL naar bestanden met spaties in de naam verwijst.
Ik heb de oorspronkelijke logica voor het verwerken van ${VCL_FILE} gecommentarieerd en geprobeerd de volgorde van de commando's te wijzigen, maar dat leidde tot niets. Het werkte allemaal soepel voor mij, maar bij het starten van de service resulteerde het in een fout.
Het lijkt erop dat de fout simpelweg niet wordt weergegeven wanneer het script handmatig wordt uitgevoerd, terwijl de veronderstelde 30 minuten al zes keer voorbij zijn gevlogen en daarnaast kwam er een meer urgente taak die alle andere zaken opzij drukte. De resterende dagen van de week waren gevuld met verschillende taken en werden slechts een beetje onderbroken door een presentatie over sed en een sollicitatiegesprek met een kandidaat. Het probleem met de fout in varnishreload was onherroepelijk verloren in de zandstranden van de tijd.
Je zogenaamde sed-fu… is eigenlijk… waardeloos
Volgende week had ik een vrij dag, dus besloot ik deze ticket weer op te pakken. Ik hoopte dat er in mijn hoofd een achtergrondproces was dat ondertussen een oplossing voor het probleem zocht, en dit keer zou ik het echt begrijpen.
Aangezien de simpele wijziging van de code de vorige keer niet hielp, besloot ik gewoon om het vanaf regel 116 opnieuw te schrijven. Hoe dan ook, de bestaande code was niet bepaald logisch. Het was totaal onnodig om read.
De fout nogmaals bekijkend:
sh: echo: broken pipe — in deze commando staat echo op twee plaatsen, maar ik vermoed dat de eerste de meest waarschijnlijke schuldige is (of op zijn minst een medeplichtige). Awk lijkt me ook niet betrouwbaar. En als dit werkelijk het geval is, awk | {read; echo} veroorzaakt al deze problemen, waarom zouden we het dan niet vervangen? Dit eén-regel commando maakt niet gebruik van alle mogelijkheden van awk en dan is er ook dit overtollige read er bovenop.
Aangezien er vorige week een presentatie was over sed, wilde ik mijn onlangs verworven vaardigheden proberen en vereenvoudigen echo | awk | { read; echo} tot iets begrijpelijkers echo | sed. Hoewel dit zeker niet de beste aanpak is om de fout te achterhalen, dacht ik dat ik in ieder geval mijn sed-vaardigheden kon proberen en misschien iets nieuws over het probleem kon leren. Onderweg vroeg ik mijn collega, de auteur van de presentatie over sed, om me te helpen een efficiënter sed-script te bedenken.
Ik heb de inhoud van varnishadm vcl.show -v "$VCL_NAME" in een bestand opgeslagen, zodat ik me kon concentreren op het schrijven van het sed-script zonder me zorgen te maken over service herstarts.
Een korte uitleg van hoe sed de invoer verwerkt, is te vinden in . In de bronnen van sed is het symbool n duidelijk als scheidingsteken voor regels aangegeven.
Na een paar rondes en met de aanbevelingen van mijn collega hebben we een sed-script geschreven dat hetzelfde resultaat gaf als de oorspronkelijke regel 116.
Hieronder een voorbeeld van een bestand met invoergegevens:
> cat vcl-example.vcl
Text
// VCL.SHOW 0 1578 bestand met 3 spaties.vcl
Meer tekst
// VCL.SHOW 0 1578 bestand.vcl
Nog meer tekst
// VCL.SHOW 0 1578 bestand met TWOspecs.vcl
EindtekstDit is misschien niet duidelijk uit de bovenstaande beschrijving, maar we zijn alleen geïnteresseerd in de eerste opmerking // VCL.SHOW, terwijl er in de invoer meerdere kunnen zijn. Daarom eindigt de originele awk na de eerste 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.vclDus de inhoud van het varnishreload-script zal er ongeveer zo uitzien:
VCL_FILE="$(echo "$VCL_SHOW" | sed -En '#// VCL.SHOW#{s#.*[0-9]+ [0-9]+ (.*)$#1#p;q;};')"De bovenstaande logica kan als volgt kort worden samengevat:
Als de string overeenkomt met de reguliere expressie // VCL.SHOW, consume dan gretig de tekst die beide getallen in deze string omvat, en bewaar alles wat na deze bewerking overblijft. Geef de opgeslagen waarde terug en beëindig het programma.
Simpel, nietwaar?
We waren tevreden met het sed-script en het feit dat het de hele originele code vervangt. Al mijn tests gaven de gewenste resultaten, dus ik wijzigde “varnishreload” op de server en startte opnieuw systemctl reload varnish. Die vervelende fout echo: schrijffout: Verbroke pijp lachte ons opnieuw in het gezicht. De knipogende cursor wachtte op invoer van een nieuw commando in de donkere leegte van de terminal…
Bron: habr.com
