Publié par

Il y a 9 années -

Temps de lecture 13 minutes

Java en Production – Les fichiers de logs

Tout a déjà été dit sur les logs. Pour preuve, ce n’est plus un sujet chaud, les équipes d’exploitation sont très contentes avec les logs de nos applications :-) .

D’accord, l’envers du décor est moins reluisant et il reste une marge de progression. Nous avions proposé dans Les 10 commandements des logs applicatives des suggestions focalisées sur le contenu des fichiers de logs ; voici aujourd’hui des propositions pour gérer les fichiers eux-mêmes. Même si le sujet peut sembler trivial, ces bonnes pratiques peuvent grandement simplifier le quotidien des équipes de production et améliorer les relations tumultueuses entre exploitants et développeurs.

Au risque de surprendre certains, les exemples de ce billet utilisent Logback plutôt que le standard de-facto Log4j car certaines bonnes pratiques que je proposerai sont impossibles à mettre en oeuvre avec Log4j. Aujourd’hui, je préfère utiliser Logback à Log4j pour gérer les logs de mes applications … même si je suis nostalgique du format ‘.properties’ pour la configuration de ces dernières :-).

Bien que Logback ne soit pas le sujet de ce billet, j’ai ajouté à l’article initial un paragraphe « Pourquoi je préfère Logback à Log4j » pour expliquer ce choix.

Différents fichiers de logs pour différents besoins

On utilise souvent un seul fichier mon-application.log pour écrire toutes les logs : les informations d’audit, les logs d’exception avec des stack traces sans fins aussi bien que les informations de diagnostique/troubleshooting. Ce fichier se remplit de centaines de lignes par minute, et c’est alors la déception pour tous ses utilisateurs :

  • l’exploitant est incapable de dire si une application a un problème en regardant les logs sans un astucieux système de ‘grep‘ et d’expressions régulières,
  • l’administrateur système et les responsables de la collecte des logs sont incapables de dimensionner les disques pour des logs dont la taille explose au moindre grain de sable à coup de stack traces dont il est pourtant inutile de conserver le détail,
  • les équipes de diagnostique/troubleshooting sont noyées dans la masse des informations lorsqu’elles doivent intervenir.

Au final, c’est l’échec de la transmission de l’application du développement à la production et les exploitants prennent les développeurs pour des inconscients. Je ne saurais leur donner tort sur ce problème et voici ma proposition de découpage des fichiers de logs.

Les logs applicatives

Ce fichier ne trace que les dysfonctionnements, il n’est pas censé se remplir quand l’application fonctionne normalement et est archivé pendant plusieurs années par l’exploitant.

Ses caractéristiques sont :

  • seuls les messages de dysfonctionnement (ie >= WARN) y apparaissent,
  • ce fichier tourne (‘est rotationné’ en franglais) chaque jour pour être archivé,
  • les stack traces seront compactes pour éviter de saturer le système de fichiers. Compacter à deux lignes par cause d’une exception est un bon compromis entre le niveau de détail utile au diagnostic et la taille occupée sur disque.

Remarques :

  • que faire si l’exploitant utilise l’augmentation de la taille du fichier de logs comme indicateur de disponibilité de l’application ? Cette technique de monitoring me semble très discutable sur le fond et je proposerai dans un autre billet d’utiliser des compteurs JMX pour ce besoin. Cependant, si votre exploitant tient absolument à suivre l’augmentation de la taille d’un fichier de logs, je vous propose de l’orienter vers le fichier d’audit décrit plus bas.
  • ajouter le nom de l’instance dans le préfixe de chaque message de logs ? Cette technique est parfois utilisée pour agréger les logs provenant de plusieurs serveurs. Cependant, je préfère que le script de collecte reporte le nom d’instance dans le nom des fichiers collectés. Cela consomme moins de disque et, de toutes façons, la fusion de fichiers de logs en conservant la chronologie est très délicate car toutes les lignes de nos fichiers ne sont pas préfixées (stack traces, sauts de ligne dans les message, etc).

Exemple de fichier logback.xml avec un fichier de logs filtré à WARN, à rotation quotidienne et dont les stack traces sont compactées à 2 lignes par cause d’une exception :

<appender name="log-file" class="ch.qos.logback.core.rolling.RollingFileAppender">
   <file>my-application.log</file>
   <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <!-- only log problems, not debugging info -->
      <level>WARN</level>
   </filter>
   <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <!-- rotate every day for log collection and archiving -->
      <fileNamePattern>my-application.%d{yyyyMMdd}.log</fileNamePattern>
   </rollingPolicy>
   <encoder>
      <!-- only log 2 lines of stack trace per cause of an exception -->
      <pattern>%d{yyyy/MM/dd HH:mm:ss,SSS} [%thread] %-5level %logger{36} - %m %throwable{2}%n</pattern>
   </encoder>
