Grafana Stack 📈 1. Observabilité avec Spring Boot 3

10 Jun 2023 ⏱ 9 mn

À mes heures perdues, je travaille sur une application de veille techno qui me permet de faire la mienne (veille) comme j’ai envie. Récemment, j’ai entendu parler d’Opentelemetry un collecteur de télémétrie. Et j’ai eu envie de le tester pour voir si je pouvais rendre mon application observable.

Il existe une multitude de stack de télémétrie, mais Grafana est open source et permet d’avoir assez facilement toutes les métriques sur la même application de rendu. De plus, je voulais essayer Loki en comparaisons de ELK que j’utilise déjà au travail.

Pour en apprendre plus sur l’observabilité, allez jeter un oeil sur la documentation de Stéphane Robert concernant l’Observabilité .

Voilà donc une série d’articles détaillants comment mettre en place l’observabilité sur une application Spring Boot 3.

Les autres articles de la série :

Observabilité avec Spring Boot 3
Collecte des métriques avec OpenTelemetry
Collecte des logs avec OpenTelemetry
Déploiement d’un Grafana

La Stack Grafana

Avant de commencer, parlons un peu de la stack grafana. Elle est composée de plusieurs éléments. Dans mon boulot précédent et dans mon poste actuel, j’ai beaucoup travaillé avec la stack ELK. Elle est très efficace, mais j’ai toujours trouvé qu’elle était compliquée à mettre en place et à configurer. C’est l’occasion de tester la stack Grafana plus simple à mettre en œuvre.

Prometheus

Prometheus est le moteur de stockage de métriques. Il s’agit d’un moteur de métriques dimensionnel. Chaque métrique est représentée par un nom et par des attributs, un ensemble de clé/valeur qui spécialise la donnée. Cela permet de faire des requêtes puissantes, mais il faut faire attention à ne pas avoir d’attributs dont l’ensemble de valeurs possible est trop important sans quoi les performances et l’espace de stockage vont exploser.

Loki

Loki est le moteur de stockage de logs. Mais, contrairement à Elastic qui va indexer tout le contenu des logs, Loki ne va indexer que certains attributs. Loki stocke les logs comme prometheus les métriques. Chaque log possède un ensemble d’attributs clé/valeur qui sont indexés, le reste du message ne l’est pas. Comme pour les métriques on ne doit pas utiliser d’attribut avec un ensemble de valeurs trop grand sous peine de problèmes de performance et d’explosion du stockage. L’intérêt de cette approche est que l’empreinte sur le disque est bien plus faible que pour un Elastic. L’inconvénient est qu’il n’est pas possible de faire de recherche sur les champs non indexés et donc sur le contenu du message de log.

Tempo

Tempo quant à lui, va stocker les traces. C’est-à-dire le moyen de rapprocher les logs et les métriques dans un environnement micro-service. Cela fera l’objet d’un autre article.

Grafana

Enfin Grafana propose une interface unifiée pour visualiser toute cette télémétrie.

Spring Boot et l’observabilité

L’observabilité regroupe les 3 éléments suivants :

Les métriques
Les logs
Les traces

Sur les dernières versions du framework, l’équipe de Spring a ajouté la fonctionnalité d’observabilité qui est particulièrement bien intégré au modèle Spring Webflux et à la programmation réactive grâce à Micrometer et Reactor.

Avec très peu de code additionnel il est maintenant possible d’obtenir des métriques détaillées pour chaque exécution de stream que l’on souhaite observer.

Déploiement des métriques

Ajout des dépendences

Tout d’abord dans le pom.xml :

<dependency>
    <groupId>io.projectreactor</groupId>
    <artifactId>reactor-core-micrometer</artifactId>
</dependency>

<dependency>
    <groupId>io.micrometer</groupId>
    <artifactId>micrometer-registry-prometheus</artifactId>
</dependency>

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-actuator</artifactId>
</dependency>

reactor-core-micrometer est le plugin d’observabilité de micrometer qui lui permet de s’intégrer à reactor.
micrometer-registry-prometheus représente le format de restitution des métriques. En effet, il existe plusieurs approches quant à la collecte de métriques. L’approche choisie détermine le format de restitution. Dans notre cas, on va utiliser un Stack Grafana pour stocker et visualiser nos métriques, c’est donc le format prometheus (le moteur de stockage de métriques de grafana) qui correspond à notre choix.
spring-boot-starter-actuator l’actuator va nous permettre de mettre à disposition un API pour collecter les métriques

Configuration Spring Boot

