Falling Down the Rabbit Hole : L'histoire d'une erreur de redémarrage de vernis - Partie 1

Ghostinushanka, après avoir tapé sur les boutons pendant les 20 minutes précédentes comme si sa vie en dépendait, se tourne vers moi avec une expression semi-sauvage dans les yeux et un sourire narquois - "Mec, je pense que je comprends."

"Regardez ici", dit-il en désignant l'un des personnages à l'écran, "je parie mon chapeau rouge que si nous ajoutons ici ce que je viens de vous envoyer" - pointant vers une autre section de code - "l'erreur n'est plus être affichée."

Un peu perplexe et fatigué, je modifie l'instruction sed sur laquelle nous travaillons depuis un moment, enregistre le fichier et lance systemctl varnish reload. Le message d'erreur a disparu...

"Les e-mails que j'ai échangés avec le candidat", a poursuivi mon collègue, alors que son sourire narquois se transformait en un sourire sincère plein de joie, "j'ai soudainement compris que c'était exactement le même problème !"

Comment tout cela a-t-il commencé

L'article suppose une compréhension du fonctionnement de bash, awk, sed et systemd. Des connaissances en vernis sont appréciées mais pas obligatoires.
Les horodatages dans les extraits ont été modifiés.
Écrit avec Ghostinushanka.
Ce texte est une traduction de l'original publié en anglais il y a deux semaines ; traduction boyikoden.

Le soleil brille à travers les fenêtres panoramiques par un autre chaud matin d'automne, une tasse de boisson caféinée fraîchement infusée repose sur le côté du clavier, une symphonie préférée de sons joue dans les écouteurs sur le bruissement des claviers mécaniques, et la première entrée dans le liste des tickets de backlog sur le tableau kanban s'illumine de manière ludique avec le titre fatidique "Enquêtez sur le chargement de vernis sh : écho : erreur d'E/S dans la mise en scène" (Enquêtez sur "l'erreur de chargement de vernis : écho : erreur d'E/S" dans la mise en scène). En matière de vernis, il n'y a pas et ne peut pas y avoir d'erreurs, même si elles n'entraînent aucun problème, comme dans ce cas.

Pour ceux qui ne connaissent pas rechargement de vernis, il s'agit d'un simple script shell utilisé pour recharger la configuration vernis - également appelé VCL.

Comme le suggère le titre du ticket, l'erreur s'est produite sur l'un des serveurs de la scène, et comme j'étais convaincu que le routage du vernis dans la scène fonctionnait correctement, j'ai supposé que ce serait une erreur mineure. Donc, juste un message qui est entré dans un flux de sortie déjà fermé. Je prends un billet pour moi-même, en toute confiance que je le marquerai prêt en moins de 30 minutes, me félicite pour avoir débarrassé le tableau du prochain bric-à-brac et reviens à des choses plus importantes.

Percuter un mur à 200 km/h

Ouverture d'un dossier varnishreload, sur l'un des serveurs exécutant Debian Stretch, j'ai vu un script shell de moins de 200 lignes.

En parcourant le script, je n'ai rien vu qui puisse causer des problèmes lors de son exécution plusieurs fois directement depuis le terminal.

Après tout, c'est une étape, même si elle casse, personne ne s'en plaindra, enfin... pas trop. J'exécute le script et vois ce qui sera écrit sur le terminal, mais les erreurs ne sont plus visibles.

Quelques exécutions supplémentaires pour m'assurer que je ne peux pas reproduire l'erreur sans effort supplémentaire, et je commence à comprendre comment modifier ce script et le faire toujours générer une erreur.

Le script peut-il bloquer STDOUT (en utilisant > &-) ? Ou STDERR ? Aucun des deux n'a fonctionné au final.

De toute évidence, systemd modifie l'environnement d'exécution d'une manière ou d'une autre, mais comment et pourquoi ?
J'allume vim et j'édite varnishreload, ajouter set -x juste sous le shebang, en espérant que le débogage de la sortie du script apportera un peu de lumière.

