Tester les logs

J'aime les tests ! Les designs qu'ils font émerger, les refactorings qu'ils sécurisent et la vélocité qu'ils permettent d'atteindre.

Quand on fait des tests, on cherche à tester ce que l'on fait, pas comment on le fait. Tester les détails d'implémentation est le meilleur moyen de se fâcher avec ces validations automatiques et immédiates de notre code.

Dans ce cadre, on peut légitimement se demander s’il faut tester les logs. C'est vrai, c'est un simple détail d'implémentation, un outil de debugging en prod, non ?

Les logs, un détail d'implémentation ?

Il arrive que nos applications ne se comportent pas comme on s'y attendrait en production. Ce fameux cas qui ne peut pas arriver, auquel on n’a pas pensé et que l'on rencontre au premier clic d'un VIP.

Ces innombrables démonstrations de la loi de Murphy suffisent à elles seules à faire attention à avoir des traces les plus exploitables possibles.

Avoir des logs parlants, clairs, qui permettent une analyse simple du problème rencontré tout en respectant la RGPD demande bien souvent du code effectuant des traitements spécifiques. Au même titre que tout traitement, il est pertinent de vouloir les tester !

Si vous passez du temps à avoir des logs propres, ce n'est certainement pas pour que leur création lève une exception et empire la situation que vous étiez en train d'analyser. Enfin, ça c'est dans le pire des cas, mais des logs tout simplement inexploitables ne sont pas non plus une bonne idée.

On pense souvent aux logs quand ça ne va pas mais les logs quand tout va bien peuvent aussi être intéressants :

  • Pour tracer simplement l'avancement d'un traitement long ;
  • Pour expliquer un rattrapage. Certes, l'utilisateur n'y a vu que du feu mais votre traitement nominal a rencontré un problème, il faut peut-être analyser ça ;
  • ...

Une fois que nos logs sont propres, on peut les exploiter, par exemple en créant des alertes automatiques pertinentes.

Même s'ils ne font pas directement de traitements métier, les logs ne sont pas un détail d'implémentation. Ils font partie intégrante de la solution et doivent faire l'objet de la même attention que tout le reste du code !

Une implémentation avec Junit 5

Avec Junit 5 et la mécanique d'extensions il est très simple d'écrire une extension qui nous permettra la validation de nos logs :

import static org.assertj.core.api.Assertions.*;
 
import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.read.ListAppender;
import java.util.function.Predicate;
import org.junit.jupiter.api.extension.AfterEachCallback;
import org.junit.jupiter.api.extension.BeforeEachCallback;
import org.junit.jupiter.api.extension.ExtensionContext;
import org.junit.jupiter.api.extension.ParameterContext;
import org.junit.jupiter.api.extension.ParameterResolutionException;
import org.junit.jupiter.api.extension.ParameterResolver;
import org.slf4j.LoggerFactory;
 
public final class LogSpy implements BeforeEachCallback, AfterEachCallback, ParameterResolver {
  private Logger logger;
  private ListAppender<ILoggingEvent> appender;
 
  @Override
  public void beforeEach(ExtensionContext context) throws Exception {
    appender = new ListAppender<>();
    logger = (Logger) LoggerFactory.getLogger("com.company.application");
    logger.addAppender(appender);
    logger.setLevel(Level.TRACE);
    appender.start();
  }
 
  @Override
  public void afterEach(ExtensionContext context) throws Exception {
    logger.detachAppender(appender);
  }
 
  public void assertLogged(Level level, String content) {
    assertThat(appender.list.stream().anyMatch(withLog(level, content))).isTrue();
  }
 
  public void assertLogged(Level level, String content, int count) {
    assertThat(appender.list.stream().filter(withLog(level, content)).count()).isEqualTo(count);
  }
 
  public void assertNotLogged(Level level, String content) {
    assertThat(appender.list.stream().noneMatch(withLog(level, content))).isTrue();
  }
 
  private Predicate<ILoggingEvent> withLog(Level level, String content) {
    return event -> level.equals(event.getLevel()) && event.toString().contains(content);
  }
 
  @Override
  public boolean supportsParameter(ParameterContext parameterContext, ExtensionContext extensionContext)
    throws ParameterResolutionException {
    return parameterContext.getParameter().getType().equals(LogSpy.class);
  }
 
  @Override
  public LogSpy resolveParameter(ParameterContext parameterContext, ExtensionContext extensionContext) throws ParameterResolutionException {
    return this;
  }
}
Attention : pensez bien à changer le package "com.company.application" dans la définition du logger de tests !

On pourra alors utiliser cette extension dans nos tests :

@ExtendWith(LogSpy.class)
class MyAwsomeUnitTest {
 
  private final LogSpy logs;
 
  public MyAwsomeUnitTest(LogSpy logs) {
    this.logs = logs;
  }
 
  @Test
  void shouldDoSomethingCool() {
    // ...
 
    logs.assertLogged(Level.WARN, "something not intended happens");
  }
}

Le fonctionnement de l'extension est très simple : on ajoute un logger en niveau TRACE qui log dans une list. On peut alors très simplement vérifier les éléments dans la liste et faire les assertions que l'on souhaite. Vous avez quelques exemples ici mais n'hésitez pas à ajouter les vôtres !

Il faut tester tous les logs ?

Non ! Comme pour tout, le but n'est pas de tout tester : "I get paid for code that works, not for tests" - Kent Beck.

Les tests doivent vous aider, vous faire gagner du temps. Testez vos logs si vous en ressentez le besoin. Avec le temps, étrangement, vous ressentirez de plus en plus ce besoin, enfin, vous ferez ces tests sans y penser et sans y consacrer d'énergie, mais ça, c'est une autre histoire.