Maintenant, il reste à ajouter la configuration de l’actuator dans le fichier application.yaml :

spring:
  application.name: MyApplication


management:
  endpoints.web.exposure.include: prometheus,health
  metrics:
    distribution.percentiles-histogram:
      http.server.requests: true
    tags:
      application: ${spring.application.name}

Le nom de l’application va permettre d’avoir un contexte dans tous les logs et toutes les métriques. Ainsi, si vous avez plusieurs applications spring qui génère des métriques cela vous permettra de les différentier. De la même façon si vous avez un cluster de plusieurs nœuds, il sera intéressant d’ajouter ici l’identifiant du nœuds.

Pour le reste, la ligne importante est endpoints.web.exposure.include: prometheus qui va activer l’api de collecte pour prometheus. Le reste des paramètres permet d’avoir un peu plus de détails dans les métriques collectées.

À partir de là, l’application est déjà capable de fournir une grosse quantité de métriques sur le fonctionnement de Spring et de la JVM. Démarrer l’application et, avec un postman par exemple, faire une requête GET /actuator/prometheus qui est la route par défaut pour Prometheus.

# HELP jvm_threads_peak_threads The peak live thread count since the Java virtual machine started or peak was reset
# TYPE jvm_threads_peak_threads gauge
jvm_threads_peak_threads{context="MyApplication",} 45.0
# HELP jvm_gc_overhead_percent An approximation of the percent of CPU time used by GC activities over the last lookback period or since monitoring began, whichever is shorter, in the range [0..1]
# TYPE jvm_gc_overhead_percent gauge
jvm_gc_overhead_percent{context="MyApplication",} 0.00497286035688716
# HELP system_cpu_usage The "recent cpu usage" of the system the application is running in
# TYPE system_cpu_usage gauge
system_cpu_usage{context="MyApplication",} 0.0
# HELP process_files_max_files The maximum file descriptor count
# TYPE process_files_max_files gauge
process_files_max_files{context="MyApplication",} 1048576.0
# HELP bw_news_count Total number of News
# TYPE bw_news_count gauge
bw_news_count{context="MyApplication",} 0.0
# HELP jvm_gc_live_data_size_bytes Size of long-lived heap memory pool after reclamation
# TYPE jvm_gc_live_data_size_bytes gauge
jvm_gc_live_data_size_bytes{context="MyApplication",} 1.33460992E8
# HELP hikaricp_connections_max Max connections
# TYPE hikaricp_connections_max gauge
hikaricp_connections_max{context="MyApplication",pool="HikariPool-1",} 10.0
# HELP spring_security_authorizations_seconds  
# TYPE spring_security_authorizations_seconds summary
spring_security_authorizations_seconds_count{context="MyApplication",error="none",spring_security_authentication_type="UsernamePasswordAuthenticationToken",spring_security_authorization_decision="true",spring_security_object="exchange",} 1.0
spring_security_authorizations_seconds_sum{context="MyApplication",error="none",spring_security_authentication_type="UsernamePasswordAuthenticationToken",spring_security_authorization_decision="true",spring_security_object="exchange",} 0.005212113

Ce n’est qu’un exemple des métriques fournis de base par Spring, mais il y en a sur beaucoup d’aspects : La mémoire, la consommation CPU, les routes appelées, le temps de démarrage, …

Ajout de la première métrique

Dans le cadre de l’application de veille techno, j’ai un process de scraping des feed de news qui se déclenche toutes les heures et ça m’intéresserait bien de l’observer.

Le code de ce processus est un flux Reactor qui exécute toutes les étapes, lancé à intervales réguliers par un Scheduler :

@Override
public void run() {
    log.info("Start scraping ...");
    scraperService.scrap(properties.conservation())
            .subscribe();
}

J’ai simplifié le code réel, mais l’idée est là.

// Injection de l’ObservationRegistry via le constructeur
private final ObservationRegistry observationRegistry;

@Override
public void run() {
    log.info("Start scraping ...");
    scraperService.scrap(properties.conservation())
            .name("bw_scraping_process")
            .tap(Micrometer.observation(observationRegistry))
            .subscribe();
}

Si on relance l’application maintenant et que l’on attend que le process de scraping se termine. Puis, que l’on interroge à nouveau la route GET /actuator/prometheus. On obtient les données supplémentaires suivantes.

