Una historia de coredump sobre NGINX ctx y error_page

Los coredumps en el entorno de producción son aterradores para los ingenieros, especialmente cuando los fallos ocurren en medio de la noche. Lo experimenté personalmente hace más de una década. Intentando localizar este "fantasma" de error que solo aparecía por la noche, todo el equipo se fue a casa a dormir por la tarde y regresó a la empresa a las 12 de la noche para esperar el fallo y revisar cada servicio uno por uno. Imaginen una noche oscura y un edificio de oficinas con solo unas pocas estaciones de trabajo encendidas, observando el monitor que late constantemente en busca de datos y registros: una experiencia intensa y emocionante. Nos quedamos tres noches antes de localizar el error y solucionarlo, una experiencia inolvidable.

Poco sabíamos que volveríamos a experimentar esto. Solo que esta vez no fue nuestro propio servicio, sino que el servicio en línea del cliente tuvo un coredump. Esto fue más desafiante que nuestro propio entorno controlable:

• El error solo ocurría en el entorno de producción del usuario, y el usuario no podía reproducir el error ni en su entorno de preproducción ni en el entorno de pruebas.
• El usuario tenía código personalizado sobre el Apache APISIX de código abierto, que no era visible hasta que se firmó un NDA por separado.
• No se podían agregar registros de depuración.
• El error solo ocurría a las 3 am, lo que requería recursos adicionales del cliente para manejarlo de inmediato.

En resumen, este problema no se podía reproducir, no había código fuente completo y no había un entorno para probar. Sin embargo, tuvimos que localizar el error, encontrar una manera de reproducirlo y finalmente proporcionar una solución. Durante el proceso, enfrentamos muchos desafíos y aprendimos mucho de ellos. Aquí compartimos algunos puntos interesantes encontrados durante el proceso de depuración. Espero que brinden alguna orientación cuando las personas estén depurando NGINX y APISIX.

Descripción del Problema

Después de que el usuario actualizó APISIX de la versión 2.4.1 a la 2.13.1, ocurrieron coredumps de manera cíclica, con el siguiente mensaje de error:

Del mensaje de coredump, pudimos ver que el fallo de segmentación ocurre en el lua-var-nginx-module. Y aquí están los datos correspondientes (parciales) en la memoria:

#0  0x00000000005714d4 in ngx_http_lua_var_ffi_scheme (r=0x570d700, scheme=0x7fd2c241a760)
    at /tmp/vua-openresty/openresty-1.19.3.1-build/openresty-1.19.3.1/../lua-var-nginx-module/src/ngx_http_lua_var_module.c:152
152        /tmp/vua-openresty/openresty-1.19.3.1-build/openresty-1.19.3.1/../lua-var-nginx-module/src/ngx_http_lua_var_module.c: No such file or directory.
(gdb) print *r
$1 = {signature = 0, connection = 0x0, ctx = 0x15, main_conf = 0x5adf690, srv_conf = 0x0, loc_conf = 0x0, read_event_handler = 0xe, write_event_handler = 0x5adf697,
  cache = 0x2, upstream = 0x589c15, upstream_states = 0x0, pool = 0x0, header_in = 0xffffffffffffffff}

Podemos ver que los datos en la memoria tienen un problema.

Algunas Reflexiones Antes del Análisis

El fallo de segmentación generalmente ocurre en dos escenarios:

1. Leer/escribir una dirección inválida en la memoria, como acceder a un índice de matriz fuera de límites, el fallo de segmentación ocurre inmediatamente.
2. Hacer una escritura inválida pero modificar una dirección válida, por lo que no genera un fallo de segmentación de inmediato. Durante la ejecución del programa, intenta acceder a datos en la dirección defectuosa y genera un fallo de segmentación. Por ejemplo, cuando el valor de un puntero se modifica por error, más tarde, cuando accedemos a este puntero, podría desencadenar un fallo de segmentación.

Para el primer escenario, el problema se puede localizar fácilmente si revisamos la pila de llamadas.

Para el segundo escenario, como no está claro dónde ocurre el error en primer lugar, el código que generó el error y el código que desencadenó el fallo de segmentación pueden no estar en la misma ubicación, incluso completamente no relacionados, lo que dificulta su localización. Solo podríamos recopilar más información contextual relacionada con el fallo, como:

• Detalles de la configuración actual de APISIX.
• La etapa de procesamiento de la solicitud actual.
• Los detalles de la solicitud actual.
• El número de conexiones concurrentes.
• El registro de errores.

A través de esta información, intentaríamos encontrar el error revisando el código y encontrando una manera de reproducir el problema.

Análisis

1. Verificación del Contexto de los Errores

