Tirer partie du logger Symfony

La journalisation, c’est l’assurance vie du développeur : quand un client vous signale que son application fonctionne mal par intermittence, les marges de manoeuvres sont limitées. Heureusement, Symfony dispose d’outils plutôt sympathiques pour nous aider à diagnostiquer un incident passé. Bienvenue dans le monde de la journalisation ! 🙂

Notons que Symfony utilise le désormais célèbre monolog. Comme tous les services, il est facilement accessible sous forme de service (merci l’injection de dépendance) dans n’importe contrôleur :

namespace App\Controller\Api;

use Symfony\Bundle\FrameworkBundle\Controller\AbstractController;
use Psr\Log\LoggerInterface;

class FooController extends AbstractController
{
    public function edit(LoggerInterface $logger)
    {
        $logger->info('Hey ! I am writing in logs !!');
    }
}

Et voilà, nous savons déjà écrire dans les logs Symfony ! 😇
Ah ah, c’est bien beau tout ça, mais où retrouver ces messages (ou entrées logs) ? Eh bien malheureusement, à ce stade, il se peut qu’il ne se passe rien (ou presque) et par conséquent nos messages sont perdus dans l’immensité de l’univers Symfony. Si cela arrive, c’est que le bundle monolog n’est pas installé. Il va donc devoir le faire manuellement :

# composer require symfony/monolog-bundle

Une fois le problème résolu, on peut (enfin) voir apparaître nos messages dans le Symfony profiler :

Handlers (gestionnaires)

A chaque fois qu’on va envoyer une entrée vers monolog (comme ci dessus), ce dernier va appeler la liste (dans l’ordre) des « handlers » (on appelle ça une pile) définis et leur passer la dite entrée. Un « handler » peut être perçu comme un gestionnaire qui va écrire le message quelque part (fichier, base de données, mail, etc) sous certaines conditions. Sous Symfony 6, en mode dev, on a les 2 gestionnaires suivants (config/packages/monolog.yaml) :

when@dev:
    monolog:
        handlers:
            main:  ①
                type: stream  ②
                path: "%kernel.logs_dir%/%kernel.environment%.log"  ③
                level: debug  ④
                channels: ["!event"]  ⑤
            console:  ①
                type: console  ②
                process_psr_3_messages: false
                channels: ["!event", "!doctrine", "!console"]

Fichier de configuration Monolog.

Un éclaircissement s’impose :

• ① → main et console sont les noms des gestionnaires.
• ② → type défini le type du gestionnaire. Pour l’instant on se cantonne à stream (système de fichier).
• ③ → en cas de type « stream », on indique le chemin fu fichier qui va stocker les entrées.
• ④ → level est le niveau d’erreur minimal requis pour déclencher le gestionnaire.
• ⑤ → channels permet d’indiquer quelles catégories d’entrées sont autorisées ou non.

J’admets, ça déroute un peu au début… La question est : que fait le gestionnaire lorsqu’il reçoit une entrée ? Réponse : cela dépend d’abord du niveau d’erreur et du « channel ».

Les gestionnaires sont appelés dans l’ordre dans lequel ils sont définis dans la clé handlers. Pour cette raison, il est conseillé de ne pas utiliser plusieurs fichiers de configuration et d’utiliser l’annotation Symfony when@dev.

Niveaux d’erreurs

Dans l’ordre (du moins important au plus important), les niveaux d’erreurs (« levels ») disponibles dans monolog :

• debug
• info
• notice
• warning
• error
• critical
• alert
• emergency

Le niveau d’erreurs va servir à Monolog pour déterminer si le gestionnaire doit être utilisé ou non. Car comme je l’ai dit plus haut, à chaque fois que l’on écrit :

$logger->...

Monolog va tester tous les gestionnaires définis dans le fichier de configuration et déterminer à chaque fois s’il doit traiter la demande. Reprenons l’exemple précédant :

$logger->info('Hey ! I am writing in logs !!');

D’après le fichier de configuration, nous avons deux gestionnaires : « main » et « console ». Dans l’ordre, :