</appender>

Les logs de diagnostic/troubleshooting

Ce fichier est destiné aux équipes de diagnostic/troubleshooting qui peuvent ajouter ou retirer des informations de debug selon leurs besoins. Ces logs ne sont pas archivées et doivent être très détaillées sans pour autant saturer le système de fichiers.

Ses caractéristiques sont :

  • aucun filtrage sur le niveau de log (TRACE, …),
  • reconfiguration à chaud du framework de log pour ajouter/supprimer des informations selon les besoins,
  • rotation avec écrasement des fichiers pour éviter de saturer le système de fichiers.

Exemple de fichier logback.xml avec un rechargement de la configuration toutes les 30 secondes et un fichier de logs de troubleshooting

<configuration scan="true" scanPeriod="30 seconds">
  ...
   <appender name="troubleshooting-file" class="ch.qos.logback.core.rolling.RollingFileAppender">
      <file>my-application-troubleshooting.log</file>
      <!-- 10x10Mo files to limit size on disk -->
      <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
         <fileNamePattern>my-application-troubleshooting.%i.log</fileNamePattern>
         <maxIndex>10</maxIndex>
      </rollingPolicy>
      <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
         <maxFileSize>10MB</maxFileSize>
      </triggeringPolicy>
      <encoder>
         <pattern>%d{yyyy/MM/dd HH:mm:ss,SSS} [%thread] %-5level %logger{36} - %m%n</pattern>
      </encoder>
   </appender>
</configuration>

Logs d’audit

Ce fichier est destiné à l’audit de sécurité, on y trace « qui a fait quoi à quelle heure », il grossit donc en permanence et peut dépasser le Go chaque jour.

Ses caractéristiques sont :

  • seuls les messages d’audit y apparaissent,
  • ce fichier tourne chaque jour pour être archivé.

Remarques :

  • Certains estiment que le framework de logs n’a pas vocation à gérer les informations d’audit. Bien que je comprenne la théorie, je trouve en pratique bien plus simple de gérer simultanément les deux pour les raisons suivantes:
    • l’audit doit tracer toutes les erreurs pour permettre d’analyser les problèmes de sécurité, il faudrait donc tracer les exceptions à la fois dans les logs et dans l’audit,
    • les frameworks de logging sont très efficaces pour gérer l’écriture de gros volumes de messages sur disque,
    • bien qu’il existe théoriquement un risque qu’une équipe de diagnostic fasse une erreur de configuration et désactive l’audit, je n’ai jamais entendu parler de ce genre de bourde.
  • Faut-il augmenter la fréquence de rotation pour prévenir une dégradation des performances lorsque les fichiers d’audit dépassent le Go chaque jour ? Je ne pense pas : j’ai travaillé récemment sur une application Linux RHEL 5 / JVM Hotspot 6 / Tomcat / Log4j qui générait plus d’un Go de logs d’audit chaque jour. L’impact sur les performances était négligeable et l’augmentation de la fréquence de rotation n’a eu aucun impact. En revanche, en cas d’écriture massive sur disque, il faut collaborer avec l’administrateur système pour qu’il vérifie ses configurations OS et disques (c.f. RAID 1) ; les administrateurs sont habitués à ces problèmes avec les fichiers de logs des bases de données.

Exemple de fichier logback.xml avec un fichier d’audit avec rotation quotidienne qui ne traite que les loggers ayant la racine ‘fr.xebia.audit’ :

<appender name="audit-file" class="ch.qos.logback.core.rolling.RollingFileAppender">
   <file>${LOGS_FOLDER}/my-application-audit.log</file>
   <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <!-- rotate every day -->
      <fileNamePattern>/my-application-audit.%d{yyyyMMdd}.log.zip</fileNamePattern>
   </rollingPolicy>
   <encoder>
      <!-- don't output the date or the logger name because the auditing framework handles this -->
      <pattern>%m %throwable{0}%n</pattern>
   </encoder>
</appender>

<!-- route the 'fr.xebia.audit' log messages to the audit-file -->
<logger name="fr.xebia.audit" additivity="false" level="TRACE">
   <appender-ref ref="audit-file" />
</logger>

Un répertoire dédié pour les fichiers de logs archivés

