Le timeout MySQL à une ligne qui m'a pris trois jours à diagnostiquer

Le symptôme : un 500 qui ne se ressemble jamais

Un CRM B2B pour des commerciaux qui closent des deals et émettent des factures. Un matin, le support remonte des erreurs « la facture ne s'est pas créée ». Pas systématiquement. Pas chez tout le monde. Et, le détail qui rend fou, impossible à reproduire en cliquant moi-même. Je crée dix factures à la suite : zéro erreur. Je rejoue le scénario exact d'un ticket : ça passe.

Côté serveur, des HTTP 500 par à-coups. Mais pas de pattern dans les stack traces : tantôt l'erreur pointait sur l'écriture en base, tantôt sur une opération réseau, tantôt sur rien d'identifiable. Un bug qui n'a pas de signature claire, c'est le pire des deux mondes : on ne sait même pas quoi chercher dans le code.

Un bug qui ne se reproduit qu'en prod et seulement sous charge n'est presque jamais « dans le code » au sens classique. Il est dans ce que la charge ajoute : la concurrence, les timeouts, la contention de ressources.

L'enquête : corréler plutôt que deviner

Première règle quand on ne peut pas reproduire : arrêter d'essayer de reproduire, et aller lire ce que la prod, elle, a vu. J'ai passé deux jours dans les logs applicatifs et les breadcrumbs Sentry du flux de facturation. Pas pour trouver « l'erreur », je l'avais déjà, c'était un 500, mais pour trouver ce qui était différent les fois où ça plantait.

La piste est venue d'une corrélation temporelle. En alignant l'horodatage des 500 avec les logs métier, un motif est apparu : les erreurs tombaient quand deux agents facturaient le même deal quasi simultanément. Un cas rare en démo, fréquent en vrai : deux personnes d'une même équipe qui cliquent à quelques secondes d'intervalle sur le même dossier en fin de journée.

Et le second indice, décisif : les 500 ne tombaient jamais tout de suite. Ils arrivaient environ 50 secondes après le début de la requête concurrente. Un chiffre rond, reproductible. Quand un délai d'erreur est ce stable, ce n'est pas du hasard réseau, c'est un timeout configuré qui se déclenche.

La cause racine : une transaction trop longue contre un timeout trop court

La création d'une facture, ce n'est pas une simple insertion. C'est une transaction multi-étapes : générer le PDF, l'uploader sur Firebase Storage, puis écrire la ligne en MySQL. Le tout dans une seule transaction pour garantir la cohérence : pas de facture en base sans PDF accessible.

Or la génération du PDF et surtout l'upload vers Firebase prennent du temps. En conditions normales, quelques secondes. Mais sous charge, avec un Firebase qui ralentit et un PDF lourd, ça pouvait grimper à 70 à 120 secondes. Pendant tout ce temps, la transaction tient un verrou de ligne sur le deal facturé.

