Falling Down the Rabbit Hole: La historia de un error de reinicio de barniz - Parte 1

fantasmainushanka, después de golpear los botones durante los últimos 20 minutos como si su vida dependiera de ello, se vuelve hacia mí con una expresión medio salvaje en sus ojos y una sonrisa maliciosa: "Amigo, creo que entiendo".

“Mira aquí”, dice señalando a uno de los personajes en la pantalla, “apuesto mi sombrero rojo a que si añadimos aquí lo que te acabo de enviar” -señalando a otra sección del código- “el error ya no aparecerá”. se mostrará."

Un poco desconcertado y cansado, cambio la instrucción sed en la que hemos estado trabajando durante un tiempo, guardo el archivo y ejecuto systemctl varnish reload. El mensaje de error ha desaparecido...

"Los correos electrónicos que intercambié con el candidato", continuó mi colega, mientras su sonrisa se transforma en una sonrisa genuina llena de alegría, "¡De repente me di cuenta de que este es exactamente el mismo problema!"

Cómo comenzó todo

El artículo asume una comprensión de cómo funcionan bash, awk, sed y systemd. El conocimiento del barniz es preferible pero no obligatorio.
Se han cambiado las marcas de tiempo en los fragmentos.
escrito con fantasmainushanka.
Este texto es una traducción del original publicado en inglés hace dos semanas; traducción boyikoden.

El sol brilla a través de las ventanas panorámicas en otra cálida mañana de otoño, una taza de bebida con cafeína recién preparada descansa a un lado del teclado, una sinfonía favorita de sonidos suena en los auriculares sobre el susurro de los teclados mecánicos, y la primera entrada en el la lista de tickets atrasados ​​en el tablero kanban brilla con el fatídico título "Investigar varnishreload sh: echo: I/O error in staging" (Investigar "varnishreload sh: echo: I/O error" in staging). Cuando se trata de barnizar, no hay ni puede haber errores, aunque no den lugar a ningún problema, como en este caso.

Para aquellos que no están familiarizados con recargar barniz, este es un script de shell simple que se usa para recargar la configuración barniz - también llamado VCL.

Como sugiere el título del ticket, el error ocurrió en uno de los servidores del escenario, y dado que estaba seguro de que el enrutamiento del barniz en el escenario funcionaba correctamente, asumí que sería un error menor. Entonces, solo un mensaje que entró en un flujo de salida ya cerrado. Tomo un boleto para mí, con plena confianza de que lo marcaré como listo en menos de 30 minutos, me doy una palmadita en el hombro por limpiar el tablero de la siguiente basura y volver a cosas más importantes.

Chocar contra una pared a 200 km/h

Abriendo un archivo varnishreload, en uno de los servidores que ejecutan Debian Stretch, vi un script de shell de menos de 200 líneas.

Después de ejecutar el script, no noté nada que pudiera generar problemas al ejecutarlo varias veces directamente desde la terminal.

Después de todo, esto es un escenario, incluso si se rompe, nadie se quejará, bueno... no demasiado. Ejecuto el script y veo lo que se escribirá en la terminal, pero los errores ya no son visibles.

Un par de ejecuciones más para asegurarme de que no puedo reproducir el error sin un poco de esfuerzo adicional, y empiezo a descubrir cómo cambiar este script y hacer que siga arrojando un error.

¿Puede el script bloquear STDOUT (usando > &-)? ¿O STDERR? Ninguno de los dos funcionó al final.

Obviamente, systemd cambia el entorno de ejecución de alguna manera, pero ¿cómo y por qué?
Enciendo vim y edito varnishreload, agregando set -x justo debajo del tinglado, con la esperanza de que la depuración de la salida del script arroje algo de luz.

