Journal J'ai trouvé un bug dans journalctl

Salut!

La semaine dernière, je suis tombé sur un bug.

Le contexte, c'est une plateforme de test automatique ou on lance un système (Linux avec nos applications ajoutées dedans), on lui fait faire des trucs et on vérifie qu'il fait ce qu'on veut (je vous épargne les détails).

Entre autre choses, on utilise journalctl pour consulter les logs émis par différents services et se synchroniser dessus. On a des besoins du type "attendre que tel message de log apparaisse" ou alors "vérifier que tel message de log n'apparaît pas pendant 5 minutes".

Pour cela, on utilise les "curseurs" de journalctl. D'abord, on récupère le curseur actuel avec journalctl --show-cursor. Ça retourne une chaîne de caractères qui permet de savoir où on en est dans les logs. Ensuite, on utilise, au choix, les options -c ou --after-cursor pour récupérer les logs émis à partir de ce curseur, inclus avec -c, ou exclu avec --after-cursor.

Dans notre cas, on a en plus besoin de filtrer les logs correspondant à un service spécifique et/ou à un niveau de log spécifique, ce qui se fait avec les options -u et -p de journalctl.

Chacune de ces options prise séparément semble bien fonctionner.

Pourtant, dans certains de nos tests, un log émis avant le curseur (parfois plusieurs secondes avant) était pris en compte alors qu'il ne devrait pas. Ou bien, inversement, le premier log juste après le curseur n'était pas détecté. On a fait quelques aller-retours entre les options -c et --after-cursor dans nos outils de tests avant de bien comprendre le problème.

Ce problème se trouve dans l'implémentation de --after-cursor. Cette option est implémentée en récupérant les mêmes logs que l'option -c, et en ignorant la première entrée dans le résultat (celle pointée par le curseur). Oui mais voilà: si les entrées du journal sont filtrées par ailleurs (avec les options -u et/ou -p, par exemple), --after-cursor va tout de même ignorer la première entrée du journal, et va le faire après ce premier filtrage. Ce qui fait qu'elle va parfois ignorer un message qui n'était en fait pas celui pointé par le curseur, déjà éliminé par une étape de filtrage précédente.

Le problème est présent au moins depuis systemd version 250 (publiée en 2021), il est probablement bien plus ancien mais je n'ai pas testé d'autres versions de journalctl. Il sera corrigé dans les prochaines versions de systemd suite à mon rapport de bug et une correction rapide par les développeurs de systemd. Mais en attendant, on a pu contourner le problème: en insérant des messages supplémentaires dans nos logs juste avant de récupérer le curseur, on peut utiliser l'option -c de journalctl tout en s'assurant que le message pointé par le curseur ne sera pas celui qu'on essaie de détecter (mais un message artificiel inséré spécialement pour ça dans le log). Nos tests automatiques ne sont plus aléatoirement cassés avec des problèmes qui disparaissent dès qu'on active des logs de debug.

Conclusion

C'est une histoire qui finit bien: le bug a été corrigé rapidement et il existe un contournement qui nous évite de devoir faire une mise à jour de systemd (cela pourra attendre la prochaine version LTS de la distribution Linux utilisée).

C'est aussi un rappel de ne pas faire confiance aveuglément à ce qui est indiqué dans la documentation des logiciels que vous utilisez: parfois, les choses ne se comportent pas exactement comme attendu, et ça vaut le coup de bien vérifier ce qu'il se passe dans les cas un peu "tordus" (du genre utiliser 2 options d'une ligne de commande en même temps).

C'est enfin un remerciement aux développeurs de systemd et d'autres projets qui sont réactifs et peuvent corriger ce genre de problème rapidement (une autre fois je vous raconterai peut-être des aventures avec un rapport de bug chez Microsoft, mais pour l'instant, celui-là n'a pas de solution en vue).