Maintenant, le piège. MySQL/InnoDB a une valeur par défaut pour innodb_lock_wait_timeout : 50 secondes. C'est le temps qu'une transaction accepte d'attendre un verrou détenu par une autre avant d'abandonner. Faites le calcul : si une première transaction tient son verrou pendant 90s, et qu'une seconde arrive pour facturer le même deal, la seconde attend… et au bout de 50s, MySQL la tue avec Lock wait timeout exceeded; try restarting transaction. Côté API, ça remonte en 500.

  t=0s    Agent A  ── BEGIN ──▶ lock(deal#42) ─▶ [ génère PDF + upload Firebase ... lent ... ]
                                  │
  t=8s    Agent B  ── BEGIN ──▶ WAIT lock(deal#42)  ⏳
                                  │ (attend que A libère)
  t=58s            Agent B  ✗ Lock wait timeout exceeded (50s)  ──▶ HTTP 500
                                  │
  t=95s   Agent A  ── COMMIT ─▶ (trop tard, B a déjà échoué)

Tout collait. « Seulement sous charge » → il faut deux requêtes concurrentes sur le même deal. « Impossible à reproduire seul » → un seul utilisateur ne crée jamais la collision. « Pas de stack trace stable » → selon le timing, l'erreur surgissait à des endroits différents du flux. Et le délai rond de ~50s était la signature du timeout InnoDB par défaut.

Le fix : une ligne, et de la lumière pour la prochaine fois

Le correctif immédiat tient en une instruction, posée à l'initialisation de chaque connexion du pool. On laisse aux transactions légitimement longues le temps de finir avant que la concurrente n'abandonne :

// init du pool de connexions, exécuté à chaque nouvelle connexion
pool.on('connection', (conn) => {
  // défaut MySQL = 50s, plus court que notre pire transaction de facture (~120s)
  conn.query('SET SESSION innodb_lock_wait_timeout = 120');
});

// + rendre le problème VISIBLE la prochaine fois
Sentry.addBreadcrumb({ category: 'invoice', message: 'tx:start lock(deal)', level: 'info' });
// ... génération PDF + upload Firebase ...
Sentry.addBreadcrumb({ category: 'invoice', message: 'tx:commit', level: 'info' });

Les breadcrumbs Sentry autour du verrou ne corrigent rien, mais ils transforment le prochain incident : au lieu de trois jours à corréler des horodatages à la main, on verra noir sur blanc « tx:start » sans « tx:commit » correspondant, avec la durée. Le diagnostic passe de jours à minutes. C'est un investissement, pas du décor.

Le fix profond : sortir le lent hors du verrou

La vraie correction structurelle ne touche pas au timeout, elle touche à la durée du verrou. Le PDF et l'upload Firebase n'ont aucune raison de se faire pendant que la ligne est verrouillée. On inverse l'ordre : faire tout le travail lent hors transaction (générer le PDF, l'uploader, récupérer l'URL), puis ouvrir une transaction courte qui ne fait qu'une écriture finale. Le verrou passe de 90 secondes à quelques millisecondes.

• Avant : BEGIN → lock → [PDF + upload, 90s] → write → COMMIT. Le verrou tenu tout du long.
• Après : [PDF + upload, 90s, sans verrou] → BEGIN → lock → write → COMMIT (quelques ms). La fenêtre de collision s'effondre.

Et il y a un corollaire indispensable : si le travail lent se fait avant l'écriture, il faut rendre la création de facture idempotente. Sinon un agent qui réessaie après un échec risque de créer un doublon, ou de ré-uploader un PDF orphelin. Une clé d'idempotence sur le couple (deal, agent) rend le retry sûr, c'est exactement le genre de garantie que je détaille dans mon article sur l'idempotence des agents IA. Sous charge, « réessayer sans danger » n'est pas un luxe, c'est la condition pour que le système se rattrape tout seul.

Ce que je retiens

• « Sous charge, irreproductible » = concurrence, jusqu'à preuve du contraire. Ce trio de symptômes pointe presque toujours vers de la concurrence, des timeouts ou de la contention de ressources, pas vers une faute de logique isolée.
• Le fix peut tenir en une ligne ; le diagnostic, c'est le métier. N'importe qui peut écrire SET SESSION innodb_lock_wait_timeout = 120. Le savoir-faire, c'est de comprendre pourquoi cette ligne, à cet endroit, et ce qu'elle ne résout pas.
• Instrumentez le flux pendant que vous y êtes. Le prochain incident similaire doit se diagnostiquer en minutes, pas en jours. Des breadcrumbs autour des sections critiques sont le meilleur ratio effort/valeur qui soit.
• Les valeurs par défaut sont des hypothèses déguisées. 50s de innodb_lock_wait_timeout, c'est un choix raisonnable… pour des transactions courtes. Dès qu'une transaction sort de l'ordinaire, chaque défaut mérite d'être questionné, pas hérité.

Ce post-mortem est la version technique d'une histoire que je raconte aussi côté état d'esprit : la même chasse au bug fantôme, vue comme une discipline mentale, est dans mon article sur le debugging façon hardware vintage. Ici on a démonté le moteur ligne par ligne ; là-bas on parle de la patience et de la méthode qui rendent ce démontage possible. Lecture complémentaire, pas redite.