EXP: Logs dynamiques (partie 1) / EXP: Dynamic logs (part 1)

Passons aux choses sérieuses. Dans une suite d'articles, nous allons proposer diverses ressources permettant d'améliorer l'exploitabilité de nos développements. Divers sujets seront abordés: gestion des erreurs, audits, etc. Ce faisant, nous allons petit à petit construire une bibliothèque utilisable sur des projets réels et ce blog lui servira de documentation. Pour les reconnaître facilement, les articles relatifs à l'exploitabilité auront un titre qui commencera par EXP. Dans cet article nous allons parler de logs.

Les logs sont une fonctionnalité de Mulesoft largement utilisée, souvent de façon excessive et anarchique. Les moyens de se renseigner sur le déroulement d'un traitement Mulesoft étant limité (aux logs justement), les développeurs ont tendance à en abuser et très vite, à mélanger les informations générales et particulières. Le système de log devient un véritable fleuve d'informations difficilement utilisables. On se retrouve alors devant un dilemme: être concis pour pouvoir mieux suivre le déroulement d'un processus, ou être bavard afin de se donner une chance de collecter L'information qui nous sera utile en cas d'incident. Heureusement, le système de logs, basé sur Log4J admet la notion de niveau: ERROR, WARN, INFO, DEBUG, TRACE. Le souci est que ce niveau n'est pas ajustable dynamiquement. Pour le modifier, il faut arrêter le serveur et le faire redémarrer. Si l'on est en présence d'un phénomène subit dont on ne comprend pas l'origine, ce redémarrage n'est probablement pas une option:

1. Redémarrer un serveur en production est un évènement qui généralement réclame une interruption de service, des autorisations, une procédure à suivre et une communication aux utilisateurs: ce n'est pas anodin.
2. Le simple fait d'arrêter le service et le faire redémarrer peut faire disparaître le phénomène à observer, et il peut se passer un temps assez long avant qu'on ne puisse l'observer à nouveau.
3. Abaisser le niveau de logs peut engendrer un flots de messages provenant de bien des parties de l'application qui n'ont pas besoin d'un tel niveau de précision dans la surveillance mais qui vont, bien sûr, largement encombrer les fichiers de logs.

Bref, il nous faut quelque chose de plus fin et de plus dynamique. Le mécanisme des niveaux de Log4J est à la fois trop entier et trop rigide. Dans cet article, nous allons proposer une première version des DLog (Dynamic Log) qui vont permettre de changer le niveau d'un log.

Bien sûr, les logs de Mulesoft ne sont pas dynamiques (le niveau ne peut être précisé qu'en "dur"). Il n'est donc pas possible d'utiliser directement le Logger de Mulsoft. Ce que l'on va faire, c'est appeler un subflow, qui en fonction d'une variable d'environnement va diriger le message vers un Logger au niveau souhaité:

Nous allons ignorer un court instant le "Retrieve Log Strategy" qui l'entame. Le "coeur" de notre subflow est un composant Choice qui dirige l'exécution vers un Logger pris parmi sept, c'est à dire un par niveau plus un niveau par défaut (INFO). Chaque branche When définit un prédicat basé sur la valeur d'une variable appelé "log_strategy" qui précise, dans le champ "level", le niveau de log souhaité.

Le composant Logger de la branche est des plus classique. Il se contente de Logger le payload. A charge à l'appelant de fournir dans le payload, la valeur que l'on veut loguer. 

Bon. Jusque là, rien de bien révolutionnaire. Reste à savoir comment nous allons exploiter ce subflow. On imagine que s'il faut:

1. sauvegarder le payload courant dans une variable,
2. mettre dans le payload le message à logger,
3. appeler le logger dynamique,
4. restaurer le payload sauvegardé

nous allons très considérablement alourdir l'écriture du log. Ce qu'il nous faudrait, c'est un moyen d'effectuer ce log en utilisant un seul composant, comme nous l'aurions fait avec le Logger standard de Mulesoft. Quelque chose qui ressemble à ça:

C'est certes un peu plus "lourd" que le Logger classique, car:

1. Le composant est un TransformMessage et non un Logger et est donc un peu moins facilement reconnaissable du premier coup d'oeil. C'est pour cela, que par convention, nous feront commencer sa description par un DLOG majuscule.
2. Le corps du composant enrobe le message à loguer dans l'invocation de la méthode "dlog": il n'est pas fourni seul, ce qui complexifie un peu l'écriture.

Toute la "magie" est bien sûr dans la fonction "dlog" car c'est elle qui doit invoquer le subflow présenté plus haut. Une fonction DataWeave permet d'invoquer un flow: lookup. Noter que lookup peut invoquer un flow, pas un subflow. C'est pourquoi notre subflow possède une partie "source" (c'est donc un flow en réalité). La fonction "dlog" a été isolée dans un module de fonctions personnalisées (Custom function) afin d'alléger l'écriture du log dynamique : elle peut être réutilisée à loisir. Ce fichier est placé dans le répertoire "ressources" du projet:

Le contenu de ce fichier ne contient pour l'instant que la définition de la fonction "dlog". Il a vocation à s'enrichir aux fils des articles de ce blog. La fonction dlog, elle aussi va s'enrichir:

%dw 2.0

fun dlog(log, message)=

Mule::lookup("dlog", log)

