Guide pratique : corriger les bogues non reproductibles
Qui n’a jamais connu cette situation frustrante où un bogue aléatoire surgit dans un code qui semble pourtant correcte ? Ces bogues non reproductibles, véritables cauchemars des développeurs, apparaissent brusquement et échappent aux tests habituels.
Ce type de problème devient particulièrement critique en production, où il peut non seulement nuire à l’expérience utilisateur, mais également ternir l’image de marque d’une entreprise et impacter son chiffre d’affaires. Les clients, à juste titre, exigent des solutions rapides et efficaces.
Alors, comment corriger les bogues non reproductibles lorsque chaque tentative pour les reproduire échoue ? Dans ce guide pratique, nous allons explorer une méthodologie éprouvée pour traquer et résoudre ces anomalies insaisissables.
Etude de cas : un dysfonctionnement non reproductible
Une anomalie rarissime en production
Récemment, un client nous a signalé un problème inattendu sur une application que nous maintenons. Le comportement décrit était troublant : en une décennie d’utilisation, aucun bogue de ce genre n’avait été détecté. Pourtant, au cours des deux derniers mois, deux occurrences ont été remontées.
Les journaux (logs) de l’application n’indiquaient aucune anomalie liée aux classes responsables du traitement métier. Et comme souvent dans ce genre de cas, le problème n’a pas pu être reproduit sur les environnements de test, hors production.
Une cause indirecte et complexe
La difficulté de ce problème résidait dans son origine : un dysfonctionnement au sein d’un algorithme annexe, indirectement lié au traitement métier principal.
Pour mieux comprendre, j’ai reproduit un scénario dans une application Java simplifiée, simulant une gestion de données dans une collection. Cette simulation permet d’augmenter la fréquence d’apparition de l’anomalie grâce à une série d’événements déclenchés aléatoirement (vous trouverez le code source et l’historique de ses modifications sur GitLab).
Le code de la classe Provider (traitement métier)
// src/main/java/fr/lavoiedudev/article/java/concurrent/Provider.java
package fr.lavoiedudev.article.java.concurrent;
import java.util.ArrayList;
import java.util.Iterator;
import java.util.List;
import java.util.Random;
/**
* Provider gérant une liste d'entiers aléatoires de manière aléatoire.
*/
public class Provider {
/** Nombre maximum d'items */
private static final int MAX_SIZE = 50000;
/** Borne maximal des nombres aléatoires générés */
private static final int MAX = 100;
/** Le générateur de nombres aléatoires */
private final Random random = new Random();
/** La liste des entiers aléatoires gérés */
private final List<Integer> items = new ArrayList<>();
/**
* Retourne la taille de la collection d'entiers.
* @return la taille de la collection interne gérée.
*/
public int size() {
return items.size();
}
/**
* Rafraîchit les items.
*/
public void populate() {
// Suppression random des éléments
Iterator<Integer> iterator = items.iterator();
while (iterator.hasNext()) {
Integer item = iterator.next();
if (item < random.nextInt(MAX)) {
iterator.remove();
}
}
// Ajout des éléments pour arriver de nouveau au nombre max d'éléments
for (int count = items.size(); count < MAX_SIZE; count++) {
items.add(random.nextInt(MAX));
}
}
/**
* Ajoute un item aléatoire à la fin de la liste.
*/
public void insertSingle() {
items.add(random.nextInt(MAX));
}
/**
* Supprime des items aléatoirement.
*/
public void removeMultiple() {
double percent = random.nextDouble(0.1);
int size = items.size();
int overflowCount = size - MAX_SIZE;
// Déterminer le nombre d'éléments à supprimer
int targetSize = (int) ((1.0 - percent) * Math.min(MAX_SIZE, size));
if (overflowCount > 0) {
targetSize -= overflowCount;
}
// Suppression aléatoire des items dans la liste
while (size > targetSize) {
items.remove(random.nextInt(size));
size--;
}
}
}La classe Provider est responsable des traitements métier, elle permet d’ajouter, supprimer ou remplacer des entiers dans la collection gérée. La méthode size() permet de consulter régulièrement l’évolution de la taille de la collection.
Simulation du problème : la classe App
La classe suivante déclenche les traitements métier de manière aléatoire, simulant ainsi un comportement utilisateur :
// /src/main/java/fr/lavoiedudev/article/java/concurrent/App.java
package fr.lavoiedudev.article.java.concurrent;
import java.util.Random;
public class App {
private static final Random RANDOM = new Random();
/**
* Exécute le runnable après un délai aléatoire.
* @param origin le temps minimal d'attente.
* @param bound Le temps maximal d'attente.
* @param runnable Le runnable à exécuter après la fin du temps d'attente.
*/
private static void delayedBehaviour(long origin, long bound, Runnable runnable) {
try {
long delay;
synchronized (RANDOM) {
delay = RANDOM.nextLong(origin, bound);
}
Thread.sleep(delay);
runnable.run();
} catch (InterruptedException|RuntimeException e) {
// ignore
}
}
public static void main(String[] argv) throws InterruptedException {
Provider provider = new Provider();
// Création des threads exécutant les traitements métiers aléatoirement
Thread populateThread = new Thread(() -> {
while (true) {
delayedBehaviour(1000, 5000, provider::populate);
}
});
Thread insertThread = new Thread(() -> {
while (true) {
delayedBehaviour(0, 10, provider::insertSingle);
}
});
Thread removeThread = new Thread(() -> {
while (true) {
delayedBehaviour(500, 2500, provider::removeMultiple);
}
});
Thread print = new Thread(() -> {
while (true) {
try {
Thread.sleep(100);
System.out.printf("Collection size: %d%n", provider.size());
} catch (InterruptedException e) {
return;
}
}
});
// Start threads
Thread[] threads = new Thread[]{ populateThread, insertThread, removeThread, print };
for (Thread thread: threads) {
thread.start();
}
// Wait threads
for (Thread thread: threads) {
thread.join();
}
}
}Résultat : un comportement inattendu
Lors de l’exécution du programme, on s’attend à ce que la taille de la collection se stabilise autour de 50 000 (grâce à la méthode populate). Pourtant, il arrive que cette taille chute drastiquement pendant plusieurs minutes avant de revenir à la normale, comme illustré ci-dessous :
Collection size: 20
Collection size: 39
Collection size: 58
...
Collection size: 608
Collection size: 624
Collection size: 50009
Collection size: 50028
...
Collection size: 50167
Collection size: 50189
Collection size: 45447
Collection size: 45468
...
Collection size: 7292
Collection size: 7313
Collection size: 6646
Collection size: 6663
...
Collection size: 6455
Collection size: 6477
Collection size: 50068
Collection size: 50107Pourquoi ce bogue est problématique ?
Bien que le code semble correct, les tests unitaires de la classe Provider ne révèlent aucune erreur :
$ mvn test
...
[INFO] --- maven-surefire-plugin:2.19.1:test (default-test) @ concurrent ---
-------------------------------------------------------
T E S T S
-------------------------------------------------------
Running fr.lavoiedudev.article.java.concurrent.ProviderTest
Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.033 sec - in fr.lavoiedudev.article.java.concurrent.ProviderTest
Results :
Tests run: 3, Failures: 0, Errors: 0, Skipped: 0
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
...Cependant, l’exécution montre un écart anormal sur la taille attendue. Cela démontre l’importance de diagnostiquer les bogues non reproductibles en allant au-delà des tests automatisés.
Etape 1 : mise en place des journaux (logs)
Une situation tendue avec le client
Il arrive que le comportement réel d’une application diffère des attentes initiales définies lors de sa conception. C’est particulièrement frustrant lorsque, comme ici, les tests unitaires confirment que les traitements métier fonctionnent correctement, mais que l’anomalie continue de se manifester en production.
Dans ce type de situation, les attentes des clients sont claires : trouver et résoudre le bogue. Même sans solution immédiate, il est essentiel de montrer que l’équipe est proactive et mobilisée pour diagnostiquer l’anomalie. Cette approche rassure le client et renforce la confiance dans le service fourni.
Comprendre la dynamique de l’application
Pour explorer et identifier l’origine d’un comportement inattendu, la journalisation (logging) est une solution éprouvée. Elle permet de tracer l’exécution des algorithmes et de collecter des informations cruciales lors de la reproduction du problème. L’analyse des journaux générés devient alors une étape clé pour mieux comprendre le fonctionnement interne de l’application.
Nous allons illustrer cette approche en ajoutant un mécanisme de journalisation dans le code source de l’application.
Paramétrage de la journalisation en Java
Commençons par créer le fichier de configuration des journaux log.properties :
# /log.properties
# Pousser la sortie vers un fichier de log
handlers=java.util.logging.FileHandler
# Configuration du FileHandler
java.util.logging.FileHandler.formatter=java.util.logging.SimpleFormatter
java.util.logging.FileHandler.pattern=application.log
# Format personnalisé des journaux
java.util.logging.SimpleFormatter.format=[%4$s] %1$s - %2$s - %5$s%6$s%n
# Activation des niveaux INFO et plus sur notre application
fr.lavoiedudev.article.java.concurrent=INFOCe fichier configure un handler pour écrire les journaux dans un fichier nommé application.log. Il utilise un format simple, mettant en évidence les niveaux d’urgence (INFO, SEVERE) et les messages associés.
Journalisation des événements de la classe App
La journalisation est ensuite intégrée dans la classe App. Nous ajoutons un logger et des instructions de journalisation à des endroits clés :
// /src/main/java/fr/lavoiedudev/article/java/concurrent/App.java
package fr.lavoiedudev.article.java.concurrent;
+import java.io.FileInputStream;
+import java.io.IOException;
+import java.io.InputStream;
import java.util.Random;
+import java.util.logging.Level;
+import java.util.logging.LogManager;
+import java.util.logging.Logger;
public class App {
+ private static final Logger LOG = Logger.getLogger(App.class.getName());
+
private static final Random RANDOM = new Random();
// ...
Thread.sleep(delay);
runnable.run();
- } catch (InterruptedException|RuntimeException e) {
+ } catch (InterruptedException e) {
// ignore
+ } catch (RuntimeException e) {
+ LOG.log(Level.SEVERE, "Echec du traitement", e);
}
}
public static void main(String[] argv) throws InterruptedException {
+ try (InputStream fis = new FileInputStream("log.properties")) {
+ LogManager.getLogManager().readConfiguration(fis);
+ } catch (IOException e) {
+ LOG.log(Level.SEVERE, "Echec de lecture de la configuration du logger", e);
+ System.exit(1);
+ }
+
Provider provider = new Provider();
// ...
try {
Thread.sleep(100);
+ LOG.info("Collection size: " + provider.size());
System.out.printf("Collection size: %d%n", provider.size());
} catch (InterruptedException e) {
return;
// ...Ce que nous ajoutons :
- Configuration du système de journalisation à partir du fichier de configuration précédent.
- Ajout des instructions de journalisation des erreurs critiques (échec de traitement).
- Ajout des instructions de journalisation de l’état de la collection (taille).
Journaliser les traitements métier
La classe Provider est également enrichie avec des instructions de journalisation pour tracer les traitements internes :
// /src/main/java/fr/lavoiedudev/article/java/concurrent/Provider.java
// ...
import java.util.Iterator;
import java.util.List;
import java.util.Random;
+import java.util.logging.Logger;
/**
* Provider gérant une liste d'entiers aléatoires de manière aléatoire.
*/
public class Provider {
+ /** Logger lié au traitement du provider. */
+ private static final Logger LOG = Logger.getLogger(Provider.class.getName());
+
/** Nombre maximum d'items */
private static final int MAX_SIZE = 50000;
// ...
public void populate() {
+ LOG.info("populate: suppression des entiers");
+
// Suppression random des éléments
Iterator<Integer> iterator = items.iterator();
while (iterator.hasNext()) {
// ...
}
}
+ LOG.info("populate: ajout des nouveaux entiers");
// Ajout des éléments pour arriver de nouveau au nombre max d'éléments
for (int count = items.size(); count < MAX_SIZE; count++) {
items.add(random.nextInt(MAX));
}
+
+ LOG.info("populate: fin des traitements");
}
/**
* Ajoute un item aléatoire à la fin de la liste.
*/
public void insertSingle() {
+ LOG.info("insertSingle: Ajout d'un nouvel entier");
+
items.add(random.nextInt(MAX));
+
+ LOG.info("insertSingle: fin du traitement");
}
/**
* Supprime des items aléatoirement.
*/
public void removeMultiple() {
+ LOG.info("removeMultiple: Calcul du nombre d'éléments à supprimer");
double percent = random.nextDouble(0.1);
int size = items.size();
// ...
targetSize -= overflowCount;
}
+ LOG.info("removeMultiple: suppression des entiers superflus");
// Suppression aléatoire des items dans la liste
while (size > targetSize) {
items.remove(random.nextInt(size));
size--;
}
+
+ LOG.info("removeMultiple: fin du traitement");
}
}Résultat : un outil de diagnostic robuste
En ajoutant des logs sur chaque étape clé des traitements métier, nous obtenons une vue claire de l’exécution réelle. Cela facilite le diagnostic des anomalies, même dans des scénarios difficiles à reproduire.
Etape 2 : analyse des journaux
Observer le comportement du programme
Maintenant que la journalisation est configurée, relançons le programme et attendons que l’anomalie se produise. Voici un extrait des journaux :
[INFOS] 2024-07-25T07:59:04.826644200+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.App lambda$main$3 - Collection size: 43949
[INFOS] 2024-07-25T07:59:04.826644200+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.Provider insertSingle - insertSingle: Ajout d'un nouvel entier
...
[INFOS] 2024-07-25T07:59:04.846842+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.Provider insertSingle - insertSingle: fin du traitement
[INFOS] 2024-07-25T07:59:04.848187200+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.Provider populate - populate: suppression des entiers
[INFOS] 2024-07-25T07:59:04.853209600+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.Provider insertSingle - insertSingle: Ajout d'un nouvel entier
[INFOS] 2024-07-25T07:59:04.853209600+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.Provider insertSingle - insertSingle: fin du traitement
[GRAVE] 2024-07-25T07:59:04.853209600+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.App delayedBehaviour - Echec du traitement
java.util.ConcurrentModificationException
at java.base/java.util.ArrayList$Itr.checkForComodification(ArrayList.java:1013)
at java.base/java.util.ArrayList$Itr.next(ArrayList.java:967)
at fr.lavoiedudev.article.java.concurrent.Provider.populate(Provider.java:45)
at fr.lavoiedudev.article.java.concurrent.App.delayedBehaviour(App.java:31)
at fr.lavoiedudev.article.java.concurrent.App.lambda$main$0(App.java:52)
at java.base/java.lang.Thread.run(Thread.java:840)
[INFOS] 2024-07-25T07:59:04.856871200+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.Provider insertSingle - insertSingle: Ajout d'un nouvel entier
...
[INFOS] 2024-07-25T07:59:04.926360700+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.Provider insertSingle - insertSingle: fin du traitement
[INFOS] 2024-07-25T07:59:04.927427500+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.App lambda$main$3 - Collection size: 43289
...
[INFOS] 2024-07-25T07:59:11.438467300+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.Provider insertSingle - insertSingle: fin du traitement
[INFOS] 2024-07-25T07:59:11.446466100+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.App lambda$main$3 - Collection size: 33708
[INFOS] 2024-07-25T07:59:11.448467400+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.Provider insertSingle - insertSingle: Ajout d'un nouvel entier
...
[INFOS] 2024-07-25T07:59:11.486467300+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.Provider insertSingle - insertSingle: fin du traitement
[GRAVE] 2024-07-25T07:59:11.493468100+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.App delayedBehaviour - Echec du traitement
java.lang.NullPointerException: Cannot invoke "java.lang.Integer.intValue()" because "item" is null
at fr.lavoiedudev.article.java.concurrent.Provider.populate(Provider.java:47)
at fr.lavoiedudev.article.java.concurrent.App.delayedBehaviour(App.java:31)
at fr.lavoiedudev.article.java.concurrent.App.lambda$main$0(App.java:52)
at java.base/java.lang.Thread.run(Thread.java:840)
[INFOS] 2024-07-25T07:59:11.495468+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.Provider insertSingle - insertSingle: Ajout d'un nouvel entier
...
[INFOS] 2024-07-25T07:59:11.545049500+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.Provider insertSingle - insertSingle: Ajout d'un nouvel entier
[INFOS] 2024-07-25T07:59:11.547203600+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.App lambda$main$3 - Collection size: 16711
...Dans ces journaux, nous observons plusieurs exceptions qui provoquent la perte d’éléments dans la collection. Selon le type d’exception cette perte semble être variable. Lorsque l’exception NullPointerException survient, la perte est souvent plus importante que lorsque l’exception ConcurrentModificationException est levée.
Diagnostiquer précisément le comportement anormal
Analyser les exceptions levées par le programme
Vis-à-vis du code source ces erreurs ne devraient pas se manifester. La collection ne contient aucun objet null, donc l’exception NullPointerException est impossible … Concernant l’exception ConcurrentModificationException, elle survient lorsque nous modifions une liste alors que nous itérerons dessus. Le test unitaire suivant est un exemple qui génère systématiquement cette exception. Cependant, la classe Provider n’effectue jamais ce type de traitement !
// /src/test/java/fr/lavoiedudev/article/java/concurrent/AppTest.java
package fr.lavoiedudev.article.java.concurrent;
import org.junit.jupiter.api.Test;
import java.util.ArrayList;
import java.util.Arrays;
import java.util.ConcurrentModificationException;
import java.util.List;
import static org.junit.jupiter.api.Assertions.*;
class AppTest {
/**
* Echec de l'itération en cas de modification de la liste itérée.
*/
@Test()
public void testThrowsConcurrentModificationException() {
assertThrows(ConcurrentModificationException.class, () -> {
List<Integer> items = new ArrayList<>(Arrays.asList(1, 2, 3, 4, 5));
for (Integer item: items) {
if (item > 3) {
items.clear();
}
}
});
}
}Analyser le comportement dynamique du programme
En lisant les journaux, lorsque les exceptions surviennent, le nombre d’éléments de la collection diminue. Nous voyons en effet que l’événement « populate: suppression des entiers » est présent, mais nous ne retrouvons pas l’événement « populate: ajout des nouveaux entiers ». Cela signifie que l’exception survient durant la suppression sans que la collection ne soit réalimentée. Nous comprenons maintenant pourquoi parfois, durant une longue période, la taille de la collection reste faible. Les suppressions sont réalisées au travers des méthodes populate et removeMultiple, mais la fréquence d’appel à la méthode insertSingle est insuffisante pour compenser cette perte.
Déterminer l’origine probable du bogue
L’anomalie étant diagnostiquée, nous devons maintenant identifier son origine. En analysant plus précisément les journaux, nous observons qu’un appel à insertSingle est réalisé alors que le traitement populate est encore en cours :
...
[INFOS] 2024-07-25T07:59:04.846842+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.Provider insertSingle - insertSingle: fin du traitement
[INFOS] 2024-07-25T07:59:04.848187200+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.Provider populate - populate: suppression des entiers
[INFOS] 2024-07-25T07:59:04.853209600+02:00[Europe/Paris] - fr.lavoiedudev.article.java.concurrent.Provider insertSingle - insertSingle: Ajout d'un nouvel entier
...Cela expliquerait l’occurrence de l’exception ConcurrentModificationException. En revanche, nous n’avons aucune piste pour les NullPointerException.
Etape 3 : réaliser un correctif partiel
Même si nous n’avons pas de solution à toutes les erreurs, nous pouvons réaliser un premier correctif simple pour sécuriser l’accès à la liste Java. Le client sera déjà heureux de savoir qu’un dysfonctionnement est corrigé.
L’exécution des méthodes de la classe Provider en parallèle est liée aux appels concurrents déclenchés par les différents threads. Nous devons donc mettre en place les protections nécessaires pour éviter les accès concurrents à la collection. En Java, la meilleure solution est d’utiliser le mot-clé synchronized. Nous allons donc ajouter le bloc synchronized autour des instructions des méthodes de la classe Provider pour garantir l’intégrité des données dans un environnement multi-thread.
// ...
synchronized (items) {
// ...
}
// ...Après plusieurs minutes d’exécution, l’application affiche en console une taille de collection oscillant entre 42 000 et 51 000 éléments. Par ailleurs, aucune des exceptions ConcurrentModificationException ou NullPointerException n’est survenue.
Etape 4 : mise en observation
L’origine exacte des exceptions NullPointerException reste incertaine. Il est probable qu’un accès concurrent en lecture/écriture à la liste provoque un dérèglement de l’Iterator, mais cette hypothèse reste à confirmer. Pour avancer, nous avons décidé de déployer l’application corrigée avec le bloc synchronized et de surveiller son comportement sur une période prolongée.
Ce déploiement permet au client de réutiliser son application dans des conditions presque normales, tout en sachant qu’une enquête approfondie est en cours. Si, après une période d’observation raisonnable, aucune anomalie ne survient, nous pourrons considérer le bogue comme résolu.
Conclusion : servir son client !
Le diagnostic de l’anomalie réelle a révélé qu’elle résultait d’un accès concurrent à une liste partagée. Ce problème survenait dans deux contextes distincts :
- Une tâche en arrière-plan, déclenchée par la réception d’un événement, effectuait un traitement long, susceptible de générer une
ConcurrentModificationException. - En parallèle, une action humaine initiée par l’utilisateur contribuait à cet accès concurrent.
Un élément critique dans cette situation était que la tâche en arrière-plan capturait cette exception sans la journaliser, compliquant considérablement le diagnostic initial. Pour résoudre le problème, nous avons :
- Ajouté des instructions de journalisation à des endroits stratégiques du code, identifiant ainsi l’exception.
- Analysé les journaux pour établir qu’un accès concurrent était en cause, bien que difficile à détecter en raison de l’utilisation d’un framework non thread-safe pour le traitement en arrière-plan.
- Livré une deuxième version avec le bloc
synchronizedpour sécuriser les accès à la liste.
Cependant, comme l’anomalie ne se manifeste que dans l’environnement de production, il est impossible de valider complètement la correction. L’application reste donc en observation.
Malgré ces incertitudes, notre approche proactive a été bien perçue par le client. Le maintien de la confiance repose autant sur les actions correctives que sur une communication transparente. Cette expérience souligne l’importance d’un support technique réactif, même lorsque les solutions demandent du temps et de la réflexion.
Envie d’aller plus loin ?
Apprenez à maîtriser la journalisation, les techniques de débogage et bien plus encore avec des bases solides en développement logiciel. Découvrez mon livre pour transformer vos idées en applications concrètes. Obtenez votre exemplaire :