Depuis près de deux semaines, nous avons constaté (par remontée utilisateur principalement) des lenteurs et des défauts (erreurs 503 dues à des timeouts) sur le HTTP et sur le S3 de garage (à la fois en récupération et en upload d'image sur Mastodon notamment).
Le premier niveau d'étude du problème a montré que seuls deux noeuds étaient disponibles sur le cluster. Pour cause : le serveur derrière bambino était éteint depuis le 23/06, probablement pour cause de capteur de température (refroidissement passif sur la machine, 34-35°c ambiant).
kubernetes avait pris le relais sur les services, et garage fonctionnait plutôt bien sur 2 noeuds. La machine a été redémarrée le 30/06 à 18h30 CEST, sans problème particulier. Le tranquility garage a été abaissé pour favoriser le resync, qui s'est achevé le 2/07 à 5h30 CEST environ.
La supervision americancurl montre des points de mesure éparses pour Garage mais pas pour le node exporter. Ceci semble indiquer un souci lié au cluster garage, quelle qu'en soit l'origine.
Le noeud montre un fort niveau d'iotime :
Sur des prises de mesure en volume io, pour autant il y a raisonnablement peu de lecture ou écriture, ici sur 5 minutes en accumulé :
On constate par périodes (toutes les quelques dizaines de secondes) que l'API garage, le S3 et le Web sont incapables de répondre aux requêtes immédiatement depuis ce noeud précisément. Ce qui explique les trous dans les métriques, ainsi que les erreurs continues malgré le retour du cluster à 3 noeuds.
Dans ces cas, les endpoints finissent par répondre, mais avec un délai notable :
curl -v > /dev/null 0.16s user 0.05s system 0% cpu 2:03.98 total
curl -v localhost:3903/metrics 0.00s user 0.02s system 0% cpu 1:00.80 total
Constaté plusieurs fois avec exactement 2 minutes, ou exactement 1 minute.
Les logs de garage sur le noeud sont évocateurs également : pas d'activité pendant l'attente, puis de nombreuses requêtes loggées immédiatement. Souvent, après l'attente, un warning particulier est loggé :
garage 2023-07-02T11:30:44.711211Z WARN garage_api::generic_server: Response: error 500 Internal Server Error, Internal error (Hyper error): error reading a body from connection: Connection reset by peer (os error 104)
Après la reprise le trafic est normal quelques dizaines de secondes, et le noeud lance plusieurs resyncs de blocs, avant de planter à nouveau.
Tout cela est à nouveau terminé, tous les nœuds ont réintégré le cluster et les resync errors sont bien tombées à zéro.
Pour suivi, nous subissons actuellement ce qui ressemble à une variante du problème. Après avoir déconnecté Bambino du cluster pour remplacement et sans avoir fini de resynchroniser Cyprus, la resync queue est énorme (300k blocs) et le service globalement lent.
Petite interprétation consolidée des faits en guise de RFO.
Pour les pressé•e•s :
bambino
sans que nous en ayons connaissancebambino
bambino
americancurl
americancurl
du cluster garage
garage
de cyprus
sur SSDgarage
dans nos conditions d'IOgarage
de bambino
sur SSD, service rétabli
americancurl
americancurl
americancurl
americancurl
dans le clusterNous ne conservons pas la métrologie par défaut assez longtemps pour remonter au début de l'incident, donc nous n'avons pas de report exact, mais plusieurs retours via Matrix et Mastodon nous ont mis la puce à l'oreille.
Le 27/06 probablement le premier retour :
Bonsouiiiiinr Est-ce qu’une difficulté à envoyer des médias sur MastoTedomum est de mon côté, ou c’est côté instance ? Bon courage pour tout
Genre une 503.
Le problème n'étant à l'époque pas général, il a mis bien plus de temps à être considéré comme un véritable incident et pas un défaut isolé dû à un restart de service ou une lenteur passagère.
La concomitance avec un incident sur Matrix impactant la cryptographie de bout en bout a encore plus masqué le défaut à nos yeux. Le problème est devenu critique le 2/07, soit 5 jours plus tard, lorsque le noeud le plus impactant dans le défaut - americancurl
- a commencé à perdre sérieusement pied.
Un défaut détaillé plus loin, lié vraisemblablement à la gestion de la resynchronisation des blocs et aux IO limitées sur nos disques durs de l'infrastructure, a commencé à ralentir notre cluster garage
, solution de stockage compatible S3. S3 est un standard pour le stockage d'objets sur le Web, le cluster en question stocke par exemples toutes les pièces-jointes Mastodon et vidéos Peertube de TeDomum.
C'est un cluster à 3 noeuds, configuré pour nécessiter 2 noeuds fonctionnels à tout moment et donc pouvoir en perdre un. La situation est toutefois toute autre lorsque le défaut n'est pas franc. Dans ce cas, les performances peuvent être fortement diminuées, ce que nous avons constaté : des requêtes vers le cluster qui durent 10 secondes à 2 minutes dans une situation où un noeud était franchement indisponible, puis revenu, et un autre noeud avec un défaut de disque dur.
Mastodon a été le service le plus impacté. Il est configuré pour utiliser notre cluster garage
comme stockage S3. Mastodon emploie la bilbiothèque Paperclip pour le stockage S3, qui elle-même s'appuie sur la bibliothèque Stoplight pour gérer les défauts éventuels du stockage en arrière-plan. Lorsqu'un toot est reçu avec une image, le texte est stocké en base de données, puis une tâche planifiée récupère l'image depuis l'instance d'origine et la stocke dans garage
pour la mettre ensuite à disposition. Ce décalage explique que très ponctuellement des images puissent être affichées comme indisponibles par Mastodon : le toot est là, mais pas encore l'image.
Dans le cas présent, les requêtes vers garage
prenant parfois jusqu'à 2 minutes, elles étaient automatiquement interrompues par Mastodon par un timeout à 1 minute. A chaque échec, Stoplight mémorise le défaut du service de stockage et place automatiquement les suivantes en échec, si bien que quelques échecs éparses (c'était le cas au début) peuvent avoir un effet en salves d'images non disponibles. Pire, le comportement allonge la durée de blocage lorsque les échecs se multiplient.
Au plus difficile de l'incident, c'est-à-dire les 7-8 juillet, 90% des images étaient en échec.
Un défaut d'IO sur americancurl
a possiblement été déclenché par un défaut sur bambino
et a entraîné un défaut général sur le cluster.
Très simplement, bambino
a été éteint du 22 juin au 30 juin. Il s'est éteint très vraisemblablement à cause d'une élévation de température (> 30° dans l'environnement et ventilation perfectible dans le meuble) et d'un déclenchement de la sécurité sur sa carte mère.
L'extinction de la machine n'a été détectée que le 29 juin car elle hébergeait uniquement un noeud garage
et la résilience native du cluster avait presque complètement masqué le défaut.
Le noeud semble avoir commencé à défaillir suite à un défaut d'IO sur son disque de stockage, connecté en USB3 en externe. Le transfert de données a montré une limite à 10Mo/s sur ce disque. Hors en l'absence de bambino
il a reçu mécaniquement 50% de requêtes en plus et probablement atteint ses limites.
Après plusieurs tests, captures réseau et captures syscalls, nous avons déterminé qu'un défaut des IO sur le noeud, notamment des IO en attente dans une routine asynchrone de garage
, causait l'indisponibilité de l'ensemble du processus et de ses interfaces : toute requête, y-compris sur les API d'administration était bloquée, de même que si tokio
, la bibliothèque d'IO asynchrone employée par garage
était bloquée.
Nous pensons que ce comportement a agravé l'impact en allongeant les durées de requêtes et en excluant régulièrement le noeud du cluster car il ne répondait plus assez vite. Ainsi, lorsque americancurl
était exclu du cluster alors que nous n'avions pas encore rétabli bambino
, le dernier noeud seul ne pouvait plus accepter de requête en écriture.
Ce défaut reste à isoler dans le code, il a été traité brutalement en isolant americancurl
du cluster une fois bambino
rétabli.
La cause racine est incertaine à ce stade. Notre meilleure piste reste un effet boule de neige liée à la queue de resynchronisation de ŋarage
.
Dans son comportement interne, garage
stocke les objets découpés en blocs, les blocs sont répliqués en asynchrone entre les noeuds, par un mécanisme de synchronisation. En cas d'erreur, les blocs à resynchroniser sont placée dans une queue pour ré-essayer. Cette queue est stockée dans une table de métadonnée (format LMDB sur notre instance).
A intervalle régulier (allégé par un mécanisme de traquility), garage
retente la synchronisation des blocs en attente, puis les replace dans la queue si l'erreur persiste.
Lorsqu'un noeud ne parvient plus à suivre le trafic du cluster pour quelque raison (par exemple celles évoquées puis haut pour americancurl
), alors les synchronisations de blocs échouent et les autres noeuds ajoutent tous les nouveaux blocs à la queue de resynchronisation, et les retentent en boucle.
Lorsque le nombre de blocs en queue (jusqu'à plus de 300000 dans notre cas) est trop important, la quantité d'IO en écriture liée à la sortie de queue et réinsertion est telle qu'elle effondre les performances du stockage, encore une fois en USB3 externe sur les noeuds du cluster, même sur des disques avec de bonnes performances.
Ce comportement a été intensifié par les tâches de nettoyage de média Mastodon qui suppriment des objets et ont rajouté encore à la queue.
Les premiers jours du défaut, nous n'avons d'abord pas pris la situation au sérieux. Le défaut était localisé sur americancurl
unqiuement et pas encore assez critique pour être visible généralement.
bambino
Bambino a été détecté hors ligne le 29 juin suite à une consultation des métriques.
Le défaut a été confirmé le 30 juin sur place, et bambino
a redémarré immédiatement.
Le 1er juillet bambino
avait fini de rattraper son retard sur le cluster, nous donnant espoir que le défaut était corrigé.
americancurl
En suivant les métriques garage
pour la reconstruction de bambino
nous avons détecté que americancurl
peinait à répondre aux requêtes et commencé à investiguer sur ce noeud le 1er juillet.
Par exemple le graphe de fin de resynchronisation avec bambino
montre des métriques à trous, lorsque l'API ne répond plus :
Le 2 juillet, munis de captures réseau, de captures syscalls, d'analyse des statistiques d'IO détaillées sur la machine, nous avons creusé ce défaut de americancurl
.
Nous avons conclu à un défaut d'IO, réseau ou stockage, en misant « probablement stockage ». Nous avons également identifié le comportement de garage
qui freeze globalement, identifié que la prochaine version permettrait de supprimer la dépendance aux fsync
qui pourrait améliorer ce défaut.
Finalement en fin de journée nous avons déconnecté americancurl
du cluster dans l'espoir de réablir un comportement correct. Les requêtes étaient à nouveaux plutôt correctement servies, avec toujours des défauts, en nombre croissant.
Le premier constat a été mené le 3 juillet : le taux d'IO continuait d'augmenter, y-compris sur les noeuds. Les IO approchaient les 100% sur les 2 noeuds.
Une partie s'expliquait par plus de requêtes sur 2 noeuds que sur 3, mais pas uniquement. Le taux d'IO a rapidement été isolé le 4 juillet comme des écritures sur les metadata, sans justifier de pourquoi le LMDB était particulièrement chargé.
Le 7 juillet, l'impact sur Mastodon a été confirmé avec la compréhension que le défaut était lié aux écritures S3 en échec et non aux lectures, et à Stoplight qui amplifiait l'impact.
Une première piste a été ouverte pour instrumenter garage
avec tokio-console
, piste qui n'a pas abouti à ce jour.
Le 8 juillet, la meilleure piste identifiée était la queue de resynchronisation, qui a donné lieu à une résolution.
Dès le 2/07, sous l'hypothèse que le problème sur americancurl
était lié aux IO, nous avons envisagé de remplacer le stockage de la machine, et évoqué les alternatives en fonction du nombre de slots disponibles.
Le 6/07, constatant que le problème était global sur le cluster et sans piste de résolution à court terme, nous avons commencé à évoquer de basculer partiellement ou totalement sur du stockage flash pour augmenter les performances au moins d'écriture sur les meta garage.
Cette démarche peut sembler contre-intuitive : il faut plutôt résoudre le problème racine qui génère les IO. Pour autant et pour d'autres usages nous savons que nous devrons déployer du flash d'ici 1 an. Le fil de messages kity#17 (closed) a été ouvert pour approfondir ce sujet.
Plus tard dans la journée du 6/07 nous avons fait l'hypothèse (fausse) que les reads random étaient à l'origine de la pression IO et migré les métadonnées garage
de cyprus
depuis le stockage rotatif USB3 vers le SSD interne qui sert également à l'OS, au moins de façon temporaire. Cela n'a pas résolu franchement le problème puisque bambino
traînait toujours derrière.
Le 8/07 nous avons confirmé la présence de place SSD suffisante sur bambino
pour migrer de même les métadonnées sur le même support que l'OS, ce que nous avons fait dans la journée. Cette intervention a rétabli des performances normales côté Mastodon, et le service est resté fonctionnel jusqu'à maintenant.
Plus tard le 8/07, pour préparer la réintégration de americancurl
nous avons planifié une coupure complète du noeud pour vérifier les slots, constaté un seul SATA3 interne utilisé pour l'OS, et pris la décision d'acheter 4To de SSD en SATA3.
Le SSD de americancurl
était reçu le 10/07, installé le 13/07 :
Après quelques corrections dues à une montée de version de Debian 10 à Debian 12, puis rollback à ce stade vers Debian 11, americancurl
est donc à nouveau dans le cluster.
Réintégrer un noeud garage
après plusieurs semaines d'interruption et donc une queue de resynchronisation était un exercice intéressant, et la métrologie collectée est préciseuse, donc capitalisée à suivre.
Le noeud a rejoint le cluster officiellement à 10h39 le 15/07 :
Ca a l'air ok, je réactive garage sur americancurl YOLO.
Le premier effet était une très forte charge IO, CPU et réseau due à la synchronisation des tables de métadonnées avec le reste du cluster :
Quelques instants plus tard, les blocs ont commencé à resynchroniser (aidés par une tranquility abaissée à 0 pendant la resynchronisation). Environ 3h plus tard la resynchronisation était terminée et la taille de la queue de resynchronisation retombée, de même que le nombre de blocs en erreur.
Pendant ce temps, les RPC du block manager - à un niveau croissant lentement et globalement élevé, interprété comme du requeue systématique les jours précédent - ont d'abord doublé pendant la resynchronisation, puis sont retombées à un niveau très bas.
Le taux global de RPC à plus de 100/s est reombé à max 10/s.
Plus surprenant, les IO disques elles-mêmes ont suivi un pattern en deux temps : d'abord pendant la resynchronisation les IO ont explosé, tout-à-fait supportées par les SSD puisque les principales écritures sont sur le full flash de americancurl
. Puis elles se sont restabilisées, à un niveau équivalent en écriture et un niveau supérieur en lecture à la situation précédente.
En approfondissant par noeud, sur americancurl
le comportement est classique : il a d'abord recopié les données (beaucoup de writes et reads) puis lancé un scrub (beaucoup de read constant). Puis il est revenu à un niveau très bas.
Sur cyprus
, les IO sont restées constantes pendant tout l'exercice.
Sur bambino
en revanche, les IO ont augmenté significativement après.
Le comportement est possiblement perturbé du fait que pour les métriques saisies, seul cyprus
reçoit des requêtes Web et API. Depuis, l'ensemble des noeuds a réintégré le cluster et nous continuons d'observer.
Avec kity#17 (closed), americancurl est rétabli en full flash, donc avec les meta sur flash.
On observe sur les jours à venir la métrologie garage pour confirmer l'intuition : que le raccourcissement de la resync queue s'accompagne d'une diminution des RPC au sein du cluster et d'une diminution des IO sur les meta liées au requeue de 300k blocs en boucle.
Si tel est le cas, on réfléchira à comment améliorer garage, au minimum la documentation, pour expliquer ce type de phénomène : quand un noeud commence à traîner, voire est déconnecté, l'allongement progressif de la resync queue a un impact croissant sur en IO de meta sur les autres noeuds, ce qui peut finir par effondrer complètement le cluster. La configuration du tranquility ne semble pas suffire à limiter cet impact dans le temps.
Après une semaine de recul la situation est toujours difficile : ça bombarde en io sur les SSD, mais c'est des SSD donc ça passe.
On continue d'attendre le rétablissement de americancurl, normalement ce soir, pour diminuer la taille de la resync queue et la quantité d'io.
La bascule des meta de bambino
sur SSD est terminée.
Par erreur, le cluster_layout
a été supprimé sur le noeud pendant la recopie, donc on a généré un nouveau layout et appliqué au passage, pour regénérer le fichier sur bambino
.
Prochaines actions entreprises :
bambino
sur SSD, il y a de la place disponible pour çaRésumé de nos derniers progrès sur le sujet.
De nombreuses tentatives n'ont pas résolu le défaut, qui est en partie amplifié par le comportement de Stoplight côté Mastodon, bloquant en amont les requêtes vers le backend, avec du backoff, lorsqu'une erreur est remontée par Garage. Concrètement, après 10 ou 20 erreurs, le backend est désactivé pendant plusieurs minutes avant de réessayer. Lorsqu'il réessaie il relance aussi toutes les tâches en attente et bombarde donc le backend, qui s'effondre, etc.
Quatre actions ont été menées avant-hier et hier pour essayer d'améliorer (avec un résultat positif, mais pas suffisant) :
cyprus
sur le SSD qui sert aussi à l'OS plutôt que l'USB externe ;cyprus
, les autres noeuds servant de standby à ce stadeamericancurl
qui générait un maximum de timeouts puisque dans un état encore pire que la semaine dernièreDELETE
par seconde sur le S3 quand elles tournaientDéjà on vois bien quand on retire americancurl du cluster l'effet sur les IOs
Les deux pods garage sont sur bambino et cyprus, le premier est à 100% d'IO (avec 300% d'oversuscribe) et le second est à 30% seulement. Ce qui peut s'expliquer par la bascule des meta de cyprus
sur du SSD.
Max a passé la tranquility du scrub et du resync à 20, et descendu le nombre de worker à 1 - on va voir si ça fait baisser la charge IOPS. Une explication plausible est que la quantité de blocs en resync, même avec une tranquility élevée, génère un grand nombre de retry et requeue, qui écrivent chacun des metadata et entraînent du write continu sur le LMDB.
Comparaison entre Cyprus et Bambino (on voit bien le passage sur SSD sur Cyprus et le 4/07 où le disque de Bambino commence à saturer en IO) :
De façon très intéressante, je constate des performances io dégradées également sur les autres noeuds.
Sur cyprus :
# time dd if=/dev/zero of=/mnt/ted1/debug/testwrite bs=1024 count=1 conv=fsync
real 0m4.942s
# time dd if=/dev/zero of=/mnt/ted1/debug/testwrite bs=1024 count=1 conv=fsync
real 0m1.705s
# time dd if=/dev/zero of=/mnt/ted1/debug/testwrite bs=1024 count=1 conv=fsync
real 0m2.087s
# time dd if=/dev/zero of=/mnt/ted1/debug/testwrite bs=1024 count=1 conv=fsync
real 0m2.103s
# time dd if=/dev/zero of=/mnt/ted1/debug/testwrite bs=1024 count=100 conv=fsync
real 0m1.345s
# time dd if=/dev/zero of=/mnt/ted1/debug/testwrite bs=1024 count=100 conv=fsync
real 0m1.711s
# time dd if=/dev/zero of=/mnt/ted1/debug/testwrite bs=1M count=1024 conv=fsync
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 75.472 s, 14.2 MB/s
real 1m15.475s
Les performances USB sont significativement inférieures à la normale, le fsync lui-même est particulièrement lent.
Une fois garage arrêté, je relance le même de fsync de 1ko en 1 fois, 100 fois, 10000 fois (10Mo) :
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync
real 0m 0.21s
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync
real 0m 0.50s
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync
real 0m 0.56s
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync
real 0m 0.65s
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync
real 0m 0.06s
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync
real 0m 0.20s
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync
real 0m 0.08s
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync
real 0m 0.05s
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=100 conv=fsync
real 0m 0.20s
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=100 conv=fsync
real 0m 0.51s
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=100 conv=fsync
real 0m 0.67s
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=100 conv=fsync
real 0m 0.76s
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=10000 conv=fsync
real 0m 0.69s
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=10000 conv=fsync
real 0m 1.60s
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=10000 conv=fsync
real 0m 0.31s
Et poussé jusqu'à 1Go par blocs de 1Mo pour tester le débit global :
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1M count=1024 conv=fsync
real 0m 28.35s
Ce qui donne un 300Mbps, pas fou mais honorable pour un disque USB.
Tests d'écriture sur le disque externe vs. le disque interne, pour tester l'état de la stack io et du disque lui-même. On écrit 1ko, puis 100ko en 100 séquence fsync de 1ko.
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync
real 0m 26.11s
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync
real 0m 0.19s
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync
real 0m 0.28s
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync
real 4m 15.84s
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=100 conv=fsync
real 1m 5.89s
Puis sur le stockage interne :
# time dd if=/dev/zero of=/host/root/testwrite bs=1024 count=1 conv=fsync
real 0m 0.09s
# time dd if=/dev/zero of=/host/root/testwrite bs=1024 count=1 conv=fsync
real 0m 0.09s
# time dd if=/dev/zero of=/host/root/testwrite bs=1024 count=1 conv=fsync
real 0m 0.07s
# time dd if=/dev/zero of=/host/root/testwrite bs=1024 count=1 conv=fsync
real 0m 0.09s
# time dd if=/dev/zero of=/host/root/testwrite bs=1024 count=100 conv=fsync
real 0m 0.11s
Tentative de capture d'une requête vers le /doesnotexist
du garage problématique, depuis l'apiserver qui émet la requête d'un côté, depuis le noeud où est le garage de l'autre. Une requête problématique vue de part et d'autre : aucun indice de défaut réseau côté client ou serveur.
No. Time Source Destination Protocol Length Info
262 *REF* 10.50.0.1 10.21.2.131 TCP 60 14089 → 3903 [SYN] Seq=0 Win=65280 Len=0 MSS=1280 SACK_PERM TSval=7052379 TSecr=0 WS=128
263 0.002686 10.21.2.131 10.50.0.1 TCP 60 3903 → 14089 [SYN, ACK] Seq=0 Ack=1 Win=64668 Len=0 MSS=1280 SACK_PERM TSval=3907639448 TSecr=7052379 WS=128
264 0.002743 10.50.0.1 10.21.2.131 TCP 52 14089 → 3903 [ACK] Seq=1 Ack=1 Win=65280 Len=0 TSval=7052382 TSecr=3907639448
265 0.002829 10.50.0.1 10.21.2.131 HTTP 207 GET /doesnotexist HTTP/1.1
266 0.005884 10.21.2.131 10.50.0.1 TCP 52 3903 → 14089 [ACK] Seq=1 Ack=156 Win=64640 Len=0 TSval=3907639451 TSecr=7052382
267 130.805263 10.21.2.131 10.50.0.1 HTTP/JSON 318 HTTP/1.1 400 Bad Request , JavaScript Object Notation (application/json)
268 130.805326 10.50.0.1 10.21.2.131 TCP 52 14089 → 3903 [ACK] Seq=156 Ack=267 Win=65024 Len=0 TSval=7183184 TSecr=3907770250
269 130.806836 10.50.0.1 10.21.2.131 TCP 52 14089 → 3903 [FIN, ACK] Seq=156 Ack=267 Win=65024 Len=0 TSval=7183185 TSecr=3907770250
270 130.836215 10.21.2.131 10.50.0.1 TCP 52 3903 → 14089 [FIN, ACK] Seq=267 Ack=157 Win=64640 Len=0 TSval=3907770281 TSecr=7183185
271 130.836249 10.50.0.1 10.21.2.131 TCP 52 14089 → 3903 [ACK] Seq=157 Ack=268 Win=65024 Len=0 TSval=7183215 TSecr=3907770281
No. Time Source Destination Protocol Length Info
1276 *REF* 10.50.0.1 10.21.2.131 TCP 60 14089 → 3903 [SYN] Seq=0 Win=65280 Len=0 MSS=1280 SACK_PERM TSval=7052379 TSecr=0 WS=128
1277 0.000058 10.21.2.131 10.50.0.1 TCP 60 3903 → 14089 [SYN, ACK] Seq=0 Ack=1 Win=64668 Len=0 MSS=1280 SACK_PERM TSval=3907639448 TSecr=7052379 WS=128
1278 0.002700 10.50.0.1 10.21.2.131 TCP 52 14089 → 3903 [ACK] Seq=1 Ack=1 Win=65280 Len=0 TSval=7052382 TSecr=3907639448
1279 0.002947 10.50.0.1 10.21.2.131 HTTP 207 GET /doesnotexist HTTP/1.1
1280 0.002977 10.21.2.131 10.50.0.1 TCP 52 3903 → 14089 [ACK] Seq=1 Ack=156 Win=64640 Len=0 TSval=3907639451 TSecr=7052382
1341 130.802996 10.21.2.131 10.50.0.1 HTTP/JSON 318 HTTP/1.1 400 Bad Request , JavaScript Object Notation (application/json)
1352 130.805458 10.50.0.1 10.21.2.131 TCP 52 14089 → 3903 [ACK] Seq=156 Ack=267 Win=65024 Len=0 TSval=7183184 TSecr=3907770250
1360 130.807532 10.50.0.1 10.21.2.131 TCP 52 14089 → 3903 [FIN, ACK] Seq=156 Ack=267 Win=65024 Len=0 TSval=7183185 TSecr=3907770250
1392 130.833810 10.21.2.131 10.50.0.1 TCP 52 3903 → 14089 [FIN, ACK] Seq=267 Ack=157 Win=64640 Len=0 TSval=3907770281 TSecr=7183185
1394 130.836460 10.50.0.1 10.21.2.131 TCP 52 14089 → 3903 [ACK] Seq=157 Ack=268 Win=65024 Len=0 TSval=7183215 TSecr=3907770281
Pendant les phases down, on note une différence de comportement selon la source des requêtes :
L'ICMP vers le pod garage, ou les connexions vers d'autres process qui tournent sur le même hôte ne posent pas de problème alors même que les requêtes garage sont bloquées.
Quand plusieurs requêtes sont lancées en parallèle, elles aboutissent toutes en même temps. Le comportement ressemble à un blocage côté garage ou système, qui bloque les requêtes, entraint une accumulation de requêtes inflight, qui augmente le nombre de threads tokio côté garage, tous bloqués, et augmente donc progressivement le load average. Lorsque ça débloque, tout est répondu, le LA instantané retombe très rapidement bas.
Logs de bambino sur le cluster de test, qui ne génère normalement aucune io pour de la lecture ou écriture de blocs :
garage 2023-07-02T11:30:31.808268Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.815648Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.822816Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.829907Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.837205Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.844637Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.852019Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.859065Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.866299Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.873121Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.880279Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.887466Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.894581Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.901931Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.909379Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.916364Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.923208Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.930386Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.937719Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.944907Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.952175Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.960922Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.969893Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.977068Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.984201Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.991150Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:31.998517Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.005441Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.012918Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.020021Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.027266Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.034109Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.041289Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.048421Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.055601Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.063233Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.070361Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.077223Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.084188Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.091034Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.097961Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.104282Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.117865Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.125035Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.132395Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.139675Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.146660Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.153710Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.161212Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.168686Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.176337Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.184301Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.191707Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.199354Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.206911Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.214644Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.222446Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.230353Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.238057Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.245716Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.253577Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.261014Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.319132Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.326743Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.334231Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.341957Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.349772Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.357260Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.364760Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.371899Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.379292Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.386837Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.394838Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.402866Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.459755Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.467162Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.474386Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.481640Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.488960Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.496409Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.504032Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.511669Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.519036Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.526161Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.533543Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.541116Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.548718Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.556414Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.564294Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.571683Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.579127Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.586271Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.593431Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.600737Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:30:32.608097Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3
garage 2023-07-02T11:34:17.206994Z INFO garage_rpc::system: Doing a bootstrap/discovery step (not_configured: false, no_peers: false, bad_peers: true)
garage 2023-07-02T11:34:17.421718Z ERROR garage_rpc::system: Failed to create kubernetes custom resource: ApiError: Apply failed with 1 conflict: conflict with "kubectl-client-side-apply" using apiextensions.k8s.io/v1: .spec.versions: Conflict (ErrorResponse { status: "Failure", message: "Apply failed with 1 conflict: conflict with \"kubectl-client-side-apply\" using apiextensions.k8s.io/v1: .spec.versions", reason: "Conflict", code: 409 })
garage 2023-07-02T11:34:17.480488Z INFO garage_rpc::kubernetes: Found Pod: Some("9221ed752ca612d327afb5be5a57a25c4366a4991859790e159b72fc8d3793b1")
garage 2023-07-02T11:34:17.480510Z INFO garage_rpc::kubernetes: Found Pod: Some("1fab23af95d8e30075c184e1179d4da395c7405724946cad810ea0afc47f9b21")
garage 2023-07-02T11:34:17.480520Z INFO garage_rpc::kubernetes: Found Pod: Some("bed6b7ea1f11c919eff8f5c1676411cf76b2e4a6374fe5aa5c3b8fa3ee45446f")
Stream closed EOF for tedomum-tests/garage-xzpl9 (garage-init)
Pendant le temps où le noeud americancurl est en défaut, les autres constatent bien un défaut de réponse, y-compris sur le RPC a priori :
garage 2023-07-02T11:30:41.746489Z ERROR garage_util::background::worker: Error in worker block_ref GC (TID 32): in try_send_and_delete in table GC:
garage GC: send tombstones
garage Could not reach quorum of 2. 1 of 2 request succeeded, others returned errors: ["Netapp error: Not connected: xxxxxxxxx"]
Depuis près de deux semaines, nous avons constaté (par remontée utilisateur principalement) des lenteurs et des défauts (erreurs 503 dues à des timeouts) sur le HTTP et sur le S3 de garage (à la fois en récupération et en upload d'image sur Mastodon notamment).
Le premier niveau d'étude du problème a montré que seuls deux noeuds étaient disponibles sur le cluster. Pour cause : le serveur derrière bambino était éteint depuis le 23/06, probablement pour cause de capteur de température (refroidissement passif sur la machine, 34-35°c ambiant).
kubernetes avait pris le relais sur les services, et garage fonctionnait plutôt bien sur 2 noeuds. La machine a été redémarrée le 30/06 à 18h30 CEST, sans problème particulier. Le tranquility garage a été abaissé pour favoriser le resync, qui s'est achevé le 2/07 à 5h30 CEST environ.
La supervision americancurl montre des points de mesure éparses pour Garage mais pas pour le node exporter. Ceci semble indiquer un souci lié au cluster garage, quelle qu'en soit l'origine.
Le noeud montre un fort niveau d'iotime :
Sur des prises de mesure en volume io, pour autant il y a raisonnablement peu de lecture ou écriture, ici sur 5 minutes en accumulé :
On constate par périodes (toutes les quelques dizaines de secondes) que l'API garage, le S3 et le Web sont incapables de répondre aux requêtes immédiatement depuis ce noeud précisément. Ce qui explique les trous dans les métriques, ainsi que les erreurs continues malgré le retour du cluster à 3 noeuds.
Dans ces cas, les endpoints finissent par répondre, mais avec un délai notable :
curl -v > /dev/null 0.16s user 0.05s system 0% cpu 2:03.98 total
curl -v localhost:3903/metrics 0.00s user 0.02s system 0% cpu 1:00.80 total
Constaté plusieurs fois avec exactement 2 minutes, ou exactement 1 minute.
Les logs de garage sur le noeud sont évocateurs également : pas d'activité pendant l'attente, puis de nombreuses requêtes loggées immédiatement. Souvent, après l'attente, un warning particulier est loggé :
garage 2023-07-02T11:30:44.711211Z WARN garage_api::generic_server: Response: error 500 Internal Server Error, Internal error (Hyper error): error reading a body from connection: Connection reset by peer (os error 104)
Après la reprise le trafic est normal quelques dizaines de secondes, et le noeud lance plusieurs resyncs de blocs, avant de planter à nouveau.