Les katas-logs contre les cata-logs

Les logs ou évènements journalisés ont longtemps eu un usage restreint et sans réel valeur métier.
Avec l’arrivée de nouveaux outils, les logs répondent à des besoins de plus en plus variés et de plus en plus valorisés par les entreprises.

Les journaux applicatifs gardent évidemment leur rôle de détection d’erreurs, leur rôle d’historisation et leur utilité de déverminage mais ils gagnent de nouveaux usages pouvant être grandement valorisés suivant la maturité des entreprises dans ce domaine :

• Monitoring fin pour une exploitation sereine des services informatiques
• Usages « façon » BI pour un usage d’analyse métier
• Surveillance des accès et gestion de la sécurité
• Anticipations métier automatiques calculées sur des bases statistiques à partir des journaux déjà émis par les utilisateurs d’applications (Apprentissage machine)

Bien sûr, la multiplicité des outils disponibles ou la diversité des architectures modernes, microservices, nuages, webservices…, amènent des problématiques qu’il faut apprendre à gérer :

• Prolifération du volume des journaux applicatifs (augmentation des coûts de stockage, impact environnemental : électricité consommé, stockage, coût en bande passante, …)
• Augmentation des temps de rétention souhaités (augmentation des coûts de stockage)
• Obligation d’ajouter des infrastructures de traitement des logs (augmentation des coûts d’infrastructure et augmenation des compétences nécessaires):

1. Outils de centralisation
2. Outils de collecte et de traiement des logs
3. Outils d’apprentissage machine

• Augmentation de la complexité des architectures et donc du suivi des parcours utilisateurs
• Augmentation des risques de perturbation des applicatifs (impact sur les performances, sur l’espace disque disponible, la bande passante réseau …)

Le sujet de cet article est donc de proposer quelques pistes importantes pour permettre de vivre bien ces modifications d’usage selon plusieurs axes.

Axe des coûts (stockage, bande passante, compétences, outillages, ressources systèmes,…)

Les disques, l’électicité, l’infrastructure réseau et les compétences nécessaires à leur exploitation coûtent cher.
Une bonne pratique, qui tombe pourtant sous le sens et qui est souvent peu prise en compte dans la réalité, consiste tout simplement à ne journaliser que ce qui est nécessaire pour répondre aux besoins de l’entreprise. Il convient donc de se poser chaque fois les bonnes questions:

• A quoi vont servir ces journaux ?
• Historique pour déverninage ?
• Archivage légal ?
• Analyses d’informations métier ?
• Détection de problèmes de sécurité ?
• …

Pour chaque usage : – Quel public cible ? Humain ? Machine/Script ? Les deux ? – Quel niveau d’information ? Erreurs détaillées, informations services métier utilisés, informations techniques, … – Quelle durée de conservation ? – Archivage ? Sous quel protocol ? – Centralisation nécessaire ? – Anonymisation/Cryptage nécessaire ? – Signature nécessaire ? – …

Exemple de matrice de questionnement

 
On comprends donc que le coût varie grandement par usage et que certains journaux peuvent même être dupliqués, ajoutant encore au coût global du système de journalisation du système d’information…
Une fois ces questions posées et les réponses connues, il convient donc d’évaluer le coût de la journalisation par usage pour permettre de péparer les politiques d’achat, de recrutement, de rotation, de supression et d’archivage des logs, …

• Combien coûtent vos journeaux locaux de déverminage ?
• Combien coûtent vos journeaux d’intelligence métier ?
• …

Axe des parcours utilisateurs et de l’intelligence métier

Pour être capable d’analyser le métier et plus particulièrement les parcours utilisateurs, il est indispensable de se donner des moyens de corrélation adaptés.
Dans des environnements hautement asynchrones (Ajax, webservices, évènements,…) et hautement distribués, ajouter l’utilisateur à un évènement de journal n’est pas suffisant. De même, le timestamp de l’évènement n’est d’aucun secours… car changeant de sous-système en sous-système…
On notera au passage qu’un temps synchronisé, NTP, est obligatoire sur l’ensemble des serveurs qui émettent des journaux pour pouvoir les corréler un minimum et agréger des logs de différentes sources tout en étant capable de lier des évènements indépendants tout en conservant leur chronologie d’apparition.
Il faut donc ajouter une information de corrélation de requête qui doit forcément être journalisée grâce au MDC mais dont le lieu de génération peut être initié à plusieurs endroits.