Le fichier est corrigé, je recharge donc le vernis et je vois que le changement a complètement tout cassé ... L'échappement est un gâchis complet, avec des tonnes de code de type C dedans. Même le défilement dans le terminal ne suffit pas pour trouver où il commence. Je suis complètement confus. Le mode débogage peut-il affecter le travail des programmes exécutés dans un script ? Sans blague. Bug dans la coque ? Plusieurs scénarios possibles volent dans ma tête comme des cafards dans différentes directions. Une tasse de boisson pleine de caféine se vide en un instant, un petit tour à la cuisine pour un réapprovisionnement et… c'est parti. J'ouvre le script et regarde de plus près le shebang: #!/bin/sh.

/bin/sh - c'est juste un lien symbolique bash, donc le script est interprété en mode compatible POSIX, n'est-ce pas ? Ce n'était pas là ! Le shell par défaut sur Debian est dash, ce qui correspond exactement à se réfère /bin/sh.

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

Pour les besoins du procès, j'ai changé le shebang en #!/bin/bash, supprimé set -x et réessayé. Enfin, lors du rechargement ultérieur de vernis, une erreur tolérable est apparue dans la sortie :

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

Ligne 124, c'est ici !

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 }

Mais il s'est avéré que la ligne 124 est plutôt vide et sans intérêt. Je ne pouvais que supposer que l'erreur s'était produite dans le cadre d'une multiligne commençant à la ligne 116.
Ce qui est finalement écrit dans la variable VCL_FILE à la suite de l'exécution du sous-shell ci-dessus ?

Au début, il envoie le contenu de la variable VLC_SHOW, créé à la ligne 115, à la commande suivante via le tube. Et puis que s'y passe-t-il ?

Premièrement, il utilise varnishadm, qui fait partie du package d'installation de vernis, pour configurer vernis sans redémarrer.

sous-commande vcl.show -v est utilisé pour sortir la configuration VCL entière spécifiée dans ${VCL_NAME}, à STDOUT.

Pour afficher la configuration VCL actuellement active ainsi que plusieurs versions précédentes des configurations de routage de vernis qui sont encore en mémoire, vous pouvez utiliser la commande varnishadm vcl.list, dont la sortie ressemblera à ce qui suit :

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

Valeur variable ${VCL_NAME} situé dans une autre partie du script varnishreload au nom de la VCL actuellement active, le cas échéant. Dans ce cas, ce sera "reload_20190101_120000_12397".

D'accord, variable. ${VCL_SHOW} contient la configuration complète pour le vernis, jusqu'à présent clair. Maintenant, je comprends enfin pourquoi la sortie dash avec set -x s'est avéré tellement cassé - il incluait le contenu de la configuration résultante.

Il est important de comprendre qu'une configuration VCL complète peut souvent être composée de plusieurs fichiers. Les commentaires de style C sont utilisés pour définir où un fichier de configuration a été inclus dans un autre, et c'est exactement ce dont parle la ligne suivante de l'extrait de code.
La syntaxe des commentaires décrivant les fichiers inclus a le format suivant :

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

Les chiffres dans ce contexte ne sont pas importants, nous sommes intéressés par le nom du fichier.

Alors que se passe-t-il dans le marais de commandes qui commence à la ligne 116 ?
Avouons-le.
La commande se compose de quatre parties :

  1. Simple echo, qui affiche la valeur de la variable ${VCL_SHOW}
    echo "$VCL_SHOW"
  2. awk, qui recherche une ligne (enregistrement), où le premier champ, après avoir divisé le texte, sera "//", et le second sera "VCL.SHOW".
    Awk écrira la première ligne qui correspond à ces modèles, puis arrêtera immédiatement le traitement.

    awk '$1 == "//" && $2 == "VCL.SHOW" {print; exit}'
  3. Un bloc de code qui stocke les valeurs des champs dans cinq variables, séparées par des espaces. La cinquième variable FILE reçoit le reste de la ligne. Enfin, le dernier echo écrit le contenu de la variable ${FILE}.
    { read -r DELIM VCL_SHOW INDEX SIZE FILE; echo "$FILE" }
  4. Étant donné que toutes les étapes 1 à 3 sont incluses dans un sous-shell, la sortie de la valeur $FILE sera écrit dans une variable VCL_FILE.

Comme le commentaire de la ligne 119 le suggère, cela a pour seul but de traiter de manière fiable les cas où la VCL fera référence à des fichiers avec des caractères d'espacement dans leurs noms.

