ProHoster > blog > administratie > Falling Down the Rabbit Hole: het verhaal van een fout bij het opnieuw opstarten van vernis - Deel 1

Falling Down the Rabbit Hole: het verhaal van een fout bij het opnieuw opstarten van vernis - Deel 1

geestinushanka, die de afgelopen twintig minuten op de knoppen heeft zitten hameren alsof zijn leven ervan afhangt, draait zich naar mij toe met een halfwilde blik in zijn ogen en een sluwe grijns: "Kerel, ik denk dat ik het snap."

‘Kijk eens,’ zegt hij, wijzend naar een van de symbolen op het scherm, ‘ik durf te wedden dat als we hier toevoegen wat ik je zojuist heb gestuurd,’ wijzend naar een ander stuk code, ‘de fout niet langer zal worden weergegeven. zal worden vertoond."

Een beetje verbaasd en moe pas ik de sed-expressie aan waar we al een tijdje aan werken, sla het bestand op en voer het uit systemctl varnish reload. De foutmelding is verdwenen...

“Uit de e-mails die ik met de kandidaat heb uitgewisseld,” vervolgde mijn collega, terwijl zijn grijns uitgroeide tot een oprechte glimlach van vreugde, “drong het plotseling tot me door dat dit precies hetzelfde probleem is!”

Hoe het allemaal begon

Het artikel gaat ervan uit dat je begrijpt hoe bash, awk, sed en systemd werken. Kennis van vernis heeft de voorkeur, maar is niet vereist.
Tijdstempels in fragmenten zijn gewijzigd.
Geschreven met geestinushanka.
Deze tekst is een vertaling van het origineel dat twee weken geleden in het Engels is gepubliceerd; vertaling boikoden.

De zon schijnt door de panoramische ramen op weer een warme herfstochtend, een kopje vers bereide, cafeïnerijke drank staat ver van het toetsenbord, je favoriete symfonie van geluiden klinkt in je koptelefoon en overstemt het geritsel van mechanische toetsenborden, en de eerste invoer in de lijst met achterstandstickets op het Kanban-bord gloeit speels met de noodlottige titel "Investigate lakreload" sh: echo: I/O-fout in staging" (Onderzoek "varnishreload sh: echo: I/O-fout" in staging). Als het om vernis gaat, is en kan er geen ruimte zijn voor fouten, zelfs als deze niet tot problemen leiden zoals in dit geval.

Voor degenen die er niet bekend mee zijn vernisherladen, is dit een eenvoudig shellscript dat wordt gebruikt om de configuratie opnieuw te laden vernis - ook wel VCL genoemd.

Zoals de titel van het ticket suggereert, deed de fout zich voor op een van de servers op het podium, en aangezien ik er zeker van was dat de lakroutering op het podium goed werkte, ging ik ervan uit dat dit een kleine fout zou zijn. Dus gewoon een bericht dat in een reeds gesloten uitvoerstroom terechtkwam. Ik neem het kaartje voor mezelf, in het volste vertrouwen dat ik het in minder dan 30 minuten klaar zal markeren, geef mezelf een schouderklopje omdat ik het bord weer van de zoveelste rommel heb opgeruimd en ga terug naar belangrijkere zaken.

Met 200 km/u tegen een muur botsen

Het bestand openen varnishreload, op een van de servers waarop Debian Stretch draait, zag ik een shellscript van minder dan 200 regels lang.

Nadat ik het script had doorlopen, merkte ik niets op dat tot problemen kon leiden als ik het meerdere keren rechtstreeks vanaf de terminal uitvoerde.

Dit is tenslotte een etappe, zelfs als deze kapot gaat, zal niemand klagen, nou ja... niet te veel. Ik voer het script uit en kijk wat er naar de terminal wordt geschreven, maar de fouten zijn niet langer zichtbaar.

Nog een paar runs om er zeker van te zijn dat ik de fout niet zonder enige extra inspanning kan reproduceren, en ik begin erachter te komen hoe ik dit script kan veranderen, zodat het nog steeds een fout oplevert.

Kan het script STDOUT overschrijven (met behulp van > &-)? Of STDERR? Geen van beide werkte uiteindelijk.

Blijkbaar wijzigt systemd op de een of andere manier de opstartomgeving, maar hoe en waarom?
Ik open vim en bewerk het varnishreload, toevoegen set -x precies onder de rommel, in de hoop dat de debug-uitvoer van het script enig licht zal werpen.