# HELP bw_scraping_process_seconds  
# TYPE bw_scraping_process_seconds summary
bw_scraping_process_seconds_count{context="MyApplication",error="none",reactor_status="completed",reactor_type="Mono",} 1.0
bw_scraping_process_seconds_sum{context="MyApplication",error="none",reactor_status="completed",reactor_type="Mono",} 17.026397336
# HELP bw_scraping_process_seconds_max  
# TYPE bw_scraping_process_seconds_max gauge
bw_scraping_process_seconds_max{context="MyApplication",error="none",reactor_status="completed",reactor_type="Mono",} 17.026397336
# HELP bw_scraping_process_active_seconds_max  
# TYPE bw_scraping_process_active_seconds_max gauge
bw_scraping_process_active_seconds_max{context="MyApplication",reactor_type="Mono",} 0.0
# HELP bw_scraping_process_active_seconds  
# TYPE bw_scraping_process_active_seconds summary
bw_scraping_process_active_seconds_active_count{context="MyApplication",reactor_type="Mono",} 0.0
bw_scraping_process_active_seconds_duration_sum{context="MyApplication",reactor_type="Mono",} 0.0

L’observabilité de reactor produit en tout 2 groupes de 3 métriques :

Les métriques d’exécution
- le nombre total d’appels
- la durée maximale
- la somme des durées
Les métriques d’exécution longue (active) qui donne les mêmes compteurs pour des opérations de plus longues durées qui ne seraient pas terminées.

Utilisation d’une Gauge

Ces métriques sont pratiques, mais pas simple à interpréter. Finalement, si vous souhaitez voir l’évolution de la durée du scraping au fil du temps, cela n’est pas possible. Au mieux, vous avez la durée moyenne. C’est pour cela qu’il peut être intéressant de déclarer une Gauge qui va permettre cette observation.

private final AtomicLong lastScrapingDuration = new AtomicLong(0);

public ScraperTaskScheduler(MeterRegistry registry) {
    TimeGauge.builder("bw_scraping_process", lastScrapingDuration::get, TimeUnit.MILLISECONDS)
            .description("Last scraping duration")
            .register(registry);
}

@Override
public void run() {
    log.info("Start scraping ...");
    long startTime = System.currentTimeMillis();
    scraperService.scrap(properties.conservation())
            .doFinally(s -> lastScrapingDuration.set(System.currentTimeMillis() - startTime))
            .subscribe();
}

Les TimeGauge permettent d’ajouter au compteur une unité de temps.

Maintenant si on relance l’application pour voir les compteurs, voilà ce que l’on a.

# HELP bw_scraping_process_seconds Last scraping duration
# TYPE bw_scraping_process_seconds gauge
bw_scraping_process_seconds{context="MyApplication",} 14.201

Ce n’est pas flagrant comme changement mais, dans le cas d’une gauge, chaque nouvelle valeur vient remplacer la précédente. Contrairement à un timer ou un compteur qui additionne chaque nouvelle valeur avec la précédente.

Ajout du contexte

Il est possible d’ajouter du contexte dans les métriques programmatiquement en utilisant le MeterRegistryCustomizer. Il sera cependant plus simple d’utiliser les paramètres de configuration vu au début de cet article.

@Configuration
public class SpringConfiguration {
    @Bean
    public MeterRegistryCustomizer<MeterRegistry> metricsCommonTags(@Value("${spring.application.name}") String application) {
        return registry -> registry.config()
                .commonTags("context", application.toLowerCase());
    }
}

Sécurisation

Dernier point important, la sécurisation du point d’accès aux métriques. Pensez à sécuriser ce point d’accès, même si y accéder ne suffira pas à pirater l’application, les métriques laissent passer bon nombre d’informations exploitables qui permettrait à une personne mal intentionnée de dénicher d’éventuelles failles de sécurités.

Amélioration des logs

Les logs par défaut de Spring sont vraiment appréciables et bien formatés. Mais des logs au format texte restent un enfer à parser. Tous ceux qui ont travaillé un peu avec Logstash ont leurs collections de grok bien au chaud pour ce genre de chose.

Le plus simple est de faire en sorte que Spring sorte les logs en JSON, déjà parsé, elles seront directement lisibles par le collecteur. L’idéal serait que l’on puisse régler ça grâce à une variable d’environnement, ce qui permettrait de garder les logs “humain” pendant le développement et d’utiliser le json pour la production.

Logback possède un plugin qui permet d’obtenir ce résultat.

Ajouter les dépendances

<dependency>
    <groupId>ch.qos.logback.contrib</groupId>
    <artifactId>logback-json-classic</artifactId>
    <version>0.1.5</version>