J'ai commenté la logique de traitement d'origine pour ${VCL_FILE} et essayé de changer la séquence de commandes, mais cela n'a rien donné. Tout a fonctionné proprement pour moi, et dans le cas du démarrage du service, cela a donné une erreur.

Il semble que l'erreur ne soit tout simplement pas reproductible lors de l'exécution manuelle du script, alors que les 30 minutes estimées se sont déjà terminées six fois et, en plus, une tâche plus prioritaire est apparue, écartant le reste des cas. Le reste de la semaine a été rempli de tâches variées et n'a été que légèrement dilué avec une conférence sur sed et un entretien avec le candidat. Problème d'erreur dans varnishreload irrémédiablement perdu dans les sables du temps.

Votre soi-disant sed-fu... en fait... des ordures

La semaine suivante a eu une journée assez libre, alors j'ai décidé de reprendre ce billet. J'espérais que dans mon cerveau, un processus d'arrière-plan cherchait tout ce temps une solution à ce problème, et cette fois je comprendrai certainement ce qui ne va pas.

Comme la dernière fois que le simple fait de changer le code n'a pas aidé, j'ai juste décidé de le réécrire à partir de la 116e ligne. En tout cas, le code existant était stupide. Et il n'est absolument pas nécessaire d'utiliser read.

En regardant à nouveau l'erreur:
sh: echo: broken pipe - dans cette commande, l'écho est à deux endroits, mais je soupçonne que le premier est le coupable le plus probable (enfin, ou du moins un complice). Awk n'inspire pas confiance non plus. Et au cas où c'est vraiment awk | {read; echo} la conception entraîne tous ces problèmes, pourquoi ne pas la remplacer ? Cette commande en une ligne n'utilise pas toutes les fonctionnalités de awk, et même ce supplément read en appendice.

Depuis la semaine dernière, il y a eu un rapport sur sedJe voulais essayer mes compétences nouvellement acquises et simplifier echo | awk | { read; echo} en un plus compréhensible echo | sed. Bien que ce ne soit certainement pas la meilleure approche pour attraper le bogue, j'ai pensé au moins essayer mon sed-fu et peut-être apprendre quelque chose de nouveau sur le problème. En cours de route, j'ai demandé à mon collègue, l'auteur du discours sed, de m'aider à trouver un script sed plus efficace.

j'ai laissé tomber le contenu varnishadm vcl.show -v "$VCL_NAME" dans un fichier afin que je puisse me concentrer sur l'écriture du script sed sans les tracas des redémarrages de service.

Une brève description de la manière exacte dont sed gère les entrées peut être trouvée dans son manuel GNU. Dans les sources sed, le symbole n explicitement spécifié comme séparateur de ligne.

En plusieurs passes, et avec les conseils de mon collègue, nous avons écrit un script sed qui a donné le même résultat que toute la ligne originale 116.

Vous trouverez ci-dessous un exemple de fichier avec des données d'entrée :

> 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

Ce n'est peut-être pas évident d'après la description ci-dessus, mais nous ne sommes intéressés que par le premier commentaire // VCL.SHOW, et il peut y en avoir plusieurs dans les données d'entrée. C'est pourquoi l'awk d'origine se termine après la première correspondance.

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

Ainsi, le contenu du script de vernissage ressemblerait à ceci :

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

La logique ci-dessus peut être résumée comme suit :
Si la chaîne correspond à l'expression régulière // VCL.SHOW, puis dévorez avidement le texte qui comprend les deux nombres dans cette ligne, et enregistrez ce qui reste après cette opération. Émettez la valeur enregistrée et terminez le programme.

Simple, n'est-ce pas ?

Nous étions satisfaits du script sed et du fait qu'il remplace tout le code d'origine. Tous mes tests ont donné les résultats souhaités, j'ai donc changé le "varnishreload" sur le serveur et j'ai relancé systemctl reload varnish. Sale erreur echo: write error: Broken pipe nous a encore ri au nez. Un curseur clignotant attendait qu'une nouvelle commande soit saisie dans le vide obscur du terminal...

Source: habr.com

Ajouter un commentaire