Falling Down the Rabbit Hole: Die Geschichte eines Lack-Neustartfehlers – Teil 1

GhostinushankaNachdem er die letzten 20 Minuten auf den Knöpfen gehämmert hat, als hinge sein Leben davon ab, dreht er sich mit einem halb wilden Ausdruck in den Augen und einem verschmitzten Grinsen zu mir um: „Alter, ich glaube, ich verstehe.“

„Schau mal her“, sagt er und zeigt auf eines der Symbole auf dem Bildschirm, „ich wette, mein Roter Hut, wenn wir hinzufügen, was ich dir gerade hierher geschickt habe“, zeigt er auf einen anderen Codeabschnitt, „wird der Fehler nicht mehr angezeigt.“

Etwas verwirrt und müde ändere ich die sed-Anweisung, an der wir eine Weile gearbeitet haben, speichere die Datei und führe sie aus systemctl varnish reload. Die Fehlermeldung ist verschwunden...

„Die E-Mails, die ich mit dem Kandidaten ausgetauscht habe“, fuhr mein Kollege fort, während sich sein Grinsen in ein echtes Lächeln voller Freude verwandelte, „Mir wurde plötzlich klar, dass es sich um genau das gleiche Problem handelt!“

Wie hat alles angefangen

Der Artikel setzt ein Verständnis der Funktionsweise von Bash, Awk, Sed und Systemd voraus. Kenntnisse im Lackbereich sind wünschenswert, aber nicht zwingend erforderlich.
Zeitstempel in Snippets wurden geändert.
Geschrieben mit Ghostinushanka.
Dieser Text ist eine Übersetzung des vor zwei Wochen auf Englisch veröffentlichten Originals; Übersetzung boyikoden.

An einem weiteren warmen Herbstmorgen scheint die Sonne durch die Panoramafenster, eine Tasse frisch gebrühtes koffeinhaltiges Getränk steht abseits der Tastatur, eine Lieblingsklangsymphonie erklingt über dem Rascheln mechanischer Tastaturen im Kopfhörer und der erste Eintrag in der Backlog-Ticketliste auf dem Kanban-Board leuchtet spielerisch mit dem schicksalhaften Titel „Untersuchen Sie den Lackreload sh: echo: I/O-Fehler im Staging“ (Untersuchen Sie „varnishreload sh: echo: I/O-Fehler“ in Bühne). Beim Lackieren gibt es und darf es keine Fehler geben, auch wenn sie, wie in diesem Fall, keine Probleme nach sich ziehen.

Für diejenigen, die es nicht kennen LacknachladenDies ist ein einfaches Shell-Skript, das zum Neuladen der Konfiguration verwendet wird Lack - auch VCL genannt.

Wie der Titel des Tickets vermuten lässt, trat der Fehler auf einem der Server in der Bühne auf, und da ich sicher war, dass das Routing von Lack in der Bühne ordnungsgemäß funktionierte, ging ich davon aus, dass es sich um einen geringfügigen Fehler handelte. Also nur eine Nachricht, die in einen bereits geschlossenen Ausgabestream gelangt ist. Ich nehme ein Ticket für mich selbst, in der festen Überzeugung, dass ich es in weniger als 30 Minuten als fertig markieren werde, klopfe mir selbst auf die Schulter, weil ich den nächsten Müll von der Tafel geräumt habe, und kümmere mich wieder um wichtigere Dinge.

Mit 200 km/h gegen eine Wand prallen

Öffnen einer Datei varnishreload, auf einem der Server, auf denen Debian Stretch läuft, habe ich ein Shell-Skript gesehen, das weniger als 200 Zeilen lang war.

Beim Durchlaufen des Skripts habe ich nichts gesehen, was zu Problemen führen könnte, wenn es mehrmals direkt vom Terminal ausgeführt wird.

Schließlich ist dies eine Bühne, selbst wenn sie kaputt geht, wird sich niemand beschweren, naja ... nicht zu viel. Ich führe das Skript aus und sehe, was auf das Terminal geschrieben wird, aber die Fehler sind nicht mehr sichtbar.

Noch ein paar Durchläufe, um sicherzustellen, dass ich den Fehler nicht ohne zusätzlichen Aufwand reproduzieren kann, und ich beginne herauszufinden, wie ich dieses Skript ändern kann, damit es immer noch einen Fehler auslöst.

Kann das Skript STDOUT blockieren (mit > &-)? Oder STDERR? Beides hat am Ende nicht funktioniert.

Offensichtlich ändert systemd die Ausführungsumgebung auf irgendeine Weise, aber wie und warum?
Ich schalte vim ein und bearbeite varnishreload, hinzufügend set -x direkt unter dem Schebang, in der Hoffnung, dass das Debuggen der Ausgabe des Skripts etwas Licht ins Dunkel bringt.

