Observer votre application Symfony en toute simplicité avec OpenTelemetry (partie 3)

Maintenant que nous avons pu voir dans notre précédent article la mise en place globale de l’observation de notre application avec OpenTelemetry, il est temps d’aller jouer avec et de voir nos signaux s’afficher dans Grafana ! Notre première partie se trouve également ici si vous ne l'avez pas consultée. Petit rappel, il faut lancer le projet en utilisant :

Et une fois les containers disponibles, vous pouvez ouvrir Grafana en naviguant sur http://localhost:3000

Commençons tout d’abord par jeter un œil aux diverses Traces générées par notre application, et notamment celles liées à l’auto-instrumentation. Le projet contient quelques contrôleurs très simples, qui ont pour but de représenter les différentes possibilités d’émissions de signaux. En se rendant sur la homepage, vous verrez un simple “Hello world” s’afficher. Toutefois, si vous vous en rappelez, nous avions vu qu’un hook était lié au Kernel, via la bibliothèque d’auto-instrumentation pour Symfony. Ainsi, cette simple requête a dû en elle-même générer une Trace.

Et en effet, en fouillant dans Grafana on retrouve bel et bien l’appel fait à notre route homepage : 

Une Trace qui contient une simple Span a bien été générée et envoyée jusqu’à notre visualizer, et ce grâce à l’auto-instrumentation ! Vérifions désormais le bon fonctionnement des autres types d’auto-instrumentation fournis, à savoir ceux attachés via hooks à la méthode HttpClientInterface::request, ainsi qu’à la méthode MessageBusInterface::dispatch. Nous avons préparé de simples contrôleurs pour faciliter ça.

Tout d’abord, en se rendant sur https://localhost/http-client-trace, le contrôleur est censé générer une requête à l’API health-check de Grafana via HttpClientInterface::request.

En allant vérifier dans Grafana, on retrouve bien une Trace liée à la requête principale, mais celle-ci contient plusieurs Span :

En cliquant sur l’ID de la Trace, on peut l’observer plus en détail, et remarquer une Span nommée grafanaGET qui correspond à la requête effectuée par le contrôleur !

Testons alors l’instrumentation Messenger fournie par la bibliothèque. Le contrôleur lié à la route https://localhost/send-message envoie un simple message à un consumer à travers le conteneur RabbitMQ. Nous verrons un peu plus tard l’émission de signaux depuis ce worker, mais en attendant : 

La Trace liée à la requête sur la route “send_message” contient bel et bien des Spans auto-instrumentées par les hooks attachés à MessageBusInterface::dispatch et SenderInterface::send ! 

Nous avons expliqué précédemment comment auto-instrumenter nos commandes console grâce au Listener que nous avons écrit. Vérifions dès lors que tout fonctionne comme attendu. La commande App\Command\DemoCommand a pour but de tester simplement plusieurs des cas que l’on pourra rencontrer dans une véritable application et de montrer que ceux-ci sont bien répercutés dans nos signaux.

Rendons nous tout d’abord dans notre container PHP :

Puis lançons la commande de base :

Sans flag particulier, cette commande retourne juste Command::Success et se retrouve bien dans Grafana :

Avec le flag qui simulera un échec :

La Trace se retrouve également dans Grafana, mais bien marquée en échec, comme voulu via notre Listener :

Enfin, en simulant une Exception qui se produirait dans notre code :

La Trace produite est non seulement marquée en erreur, mais comme espéré, l’Exception levée a bien été enregistrée comme événement :

Pour finir sur les Traces, essayons désormais de voir comment en créer nous-même pour aller un peu plus loin. Le contrôleur App\Controller\ManualTracingController contient un exemple qui montre comment créer une simple Span, puis une “sous-Span” intégrée à la première, mais liée à une fonction interne à notre code (qui ici génère juste un nombre aléatoire). Après avoir fait un appel à https://localhost/manual-tracing, voici ce que nous pouvons observer :

On retrouve alors la Trace principale liée à notre requête, puis une première Span manual-tracing créée dans le contrôleur, et enfin la Span doSpecificStuff-nested-span créée dans notre fonction privée, bel et bien attachée à la Span parente, et dans laquelle l’attribut app.random_number_value que nous avons créé à la main est bien présent, et contient la valeur générée lors du passage de la requête !

On voit bien alors à quel point il est aisé d’aller émettre des informations depuis notre application que nous pourrons surveiller !

Concernant les logs, nous n’en générons ici qu’à deux endroits de l’application, dans le contrôleur de la HomePage, un message de type “info” qui dit tout simplement "Log from HomePageController", et un dans le Handler du DemoMessage que nous dispatchons sur une autre route.

En choisissant la source de donnée “Loki” dans Grafana et en filtrant sur {service_name=”symfony_app”}, on retrouve bien le log émis lorsque nous avons visité la HomePage :

De même, en choisissant cette fois-ci le service symfony_worker, on retrouve le log lié à la consommation du DemoMessage dispatché plus tôt, log cette fois-ci émis par le worker :

Grâce à notre décorateur du logger Monolog, injecter et utiliser LoggerInterface dans notre code applicatif permet donc directement la transmission des signaux de type Log au collector, puis à Loki pour enfin les observer dans Grafana !

Concernant enfin les Metrics, nous avons créé un contrôleur App\Controller\MetricsController avec deux routes pour mesurer deux types de Metrics différentes. Ainsi, visiter https://localhost/metrics/{count} (où count est un entier choisi de manière arbitraire) génère une Metric de type Counter qui pourrait par exemple dans une véritable application compter le nombre de kilomètres effectués par un véhicule (un Counter ne fait qu’augmenter). Ici on lui donne des valeurs arbitraires et il est remis à 0 à chaque requête donc ce n’est pas son cas d’usage idéal, mais il nous permet de voir tout de même nos Metrics transmises à Grafana en choisissant Mimir comme source de données :

Pour l’exemple, nous avons fait trois appels à la route /metrics/{count} avec les valeurs suivantes : 32, 1312 et 256 et nous les voyons bien apparaître sur le graphique.

L’autre route /metrics/memory émet une Metric de type Gauge (une simple mesure à un instant donné), qui en l’occurrence calcule la mémoire consommée en MB pour effectuer la tâche suivante : 

On peut alors voir que cette action aura consommé environ 0,05MB de mémoire pour s’effectuer, et ce, même en la répétant un peu plus tard (le deuxième trait vert correspond à un deuxième appel de notre part sur cette route), ce qui est a priori attendu. Et voici comment nous avons généré plusieurs types de Metrics pour notre application !

À noter qu’il est également possible de générer des Metrics dans Prometheus à partir des Traces exportées dans Tempo. N’hésitez pas à parcourir la documentation et à jouer avec par vous-mêmes !

Tout au long de ces articles, nous avons pu voir pourquoi et comment mettre en place l’observation de nos applications grâce à OpenTelemetry et à l’écosystème OpenSource disponible autour de ces pratiques. Nous avons vu qu’avec quelques dépendances, quelques lignes de codes et une infrastructure adaptée, notre application peut être entièrement surveillée sur tous les plans !

À noter qu’ici, nous avons tenté de couvrir un bon nombre de cas et que cela peut ainsi paraître lourd en terme de nombre de logiciels supplémentaires à faire tourner, à vous bien sûr de faire la part des choses et de trouver le bon compromis qui correspondra à vos besoins.

Si vous souhaitez aller plus loin, en plus des différentes documentations mentionnées dans ces articles, sachez qu’un bundle Symfony est en cours de création dont l’objectif est de faciliter encore l’expérience développeur !