Twitter iPhone pliant OnePlus 11 PS5 Disney+ Orange Livebox Windows 11

Bug étrange NTP

18 réponses
Avatar
François Boisson
Bonjour à tous

J'ai chez moi depuis plus de six ans un serveur NTP (qui est d'ailleurs dans
le pool NTP). Ce serveur marche fort bien mais a un bug bizarre depuis le
passage à squeeze (sans certitude, je ne me souviens pas de ce bug au début
mais bon). Les faits:

Toutes les 2^22 secondes soit en gros 1 mois 20 jours, le serveur, prend
89,06s d'avance (et est ejecté du pool donc). Les bugs se
sont produit à ces dates (et peut être avant):
12/08/2014 13:44:02
30/09/2014 02:56:06 17/11/2014 15:02:38 05/01/2015 04:14:12
22/02/2015 17:21:55
12/04/2015 07:30:46
30/05/2015 20:40:21

Le serveur est un stratum 2 et ça n'est pas du semble-t-il à une dérive du
serveur de stratum 1 (un décalage à ce point n'est de toute façon pas
possible). Le noyau est un 2.6.32-5-686 et la ntp est 1:4.2.6.p2+dfsg-1+deb6u3

Sur un autre serveur ntp, lui aussi dans le pool, lui aussi squeeze, avec la
même version de ntp mais le noyau de lenny 2.6.26-2-686, il n'y a pas ce bug.

Je pense plutôt à un souci matériel, j'ai le souvenir d'un plantage du module
rtc de temps à autre avant de changer de noyau. La machine a été reboutée aux
dates suivantes
francois@cerbere:/var/log$ ls -altr dmesg*
-rw-r----- 1 root adm 6847 17 avril 2012 dmesg.4.gz
-rw-r----- 1 root adm 6456 20 mai 2013 dmesg.3.gz
-rw-r----- 1 root adm 6494 19 déc. 2013 dmesg.2.gz
-rw-r----- 1 root adm 7935 7 févr. 2014 dmesg.1.gz
-rw-r----- 1 root adm 22567 10 avril 2014 dmesg.0
-rw-r----- 1 root adm 23616 7 mai 2014 dmesg
le passage en squeeze ayant été fait le 7 février 2014.

C'est un FitPC installé en 2008 qui marche de façon continuelle (là son uptime
est de 11:42:58 up 437 days, 3 min

Le bug en lui même ne me gêne pas, je vais faire un «at» régulier qui
relancera le démon ntp tous les 2^22 secondes mais j'aimerais avoir une
explication notamment savoir pourquoi 89,06s.

Si quelqu'un a une idée.


François Boisson

--
Lisez la FAQ de la liste avant de poser une question :
http://wiki.debian.org/fr/FrenchLists

Pour vous DESABONNER, envoyez un message avec comme objet "unsubscribe"
vers debian-user-french-REQUEST@lists.debian.org
En cas de soucis, contactez EN ANGLAIS listmaster@lists.debian.org
Archive: https://lists.debian.org/20150718114851.99eaf637493362ddc9b84842@maison.homelinux.net

8 réponses

1 2
Avatar
Christophe De Natale
Bonsoir,

Et en te fiant à ta première impression du souci matériel, ne serait-ce pas une interférence horloge rtc >> pile du bios ?

Cordialement,

Christophe De Natale



Le 20 juil. 2015 à 22:10, François Boisson a écrit :

Le Mon, 20 Jul 2015 10:08:07 +0200
François Boisson a écrit:

L'heure matérielle est censée se mettre à jour toutes les 11 minutes. En fait
tout ce passe comme si la machine s'était gelée pendant ces 89,06s. On
pourrait peut être imaginer que pour une raison ou une autre, aucune
interruption n'ait été traitée pendant ce laps de temps. Maids ça me parait
tiré par les cheveux. La machine est un FitPC cadencé à 499.955MHz



Autre chose qui m'incite à penser à des interruptions non traitées:
Voilà un partie du fichier de log (j'"ai une manie, je je fais des logs de
tout):
Dans l'ordre, Jour, Mois, Heure, Minutes, Seconde, Decalage avec
un autre serveur NTP, temps en secondes depuis le début de la journée
et enfin temps écoulé depuis la ligne suivante.

18 Jul 9 32 24 -0,001192 34344 317
18 Jul 9 37 41 -0,001053 34661 325
18 Jul 9 43 6 -0,000326 34986 318
18 Jul 9 48 24 89,060533 35304 314
18 Jul 9 53 38 89,06075 35618 314
18 Jul 9 58 52 89,060771 35932 318
18 Jul 10 4 10 89,061083 36250 314
18 Jul 10 9 24 89,060588 36564 315
18 Jul 10 14 39 89,060753 36879 403
18 Jul 10 21 22 -0,000297 37282 314
18 Jul 10 26 36 -0,000587 37596 314