Después de un análisis cuidadoso, descubrimos que el error generalmente ocurre entre las 3 am y las 4 am, con el siguiente mensaje de error de coredump:

Finalmente, nos dimos cuenta de que el registro de errores está asociado con las operaciones del usuario. Debido a ciertas razones, todos los mensajes de upstream se borrarían en este momento. Por lo tanto, sospechamos que el problema está asociado con las operaciones de borrado/reinicio de upstream, y el coredump podría ser causado por ingresar a una rama de excepción después de que el error regresa.

2. Obtener la Pila de Llamadas de Lua

Dado que GDB no puede rastrear la pila de llamadas de Lua, no pudimos localizar qué llamada produjo el error. Por lo tanto, lo primero que necesitaríamos hacer es obtener la pila de llamadas de Lua; teníamos dos métodos para obtener las pilas de llamadas:

1. En la biblioteca lua-var-nginx-module agregar código para imprimir la pila de llamadas (print(debug.traceback(...)). El inconveniente es que generará muchos registros de errores, afectando negativamente el entorno de producción.
2. Usar openresty-gdb-utils mantenido por API7.ai, este kit de herramientas utiliza el DSL de GDB y la extensión de Python para mejorar la capacidad de GDB para analizar la pila de llamadas de Lua. Nota, necesitarás activar el símbolo de depuración en el momento de la compilación. Está incluido por defecto en APISIX.

Luego, obtuvimos la siguiente pila de llamadas.

Combinando ambas pilas de llamadas de Lua y C, pudimos encontrar que el coredump se debía a que el usuario llamó a ngx.ctx.api_ctx.var.scheme en el plugin de Prometheus. Sin embargo, la razón del fallo aún no estaba clara, necesitaríamos analizarlo más a fondo.

3. El Caché Causó el Problema

El error ocurrió al acceder a una variable de ngx.ctx.api_ctx.var que ejecutó una llamada en el lua-var-nginx-module descrito anteriormente. Para aumentar la eficiencia, almacenó en caché la solicitud actual. Recordamos que el error ocurrió cuando el valor del cuerpo de la solicitud tenía una excepción, por lo que la validez de la solicitud en caché también era cuestionable. Para verificar esta idea, detuvimos el programa de tomar la memoria en caché, pero volvimos a obtener la solicitud cada vez.

else
    --val = get_var(key, t._request)
    val = get_var(key, nil)              <============ t._request cambió a nil
end

El usuario probó con esta versión modificada durante toda la noche, y el error no volvió a ocurrir; verificamos que el cuerpo de la solicitud tenía un problema.

4. El Error en ngx.ctx

El cuerpo de la solicitud en caché se guardó en ngx.ctx, y el único lugar que modificó ngx.ctx fue en apisix/init.lua.

function _M.http_header_filter_phase()
    if ngx_var.ctx_ref ~= '' then
        -- prevenir la fuga de la tabla
        local stash_ctx = fetch_ctx()

        -- redirección interna, por lo que deberíamos aplicar el ctx
        if ngx_var.from_error_page == "true" then
            ngx.ctx = stash_ctx          <================= AQUÍ
        end
    end

    core.response.set_header("Server", ver_header)

    local up_status = get_var("upstream_status")
    if up_status then
        set_resp_upstream_status(up_status)
    end

¿Por qué necesitábamos recuperar ngx.ctx aquí? Porque ngx.ctx se almacena en el registro de Lua, el ngx.ctx correspondiente se puede encontrar a través del índice del registro. Y el índice se almacenó en el miembro ctx de la estructura de solicitud de NGINX. Cada vez que se hacía una redirección interna, NGINX borraba ctx, y por lo tanto no se podía encontrar el índice.

Para resolver este problema, APISIX creó una tabla, la tabla guardaba el ngx.ctx actual antes de redirigir, y luego usaba ngx.var para registrar el índice de ngx.ctx en esta tabla, siempre que necesitara ser restaurado, podríamos obtener ngx.ctx directamente de la tabla.

El código en la figura anterior solo se activaba cuando el usuario configuró las instrucciones error_page, y después de que ocurriera un error después de las redirecciones internas.

Y sabíamos exactamente que el usuario activó la instrucción error_page después de la actualización de la versión, combinado con el error que ocurrió por el cambio de upstream que describimos anteriormente. Todas las cosas parecían estar conectadas. ¿Fue realmente el ngx.ctx el que creó el error durante el proceso de manejo de errores?

5. ¿Por Qué ngx.ctx Tiene un Error?

Con la pregunta, revisamos el código relacionado con la copia de seguridad de ngx.ctx, y encontramos problemas más extraños. Después de fallar en set_upstream, nunca tomaba el paso de recuperación de ngx.ctx, porque salía temprano, no hacía una copia de seguridad de ngx.ctx, y tampoco iba al proceso de recuperación.

¡Esto era obviamente un error! Bueno, esto se debe a que ngx.ctx necesitaba ser recuperado después de redirigir. ¿Y cómo se recuperaba ngx.ctx en este proceso? ¿Dónde se equivocó ngx.ctx en primer lugar? Ahora había demasiadas incertidumbres, necesitábamos recopilar más datos.

Después de discutir, agregamos un segundo registro en producción, y descubrimos que, cuando el error ocurría después de una redirección interna, ngx.ctx no pasaba por el proceso de recuperación, ¡sino que causaba directamente el coredump!

Este era un fenómeno desconcertante porque si el ngx.ctx no se recuperaba después de la redirección, ngx.ctx estaría vacío/nulo. Y había código que verificaba valores vacíos; no debería desencadenar el código de coredump en el plugin.

local function common_phase(phase_name)
    local api_ctx = ngx.ctx.api_ctx
    if not api_ctx then              <============ AQUÍ
        return
    end

    plugin.run_global_rules(api_ctx, api_ctx.global_rules, phase_name)

Entonces, ¿fue esta redirección interna de error_page la que causó que ngx.ctx tuviera un problema?

6. Conclusión Inicial

Después de analizar y verificar, obtuvimos una comprensión básica del proceso erróneo.

set_upstream falló y redirigió a la etapa de procesamiento de errores de error_page, y el ngx.ctx esperado vacío tenía un valor inesperado. Y debido al error de APISIX, no recuperó ngx.ctx antes de redirigir, causando que ngx.ctx tuviera datos sucios al acceder, lo que provocó el coredump. Para resolver este problema, solo necesitaríamos recuperar ngx.ctx después de redirigir; la implementación detallada de este commit se proporciona al final del artículo como referencia.

Aunque proporcionamos una solución para el error, aún no pudimos comprender la lógica completa del error. Debido a que el usuario no modificó la lógica de ngx.ctx, la versión de código abierto debería poder reproducirlo. Para no seguir afectando el entorno de producción y el proceso de implementación del usuario, decidimos continuar investigando la causa raíz.

7. Reproducción Exitosa

De lo que sabíamos, no pudimos reproducir el problema. Después del análisis, decidimos verificar dos de los siguientes lugares:

• ¿La redirección interna tenía ramas especiales de procesamiento?
• ¿Ngx.ctx tenía ramas especiales de procesamiento?

Para el primer punto, durante el procesamiento de cada módulo de filtro de NGINX, podría tener algunas ramas de excepción que afectaran a los miembros ctx del cuerpo de la solicitud, afectando así a ngx.ctx. Revisamos los módulos del usuario compilados en NGINX en busca de posibles ramas de excepción, pero no encontramos problemas similares.

Para el segundo punto, después de la investigación, descubrimos que durante el handshake SSL, ngx.ctx tiene un problema de reutilización. Si la etapa HTTP no podía obtener ngx.ctx, intentaría obtenerlo de la etapa SSL. La etapa SSL tiene su propio ngx.ctx, y eso podría causar problemas para ngx.ctx.

Basándonos en los descubrimientos anteriores, diseñamos las siguientes condiciones y pudimos reproducir el problema con éxito:

1. Misma versión de APISIX que la del usuario.
2. Activar el certificado SSL.
3. Crear un error interno que active error_page (como solicitar upstream cuando no hay ninguno).
4. Conexión larga.
5. Plugin de Prometheus (el coredump ocurrió en el plugin para el usuario).

Finalmente, hicimos ladrillos sin paja. A través de conjeturas y verificaciones, finalmente descubrimos el proceso completo de este error. Una vez que hay una reproducción completa, ya no es difícil resolver el problema, y el proceso final no se describirá en detalle aquí. Creo que todos tienen muchas experiencias en problemas que pueden reproducirse con precisión.

Resumen

La causa raíz de este problema: debido a que ngx.ctx no se restaura después de ingresar a error_page, todas las solicitudes en la conexión larga reutilizan el mismo ngx.ctx en la fase SSL. Finalmente, causando que ngx.ctx tenga datos sucios y se genere un coredump.

En el seguimiento, también propusimos una solución correspondiente a este problema: asegurar que ngx.ctx pueda restaurarse normalmente después de la redirección interna. Por favor, consulte el PR específico.

Si su APISIX utiliza funciones que involucran redirección interna como error_page, actualice a la última versión lo antes posible.

Escribir programas y depurar son tareas científicamente rigurosas y no hay lugar para la ambigüedad. Para resolver un problema, necesitaremos recopilar información, seguir todas las pistas potenciales, analizar la pila de llamadas y luego descubrir el contexto para reproducir el error. Finalmente, el problema se resuelve.