Het bestand is gecorrigeerd, dus ik laad de vernis opnieuw en zie dat de verandering alles volledig kapot heeft gemaakt... De uitlaat is een complete puinhoop, waarin heel veel C-achtige code zit. Zelfs scrollen in de terminal is niet voldoende om te vinden waar het begint. Ik ben volledig in de war. Kan de foutopsporingsmodus de werking beïnvloeden van programma's die in een script worden gestart? Nee, het is onzin. Bug in de schaal? Verschillende mogelijke scenario's razen als kakkerlakken door mijn hoofd in verschillende richtingen. Het kopje cafeïnehoudende drank is meteen leeg, even naar de keuken om de bouillon aan te vullen en... daar gaan we. Ik open het script en bekijk de kreng van dichterbij: #!/bin/sh.

/bin/sh - dit is slechts een symbolische link naar bash, dus het script wordt geïnterpreteerd in POSIX-compatibele modus, toch? Niet zo! De standaardshell op Debian is dash, en dat is precies hoe het eruit ziet. verwijst /bin/sh.

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

Als test heb ik de shebang veranderd in #!/bin/bash, verwijderd set -x en probeerde het opnieuw. Uiteindelijk verscheen er bij het daaropvolgende opnieuw opstarten van de vernis een aanvaardbare fout in de uitvoer:

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

Lijn 124, hier is hij!

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 }

Maar het blijkt dat lijn 124 behoorlijk leeg is en niet interessant. Ik kon alleen maar aannemen dat de fout optrad als onderdeel van een reeks met meerdere regels die begon op regel 116.
Wat wordt er uiteindelijk naar de variabele geschreven? VCL_FILE als gevolg van het uitvoeren van de bovenstaande sub-shell?

In het begin verzendt het de inhoud van de variabele VLC_SHOW, gemaakt op regel 115, na het commando via de pipe. En wat gebeurt daar dan?

Ten eerste wordt het daar gebruikt varnishadm, dat deel uitmaakt van het lakinstallatiepakket, voor het aanbrengen van lak zonder opnieuw te starten.

Sub-team vcl.show -v gebruikt om de volledige VCL-configuratie uit te voeren die is opgegeven in ${VCL_NAME}, naar STDOUT.

Om de huidige actieve VCL-configuratie weer te geven, evenals verschillende eerdere versies van lakrouteringsconfiguraties die zich nog in het geheugen bevinden, kunt u de opdracht gebruiken varnishadm vcl.list, waarvan de uitvoer vergelijkbaar zal zijn met die hieronder:

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

Variabele waarde ${VCL_NAME} wordt in een ander deel van het script geïnstalleerd varnishreload naar de naam van de momenteel actieve VCL, als die er is. In dit geval zal dit “reload_20190101_120000_12397” zijn.

Geweldig, variabel ${VCL_SHOW} bevat volledige configuratie voor vernis, voorlopig helder. Nu begrijp ik eindelijk waarom de dash-uitvoer is set -x bleek zo kapot te zijn - het bevatte de inhoud van de resulterende configuratie.

Het is belangrijk om te begrijpen dat een volledige VCL-configuratie vaak uit verschillende bestanden kan worden samengesteld. Commentaar in C-stijl wordt gebruikt om aan te geven waar bepaalde configuratiebestanden in andere zijn opgenomen, en dat is waar het volgende codefragment over gaat.
De syntaxis voor opmerkingen die de opgenomen bestanden beschrijven, heeft de volgende indeling:

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

De cijfers zijn in deze context niet belangrijk, we zijn geïnteresseerd in de bestandsnaam.

Wat gebeurt er uiteindelijk in het moeras van opdrachten dat begint op regel 116?
Laten we het uitzoeken.
Het team bestaat uit vier delen:

  1. eenvoudig echo, waarmee de waarde van de variabele wordt afgedrukt ${VCL_SHOW} 
    echo "$VCL_SHOW"
  2. awk, dat zoekt naar een regel (record) waarbij het eerste veld, na het verbreken van de tekst, “//” is, en het tweede “VCL.SHOW”.
    Awk schrijft de eerste regel uit die overeenkomt met deze patronen en stopt vervolgens onmiddellijk met de verwerking.

    awk '$1 == "//" && $2 == "VCL.SHOW" {print; exit}'
  3. Een codeblok dat veldwaarden opslaat in vijf variabelen, gescheiden door spaties. De vijfde FILE-variabele ontvangt de rest van de regel. Ten slotte schrijft de laatste echo de inhoud van de variabele weg ${FILE}. 
    { read -r DELIM VCL_SHOW INDEX SIZE FILE; echo "$FILE" }
  4. Omdat alle stappen 1 tot en met 3 zijn ingesloten in een subshell, wordt de waarde uitgevoerd $FILE wordt naar een variabele geschreven VCL_FILE.

