"inspect" : Plugin de débogage dynamique Lua pour Apache APISIX

Pourquoi avons-nous besoin du plugin de débogage dynamique Lua ?

Apache APISIX contient une quantité importante de code Lua. Existe-t-il un moyen d'inspecter les valeurs des variables dans le code au moment de l'exécution sans modifier le code source ?

Modifier le code source Lua pour le débogage présente plusieurs inconvénients :

Les environnements de production ne devraient pas et souvent n'autorisent pas la modification du code source
Modifier le code source nécessite un rechargement, ce qui perturbe le fonctionnement des processus métier
Il peut être difficile de modifier le code source dans des environnements conteneurisés
Les codes temporairement générés sont susceptibles d'être omis lors du retour en arrière, entraînant des problèmes de maintenance

Nous avons généralement besoin d'inspecter les valeurs des variables, non seulement au début ou à la fin des fonctions, mais également lorsque des conditions spécifiques sont remplies, comme lorsqu'une boucle atteint un certain nombre d'itérations ou lorsqu'une condition spécifique est vraie. De plus, il ne suffit pas toujours de simplement imprimer les valeurs des variables ; il peut également être nécessaire d'envoyer des informations pertinentes à des systèmes externes. En outre, comment rendre ce processus dynamique, et peut-il être fait sans affecter négativement les performances du programme ?

Le plugin de débogage dynamique Lua, inspect, vous aide à répondre à ces exigences.

Gestion personnalisable des points d'arrêt
Définition dynamique des points d'arrêt
Plusieurs points d'arrêt peuvent être définis
Les points d'arrêt peuvent être configurés pour ne se déclencher qu'une seule fois
L'impact sur les performances peut être contrôlé et maintenu dans une portée spécifique

Principe de fonctionnement du plugin

Il utilise pleinement la fonction Debug API de Lua pour implémenter ses fonctionnalités. Pendant le mode interpréteur, chaque bytecode exécuté peut être mappé à un fichier spécifique et à un numéro de ligne. Pour définir des points d'arrêt, il suffit de vérifier si le numéro de ligne correspond à la valeur attendue et d'exécuter la fonction de point d'arrêt que nous avons déjà définie. Cela nous permet de traiter les informations de contexte de la ligne correspondante, y compris les upvalues, les variables locales et certaines métadonnées, comme la pile.

APISIX utilise l'implémentation JIT de Lua : LuaJIT, où de nombreux chemins de code chauds sont compilés en code machine pour être exécutés. Cependant, ceux-ci ne sont pas affectés par Debug API, nous devons donc vider le cache JIT avant d'activer les points d'arrêt. L'essentiel est que nous pouvons choisir de ne vider que le cache JIT d'une fonction Lua spécifique, réduisant ainsi l'impact sur les performances globales. Lorsqu'un programme s'exécute, de nombreux blocs de code compilés JIT seront nommés trace dans LuaJIT. Ces traces sont associées à des fonctions Lua, et une seule fonction Lua peut inclure plusieurs traces, faisant référence à différents chemins chauds dans la fonction.

Nous pouvons spécifier leurs objets de fonction et vider leur cache JIT pour les fonctions globales et de niveau module. Cependant, si le numéro de ligne correspond à d'autres types de fonctions, comme les fonctions anonymes, nous ne pouvons pas obtenir l'objet de fonction globalement. Dans de tels cas, nous ne pouvons que vider tout le cache JIT. De nouvelles traces ne peuvent pas être générées pendant le débogage, mais les traces existantes non vidées continuent de s'exécuter. Tant que nous avons suffisamment de contrôle, les performances du programme ne seront pas affectées, car un système en ligne qui fonctionne depuis longtemps ne générera généralement pas de nouvelles traces. Une fois le débogage terminé et tous les points d'arrêt révoqués, le système reviendra au mode JIT normal, et le cache JIT vidé sera régénéré une fois qu'il ré-entrera dans le point chaud.

Installation et configuration

Ce plugin est activé par défaut.

Configurez correctement conf/confg.yaml pour activer ce plugin :

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

Le plugin lit les définitions de points d'arrêt dans le fichier '/usr/local/apisix/plugin_inspect_hooks.lua' toutes les 3 secondes par défaut. Pour déboguer, il suffit de modifier ce fichier.

Nous recommandons de créer un lien symbolique vers ce chemin afin qu'il soit plus facile d'archiver différentes versions historiques du fichier de points d'arrêt.

Veuillez noter que lorsque le fichier est modifié, le plugin effacera tous les points d'arrêt précédents et activera tous les nouveaux points d'arrêt définis dans le fichier de points d'arrêt. Ces points d'arrêt seront effectifs dans tous les processus worker.

Généralement, il n'est pas nécessaire de supprimer le fichier, car lors de la définition des points d'arrêt, vous pouvez spécifier quand les révoquer.

La suppression de ce fichier annulera tous les points d'arrêt pour tous les processus worker.

Les logs de démarrage et d'arrêt des points d'arrêt seront enregistrés au niveau de log 'WARN'.

Définir des points d'arrêt

require("apisix.inspect.dbg").set_hook(file, line, func, filter_func)

file, le nom du fichier, qui peut être n'importe quel nom de fichier ou chemin non ambigu.
line, le numéro de ligne dans le fichier, veuillez noter que les points d'arrêt sont étroitement liés aux numéros de ligne, donc si le code change, le numéro de ligne doit également changer.
func, le nom de la fonction dont la trace doit être vidée. Si c'est nil, alors toutes les traces dans la luajit vm seront vidées.
filter_func, une fonction Lua personnalisée qui gère le point d'arrêt
- Le paramètre d'entrée est appelé table qui inclut les éléments suivants :
  - finfo: la valeur de retour de debug.getinfo(level, "nSlf")
  - uv: table de hachage des upvalues
  - vals: table de hachage des variables locales
