"inspect": Plugin de Depuración Dinámica Lua para Apache APISIX

JinHua Luo

January 29, 2023

Technology

¿Por qué necesitamos el complemento de depuración dinámica de Lua?

Apache APISIX contiene una cantidad significativa de código Lua. ¿Existe alguna forma de inspeccionar los valores de las variables en el código en tiempo de ejecución sin modificar el código fuente?

Modificar el código fuente de Lua para depurar tiene varias desventajas:

  • Los entornos de producción no deberían y, a menudo, no permiten modificar el código fuente.
  • Modificar el código fuente requiere recargar, lo que interrumpe el funcionamiento de los procesos de negocio.
  • Puede ser complicado modificar el código fuente en entornos contenerizados.
  • Los códigos generados temporalmente son propensos a ser omitidos al revertir, lo que lleva a problemas de mantenimiento.

Normalmente necesitamos inspeccionar los valores de las variables, no solo cuando las funciones comienzan o terminan, sino también cuando se cumplen condiciones específicas, como cuando un bucle alcanza un cierto número de iteraciones o cuando una condición específica es verdadera. Además, no siempre es suficiente simplemente imprimir los valores de las variables; también puede ser necesario enviar información relevante a sistemas externos. Además, ¿cómo hacer que este proceso sea dinámico y sin afectar negativamente el rendimiento del programa?

El complemento de depuración dinámica de Lua, inspect, te ayuda a cumplir con los requisitos anteriores.

  • Manejo de puntos de interrupción personalizables.
  • Configuración dinámica de puntos de interrupción.
  • Se pueden establecer múltiples puntos de interrupción.
  • Los puntos de interrupción se pueden configurar para activarse solo una vez.
  • El impacto en el rendimiento se puede controlar y mantener dentro de un alcance específico.

Principio de funcionamiento del complemento

Utiliza completamente la función Debug API de Lua para implementar sus características. Durante el modo de intérprete, cada bytecode ejecutado podría mapearse a un archivo específico y un número de línea. Para establecer puntos de interrupción, solo necesitamos verificar si el número de línea es igual al valor esperado y ejecutar la función de punto de interrupción que ya hemos definido. Esto nos permite procesar la información de contexto de la línea correspondiente, incluyendo upvalue, variables locales y algunos metadatos, como la pila.

APISIX utiliza la implementación JIT de Lua: LuaJIT, donde muchas rutas de código caliente se compilan en código de máquina para ejecutarse. Sin embargo, estas no se ven afectadas por Debug API, por lo que necesitamos borrar la caché JIT antes de activar los puntos de interrupción. La clave es que podemos elegir borrar solo la caché JIT de una función Lua específica, reduciendo el impacto en el rendimiento global. Cuando un programa se ejecuta, muchos bloques de código compilados JIT se denominarán trace en LuaJIT. Estos traces están asociados con funciones Lua, y una sola función Lua puede incluir múltiples traces, refiriéndose a diferentes rutas calientes dentro de la función.

Podemos especificar sus objetos de función y borrar su caché JIT para funciones globales y de nivel de módulo. Sin embargo, si el número de línea corresponde a otros tipos de funciones, como funciones anónimas, no podemos obtener el objeto de función globalmente. En tales casos, solo podemos borrar toda la caché JIT. No se pueden generar nuevos traces durante la depuración, pero los traces existentes no borrados continúan ejecutándose. Siempre que tengamos suficiente control, el rendimiento del programa no se verá afectado, ya que un sistema en línea que ha estado funcionando durante mucho tiempo generalmente no generará nuevos traces. Una vez que la depuración termina y todos los puntos de interrupción han sido revocados, el sistema volverá al modo JIT normal, y la caché JIT borrada se regenerará una vez que vuelva a entrar en el punto caliente.

Instalación y configuración

Este complemento está habilitado por defecto.

Configura conf/confg.yaml correctamente para habilitar este complemento:

plugins:
...
  - inspect
plugin_attr:
  inspect:
    delay: 3
    hooks_file: "/usr/local/apisix/plugin_inspect_hooks.lua"