Zoals het commentaar op regel 119 suggereert, dient dit uitsluitend voor het betrouwbaar afhandelen van gevallen waarin VCL naar bestanden verwijst met spaties in hun naam.

Ik heb de oorspronkelijke verwerkingslogica becommentarieerd ${VCL_FILE} en probeerde de commandovolgorde te veranderen, maar het leidde nergens toe. Bij mij werkte alles prima, maar toen ik de service startte, gaf hij een foutmelding.

Het lijkt erop dat de fout eenvoudigweg niet reproduceerbaar is bij het handmatig uitvoeren van het script, terwijl de veronderstelde 30 minuten al zes keer zijn verstreken en bovendien een taak met een hogere prioriteit is verschenen, waardoor andere zaken terzijde worden geschoven. De rest van de week was gevuld met een verscheidenheid aan taken en werd slechts lichtjes afgezwakt door een rapport over sed en een interview met een kandidaat. Probleem met fout in varnishreload was onherroepelijk verloren gegaan in het zand van de tijd.

Je zogenaamde sed-fu... is eigenlijk... onzin

De week daarop had ik een redelijk vrije dag, dus besloot ik dit ticket opnieuw aan te pakken. Ik hoopte dat er in mijn brein een of ander achtergrondproces al die tijd naar een oplossing voor dit probleem had gezocht, en deze keer zou ik zeker begrijpen wat er aan de hand was.

Omdat het simpelweg veranderen van de code de vorige keer niet hielp, heb ik besloten om het te herschrijven vanaf regel 116. Hoe dan ook, de bestaande code was dom. En het is absoluut niet nodig om het te gebruiken read.

Nog eens naar de fout gekeken:
sh: echo: broken pipe – echo komt op twee plaatsen voor in dit commando, maar ik vermoed dat de eerste de meest waarschijnlijke boosdoener is (of op zijn minst een medeplichtige). Awk wekt ook geen vertrouwen. En voor het geval dat echt zo is awk | {read; echo} het ontwerp leidt tot al deze problemen, waarom zou je het niet vervangen? Dit commando van één regel gebruikt niet alle functies van awk, en zelfs niet deze extra read in aanvulling.

Sinds vorige week was er een rapport over sed, Ik wilde mijn nieuw verworven vaardigheden uitproberen en vereenvoudigen echo | awk | { read; echo} naar een begrijpelijker geheel echo | sed. Hoewel dit zeker niet de beste aanpak is om de bug te identificeren, dacht ik dat ik op zijn minst mijn sed-fu zou proberen en misschien iets nieuws over het probleem zou leren. Onderweg vroeg ik mijn collega, de auteur van de sed-talk, om me te helpen een efficiënter sed-script te bedenken.

Ik heb de inhoud laten vallen varnishadm vcl.show -v "$VCL_NAME" naar een bestand, zodat ik me kon concentreren op het schrijven van het sed-script zonder gedoe met opnieuw opstarten van de service.

Een korte beschrijving van hoe sed input precies verwerkt, vindt u in zijn GNU-handleiding. In de sed-bronnen staat het symbool n expliciet opgegeven als lijnscheidingsteken.

In verschillende passen en met de aanbevelingen van mijn collega schreven we een sed-script dat hetzelfde resultaat opleverde als de gehele originele regel 116.

Hieronder vindt u een voorbeeldbestand met invoergegevens:

> 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

Dit is misschien niet duidelijk uit de bovenstaande beschrijving, maar we zijn alleen geïnteresseerd in de eerste opmerking // VCL.SHOW, en er kunnen er meerdere in de invoergegevens voorkomen. Dit is de reden waarom de oorspronkelijke awk eindigt na de eerste wedstrijd.

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

De inhoud van het lakreload-script ziet er dus ongeveer zo uit:

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

De bovenstaande logica kan in het kort als volgt worden uitgedrukt:
Als de tekenreeks overeenkomt met een reguliere expressie // VCL.SHOW, verslind dan gretig de tekst die beide getallen in deze regel bevat, en bewaar alles wat overblijft na deze bewerking. Zend de opgeslagen waarde uit en beëindig het programma.

Eenvoudig, nietwaar?

We waren blij met het sed-script en het feit dat het alle originele code verving. Al mijn tests gaven de gewenste resultaten, dus ik veranderde de “varnishreload” op de server en voerde deze opnieuw uit systemctl reload varnish. Slechte fout echo: write error: Broken pipe lachte ons weer uit in ons gezicht. De knipogende cursor wachtte op een nieuw commando dat werd ingevoerd in de donkere leegte van de terminal...

Bron: www.habr.com

Voeg een reactie