Journalisation de diagnostic avec le module JavaScript NGINX

Dépannage en production sans réglage du journal des erreurs

Éditeur – Ce blog est l’un des nombreux qui traitent de la journalisation avec NGINX et NGINX Plus. Veuillez également consulter :

• Traçage des applications avec NGINX et NGINX Plus
• Demandes d'échantillonnage avec journalisation conditionnelle NGINX

C'est également l'un des nombreux blogs sur les cas d'utilisation du module JavaScript NGINX. Pour la liste complète, voir Cas d'utilisation du module JavaScript NGINX .

NGINX aide les organisations de toutes tailles à gérer leurs sites Web, applications et API stratégiques. Quelle que soit votre échelle et votre choix d’infrastructure de déploiement, l’exécution en production n’est pas facile. Dans cet article, nous parlons d’un des aspects les plus difficiles d’un déploiement de production : la journalisation. Plus précisément, nous discutons de l’équilibre à trouver entre la collecte de la bonne quantité de journaux détaillés pour le dépannage sans être submergé de données inutiles.

Notions de base sur la journalisation

NGINX fournit deux mécanismes de journalisation différents : la journalisation des accès pour les demandes des clients et la journalisation des erreurs lorsque les choses tournent mal. Ces mécanismes sont disponibles dans les modules HTTP et Stream (TCP/UDP), mais ici nous nous concentrons sur le trafic HTTP. (Il existe également un troisième mécanisme de journalisation qui utilise le niveau de gravité de débogage , mais nous n'en parlerons pas ici.)

Une configuration de journalisation NGINX typique par défaut ressemble à ceci.

http { 
log_format main 
'$remote_addr - $remote_user [$time_local] "$request" '
'$status $body_bytes_sent "$http_referer" '
'"$http_user_agent" "$http_x_forwarded_for"';

access_log /var/log/nginx/access.log main; # Journaliser en utilisant le format 'main'
error_log /var/log/nginx/error.log warn; # Journaliser jusqu'au niveau de gravité 'warn'
...
}

La directive log_format décrit le contenu et la structure des entrées de journal créées lorsque la directive access_log est incluse dans la configuration. L'exemple ci-dessus est une extension du format de journal commun (CLF) utilisé par de nombreux serveurs Web. Avec la directive error_log , vous spécifiez le niveau de gravité des messages à enregistrer, mais pas le contenu ou le format des entrées, qui sont fixes. Plus d’informations à ce sujet dans la section suivante.

D'autres aspects notables de la journalisation NGINX incluent :

• Les directives de journalisation sont automatiquement héritées par les contextes de configuration de niveau inférieur. Par exemple, une directive access_log dans le contexte http est appliquée à tous les blocs server{} .
• Une directive de journalisation dans un contexte enfant remplace les directives héritées.
• Plusieurs directives de journalisation peuvent exister dans le même contexte. Par exemple, deux directives access_log peuvent être utilisées pour créer à la fois un fichier journal CLF standard et un deuxième journal plus détaillé.

La réalité de la journalisation en production

En termes généraux, nous souhaitons utiliser le journal d’accès pour fournir des analyses et des statistiques d’utilisation, et utiliser le journal des erreurs pour la détection des pannes et le dépannage. Mais gérer un système de production est rarement aussi simple. Voici quelques défis courants :

• Les journaux d'accès manquent de détails suffisants pour le dépannage
• Les journaux d'erreurs révèlent de bons détails au niveau de gravité des informations, mais ils sont trop détaillés pour les opérations normales
• Le format du journal des erreurs est fixe et ne peut donc pas être personnalisé pour inclure des variables présentant un intérêt particulier
• Les entrées dans le journal des erreurs n’incluent pas le contexte de la demande et sont difficiles à faire correspondre avec l’entrée du journal d’accès correspondante

De plus, la modification de la configuration NGINX pour ajouter ou supprimer des détails de journalisation dans un environnement de production peut également nécessiter de suivre un processus de contrôle des modifications et de redéployer la configuration. Entièrement sûr, mais quelque peu fastidieux lors du dépannage d'un problème en direct tel que « pourquoi est-ce que je vois un pic de 4xx / 5xx erreurs ?". Cela est bien sûr amplifié lorsque plusieurs instances NGINX gèrent le même trafic sur un cluster.

Utilisation d'un deuxième journal d'accès pour les erreurs

La personnalisation du format du journal d'accès pour enrichir les données collectées pour chaque demande est une approche courante pour des analyses améliorées, mais elle n'est pas adaptée au diagnostic ou au dépannage. Demander au journal d'accès principal d'effectuer deux tâches est une solution artificielle, car nous souhaitons généralement beaucoup plus d'informations pour le dépannage que pour les analyses classiques. L'ajout de nombreuses variables au journal d'accès principal peut augmenter considérablement les volumes de journaux avec des données qui ne sont utiles qu'occasionnellement.

Au lieu de cela, nous pouvons utiliser un deuxième journal d’accès et y écrire uniquement lorsque nous rencontrons une erreur qui justifie un débogage. La directive access_log prend en charge la journalisation conditionnelle avec le paramètre if : les requêtes ne sont enregistrées que lorsque la variable spécifiée est évaluée à une valeur différente de zéro et non vide.

map $status $is_error { 400 1; # Requête incorrecte, y compris le certificat client expiré 495 1; # Erreur de certificat client 502 1; # Passerelle incorrecte (aucun serveur en amont n'a pu être sélectionné) 504 1; # Délai d'expiration de la passerelle (impossible de se connecter au serveur en amont sélectionné) par défaut 0; } access_log /var/log/nginx/access_debug.log access_debug if=$is_error; # Journalisation de diagnostic access_log /var/log/nginx/access_debug.log main;

Avec cette configuration, nous passons la variable $status via un bloc de mappage pour déterminer la valeur de la variable $is_error , qui est ensuite évaluée par le paramètre if de la directive access_log . Lorsque $is_error est évalué à1 nous écrivons une entrée de journal spéciale dans le fichier access_debug.log .

Cependant, cette configuration ne détecte pas les erreurs rencontrées lors du traitement des requêtes qui sont finalement résolues et qui entraînent donc un statut200 D'ACCORD . Un tel exemple est lorsque NGINX équilibre la charge entre plusieurs serveurs en amont. Si une erreur est rencontrée avec le serveur sélectionné, NGINX transmet la requête au serveur suivant dans les conditions configurées par la directive proxy_next_upstream . Tant que l'un des serveurs en amont répond avec succès, le client reçoit une réponse réussie, qui est enregistrée avec le statut200 . Cependant, l’expérience utilisateur risque d’être médiocre en raison des nouvelles tentatives, et il peut ne pas être immédiatement évident qu’un serveur en amont n’est pas sain. Après tout, nous avons enregistré un200 .

Lorsque NGINX tente de se connecter à plusieurs serveurs en amont, leurs adresses sont toutes capturées dans la variable $upstream_addr . Il en va de même pour d’autres variables $upstream_* , par exemple $upstream_status qui capture le code de réponse de chaque serveur tenté. Ainsi, lorsque nous voyons plusieurs entrées dans ces variables, nous savons que quelque chose de grave s’est produit : nous avons probablement un problème avec au moins l’un des serveurs en amont.

Que diriez-vous d'écrire également dans access_debug.log lorsque la demande a été transmise par proxy à plusieurs serveurs en amont ?

map $upstream_status $multi_upstreams { "~," 1; # A une virgule par défaut 0; } map $status $is_error { 400 1; # Requête incorrecte, y compris le certificat client expiré 495 1; # Erreur de certificat client 502 1; # Passerelle incorrecte (aucun serveur en amont n'a pu être sélectionné) 504 1; # Délai d'expiration de la passerelle (impossible de se connecter au serveur en amont sélectionné) par défaut $multi_upstreams; # Si nous avons essayé plus d'un serveur en amont } access_log /var/log/nginx/access_debug.log access_debug if=$is_error; # Journalisation de diagnostic access_log /var/log/nginx/access.log main; # Journalisation régulière

Ici, nous utilisons un autre bloc de carte pour produire une nouvelle variable ( $multi_upstreams ) dont la valeur dépend de la présence d'une virgule ( , ) dans $upstream_status . Une virgule signifie qu'il y a plus d'un code d'état et que, par conséquent, plus d'un serveur en amont a été rencontré. Cette nouvelle variable détermine la valeur de $is_error lorsque $status n'est pas l'un des codes d'erreur répertoriés.

À ce stade, nous avons notre journal d'accès habituel et un fichier access_debug.log spécial qui contient les requêtes erronées, mais nous n'avons pas encore défini le format du journal access_debug . Assurons-nous maintenant que nous disposons de toutes les données dont nous avons besoin dans le fichier access_debug.log pour nous aider à diagnostiquer les problèmes.

Journalisation JSON avec JavaScript

Obtenir des données de diagnostic dans access_debug.log n'est pas difficile. NGINX fournit plus de 100 variables liées au traitement HTTP, et nous pouvons définir une directive log_format spéciale qui capture autant d'entre elles que nécessaire. Cependant, la création d’un format de journal naïf à cette fin présente quelques inconvénients.

• Il s'agit d'un format personnalisé – vous devez former un analyseur de journaux à le lire
• Les entrées peuvent être très longues et difficiles à lire pour les humains lors du dépannage en direct
• Vous devez continuellement vous référer au format du journal afin d'interpréter les entrées
• Il n'est pas possible d'enregistrer des valeurs non déterministes telles que « tous les en-têtes de requête »

Nous pouvons relever ces défis en écrivant des entrées de journal dans un format structuré tel que JSON, en utilisant le module JavaScript NGINX<.htmla> (njs). Le format JSON est également largement pris en charge par les systèmes de traitement de journaux tels que Splunk , LogStash , Graylog et Loggly . En déchargeant la syntaxe log_format sur une fonction JavaScript, nous bénéficions de la syntaxe JSON native, avec accès à toutes les variables NGINX et aux données supplémentaires de l' objet njs ' r ' .

js_import conf.d/json_log.js;js_set $json_debug_log json_log.debugLog;

log_format access_debug escape=none $json_debug_log; # Déchargement vers njs 
access_log /var/log/nginx/access_debug.log access_debug if=$is_error;

La directive js_import spécifie le fichier contenant le code JavaScript et l'importe en tant que module. Le code lui-même peut être trouvé ici . Chaque fois que nous écrivons une entrée de journal d'accès qui utilise le format de journal access_debug , la variable $json_debug_log est évaluée. Cette variable est évaluée en exécutant la fonction JavaScript debugLog telle que définie par la directive js_set .

Cette combinaison de code JavaScript et de configuration NGINX produit des journaux de diagnostic qui ressemblent à ceci.

$ tail --lines=1 /var/log/nginx/access_debug.log | jq { "horodatage": "2020-09-21T11:25:55+00:00", "connexion": { "request_count": 1, « temps_écoulé » : 0.555, "pipelined": false, "ssl": { "protocole": « TLSv1.2 », « chiffrement » : "ECDHE-RSA-AES256-GCM-SHA384", "session_id": "b302f76a70dfec92f6bd72de5732692481ebecbbc69a4d81c900ae4dc928485c", "session_reused": false, "client_cert": { "status": "AUCUN" } } }, "requête": { "client": "127.0.0.1", "port": 443, "hôte": "foo.example.com", "méthode": "GET", "uri": "/one", "http_version": 1.1, « octets_reçus » : 87, "headers": { "Hôte": "foo.example.com:443", "Agent utilisateur": "curl/7.64.1", "Accepter": "*/*" } }, "upstreams": [ { "server_addr": "10.37.0.71", "port_serveur": 443, « connect_time » : nul, « header_time » : nul, « response_time » : 0,551, « octets_envoyés » : 0, « octets_reçus » : 0, « statut » : 504 }, { "adresse_serveur": "10.37.0.72", "port_serveur": 443, « connect_time » : 0,004, « header_time » : 0,004, « temps_de_réponse » : 0,004, « octets_envoyés » : 92, « octets_reçus » : 4161, « statut » : 200 } ], "réponse": { "statut": 200, « octets_envoyés » : 186, "en-têtes": { "Type de contenu": "texte/html", "Longueur du contenu": "4161" } } }

Le format JSON nous permet d'avoir des objets séparés pour les informations relatives à la connexion HTTP globale (y compris SSL/TLS), à la demande, aux flux en amont et à la réponse. Notez comment le premier amont (10.37.0.71) a renvoyé le statut 504( Délai d'expiration de la passerelle) avant que NGINX n'essaie la connexion en amont suivante (10.37.0.72), qui a répondu avec succès. Le délai d'attente d'une demi-seconde (signalé comme response_time dans le premier élément de l'objet upstreams ) représente la majeure partie de la latence globale de cette réponse réussie (signalée comme elapsed_time dans l'objet connection ).

Voici un autre exemple d'entrée de journal (tronquée), pour une erreur client causée par un certificat client expiré.

{ 
"horodatage": "2020-09-22T10:20:50+00:00",
"connexion": {
"ssl": {
"protocole": "TLSv1.2",
"chiffrement" : "ECDHE-RSA-AES256-GCM-SHA384",
"session_id": "30711efbe047c38a98c2209cc4b5f196988dcf2d7f1f2c269fde7269c370432e",
"session_reused": false,
"client_cert": {
"status": "ÉCHEC : le certificat a expiré",
"serial": "1006",
"empreinte digitale" : "0c47cc4bd0fefbc2ac6363345cfbbf295594fe8d",
"subject": "emailAddress=liam@nginx.com,CN=test01,OU=Demo CA,O=nginx,ST=CA,C=US",
"issuer": "CN=CA intermédiaire de démonstration,OU=CA de démonstration,O=nginx,ST=CA,C=US",
"démarre" : "20 septembre 12:00:11 2019 GMT",
"expire" : "20 sept. 12:00:11 2020 GMT",
"expiré" : vrai,
...
"réponse" : {
"statut" : 400,
"octets_envoyés": 283,
"en-têtes": {
"Type de contenu": "texte/html",
"Longueur du contenu": "215"
}
}

Résumé

En générant des données de diagnostic riches uniquement lorsque nous rencontrons une erreur, nous permettons un dépannage en temps réel sans avoir à effectuer de reconfiguration. Les requêtes réussies ne sont pas impactées car le code JavaScript s'exécute uniquement lorsque nous détectons une erreur lors de la phase de journalisation, après l'envoi du dernier octet au client.

La configuration complète est disponible sur GitHub – pourquoi ne pas l’essayer dans votre environnement ? Si vous n'utilisez pas encore NGINX Plus, démarrez un essai gratuit de 30 jours dès aujourd'hui ou contactez-nous pour discuter de vos cas d'utilisation .