L'horloge gelée que personne n'a remarquée

Un tableau de bord Grafana était figé depuis 14 h. Pas en panne, pas en erreur : figé. Des lignes plates et plausibles, des panneaux au vert, les moniteurs du pool NTP silencieux. Selon chaque vérification censée attraper un problème, il n'y avait pas de problème. L'horloge allait bien.

L'horloge n'allait pas bien. Elle avait cessé de connaître l'heure des heures plus tôt et mentait avec assurance depuis ce temps-là, et la seule raison pour laquelle je l'ai attrapée, c'est que je fixais justement un nombre qui ne devrait jamais se répéter.

Il est question ici de ts2phc-go, une réimplémentation en Go que j'ai écrite du ts2phc de linuxptp. Sa tâche est étroite : discipliner le PHC d'une carte réseau au signal PPS d'un récepteur GPS. Sur un serveur du pool NTP public, ce PHC est la fondation. chrony le lit comme référence locale et sert du stratum 1 à qui le demande. Si le PHC dérive, tout le monde en aval dérive. Si le PHC gèle, tout le monde en aval gèle, et personne ne s'en aperçoit, parce qu'une horloge gelée qui tique encore est impossible à distinguer d'une horloge qui fonctionne pour tout ce qui ne lui demande que l'heure.

Le nombre qui ne devrait pas se répéter#

Le servo dans ts2phc-go journalise son état à chaque seconde. Un des champs est freq_ppb, la correction de fréquence qu'il applique présentement à l'oscillateur du PHC, en parties par milliard. Un servo qui discipline pousse toujours là-dessus. L'oscillateur dérive avec la température, la boucle le poursuit, la correction vacille constamment dans les derniers chiffres. C'est le battement de cœur. Un servo vivant ne rapporte pas le même flottant exact deux fois de suite, parce que le monde physique ne lui tend pas le même décalage exact deux fois de suite.

Je faisais défiler les journaux et j'ai vu ceci :

14:02:51  offset       4 ns  freq_ppb 17139.674132458233  ...
14:02:52  offset       4 ns  freq_ppb 17139.674132458233  ...
14:02:54  offset       4 ns  freq_ppb 17139.674132458233  ...

17139.674132458233, identique octet pour octet, sur un écart de trois secondes. Ça, ce n'est pas une horloge qui tient bon. Une horloge qui tient bon gigote encore dans les chiffres faibles. Ça, c'est une horloge qui a arrêté de calculer. Le servo ne pilotait rien. Il imprimait la dernière valeur qu'il avait jamais calculée, encore et encore, comme une montre arrêtée que quelqu'un aurait calée pour qu'elle ait l'air de marcher.

Pourquoi chaque moniteur restait au vert#

La défaillance était en amont du servo. Le flux NTP de gpsd était mort. La boucle principale dans ts2phc-go lit un décalage de la source GPS à chaque itération, et quand la source n'a rien à donner, la boucle frappe un continue. À chaque itération. Donc le servo n'a jamais échantillonné de nouveau décalage, ne s'est jamais mis à jour, et le PHC a simplement cessé d'être discipliné. Il a coasté sur son propre oscillateur à partir de 14 h, dérivant librement, pendant que le servo restait là à réciter son dernier freq_ppb.

Voici la partie qui devrait vous mettre mal à l'aise. chrony, en aval, a continué de lire ce PHC comme sa référence et a continué d'annoncer du stratum 1 au pool, parfaitement content. Du point de vue de chrony, rien n'avait changé. Le PHC retournait toujours une heure. L'heure était fausse et de plus en plus fausse, mais chrony n'avait aucun moyen de le savoir, parce qu'il lit le PHC comme référence locale sans recoupement indépendant. Un PHC gelé mais plausible est impossible à distinguer d'un PHC vivant pour tout ce qui ne lui demande que l'heure qu'il est. Il faut lui demander quelque chose qu'il ne peut pas feindre, soit s'il se fait encore dire l'heure par quelque chose à l'extérieur de lui-même.

Les moniteurs externes du pool ne pouvaient pas le voir non plus. Ils mesurent le décalage par rapport au consensus, et une horloge qui a gelé alors qu'elle était déjà correcte reste assez correcte, pour un temps, pour passer. Le temps que la dérive aurait fait déclencher un seuil, le dommage à la confiance en aval était déjà fait.

