Utilisation de Logbook pour tracer les appels HTTP au sein d'une API REST Spring Boot

Dans le cadre de l’une de mes missions, nous avons mis en place une API de recherche de données sur des entreprises développée à l’aide de Spring Boot. Les données étaient collectées auprès de divers fournisseurs d’information dont une base de données ElasticSearch contenant les données propres au client.

Dans ce contexte, nous avions un besoin de traçabilité sur le comportement de notre API ainsi que nos interactions avec nos fournisseurs.
Afin de répondre à ce besoin, nous avons utilisé Logbook, une librairie open source de log Java développée par Zalando.

Voyons ensemble comment Logbook nous a permis de répondre à cette problématique.

Les mains dans le code

Créons notre application

Nous allons donc démontrer l’utilisation de Logbook à travers le développement d’une API REST qui va exposer un endpoint de recherche d’entreprises.
Pour cela, nous allons créer une application maven avec deux sous modules Spring Boot :

• Une API REST exposant notre endpoint de recherche (module search-api)
• Une API qui sera notre fournisseur d’information et sera appelée par notre API de recherche (module provider-api)

Commençons par créer notre projet multi-module maven. Pour cela, on crée un simple projet maven dans lequel nous allons supprimer le dossier src et ajouter les dépendances que l’on va utiliser dans nos sous modules.

Nous aurons deux sous module Spring Boot (version 2.3.1) écrits en Java 11