Le principe

Le premier composant d’infrastucture(CI) en interaction avec l’utilisateur, détecté par l’absence d’identifiant de requête déjà généré, doit générer un identifiant de requête suffisament unique pour avoir très peu de chance d’entrer en collision avec un autre évènement et suffisemment décentralisé pour éviter les points de panne ou de contention lors de sa génération (Exemple à éviter : séquence partagée).
Un UUID généré par exemple grâce à la classe java.util.UUID ou encore grâce au binaire uuidgen sous Linux est un très bon candidat pour ce besoin et consomme finalement peu de ressources système.
Cet identifiant de correlation est alors ajouté au MDC de l’utilisateur pour être journalisé avec tout évènement applicatif.
Tous les appels vers les sous-sytèmes doivent contenir cet identifiant de requête pour que celui-ci sache le détecter et le propager.
Le lieu de génération peut se faire en divers endroits dont voici deux exemples classiques:

1. Dans le code d’une servlet par génération/récupération d’identifiant de requête pour ajout au MDC de la requête en cours puis transmission dans les headers des connexions vers les sous-systèmes
2. Dans un reverse proxy utilisé pour la répartition de charge par la détection ou l’ajout d’un header spécifique qui sera recupéré dans une servlet pour alimenter le MDC de la requête cours puis transmissions sur tous les appels aux sous-systèmes.

Les seuls problèmes à cette transmission peuvent être les composants d’infrastructure de type boîte noire avec un code souvent propriétaire… il vous faudra alors adapter selon les cas le mode de transmission de l’identifiant de requête si même possible …

Axe de découverte des dépendances fonctionalités/infrastructure

Si nous avons vu qu’il est nécessaire d’avoir un identifiant de correlation de requête pour avoir de l’intelligence métier, il peut également être très utile de posséder de tels identifiants pour pouvoir dresser une carte des dépendances des composants d’infrastructure activés par chaque fonctionnalité proposée à l’utilisateur. Ceci à des fins d’intelligence métier ou bien pour acquérir la maîtrise technique de la dynamique de son infrastrucure.
Vous est-il arrivé de vous poser les questions suivantes :

• Quels sont les composants techniques qui permettent de répondre au besoin B ?
• Si les composants C et D tombent en panne, quels fonctionnalités puis-je encore rendre à mes utilisateurs ?
• Quels scénraii de test dois-je utiliser pour simuler une charge maximale pour mes tests de charge ?
• Combien de messages sortants du composant C pour répondre à la fonctionalité F ?
• …

Si c’est le cas, on voit que deux informations supplémentaires sont nécessaires en plus de l’identifiant de requête : 1. Quel service est rendu 2. Par qui, au sens de composant d’infrastructue, est rendu ce service
On notera comme pour l’identifiant de requête que ce type d’information est également très utile pour débugger si le SI fonctionne principalement à l’aide de services distribués, webservices, micro-services, … et que l’on souaite rassembler tout ceci en un seul endroit.

Axe des impacts applicatifs ou d’infrastructure

On l’a vu, les journaux amènent des coûts et des complexités techniques pour leur centralisation.
On l’a vu également, les patterns de génération des évènements de journalisation doivent contenir plusieurs informations pour aider à l’utilisation effective des divers journaux générés par le système d’information.
Mais quel est l’impact des logs sur les applicatifs ou l’infrastructure ?
Peuvent-il générer des pannes ou des lenteurs dans l’exécution des services que je souhaite rendre à mes utilisateurs ?
Bien sûr, toutes les réponses ne seront pas dans cet article mais voici quelques mesures de performances pour des cas d’usage différents et qui montrent que journaliser n’importe quoi, parfois n’importe comment peut grandement nuire à la santé de votre système d’information, de votre porte monnaie ou de votre utilisateur qui va vous en vouloir pour les lenteurs de votre application…

Description des cas de test

Ces tests ont pour but de suivre le fonctionnement du système lorsque l’on souhaite logger **300 000** messages. Ils jouent sur les paramètres des **patterns log4J2**, **logback** ou bien sur la bufferisation des fichiers pour mesurer les différents impacts sur les ressources :

• Cpu
• Mémoire
• Messages/s
• Taille disque