1. Monolog regarde le niveau d’erreur (clé level) du gestionnaire « main » : ici c’est debug.
2. debug est le niveau minimal requis pour que le gestionnaire « main » traiter le message. Comme on a utilisé la méthode info ($logger->info), le message a un niveau d’erreur « info » qui est supérieur à « debug ». Le gestionnaire « main » traite le message.
3. Monolog regarde le niveau d’erreur du gestionnaire « console » : ici c’est debug car la clé level est absente de la définition de ce gestionnaire.
4. « debug étant le niveau d’erreur minimal, le gestionnaire « console » ne peut que traiter le message.

Prenons un autre exemple. D’abord modifions la configuration Monolog comme ci-après :

when@dev:
    monolog:
        handlers:
            main:
                type: stream
                path: "%kernel.logs_dir%/%kernel.environment%.log"
                level: warning  ①
                channels: ["!event"]
            console:
                type: console
                process_psr_3_messages: false
                channels: ["!event", "!doctrine", "!console"]

• ① → le niveau minimal d’alerte du gestionnaire « main » est maintenant warning.

Puis exécutons ce code :

use Psr\Log\LoggerInterface;

class FooController extends AbstractController
{
    public function edit(LoggerInterface $logger)
    {
        $logger->debug('Hey ! I am writing in logs !!');   ①
        $logger->info('Hey ! I am writing in logs !!');   ②
        $logger->notice('Hey ! I am writing in logs !!');   ③
        $logger->warning('Hey ! I am writing in logs !!');   ④
        $logger->error('Hey ! I am writing in logs !!');   ⑤
        $logger->critical('Hey ! I am writing in logs !!');   ⑥
        $logger->alert('Hey ! I am writing in logs !!');   ⑦
        $logger->emergency('Hey ! I am writing in logs !!');   ⑧
    }
}

Que va t’il se passer ? Comme tout à l’heure voyons le déroulé des opérations, dans l’ordre. La première ligne à traiter est ① :

1. Monolog regarde le niveau d’erreur (clé level) du gestionnaire « main » : warning.
2. le niveau du message est debug, ce qui est inférieur à warning. Le gestionnaire ne traite pas le message.
3. Monolog regarde le niveau d’erreur du gestionnaire « console » : debug.
4. le niveau du message est debug, ce qui est égal à debug. Le gestionnaire « console » traite le message.

Comme il n’y a plus de gestionnaires dans la pile, on passe à la ligne ② :

1. Monolog regarde le niveau d’erreur du gestionnaire « main » : warning.
2. le niveau du message est info, ce qui est inférieur à warning. Le gestionnaire ne traite pas le message.
3. Monolog regarde le niveau d’erreur du gestionnaire « console » : debug.
4. le niveau du message est info, ce qui est supérieur à debug. Le gestionnaire traite le message.

Comme il n’y a plus de gestionnaires dans la pile, on passe à la ligne ③ :

1. Monolog regarde le niveau d’erreur du gestionnaire « main » : warning.
2. le niveau du message est notice, ce qui est inférieur à warning. Le gestionnaire ne traite pas le message.
3. Monolog regarde le niveau d’erreur du gestionnaire « console » : debug.
4. le niveau du message est notice, ce qui est supérieur à debug. Le gestionnaire traite le message.

Comme il n’y a plus de gestionnaires dans la pile, on passe à la ligne ④ :

1. Monolog regarde le niveau d’erreur du gestionnaire « main » : warning.
2. le niveau du message est warning, ce qui est égal à warning. Le gestionnaire traite le message.
3. Monolog regarde le niveau d’erreur du gestionnaire « console » : debug.
4. le niveau du message est warning, ce qui est supérieur à debug. Le gestionnaire traite le message.

Et ainsi de suite, inutile d’aller plus loin, à partir de la ligne ④ les deux gestionnaires sont utilisés, contre un seul avant la ligne ④. Donc si vous avez suivi 😝, et je suis sûr que c’est le cas, on retrouve 5 lignes dans le gestionnaire « main » :

[2023-03-20T19:45:56.784066+00:00] request.INFO: Matched route "_wdt". [...]
[2023-03-20T19:51:05.648407+00:00] app.WARNING: Hey ! I am writing in logs !! [] []
[2023-03-20T19:51:05.653301+00:00] app.ERROR: Hey ! I am writing in logs !! [] []
[2023-03-20T19:51:05.654188+00:00] app.CRITICAL: Hey ! I am writing in logs !! [] []
[2023-03-20T19:51:05.655030+00:00] app.ALERT: Hey ! I am writing in logs !! [] []
[2023-03-20T19:51:05.656267+00:00] app.EMERGENCY: Hey ! I am writing in logs !! [] []