On voit bien le souci à 09:48:24, on voit bien que malgré le décalage
de leur système, le temps écoulé entre deux enregistrements restde de l'ordre
de 325s. On voit également que lorsque j'ai remis la machine à l'heure,
il y a un décalage de l'ordre de 89s (403 - 89 = 314). Le script est un
while /bin/true; do
betises diverses
sleep 300
done

sleep appelle xnanosleep qui appelle nanosleep. La norme POSIX indique que

«Configurer la valeur de l'horloge CLOCK_REALTIME avec clock_settime() ne
doit pas avoir d'effet sur les threads bloqués attendant un service de temps
relatif basé sur cette horloge. Cela inclut la fonction nanosleep() ;
En conséquence, ces services de temps doivent expirer lorsque la durée
relative demandée est atteinte, indépendamment de l'ancienne ou
la nouvelle valeur de l'horloge. »

En clair donc, il y eu pour la machine 314s d'interruption horloge entre chaque
ligne, changement d'heure ou pas. Lorsque j'ai changé d'heure, lui faisant rattraper
les 89,06s perdus, on retrouve ces 89,06s dans l'expression du temps écoulé entre deux
mesures (314s vraies + 89s de décalage du à ma remise à l'heure). Par contre, lors
du bug, il n'y a pas de décalage dans le temps écoulé, on aurait du avoir
314-89"5 [À ce stade, je félicite les 5 qui sont encore en train de lire!]. Bref
tout ça pour dire qu'on dirait bien que la machine s'est figée 89s ou que c'est
tout comme. Vraiment mystérieux ce truc.

François Boisson

--
Lisez la FAQ de la liste avant de poser une question :
http://wiki.debian.org/fr/FrenchLists

Pour vous DESABONNER, envoyez un message avec comme objet "unsubscribe"
vers
En cas de soucis, contactez EN ANGLAIS
Archive: https://lists.debian.org/ melinux.net




--
Lisez la FAQ de la liste avant de poser une question :
http://wiki.debian.org/fr/FrenchLists

Pour vous DESABONNER, envoyez un message avec comme objet "unsubscribe"
vers
En cas de soucis, contactez EN ANGLAIS
Archive: https://lists.debian.org/
Avatar
Vincent Lefevre
On 2015-07-20 22:10:52 +0200, François Boisson wrote:
Autre chose qui m'incite à penser à des interruptions non traitées:



Mais pourquoi toutes les 2^22 secondes, et pourquoi pendant
89,06 secondes?

En clair donc, il y eu pour la machine 314s d'interruption horloge
entre chaque ligne, changement d'heure ou pas. Lorsque j'ai changé
d'heure, lui faisant rattraper les 89,06s perdus, on retrouve ces
89,06s dans l'expression du temps écoulé entre deux mesures (314s
vraies + 89s de décalage du à ma remise à l'heure). Par contre, lors
du bug, il n'y a pas de décalage dans le temps écoulé, on aurait du
avoir 314-89"5 [À ce stade, je félicite les 5 qui sont encore en
train de lire!]. Bref tout ça pour dire qu'on dirait bien que la
machine s'est figée 89s ou que c'est tout comme. Vraiment mystérieux
ce truc.



Voilà, ta machine a été enlevée par des extraterrestres! :)

Pendant ces 89 secondes, est-ce qu'il y a des choses qui apparaissent
dans les logs? Et si tu envoies un message dans les logs toutes les
10 secondes, que se passe-t-il pendant ces 89 secondes?

--
Vincent Lefèvre - Web: <https://www.vinc17.net/>
100% accessible validated (X)HTML - Blog: <https://www.vinc17.net/blog/>
Work: CR INRIA - computer arithmetic / AriC project (LIP, ENS-Lyon)

--
Lisez la FAQ de la liste avant de poser une question :
http://wiki.debian.org/fr/FrenchLists

Pour vous DESABONNER, envoyez un message avec comme objet "unsubscribe"
vers
En cas de soucis, contactez EN ANGLAIS
Archive: https://lists.debian.org/
Avatar
François Boisson
Le Sun, 26 Jul 2015 14:38:08 +0200
Vincent Lefevre a écrit:

On 2015-07-20 22:10:52 +0200, François Boisson wrote:
> Autre chose qui m'incite à penser à des interruptions non traitées:

Mais pourquoi toutes les 2^22 secondes, et pourquoi pendant
89,06 secondes?




Si je le savais... Prochain bug dans une semaine.

[...]


Voilà, ta machine a été enlevée par des extraterrestres! :)

Pendant ces 89 secondes, est-ce qu'il y a des choses qui apparaissent
dans les logs? Et si tu envoies un message dans les logs toutes les
10 secondes, que se passe-t-il pendant ces 89 secondes?



Justement, on dirait qu'il ne se passe rien, nada, que dalle, nothing, la
machine semble être gelée complètement d'après les logs: Il y a une période ou
aucun évènement n'a eu lieu...

à suivre...

François Boisson
Avatar
Francois Boisson
Bien le bug est passé comme prévu, voilà ce que ça donne:

[code]
22:52:26 <---- HEURE SUR UN AUTRE SERVEUR NTP: heure exacte donc
vendredi 4 septembre 2015, 22:52:26 (UTC+0200) <---- DATE MACHINE (date)
0 <--- HEURE système moins HEURE RTC en secondes (via un pgm C maison)
22:52:34
vendredi 4 septembre 2015, 22:52:34 (UTC+0200)

0
22:52:43
vendredi 4 septembre 2015, 22:52:43 (UTC+0200)

0
22:52:54
vendredi 4 septembre 2015, 22:52:54 (UTC+0200)
-89
22:53:02
vendredi 4 septembre 2015, 22:53:02 (UTC+0200)
-89
22:53:10
vendredi 4 septembre 2015, 22:53:10 (UTC+0200)
-89
[..]
22:59:46
vendredi 4 septembre 2015, 22:59:46 (UTC+0200)
-89
22:59:54
vendredi 4 septembre 2015, 22:59:54 (UTC+0200)
-89
23:00:02
vendredi 4 septembre 2015, 23:00:02 (UTC+0200)
0 <--------------- RECALAGE heure RTC sans intervention
23:00:11
vendredi 4 septembre 2015, 23:00:11 (UTC+0200)

0
23:00:19
vendredi 4 septembre 2015, 23:00:19 (UTC+0200)

0
[/code]
Le serveur NTP a été relancé à
[code]16354 ntpd Fri Sep 4 23:46:17 2015 [/code]
parce que il
avait toujours un décalage de 89s avec le reste du monde.
Log de poolntp (heure GMT):
[code]
1441409460,"2015-09-04 23:31:00",-0.0000973939895629883,1,-13.7
1441408361,"2015-09-04 23:12:41",-0.00238072872161865,1,-15.5
1441407236,"2015-09-04 22:53:56",0.000102996826171875,1,-17.3
1441406139,"2015-09-04 22:35:39",-0.0020374059677124,1,-19.3
1441405024,"2015-09-04 22:17:04",-0.0000807046890258789,1,-21.4
1441403883,"2015-09-04 21:58:03",-0.00218832492828369,1,-23.6 <--- RELANCE
SERVEUR 1441402698,"2015-09-04 21:38:18",-89.0613644123077,-4,-25.8
1441401493,"2015-09-04 21:18:13",-89.0638047456741,-4,-23
1441400294,"2015-09-04 20:58:14",-89.0625076293945,-4,-20 <---- DECALAGE
SERVEUR 1441399167,"2015-09-04 20:39:27",0.00154829025268555,1,20
1441398054,"2015-09-04 20:20:54",-0.000956535339355469,1,20
1441396948,"2015-09-04 20:02:28",0.00281929969787598,1,20
1441395821,"2015-09-04 19:43:41",-0.00122296810150146,1,20
[/code]

Bilan:
* J'avais redémarré le serveur. Si le bug est lié au serveur NTP, le prochain
aurait eu lieu le Dimanche 6/09 au matin et non le 4/09. C'est donc
indépendant du serveur NTP.
* L'heure prévu du bug (le 4 septembre vers 22h53.) était parfaite.
* Le fait que l'heure système ne décroche jamais de l'heure d'un autre serveur
NTP montre que l'horloge système fonctionne correctement
* C'est un décalage brusque et immédiat de l'heure RTC de 89s dans l'avenir
* À 23:00 visiblement l'heure RTC s'est recalé sur l'heure système mais le
serveur NTP a continué sur la mauvaise heure.
* Mon hypothèse de gel de la machine est fausse, on a bien le serveur NTP
interrogé toutes les 8s

Questions:
* Pourquoi l'heure RTC se décale comme ça?
* Pourquoi ce décalage s'impose au serveur NTP? Ça n'est pas logique, l'heure
fiable c'est l'heure système.