La récupération a été simple une fois que je savais où regarder. Redémarrer gpsd, attendre une localisation 3D (elle est revenue sur 23 à 25 satellites), la source a recommencé à tendre des décalages frais à la boucle, le servo s'est réveillé, et chrony en aval s'est reverrouillé à environ +9 ns à environ +/-19 ns. Le correctif au complet, c'était un redémarrage de processus. Le trouver, c'était remarquer un flottant.

Comment j'en suis arrivé là : lire les structs contre les en-têtes#

Je devrais reculer, parce que la raison pour laquelle j'ai fait confiance à cet indice freq_ppb du tout, c'est que j'avais passé beaucoup de temps à l'intérieur de ce code, à vérifier ce qu'il rapportait contre ce que le matériel faisait réellement. C'est cette habitude qui a fait sauter la valeur gelée aux yeux.

Quand j'ai écrit ts2phc-go la première fois, j'ai fait la chose qu'on est censé faire avec une ABI noyau : j'ai lu mes structs Go ligne par ligne contre les en-têtes UAPI dans l'arbre du noyau, plutôt que de me fier à ce qu'ils avaient l'air corrects. Ils n'avaient pas l'air corrects.

Le struct ClockCaps faisait 76 octets : huit champs int32 plus une zone réservée [11]int32. Mais PTP_CLOCK_GETCAPS encode une copie de 80 octets dans son numéro d'ioctl. Le noyau se fiche de la taille de votre struct. Il copie le nombre d'octets que dit l'ioctl, ce qui veut dire qu'à chaque démarrage, le noyau écrivait quatre octets au-delà de la fin de mon struct. Ça n'avait pas encore planté. C'est le pire genre de bogue, celui qui corrompt la mémoire sans dire un mot.

// PTP_CLOCK_GETCAPS encodes an 80-byte copy. This struct was 76.
// The kernel writes the size the ioctl says, not the size you allocated.
type ClockCaps struct {
	MaxAdj    int32
	NChannels int32
	NAlarm    int32
	NExtTs    int32
	NPerOut   int32
	PPS       int32 // was swapped with NPins below
	NPins     int32
	CrossTs   int32
	AdjPhase  int32
	MaxPhaseAdj int32 // was missing entirely
	Reserved  [11]int32
}

Pendant que j'étais là-dedans, j'en ai trouvé deux autres. Les champs pps et n_pins étaient inversés par rapport à la définition UAPI, donc je lisais chacun comme l'autre. Et max_phase_adj manquait complètement de mon struct, ce qui est une partie de la raison pour laquelle la taille était fausse.

Puis un autre, séparé, à un endroit différent. PTP_EXTTS_REQUEST2, la requête d'horodatage externe v2, était encodée avec le numéro d'ioctl 10. Le numéro 10, c'est PTP_CLOCK_GETCAPS2. La requête v2 est le numéro 11. Donc chaque fois que le code demandait une requête d'horodatage externe v2, il émettait en fait un getcaps, le noyau retournait ENOTTY, et le code retombait silencieusement sur la v1. Silencieusement. Ça marchait. Ça perdait juste discrètement PTP_STRICT_FLAGS à chaque fois et personne ne le remarquait, parce que retomber sur la v1 est une chose parfaitement fonctionnelle à faire.

Le bogue que j'ai laissé exprès#

Le geste satisfaisant, c'est de corriger chaque bogue qu'on trouve. Le geste correct ne l'est parfois pas, et c'est un de ces cas-là.

Ce bogue de numéro d'ioctl v2, celui qui faisait que la requête stricte retombait silencieusement sur la v1, je l'ai laissé non corrigé sur la carte réseau de production. Exprès.

Le raisonnement : faire en sorte que la requête v2 se déclenche vraiment n'avait aucun avantage pour ce déploiement. Le chemin v2 active un mode strict à un seul front. Cette conception ne veut pas du mode strict à un seul front. Elle veut les deux fronts plus un filtre (plus là-dessus dans un instant), ce qui est une stratégie délibérément différente. Donc corriger le bogue aurait, au mieux, ne rien changé d'utile, et au pire changé le comportement de la carte réseau exacte assise en production en train de servir le pool, pour aucun bénéfice. Le repli sur la v1 n'était pas une défaillance, c'était le comportement que je voulais, atteint par accident. Savoir quels bogues ne pas corriger est une compétence, et c'en est une plus discrète que de savoir comment les corriger.

Le filtre des deux fronts, qui est le vrai point#

La raison pour laquelle cette conception veut les deux fronts, c'est la carte réseau. L'Intel i210 livre à la fois le front montant et le front descendant du PPS au FIFO d'horodatage. Un lecteur naïf qui n'attend qu'un front par seconde en obtient deux, les entrelace, et calcule du n'importe quoi. Un audit antérieur du flux brut d'impulsions avait signalé des « impulsions » de 458 ms, ce qui n'est pas une impulsion PPS, c'est l'écart entre un front montant d'une seconde et un front descendant de la seconde précédente lu par erreur comme un seul intervalle.

