Une histoire de coredump sur NGINX ctx et error_page

Les coredumps en environnement de production sont une source d'angoisse pour les ingénieurs, surtout lorsque les plantages surviennent au milieu de la nuit. J'en ai fait l'expérience il y a plus de dix ans. Pour tenter de localiser ce bug "fantôme" qui ne se manifestait qu'à la nuit tombée, toute l'équipe est rentrée chez elle pour dormir l'après-midi et est revenue à l'entreprise à minuit pour attendre le crash et vérifier chaque service un par un. Imaginez une nuit sombre et un immeuble de bureaux avec seulement quelques postes de travail allumés, surveillant un moniteur qui affiche en permanence des données et des logs – une expérience intense et excitante. Nous sommes restés trois nuits avant de localiser le bug et de le résoudre, une expérience inoubliable.

Nous ne savions pas que nous allions revivre cela. Sauf que cette fois, ce n'était pas notre propre service, mais le service en ligne d'un client qui avait un coredump. Cela était plus difficile que notre environnement contrôlable :

• L'erreur ne se produisait que dans l'environnement de production de l'utilisateur, et l'utilisateur ne pouvait pas reproduire l'erreur même dans son environnement de pré-production et de test.
• L'utilisateur avait du code personnalisé sur l'Apache APISIX open source, qui n'était pas visible avant la signature d'un NDA séparé.
• Impossible d'ajouter des logs de débogage.
• L'erreur ne se produisait qu'à 3 heures du matin, nécessitant donc des ressources supplémentaires du client pour être gérée immédiatement.

En bref, ce problème était impossible à reproduire, sans code source complet, et sans environnement de test. Cependant, nous devions localiser l'erreur, trouver un moyen de la reproduire et finalement fournir un correctif. Durant ce processus, nous avons rencontré de nombreux défis et avons beaucoup appris. Voici quelques points intéressants rencontrés lors du processus de débogage. J'espère qu'ils fourniront des pistes utiles pour le débogage de NGINX et APISIX.

Description du problème

Après que l'utilisateur ait mis à jour APISIX de la version 2.4.1 à la version 2.13.1, des coredumps se sont produits de manière cyclique, avec le message d'erreur suivant :

À partir du message de coredump, nous pouvions voir que la segmentation fault se produisait dans le module lua-var-nginx-module. Et voici les données correspondantes (partielles) en mémoire :

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

Nous pouvions voir que les données en mémoire posaient problème.

Quelques réflexions avant l'analyse

La segmentation fault se produit généralement dans deux scénarios :

1. Lecture/écriture d'une adresse mémoire invalide, comme accéder à un index de tableau hors limites, la segmentation fault se produit immédiatement.
2. Effectuer une écriture invalide mais modifier une adresse valide, donc cela ne génère pas immédiatement une segmentation fault. Pendant l'exécution du programme, il essaie d'accéder aux données à l'adresse défectueuse et génère une segmentation fault. Par exemple, lorsque la valeur d'un pointeur est modifiée par erreur, plus tard, lorsque nous accédons à ce pointeur, cela peut déclencher une segmentation fault.

Pour le premier scénario, le problème peut être facilement localisé si nous vérifions la pile d'appels.

Pour le second scénario, puisqu'il n'est pas clair où l'erreur se produit initialement, le code qui a généré l'erreur et le code qui a déclenché la segmentation fault peuvent ne pas être au même endroit, voire complètement sans rapport, rendant la localisation difficile. Nous ne pouvions que collecter plus d'informations contextuelles impliquant le crash, telles que :

• Les détails de la configuration actuelle d'APISIX.
• L'étape de traitement de la requête actuelle.
• Les détails de la requête actuelle.
• Le nombre de connexions concurrentes.
• Le log d'erreur.

À travers ces informations, nous essaierions de trouver le bug en examinant le code et en trouvant un moyen de reproduire le problème.

Analyse

1. Vérification du contexte des erreurs

Après une analyse minutieuse, nous avons constaté que l'erreur se produisait généralement entre 3 et 4 heures du matin, avec le message de coredump suivant :

Finalement, nous avons réalisé que le log d'erreur était associé aux opérations de l'utilisateur. Pour certaines raisons, tous les messages en amont étaient effacés à ce moment-là. Nous avons donc suspecté que le problème était lié aux opérations de réinitialisation/effacement en amont, et que le coredump pourrait être causé par l'entrée dans une branche d'exception après le retour de l'erreur.

2. Obtenir la pile d'appels de Lua

