SLF4J, Servlet & RequestId

Comme beaucoup de développeurs j'ai eu l'occasion de lire, copier, coller, déchiffrer, générer de nombreuses lignes de logs à travers les applications en phase de développement ou de maintenance.

Un problème commun auquel on se retrouve rapidement confronté si l'on code des applications Web (donc multi-utilisateurs), c'est celui de pouvoir suivre les logs générés par une requête en particulier dans des fichiers de logs qui font souvent plusieurs milliers de lignes.



Pour résoudre ce soucis, SLF4J propose une API très intéressante permettant d'attacher au thread courant des valeur sous forme de contexte de log : le Mapped Diagnostic Context ou MDC

Comment on faisait avant ?

Prennons un exemple, nous avons une application app découpée en deux modules, l'un app-core défini le coeur de l'application (les objets et algos métier etc...) et l'autre app-ui son rendu graphique (Wicket ou GWT par exemple).

Cette application utilise SLF4J avec LOG4J comme implémentation, voici un extrait du fichier de configuration log4j.xml définissant le pattern des logs générés :

Avant d'utiliser le MDC, si vous voulez associer à chaque log un identifiant de requête ou un login utilisateur, vous serez certainement tenté de rendre tout ceci explicite pour le module app-core en utilisant par exemple des appels comme :

logger.debug("[requestId:{}][login:{}] Mon message",2, "toto");

qui génèreront un log du type :

MaClasse - [requestId:2][login:toto] Mon message

Il faut donc gérer la lecture/écriture des valeurs à la main dans le module coeur qui n'a pourtant que faire d'un requestId (pourquoi des requête? c'est quoi ces requêtes ?) ou d'un login utilisateur (ce deuxième point pourrait être discuté).

C'est ici qu'intervient le MDC, puisque qu'il permet de manière transparente d'ajouter des valeurs dans le MDC qui deviennent accessibles aux générateur de log à travers leur pattern de configuration.

Comment on fait maintenant ?

En modifiant la configuration comme ceci :

et en modifiant les appels précédants en :

logger.debug("Mon message");

on obtiendrai les mêmes logs qu'auparavant sans pour autant spécifier dans le code métier l'éxistence de requête HTTP ou d'un utilisateur.

Mais me direz-vous, comment sont affectée les valeurs requestId et login utilisée dans la configuration ?
Et bien rien de plus simple puisqu'il suffit en fait d'ajouter deux appel à chaque requête traitée par le module app-ui

MDC.put("requestId",2);
MDC.put("login","toto");

Où ajouter ce bout de code, comment le rendre plus générique ? Pour cela, rien ne vaut une bonne vieille implémentation sortie tout droit de la documentation de LogBack (remplaçant de LOG4J sur la scène des librairies de logs)

Cette UserServletFilter fournit une implémentation permettant d'extraire de toutes les requêtes HTTP filtrées le nom de l'utilisateur et de l'ajouter au MDC sous le nom "username".

Dans notre cas, nous devrions ajouter une gestion des identifiants de requête, le code ressemblerait plutot à ceci :

public class UserServletFilter implements Filter {

  private final String USER_KEY   = "login";
  private final String REQUEST_ID = "requestId";

  private static lastRequestId = 0; 

  private static final synchronized Integer nextRequestId(){
    lastRequestId = (lastRequestId + 1) % Integer.MAX_VALUE;
    return lastRequestId;
  }

  public void doFilter(ServletRequest request, ServletResponse response,
    FilterChain chain) throws IOException, ServletException {

    boolean successfulRegistration = false;

    HttpServletRequest req = (HttpServletRequest) request;    
    Principal principal = req.getUserPrincipal();
    // Please note that we could have also used a cookie to 
    // retrieve the user name

    if (principal != null) {
      String username = principal.getName();
      successfulRegistration = registerUsername(username);
      MDC.put(REQUEST_ID, nextRequestId());
    } 

    try {
      chain.doFilter(request, response);
    } finally {
      if (successfulRegistration) {
        MDC.remove(USER_KEY);
      }
      MDC.remove(REQUEST_ID);
    }
  }

  ...

  /**
   * Register the user in the MDC under USER_KEY.
   * 
   * @param username
   * @return true id the user can be successfully registered
   */
  private boolean registerUsername(String username) {
    if (username != null && username.trim().length() > 0) {
      MDC.put(USER_KEY, username);
      return true;
    }
    return false;
  }
}

Tu salis, tu nettoies !

Dans les exemples de code ci-dessus, nous avons utilisé les API du MDC pour enlever les valeurs que nous avions affecter auparavant

MDC.remove("requestId");

En effet, le MDC étant attaché à un Thread (via l'utilisation de ThreadLocal) il est probable qui le Thread une fois réutilisé détienne toujours une référence vers le MDC et donc se mette à générer des logs incohérent avec le comportement prévu.

Et si je veux pas utiliser de Filter ?

Le fonctionnement des filtres HTTP est tel qu'il est utilisable partout (sous réserve d'utiliser un conteneur de Servlet évidemment), si par contre vous préférez implémenter cette logique directement dans le workflow de votre framework JavaWeb préféré, c'est toujours possible et même parfois plus simple.

Deux exemples :

• Dans Wicket, vous pouvez très utiliser le RequestCyle dans ce but, les méthodes onBeginRequest(), onEndRequest() et onRuntimeException() faisant respéctivement de l'ajout, de la suppression de valeurs au MDC.
• Dans GWT, vous pouvez étendre le RemoteServiceServlet de base pour ajouter le comportement voulu aux méthodes processCall(..) et doUnexpectedFailure(..).

Remarque : toute ressemblance avec du code présenté à ses collègues par @fbaligand serait totalement fortuite :-)