URL: https://linuxfr.org/users/nono/journaux/petite-histoire-de-debug Title: Petite histoire de debug Authors: Bruno Michel Date: 2020年07月29日T19:58:41+02:00 License: CC By-SA Tags: debugging, debugger et cozycloud Score: 56 Certaines personnes trouvent que les contenus sur LinuxFr.org sont de moins en moins techniques, et mon dernier journal parlait de motivation au travail, donc très peu technique. Pour compenser, je vais vous raconter une petite histoire sur du debug que j'ai fait la semaine dernière. Jeudi dernier, dans l'après-midi, je venais de finir de coder une petite fonctionnalité et j'allais merger la pull request associée. Mais, au moment de faire ça, je me rends compte que l'intégration continue est au rouge : les tests d'intégration ont échoué. Ce sont une suite de tests écrits en Ruby qui lancent la partie serveur de Cozy (appelée [cozy-stack](https://github.com/cozy/cozy-stack)), font des appels à l'API et vérifient que les réponses correspondent aux attentes. C'est surtout utilisé pour des parties où les tests unitaires ne sont pas suffisants, comme la mise en place de partage de fichiers entre deux instances Cozy. Premier réflexe : copier les logs de l'échec et relancer le build. Ça arrive de temps à autres que les tests d'intégration échouent pour de mauvaises raisons (un problème réseau, la machine virtuelle a ramé et on a atteint un timeout, etc.), même si c'est de plus en plus rare. Bon, c'est toujours rouge. J'avais lancé les tests en local et ça passait, mais je vérifie une deuxième fois : chez moi, ça marche (c) ! Bon, va falloir réfléchir un peu et trouver de quoi ça vient. A priori, le test qui échoue a peu à voir avec le code modifié. Le dernier commit dans master date de mardi matin, c'était une mise à jour d'une dépendance et le build était vert à ce moment-là. Je veux savoir si le problème vient réellement de ma modification ou si c'est quelque chose d'externe, je crée alors une autre pull request avec juste un changement anodin par rapport à la branche principale pour lancer les tests d'intégration. C'est rouge aussi, le problème ne vient pas de mes modifications. Ça se complique, il va falloir trouver ce qui a changé entre mardi matin et jeudi après-midi. Premier suspect : l'environnement d'intégration lui-même. Je passe pas mal de temps à chercher dans les documentations et blogs de GitHub, mais a priori, GitHub Actions n'a pas bougé significativement entre temps (j'ai d'ailleurs le même numéro de version du runner pour tous les builds récents, `2.267.1`). J'en profite aussi pour demander à mes collègues si ce problème leur dit quelque chose. Deuxième suspect : les dépendances. C'est un grand classique, on peut facilement se retrouver avec du code différent en local et sur la CI. Normalement, c'est le moins cas ces dernières années avec la généralisation des fichiers de _lock_ pour les dépendances, mais j'ai encore eu le cas il y a quelque mois à cause d'un bug de bundler, l'outil de gestion de dépendances de Ruby. Bon, j'ai la même version de Ruby, Rubygems et bundler en local que sur la CI. Les fichiers de lock sont bien utilisés, aussi bien pour le code testé en Go que pour l'outillage de test en Ruby. Il va falloir plonger plus profondément dans le code. J'hésite entre l'ajout de logs et chercher un moyen de me connecter en ssh sur la CI, mais je crains de passer beaucoup de temps sur la deuxième solution, donc je préfère commencer par simplement ajouter des logs, en me disant que si au bout d'une heure je suis toujours coincé, il sera sûrement temps de passer à l'autre méthode. En ajoutant les logs, je trouve la source du problème : normalement, quand un utilisateur ajoute une image ou photo sur son instance Cozy, la stack génère des vignettes avec Image Magick et les applications peuvent être notifiées quand la génération a fini via une websocket, et ici, on reçoit 0 messages de notification, alors qu'on s'attend à en recevoir 3 (un par taille : _large_, _medium_ et _small_). Je vérifie rapidement que Image Magick est bien installé sur la CI, avec une version à jour, mais je rajoute rapidement des informations de timing pour mieux comprendre ce qu'il se passe. Et là, je me rends compte qu'il se passe vraiment très peu de temps entre la fin de l'upload de l'image et le moment où on vérifie les vignettes générées. Je suspecte donc un problème liée à la websocket. On utilise une bibliothèque Ruby appelée [faye-websocket-ruby](https://github.com/faye/faye-websocket-ruby) pour se connecter en websocket, et cette bibliothèque s'appuie sur EventMachine (une boucle événementielle en Ruby). Je vais lire la documentation et je trouve que l'on peut ajouter un callback pour avoir accès aux erreurs : ```ruby ws.on :error do |err| puts err end ``` Je relance des tests sur GitHub Actions, et j'obtiens une jolie erreur `ECONNREFUSED`. Je continue d'essayer de trifouiller pour avoir plus d'informations, mais il faut se rendre à l'évidence, je tourne un peu en rond. Je décide de faire un petit résumé de ce que je sais : - le code de test en Ruby n'arrive pas à se connecter en websocket à la stack - pourtant la stack tourne bien et sur le port TCP attendu car les connexions HTTP classiques juste avant passent bien (et j'ai vérifié lors du debug que je pouvais aussi faire une connexion HTTP juste après) - l'erreur est `ECONNREFUSED` et ça me laisse très fortement penser qu'on essaye d'ouvrir une connexion TCP vers le mauvais endroit - pour ouvrir la websocket, on passe deux informations : le nom de domaine et le port - on passe `alice.test.cozy.tools` comme nom de domaine et `8081` comme port, et ça m'a l'air bon - une connexion TCP, c'est un quadruplet adresse IP source, port source, adresse IP destination, port destination - `alice.test.cozy.tools` résout en 127.0.0.1 (comme tous les sous-domaines de `cozy.tools`). Et là, j'ai une intuition (ou l'expérience qui parle) : la résolution de nom, pour passer du nom de domaine à une adresse IP ! Dans la très grande majorité des cas, cette résolution de nom se fait via la glibc. Mais les appels sont bloquants, et c'est problématique d'avoir des appels bloquants qui peuvent potentiellement durer jusqu'à quelques secondes dans une boucle événementielle comme Event Machine. De mémoire, il y a deux manières classiques de contourner le problème : - avoir un pool de threads dédiés à la résolution de noms (il me semble que c'est l'approche retenue par Nodejs) - ou réimplémenter la résolution de nom. Je fouille le code de faye-websocket-ruby et d'Event Machine, et je trouve rapidement ce que je cherche : https://github.com/eventmachine/eventmachine/blob/master/lib/em/resolver.rb. EventMachine réimplémente la résolution de nom (sans chercher le détail, on voit qu'il lit les fichiers `/etc/hosts` et `/etc/resolv.conf`). OK, j'ai une piste, il ne me reste plus qu'à l'exploiter. Je ne vois pas de moyen simple de monkey-patcher le code Ruby (il y a pas mal d'indirections), mais je peux jouer sur le fichier `/etc/hosts` pour forcer la résolution de nom sur 127.0.0.1. Ça confirme rapidement que la piste est bonne et me donne un moyen de réparer les tests d'intégration (au moins de manière provisoire) : https://github.com/cozy/cozy-stack/commit/15712ad12fb9b7a94f1089f5f08f959741c10c7c. Au moment du commit, j'avais encore un peu de mal à comprendre pourquoi ça avait changé sur la CI, mais j'ai eu l'explication quelques minutes plus tard. Notre admin/sys avait rajouté la résolution DNS en IPv6 mardi en milieu de journée, mais il n'avait pas fait le rapprochement entre ça et le problème de vignettes sur les tests d'intégration. Je suppose donc que la résolution DNS d'EventMachine doit se faire d'une manière légèrement différente et retourner l'adresse en IPv6 alors que la stack écoute sur 127.0.0.1 (IPv4). Pour le moment, je vais rester sur ce correctif mais si je trouve un peu de temps cette semaine, j'aimerais bien faire un rapport de bug détaillé à EventMachine, voire proposer un correctif. J'en profite pour rappeler trois astuces connues mais toujours aussi pertinentes pour débugger efficacement : 1. **Résumer ce que l'on sait** : idéalement, si on a un collègue disponible, on peut lui expliquer le problème, mais à défaut, on peut aussi utiliser [un canard en plastique](https://fr.wikipedia.org/wiki/M%C3%A9thode_du_canard_en_plastique) ou du papier et un crayon. Résumer ce que l'on sait et l'expliquer permet souvent de voir les trous et oublis. 2. **Faire des pauses** : quand on débug, il faut à la fois être attentif aux petits indices que l'on peut trouver et faire preuve d'imagination pour trouver de nouvelles pistes. Faire des pauses, que ce soit passer l'aspirateur, méditer, faire du sport, parler avec un collègue ou dormir, permet de laisser du temps au cerveau pour travailler en tâche de fond et revenir dans un état d'esprit plus disposé à voir ces petits indices. 3. **Diviser pour mieux régner** : enfin, il est facile de passer beaucoup de temps à chercher dans le vide, à suivre le déroulement complet de tout le processus dans un débugger sans trop savoir ce que l'on cherche. Il vaut mieux être capable d'émettre des hypothèses et formuler des moyens de vérifier si ces hypothèses sont vérifiées. Si l'hypothèse peut être vérifiée rapidement, autant le faire, même si ça vous paraît très peu probable que le problème vienne de là : au moins, vous serez fixé et vous pourrez plus facilement passer à la suite. Parfois, on peut faire des hypothèses assez précises, mais d'autres fois, on peut s'en remettre à une recherche dichotomique sur les différentes étapes. Si le processus pour reproduire un bug passe par un certain nombre d'étapes, on peut regarder si en gros à la moitié, on est dans l'état attendu ou non, puis en redivisant sur les étapes qui restent, on peut finir par isoler l'étape en question. Voilà, j'espère que ça vous inspirera la prochaine fois que vous partirez à la chasse aux bugs !

AltStyle によって変換されたページ (->オリジナル) /