Prochain BUG le 23 Octobre à 9:58 GMT (donc à 11:58 heure Française). Si vous
avez des tests à proposer...

En clair: Je n'y comprends pas grand chose.

François Boisson
Avatar
Sylvain L. Sauvage
Le samedi 5 septembre 2015, 09:30:47 Francois Boisson a écrit :
[…]
Questions:
* Pourquoi l'heure RTC se décale comme ça?
* Pourquoi ce décalage s'impose au serveur NTP?



Et aussi : Pourquoi le serveur NTP voit le décalage quand il
apparaît mais pas quand il disparaît ?

Ça n'est pas logique, l'heure fiable c'est l'heure système.



Effectivement, il n’y a pas de raison logique pour que NTP se
cale sur la RTC. Mais il y a des raisons de caler la RTC sur le
temps NTP.

Et ça aiderait à répondre à la question que tu n⠀™as pas
posée : Comment la RTC reprend la bonne heure ?

J’avais une piste : le noyau. En effet, c’est ce que fait
l’option CONFIG_RTC_SYSTOHC de Linux : toutes les 11 minutes, i l
cale la RTC avec l’heure système si « l’espac e utilisateur » dit
qu’il est synchronisé avec NTP.
Sauf que cette option a été ajoutée au noyau 3.10 et n ’existe
pas dans le 2.6…

Prochain BUG le 23 Octobre à 9:58 GMT (donc à 11:58 heure
Française). Si vous avez des tests à proposer...



Je dirais bien que pouvoir intercepter les appels à la RTC
pourrait être intéressant mais ça me semble une grosse t âche…

En clair: Je n'y comprends pas grand chose.



Et grâce à moi, tu y comprends encore moins ;o)

--
Sylvain Sauvage
Avatar
François Boisson
Le Sat, 05 Sep 2015 11:31:29 +0200
"Sylvain L. Sauvage" a écrit:

Et aussi : Pourquoi le serveur NTP voit le décalage quand il
apparaît mais pas quand il disparaît ?



dans le deuxième cas le décalage est trop grand et ans ce cas, NTP ne rattrape
pas l'heure. Ce qui est bizarre c'est que ntpd ne fait jamais de sauts
brusques... Les logs de NTP montre un décalage brutale avant 22:57 et après
22:40.


> Ça n'est pas logique, l'heure fiable c'est l'heure système.

Effectivement, il n’y a pas de raison logique pour que NTP se
cale sur la RTC. Mais il y a des raisons de caler la RTC sur le
temps NTP.

Et ça aiderait à répondre à la question que tu n’as pas
posée : Comment la RTC reprend la bonne heure ?

J’avais une piste : le noyau. En effet, c’est ce que fait
l’option CONFIG_RTC_SYSTOHC de Linux : toutes les 11 minutes, il
cale la RTC avec l’heure système si « l’espace utilisateur » dit
qu’il est synchronisé avec NTP.
Sauf que cette option a été ajoutée au noyau 3.10 et n’existe
pas dans le 2.6…




Mince je pensais que cela existait déjà sur le 2.6. C'était mon explication...


> Prochain BUG le 23 Octobre à 9:58 GMT (donc à 11:58 heure
> Française). Si vous avez des tests à proposer...

Je dirais bien que pouvoir intercepter les appels à la RTC
pourrait être intéressant mais ça me semble une grosse tâche…




Driver=rtc_cmos...


> En clair: Je n'y comprends pas grand chose.

Et grâce à moi, tu y comprends encore moins ;o)




Bon, à suivre...
Avatar
Sylvain L. Sauvage
Le samedi 5 septembre 2015, 17:11:48 François Boisson a écrit :
[… CONFIG_RTC_SYSTOHC …]
> Sauf que cette option a été ajoutée au noyau 3.10 et
> n’existe pas dans le 2.6…

Mince je pensais que cela existait déjà sur le 2.6. C'é tait
mon explication...



Vérifie quand même sur ton noyau (/boot/config-*), ça a peut-
être été rétroporté. (Mais l’option n⠀™apparaît pas dans le
2.6.32.67 de kernel.org, donc c’est mal barré.)

--
Sylvain Sauvage
Avatar
François Boisson
Le Sat, 05 Sep 2015 19:45:57 +0200
"Sylvain L. Sauvage" a écrit:

Vérifie quand même sur ton noyau (/boot/config-*), ça a peut-
être été rétroporté. (Mais l’option n’apparaît pas dans le
2.6.32.67 de kernel.org, donc c’est mal barré.)



C'est effectivement absent.... Bon, si il n'y avait que ça d'incompréhensible,
ça irait.....
1 2