Une fois nos fichiers bien séparés, nous pouvons encore faciliter le travail des équipes d’exploitation avec une astuce très simple : stocker dans un autre répertoire les fichiers qui ont tourné. Il suffit de déclarer un répertoire logs-to-collect à côté de notre répertoire logs. Les bénéfices sont nombreux :

  • Le script de collecte des logs (compression et transfert sur un serveur de backup) est grandement simplifié. Il n’est plus nécessaire d’utiliser un astucieux mécanisme de pattern sur le nom des fichiers pour exclure ceux qui sont en cours d’utilisation. Tous les fichiers du répertoires logs-to-collect peuvent être collectés à n’importe quel moment.
  • L’équipe de collecte de logs peut conserver autant de fichiers de logs d’archive sur le serveur sans nuire à la lisibilité du répertoire logs en y laissant des centaines d’entrées.
  • Il n’y a plus de risques de perdre les fichiers créés dans des circonstances exceptionnelles (opération de diagnostic, etc) et dont le nom ne correspondrait pas aux patterns du script de collecte, il suffit de déplacer ces fichiers dans le répertoire logs-to-collect.

Remarque : seules les logs applicatives et d’audit ont vocation à être reversées dans ce répertoire. Les logs de diagnostic/troubleshooting ne sont pas archivées et restent donc dans le répertoire logs.

Structure de répertoires avec un répertoire logs-to-collect dédié aux fichiers à archiver
logs-to-collect folder

Exemple de configuration avec logback

<appender name="log-file" class="ch.qos.logback.core.rolling.RollingFileAppender">
  <file>logs/my-application.log</file>
  <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
    <!-- roll every day in a dedicated non-active folder -->
    <fileNamePattern>logs-to-collect/my-application.%d{yyyyMMdd}.log</fileNamePattern>
  </rollingPolicy>
  ...
</appender>

Compresser les fichiers lors de leur rotation

Dernière astuce pour faire plaisir aux équipes d’exploitation en limitant la consommation d’espace disque : nos frameworks de logs savent maintenant compresser les fichiers (zip ou gzip) lors des rotations. Cette compression n’a en général aucun impact sur les performances de nos applications grâce aux CPU multi-cœurs, cela simplifiera encore le script de collecte des logs.

Pour la recherche dans des fichiers compressés, il faut garder en tête zcat et gzcat qui permettent d’extraire simplement les informations utiles.

Exemple de fichier logback.xml avec un fichier d’audit avec rotation quotidienne qui ne traite que les loggers ayant la racine ‘fr.xebia.audit’ :

<appender name="zipped-archive" class="ch.qos.logback.core.rolling.RollingFileAppender">
   ...
   <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <!-- rotate and zip every day -->
      <fileNamePattern>my-log-file.%d{yyyyMMdd}.log.zip</fileNamePattern>
   </rollingPolicy>
   ...
</appender>

Un fichier de configuration de logs prêt pour la production

Voici un fichier de configuration logback.xml prêt pour la production qui reprend toutes les bonnes pratiques de ce billet; il tient en 50 lignes :-).

<configuration scan="true">
  <property name="LOGS_FOLDER" value="${catalina.base}/logs" />
  <property name="LOGS_TO_COLLECT_FOLDER" value="${catalina.base}/logs-to-collect" />

   <appender name="log-file" class="ch.qos.logback.core.rolling.RollingFileAppender">
      <file>${LOGS_FOLDER}/my-application.log</file>
      <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
         <level>WARN</level>
      </filter>
      <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
         <fileNamePattern>${LOGS_TO_COLLECT_FOLDER}/my-application.%d{yyyyMMdd}.log</fileNamePattern>
      </rollingPolicy>
      <encoder>
         <pattern>%d{yyyy/MM/dd HH:mm:ss,SSS} [%thread] %-5level %logger{36} - %m %throwable{0}%n</pattern>
      </encoder>
   </appender>

   <appender name="audit-file" class="ch.qos.logback.core.rolling.RollingFileAppender">
      <file>${LOGS_FOLDER}/my-application-audit.log</file>
      <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
         <fileNamePattern>${LOGS_TO_COLLECT_FOLDER}/my-application-audit.%d{yyyyMMdd}.log.gzip</fileNamePattern>
      </rollingPolicy>
      <encoder>
         <pattern>%m %throwable{0}%n</pattern>
      </encoder>
   </appender>

   <appender name="troubleshooting-file" class="ch.qos.logback.core.rolling.RollingFileAppender">
      <file>${LOGS_FOLDER}/my-application-troubleshooting.log</file>
      <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
         <fileNamePattern>${LOGS_FOLDER}/my-application-troubleshooting.%i.log</fileNamePattern>
         <maxIndex>10</maxIndex>
      </rollingPolicy>
      <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
         <maxFileSize>10MB</maxFileSize>
      </triggeringPolicy>
      <encoder>
         <pattern>%d{yyyy/MM/dd HH:mm:ss,SSS} [%thread] %-5level %logger{36} - %m%n</pattern>
      </encoder>
   </appender>

   <logger name="fr.xebia.audit" additivity="false" level="TRACE">
      <appender-ref ref="audit-file" />
   </logger>
   
   <root level="WARN">
      <appender-ref ref="log-file" />
      <appender-ref ref="troubleshooting-file" />
   </root>