Notez que la pile des gestionnaires est toujours appelée en totalité, c’est à dire qu’une même entrée peut être écrite à plusieurs endroits (l’utilisation d’un gestionnaire n’arrête pas le traitement de la pile).

Format d’une entrée log

Dans le paragraphe précédent, nous avons vu qu’une entrée dans un log ressemble à ceci :

[2023-03-20T19:51:05.656267+00:00] app.EMERGENCY: Hey ! I am writing in logs !! [] []

Plus généralement, on peut écrire une telle entrée :

[date] handler.LEVEL: <message> <context> <extra-data>

• [date] : date de l’entrée log, au format Y-m-d\TH:i:sP.
• handler : le nom du gestionnaire utilisé. Par défaut Symfony utilise app.
• LEVEL : le niveau d’erreur de l’entrée log.
• <message> : le contenu de l’entrée log, sous forme de message explicite.
• <context> : informations additionnelles (ou metadata) utiles pour la compréhension du message.
• <extra-data> : informations additionnelles (non accessible depuis les assistants Symfony).

Channels

Les « channels » servent à identifier les entrées log. A chaque channel correspond un service monolog.logger.XXX (remplacez XXX par le nom du channel). Pour lister les « channels » utilisés dans Symfony, on liste les services correspondant :

# ./bin/console debug:container monolog.log

# Output
  [0 ] monolog.logger
  [1 ] monolog.logger_prototype
  [2 ] monolog.activation_strategy.not_found
  [3 ] monolog.handler.fingers_crossed.error_level_activation_strategy
  [4 ] monolog.formatter.chrome_php
  [5 ] monolog.formatter.gelf_message
  [6 ] monolog.formatter.html
  [7 ] monolog.formatter.json
  [8 ] monolog.formatter.line
  [9 ] monolog.formatter.loggly
  [10] monolog.formatter.normalizer
  [11] monolog.formatter.scalar
  [12] monolog.formatter.wildfire
  [13] monolog.formatter.logstash
  [14] monolog.http_client
  [15] monolog.processor.psr_log_message
  [16] monolog.handler.main                ①
  [17] monolog.handler.console             ②
  [18] monolog.logger.request
  [19] monolog.logger.console
  [20] monolog.logger.cache
  [21] monolog.logger.mailer
  [22] monolog.logger.translation
  [23] monolog.logger.php
  [24] monolog.logger.event
  [25] monolog.logger.router
  [26] monolog.logger.profiler
  [27] monolog.logger.doctrine
  [28] monolog.logger.security
  [29] monolog.logger.deprecation
  [30] monolog.handler.null_internal
 > 

Listing 7.1 – Liste des services Monolog sous Symfony.

On retrouve nos deux gestionnaires du paragraphe précédent :

• ① → gestionnaire « main » qui a comme alias « monolog.handler.main» .
• ② → gestionnaire « console » qui a comme alias « monolog.handler.console» .

Inspectons le service monolog.handler.main en détail :

# php bin/console debug:container monolog.handler.main

Ce qui devrait afficher quelque chose de similaire à ceci :

Information for Service "monolog.handler.main"
==============================================

 Stores to any stream resource

 ---------------- ------------------------------- 
  Option           Value                          
 ---------------- ------------------------------- 
  Service ID       monolog.handler.main           
  Class            Monolog\Handler\StreamHandler  
  Tags             kernel.reset (method: reset)   
  Calls            pushProcessor                  
  Public           no                             
  Synthetic        no                             
  Lazy             no                             
  Shared           yes                            
  Abstract         no                             
  Autowired        no                             
  Autoconfigured   no                             
 ---------------- ------------------------------- 

Le service monolog.handler.main est donc une instance de la classe Monolog\Handler\StreamHandler. Faisant la même chose avec monolog.handler.console :

 ---------------- ----------------------------------------------- 
  Option           Value                                          
 ---------------- ----------------------------------------------- 
  Service ID       monolog.handler.console                        
  Class            Symfony\Bridge\Monolog\Handler\ConsoleHandler  
  Tags             kernel.event_subscriber                        
                   kernel.reset (method: reset)                   
                   container.no_preload                           
  Public           no                                             
  Synthetic        no                                             
  Lazy             no                                             
  Shared           yes                                            
  Abstract         no                                             
  Autowired        no                                             
  Autoconfigured   no                                             
 ---------------- ----------------------------------------------- 

