Caída en la madriguera del conejo: Historia de un error en la reiniciación de varnish — parte 1

ghostinushanka, golpeando los botones durante los últimos 20 minutos, como si su vida dependiera de ello, se vuelve hacia mí con una expresión semi-salvaje en los ojos y una sonrisa astuta - «Amigo, creo que lo entendí.»

«Mira aquí,» - dice, señalando uno de los símbolos en la pantalla - «Apuestemos mi sombrero rojo a que si agregamos aquí lo que te acabo de enviar» - señalando otra parte del código - «el error ya no aparecerá.»

Un poco confundido y cansado, modifico la expresión sed en la que hemos estado trabajando por un tiempo, guardo el archivo y lo ejecuto systemctl varnish reload. El mensaje de error ha desaparecido...

«Los correos que intercambié con el candidato,» continuó mi colega, mientras su sonrisa se transformaba en una genuina llena de alegría, «de repente me di cuenta de que era exactamente el mismo problema!»

De dónde empezó todo

El artículo asume un entendimiento de los principios de bash, awk, sed y systemd. Conocer varnish es bienvenido, pero no es obligatorio.
Las marcas de tiempo en los snippets han sido modificadas.
Escrito junto con ghostinushanka.
Este texto es una traducción del original, publicado en inglés hace dos semanas; la traducción boikoden.

El sol brilla a través de las ventanas panorámicas en otra cálida mañana de otoño, una taza de café recién preparado descansa al lado del teclado, en los auriculares suena mi sinfonía favorita de sonidos, superando el susurro de los teclados mecánicos, y el primer registro en la lista de tickets del backlog en el tablero kanban brilla juguetonamente con el título decisivo “Investigar varnishreload sh: echo: I/O error en staging” (Investigar “varnishreload sh: echo: I/O error” en staging). Cuando se trata de varnish, no hay cabida para errores, incluso si no se traducen en problemas, como en este caso.

Para aquellos que no están familiarizados con varnishreload, es un simple script de shell utilizado para reiniciar la configuración de varnish — también conocida como VCL.

Como sugiere el nombre del ticket, el error ocurrió en uno de los servidores en staging, y dado que estaba seguro de que la ruta de varnish en staging funcionaba correctamente, supuse que sería un error menor. Simplemente un mensaje que se coló en un flujo de salida ya cerrado. Tomo el ticket para mí, con la plena confianza de que lo marcaré como resuelto en menos de 30 minutos, dándome una palmadita en la espalda por limpiar el tablero de otro desecho y volver a cosas más importantes.

Chocando contra una pared a 200 km/h

Al abrir el archivo varnishreload, en uno de los servidores que ejecuta Debian Stretch, vi un script de shell de menos de 200 líneas.

Revisando el script, no noté nada que pudiera causar problemas al ejecutarlo múltiples veces directamente desde el terminal.

Al final, es una etapa, incluso si se rompiera, nadie se quejaría, bueno... no demasiado. Ejecuto el script y veo qué se imprime en el terminal, solo que ya no hay errores visibles.

Un par de ejecuciones más, para asegurarme de que no puedo reproducir el error sin ningún esfuerzo adicional, y comienzo a pensar en cómo modificar este script para hacerlo generar un error.

¿Quizás redirigir STDOUT (usando > &-)? ¿O STDERR? Ninguna de las dos funcionó al final.

Obviamente, systemd de alguna manera está alterando el entorno de ejecución, pero ¿cómo y por qué?
Abro vim y edito varnishreload, añadiendo set -x justo debajo del shebang, esperando que la salida de depuración del script arroje un poco de luz.

El archivo está corregido, así que reinicio varnish y veo que el cambio lo ha roto todo... La salida es un completo caos, con toneladas de código similar a C. Ni siquiera el desplazamiento en el terminal es suficiente para encontrar dónde comienza. Estoy completamente confundido. ¿Puede el modo de depuración afectar el funcionamiento de los programas ejecutados en el script? No, eso es una locura. ¿Un bug en el shell? Varios posibles escenarios corren por mi cabeza como cucarachas en diferentes direcciones. La taza de un bebida llena de cafeína se vacía instantáneamente, un rápido viaje a la cocina para reabastecer y… ¡vamos! Abro el script y me acerco al shebang: #!/bin/sh.