</dependency>
<dependency>
    <groupId>ch.qos.logback.contrib</groupId>
    <artifactId>logback-jackson</artifactId>
    <version>0.1.5</version>
</dependency>

Configuration logback

Ensuite on configure logback comme suit dans un fichier logback-spring.xml:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <springProperty scope="context" name="appName" source="spring.application.name"/>
    <springProperty scope="context" name="rootLevel" source="logging.level.root"/>

    <springProfile name="json-logging">
        <contextName>${appName}</contextName>
        <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
            <layout class="ch.qos.logback.contrib.json.classic.JsonLayout">
                <jsonFormatter class="ch.qos.logback.contrib.jackson.JacksonJsonFormatter"/>
                <timestampFormat>${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd'T'HH:mm:ss.SSS'Z'}</timestampFormat>
                <appendLineSeparator>true</appendLineSeparator>
                <prettyPrint>false</prettyPrint>
            </layout>
        </appender>
        <statusListener class="ch.qos.logback.core.status.NopStatusListener" />
    </springProfile>

    <springProfile name="!json-logging">
        <include resource="org/springframework/boot/logging/logback/console-appender.xml"/>
    </springProfile>

    <root level="${rootLevel}">
        <appender-ref ref="CONSOLE"/>
    </root>
</configuration>

L’intérêt de cette configuration, c’est qu’elle est attachée au profil. Il est donc facile de passer de cette configuration à la configuration par défaut des logs via la variable d’environnement SPRING_PROFILES_ACTIVE=json-logging.

À noter l’utilisation de spring.application.name que l’on a mis à jour dans les propriétés de l’application et qui va se retrouver dans le contexte. Ce qui permettra de distinguer les logs de notre application d’autres logs dans loki et qui mettra ainsi le même contexte sur nos métriques et sur les logs.

Relancer l’application

Si on relance l’application avec la configuration que l’on vient de mettre en place, voilà ce que cela va donner :

{"timestamp":"2023-05-30T23:07:12.880Z","level":"INFO","thread":"main","logger":"fr.ght1pc9kc.myapp.MyApplication","message":"Starting MyApplication using Java 17.0.6 with PID 31428 ( started by marthym in )","context":"MyApplication"}
{"timestamp":"2023-05-30T23:07:12.893Z","level":"DEBUG","thread":"main","logger":"fr.ght1pc9kc.myapp.MyApplication","message":"Running with Spring Boot v3.1.0, Spring v6.0.9","context":"MyApplication"}
{"timestamp":"2023-05-30T23:07:12.894Z","level":"INFO","thread":"main","logger":"fr.ght1pc9kc.myapp.MyApplication","message":"The following 1 profile is active: \"json-logging\"","context":"MyApplication"}
{"timestamp":"2023-05-30T23:07:13.973Z","level":"INFO","thread":"main","logger":"org.flywaydb.core.internal.license.VersionPrinter","message":"Flyway Community Edition 9.16.3 by Redgate","context":"MyApplication"}
{"timestamp":"2023-05-30T23:07:13.973Z","level":"INFO","thread":"main","logger":"org.flywaydb.core.internal.license.VersionPrinter","message":"See release notes here: https://rd.gt/416ObMi","context":"MyApplication"}
{"timestamp":"2023-05-30T23:07:13.973Z","level":"INFO","thread":"main","logger":"org.flywaydb.core.internal.license.VersionPrinter","message":"","context":"MyApplication"}
{"timestamp":"2023-05-30T23:07:13.980Z","level":"INFO","thread":"main","logger":"com.zaxxer.hikari.HikariDataSource","message":"HikariPool-1 - Starting...","context":"MyApplication"}
{"timestamp":"2023-05-30T23:07:14.067Z","level":"INFO","thread":"main","logger":"com.zaxxer.hikari.pool.HikariPool","message":"HikariPool-1 - Added connection org.sqlite.jdbc4.JDBC4Connection@6f8667bb","context":"MyApplication"}
{"timestamp":"2023-05-30T23:07:14.068Z","level":"INFO","thread":"main","logger":"com.zaxxer.hikari.HikariDataSource","message":"HikariPool-1 - Start completed.","context":"MyApplication"}

Beaucoup plus difficile à lire pour un humain, mais bien plus simple à parser.

Conclusion

Voilà les quelques améliorations à mettre en place dans une application Spring pour simplifier la collecte des métriques. Dans le prochain article, nous verrons comment mettre en place un collecteur OpenTelemetry et récupérer les métriques que l’on vient de configurer.