- Si la valeur de retour de la fonction est true, alors le point d'arrêt sera automatiquement révoqué. Sinon, le point d'arrêt continuera à être effectif.

Par exemple :

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)
--- plus de points d'arrêt ...

Veuillez noter que le point d'arrêt demo organise certaines informations et les envoie à un serveur externe. De plus, la bibliothèque resty.http utilisée est une bibliothèque asynchrone basée sur cosocket.

Chaque fois que vous appelez l'API asynchrone d'OpenResty, elle doit être envoyée avec un délai en utilisant timer, car l'exécution des fonctions sur les points d'arrêt est synchrone et bloquante, elle ne reviendra pas au programme principal de nginx pour un traitement asynchrone, donc elle doit être retardée.

Cas d'utilisation

Déterminer les routes en fonction du contenu du corps de la requête

Disons que nous avons une exigence : comment pouvons-nous configurer une route qui n'accepte que les requêtes POST avec la chaîne APISIX: 666 dans le corps de la requête ?

Dans la configuration de la route, il y a un champ vars, qui peut être utilisé pour vérifier la valeur des variables nginx afin de déterminer si la route doit être correspondante. La variable $request_body fournie par nginx contient la valeur du corps de la requête, nous pouvons donc utiliser cette variable pour implémenter notre exigence.

Essayons de configurer les routes :

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
        }
    }
}'

Ensuite, nous pouvons essayer ceci :

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"}

Étrange, pourquoi ne pouvons-nous pas correspondre à cette route ?

Nous allons ensuite consulter la documentation pour cette variable dans nginx :

La valeur de la variable est disponible dans les emplacements traités par les directives proxy_pass, fastcgi_pass, uwsgi_pass et scgi_pass lorsque le corps de la requête a été lu dans un tampon mémoire.

En d'autres termes, nous devons d'abord lire le corps de la requête avant d'utiliser cette variable.

Lors de la correspondance de la route, cette variable sera-t-elle vide ? Nous pouvons utiliser le plugin inspect pour le vérifier.

Nous avons trouvé la ligne de code qui correspond à la route :

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
...

Vérifions la variable request_body à la ligne 515, qui est router.router_http.match(api_ctx).

Configurer des points d'arrêt

Modifiez le fichier /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)

Créez un lien symbolique vers le chemin du fichier de points d'arrêt :

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

Vérifiez les logs pour confirmer que le point d'arrêt est effectif.

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

Redéclenchez la correspondance des routes :

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

Vérifiez les logs :

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"

Bien sûr, request_body est vide !

Solution

Puisque nous savons que nous devons lire le corps de la requête pour utiliser la variable request_body, nous ne pouvons pas utiliser vars pour cela. Au lieu de cela, nous pouvons utiliser le champ filter_func dans la route pour répondre à notre exigence.

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
        }
    }
}'

Vérifions :

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"
}

Problème résolu !

Afficher certains logs bloqués par le niveau de log.

En général, nous n'activons pas les logs de niveau INFO dans un environnement de production, mais parfois nous avons besoin de vérifier certaines informations détaillées. Comment pouvons-nous faire cela ?

Nous ne définissons généralement pas directement le niveau INFO et rechargeons ensuite, car cela présente deux inconvénients :

Trop de logs, ce qui affecte les performances et augmente la difficulté de vérification
Le rechargement entraîne la déconnexion des connexions persistantes, affectant le trafic en ligne

Généralement, nous avons seulement besoin de vérifier les logs d'un point spécifique ; par exemple, nous savons tous qu'APISIX utilise etcd comme base de données de distribution de configuration, donc pouvons-nous voir quand la configuration de la route est mise à jour de manière incrémentielle sur le plan de données ? Quelles données spécifiques ont été mises à jour ?

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 fonction Lua pour la synchronisation incrémentielle est sync_data(), mais elle affiche les données incrémentielles de la surveillance etcd au niveau INFO.

Essayons donc d'utiliser le plugin inspect pour afficher. Nous n'afficherons que les changements des ressources de routes.

Modifiez /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 logique de cette fonction de traitement de point d'arrêt indique clairement la capacité de filtrage. Si la key de watch est /routes, et que err est vide, elle affichera les données retournées par etcd une seule fois, puis annulera le point d'arrêt.

Notez que sync_data() est une fonction locale, donc elle ne peut pas être référencée directement. Dans ce cas, nous ne pouvons que définir le troisième paramètre de set_hook à nil, ce qui a pour effet secondaire de vider toutes les traces.

Dans l'exemple ci-dessus, nous avons créé un lien symbolique, donc il suffit de sauvegarder les fichiers après modification. Les points d'arrêt seront activés après quelques secondes ; vous pouvez vérifier le log pour confirmer.

En vérifiant le log, nous pouvons obtenir les informations dont nous avons besoin, qui sont affichées au niveau de log WARN. Il montre également l'heure à laquelle nous obtenons les données incrémentielles d'etcd sur le plan de données.

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

Conclusion

Le débogage dynamique Lua est une fonction auxiliaire importante. Avec le plugin inspect d'APISIX, nous pouvons faire beaucoup de choses telles que :

Dépanner et identifier la cause des problèmes
Afficher certains logs bloqués et récupérer diverses informations selon les besoins
Apprendre le code Lua en déboguant

Veuillez lire ces documentations associées pour plus de détails.