/bin/sh — es solo un symlink a bash, así que el script se interpreta en modo compatible con POSIX, ¿verdad? ¡No tan rápido! La shell por defecto en Debian es dash, y eso es precisamente a lo que se refiere /bin/sh.

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

Por curiosidad, cambié el shebang a #!/bin/bash, lo eliminé set -x y lo intenté de nuevo. Finalmente, al reiniciar varnish, apareció un mensaje de error aceptable en la salida:

Jan 01 12:00:00 hostname varnishreload[32604]: /usr/sbin/varnishreload: línea 124: echo: error de escritura: Tubería rota
Jan 01 12:00:00 hostname varnishreload[32604]: VCL 'reload_20190101_120000_32604' compilado

¡Aquí está la línea 124!

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                         # toda esta ceremonia para manejar espacios en 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 "falló al obtener el nombre del archivo VCL"
129         fi
130
131         echo "$VCL_FILE"
132 }

Pero, como resultó, la línea 124 está bastante vacía y no presenta interés. Solo pude suponer que el error ocurrió como parte de un multílinado que comienza en la línea 116.
¿Qué se escribe en la variable VCL_FILE como resultado de la ejecución del sub-shell mencionado anteriormente?

Al principio, envía el contenido de la variable VLC_SHOW, creada en la línea 115, al siguiente comando a través de un pipe. ¿Y qué sucede allí?

Primero, se utiliza varnishadm, que es parte del paquete de instalación de varnish, para configurar varnish sin reiniciarlo.

El subcomando vcl.show -v se utiliza para mostrar toda la configuración VCL especificada en ${VCL_NAME}, en STDOUT.

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

descartado   frío/ocupado       1 reload_20190101_120000_11903
descartado   frío/ocupado       2 reload_20190101_120000_12068
descartado   frío/ocupado       16 reload_20190101_120000_12259
descartado   frío/ocupado       16 reload_20190101_120000_12299
descartado   frío/ocupado       28 reload_20190101_120000_12357
activo      auto/cálido       32 reload_20190101_120000_12397
disponible   auto/cálido       0 reload_20190101_120000_12587

El valor de la variable ${VCL_NAME} se establece en otra parte del script varnishreload al nombre del VCL activo en ese momento, si lo hay. En este caso, será “reload_20190101_120000_12397”.

Genial, la variable ${VCL_SHOW} contiene la configuración completa para varnish, hasta ahora está claro. Ahora, finalmente entendí por qué la salida de dash con set -x resultó tan dañada—incluía el contenido de la configuración resultante.

Es importante entender que la configuración completa de VCL a menudo puede ser ensamblada a partir de varios archivos. Se utilizan comentarios al estilo C para indicar dónde se han incluido unos archivos de configuración en otros, y esto es precisamente de lo que trata la línea del fragmento de código que se presenta a continuación.
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.

¿Qué está pasando en el grupo de comandos que comienza en la línea 116?
Vamos a desglosarlo.
El comando se compone de cuatro partes:

  1. Simple echo, que imprime el valor de la variable ${VCL_SHOW}
    echo "$VCL_SHOW"
  2. awk, que busca la línea (registro) donde el primer campo, después de dividir el texto, es “//”, y el segundo es «VCL.SHOW».
    Awk imprimirá la primera línea que coincida con estos patrones y luego detendrá inmediatamente el procesamiento.
    awk '$1 == "//" && $2 == "VCL.SHOW" {print; exit}'
  3. Un bloque de código que guarda en cinco variables los valores de los campos separados por espacios. La quinta variable FILE obtendrá el resto de la línea. Finalmente, el último echo imprimirá el contenido de la variable ${FILE}.
    { read -r DELIM VCL_SHOW INDEX SIZE FILE; echo "$FILE" }
  4. Dado que todos los pasos del 1 al 3 están encerrados en un sub-shell, el valor de $FILE se guardará en la variable VCL_FILE.