Cette fois on a une instance de la classe Symfony\Bridge\Monolog\Handler\ConsoleHandler.

On peut en déduire qu’avec Symfony, la classe du service défini le channel de l’entrée log.

Jusque là, on peut donc écrire le tableau suivant :

Logger	Classe
monolog.handler.main	StreamHandler
monolog.handler.console	ConsoleHandler

Si vous avez suivi le raisonnement, il vient qu’on sait désormais choisir le channel qu’on veut utiliser pour nos entrées : il suffit de correctement paramétrer l’injection de dépendance, en utilisant la classe associée au channel souhaité, en se référant à la liste des services Monolog.

Exemple : je veux utiliser le « channel » doctrine pour écrire dans mes logs. D’après la liste, son alias est monolog.logger.doctrine. Affichons le détail de ce service :

---------------- ------------------------------- 
  Service ID       monolog.logger.doctrine        
  Class            Symfony\Bridge\Monolog\Logger  

A ce stade nous avons deux façons de faire, et comme il ne s’agit de faire un cours sur l’injection de dépendance, j’en choisi une. Commençons par injecter l’interface LoggerInterface dans un contrôleur :

namespace App\Controller\Api;

use Symfony\Bundle\FrameworkBundle\Controller\AbstractController;
use Psr\Log\LoggerInterface;

class FooController extends AbstractController
{
    /**
     * @var LoggerInterface
     */
    private $logger;

    public function __construct(LoggerInterface $logger)
    {
        $this->logger = $logger;
    }

    public function edit()
    {
        $this->logger->info('Hey ! I am writing in logs !!');
        $this->logger->critical('Oops something bad is happening');
    }
}

Puis on spécifie le service à utiliser dans services.yaml :

services:
    App\Controller\Api\FooController:
        arguments:
            $logger: '@monolog.logger.doctrine'

On vérifie ensuite que le « channel » doctrine est bien utilisé :

[2023-01-06 13:07:46] doctrine.INFO: Hey ! I am writing in logs !! [] []
[2023-01-06 13:07:46] doctrine.CRITICAL: Oops something bad is happening [] []

Type de gestionnaire

Pour le moment on a utilisé un seul type de gestionnaire : stream. Il en existe d’autres :

• fingers_crossed : ce gestionnaire stocke dans un buffer les entrées log qu’il reçoit. Si une entrée atteint un certain niveau d’erreur, cela déclenche le « vidage » du buffer en direction d’un autre handler. Plus d’explications dans le paragraphe dédié au gestionnaire finger_crossed.
• rotating_file : permet de ne conserver les logs (dans le cas d’un stockage dans un système de fichier) qu’un certain nombre de jours. Plus d’explications dans le paragraphe dédié au gestionnaire rotating_file.
• syslog : ce gestionnaire utilise la fonction php syslog pour l’entrée log reçue.

Plusieurs fichiers de logs

Grâce aux « channels », on va pouvoir séparer nos logs dans différents fichiers. Supposons que je veuille que les entrées log de doctrine soient stockées dans un fichier séparé. Il suffit de créer un gestionnaire qui ne va prendre en compte que le « channel » doctrine, et pas les autres :

monolog:
    handlers:
        doctrine_logging:
            type: stream
            path: "%kernel.logs_dir%/doctrine.%kernel.environment%.log"
            level: debug
            channels: ['doctrine']   ①

On a maintenant un fichier /var/log/doctrine.dev.log qui contient, entre autres, nos deux entrées log :

[2018-10-06 21:28:35] doctrine.INFO: Hey ! I am writing in logs !! [] []
[2018-10-06 21:28:35] doctrine.CRITICAL: Oops something bad is happening [] []

Mais ces deux entrées se trouvent encore dans /var/log/dev.log. C’est normal, il faut modifier la configuration du gestionnaire principal pour qu’il écarte le channel doctrine :

monolog:
    handlers:
        main:
            type: stream
            path: "%kernel.logs_dir%/%kernel.environment%.log"
            level: debug
            channels: ["!event", "!doctrine"]   ①

