Commentaires

Log me tender ♥

Introduction

Les logs tout le monde connait, configurés souvent par défaut dans les frameworks récents, ils permettent durant le développement de garder un oeil sur les différents évènements qui se déclenchent au cours de l’exécution de votre appli. Ils peuvent aussi bien faire remonter des erreurs non attrapées que nous informer de la création d’une ressource par exemple.

Lorsque l’application passe en production, nos très chers logs ne sont plus à notre disposition immédiate. Cela peut avoir quelques effets indésirables comme leur taille non maitrisée ou tout simplement le passage à la trappe d’informations capitales.

Plusieurs possibilités s’offrent à vous comme par exemple graylog et sentry, deux outils open source (what else ?) dont nous allons parler aujourd’hui.

Sentry

Sentry est un outil de tracking d’erreurs. Il est idéal pour récupérer une belle exception non catchée avec tout un contexte associé. Stacktrace, origine de l’appel, fréquence des erreurs, assignations des erreurs à un agent, possibilité de le linker à github ou gitlab pour les issues.

A noter que Sentry fournit une offre hébergée chez eux, dont une gratuite, qui peut vous permettre de tester plus rapidement et pourquoi pas l'utiliser en production.

Graylog

Graylog est un agrégateur de logs. Plusieurs sources différentes (nginx, apache, redis, syslog, etc) peuvent envoyer leurs logs vers cet outil qui met à disposition un moteur de recherche puissant ainsi que des règles de parsing de logs avancés. Il peut ressembler à Sentry sous certains aspects (pourquoi ne pas lui envoyer les exceptions ?) et peut même remplacer Sentry sous une certaine forme mais son rôle reste au final le parsing, monitoring et recherche de logs.

Installation des outils de monitoring

Les différents services seront lancés via docker afin de vous simplifier l'expérimentation.

Démarrage de la stack

Commencez par créer le fichier docker-compose qui va nous permettre de lancer la stack complète :

touch docker-compose.yml

Le contenu de celui-ci doit ressembler à cela.

# docker-compose.yml
version: '2'

services:
  redis:
    image: redis

  postgres:
    image: postgres
    environment:
      POSTGRES_USER: sentry
      POSTGRES_PASSWORD: sentry
      POSTGRES_DBNAME: sentry
      POSTGRES_DBUSER: sentry
      POSTGRES_DBPASS: sentry

  sentry:
    image: sentry
    links:
    - redis
    - postgres
    ports:
    - 9000:9000
    environment:
      SENTRY_SECRET_KEY: '!!!SECRET!!!'
      SENTRY_POSTGRES_HOST: postgres
      SENTRY_DB_USER: sentry
      SENTRY_DB_PASSWORD: sentry
      SENTRY_REDIS_HOST: redis

  cron:
    image: sentry
    links:
    - redis
    - postgres
    command: "sentry run cron"
    environment:
      SENTRY_SECRET_KEY: '!!!SECRET!!!'
      SENTRY_POSTGRES_HOST: postgres
      SENTRY_DB_USER: sentry
      SENTRY_DB_PASSWORD: sentry
      SENTRY_REDIS_HOST: redis

  worker:
    image: sentry
    links:
    - redis
    - postgres
    command: "sentry run worker"
    environment:
      SENTRY_SECRET_KEY: '!!!SECRET!!!'
      SENTRY_POSTGRES_HOST: postgres
      SENTRY_DB_USER: sentry
      SENTRY_DB_PASSWORD: sentry
      SENTRY_REDIS_HOST: redis

  mongo:
    image: mongo:3

  elasticsearch:
    image: docker.elastic.co/elasticsearch/elasticsearch:5.5.2
    environment:
      - http.host=0.0.0.0
      - xpack.security.enabled=false
      - "ES_JAVA_OPTS=-Xms512m -Xmx512m"
    ulimits:
      memlock:
        soft: -1
        hard: -1
    mem_limit: 1g

  graylog:
    image: graylog/graylog:2.3.2-1
    environment:
      - GRAYLOG_PASSWORD_SECRET=somepasswordpepper
      # Password: admin
      - GRAYLOG_ROOT_PASSWORD_SHA2=8c6976e5b5410415bde908bd4dee15dfb167a9c873fc4bb8a81f6f2ab448a918
      - GRAYLOG_WEB_ENDPOINT_URI=http://127.0.0.1:9001/api
    links:
      - mongo
      - elasticsearch
    ports:
      - 9001:9000
      - 514:514
      - 514:514/udp
      - 12201:12201
      - 12201:12201/udp

Une fois fait, reste à démarrer l'ensemble de nos éléments :

docker-compose up -d

Si vous souhaitez garder un oeil sur l'avancement :

docker-compose logs -f

Sentry nécessite une étape supplémentaire avant de pouvoir démarrer :

docker-compose exec sentry sentry upgrade

Si tout se passe bien, nos serveurs sont disponibles sur http://localhost:9000 pour graylog et http://localhost:9001 pour Sentry.

Graylog fournit par défaut l’utilisateur admin/admin pour vous connecter. Une fois connecté, il suffit de créer une nouvelle input de type GELF UDP sur le port 12201

Sentry nécessite la création d’un utilisateur et d’un projet manuellement. Une fois le projet créé, il suffit de se rendre dans la partie "Project Settings" du projet pour récupérer le DSN dans la rubrique "Client Keys"

Installation de symfony

Passons rapidement sur la magnifique version 4 de symfony :) et jetons les bases de notre projet :

composer create-project symfony/skeleton ./