El archivo está arreglado, así que vuelvo a cargar Varnish y veo que el cambio rompió todo por completo... El escape es un completo desastre, con toneladas de código tipo C en él. Incluso desplazarse en la terminal no es suficiente para encontrar dónde comienza. Estoy completamente confundido. ¿Puede el modo de depuración afectar el trabajo de los programas que se ejecutan en un script? Ningún bullshit. ¿Error en el caparazón? Varios escenarios posibles vuelan en mi cabeza como cucarachas en diferentes direcciones. Una taza de bebida llena de cafeína se vacía instantáneamente, un viaje rápido a la cocina para reabastecerse y... vamos. Abro el guión y miro más de cerca el asunto: #!/bin/sh.

/bin/sh - esto es solo un enlace simbólico de bash, por lo que el script se interpreta en modo compatible con POSIX, ¿verdad? ¡No estaba allí! El shell predeterminado en Debian es dash, que es exactamente lo que se refiere a /bin/sh.

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

Por el bien de la prueba, cambié el shebang a #!/bin/bash, eliminado set -x y lo intenté de nuevo. Finalmente, en la recarga posterior de barniz, apareció un error tolerable en la salida:

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

Línea 124, ¡aquí está!

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 }

Pero resultó que la línea 124 está bastante vacía y no tiene interés. Solo podía suponer que el error ocurrió como parte de una línea múltiple que comienza en la línea 116.
Lo que finalmente se escribe en la variable VCL_FILE como resultado de ejecutar el sub-shell anterior?

Al principio envía el contenido de la variable VLC_SHOW, creado en la línea 115, al siguiente comando a través de la tubería. ¿Y entonces qué pasa allí?

Primero, utiliza varnishadm, que forma parte del paquete de instalación de Varnish, para configurar Varnish sin reiniciar.

subcomando vcl.show -v se utiliza para dar salida a toda la configuración de VCL especificada en ${VCL_NAME}, a SALIDAESTÁNDAR.

Para mostrar la configuración de VCL actualmente activa, así como varias versiones anteriores de las configuraciones de enrutamiento de Varnish que aún están en la memoria, puede usar el comando varnishadm vcl.list, cuya salida será similar a la siguiente:

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

Valor variable ${VCL_NAME} ambientado en otra parte del guión varnishreload al nombre de la VCL actualmente activa, si la hay. En este caso será “reload_20190101_120000_12397”.

Bien, variable. ${VCL_SHOW} contiene la configuración completa para barniz, hasta ahora clara. Ahora finalmente entiendo por qué la salida del guión con set -x resultó estar tan roto que incluía el contenido de la configuración resultante.

Es importante comprender que una configuración completa de VCL a menudo se puede improvisar a partir de varios archivos. Los comentarios de estilo C se utilizan para definir dónde se ha incluido un archivo de configuración en otro, y eso es exactamente de lo que trata la siguiente línea de fragmento de código.
La sintaxis de los comentarios que describen los archivos incluidos tiene el siguiente formato:

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

Los números en este contexto no son importantes, nos interesa el nombre del archivo.

Entonces, ¿qué sucede en el pantano de comandos que comienza en la línea 116?
Seamos realistas.
El comando consta de cuatro partes:

1. Simple echo, que muestra el valor de la variable ${VCL_SHOW}

   echo "$VCL_SHOW"

2. awk, que busca una línea (registro), donde el primer campo, después de dividir el texto, será “//”, y el segundo será “VCL.SHOW”.
   Awk escribirá la primera línea que coincida con estos patrones y luego dejará de procesar inmediatamente.

   awk '$1 == "//" && $2 == "VCL.SHOW" {print; exit}'

3. Un bloque de código que almacena los valores de los campos en cinco variables, separados por espacios. La quinta variable ARCHIVO recibe el resto de la línea. Finalmente, el último eco escribe el contenido de la variable ${FILE}.

   { read -r DELIM VCL_SHOW INDEX SIZE FILE; echo "$FILE" }

4. Dado que todos los pasos 1 a 3 están encerrados en una subcapa, la salida del valor $FILE se escribirá en una variable VCL_FILE.