Temps global de traitement Différentes configurations testées sur un File appender

Système d’exploitation ayant servi aux tests

-Computer-

• Processor : 4x Intel(R) Core(TM) i5-6200U CPU @ 2.30GHz
• Memory : 8086MB (2886MB used)
• Operating System : Ubuntu 16.04 LTS

-Display-

• Resolution : 1920×1080 pixels
• OpenGL Renderer : Mesa DRI Intel(R) HD Graphics 520 (Skylake GT2)
• X11 Vendor : The X.Org Foundation

-Multimedia-

• Audio Adapter : HDA-Intel – HDA Intel PCH

-SCSI Disks-

• ATA : Disque SSD 512Go

Résultats globaux

Premières conclusions

• Les patterns qui réduisent énormément le nombre de messages émis/seconde sont les éléments de traçabilité du code : %c{1}:%M:%L (Cas 1 vs Cas 2)
• Le timestamp sous forme d’epoch time en millisecondes réduit la taille disque occupée. De plus, au niveau des usages, un epoch time permet de mixer plus facilement des logs différents, de les traiter avec des outils comme awk ou excel (Cas 3 vs Cas 6)
• Un environnement multithread réduit le nombre de messages émis par rapport à un environnement monothread (Cas 6 vs Cas 9)
• Les logs d’exceptions avec stack traces sont très coûteux en nombre de messages émis/seconde mais aussi en place disque. Le cas 11 montre que l’on peut faire un résumé des exceptions pour – regagner en nombre de messages émis/seconde et en place disque (Cas 10 vs Cas 11). Un conseil avisé pourrait être de séparer les logs d’exceptions dans un journal à part et de ne pas utiliser un temps de rétention trop long pour éviter la consommation excessives de ressources système et ne pas perturber les autres applications.
• Les différence entre log4j2 et logback sont minimes et le mode gcfree est peu impactant si les patterns gourmands sont déjà écartés. Exception au cas 12 où les logs paramétrés sont moins coûteux en mode non gcfree.

Conclusions supplémentaires

• La comparaison des cas 1, 7 et 8 permet de voir que la désactivation du buffer à quelques conséquences négatives sur le cpu et aucune sur la mémoire. Le doublement du buffer n’a quasiment aucun effet sur le cpu, la mémoire ou le temps d’exécution. Les paramètres par défauts sont donc bien choisis sur log4j2 ou logback.
• Les logs d’exceptions avec stack traces sont très coûteux en cpu ou mémoire également. Il faut éviter de produire des exceptions qui seraient automatiquement journalisées. Il ne faut donc logger que celles qui pourraient apporter une information utile à la résolution d’un problème technique donné et pas les exceptions qui gèrent les cas d’erreur métier. Dans les cas d’erreurs métier, il faut journaliser des évènements métier. Ex: Une IllegalStateException doit-elle être journalisée ? Ne pourrait-on la remplacer par un message métier du type: ‘Un dossier de prêt immobilier doit contenir l’ensemble des documents emprunteurs obligatoires.’
• Si l’on regarde les cas les plus efficaces et valides en environnement web, les cas 9, 11, et 12, qui ont de loin une emprunte système moindre, les différences entre log4J2, log4J2 (mode gcfree) ou logback sont assez mineures au niveau cpu. On voit par contre que log4J2 en mode gcfree est très intéressant au niveau de la mémoire consommée: environ 40% de moins

Utilisation CPU

Utilisation CPU log4j2	Utilisation CPU log4j2 + gcfree	Utilisation CPU logback

Utilisation mémoire

Utilisation mémoire log4j2	Utilisation mémoire log4j2 + gcfree	Utilisation mémoire logback

Conclusion générale

Les journaux applicatifs prennent de la valeur.
Négligés par le passé, ils font désormais partie intégrante de la chaîne de production et doivent être réfléchis et préparés comme un élément d’architecture important.
Ils peuvent désormais améliorer la productivité générale de maintenance et d’exploitation de l’infrastructure des systèmes d’information par une connaissance de leur fonctionnement statique et dynamique, améliorer les services rendus sur des axes métiers ou encore, lorsqu’ils sont biens pensés pour ne répondre qu’aux besoins réels, économiser des ressources et limiter les impacts négatifs comme remplir un disque inopinément, prendre de la bande passante, …
Alors à vos katas !