Ecrire des logs manipulables

Cet article a été publié depuis plus de 6 mois, cela signifie que le contenu peut ne plus être d'actualité.

La notion de logs (ou journaux en français) est primordiale en développement. Ce sont eux qui permettent de faire remonter les informations générées par l’application une application. Ces derniers peuvent se présenter sous différentes formes : fichiers, base de données, sortie écran… Mais comment est-il possible de traiter ces différents retours facilement ?

Les données recueillies par les fichiers de logs informent des diverses situations rencontrées lors l’exécution du code. Cela peut être des cas inattendus (exceptions), des erreurs, des informations sur les actions effectuées par les utilisateurs. Ils permettent aux développeurs de retracer l’exécution d’un bout de code. Les fichiers alors générés peuvent contenir un grand nombre d’informations et les analyser peut s’avérer être une tâche longue et complexe.

Bien entendu les informations écrites dans les fichiers de logs sont dépendantes de la phase de vie du projet. Il est ainsi fort probable que pendant la phase de développement, une grande quantité d’informations soient enregistrées afin d’avoir un maximum de détails. Par contre, une fois en production, le niveau de log sera réduit à son minimum afin d’avoir les informations essentielles.

De ce fait, une analyse automatique des logs s’avère très intéressante et peut révéler de nombreuses informations. Mais comment écrire des logs qui puissent être facilement traités et analysés par une machine ?

Pour cela, je vais m’appuyer sur les PSR (Propose a Standards Recommendation) de PHP et plus particulièrement la PSR-3 qui concerne les bibliothèques de journalisation. Si vous ne connaissez pas les PSR, il s’agit de recommandations validées par le PHP FIG (PHP Framework Interoperability Group) ayant pour objectif d’améliorer l’interopérabilité entre les frameworks PHP.

Pour résumer rapidement, dans PSR-3, on retrouve 8 niveaux de log avec autant de méthodes associées. Par exemple, le niveau DEBUG est associé à la méthode public function debug($message, array $context = array()). On retrouve également une fonction générique public function log($level, $message, array $context = array());

Ce que l’on peut remarquer avec les signatures de ces fonctions, c’est qu’elle ne se limite pas à écrire un message dans un fichier. Elles permettent également de renseigner un contexte d’exécution. Il est donc intéressant lorsque l’on écrit une ligne de log, de fournir des données sur l’état de l’application au moment donné. Par exemple :

$logger->info('User deletion', [
  'userLogged'  => $userLogged->getId(),
  'userDeleted' => $userDeleted->getId(),
]);

Le code ci-dessus génère la ligne suivante :

[2015-06-28 16:11:12] myapp.INFO: User deletion {"userLogged":1234,"userDeleted":7412} []

Cet exemple n’est pas très intéressant, je me limite à fournir les identifiants des utilisateurs concernés par l’action de suppression d’un utilisateur. De plus, si l’utilisateur est physiquement supprimé de la base de données, le fait d’avoir son identifiant est inutile. Il aurait été plus logique de donner les objets à la fonction de log qui les aurait sérialisés pour l’écrire du fichier.

Il est intéressant de noter que la ligne de log générée automatiquement analysée car elle est créée selon un schéma bien défini. Elle peut ainsi être découpée en 5 :

  1. La date d’enregistrement : 2015-06-28 16:11:12
  2. Le niveau de log : myapp.INFO
  3. Le message de log : User deletion
  4. Le contexte d’exécution : {"userLogged":1234,"userDeleted":7412}
  5. Des données additionnels (dont je ne parle pas dans ce billet) : []

Il est donc très facile d’analyser les fichiers de manière automatique. L’analyse peut permettre d’obtenir des informations sur les erreurs rencontrées le plus souvent par l’application, mais également de faire des statistiques sur certaines utilisations de l’application. Ce travail d’analyse peut être réduit à son minimum car ce genre de logs peut être envoyé et analysé par des plateformes de type ELK (Elasticsearch Logstash Kibana).

Notons au passage que cette ligne de log aurait pu être plus difficilement analysable si elle avait été écrite de la manière suivante :

$logger->info(sprintf('User "%d" delete user "%d"',
  $userLogged->getId(),
  $userDeleted->getId()
);
// => [2015-06-28 16:11:12] myapp.INFO: User "1234" delete user "7412" []

Le problème avec cette méthode est que le message de log n’est pas “unique” pour une action donnée. Effectivement, l’action ayant déclenché l’écriture de la ligne est mélangée avec son contexte d’exécution.

Si vous souhaitez en savoir plus sur l’utilisation des fichiers de logs, Grégoire PINEAU, développeur chez SensioLabs a fait une excellente présentation lors du SFLive 2015 sur le sujet.