Como sugiere el comentario en la línea 119, esto tiene el único propósito de manejar de manera confiable los casos en los que la VCL se referirá a archivos con espacios en blanco en sus nombres.

He comentado la lógica de procesamiento original para ${VCL_FILE} e intenté cambiar la secuencia de comandos, pero no condujo a nada. Me funcionó todo limpio, y en el caso de iniciar el servicio, daba error.

Parece que el error simplemente no es reproducible cuando se ejecuta el script manualmente, mientras que los 30 minutos estimados ya han terminado seis veces y, además, ha aparecido una tarea de mayor prioridad, dejando de lado el resto de los casos. El resto de la semana estuvo lleno de tareas variadas y solo se diluyó ligeramente con una charla sobre sed y una entrevista con el candidato. Problema de error en varnishreload perdido irremediablemente en las arenas del tiempo.

Su supuesto sed-fu... en realidad... basura

La semana siguiente tenía un día bastante libre, así que decidí tomar este boleto nuevamente. Esperaba que en mi cerebro, algún proceso de fondo todo este tiempo estuviera buscando una solución a este problema, y ​​esta vez definitivamente entenderé qué es lo que está mal.

Desde la última vez, simplemente cambiar el código no ayudó, simplemente decidí reescribirlo comenzando desde la línea 116. En cualquier caso, el código existente era una tontería. Y no hay absolutamente ninguna necesidad de usar read.

Mirando el error de nuevo:
sh: echo: broken pipe - en este comando, echo está en dos lugares, pero sospecho que el primero es el culpable más probable (bueno, o al menos un cómplice). Awk tampoco inspira confianza. Y en caso de que realmente lo sea awk | {read; echo} el diseño lleva a todos estos problemas, ¿por qué no reemplazarlo? Este comando de una línea no usa todas las características de awk, e incluso este extra read en apéndice.

Desde la semana pasada hubo un informe sobre sedQuería probar mis habilidades recién adquiridas y simplificar echo | awk | { read; echo} en una forma más comprensible echo | sed. Si bien este definitivamente no es el mejor enfoque para detectar el error, pensé que al menos probaría mi sed-fu y tal vez aprendería algo nuevo sobre el problema. En el camino, le pedí a mi colega, el escritor de charlas sed, que me ayudara a crear un guión sed más eficiente.

Dejé el contenido varnishadm vcl.show -v "$VCL_NAME" a un archivo para que pueda concentrarme en escribir el script sed sin ninguna de las molestias de los reinicios del servicio.

Puede encontrar una breve descripción de cómo sed maneja la entrada en su manual GNU. En las fuentes sed, el símbolo n especificado explícitamente como un separador de línea.

En varias pasadas, y con el consejo de mi colega, escribimos un script sed que dio el mismo resultado que toda la línea original 116.

A continuación se muestra un archivo de muestra con datos de entrada:

> 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

Puede que no sea obvio a partir de la descripción anterior, pero solo nos interesa el primer comentario. // VCL.SHOW, y puede haber varios de ellos en los datos de entrada. Esta es la razón por la que el awk original termina después de la primera coincidencia.

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

Entonces, el contenido del script varnishreload se vería así:

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

La lógica anterior se puede resumir de la siguiente manera:
Si la cadena coincide con la expresión regular // VCL.SHOW, luego devore con avidez el texto que incluye ambos números en esa línea, y guarde lo que quede después de esta operación. Emita el valor almacenado y finalice el programa.

Sencillo, ¿no?

Estamos contentos con el script sed y el hecho de que reemplaza todo el código original. Todas mis pruebas dieron los resultados deseados, así que cambié "varnishreload" en el servidor y ejecuté de nuevo systemctl reload varnish. sucio error echo: write error: Broken pipe volvió a reírse en nuestra cara. Un cursor parpadeante esperaba que se ingresara un nuevo comando en el oscuro vacío de la terminal...

Fuente: habr.com