Les logs à la rescousse

Nous utilisons le monitoring des performances des applications (APM) de New Relic pour monitorer et régler nos propres services. L'APM rassemble les métriques et les traces pertinentes pour identifier et diagnostiquer les problèmes de service. Mais malheureusement, même pour nous, il est impossible d’instrumenter tout ce que nous voulons savoir à l’avance. Si l’ajout de l'instrumentation pour une enquête ou après un incident est une bonne pratique, que se passe-t-il si vous souhaitez résoudre le problème immédiatement avec les données déjà à votre disposition ?

Les logs à la rescousse !

Pourquoi les logs sont‑ils si formidables ?

Le plus ancien format de télémétrie est peut-être du texte non structuré écrit dans un fichier. Les programmes sortent du texte depuis les débuts de l’informatique moderne. Cette omniprésence est le premier super‑pouvoir des logs. Même lorsque d'autres informations font défaut, il y a de fortes chances que quelqu'un ait émis un log indiquant ce qui se passe.

Le logging est devenu tellement courant que les bibliothèques standard de nombreux langages intègrent directement sa prise en charge. Les écosystèmes sans enregistreur standard ont presque toujours des alternatives tierces robustes et flexibles. En outre, de nombreux outils existent pour formater, contrôler et capturer les logs et aider à leur interprétation sur tout le stack.

Qu'y a-t-il de moins formidable dans les logs ?

Le manque de structure constitue le point de friction des logs en tant que type de télémétrie. En raison de leur importante base textuelle, les logs peuvent ressembler à un fourre-tout, ou tout est mélangé sans aucune logique. Comparés au sens clair d'une valeur de métrique ou au schéma et relations bien connus pour les spans de traces, les logs sont compliqués.

Ce qui complique encore le manque de structure, c'est que vous ne contrôlez peut-être pas le formatage des logs qui vous intéressent le plus. Qu'il s'agisse de votre serveur web ou de votre prestataire cloud, une partie de ces résultats critiques peut consister à « prendre ce que vous pouvez » en matière de formatage et de contenu.

Les logs peuvent également être énormes. La facilité avec laquelle ils sont générés se traduit par la possibilité que chaque niveau du stack peut déchaîner un torrent de texte. Si vous n'êtes pas vigilant, certains logs de débogage peuvent même provoquer des problèmes avec les applications locales lorsque les disques manquent d'espace. L’ingestion, le stockage et l’interrogation d’un énorme volume de données peuvent constituer un véritable défi.

Comment utiliser les logs plus efficacement ?

Compte tenu de ces forces et de ces faiblesses, comment pouvez-vous améliorer votre activité de logging et tirer le meilleur parti de ce vénérable type de données ? Nous allons examiner quelques fonctionnalités du logging de New Relic qui mettent en évidence la façon dont les logs peuvent vous donner des informations précieuses au-delà de l'instrumentation classique que nous connaissons et aimons tous.

Logging structuré

J'ai comparé les logs à un fourre-tout encombré. Mais rien ne dit que votre fourre-tout doit être en désordonné. Si les logs proviennent d'une application que vous contrôlez, vous pouvez profiter du logging structuré pour mettre de l'ordre au chaos.

Dans la forme la plus courante, nous apportons de la clarté à nos logs en émettant des données JSON au lieu de lignes de texte brut. Ce JSON peut avoir des attributs standards pour aider les processeurs ultérieurs. Ainsi, au lieu d'avoir un log comme celui-ci :

Vous pouvez obtenir toute cette richesse en comprenant ce qui s’est passé après coup :

Souvent, ce formatage de log peut s'intégrer à votre infrastructure web, de sorte que vous n'avez même pas besoin de paramétrer des valeurs supplémentaires ni de créer le JSON directement vous-même. De bons exemples de cela avec Rails sont lograge et semantic_logger.

Association des logs à d'autres données

La possibilité d'ajouter de la structure et du sens à nos logs facilite désormais la façon dont nous les utilisons dans un système centralisé, qu'il s'agisse d'un stack ELK (Elasticsearch, Logstash et Kibana) sur site ou d'un fournisseur SaaS comme New Relic. Pour les développeurs d'applications, le filtrage des logs de leur application est la première étape pour trouver ces aiguilles dans la botte de foin.

Les agents de New Relic APM proposent tous des fonctionnalités intégrées de transfert de logs qui ajoutent automatiquement des métadonnées pour connecter non seulement l'application, mais également les traces et les étendues (c'est-à-dire les requêtes individuelles dans votre système). Grâce à cela, vous pouvez voir, par exemple, les logs qui se sont produits parallèlement à une trace d'erreur spécifique.

Si la trace du stack et les autres propriétés de l'erreur ne vous donnent pas toutes les informations nécessaires, les logs que vous avez à portée de main peuvent vous les fournir.

Les organisations ne souhaitent pas toutes utiliser le transfert des logs par l'agent APM ; par exemple, il est possible que vous disposiez déjà d'un redirecteur configuré dans votre cluster Kubernetes ou avec un serveur Syslog centralisé. Même si une solution autre que l'agent APM redirige vos logs, vous pouvez toujours profiter de cette connexion riche entre les logs et l'APM via l'option d'amélioration locale, Local decoration. Lorsqu'elle est activée, cette option modifie les logs écrits pour qu'ils contiennent les métadonnées nécessaires afin que vous ayez le plaisir et l'avantage de voir vos logs connectés dans l'interface utilisateur de New Relic.

Analyse des logs

