Publié par

Il y a 10 ans -

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 10 ans

    Bonjour,

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

    Juste un bmol. Il me semble que ce n’est pas l’application de dcider de la rotation ou non des logs et quand elle doit se faire. Il s’agit plutt d’une tche d’exploitation sur laquelle l’administrateur systme 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 10 ans

    @Waddle,

    Merci pour votre retour d’exprience. Je vous rejoins sur le fait que la gestion des logs relve de l’quipe d’exploitation mais je crains d’avoir une opinion diffrente sur l’ajout a logrotate nos applications Java :-) .

    Je prfre demander aux quipes de dveloppement et d’exploitation de s’accorder sur la configuration du framework de logs plutt que d’ajouter une couche intermdiaire logrotate/cronolog dont le comportement est subtile et souvent mal compris.

    Comment se comporte un fichier de log gr par un processus java quand une autre application essaie d’en modifier le contenu ? En plus de dpendre du systme 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 systmes de fichiers :-) .

    Je suis surement chaud par ma dernire exprience dans ce domaine : la rotation du fichier catalina.out de Tomcat avec cronolog. En thorie assez banal (1). Durant les deux annes que j’ai pass sur cette plateforme, cette rotation n’a jamais t fiable et nous avons rgulirement perdu des journes entires 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 10 ans

    Effectivement, l’exprience de chacun rend plus ou moins mfiant certains outils ou techniques, c’est tout ce qu’il y a de plus naturel. Simplement, je trouve plus logique de regrouper la stratgie de rotation au niveau systme 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’hbergement (entre autre), et nos quipes sont trs qualifies ;-)

  4. Publié par , Il y a 10 ans

    @Waddle

    Un Contegix la franaise ??? Un hbergeur qui sait lire des stack traces ? Il faut nous en dire plus … et proposer une soire au Paris JUG sur Java vu par un hbergeur. Plutt que de vous envoyer un email priv, c’est une demande publique :-).

    Pour revenir « logrotate over java », comment se passe la concurrence d’accs 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 10 ans

    Concernant l’utilisation des logs pour suivre la dispo de l’appli (par contrle de l’autgmentation de la taille), a m’a valu une de mes plus grosse rigolade professionnelle (jaune, la rigolade). Le systme comparait la taille des logs 5 mins d’intervalle, et si cette taille n’avait pas augment, une relance des serveurs tait effectue.

    La consquence : 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 compltement crtin. Sin on a besoin de vrifier qu’une application est prsente, il y a des outils pour cela (patrol, etc…)

    Sinon, un autre type de logs est trs intressant mettre en place : le log d’utlisation de resources partages. Par exemple, un log pour les connexion une base de donnes, de serveur LDAP, etc. cela permet d’valuer les pics de charge sur ces resources. Pratique.

  6. Publié par , Il y a 10 ans

    Je prfre pas faire de pub publique dans les commentaires de votre blog puisque nous sommes concurrents sur d’autres aspects ;-) mais si vous tes intress, 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 rdhibitoire normalement.

  7. Publié par , Il y a 10 ans

    valuer la charge d’une application ou d’une ressource (SGBD, JMS, LDAP) par rapport ses logs ne me semble pas tre une mthode approprie.
    JMX et les agents de monitoring sont d’avantages prconiss.

  8. Publié par , Il y a 10 ans

    @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 intresses par ce dbat m’envoient un email :-)

    > quelques lignes peuvent tre perdues. Rien de rdhibitoire normalement.

    J’ai rcemment 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 grce nos frameworks logback/log4j :-)

    Cyrille

  9. Publié par , Il y a 10 ans

    @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 gots personnels mais parce que mes interlocuteurs de l’exploitation prfrent 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 10 ans

    @Sbastien,

    Je suis bien d’accord avec vous ! J’ai t choqu la premire 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 10 ans

    Merci pour cet article qui exprime les besoins de lexploitation. Cest toujours trs intressant de se placer du point de vue de lexploitation.

    Sagissant du format des fichiers de configuration, pour une personne capable de programmer, le format Groovy compar au formats XML et properties offre une puissance dexpression trs largement suprieure. Il me semble que dans la majorit des cas, une fois quon goutte ce nouveau format (logback.groovy), on ne peut plus revenir en arrire mais on na pas encore suffisamment de recul sur le sujet.

    Vivement le prochain article,

  12. Publié par , Il y a 10 ans

    @Cyrille

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

    J’ai galement travaill sur un site dernirement pour un assureur ou certaines traces devaient tre conserves et avaient en outre une valeur lgale. Nous avons opt dans ce cas pour un stockage de ces « logs » en base plutt que dans un fichier, mais on s’loigne du sujet :-)

  13. Publié par , Il y a 10 ans

    Question pseudo-technique :

    Quelle est l’impact de garder les numros 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 forcment crit (grosses mthodes…).

    Merci,

    Tom

  14. Publié par , Il y a 10 ans

    @Tom,
    L’affichage du numro de ligne de code java qui a gnr le message de log est trs couteux et ne devrait pas tre activ en production si les performances sont importantes. Ce cot provient du fait que le framework de logs doit gnrer une stack trace puis parser la chaine de caractre pour en extrait le numro 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 diffrent. En plus d’tre un « quick win », cette tactique amliorera la qualit des logs en les rendant plus explicites.

    Dans un deuxime temps, le refactoring des mthodes obses peut tre entrepris si c’est compatible avec les enjeux du projet …

    Cyrille

  15. Publié par , Il y a 10 ans

    @Waddle,

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

    Je n’en dvoile 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 apro geek cet t, ce poourrait-tre l’occasion :-)

    Cyrille

  16. Publié par , Il y a 10 ans

    @Ceki ,

    groovy vs. xml vs. properties
    Je crois qu’il est ncessaire que j’ajoute une deuxime partie ce billet pour essayer la configuration groovy !

    Rflexion faite, je vois deux raisons pour lesquelles les exploitants pourraient prfrer groovy XML pour configurer nos logs :
    * les configurations sous forme de DSL se banalisent : Varnish Cache, lighthttpd, etc
    * ils dtestent tellement XML qui est tellement unfriendly grep, sed, awk et autres expressions rgulires :-)

    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 problmes de class loader et de jar qui embarquent ‘la terre entire’ dans des versions obsolte.

    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 numro de ligne du code source java ?

    Cyrille

  17. Publié par , Il y a 10 ans

    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 active par dfaut car mme si le cot d’extraction est lev. En dautres termes, le convertisseur %xEx est automatiquement ajout sauf si lutilisateur spcifie explicitement le convertisseur %ex ou %nopex. Le surcout de %xEx est pay qu’en cas d’exception, ce qui est par dfinition exceptionnel et devrait jamais impacter la performance.

    A ce stade, je voudrais mentionner le convertisseur %caller qui peut savrer trs pratique pour debugger certains problmes survenant en production. (Attention, vu le surcot, activer que slectivement.)

  18. Publié par , Il y a 10 ans

    @Ceki

    > vu la faiblesse syntaxique du format .properties …

    Faiblesse que ne dissuade pas les gens de rgulirement projeter des structures de donnes arborescentes ou orientes object dans du clef-valeur avec des clefs composes grand renfort de ‘_’, de numros d’index et d’autres dlices 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 cachs la "<input type='hidden' name='cart_item_3_id' ... />".

    Que celui qui n’a jamais faut me jette la premire pierre :-).

    Dans le mme registre mais avec des technologies la mode, avez-vous dj 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 rgulires sur les clefs ; un vrai rgal :-) .

    Malgr toutes ces hrsies, 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 9 ans

    Bonjour,
    J’ai une question : J’ai intgr 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 requtes pour un affichage customis.
    Est ce qu’il y a un moyen de gnrer un identifiant pour les diffrents log qui sont enregistr ( pour le moment j’en gnre a l’aide de combinaison (%relative %level).
    Aussi est ce qu’il y a moyen d’encapsuler (LogBack+SLF4J) pour les intgrs 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 mme.
    Merci vous.

  20. Publié par , Il y a 9 ans

    Bonjour Cissine,

    > « Est ce quil y a un moyen de gnrer un identifiant pour les diffrents log qui sont enregistr ( pour le moment jen gnre a laide de combinaison (%relative %level). »

    Votre besoin me rappelle les Mapped Diagnostic Context que j’ai dj utilis pour tracer un numro de tlphone client chez un oprateur tlcom ou un numro de compte client dans une banque.

    > « … moyen dencapsuler (LogBack+SLF4J) pour les intgrs toute sorte dapplication sans que dautres utilisateurs aient le droit de modifi quoi que ce soit que ca soit dans le fichier de configuration ou lapplication elle mme. »

    Je prfre en gnral faire confiance aux quipes de dveloppement et d’exploitation plutt que de les contraindre. S’il y a un problme de confiance avec les uns ou avec les autres, je pense qu’il vaut mieux traiter sur le fond et se sparer des gens … dans la mesure o il y a rellement un problme :-) .
    J’ai travaill dans des organisations qui ne faisaient pas confiance telle ou telle quipe, souvent en mprisant leurs comptences et leur travail. C’tait aussi dsagrable qu’inefficace.

    Le fonctionnement le plus efficace que j’ai vu est
    1) les quipes de dv ajoutent des log dans leur code en faisant de leur mieux pour diffrencier trace/debug/info/warn/error . J’utilise souvent :
    – warn : les comportements inattendus souvent des situations qui auraient pu mriter une IllegalStateException
    – info : les messages qui me donnent une ide globale du fonctionnement de la zone
    – debug : les informations dtailles dont j’ai besoin quand je troubleshoot prcisment cette zone
    – trace : les informations ultra dtailles que je ne devrais jamais activer mais que j’utilise quand en dernier recours pour dbugger une zone de code quand je suis perdu,

    2) les ops disent dans quel rpertoire 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 « expands » dans des rpertoire que les exploitants ne savent pas trouver facilement,

    3) les dv prparent 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 infrieurs (info/debug) pour des cas particuliers,

    4) les ops valident le fichier et le dploient en parallle du war/ear s’il doit tre situ l’extrieur 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 itrent conjointement pour amliorer les messages

    Cyrille (Xebia)

  21. Publié par , Il y a 9 ans

    « Juste un bmol. Il me semble que ce nest pas lapplication de dcider de la rotation ou non des logs et quand elle doit se faire. Il sagit plutt dune tche dexploitation sur laquelle ladministrateur systme doit avoir la main sans avoir modifier lapplication (ou un fichier du classpath ou que celui-ci puisse se trouver). »
    Grant une application dploye sur une 50aine de machine avec diffrents OS. Le problme est qu’un script de rotation de log est trs dpendant de l’OS et de l’installation. Quand l’installation de l’appli est gnrique, pas de souci, mais si elle ne l’est pas (rpertoire diffrent pour le plus courant, user diffrent, etc), les problmes surviennent. Laisser le framework gr cette partie rgle compltement le problme, et logback implmente 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 intgre dans le war avec une configuration de log gnrique + 1 seconde partie en dehors du war, avec rechargement chaud. L’intrt tant d’tre sr de ne pas oublier le fichier de conf ni qu’il soit modifi par erreur et en mme temps permettre pendant le run de sortir les traces de debug/trace d’une classe prcise en cas de problme ?

  22. Publié par , Il y a 9 ans

    Logback propose ce genre de fonctionnalits (include d’un autre fichier, dfinition de proprits). Ca reste basique, mais sur le point technique, a semble ralisable.

    Niveau ralisation, JMX me semble mieux appropri pour modifier les logs chaud.

  23. Publié par , Il y a 9 ans

    Bonjour,
    L’article est intressant, et les commentaires aussi.
    J’ai repr une erreur rcurrente 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 aprs n’est pas pris en compte : %d{HH:mm:ss,SSS} donne le mme 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 9 ans

    @Laurent,

    Merci pour la remarque. La coquille est corrige. J’avais activ une rotation la minute pour vrifier le comportement de logback. C’est corrig.

    Cyrille

  25. Publié par , Il y a 9 ans

    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 Sapient, 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.