El complemento lee las definiciones de puntos de interrupción del archivo '/usr/local/apisix/plugin_inspect_hooks.lua' cada 3 segundos por defecto. Para depurar, solo necesitas editar este archivo.

Recomendamos crear un enlace simbólico a esta ruta para que sea más fácil archivar diferentes versiones históricas del archivo de puntos de interrupción.

Ten en cuenta que cuando el archivo se modifica, el complemento borrará todos los puntos de interrupción anteriores y habilitará todos los nuevos puntos de interrupción definidos en el archivo de puntos de interrupción. Estos puntos de interrupción serán efectivos en todos los procesos de trabajo.

Generalmente, no es necesario eliminar el archivo, ya que al definir puntos de interrupción, puedes especificar cuándo revocarlos.

Eliminar este archivo cancelará todos los puntos de interrupción para todos los procesos de trabajo.

Los registros del inicio y la parada de los puntos de interrupción se registrarán en el nivel de registro 'WARN'.

Definir puntos de interrupción

require("apisix.inspect.dbg").set_hook(file, line, func, filter_func)
  • file, el nombre del archivo, que puede ser cualquier nombre de archivo o ruta no ambigua.
  • line, el número de línea en el archivo, ten en cuenta que los puntos de interrupción están estrechamente vinculados a los números de línea, por lo que si el código cambia, el número de línea también debe cambiar.
  • func, el nombre de la función cuyo trace debe borrarse. Si es nil, entonces se borrarán todos los traces en la luajit vm.
  • filter_func, una función Lua personalizada que maneja el punto de interrupción
    • El parámetro de entrada es una table que incluye lo siguiente:
      • finfo: el valor de retorno de debug.getinfo(level, "nSlf")
      • uv: tabla hash de upvalues
      • vals: tabla hash de variables locales
    • Si el valor de retorno de la función es true, entonces el punto de interrupción se revocará automáticamente. De lo contrario, el punto de interrupción seguirá siendo efectivo.

Por ejemplo:

local dbg = require "apisix.inspect.dbg"
dbg.set_hook("limit-req.lua", 88, require("apisix.plugins.limit-req").access,
function(info)
    ngx.log(ngx.INFO, debug.traceback("foo traceback", 3))
    ngx.log(ngx.INFO, dbg.getname(info.finfo))
    ngx.log(ngx.INFO, "conf_key=", info.vals.conf_key)
    return true
end)
dbg.set_hook("t/lib/demo.lua", 31, require("t.lib.demo").hot2, function(info)
    if info.vals.i == 222 then
        ngx.timer.at(0, function(_, body)
            local httpc = require("resty.http").new()
            httpc:request_uri("http://127.0.0.1:9080/upstream1", {
                method = "POST",
                body = body,
            })
        end, ngx.var.request_uri .. "," .. info.vals.i)
        return true
    end
    return false
end)
--- más puntos de interrupción ...

Ten en cuenta que el punto de interrupción demo organiza alguna información y la envía a un servidor externo. Además, la biblioteca resty.http utilizada es una biblioteca asíncrona basada en cosocket.

Siempre que se llame a la API asíncrona de OpenResty, debe enviarse con un retraso utilizando timer, porque la ejecución de funciones en puntos de interrupción es síncrona y bloqueante, no volverá al programa principal de nginx para el procesamiento asíncrono, por lo que necesita retrasarse.

Casos de uso

Determinar rutas basadas en el contenido del cuerpo de la solicitud

Supongamos que tenemos un requisito: ¿cómo podemos configurar una ruta que solo acepte solicitudes POST con la cadena APISIX: 666 en el cuerpo de la solicitud?

En la configuración de la ruta, hay un campo vars, que se puede utilizar para verificar el valor de las variables de nginx para determinar si la ruta debe coincidir. La variable $request_body proporcionada por nginx contiene el valor del cuerpo de la solicitud, por lo que podemos usar esta variable para implementar nuestro requisito.

Probemos a configurar las rutas:

curl http://127.0.0.1:9180/apisix/admin/routes/var_route \
-H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' -X PUT -i -d '
{
    "uri": "/anything",
    "methods": ["POST"],
    "vars": [["request_body", "~~", "APISIX: 666"]],
    "upstream": {
        "type": "roundrobin",
        "nodes": {
            "httpbin.org": 1
        }
    }
}'