Mais que se passe-t-il si vos logs ne sont pas au format JSON et contiennent des numéros utiles enfouis dans le texte ? Par exemple, certaines de nos applications Java ont des classes de « service » internes avec leur propre système de cycle de vie qui enregistre les messages comme celui-ci :

Ces informations de synchronisation imprimées à la toute fin de la ligne constitueraient une métrique ou un événement intéressant, mais l'information est enfouie dans les messages du log uniquement. Toutefois, nous pouvons toujours rechercher ce dont nous avons besoin avec une requête.

Dans ce cas, nous commençons par trouver les lignes qui nous intéressent via l'interface de logging, ce qui facilite la recherche sur des mots-clés et des paires de valeurs d'attributs de base. À côté du bouton « Query logs » se trouve le bouton « NRQL ». C'est là que se trouve le véritable pouvoir. Cliquez dessus pour ouvrir le générateur de requêtes. Vous y trouvez le langage de requêtes New Relic (NRQL) qui a été utilisé pour rechercher l'ensemble de logs actuel :

Puisque le filtre appliqué sélectionne les messages qui nous intéressent, il est possible de séparer le texte du message avec l'une des fonctions NRQL les plus récentes, aparse. Je ne vais pas répéter ce qui se trouve dans la documentation, mais pour le message ci-dessus, nous pouvons utiliser aparse de cette façon pour extraire nos informations sur le timing :

Parfait ! Cela nous donne maintenant un attribut dans notre résultat nommé startupDuration. Nous aimerions également obtenir le nom de la classe. Pour ce faire, associons aparse à un bloc WITH :

Nous voyons maintenant un tableau avec les services et leur timing. Voyons si l'on peut l'utiliser pour faire quelques calculs ! Nous allons regrouper par service et faire la moyenne de startupDuration pour voir les performances de chaque classe :

Malheureusement, la colonne de droite ne donne aucune moyenne. Pourquoi ? Rappelez-vous que nous sommes au pays des logs où tout est texte ! Heureusement, un appel de fonction rapide peut résoudre ce problème pour nous.

Pour une utilisation à long terme, il serait bon d'enregistrer ces données en tant que véritable métrique directement dans l'application, ou via la fonctionnalité events-to-metric de New Relic. Autre possibilité : nous pouvons créer une règle d'analyse syntaxique qui extrait la valeur de son propre attribut lorsque les données sont ingérées, ce qui facilitera les requêtes plus tard.

Quelle que soit l'option choisie, nous pouvons faire notre travail dès aujourd’hui avec les logs que nous avons déjà. Et comme ces logs ne sont qu'un groupe de données supplémentaire dans NRDB, nous pouvons utiliser ces résultats dans d'autres parties de New Relic, telles que les alertes, les dashboards ou l'élaboration des SLO.

Corrélation des logs dans le temps

Une dernière astuce pour vous donner une idée du pouvoir que vous confèrent les logs arbitraires et NRQL. Supposons que, comme plus haut, nous nous intéressons au temps pris par le démarrage de notre application. Mais cette fois, nous n'avons aucune ligne avec des horaires bien intégrés. Au lieu de cela, nous avons deux lignes entre lesquelles nous aimerions obtenir l'intervalle de temps ; une où l'application a démarré, puis une autre plus tard lorsque le trafic a commencé à arriver.

Pour rendre cela plus concret, prenons un exemple donné par l'équipe Logging de New Relic elle-même ! Lorsque notre service d'ingestion principal démarre, nous obtenons deux lignes différentes :

• La première, starting log-parser-consumer, indique que l'application Java a démarré.
• La seconde appelle le nom de classe de notre client, Kafka (LogsToParseKafkaConsumerAutoService) et nous indique qu'elle est en cours d'exécution.

Pour commencer, nous allons créer une requête pour trouver ces lignes respectives et rien d'autre. Cela semble correct :

Ensuite, nous avons besoin d’un groupe de données unique sur lequel nous appuyer, quelque chose de différent pour chaque démarrage d’application. New Relic utilise une journalisation structurée et nous obtenons un pod_name unique, parfait à cet effet. La requête suivante vise à afficher les deux messages qui nous intéressent regroupés par pod. Une colonne contient le message de début et l'autre le message de fin :

Nous pouvons confirmer que cela correspond à ce que nous recherchons et nous obtenons les deux lignes côte à côte pour chaque pod_name :

Vous n'avez peut-être pas encore vu la fonction latest dans NRQL. Il s'agit d'une fonction d'agrégation qui fait exactement ce que son nom indique : elle prend la toute dernière valeur du dataset. Ici, nous extrayons le message , mais après avoir confirmé qu'il fonctionne, ce que nous voulons vraiment, c'est le tout dernier horodatage, latest(timestamp). Avec cela, nous pouvons faire le calcul sur les heures de début et de fin et, voilà, nous avons des données de synchronisation entre deux points arbitraires dans notre flux de logs !

Conclusion

Si vous cherchez à mesurer quelque chose de numérique, votre meilleur atout peut être une métrique. Mais s’il ne vous reste que des logs, ne désespérez pas ! Dans l'équipe Logging de New Relic, nous avons eu plusieurs fois recours aux astuces ci-dessus pour trouver les nouvelles données de performance que nous souhaitions suivre, pour localiser facilement la source des erreurs et pour améliorer les alertes et le monitoring. Vos logs peuvent vous apporter une nouvelle visibilité sur votre système, alors lancez-vous dans le logging !