Puisque GDB ne peut pas tracer la pile d'appels de Lua, nous ne pouvions pas localiser quel appel avait produit l'erreur. Donc, la première chose à faire était d'obtenir la pile d'appels de Lua ; nous avions deux méthodes pour obtenir les piles d'appels :

1. Dans la bibliothèque lua-var-nginx-module, ajouter du code pour imprimer la pile d'appels (print(debug.traceback(...)). L'inconvénient est que cela générera beaucoup de logs d'erreur, impactant négativement l'environnement de production.
2. Utiliser openresty-gdb-utils maintenu par API7.ai, cet outil utilise le DSL de GDB et l'extension python pour améliorer la capacité de GDB à analyser la pile d'appels de Lua. Notez, vous devrez activer le symbole de débogage lors de la compilation. Il est inclus par défaut dans APISIX.

Ensuite, nous avons obtenu la pile d'appels suivante.

En combinant les piles d'appels de Lua et de C, nous avons pu constater que le coredump était dû à l'appel de ngx.ctx.api_ctx.var.scheme par l'utilisateur dans le plugin Prometheus. Cependant, la raison du crash restait floue, nous devions l'analyser plus en détail.

3. Le cache a causé le problème

L'erreur s'est produite lors de l'accès à une variable de ngx.ctx.api_ctx.var exécutant un appel dans le lua-var-nginx-module décrit ci-dessus. Pour augmenter l'efficacité, il a mis en cache la requête actuelle. Nous nous sommes souvenus que l'erreur s'est produite lorsque la valeur du corps de la requête avait une exception, donc la validité de la requête mise en cache était également douteuse. Pour vérifier cette pensée, nous avons empêché le programme de prendre la mémoire mise en cache, mais avons récupéré la requête à chaque fois.

else
    --val = get_var(key, t._request)
    val = get_var(key, nil)              <============ t._request change to nil
end

L'utilisateur a testé avec cette version modifiée pendant toute une nuit, et l'erreur ne s'est plus produite ; nous avons vérifié que le corps de la requête posait problème.

4. L'erreur dans ngx.ctx

Le corps de la requête mis en cache était sauvegardé dans ngx.ctx, et le seul endroit qui modifiait ngx.ctx était dans apisix/init.lua.

function _M.http_header_filter_phase()
    if ngx_var.ctx_ref ~= '' then
        -- prevent for the table leak
        local stash_ctx = fetch_ctx()

        -- internal redirect, so we should apply the ctx
        if ngx_var.from_error_page == "true" then
            ngx.ctx = stash_ctx          <================= HERE
        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

Pourquoi devions-nous récupérer ngx.ctx ici ? Parce que ngx.ctx est stocké dans le registre Lua, le ngx.ctx correspondant peut être trouvé via l'index du registre. Et l'index était stocké dans le membre ctx de la structure de requête NGINX. Chaque fois qu'une redirection interne était effectuée, NGINX effaçait ctx, et donc l'index ne pouvait pas être trouvé.

Pour résoudre ce problème, APISIX a créé une table, la table sauvegardait le ngx.ctx actuel avant la redirection, puis utilisait ngx.var pour enregistrer l'index de ngx.ctx dans cette table, chaque fois qu'il devait être restauré, nous pouvions obtenir ngx.ctx directement depuis la table.

Le code dans la figure ci-dessus ne se déclenchait que lorsque l'utilisateur configurait les instructions error_page, et après qu'une erreur se produisait après des redirections internes.

Et nous savions exactement que l'utilisateur avait activé l'instruction error_page après la mise à jour de version, combiné avec l'erreur qui s'est produite à partir du changement en amont que nous avons décrit ci-dessus. Toutes les choses semblaient connectées. Était-ce en fait le ngx.ctx qui créait le bug pendant le processus de gestion des erreurs ?

5. Pourquoi ngx.ctx a un bug

Avec cette question, nous avons vérifié le code lié à la sauvegarde de ngx.ctx, et nous avons trouvé des problèmes encore plus étranges. Après un échec à set_upstream, il ne passerait jamais par l'étape de récupération de ngx.ctx, car il sortait tôt, il ne sauvegardait pas ngx.ctx, et il n'allait pas non plus au processus de récupération.

C'était clairement un bug ! Eh bien, c'est parce que ngx.ctx devait être récupéré après la redirection. Et comment ce processus récupérait-il ngx.ctx ? Où ngx.ctx avait-il mal tourné initialement ? Maintenant, il y avait trop d'incertitudes, nous devions collecter plus de données.

