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

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.