Donc la fonction phare de ts2phc-go est un filtre de front dynamique qui gère les deux fronts, se verrouille sur la vraie frontière de seconde, et rejette le bruit. Quand il se verrouille, il journalise exactement ce qu'il voit :

edge filter locked, pulse width 9.999994ms

Une largeur d'impulsion de 9,999994 ms, c'est la vraie impulsion PPS de ce récepteur. Une fois le filtre verrouillé, il n'y a plus aucun des intervalles de n'importe quoi de 458 ms que l'audit naïf avait signalés, parce que le filtre sait quel front est lequel et ne discipline que contre la frontière qui compte.

L'indice des 37 secondes#

Encore une mesure des débuts, parce que c'est un exemple net d'un nombre faux qui vous dit quelque chose de vrai. La toute première fois que le servo a roulé de bout en bout, il a rapporté un décalage de 37000000084 ns. Ça, c'est 37 secondes et des poussières. Un servo qui est à 37 secondes près n'est pas un servo avec un problème de réglage, c'est un servo qui mesure deux échelles de temps différentes.

Le PHC est discipliné à TAI par ptp4l. NMEA, du GPS, rapporte UTC. TAI est exactement 37 secondes en avance sur UTC depuis 2017. Le ts2phc en C gère ça en lisant leap-seconds.list. Mon correctif a ajouté le décalage de 37 secondes directement dans la source NMEA, et le décalage s'est effondré de 37 secondes à quelques dizaines de nanosecondes. Les 84 ns restantes dans cette première lecture, c'était le vrai décalage, posé bien en vue sous une erreur d'étiquetage de 37 secondes.

Il y avait d'autres points d'hygiène que j'ai alignés sur la version C une fois que j'ai su qu'il fallait les chercher : vider le FIFO EXTTS au démarrage pour que le servo ne commence pas en mâchant des horodatages périmés mis en tampon par le noyau, configurer la broche SDP correctement pour que l'i210 achemine le PPS là où le code l'attend, et bien gérer les fronts plutôt que de supposer un front par seconde.

Le livrer sans en livrer plus que prévu#

Les correctifs (taille et ordre des champs du struct, le décalage de seconde intercalaire NMEA, le vidage du FIFO et SDP et la gestion des fronts) devaient se rendre sur la boîte de production. Le déploiement était délibérément ennuyeux. Compilé nativement sur la machine avec go1.25 et CGO désactivé, sauvegardé le binaire en cours d'exécution d'abord, remplacé, redémarré. Il s'est reverrouillé en environ une seconde et a récupéré à la ligne de base, autour de -5 ns à environ +/-17 ns.

Une chose a fait surface avant que je livre, pas après, ce qui est le but de regarder. git HEAD portait des commits au-delà des trois correctifs que je comptais déployer : il y avait aussi un changement de seuil de premier pas là-dedans. Une recompilation naïve de HEAD aurait livré ça discrètement avec les trois que j'avais réellement revus et voulus. J'ai signalé la portée et l'ai ramenée à l'ensemble prévu plutôt que de laisser le commit en trop embarquer sans examen. Livrer plus que ce que vous avez décidé de livrer est sa propre sorte d'horloge gelée : ça a l'air de la chose que vous avez testée, jusqu'au moment où ça ne l'est plus.

Quand une mesure devient un souvenir#

Un servo gelé ressemble exactement à un servo qui fonctionne, à moins d'avoir une vérification indépendante.

Le PHC ne l'a dit à personne. Il ne pouvait pas. Il n'avait aucun moyen de distinguer « je suis discipliné et correct » de « je coaste sur une valeur que j'ai calculée à 14 h », parce que rien ne lui posait la seule question qui compte, qui n'est pas quelle heure est-il mais à quel point récemment on t'a dit l'heure. chrony a posé la première question et a obtenu une réponse confiante. Personne n'a posé la deuxième jusqu'à ce que je remarque un flottant qui refusait de changer.

Donc maintenant le défaut d'échantillonnage de la boucle est bruyant au lieu de silencieux, et la chose à laquelle je fais le plus confiance n'est pas l'horloge ni le moniteur, mais le nombre identique octet pour octet, le signe qu'une mesure a cessé d'être une mesure et est devenue un souvenir.

Le code est sur GitHub.