Nous utiliserons également les dépendances à lombok pour nous abstraire des boiler plates classiques et le client HTTP Feign (voir https://blog.ippon.fr/2016/09/21/feign-encore-un-client-http/ ).

Nous aurons ainsi le pom.xml suivant

...
<properties>
        <spring-boot.version>2.3.1.RELEASE</spring-boot.version>
        <maven-compiler-plugin.version>3.8.1</maven-compiler-plugin.version>
        <lombok.version>1.18.16</lombok.version>
        <logbook.version>2.1.0</logbook.version>
        <squareup-okhttp.version>4.1.0</squareup-okhttp.version>
        <feign.version>10.11</feign.version>
    </properties>

...

<dependencyManagement>
       <dependencies>

           ...

           <!-- Dépendances qui va nous permettre via les annotations de nous abstraire de l'écriture de boiler plate
           type constructeurs, getters/setters, etc -->
           <dependency>
               <groupId>org.projectlombok</groupId>
               <artifactId>lombok</artifactId>
               <version>${lombok.version}</version>
               <scope>provided</scope>
           </dependency>

           <!-- Dépendance à la librairie que l'on va présenter dans ce blog pour logger les requetes HTTP -->
           <dependency>
               <groupId>org.zalando</groupId>
               <artifactId>logbook-bom</artifactId>
               <version>${logbook.version}</version>
               <type>pom</type>
               <scope>import</scope>
           </dependency>

           <!-- Dépendances au client HTTP que l'on va utiliser -->
           <dependency>
               <groupId>io.github.openfeign</groupId>
               <artifactId>feign-core</artifactId>
               <version>${feign.version}</version>
           </dependency>
           <dependency>
               <groupId>io.github.openfeign</groupId>
               <artifactId>feign-jackson</artifactId>
               <version>${feign.version}</version>
           </dependency>
           <dependency>
               <groupId>io.github.openfeign</groupId>
               <artifactId>feign-java11</artifactId>
               <version>${feign.version}</version>
           </dependency>
           <dependency>
               <groupId>io.github.openfeign</groupId>
               <artifactId>feign-okhttp</artifactId>
               <version>${feign.version}</version>
           </dependency>

           <!-- Dépendance au client okhttp3 utilisée par les libs feign-okhttp et par logbook-okhttp
           Cela va nous permettre de ne pas avoir de conflit entre les versions utilisées par ces libs -->
           <dependency>
               <groupId>com.squareup.okhttp3</groupId>
               <artifactId>okhttp</artifactId>
               <version>${squareup-okhttp.version}</version>
               <scope>compile</scope>
           </dependency>
       </dependencies>
   </dependencyManagement>

   ...

</project>

Nous pouvons maintenant créer nos deux sous modules search-api et provider-api.

Search API

Pour construire notre première API REST, nous allons construire notre POM en spécifiant notamment les dépendances à logbook que nous allons utiliser

...

   <dependencies>
       ....

       <!-- Dépendances pour ajouter logbook à notre API spring boot avec la configuration par défaut  -->
       <dependency>
           <groupId>org.zalando</groupId>
           <artifactId>logbook-spring-boot-starter</artifactId>
       </dependency>
       <!-- Dépendance pour utiliser logstash dans nos log généré par logbook -->
       <dependency>
           <groupId>org.zalando</groupId>
           <artifactId>logbook-logstash</artifactId>
       </dependency>
       <!-- Dépendance pour utiliser logbook avec le client okhttp -->
       <dependency>
           <groupId>org.zalando</groupId>
           <artifactId>logbook-okhttp</artifactId>
       </dependency>

       ...
   </dependencies>

...

Au niveau du code fonctionnel, nous allons mettre en place une architecture simple composée de :

• Un controller qui va exposer notre endpoint
• Un service qui va être appelé par le controller et appliquer la logique métier
• Des modèles d’objets qui vont être utilisés

On a donc les classes suivantes :

• Le controller qui va exposer notre endpoint de recherche via une méthode GET. Il va se charger de récupérer les critères de recherches et les passer au service de recherche qui va nous renvoyer les sociétés trouvées :

package fr.ippon.search.functional.controller;

import fr.ippon.search.functional.model.Company;
import fr.ippon.search.functional.model.Criteria;
import fr.ippon.search.functional.service.SearchService;
import lombok.AllArgsConstructor;
import org.springframework.http.ResponseEntity;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

import java.util.List;

@RestController
@AllArgsConstructor
public class SearchController {

   private final SearchService searchService;

   @GetMapping("/companies")
   public ResponseEntity<List<Company>> searchCompanies(Criteria criteria) {
       return ResponseEntity.ok(searchService.searchCompanies(criteria));
   }
}

• Un service qui va utiliser notre client pour renvoyer la liste de Company. Ici on va juste se contenter de renvoyer la réponse de notre provider :

package fr.ippon.search.functional.service;

import fr.ippon.search.functional.client.ProviderClient;
import fr.ippon.search.functional.model.Company;
import fr.ippon.search.functional.model.Criteria;
import lombok.AllArgsConstructor;
import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Service;

import java.util.List;

@Service
@AllArgsConstructor
@Slf4j
public class SearchService {

   private final ProviderClient providerClient;

   public List<Company> searchCompanies(Criteria criteria) {
       try {
           return providerClient.searchCompanies(criteria);
       } catch (Exception exception) {
           log.warn("Call to provider api went wrong", exception);
           return List.of();
       }
   }

}

• Une classe Company qui va contenir les informations d’une entreprise et une classe Criteria, qui comme son nom l’indique correspond à nos critères de recherche.

package fr.ippon.search.functional.model;

import lombok.AllArgsConstructor;
import lombok.Builder;
import lombok.Getter;
import lombok.NoArgsConstructor;

@Getter
@Builder
@NoArgsConstructor
@AllArgsConstructor
public class Company {
   private String name;
   private String streetName;
   private String country;
   private Status status;
}

package fr.ippon.search.functional.model;


public enum Status {
    A,
    C;

}

package fr.ippon.search.functional.model;

import lombok.AllArgsConstructor;
import lombok.Builder;
import lombok.Getter;
import lombok.NoArgsConstructor;
import lombok.Setter;

@Getter
@Setter
@Builder
@AllArgsConstructor
@NoArgsConstructor
public class Criteria {
   private String name;
   private String country;
}

• Un client HTTP qui va faire appel au provider grâce à la librairie Feign. Pour plus de détails sur l’utilisation de cette librairie, je vous invite à consulter l’article cité plus haut ou bien sur leur github :

package fr.ippon.search.functional.client;

import feign.Headers;
import feign.QueryMap;
import feign.RequestLine;
import fr.ippon.search.functional.model.Company;
import fr.ippon.search.functional.model.Criteria;

import java.util.List;

@Headers({"Content-Type: application/json"})
public interface ProviderClient {

    @RequestLine("GET /provider/companies")
    List<Company> searchCompanies(@QueryMap Criteria criteria);

}

Maintenant que la logique métier (plutôt simple ici) est implémentée, nous allons mettre en place la configuration nécessaire pour utiliser notre librairie afin d’avoir de jolis logs JSON de nos requêtes.

Ajoutons dans notre répertoire resources le fichier logback-spring.xml pour avoir la génération de logs JSON et utiliser le logger logbook.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

    <include resource="org/springframework/boot/logging/logback/defaults.xml" />
    <include resource="org/springframework/boot/logging/logback/console-appender.xml" />

    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="net.logstash.logback.encoder.LogstashEncoder"/>
    </appender>

    <logger name="fr.ippon" level="INFO" />
    <logger name="org.springframework" level="ERROR" />
    <!-- Ajout de logbook dans les logs -->
    <logger name="org.zalando.logbook" level="TRACE" />

    <root level="info">
        <appender-ref ref="CONSOLE" />
    </root>

</configuration>

Logbook met en place une configuration assez flexible. En effet, il offre la possibilité de surcharger plusieurs composants que l’on peut retrouver dans sa classe d’AutoConfiguration.
Par défaut, nous avons les logs formatés de cette manière :

{
  "@timestamp": "2020-10-27T11:26:38.860+01:00",
  "@version": "1",
  "message": "{\"origin\":\"remote\",\"type\":\"request\",\"correlation\":\"b73a97811bd040f3\",\"protocol\":\"HTTP/1.1\",\"remote\":\"0:0:0:0:0:0:0:1\",\"method\":\"GET\",\"uri\":\"http://localhost:8080/companies?name=ippon\",\"headers\":{\"accept\":[\"*/*\"],\"accept-encoding\":[\"gzip, deflate\"],\"cache-control\":[\"no-cache\"],\"connection\":[\"keep-alive\"],\"content-type\":[\"application/json\"]}}",
  "logger_name": "org.zalando.logbook.Logbook",
  "thread_name": "http-nio-8080-exec-2",
  "level": "TRACE",
  "level_value": 5000
}

On voit que le JSON généré par Logbook se retrouve sérialisé dans l’attribut message... Pas forcément pratique à exploiter tel quel...

Nous allons donc surcharger la configuration de Logbook par défaut pour lui dire qu’on utilise ici Logstash, et ainsi avoir quelque chose de plus lisible :

package fr.ippon.search.configuration;

import com.fasterxml.jackson.databind.ObjectMapper;
import lombok.AllArgsConstructor;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.zalando.logbook.HttpLogFormatter;
import org.zalando.logbook.Sink;
import org.zalando.logbook.json.JsonHttpLogFormatter;
import org.zalando.logbook.logstash.LogstashLogbackSink;

@Configuration
@AllArgsConstructor
public class LogbookConfiguration {

    private final ObjectMapper objectMapper;

    @Bean
    public Sink sink() {
        HttpLogFormatter formatter = new JsonHttpLogFormatter(objectMapper);
        return new LogstashLogbackSink(formatter);
    }

}

La librairie nous offre aussi la possibilité de configurer plusieurs types de clients HTTP pour qu’ils utilisent Logbook ( https://github.com/zalando/logbook/tree/2.1.0#okhttp-v3x ).

Dans notre cas, nous allons utiliser le client OkHttp v3.x qui est simple à configurer, à jour avec HTTP/2 et qui possède notamment une fonctionnalité de retry en cas d’erreur lorsque le service appelé utilise plusieurs adresses IP.

package fr.ippon.search.configuration;

import com.fasterxml.jackson.databind.ObjectMapper;
import feign.Client;
import feign.Feign;
import feign.jackson.JacksonDecoder;
import feign.jackson.JacksonEncoder;
import feign.okhttp.OkHttpClient;
import fr.ippon.search.functional.client.ProviderClient;
import lombok.AllArgsConstructor;
import okhttp3.ConnectionPool;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.zalando.logbook.Logbook;
import org.zalando.logbook.okhttp.GzipInterceptor;
import org.zalando.logbook.okhttp.LogbookInterceptor;

import java.util.concurrent.TimeUnit;

@AllArgsConstructor
@Configuration
public class ProviderClientConfiguration {

    private final Logbook logbook;

    private final ObjectMapper objectMapper;

    @Bean
    public ProviderClient providerClient() {
        return Feign.builder()
                .client(feignClient())
                .encoder(new JacksonEncoder(objectMapper))
                .decoder(new JacksonDecoder(objectMapper))
                .target(ProviderClient.class, "http://localhost:8081");
    }


    private Client feignClient() {
        return new OkHttpClient(
                new okhttp3.OkHttpClient.Builder()
                        .connectionPool(new ConnectionPool(100, 1, TimeUnit.HOURS))
                        .addNetworkInterceptor(new LogbookInterceptor(logbook))
                        .addNetworkInterceptor(new GzipInterceptor())
                        .build());
    }

}

On a maintenant notre Search API que vous pouvez démarrer et appeler en faisant un simple curl.

Par exemple :

curl -X GET 'http://localhost:8080/companies?name=ippon'

Vous l’aurez compris pour l’instant elle ne renverra qu’une liste vide mais ce qui nous intéresse ce sont les logs que nous a générés Logbook.

On va s'intéresser aux trois derniers logs pour voir qu’on a bien notre log d’erreur lors de l’appel au provider, suivi par le log de requête et celui de la réponse que nous a généré Logbook, le tout au format JSON.

En effet Logbook attend que la requête se finisse pour nous logger en même temps la requête et la réponse.

On a donc pour le curl ci-dessus les logs Logbook suivants :

Log de requête :

{
  "@timestamp": "2020-10-31T12:58:29.460+01:00",
  "@version": "1",
  "message": "GET http://localhost:8080/companies?name=ippon",
  "logger_name": "org.zalando.logbook.Logbook",
  "thread_name": "http-nio-8080-exec-2",
  "level": "TRACE",
  "level_value": 5000,
  "http": {
    "origin": "remote",
    "type": "request",
    "correlation": "9ea1f7b117218d79",
    "protocol": "HTTP/1.1",
    "remote": "0:0:0:0:0:0:0:1",
    "method": "GET",
    "uri": "http://localhost:8080/companies?name=ippon",
    "headers": {
      "accept": [
        "*/*"
      ],
      "accept-encoding": [
        "gzip, deflate"
      ],
      "cache-control": [
        "no-cache"
      ],
      "connection": [
        "keep-alive"
      ],
      "content-type": [
        "application/json"
      ],
      "host": [
        "localhost:8080"
      ]
    }
  }
}

Log de réponse :

{
  "@timestamp": "2020-10-31T12:58:29.462+01:00",
  "@version": "1",
  "message": "200 OK GET http://localhost:8080/companies?name=ippon",
  "logger_name": "org.zalando.logbook.Logbook",
  "thread_name": "http-nio-8080-exec-2",
  "level": "TRACE",
  "level_value": 5000,
  "http": {
    "origin": "local",
    "type": "response",
    "correlation": "9ea1f7b117218d79",
    "duration": 751,
    "protocol": "HTTP/1.1",
    "status": 200,
    "headers": {
      "Connection": [
        "keep-alive"
      ],
      "Content-Type": [
        "application/json"
      ],
      "Date": [
        "Sat, 31 Oct 2020 11:58:29 GMT"
      ],
      "Keep-Alive": [
        "timeout=60"
      ],
      "Transfer-Encoding": [
        "chunked"
      ]
    },
    "body": []
  }
}

On notera aussi l’attribut correlation dans l’objet http. Celui-ci est très utile car il permet tout simplement de faire le lien entre le log d’une requête et sa réponse associée.
Logbook nous offre aussi la possibilité de surcharger la génération par défaut de cet identifiant de corrélation (https://github.com/zalando/logbook#correlation)

Maintenant que notre Search API avec Logbook est prête, on va pouvoir ajouter notre Provider API pour voir comment Logbook fonctionne avec cette fois le client OkHttp.

Provider API

Pour la Provider API, on va implémenter une simple API qui renverra des Company en dur.

On va tout d’abord modifier le POM parent pour ajouter notre search-api en dépendance pour permettre à notre API de récupérer les modèles de données (Company et Criteria).

Dans ce genre de situation où on a des objets communs à plusieurs projets maven, il aurait été préférable de les regrouper au sein d’un projet maven à part mais pour rester focus sur notre sujet principal, on va aller au plus simple.

<?xml version="1.0" encoding="UTF-8"?>
...

    <dependencyManagement>
        <dependencies>

            <dependency>
                <groupId>fr.ippon</groupId>
                <artifactId>search-api</artifactId>
                <version>${project.version}</version>
            </dependency>
           ...

        </dependencies>
    </dependencyManagement>

   ...

</project>

Dans notre module provider-api, on va retrouver presque les mêmes dépendances que dans le search-api à l’exception des dépendances au client HTTP Feign notamment.

...

    <dependencies>
        ...

        <dependency>
            <groupId>fr.ippon</groupId>
            <artifactId>search-api</artifactId>
            <scope>provided</scope>
        </dependency>


        <dependency>
            <groupId>org.projectlombok</groupId>
            <artifactId>lombok</artifactId>
        </dependency>

    </dependencies>
...

Nous allons avoir aussi moins de code à écrire que pour la Search API.

• Le controller exposant notre endpoint qui va renvoyer en dur une liste de Company

package fr.ippon.provider.functional.controller;

import fr.ippon.search.functional.model.Company;
import fr.ippon.search.functional.model.Criteria;
import fr.ippon.search.functional.model.Status;
import org.springframework.http.ResponseEntity;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

import java.util.List;

@RestController
public class ProviderController {

   @GetMapping("/provider/companies")
   public ResponseEntity<List<Company>> searchCompanies(Criteria criteria) {
       List<Company> companies = List.of(
               Company.builder()
                       .name("Ippon Technologie")
                       .status(Status.A)
                       .streetName("16 boulevard des tentacules")
                       .country("FR")
                       .build(),

               Company.builder()
                       .name(criteria.getName())
                       .status(Status.C)
                       .streetName("15 impasse du chat qui dort")
                       .country("BE")
                       .build()
       );

       return ResponseEntity.ok(companies);
   }

}

Pour le fichier de configuration application.yml, nous allons juste changer le port du server à mapper par notre application pour éviter un conflit avec le port par défaut qui sera utilisé par notre Search API.

server:
 port: 8081

Nos deux API sont désormais fin prêtes !!
Pour tester tout cela, il est toujours bon d’écrire des tests de composant (voir https://blog.ippon.fr/2020/08/31/cucumber-et-resttemplate/ ) plutôt que de tester “manuellement” en démarrant l’application. Pour vérifier le contenu de nos logs, on pourrait ainsi utiliser une classe de ce type (https://gitlab.com/cdamon/padbowl/-/blob/master/src/test/java/com/jhipster/padbowl/common/LogSpy.java ).

Mais pour ne pas rallonger l’article, nous prendrons un raccourci en démarrant nos deux API et en effectuant un simple curl.

Et voilà, notre API nous a bien renvoyé les entreprises que l’on avait renvoyées en dur côté provider.

Mais vous l’aurez compris, ce qui va nous intéresser est ailleurs.

Voyons donc ce qu’on a dans les logs de notre search-api

On voit donc ici en premier les logs de la requête sortante, effectuée par notre API de recherche vers l’API du provider au format Logbook, suivie par les logs de la requête que nous avons lancée.

Nous avons donc maintenant des logs propres nous permettant de tracer chaque requête effectuée par un client et la réponse associée avec un niveau de détail pertinent pour l’analyse et personnalisable.

Customisons notre Logbook

En fonction des besoins, on peut en effet influer sur la configuration par défaut via le fichier application.yml ou via la redéfinition des Beans d’autoconfiguration. Parmi les plus notables, on a la possibilité de :

• Définir le statut HTTP pour lequel on veut afficher le body d’une réponse
• Définir les endpoints pour lesquels utiliser Logbook ou non
• Cacher certains headers et paramètres dans les logs
• Définir des filtres sur différentes parties d’une requêtes
• Adapter le format des logs (json, curl, splunk, ...)

Par exemple, nous pouvons simplement vouloir n’afficher le body d’une requête et de sa réponse qu’en cas d’erreur pour éviter d’avoir des logs trop verbeux.

Pour cela nous allons ajouter la configuration au fichier application.yml de search-api et provider-api :

logbook:
  minimum-status: 400
  strategy: "body-only-if-status-at-least"

Ici, nous disons à Logbook de nous logger les body seulement si le statut est supérieur ou égal à 400.
En redémarrant l’application, toutes les propriétés qu’on avait dans les logs sont là à l’exception du body.

Un des petits inconvénients (oui il y en a quand même), c’est l’absence de logs si une exception est levée au sein de l’application sans être gérée.

Pour mieux comprendre, enlevez le “try catch” dans la classe SearchService et démarrez uniquement le module search-api. Nous avons donc une exception qui est levée lors de l’appel au provider et pas de logbook dans les logs

N’étant jamais à l’abri d’une exception, nous avons au sein de ma mission, utilisé une autre librairie de Zalando permettant de gérer les exceptions au niveau des Controller pour renvoyer une réponse interprétable au client et garder des logs toujours lisibles et utiles au débuggage (voir https://github.com/zalando/problem-spring-web).

Conclusion

Souvent juste vus comme un moyen de déboguer son code, les logs peuvent souvent apporter bien plus d’informations fonctionnelles qu’on ne peut le penser. On a pu le voir ici en implémentant une utilisation de Logbook qui nous a permis d’afficher les détails du trafic HTTP au sein d’une API de manière structurée au format JSON.

On peut par exemple avoir via ces logs les temps de réponse de nos requêtes, les filtrer par critère de recherche, voir quelles requêtes sont tombées en erreur, etc. Autant de données essentielles aux stakeholders et aux développeurs pour avoir une aide à la supervision.

Au sein de ma mission, nous avons utilisé ces logs dans notre dashboard Splunk pour avoir par exemple des graphiques représentant ces informations et que nous utilisons au quotidien pour superviser notre environnement de production.

L’avantage d’une librairie comme celle qu’on vient d’utiliser, au-delà de son implémentation simplifiée par le module d’autoconfiguration, est sa capacité à être personnalisable pour l’adapter aux besoins.

Le code complet lié à cet article est disponible ici