Pour la gestion des logs, le choix le plus pragmatique reste le projet Monolog. Il gère, bien entendu, les logs à la perfection et a le mérite d’être compatible directement avec les outils qui nous intéressent.

Bien d’autres sont disponibles sur leur site officiel.

Même s’il est compatible avec ces outils, quelques librairies supplémentaires sont nécessaires pour communiquer avec graylog et sentry. Installons les :

composer require symfony/monolog-bundle graylog2/gelf-php sentry/sentry

Configuration de Monolog

Voyons comment renseigner notre fichier de configuration pour que notre appli puisse communiquer avec l’extérieur

Nous créons deux channels. Les channels servent à identifier l’origine ou le but d’une famille de log. Cela permet de centraliser par exemple toutes les lignes de log relatives aux commandes de notre application.

channels: ["order", "invoice"]

Nous créons un premier handler de type fingers_crossed. Ce type de handler agit comme un buffer de logs. Il les conservera jusqu’au franchissement du seuil définit par action_level.

Nous en profitons également pour exclure les erreurs liées à une page absente qui en soit ne sont pas des erreurs et peuvent polluer votre flux.

Enfin, nous lui indiquons qu’en cas de déclenchement, les logs doivent être transmis à un autre handler que nous appelons grouped_main.

handlers:
    main:
        type: fingers_crossed
        action_level: debug
        channels: ["!event"]
        handler: grouped_main
        excluded_404s:
            - ^/

grouped_main est de type group (#kaptainobvious). Cela signifie tout simplement qu’il transmettra les lignes de logs aux membres de ce groupe.

grouped_main:
    type: group
    members: [local_rotated, sentry, graylog]

Le handler sentry filtre au niveau error afin d’évacuer les niveaux inférieurs qui n’ont pas vocation à être monitorés de près dans cet outil. Vous pouvez référencer ici le DSN de votre projet sentry configuré plus haut.

sentry:
    level: error
    type: raven
    dsn: "%sentry.dsn%"

Le handler graylog ne filtre lui que sur le niveau info. Nous pourrons ainsi suivre un plus grand nombre d’informations que sur Sentry.

graylog:
    level: info
    type: gelf
    publisher:
        hostname: 127.0.0.1
        port: 12201

Ci-dessous, le fichier complet :

# config/packages/dev/monolog.yal
monolog:
    channels: ["order", "invoice"]
    handlers:
        main:
            type: fingers_crossed
            action_level: debug
            channels: ["!event"]
            handler: grouped_main
            excluded_404s:
                - ^/

        grouped_main:
            type: group
            members: [local_rotated, sentry, graylog]

        local_rotated:
            level: debug
            type: stream
            path: "%kernel.logs_dir%/%kernel.environment%.log"

        sentry:
            level: error
            type: raven
            dsn: "%sentry.dsn%"

        graylog:
            level: info
            type: gelf
            publisher:
                hostname: 127.0.0.1
                port: 12201

        console:
            type:   console
            process_psr_3_messages: false
            channels: ["!event", "!doctrine", "!console"]

Lancement de notre appli

./bin/console server:run

Une fois l'appli lancée, pointez votre navigateur sur http://localhost:8000. Vous devriez être accueilli par une page 404. Afin de tester, plusieurs possibilités s'offrent à vous :

Log classique : votre application utilise déjà le logger ? Vous devriez voir vos lignes arriver dans graylog. Si ces logs sont d'un niveau supérieur ou égal à error, ils seront également envoyés sur Sentry.

Lancement d'une exception : Editez un controller et lancez une exception. Celle-ci sera transmise à Sentry ainsi que le contexte qu'elle transporte (stacktrace, referrer etc...)

Conclusion

Comme nous l'avons vu, quelques lignes de configuration suffisent à avoir un suivi des logs solides pour un début en production. Avec ces outils, Sentry vous tiendra au courant de toutes erreur non catchée tandis que Graylog vous permettra de garder un oeil sur le comportement global de votre application.

Bonnes pratiques

Maitriser la taille des logs sur fichiers

Plutôt que le classique stream, préférer le type rotating_file. Il se chargera tout seul de la rotation des fichiers de log et vous évitera des mauvaises surprises liées à l’oubli de la configuration de logrotate (qui reste le plus efficace dans ce domaine)

local_rotated:
    type: rotating_file
    max_files: 15
    path: "%kernel.logs_dir%/%kernel.environment%.log"
    level: debug

Ajouter du contexte

Prenons la ligne de log suivante

$this->logger->info(sprintf("L'utilisateur N°%d vient de créer la commande N°%d",
  $user->getId(),
  $order->getId()
));

# [2017-12-16 15:04:21] L'utilisateur N°123 vient de créer la commande N°456

Extraire l’information n’est pas particulièrement aisée et non structurée :|

Dans des cas comme celui-là, Monolog permet le passage de context relatif à la ligne de log créée. Ce contexte a le mérite de structurer le message en identifiant de manière précise le nom d’une information par exemple.

$this->logger->info('user_command_created', [
  'user_id'  => $user->getId(),
  'order_id' => $order->getId()
]);

Monolog le propagera également lors de la transmission à Sentry et à Graylog. Il sera par exemple possible par le suite de faire une recherche précise sur le user_id ou sur toute autre information envoyés.

Attention à la quantité de logs produite

Suivant la quantité d’information loggées et le nombre de requêtes par seconde traitées, la gestion des logs peut rapidement se compliquer. Saturation de votre espace disque serveur, temps de réponse à rallonge de votre outil de monitoring…

Pour palier à cela, l’introduction d’une queue de traitement pour vos logs peut vous aider à absorber des charges anormales auxquelles vous pourriez être confrontés.