Die Datei ist repariert, also lade ich den Lack neu und sehe, dass die Änderung alles komplett kaputt gemacht hat ... Der Auspuff ist ein komplettes Durcheinander, mit Tonnen von C-ähnlichem Code darin. Selbst ein Scrollen im Terminal reicht nicht aus, um herauszufinden, wo es beginnt. Ich bin völlig verwirrt. Kann der Debug-Modus die Arbeit von Programmen beeinflussen, die in einem Skript ausgeführt werden? Kein Schwachsinn. Fehler in der Shell? Mehrere mögliche Szenarien fliegen in meinem Kopf wie Kakerlaken in verschiedene Richtungen. Eine Tasse koffeinhaltiges Getränk ist sofort leer, ein kurzer Gang in die Küche, um Nachschub zu holen, und ... los geht's. Ich öffne das Skript und schaue mir den Kram genauer an: #!/bin/sh.

/bin/sh - Das ist nur ein Bash-Symlink, das Skript wird also im POSIX-kompatiblen Modus interpretiert, oder? Es war nicht da! Die Standard-Shell unter Debian ist dash, was genau das ist bezieht sich /bin/sh.

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

Aus Versuchsgründen habe ich den Schebang in geändert #!/bin/bash, gelöscht set -x und versuchte es noch einmal. Schließlich erschien beim anschließenden Nachladen des Lacks ein tolerierbarer Fehler in der Ausgabe:

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

Zeile 124, hier ist sie!

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 }

Aber wie sich herausstellte, ist Zeile 124 ziemlich leer und uninteressant. Ich konnte nur annehmen, dass der Fehler im Rahmen einer Multiline ab Zeile 116 aufgetreten ist.
Was wird schließlich in die Variable geschrieben? VCL_FILE als Ergebnis der Ausführung der oben genannten Sub-Shell?

Zu Beginn wird der Inhalt der Variablen gesendet VLC_SHOW, erstellt in Zeile 115, zum nächsten Befehl über die Pipe. Und was passiert dann dort?

Erstens verwendet es varnishadm, das Teil des Lackinstallationspakets ist, um Lack ohne Neustart zu konfigurieren.

Unterbefehl vcl.show -v wird verwendet, um die gesamte in angegebene VCL-Konfiguration auszugeben ${VCL_NAME}, zu STDOUT.

Um die aktuell aktive VCL-Konfiguration sowie mehrere frühere Versionen der Routing-Konfigurationen von Lack anzuzeigen, die sich noch im Speicher befinden, können Sie den Befehl verwenden varnishadm vcl.list, dessen Ausgabe etwa wie folgt aussehen wird:

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

Variablenwert ${VCL_NAME} in einem anderen Teil des Skripts festgelegt varnishreload auf den Namen der aktuell aktiven VCL, falls vorhanden. In diesem Fall lautet es „reload_20190101_120000_12397“.

Okay, variabel. ${VCL_SHOW} enthält die komplette Konfiguration für Lack, soweit klar. Jetzt verstehe ich endlich, warum die Dash-Ausgabe mit erfolgt set -x Es stellte sich heraus, dass es so kaputt war, dass es den Inhalt der resultierenden Konfiguration enthielt.

Es ist wichtig zu verstehen, dass eine vollständige VCL-Konfiguration oft aus mehreren Dateien zusammengestellt werden kann. Kommentare im C-Stil werden verwendet, um zu definieren, wo eine Konfigurationsdatei in eine andere eingefügt wurde, und genau darum geht es in der folgenden Codezeile.
Die Syntax für Kommentare, die eingebundene Dateien beschreiben, hat das folgende Format:

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

Die Zahlen sind in diesem Zusammenhang nicht wichtig, uns interessiert der Dateiname.

Was passiert also in dem Sumpf von Befehlen, der in Zeile 116 beginnt?
Seien wir ehrlich.
Der Befehl besteht aus vier Teilen:

  1. Einfach echo, das den Wert der Variablen anzeigt ${VCL_SHOW}
    echo "$VCL_SHOW"
  2. awk, das nach einer Zeile (Datensatz) sucht, wobei das erste Feld nach der Aufteilung des Textes „//“ und das zweite „VCL.SHOW“ sein wird.
    Awk schreibt die erste Zeile aus, die diesen Mustern entspricht, und stoppt dann die Verarbeitung sofort.

    awk '$1 == "//" && $2 == "VCL.SHOW" {print; exit}'
  3. Ein Codeblock, der die Feldwerte in fünf durch Leerzeichen getrennten Variablen speichert. Die fünfte Variable FILE erhält den Rest der Zeile. Schließlich schreibt das letzte Echo den Inhalt der Variablen aus ${FILE}.
    { read -r DELIM VCL_SHOW INDEX SIZE FILE; echo "$FILE" }
  4. Da alle Schritte 1 bis 3 in einer Unterschale eingeschlossen sind, erfolgt die Ausgabe des Wertes $FILE wird in eine Variable geschrieben VCL_FILE.

Wie aus dem Kommentar in Zeile 119 hervorgeht, dient dies ausschließlich dem Zweck, Fälle zuverlässig zu behandeln, in denen die VCL auf Dateien verweist, deren Namen Leerzeichen enthalten.