</configuration>

Pourquoi je préfère Logback à Log4j

Au delà du comparatif Reasons to prefer logback over log4j que maintient le projet Logback avec un zest de chauvinisme, je trouve que le compactage des stack traces en préservant les causes d’une exception est vraiment différenciant. Je ne vois pas de solution pour le faire avec Log4j sans hacker la librairie. J’ai proposé le patch « Bug 48902 – log4j-extras – Enhancement : add %throwable{compact} to EnhancedPatternLayout » mais la gestion des causes de l’exception n’a pas été intégrée.

Conservation de la cause d’une exception avec Logback et le pattern « %thread %-5level %logger{36} – %msg %throwable{1}%n »

[main] ERROR fr.xebia.test.LoggerTest - Logged by Logback java.lang.RuntimeException: Ze caller
  at fr.xebia.test.LoggerTest.callingMethod(LoggerTest.java:52)
  at fr.xebia.test.LoggerTest.testLogback(LoggerTest.java:38)
Caused by: java.lang.RuntimeException: Ze cause
  at fr.xebia.test.LoggerTest.nestedMethod(LoggerTest.java:45)
  at fr.xebia.test.LoggerTest.callingMethod(LoggerTest.java:50)

Perte de la cause d’une exception avec Log4j et le pattern « %t %5p %c – %m %throwable{3}%n » :

[main] ERROR  fr.xebia.test.LoggerTest - Logged by Log4j java.lang.RuntimeException: Ze caller
  at fr.xebia.test.LoggerTest.callingMethod(LoggerTest.java:52)
  at fr.xebia.test.LoggerTest.testLog4j(LoggerTest.java:28)

J’apprécie aussi le fichier de configuration de test logback-test.xml, l’activation du rafraichissement de la configuration avec scan="true" et bien d’autres détails de Logback qui pourraient faire l’objet d’un prochain billet.

Publié par

Publié par Cyrille Le Clerc

CTO de Xebia, Cyrille est aussi committer sur le projet Apache CXF. Après être récemment intervenu sur les sites web et les plateformes de web service à fort traffic d'opérateurs de télécommunication, Cyrille est actuellement responsable de la mise en place d'une grille de données inter-continentale pour une grande institution financière française. Après 7 ans chez IBM Global Services et 5 ans chez Xebia, Cyrille a une expérience variée allant du monde commercial aux écosystèmes Open Source dans des approches aussi bien très cadrées et contractuelles que légères et agiles. Cyrille est aussi blogger sur blog.xebia.fr et speaker dans des conférences (In Memory Data Grids & NoSQL, applications prêtes pour la production, etc).

Commentaire

