Journalisation de diagnostic avec le module JavaScript NGINX

Liam CrillyDirecteur senior de la gestion des produits

Résolution des problèmes en production sans ajuster le journal des erreurs

Éditeur – Cet article de blog fait partie d’une série consacrée à la journalisation avec NGINX et NGINX Plus. Consultez également :

• Traçage des applications avec NGINX et NGINX Plus
• Échantillonnage des requêtes avec la journalisation conditionnelle de NGINX

Il fait également partie des nombreux articles de blog consacrés aux cas d’utilisation du module JavaScript de NGINX. Pour consulter la liste complète, voir « Cas d’utilisation du module JavaScript de NGINX ».

NGINX aide les organisations de toutes tailles à exploiter leurs sites web, applications et API stratégiques. Quels que soient votre taille et votre choix d’infrastructure de déploiement, l’exploitation en production n’est pas chose aisée. Dans cet article, nous abordons l’une des difficultés liées à un déploiement en production : la journalisation. Plus précisément, nous expliquons comment trouver le juste équilibre entre la collecte de journaux suffisamment détaillés pour résoudre les problèmes et le risque d’être submergé par des données inutiles.

Principes de base de la journalisation

NGINX propose deux mécanismes de journalisation distincts : la journalisation des accès pour les requêtes des clients et la journalisation des erreurs en cas de problème. Ces mécanismes sont disponibles dans les modules HTTP et Stream (TCP/UDP), mais nous nous concentrerons ici sur le trafic HTTP. (Il existe également un troisième mécanisme de journalisation qui utilise le niveau de sévérité de débogage, mais nous ne l’aborderons pas ici.)

Voici à quoi ressemble une configuration de journalisation NGINX classique par défaut.

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; # Log using the 'main' format
    error_log  /var/log/nginx/error.log  warn; # Log up to 'warn' severity level
    ...
}

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 Common Log Format (CLF) utilisé par de nombreux serveurs web. Avec la directive « error_log », vous spécifiez le niveau de gravité des messages à consigner, mais pas le contenu ni le format des entrées, qui sont fixes. Nous y reviendrons dans la section suivante.

Parmi les autres aspects notables de la journalisation NGINX, citons :

• Les directives de journalisation sont automatiquement héritées par les contextes de configuration de niveau inférieur. Par exemple, une directive « access_log » définie dans le contexte « http » s’applique à tous les blocs « server{} ».
• Une directive de journalisation définie dans un contexte enfant remplace les directives héritées.
• Plusieurs directives de journalisation peuvent coexister dans un 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 second journal plus détaillé.

La réalité de la journalisation en production

De manière générale, nous souhaitons utiliser le journal des accès pour obtenir des données d’analyse et des statistiques d’utilisation, et le journal des erreurs pour détecter les défaillances et résoudre les problèmes. Mais l’exploitation d’un système en production est rarement aussi simple. Voici quelques difficultés courantes :

• Les journaux d’accès ne contiennent pas suffisamment de détails pour résoudre les problèmes
• Les journaux d’erreurs fournissent un bon niveau de détail au niveau de sévérité info, mais celui-ci est trop verbeux pour les opérations courantes
• Le format des journaux d’erreurs est fixe et ne peut donc pas être personnalisé pour inclure des variables présentant un intérêt particulier
• Les entrées du journal des erreurs n’incluent pas le contexte de la requête et sont difficiles à associer à l’entrée correspondante du journal des accès.

De plus, modifier la configuration de NGINX pour ajouter ou supprimer des détails de journalisation dans un environnement de production peut également nécessiter de suivre un processus de gestion des changements et de redéployer la configuration. Cette opération est parfaitement sûre, mais quelque peu fastidieuse lorsqu’il s’agit de diagnostiquer un problème en cours, tel que : « Pourquoi est-ce que je constate une hausse des erreurs 4xx/5xx ? » Ce phénomène est bien entendu amplifié lorsque plusieurs instances NGINX traitent le même trafic au sein d’un cluster.

Utiliser un second journal d’accès pour les erreurs

Personnaliser le format du journal d’accès afin d’enrichir les données collectées pour chaque requête est une approche courante pour bénéficier d’analyses plus poussées, mais elle s’adapte mal aux besoins de diagnostic ou de dépannage. Faire remplir deux fonctions au journal d’accès principal est une solution artificielle, car le dépannage nécessite généralement beaucoup plus d’informations que les analyses courantes. L’ajout de nombreuses variables au journal d’accès principal peut considérablement augmenter le volume des journaux avec des données qui ne sont utiles qu’occasionnellement.