Como se menciona en el comentario de la línea 119, esto tiene un solo propósito: manejar de manera confiable los casos en que VCL se refiere a archivos con caracteres de espacio en sus nombres.

Comenté la lógica original de manejo para ${VCL_FILE} e intenté cambiar el orden de los comandos, pero esto no condujo a nada. Todo funcionaba bien, pero al iniciar el servicio daba un error.

Parece que el error simplemente no se reproduce cuando se ejecuta el script manualmente, y esos 30 minutos ya se han agotado seis veces, además de que ha surgido una tarea más prioritaria que ha desplazado otros asuntos. El resto de la semana estuvo llena de diversas tareas y solo se vio ligeramente aliviada por un informe sobre sed y una entrevista con un candidato. El problema con el error en varnishreload se ha perdido irremediablemente en las arenas del tiempo.

Tu llamado sed-fu... en realidad... es basura.

La semana que viene tuve un día bastante libre, así que decidí volver a trabajar en este ticket. Esperaba que en mi mente, algún proceso en segundo plano estuviera buscando la solución a este problema y que esta vez realmente entendería de qué se trataba.

Dado que la última vez un simple cambio en el código no funcionó, decidí reescribirlo comenzando desde la línea 116. De todos modos, el código existente era confuso. Y no hay absolutamente ninguna necesidad de usar read.

Mirando el error una vez más:
sh: echo: broken pipe — en este comando, echo se encuentra en dos lugares, pero sospecho que el primero es el culpable más probable (bueno, o al menos un cómplice). Awk también genera desconfianza. Y en caso de que esto realmente sea awk | {read; echo} esta construcción cause todos estos problemas, ¿por qué no reemplazarla? Este comando de una sola línea no utiliza todas las capacidades de awk, además de ese añadido innecesario read .

Dado que la semana pasada hubo una charla sobre sed, quería probar mis habilidades recientemente adquiridas y simplificar echo | awk | { read; echo} en algo más comprensible echo | sed. Aunque definitivamente no es el mejor enfoque para identificar el error, pensé que al menos intentaría mi destreza con sed y, tal vez, aprendería algo nuevo sobre el problema. A lo largo del proceso, pedí a un colega, el autor de la charla sobre sed, que me ayudara a idear un script de sed más eficiente.

Envié el contenido de varnishadm vcl.show -v "$VCL_NAME" a un archivo, así podía concentrarme en escribir el script de sed sin problemas relacionados con las recargas del servicio.

Una breve descripción de cómo sed procesa los datos de entrada se puede encontrar en su manual GNU. En las fuentes de sed, el símbolo n se especifica explícitamente como el delimitador de líneas.

Con varios pasos y las recomendaciones de mi colega, escribimos un script de sed que daba el mismo resultado que toda la línea original 116.

A continuación, se muestra un ejemplo del archivo con los datos de entrada:

> cat vcl-example.vcl
Texto
// VCL.SHOW 0 1578 archivo con 3 espacios.vcl
Más texto
// VCL.SHOW 0 1578 archivo.vcl
Aún más texto
// VCL.SHOW 0 1578 archivo con DOSespacios.vcl
Texto final

Esto puede no ser obvio a partir de la descripción anterior, pero solo nos interesa el primer comentario // VCL.SHOW, y en los datos de entrada puede haber varios. Esa es la razón por la que el awk original termina su trabajo 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á aproximadamente 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, entonces consume ansiosamente el texto que incluye ambos números en esta cadena y guarda todo lo que quede después de esta operación. Devuelve el valor guardado y finaliza el programa.

Sencillo, ¿no?

Estábamos satisfechos con el script de sed y con 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 lo volví a iniciar systemctl reload varnish. Un error terrible echo: error de escritura: Tubería rota se reía de nuevo en nuestra cara. El cursor parpadeante esperaba la entrada de un nuevo comando en la oscura vacuidad del terminal…

Fuente: habr.com

Compra un hosting fiable para sitios web con protección contra DDoS, servidores VPS VDS 🔥 Compra un hosting fiable para sitios web con protección contra DDoS, servidores VPS VDS | ProHoster