then message.payload

Deux choses sont à noter:

1. la fonction lookup est précédé de la mention de son module: Mule n'est pas importé de facto dans un module de "Custom Function".
2. dlog retourne le payload du message en cours (afin que le composant DLOG ne change pas le payload et donc n'ait pas d'effet de bord).

Il nous reste à implémenter le moyen de changer dynamiquement le niveau de Log et donc, de modifier le contenu de la variable "log_strategy". Nous allons procéder de façon très classique: utiliser l'Object Store pour faire communiquer le flot qui change cette stratégie avec les flots qui l'utilisent. "Retrieve Log Strategy" de notre subflow de log charge cette stratégie dans la variable "log_strategy".

Pour alimenter l'Object Store nous allons créer un flow HTTP très classique d'import:

Il ne nous reste plus qu'à changer le contenu de notre stratégie pour voir nos messages dynamiques s'afficher, ou non leurs fichiers de logs.

_____________________________________________________________________

Let's get down to business. In a series of articles, we'll be proposing various resources for improving the usability of our developments. We'll be covering a range of topics, from error management to auditing. In doing so, we will gradually build up a library that can be used on real projects, and this blog will serve as its documentation. To make them easily recognizable, articles relating to exploitability will have a title starting with EXP. In this article, we're going to talk about logs.

Logs are a Mulesoft feature that is widely used, often excessively and anarchically. Since the means of finding out about the progress of a Mulesoft process are limited (to logs, in fact), developers tend to overuse them and very quickly mix general and specific information. The log system becomes a veritable river of information that is difficult to use. This leaves us with a dilemma: to be concise in order to better follow the progress of a process, or to be talkative in order to give ourselves a chance to gather information that will be useful in the event of an incident. Fortunately, the Log4J-based logging system supports the notion of levels: ERROR, WARN, INFO, DEBUG, TRACE. The problem is that this level is not dynamically adjustable. To modify it, the server must be stopped and restarted. If you're dealing with a sudden phenomenon whose origin you don't understand, restarting is probably not an option:

1. Restarting a server in production is an event that generally requires service interruption, authorizations, a procedure to follow and communication to users: it's not trivial.
2. Simply stopping the service and restarting it may cause the phenomenon to disappear, and it may be some time before it can be observed again.
3. Lowering the log level can generate a flood of messages from many parts of the application that don't need such a high level of monitoring precision, but which will, of course, clutter up the log files.

In short, we need something finer and more dynamic. Log4J's level mechanism is both too complete and too rigid. In this article, we're going to propose a first version of DLog (Dynamic Log), which will enable you to change the level of a log.

Of course, Mulesoft logs are not dynamic (the level can only be specified "hard"). It is therefore not possible to use Mulsoft's Logger directly. What we'll do is call a subflow, which, depending on an environment variable, will direct the message to a Logger at the desired level:

We'll ignore for a moment the "Retrieve Log Strategy" that starts it off. The "heart" of our subflow is a Choice component which directs execution to one of seven loggers, i.e. one per level plus a default level (INFO). Each When branch defines a predicate based on the value of a variable called "log_strategy" which precises, in the "level" field, the desired log level.

The Logger component of the branch is a classic. It simply logs the payload. It's up to the caller to supply the payload with the value to be logged.

So far, so good. So far, nothing revolutionary. The question now is how we're going to exploit this subflow. If we have to:

1. save the current payload in a variable,
2. put the message to be logged in the payload,
3. call the dynamic logger,
4. restore the saved payload

and restore the saved payload, we're going to make the log writing considerably more cumbersome. What we need is a way of doing this logging using a single component, as we would have done with the standard Mulesoft Logger. Something like this:

It's certainly a little "heavier" than the classic Logger, because:

1. The component is a TransformMessage and not a Logger, and is therefore a little less easily recognizable at first glance. That's why, by convention, we'll start its description with a capital DLOG.
2. The body of the component wraps the message to be logged in the invocation of the "dlog" method: it is not supplied on its own, which makes writing a little more complex.

All the "magic" is, of course, in the "dlog" function, since it is this function that must invoke the subflow described above. A DataWeave function can be used to invoke a flow: lookup. Note that lookup can invoke a flow, not a subflow. This is why our subflow has a "source" part (so it's actually a flow). The "dlog" function has been isolated in a custom function module to lighten the load of writing the dynamic log: it can be reused at will. This file is placed in the project's "resources" directory:

For the moment, this file only contains the definition of the "dlog" function. It will be enriched as this blog is updated. The dlog function will also be enriched:

%dw 2.0

fun dlog(log, message)=

Mule::lookup("dlog", log)

then message.payload

Two things are worth noting:

1. the lookup function is preceded by a mention of its module: Mule is not imported de facto into a "Custom Function" module.
2. dlog returns the payload of the current message (so that the DLOG component doesn't change the payload and thus have any side effects).

We now need to implement a way of dynamically changing the Log level, and thus modifying the contents of the "log_strategy" variable. We're going to do this in the classic way: using the Object Store to make the stream that changes this strategy communicate with the streams that use it. Our log subflow's "Retrieve Log Strategy" function loads this strategy into the "log_strategy" variable.

To feed the Object Store, we'll create a classic HTTP import flow:

All we need to do now is change the content of our strategy to see our dynamic messages displayed, or not their log files.