Nous pouvons plutôt utiliser un second journal d’accès et n’y consigner les requêtes que lorsqu’une erreur nécessitant un débogage se produit. La directive access_log prend en charge la journalisation conditionnelle avec le paramètre if : les requêtes ne sont consignées que lorsque la variable spécifiée renvoie une valeur non nulle et non vide.

map $status $is_error {    
    400     1; # Bad request, including expired client cert
    495     1; # Client cert error
    502     1; # Bad gateway (no upstream server could be selected)
    504     1; # Gateway timeout (couldn't connect to selected upstream)
    default 0;
}

access_log /var/log/nginx/access_debug.log access_debug if=$is_error; # Diagnostic logging
access_log /var/log/nginx/access.log main;

Avec cette configuration, nous transmettons la variable « $status » à un bloc « map » afin de déterminer la valeur de la variable « $is_error », qui est ensuite évaluée par le paramètre « access_log » de la directive « if ». Lorsque « $is_error » vaut « 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 pendant le traitement de la requête lorsqu’elles sont finalement résolues et aboutissent donc à l’état 200 OK. Cela peut notamment se produire lorsque NGINX répartit la charge entre plusieurs serveurs en amont. Si une erreur survient avec le serveur sélectionné, NGINX transmet la requête au serveur suivant selon les conditions configurées par la directive proxy_next_upstream. Dès lors que l’un des serveurs en amont répond correctement, le client reçoit une réponse positive, qui est consignée avec l’état 200. Toutefois, les nouvelles tentatives risquent de dégrader l’expérience utilisateur, et il peut être difficile de constater immédiatement qu’un serveur en amont est défaillant. Après tout, nous avons consigné un état 200.

Lorsque NGINX tente de transmettre une requête à plusieurs serveurs en amont via un proxy, toutes leurs adresses sont enregistrées dans la variable $upstream_addr. Il en va de même pour les autres variables $upstream_*, par exemple $upstream_status, qui enregistre le code de réponse de chaque serveur sollicité. Ainsi, lorsque ces variables contiennent plusieurs entrées, nous savons qu’un problème est survenu : au moins l’un des serveurs en amont est probablement défaillant.

Et si nous écrivions également dans access_debug.log lorsque la requête a été transmise à plusieurs serveurs en amont ?

map $upstream_status $multi_upstreams {    
"~,"    1; # Has a comma
    default 0;
} 

map $status $is_error {
    400     1; # Bad request, including expired client cert
    495     1; # Client cert error
    502     1; # Bad gateway (no upstream server could be selected)
    504     1; # Gateway timeout (couldn't connect to selected upstream)
    default $multi_upstreams; # If we tried more than one upstream server
}

access_log /var/log/nginx/access_debug.log access_debug if=$is_error; # Diagnostic logging
access_log /var/log/nginx/access.log main; # Regular logging

Ici, nous utilisons un autre bloc « map » pour créer une nouvelle variable ($multi_upstreams) dont la valeur dépend de la présence d’une virgule (,) dans $upstream_status. Une virgule indique qu’il existe plusieurs codes d’état et que plusieurs serveurs en amont ont donc été sollicités. Cette nouvelle variable détermine la valeur de $is_error lorsque $status ne correspond à aucun des codes d’erreur répertoriés.

À ce stade, nous disposons de notre journal d’accès habituel et d’un fichier spécial access_debug.log qui contient les requêtes ayant généré des erreurs, mais nous n’avons pas encore défini le format de journalisation access_debug. Assurons-nous maintenant que le fichier access_debug.log contient toutes les données nécessaires pour nous aider à diagnostiquer les problèmes.

Journalisation JSON avec JavaScript

Il n’est pas difficile d’enregistrer les données de diagnostic dans access_debug.log. NGINX fournit plus de 100 variables liées au traitement HTTP, et nous pouvons définir une directive log_format spécifique qui enregistre autant de ces variables que nécessaire. Toutefois, la création d’un format de journalisation rudimentaire à cette fin présente quelques inconvénients.

• Il s’agit d’un format personnalisé : vous devez apprendre à un analyseur de journaux à l’interpréter.
• Les entrées peuvent être très longues et difficiles à lire lors d’un dépannage en temps réel
• Vous devez constamment vous référer au format des journaux pour interpréter les entrées
• Il n’est pas possible de journaliser des valeurs non déterministes telles que « tous les en-têtes de requête »

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

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