Ich habe die ursprüngliche Verarbeitungslogik für auskommentiert ${VCL_FILE} und versuchte, die Befehlsfolge zu ändern, aber es führte zu nichts. Bei mir funktionierte alles einwandfrei und beim Starten des Dienstes gab es einen Fehler.

Es scheint, dass der Fehler beim manuellen Ausführen des Skripts einfach nicht reproduzierbar ist, während die geschätzten 30 Minuten bereits sechs Mal abgelaufen sind und außerdem eine Aufgabe mit höherer Priorität aufgetaucht ist, die den Rest der Fälle beiseite drängt. Der Rest der Woche war mit abwechslungsreichen Aufgaben gefüllt und wurde nur durch einen Vortrag auf sed und ein Interview mit dem Kandidaten etwas aufgelockert. Fehlerproblem in varnishreload unwiederbringlich im Sand der Zeit verloren.

Dein sogenannter Sed-Fu... eigentlich... Quatsch

Die folgende Woche hatte einen ziemlich freien Tag, also beschloss ich, dieses Ticket noch einmal zu nehmen. Ich hoffte, dass in meinem Gehirn irgendein Hintergrundprozess die ganze Zeit nach einer Lösung für dieses Problem suchte, und dieses Mal werde ich definitiv verstehen, was los ist.

Da es beim letzten Mal nicht geholfen hat, einfach den Code zu ändern, habe ich beschlossen, ihn ab der 116. Zeile neu zu schreiben. Auf jeden Fall war der vorhandene Code albern. Und es besteht absolut keine Notwendigkeit, es zu verwenden read.

Schauen Sie sich den Fehler noch einmal an:
sh: echo: broken pipe - In diesem Befehl gibt es Echo an zwei Stellen, aber ich vermute, dass die erste der wahrscheinlichere Schuldige ist (naja, oder zumindest ein Komplize). Awk erweckt auch kein Vertrauen. Und für den Fall, dass es wirklich so ist awk | {read; echo} Das Design führt zu all diesen Problemen. Warum nicht ersetzen? Dieser einzeilige Befehl nutzt nicht alle Funktionen von awk und sogar dieses Extra read im Anhang.

Seit letzter Woche gab es einen Bericht darüber sedIch wollte meine neu erworbenen Fähigkeiten ausprobieren und vereinfachen echo | awk | { read; echo} in ein verständlicheres verwandeln echo | sed. Obwohl dies definitiv nicht der beste Ansatz ist, um den Fehler zu erkennen, dachte ich, ich probiere es zumindest mit meinem Sed-Fu und lerne vielleicht etwas Neues über das Problem. Unterwegs bat ich meinen Kollegen, den Sed-Talk-Autor, mir bei der Entwicklung eines effizienteren Sed-Skripts zu helfen.

Ich habe den Inhalt gelöscht varnishadm vcl.show -v "$VCL_NAME" in eine Datei, damit ich mich auf das Schreiben des Sed-Skripts konzentrieren kann, ohne den Aufwand von Dienstneustarts.

Eine kurze Beschreibung, wie sed genau mit Eingaben umgeht, finden Sie in sein GNU-Handbuch. In den sed-Quellen das Symbol n explizit als Zeilentrenner angegeben.

In mehreren Durchgängen und mit dem Rat meines Kollegen haben wir ein SED-Skript geschrieben, das das gleiche Ergebnis lieferte wie die gesamte Originalzeile 116.

Nachfolgend finden Sie eine Beispieldatei mit Eingabedaten:

> 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

Aus der obigen Beschreibung ist es vielleicht nicht ersichtlich, aber uns interessiert nur der erste Kommentar // VCL.SHOW, und es können mehrere davon in den Eingabedaten vorhanden sein. Aus diesem Grund wird das ursprüngliche awk nach dem ersten Match beendet.

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

Der Inhalt des Lackreload-Skripts würde also etwa so aussehen:

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

Die obige Logik lässt sich wie folgt zusammenfassen:
Wenn die Zeichenfolge mit dem regulären Ausdruck übereinstimmt // VCL.SHOW, verschlingen Sie dann gierig den Text, der beide Zahlen in dieser Zeile enthält, und speichern Sie alles, was nach diesem Vorgang übrig bleibt. Geben Sie den gespeicherten Wert aus und beenden Sie das Programm.

Ganz einfach, nicht wahr?

Wir waren mit dem sed-Skript und der Tatsache, dass es den gesamten Originalcode ersetzt, zufrieden. Alle meine Tests lieferten die gewünschten Ergebnisse, also habe ich „Varnishreload“ auf dem Server geändert und erneut ausgeführt systemctl reload varnish. Dreckiger Fehler echo: write error: Broken pipe lachte uns wieder ins Gesicht. Ein blinkender Cursor wartete in der dunklen Leere des Terminals auf die Eingabe eines neuen Befehls ...

Source: habr.com

Kommentar hinzufügen