27 réponses pour " Java en Production – Les fichiers de logs "

  1. Publié par , Il y a 9 années

    Bonjour,

    Excellent billet comme toujours. Comme quoi, tout n’a pas été dit sur les logs :-)

    Juste un bémol. Il me semble que ce n’est pas à l’application de décider de la rotation ou non des logs et quand elle doit se faire. Il s’agit plutôt d’une tâche d’exploitation sur laquelle l’administrateur système doit avoir la main sans avoir à modifier l’application (ou un fichier du classpath ou que celui-ci puisse se trouver). C’est pour cela qu’il est fortement conseillé d’utiliser « logrotate » (http://fr.gentoo-wiki.com/wiki/Logrotate) et non pas un framework applicatif.

  2. Publié par , Il y a 9 années

    @Waddle,

    Merci pour votre retour d’expérience. Je vous rejoins sur le fait que la gestion des logs relève de l’équipe d’exploitation mais je crains d’avoir une opinion différente sur l’ajout a logrotate à nos applications Java :-) .

    Je préfère demander aux équipes de développement et d’exploitation de s’accorder sur la configuration du framework de logs plutôt que d’ajouter une couche intermédiaire logrotate/cronolog dont le comportement est subtile et souvent mal compris.

    Comment se comporte un fichier de log géré par un processus java quand une autre application essaie d’en modifier le contenu ? En plus de dépendre du système d’exploitation, ce comportement variera selon que nous demandons à logrotate de faire un move+create ou un copy+truncate … On entre dans l’art des systèmes de fichiers :-) .

    Je suis surement échaudé par ma dernière expérience dans ce domaine : la rotation du fichier catalina.out de Tomcat avec cronolog. En théorie assez banal (1). Durant les deux années que j’ai passé sur cette plateforme, cette rotation n’a jamais été fiable et nous avons régulièrement perdu des journées entières de logs :-( .

    Vous semblez avoir été plus chanceux que moi ; à chaque situation ses solutions :-).

    Cyrille

    (1) http://www.tomcatexpert.com/knowledge-base/rotating-catalinaout-log-files

  3. Publié par , Il y a 9 années

    Effectivement, l’expérience de chacun rend plus ou moins méfiant à certains outils ou techniques, c’est tout ce qu’il y a de plus naturel. Simplement, je trouve plus logique de regrouper la stratégie de rotation au niveau système surtout si plusieurs technos et/ou applications cohabitent. De plus, les équipes d’exploitations doivent savoir utiliser les outils comme logrotate. Si ce n’est pas le cas, je vous invite à m’envoyer un mail, nous faisons de l’hébergement (entre autre), et nos équipes sont très qualifiées ;-)

  4. Publié par , Il y a 9 années

    @Waddle

    Un Contegix à la française ??? Un hébergeur qui sait lire des stack traces ? Il faut nous en dire plus … et proposer une soirée au Paris JUG sur Java vu par un hébergeur. Plutôt que de vous envoyer un email privé, c’est une demande publique :-).

    Pour revenir à « logrotate over java », comment se passe la concurrence d’accès en écriture sur le fichier ? Simplifions en nous limitant à Linux avec un file appender Logback ou Log4j. Faut-il utiliser logrotate en copy+create ou move+create ?

    Cyrille

  5. Publié par , Il y a 9 années

    Concernant l’utilisation des logs pour suivre la dispo de l’appli (par contrôle de l’autgmentation de la taille), ça m’a valu une de mes plus grosse rigolade professionnelle (jaune, la rigolade). Le système comparait la taille des logs à 5 mins d’intervalle, et si cette taille n’avait pas augmenté, une relance des serveurs était effectuée.

    La conséquence : entre 1h du mat et 5 h du mat, une relance toutes les 5 minutes…

    En conclusion, cette solution est un pur hack, et franchement un hack complètement crétin. Sin on a besoin de vérifier qu’une application est présente, il y a des outils pour cela (patrol, etc…)

    Sinon, un autre type de logs est très intéressant à mettre en place : le log d’utlisation de resources partagées. Par exemple, un log pour les connexion à une base de données, de serveur LDAP, etc. cela permet d’évaluer les pics de charge sur ces resources. Pratique.

  6. Publié par , Il y a 9 années

    Je préfère pas faire de pub publique dans les commentaires de votre blog puisque nous sommes concurrents sur d’autres aspects ;-) mais si vous êtes intéressé, je suis dispo pour vous donner des infos.

    Pour logrotate, il faut le configurer en copytruncate. Attention, s’il y a vraiment plein de lignes de logs, pendant une fraction de seconde, quelques lignes peuvent être perdues. Rien de rédhibitoire normalement.

  7. Publié par , Il y a 9 années

    Évaluer la charge d’une application ou d’une ressource (SGBD, JMS, LDAP) par rapport à ses logs ne me semble pas être une méthode appropriée.
    JMX et les agents de monitoring sont d’avantages préconisés.

  8. Publié par , Il y a 9 années

    @Waddle,

    Votre pudeur vous honore :-) je vous envoie de ce pas un email pour vous offrir un verre pour discuter de vive voix. Que les personnes intéressées par ce débat m’envoient un email :-)

    > quelques lignes peuvent être perdues. Rien de rédhibitoire normalement.

    J’ai récemment travaillé sur un site web qui permettait notamment d’uploader des photos. Il n’était pas possible de perdre quelques logs d’audit. Surtout si le but / la justification était de se dispenser de faire collaborer deux équipes pour écrire ensemble un fichier de configuration de logs.

    Mon coeur s’incline toujours vers la rotation des fichiers de logs grâce à nos frameworks logback/log4j :-)

    Cyrille

  9. Publié par , Il y a 9 années

    @Ceki,

    Merci, c’est un honneur d’avoir un commentaire d’une personne qui a autant impacté notre quotidien de javaiste.

    Pour la configuration en groovy, comme je l’ai dit dans mon billet, je suis nostalgique de nos fichiers de configuration au format ‘.properties’. Pas tellement pour mes goûts personnels mais parce que mes interlocuteurs de l’exploitation préfèrent ce format à XML.
    J’ai peur que groovy ne soit pas plus « sysadmin friendly » que ne l’est XML aux yeux des exploitants :-)

    Cyrille

  10. Publié par , Il y a 9 années

    @Sébastien,

    Je suis bien d’accord avec vous ! J’ai été choqué la première fois que j’ai vu un exploitant évaluer la disponibilité d’une application java en faisant un ‘ps’.
    Finalement, la supervision de la disponibilité en regardant l’augmentation de la taille des fichiers de logs est beaucoup plus high-tech :-)

    Sur le fond, je vous rejoins totalement et nous travaillons à un billet concernant JMX.

    Cyrille

  11. Publié par , Il y a 9 années

    Merci pour cet article qui exprime les besoins de l’exploitation. C’est toujours très intéressant de se placer du point de vue de l’exploitation.

    S’agissant du format des fichiers de configuration, pour une personne capable de programmer, le format Groovy comparé au formats XML et properties offre une puissance d’expression très largement supérieure. Il me semble que dans la majorité des cas, une fois qu’on goutte à ce nouveau format (logback.groovy), on ne peut plus revenir en arrière mais on n’a pas encore suffisamment de recul sur le sujet.

    Vivement le prochain article,

  12. Publié par , Il y a 9 années

    @Cyrille

    Toujours dispo pour une discussion autour d’un verre ;-)

    J’ai également travaillé sur un site dernièrement pour un assureur ou certaines traces devaient être conservées et avaient en outre une valeur légale. Nous avons opté dans ce cas pour un stockage de ces « logs » en base plutôt que dans un fichier, mais on s’éloigne du sujet :-)

  13. Publié par , Il y a 9 années

    Question pseudo-technique :

    Quelle est l’impact de garder les numéros de ligne dans les logs ?
    (impact en terme de perf, de compilation)

    Pour info, le format donnerait : %method\(%line\

    Je pense que cela a une certaine valeur quand le code n’est pas forcément écrit (grosses méthodes…).

    Merci,

    Tom

  14. Publié par , Il y a 9 années

    @Tom,
    L’affichage du numéro de ligne de code java qui a généré le message de log est très couteux et ne devrait pas être activé en production si les performances sont importantes. Ce coût provient du fait que le framework de logs doit générer une stack trace puis parser la chaine de caractère pour en extrait le numéro de ligne.

    Extrait de la documentation de logback :

    « Generating the line number information is not particularly fast. Thus, its use should be avoided unless execution speed is not an issue. »

    Un refactoring simple et rapide pour comprendre quelle ligne de code a émis un message de log est de s’assurer que chaque message est différent. En plus d’être un « quick win », cette tactique améliorera la qualité des logs en les rendant plus explicites.

    Dans un deuxième temps, le refactoring des méthodes obèses peut être entrepris si c’est compatible avec les enjeux du projet …

    Cyrille

  15. Publié par , Il y a 9 années

    @Waddle,

    Ecrire des logs dans une base, je crains d’avoir une fois de plus une sensibilité différente :-)

    Je n’en dévoile pas plus aujourd’hui car la gestion de l’audit est le sujet de mon prochain billet.

    Pour boire un verre, faute de session du Paris JUG en Aout, le touilleur-express a évoqué un apéro geek cet été, ce poourrait-être l’occasion :-)

    Cyrille

  16. Publié par , Il y a 9 années

    @Ceki ,

    groovy vs. xml vs. properties
    Je crois qu’il est nécessaire que j’ajoute une deuxième partie à ce billet pour essayer la configuration groovy !

    Réflexion faite, je vois deux raisons pour lesquelles les exploitants pourraient préférer groovy à XML pour configurer nos logs :
    * les configurations sous forme de DSL se banalisent : Varnish Cache, lighthttpd, etc
    * ils détestent tellement XML qui est tellement unfriendly à grep, sed, awk et autres expressions régulières :-)

    En plus de xml et groovy, voyez vous une place pour une configuration de logback au format ‘.properties’ ?

    Information de packaging dans les stack traces (« xException{length} »)

    Ces informations sont biens pratiques pour diagnostiquer les problèmes de class loader et de jar qui embarquent ‘la terre entière’ dans des versions obsolète.

    Connaissez-vous le cout en performances de l’ajout de cette information ?

    Est-il raisonnable d’activer l’ajout d’information de packaging dans les stack trace en production ou est-ce à éviter en production comme le numéro de ligne du code source java ?

    Cyrille

  17. Publié par , Il y a 9 années

    Pour faire bref, vu la faiblesse syntaxique du format .properties, je crois qu’il n’y aura pas de support pour logback.properties.

    Concernant les informations de packaging dans les stack trace, cette information est activée par défaut car même si le coût d’extraction est élevé. En d’autres termes, le convertisseur %xEx est automatiquement ajouté sauf si l’utilisateur spécifie explicitement le convertisseur %ex ou %nopex. Le surcout de %xEx est payé qu’en cas d’exception, ce qui est par définition exceptionnel et devrait jamais impacter la performance.

    A ce stade, je voudrais mentionner le convertisseur %caller qui peut s’avérer très pratique pour debugger certains problèmes survenant en production. (Attention, vu le surcoût, à activer que sélectivement.)

  18. Publié par , Il y a 9 années

    @Ceki

    > vu la faiblesse syntaxique du format .properties …

    Faiblesse que ne dissuade pas les gens de régulièrement projeter des structures de données arborescentes ou orientées object dans du clef-valeur avec des clefs composées à grand renfort de ‘_’, de numéros d’index et d’autres délices du genre :-)

    Je fais mon « coming out », je reconnais avoir il y a bien longtemps projeté une configuration arborescente dans un fichier properties avec jakarta commons-configuration. Je confesse aussi avoir propagé entre des pages web un shopping cart complet avec des champs cachés à la "<input type='hidden' name='cart_item_3_id' ... />".

    Que celui qui n’a jamais fauté me jette la première pierre :-).

    Dans le même registre mais avec des technologies à la mode, avez-vous déjà entendu les propositions de no-sqliens casssendristes pour projeter un shopping cart dans du column-oriented ? On retrouve le style « .properties flamboyant » saupoudré d’un zeste d’expressions régulières sur les clefs ; un vrai régal :-) .

    Malgré toutes ces hérésies, je suis assez d’accord avec vous sur le fond. Nous avons beaucoup plus riche que le format .properties en 2010.

    Cyrille

  19. Publié par , Il y a 8 années

    Bonjour,
    J’ai une question : J’ai intégré à mon application web le composant LogBack + SLF4J comme couche d’abstraction, tout cela en ajoutant simplement deux fichiers jar de logback et un autre de SLF4J, puis mon fichier de configuration logback.xml qui fait un certains nombres de requêtes pour un affichage customisé.
    Est ce qu’il y a un moyen de générer un identifiant pour les différents log qui sont enregistré ( pour le moment j’en génère a l’aide de combinaison (%relative %level).
    Aussi est ce qu’il y a moyen d’encapsuler (LogBack+SLF4J) pour les intégrés à toute sorte d’application sans que d’autres utilisateurs aient le droit de modifié quoi que ce soit que ca soit dans le fichier de configuration ou l’application elle même.
    Merci à vous.

  20. Publié par , Il y a 8 années

    Bonjour Cissine,

    > « Est ce qu’il y a un moyen de générer un identifiant pour les différents log qui sont enregistré ( pour le moment j’en génère a l’aide de combinaison (%relative %level). »

    Votre besoin me rappelle les Mapped Diagnostic Context que j’ai déjà utilisé pour tracer un numéro de téléphone client chez un opérateur télécom ou un numéro de compte client dans une banque.

    > « … moyen d’encapsuler (LogBack+SLF4J) pour les intégrés à toute sorte d’application sans que d’autres utilisateurs aient le droit de modifié quoi que ce soit que ca soit dans le fichier de configuration ou l’application elle même. »

    Je préfère en général faire confiance aux équipes de développement et d’exploitation plutôt que de les contraindre. S’il y a un problème de confiance avec les uns ou avec les autres, je pense qu’il vaut mieux traiter sur le fond et se séparer des gens … dans la mesure où il y a réellement un problème :-) .
    J’ai travaillé dans des organisations qui ne faisaient pas confiance à telle ou telle équipe, souvent en méprisant leurs compétences et leur travail. C’était aussi désagréable qu’inefficace.

    Le fonctionnement le plus efficace que j’ai vu est
    1) les équipes de dév ajoutent des log dans leur code en faisant de leur mieux pour différencier trace/debug/info/warn/error . J’utilise souvent :
    – warn : les comportements inattendus souvent des situations qui auraient pu mériter une IllegalStateException
    – info : les messages qui me donnent une idée globale du fonctionnement de la zone
    – debug : les informations détaillées dont j’ai besoin quand je troubleshoot précisément cette zone
    – trace : les informations ultra détaillées que je ne devrais jamais activer mais que j’utilise quand en dernier recours pour débugger une zone de code quand je suis perdu,

    2) les ops disent dans quel répertoire ils veulent ce fichier pour pouvoir le modifier à chaud
    – avec Tomcat, il suffit de le placer dans WEB-INF/classes,
    – avec les gros serveurs J2EE, il faut souvent sortir ce fichier des ear et war car les serveurs cachent les war « expandés » dans des répertoire que les exploitants ne savent pas trouver facilement,

    3) les dév préparent le fichier de configuration des log (logback.xml, log4j.properties)
    – le root logger à warn,
    – les outputs xx.log/xx-troubleshooting.log/xx-audit.log et aussi souvent xx-perfs.log,
    – certains logger à des niveaux inférieurs (info/debug) pour des cas particuliers,

    4) les ops valident le fichier et le déploient en parallèle du war/ear s’il doit être situé à l’extérieur de l’artifact,

    5) les ops peuvent modifier à chaud le fichier de configuration des logs pour changer les niveaux de logs suivant les besoins.

    6) Devs et ops itèrent conjointement pour améliorer les messages

    Cyrille (Xebia)

  21. Publié par , Il y a 8 années

    « Juste un bémol. Il me semble que ce n’est pas à l’application de décider de la rotation ou non des logs et quand elle doit se faire. Il s’agit plutôt d’une tâche d’exploitation sur laquelle l’administrateur système doit avoir la main sans avoir à modifier l’application (ou un fichier du classpath ou que celui-ci puisse se trouver). »
    Gérant une application déployée sur une 50aine de machine avec différents OS. Le problème est qu’un script de rotation de log est très dépendant de l’OS et de l’installation. Quand l’installation de l’appli est générique, pas de souci, mais si elle ne l’est pas (répertoire différent pour le plus courant, user différent, etc), les problèmes surviennent. Laisser le framework géré cette partie règle complétement le problème, et logback implémente tous ce qui manquait à log4j.

    Je me demandais si elle étais possible et pratique, de scinder un fichier de conf logback en 2 parties : une partie intégrée dans le war avec une configuration de log générique + 1 seconde partie en dehors du war, avec rechargement à chaud. L’intérêt étant d’être sûr de ne pas oublier le fichier de conf ni qu’il soit modifié par erreur et en même temps permettre pendant le run de sortir les traces de debug/trace d’une classe précise en cas de problème ?

  22. Publié par , Il y a 8 années

    Logback propose ce genre de fonctionnalités (include d’un autre fichier, définition de propriétés). Ca reste basique, mais sur le point technique, ça semble réalisable.

    Niveau réalisation, JMX me semble mieux approprié pour modifier les logs à chaud.

  23. Publié par , Il y a 8 années

    Bonjour,
    L’article est intéressant, et les commentaires aussi.
    J’ai repéré une erreur récurrente dans les exemples : la rotation n’est pas quotidienne, mais se fait à chaque minute. Il faudrait remplacer %d{yyyyMMdd-HHmm} par %d{yyyyMMdd}, ou par le minimaliste %d.
    D’autre part, en testant, j’ai constaté que, si on met une virgule, ce qui se trouve après n’est pas pris en compte : %d{HH:mm:ss,SSS} donne le même affichage que %d{HH:mm:ss}.
    Je suis curieux, j’ai testé d’autres signe. L’apostrophe : %d{HH:mm:ss’SSS} affiche : 2011-07-06 16:40:08,855
    Pourtant, les autres signes que j’ai testé passent : %d{HH:mm:ss\?{[> »;:/!ç(%$*€£`+=@#SSS} donne à l’affichage : 16:40:25\?{[> »;:/!ç(%$*€£`+=@#032
    Je code sur Eclipse sur MacosX.
    Laurent

  24. Publié par , Il y a 8 années

    @Laurent,

    Merci pour la remarque. La coquille est corrigée. J’avais activé une rotation à la minute pour vérifier le comportement de logback. C’est corrigé.

    Cyrille

  25. Publié par , Il y a 8 années

    À propos de l’utilisation de la virgule, dans le chapitre 6 de la documentation, http://logback.qos.ch/manual/layouts.html :

    Given that the comma ‘,’ character is the option separator, the pattern string [HH:mm:ss,SSS] will print the time in the [SSS] time zone which does not exist. Thus, the time will be printed in the default GMT timezone. If you wish to include a comma in your date pattern, then simply enclose the pattern between quotes. For example, %date{« HH:mm:ss,SSS »}.

Laisser un commentaire

Votre adresse de messagerie ne sera pas publiée. Les champs obligatoires sont indiqués avec *

Nous recrutons

Être un Xebian, c'est faire partie d'un groupe de passionnés ; C'est l'opportunité de travailler et de partager avec des pairs parmi les plus talentueux.