Voyez la syntaxe pour exclure un channel : !channel_name.

Rotation des logs

Pour créer un gestionnaire qui prend en charge la rotation des logs, il suffit de le spécifier dans la clé de configuration :

monolog:
    handlers:
        main:
            type:  rotating_file    ①
            path:  '%kernel.logs_dir%/%kernel.environment%.log'
            level: debug
            max_files: 10    ②

• ① → rotating_file indique au gestionnaire de prendre en charge la rotation des logs.
• ② → max_files indique la rétention du gestionnaire en jours (dans nos cas 10 jours). Au delà de cette limite, les fichiers sont détruits.

Dans ce cas, monolog crée un fichier par jour.

Filtrer les messages d’erreurs

En production, on a souvent besoin d’une journalisation réduite. Dans ce cas, on utilise le gestionnaire de type fingers_crossed qui va agir comme un buffer : il filtre toutes les entrées de la requête courante puis les transfère à un autre gestionnaire que lorsqu’une entrée log a un niveau d’erreur au moins équivalente à un seuil (qu’on défini bien sûr). Ce type de gestionnaire n’écrit rien du tout, il agit seulement comme un filtre.

Examinons la configuration du mode production de Symfony :

when@prod:
    monolog:
        handlers:
            main:
                type: fingers_crossed  ①
                action_level: error    ②
                handler: nested        ③
                excluded_http_codes: [404, 405]
                buffer_size: 50 # How many messages should be saved? Prevent memory leaks
            nested:    ④
                type: stream
                path: var/log/prod.log    ⑤
                formatter: monolog.formatter.json
            console:
                type: console
                process_psr_3_messages: false
                channels: ["!event", "!doctrine"]
            deprecation:
                type: stream
                channels: [deprecation]
                path: php://stderr

• ① → création du gestionnaire de type finger_crossed.
• ② → le seuil de déclenchement est positionné à level.
• ③ → indique le gestionnaire à utiliser lors du dépassement du seuil.
• ④ → définition du gestionnaire qui est à utiliser lors du dépassement du seuil défini à la ligne ②.
• ⑤ → les messages sont écrit dans var/log/prod.log.

Le gestionnaire nested possède lui aussi une clé level. Il faut bien entendu que la valeur indiquée dans cette clé soit inférieure à la valeur indiquée dans ②.

L’intérêt de ce gestionnaire est majeur : s’il n’y a pas d’erreurs d’un certain niveau, on n’encombre pas les logs inutilement… Par contre, en cas d’erreur sérieuse, on a tous les messages d’erreur à notre disposition.

Cas particulier de la « containérisation »

Avec l’avènement de la containérisation, il peut être intéressant d’écrire les logs (en production) directement sur la sortie du container. Dans ce cas, il suffit de l’indiquer dans la clé path de la configuration du gestionnaire nested :

path: php://stderr

Logs système

Un autre type de gestionnaire intéressant est syslog. Il permet de stocker des entrées log via le système de log de la machine qui fait tourner l’application. Par exemple, en production, on peut ajouter un tel gestionnaire :

monolog:
    handlers:
        main:
            type: fingers_crossed
            action_level: error
            handler: nested
            excluded_404s:
                # regex: exclude all 404 errors from the logs
                - ^/
        nested:
            type: stream
            path: "%kernel.logs_dir%/%kernel.environment%.log"
        # still passed *all* logs, and still only logs error or higher
        syslog_handler:
            type: syslog
            level: debug

Souvenez vous, les gestionnaires sont appelés dans l’ordre. Donc le gestionnaire syslog sera toujours appelé et il inscrira toutes les entrées dans les logs de la machine. Par exemple, sur une machine debian, le fichier est /var/log/syslog.

Happy debugging

Monolog est compatible firephp et chromephp. Il suffit d’ajouter un gestionnaire :

when@dev
    monolog:
        handlers:
            firephp:
                type: firephp
                level: info

L’extension du même nom doit être installée et activée sur le navigateur. Après installation et configuration de l’extension, les logs apparaissent dans la console :

Ce gestionnaire est à réserver au mode dev bien sûr… 😝

Références externes

• How to Log Messages to different Files (en)
• Symfony Logging (en)
• Symfony 2 : Configuration des logs Monolog (fr)