Luego podríamos probar esto:

curl http://127.0.0.1:9080/anything
{"error_msg":"404 Route Not Found"}
curl -i http://127.0.0.1:9080/anything -X POST -d 'hello, APISIX: 666.'
HTTP/1.1 404 Not Found
Date: Thu, 05 Jan 2023 03:53:35 GMT
Content-Type: text/plain; charset=utf-8
Transfer-Encoding: chunked
Connection: keep-alive
Server: APISIX/3.0.0
{"error_msg":"404 Route Not Found"}

Extraño, ¿por qué no podemos hacer coincidir esta ruta?

Luego echaremos un vistazo a la documentación de esta variable en nginx:

El valor de la variable está disponible en las ubicaciones procesadas por las directivas proxy_pass, fastcgi_pass, uwsgi_pass y scgi_pass cuando el cuerpo de la solicitud se ha leído en un búfer de memoria.

En otras palabras, necesitamos leer primero el cuerpo de la solicitud antes de usar esta variable.

Al hacer coincidir la ruta, ¿esta variable estará vacía? Podemos usar el complemento inspect para verificarlo.

Encontramos la línea de código que coincide con la ruta:

apisix/init.lua

...
api_ctx.var.request_uri = api_ctx.var.uri .. api_ctx.var.is_args .. (api_ctx.var.args or "")
router.router_http.match(api_ctx)
local route = api_ctx.matched_route
if not route then
...

Verifiquemos la variable request_body en la línea 515, que es router.router_http.match(api_ctx).

Configurar puntos de interrupción

Edita el archivo /usr/local/apisix/example_hooks.lua:

local dbg = require("apisix.inspect.dbg")
dbg.set_hook("apisix/init.lua", 515, require("apisix").http_access_phase, function(info)
    core.log.warn("request_body=", info.vals.api_ctx.var.request_body)
    return true
end)

Crea un enlace simbólico a la ruta del archivo de puntos de interrupción:

ln -sf /usr/local/apisix/example_hooks.lua /usr/local/apisix/plugin_inspect_hooks.lua

Verifica los registros para confirmar que el punto de interrupción es efectivo.

2023/01/05 12:02:43 [warn] 1890559#1890559: *15736 [lua] init.lua:68: setup_hooks():
set hooks: err: true, hooks: ["apisix\/init.lua#515"], context: ngx.timer

Vuelve a activar la coincidencia de rutas:

curl -i http://127.0.0.1:9080/anything -X POST -d 'hello, APISIX: 666.'

Verifica los registros:

2023/01/05 12:02:59 [warn] 1890559#1890559: *16152
[lua] [string "local dbg = require("apisix.inspect.dbg")..."]:39:
request_body=nil, client: 127.0.0.1, server: _,
request: "POST /anything HTTP/1.1", host: "127.0.0.1:9080"

¡Por supuesto, request_body está vacío!

Solución

Como sabemos que necesitamos leer el cuerpo de la solicitud para usar la variable request_body, no podemos usar vars para hacer esto. En su lugar, podemos usar el campo filter_func en la ruta para lograr nuestro requisito.

curl http://127.0.0.1:9180/apisix/admin/routes/var_route \
-H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' -X PUT -i -d '
{
    "uri": "/anything",
    "methods": ["POST"],
    "filter_func": "function(_) return require(\"apisix.core\").request.get_body():find(\"APISIX: 666\") end",
    "upstream": {
        "type": "roundrobin",
        "nodes": {
            "httpbin.org": 1
        }
    }
}'

Verifiquemos:

curl http://127.0.0.1:9080/anything -X POST -d 'hello, APISIX: 666.'
{
  "args": {},
  "data": "",
  "files": {},
  "form": {
    "hello, APISIX: 666.": ""
  },
  "headers": {
    "Accept": "*/*",
    "Content-Length": "19",
    "Content-Type": "application/x-www-form-urlencoded",
    "Host": "127.0.0.1",
    "User-Agent": "curl/7.68.0",
    "X-Amzn-Trace-Id": "Root=1-63b64dbd-0354b6ed19d7e3b67013592e",
    "X-Forwarded-Host": "127.0.0.1"
  },
  "json": null,
  "method": "POST",
  "origin": "127.0.0.1, xxx",
  "url": "http://127.0.0.1/anything"
}