log_format access_debug escape=none $json_debug_log; # Offload to 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 est disponible ici. Chaque fois que nous écrivons une entrée dans le journal d’accès qui utilise le format de journalisation « access_debug », la variable « $json_debug_log » est évaluée. Cette variable est évaluée en exécutant la fonction JavaScript « debugLog », comme défini par la directive « js_set ».

Cette combinaison de code JavaScript et de configuration NGINX produit des journaux de diagnostic qui se présentent comme suit.

$ tail --lines=1 /var/log/nginx/access_debug.log | jq{
   "timestamp": "2020-09-21T11:25:55+00:00",
   "connection": {
      "request_count": 1,
      "elapsed_time": 0.555,
      "pipelined": false,
      "ssl": {
         "protocol": "TLSv1.2",
         "cipher": "ECDHE-RSA-AES256-GCM-SHA384",
         "session_id": "b302f76a70dfec92f6bd72de5732692481ebecbbc69a4d81c900ae4dc928485c",
         "session_reused": false,
         "client_cert": {
            "status": "NONE"
         }
      }
   },
   "request": {
      "client": "127.0.0.1",
      "port": 443,
      "host": "foo.example.com",
      "method": "GET",
      "uri": "/one",
      "http_version": 1.1,
      "bytes_received": 87,
      "headers": {
         "Host": "foo.example.com:443",
         "User-Agent": "curl/7.64.1",
         "Accept": "*/*"
      }
   },
   "upstreams": [
      {
         "server_addr": "10.37.0.71",
         "server_port": 443,
         "connect_time": null,
         "header_time": null,
         "response_time": 0.551,
         "bytes_sent": 0,
         "bytes_received": 0,
         "status": 504
      },
      {
         "server_addr": "10.37.0.72",
         "server_port": 443,
         "connect_time": 0.004,
         "header_time": 0.004,
         "response_time": 0.004,
         "bytes_sent": 92,
         "bytes_received": 4161,
         "status": 200
      }
   ],
   "response": {
      "status": 200,
      "bytes_sent": 186,
      "headers": {
         "Content-Type": "text/html",
         "Content-Length": "4161"
      }
   }
}

Le format JSON nous permet d’utiliser des objets distincts pour les informations relatives à la connexion HTTP globale (y compris SSL/TLS), à la requête, aux serveurs en amont et à la réponse. Notez que le premier serveur en amont (10.37.0.71) a renvoyé le statut 504 (Gateway Timeout) avant que NGINX n’essaie le serveur en amont suivant (10.37.0.72), qui a répondu avec succès. Le délai d’expiration d’une demi-seconde (indiqué par response_time dans le premier élément de l’objet upstreams) représente l’essentiel de la latence globale de cette réponse réussie (indiquée par elapsed_time dans l’objet connection).

Voici un autre exemple d’entrée de journal (tronquée), correspondant à une erreur client causée par l’expiration d’un certificat client.

{   
"timestamp": "2020-09-22T10:20:50+00:00",
   "connection": {
      "ssl": {
         "protocol": "TLSv1.2",
         "cipher": "ECDHE-RSA-AES256-GCM-SHA384",
         "session_id": "30711efbe047c38a98c2209cc4b5f196988dcf2d7f1f2c269fde7269c370432e",
         "session_reused": false,
         "client_cert": {
            "status": "FAILED:certificate has expired",
            "serial": "1006",
            "fingerprint": "0c47cc4bd0fefbc2ac6363345cfbbf295594fe8d",
            "subject": "emailAddress=liam@nginx.com,CN=test01,OU=Demo CA,O=nginx,ST=CA,C=US",
            "issuer": "CN=Demo Intermediate CA,OU=Demo CA,O=nginx,ST=CA,C=US",
            "starts": "Sep 20 12:00:11 2019 GMT",
            "expires": "Sep 20 12:00:11 2020 GMT",
            "expired": true,
         ...
   "response": {
      "status": 400,
      "bytes_sent": 283,
      "headers": {
      "Content-Type": "text/html",
      "Content-Length": "215"
   }
}

Résumé

En générant des données de diagnostic détaillées uniquement lorsqu’une erreur se produit, nous permettons un dépannage en temps réel sans qu’aucune reconfiguration soit nécessaire. Les requêtes traitées avec succès ne sont pas affectées, car le code JavaScript ne s’exécute que lorsqu’une erreur est détectée 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, commencez dès aujourd’hui un essai gratuit de 30 jours ou contactez-nous pour discuter de vos cas d’utilisation.

À propos de l’auteur

Liam CrillyDirecteur senior de la gestion des produits

Autres articles de Liam Crilly