Après discussion, nous avons ajouté un deuxième log en production, et nous avons découvert que, lorsque l'erreur se produisait après une redirection interne, ngx.ctx ne passait pas par le processus de récupération, mais causait directement un coredump !

C'était un phénomène déroutant car si ngx.ctx ne récupérait pas après la redirection, ngx.ctx serait vide/null. Et il y avait du code qui vérifiait les valeurs vides; il ne devrait pas déclencher le code de coredump dans le plugin.

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

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

Alors, était-ce cette redirection interne error_page qui a déclenché ngx.ctx pour avoir un problème ?

6. Conclusion initiale

Après analyse et vérification, nous avons obtenu une compréhension de base du processus erroné.

set_upstream a échoué et a redirigé vers l'étape de traitement des erreurs d'error_page, et le ngx.ctx vide attendu avait une valeur inattendue. Et en raison du bug d'APISIX, il n'a pas récupéré ngx.ctx avant la redirection, causant à ngx.ctx d'avoir des données sales lors de l'accès, provoquant ainsi le coredump. Pour résoudre ce problème, nous devions simplement récupérer ngx.ctx après la redirection ; l'implémentation détaillée de ce commit est fournie à la fin de l'article pour référence.

Bien que nous ayons fourni un correctif pour le bug, nous n'avons toujours pas compris la logique complète du bug. Parce que l'utilisateur n'avait pas modifié la logique de ngx.ctx, la version open source devrait pouvoir reproduire. Afin de ne pas continuer à affecter l'environnement de production et le processus de déploiement de l'utilisateur, nous avons décidé de continuer à enquêter sur la cause racine.

7. Reproduction réussie

À partir de ce que nous savions, nous ne pouvions pas reproduire le problème. Après analyse, nous avons décidé de vérifier deux des endroits suivants :

• La redirection interne avait-elle des branches spéciales de traitement ?
• ngx.ctx avait-il des branches spéciales de traitement ?

Pour le premier point, pendant le traitement de chaque module de filtre de NGINX, il peut y avoir des branches d'exception qui affectent les membres ctx du corps de la requête, affectant ainsi ngx.ctx. Nous avons vérifié les modules de l'utilisateur compilés dans NGINX pour des branches d'exception potentielles mais n'avons trouvé aucun problème similaire.

Pour le second point, après investigation, nous avons constaté que pendant la poignée de main SSL, ngx.ctx a un problème de réutilisation. Si l'étape HTTP ne pouvait pas obtenir ngx.ctx, elle essaierait de l'obtenir à partir de l'étape SSL. L'étape SSL a son propre ngx.ctx, et cela pourrait causer des problèmes pour ngx.ctx.

Sur la base des découvertes ci-dessus, nous avons conçu les conditions suivantes, et avons pu reproduire le problème avec succès :

1. Même version d'APISIX que celle de l'utilisateur
2. Activer le certificat SSL
3. Créer une erreur interne qui déclenche error_page (comme demander un upstream lorsqu'il n'y en a pas)
4. Connexion longue
5. Plugin Prometheus (le coredump s'est produit dans le plugin pour l'utilisateur)

Nous avons finalement fait des briques sans paille. Par conjecture et vérification, nous avons finalement compris le processus complet de ce bug. Une fois qu'il y a une reproduction complète, il n'est plus difficile de résoudre le problème, et le processus final ne sera pas décrit en détail ici. Je crois que tout le monde a beaucoup d'expérience dans les problèmes qui peuvent être reproduits avec précision.

Résumé

La cause racine de ce problème : parce que ngx.ctx n'est pas restauré après être entré dans error_page, toutes les requêtes sur la connexion longue réutilisent le même ngx.ctx dans la phase SSL. Finalement, causant à ngx.ctx d'avoir des données sales et un coredump a été généré.

Dans le suivi, nous avons également proposé une solution correspondante à ce problème : s'assurer que ngx.ctx peut être restauré normalement après la redirection interne. Veuillez vous référer au PR spécifique.

Si votre APISIX utilise des fonctions impliquant des redirections internes telles que error_page, veuillez mettre à jour vers la dernière version dès que possible.

Écrire des programmes et déboguer sont des tâches scientifiquement rigoureuses et il n'y a pas de place pour l'ambiguïté. Pour résoudre un problème, nous devrons collecter des informations, suivre toutes les pistes potentielles, analyser la pile d'appels, puis comprendre le contexte pour reproduire l'erreur. Enfin, le problème est résolu.