¡Problema resuelto!

Imprimir algunos registros que han sido bloqueados por el nivel de registro.

En general, no habilitamos registros de nivel INFO en un entorno de producción, pero a veces necesitamos verificar información detallada. ¿Cómo podemos hacer eso?

Normalmente no configuramos directamente el nivel INFO y luego recargamos, ya que esto tiene dos desventajas:

  • Demasiados registros, lo que afecta el rendimiento y aumenta la dificultad de verificación.
  • La recarga hace que las conexiones persistentes se desconecten, afectando el tráfico en línea.

Por lo general, solo necesitamos verificar los registros de un punto específico; por ejemplo, todos sabemos que APISIX usa etcd como una base de datos de distribución de configuración, ¿podemos ver cuándo se actualiza incrementalmente la configuración de la ruta al plano de datos? ¿Qué datos específicos se han actualizado?

apisix/core/config_etcd.lua

local function sync_data(self)
...
    log.info("waitdir key: ", self.key, " prev_index: ", self.prev_index + 1)
    log.info("res: ", json.delay_encode(dir_res, true), ", err: ", err)
...
end

La función Lua para la sincronización incremental es sync_data(), pero imprime los datos incrementales de etcd watch en el nivel INFO.

Así que intentemos usar el complemento inspect para mostrar. Solo mostraremos los cambios de los recursos de rutas.

Edita /usr/local/apisix/example_hooks.lua:

local dbg = require("apisix.inspect.dbg")
local core = require("apisix.core")
dbg.set_hook("apisix/core/config_etcd.lua", 393, nil, function(info)
    local filter_res = "/routes"
    if info.vals.self.key:sub(-#filter_res) == filter_res and not info.vals.err then
        core.log.warn("etcd watch /routes response: ", core.json.encode(info.vals.dir_res, true))
        return true
    end
    return false
end)

La lógica de esta función de manejo de puntos de interrupción indica claramente la capacidad de filtrado. Si la key de watch es /routes, y err está vacío, imprimirá los datos devueltos por etcd solo una vez, luego cancelará el punto de interrupción.

Ten en cuenta que sync_data() es una función local, por lo que no se puede referenciar directamente. En ese caso, solo podemos establecer el tercer parámetro de set_hook como nil, lo que tiene el efecto secundario de borrar todos los traces.

En el ejemplo anterior, hemos creado un enlace simbólico, por lo que solo necesitamos guardar archivos después de editar. Los puntos de interrupción se habilitarán después de unos segundos; puedes verificar el registro para confirmar.

Al verificar el registro, podemos obtener la información que necesitamos, que se imprime en el nivel de registro WARN. También muestra el momento en que obtenemos los datos incrementales de etcd en el plano de datos.

2023/01/05 14:33:10 [warn] 1890562#1890562: *231311
[lua] [string "local dbg = require("apisix.inspect.dbg")..."]:41:
etcd watch /routes response: {"headers":{"X-Etcd-Index":"24433"},
"body":{"node":[{"value":{"uri":"\/anything",
"plugins":{"request-id":{"header_name":"X-Request-Id","include_in_response":true,"algorithm":"uuid"}},
"create_time":1672898912,"status":1,"priority":0,"update_time":1672900390,
"upstream":{"nodes":{"httpbin.org":1},"hash_on":"vars","type":"roundrobin","pass_host":"pass","scheme":"http"},
"id":"reqid"},"key":"\/apisix\/routes\/reqid","modifiedIndex":24433,"createdIndex":24429}]}}, context: ngx.timer

Conclusión

La depuración dinámica de Lua es una función auxiliar importante. Con el complemento inspect de APISIX, podemos hacer muchas cosas como:

  • Solucionar problemas e identificar la causa de los problemas.
  • Imprimir algunos registros bloqueados y recuperar información variada según sea necesario.
  • Aprender código Lua mediante la depuración.

Por favor, lee estas documentaciones relacionadas para más detalles.

Tags:
APISIX Basics
API Gateway Concept
Plugin