Plus la tâche est simple, plus je fais des erreurs

Plus la tâche est simple, plus je fais des erreurs

Cette tâche triviale s'est produite un vendredi après-midi et aurait dû prendre 2 à 3 minutes. En général, comme toujours.

Un collègue m'a demandé de corriger le script sur son serveur. Je l'ai fait, je le lui ai tendu et j'ai laissé tomber par inadvertance : « Le temps passe 5 minutes plus vite. » Laissez le serveur gérer lui-même la synchronisation. Une demi-heure, une heure passa, et il soufflait toujours et jurait doucement.

"Stupide! — J'ai pensé, en passant à la console du serveur — d'accord, je vais faire une pause de quelques minutes supplémentaires.

Regardez ntp, rdate, sdwdate pas installé synchronisation temporelle désactivé et ne fonctionne pas.

# timedatectl
      Local time: Sun 2019-08-25 20:44:39 +03
  Universal time: Sun 2019-08-25 17:44:39 UTC
        RTC time: Sun 2019-08-25 17:39:52
       Time zone: Europe/Minsk (+03, +0300)
     NTP enabled: no
NTP synchronized: no
 RTC in local TZ: no
      DST active: n/a

Ici, je constate immédiatement que l'heure matérielle est correcte : il sera plus facile de naviguer plus loin.

C’est là que la série d’erreurs a commencé.

La première erreur. Confiance en soi

Clic-clac...

# systemctl enable systemd-timesyncd.service && systemctl start systemd-timesyncd.service && ntpdate 0.ru.pool.ntp.org && timedatectl set-ntp on && timedatectl
25 Aug 21:00:10 ntpdate[28114]: adjust time server 195.210.189.106 offset -249.015251 sec
      Local time: Sun 2019-08-25 21:00:10 +03
  Universal time: Sun 2019-08-25 18:00:10 UTC
        RTC time: Sun 2019-08-25 18:00:10
       Time zone: Europe/Minsk (+03, +0300)
     NTP enabled: yes
NTP synchronized: yes
 RTC in local TZ: no
      DST active: n/a

Tout va bien, l'heure est synchronisée, l'heure système correspond à celle du matériel. "Prends-le", dis-je et je retournai à mes affaires.

"Prendre quoi? - le collègue s'est indigné. "C'est la même heure !"

Plus vous résolvez des problèmes typiques, plus votre réflexion devient aveugle et vous ne pensez plus que la centième ou la millième situation sera différente, mais pas cette fois.

# timedatectl
      Local time: Sun 2019-08-25 21:09:15 +03
  Universal time: Sun 2019-08-25 18:09:15 UTC
        RTC time: Sun 2019-08-25 18:05:04
       Time zone: Europe/Minsk (+03, +0300)
     NTP enabled: yes
NTP synchronized: no
 RTC in local TZ: no
      DST active: n/a

L'heure du système est encore une fois erronée.

Essayons encore:

# ntpdate 0.ru.pool.ntp.org && timedatectl && sleep 1 && timedatectl
25 Aug 21:07:37 ntpdate[30350]: step time server 89.175.20.7 offset -249.220828 sec
      Local time: Sun 2019-08-25 21:07:37 +03
  Universal time: Sun 2019-08-25 18:07:37 UTC
        RTC time: Sun 2019-08-25 18:07:37
       Time zone: Europe/Minsk (+03, +0300)
     NTP enabled: yes
NTP synchronized: yes
 RTC in local TZ: no
      DST active: n/a
      Local time: Sun 2019-08-25 21:11:46 +03
  Universal time: Sun 2019-08-25 18:11:46 UTC
        RTC time: Sun 2019-08-25 18:07:37
       Time zone: Europe/Minsk (+03, +0300)
     NTP enabled: yes
NTP synchronized: no
 RTC in local TZ: no
      DST active: n/a

Faisons-le différemment :

# date -s "2019-08-25 21:10:30" && date && sleep 1 && timedatectl
Sun Aug 25 21:10:30 +03 2019
Sun Aug 25 21:10:30 +03 2019
      Local time: Sun 2019-08-25 21:14:36 +03
  Universal time: Sun 2019-08-25 18:14:36 UTC
        RTC time: Sun 2019-08-25 18:10:30
       Time zone: Europe/Minsk (+03, +0300)
     NTP enabled: yes
NTP synchronized: no
 RTC in local TZ: no
      DST active: n/a

Et alors:

# hwclock --hctosys && timedatectl && sleep 1 && timedatectl
      Local time: Sun 2019-08-25 21:11:31 +03
  Universal time: Sun 2019-08-25 18:11:31 UTC
        RTC time: Sun 2019-08-25 18:11:31
       Time zone: Europe/Minsk (+03, +0300)
     NTP enabled: yes
NTP synchronized: yes
 RTC in local TZ: no
      DST active: n/a
      Local time: Sun 2019-08-25 21:15:36 +03
  Universal time: Sun 2019-08-25 18:15:36 UTC
        RTC time: Sun 2019-08-25 18:11:32
       Time zone: Europe/Minsk (+03, +0300)
     NTP enabled: yes
NTP synchronized: no
 RTC in local TZ: no
      DST active: n/a

Le temps est réglé sur une fraction de seconde et recommence immédiatement à « se précipiter ».

En même temps, dans les journaux, au moment d'un tel changement manuel, nous voyons uniquement les rapports du système indiquant que l'heure a changé, respectivement, dans le bon/mauvais sens et occasionnellement. Resynchronisation à partir de systemd-timesyncd.

Aug 25 21:18:51 wisi systemd[1]: Time has been changed
Aug 25 21:18:51 wisi systemd-timesyncd[29258]: System time changed. Resyncing.
Aug 25 21:18:51 wisi systemd[1187]: Time has been changed
Aug 25 21:18:51 wisi systemd[1]: Time has been changed
Aug 25 21:18:51 wisi systemd[1187]: Time has been changed

ici

# ps afx | grep "[1]187"
 1187 ?        Ss     0:02 /lib/systemd/systemd --user

A ce stade, il fallait déjà en chercher la raison, mais en 18 ans d'administration, le cerveau a accumulé des statistiques sur les erreurs de « temps » et, par habitude, accuse à nouveau la synchronisation.
Éteignons-le complètement.

# timedatectl set-ntp off && systemctl stop systemd-timesyncd.service
# hwclock --hctosys && timedatectl && sleep 1 && timedatectl
      Local time: Sun 2019-08-25 21:25:40 +03
  Universal time: Sun 2019-08-25 18:25:40 UTC
        RTC time: Sun 2019-08-25 18:25:40
       Time zone: Europe/Minsk (+03, +0300)
     NTP enabled: no
NTP synchronized: no
 RTC in local TZ: no
      DST active: n/a
      Local time: Sun 2019-08-25 21:29:31 +03
  Universal time: Sun 2019-08-25 18:29:31 UTC
        RTC time: Sun 2019-08-25 18:25:41
       Time zone: Europe/Minsk (+03, +0300)
     NTP enabled: no
NTP synchronized: no
 RTC in local TZ: no
      DST active: n/a

et dans les journaux

Aug 25 21:25:40 wisi systemd[1]: Time has been changed
Aug 25 21:25:40 wisi systemd[1187]: Time has been changed
Aug 25 21:29:30 wisi systemd[1]: Time has been changed
Aug 25 21:29:30 wisi systemd[1187]: Time has been changed

Resynchronisation disparu et sinon les journaux sont vierges.

Vérification des conclusions tcpdump sur le port 123 sur toutes les interfaces. Il n’y a aucune demande, mais le temps presse encore.

Deuxième erreur. Se précipiter

Il reste une heure avant la fin de la semaine de travail, et je ne veux pas partir en week-end avec un problème trivial non résolu (ne faites pas attention à l'heure dans le code, l'article a été écrit dans les jours suivants ).
Et là encore, au lieu de chercher la raison, j’ai commencé à essayer de trouver une explication au résultat. Je dis « inventer » parce que, aussi logique que puisse être l’explication du résultat, il s’agit d’une approche erronée pour résoudre le problème.

Ce serveur est un serveur de streaming et convertit le flux DVB-S2 en IP. Le flux DVB-S contient des horodatages, c'est pourquoi les récepteurs, multiplexeurs, brouilleurs et téléviseurs les utilisent souvent pour synchroniser l'horloge du système. Les pilotes de la carte DVB-S sont intégrés au noyau, donc le moyen le plus rapide de garantir que le flux DVB-S2 est supprimé est de déconnecter les câbles provenant des « plaques ». Heureusement, le serveur est derrière le mur, qu'il en soit ainsi.

Bien sûr, si les journaux contenaient ce qui devrait s'y trouver, cela ne serait pas arrivé, mais nous en parlerons encore une fois à la fin de l'article.

Eh bien, puisque nous avons déjà supprimé tous les signaux satellites, nous supprimerons également les signaux terrestres - en même temps, nous retirons tous les câbles réseau. Le serveur est coupé du monde extérieur et fonctionne de manière totalement autonome, mais l'horloge système est toujours pressée.

La semaine de travail est terminée et le problème de date/heure en lui-même n'est pas critique, vous pouvez donc simplement rentrer chez vous, mais là, je fais une nouvelle erreur.

Troisième erreur. Conseillers

Jamais! Ne posez jamais de questions sur les forums et les sites spécialisés généralistes (à la stackoverflow) si la réponse nécessite plus que l'étude de la première page de Google et la lecture d'une page de manuel.

Ils vous renverront vers Google, liront le même homme et expliqueront populairement les règles du forum/site, mais ne vous donneront pas de réponse.

Voici quelques facteurs objectifs :

  • personne d'autre que vous ne peut connaître le problème également ;
  • personne ne peut faire des tests dans les mêmes conditions que les vôtres

et subjectif :

  • vous ne pouvez pas contribuer pleinement à la résolution du problème, car vous avez déjà trouvé la « bonne » direction et présentez l'essence du problème en vous concentrant sur elle ;
  • le contremaître (modérateur, ancien, administrateur) a toujours raison, si le contremaître a tort... eh bien, vous savez...

Si, en répondant aux commentaires, vous êtes resté dans les limites d'un vocabulaire censuré, alors vous avez les nerfs solides.

décision

Il n’est pas nécessaire de diviser les tâches en tâches simples et complexes.

Nous cessons de nous fier à notre expérience, à nos statistiques, à nos conseillers et commençons non pas à « expliquer » le résultat final, mais à en rechercher systématiquement la raison.

Puisque quelqu'un règle l'heure, l'appel système correspondant doit se produire.

Tout comme dans la documentation des logiciels, les meilleurs documents sont les sources, de même dans l'administration système, le meilleur assistant est l'audit, dans notre cas. vérifié.

Un moment de douteJ'ai parcouru le mana, mais je n'étais pas entièrement sûr que l'heure sous Linux ne puisse être réglée que horloge_settime и régler l'heure du jour, donc pour le premier test j'ai choisi tous les appels « adaptés » :

# man syscalls | col | grep -F '(2)' | grep -vE '(:|;)' | grep -E '(time|date|clock)' | sed "s/(2).*//" | xargs -I SYSCALL echo "-S SYSCALL " | xargs echo
-S adjtimex -S clock_adjtime -S clock_getres -S clock_gettime -S clock_nanosleep -S clock_settime -S futimesat -S getitimer -S gettimeofday -S mq_timedreceive -S mq_timedsend -S rt_sigtimedwait -S s390_runtime_instr -S setitimer -S settimeofday -S stime -S time -S timer_create -S timer_delete -S timer_getoverrun -S timer_gettime -S timer_settime -S timerfd_create -S timerfd_gettime -S timerfd_settime -S times -S utime -S utimensat -S utimes

et jeter s390_runtime_instr, stime, timerfd_createqui auditctl ne l'ayant pas reconnu, a d'abord lancé un audit sous la forme :

auditctl -a exit,always -S adjtimex -S clock_adjtime -S clock_getres -S clock_nanosleep -S clock_settime -S futimesat -S getitimer -S gettimeofday -S mq_timedreceive -S mq_timedsend -S rt_sigtimedwait -S semtimedop -S setitimer -S settimeofday -S time -S timer_create -S timer_delete -S timer_getoverrun -S timer_gettime -S timer_settime -S timerfd_gettime -S timerfd_settime -S times -S utime -S utimensat -S utimes

Après vous être assuré qu'il n'y a pas d'autres journaux dans les emplacements de journaux qui m'intéressent appels système En plus de ces deux-là, je ne les ai utilisés que par la suite.

Exécuter un audit des appels système horloge_settime и régler l'heure du jour et essaye de changer la date :

# auditctl -a exit,always -S clock_settime -S settimeofday && date -s "2019-08-22 12:10:00" && sleep 5 && auditctl -D

Un délai de cinq secondes est ajouté pour que notre « parasite » soit assuré de corriger l'heure.

Nous regardons le rapport:

# aureport -s -i

Syscall Report
=======================================
# date time syscall pid comm auid event
=======================================
Warning - freq is non-zero and incremental flushing not selected.
1. 08/22/2019 12:10:00 settimeofday 3088 chkcache_proces root 479630
2. 08/26/2019 09:37:06 clock_settime 1538 date root 479629

Ici, nous voyons notre données et inconnu de nous chkcache_processes. Cela s'est retrouvé dans le rapport ci-dessus car aureport a trié la sortie par date lors de la conversion à partir du binaire, et l'événement s'est produit au moment où nous avons défini date -s "2019/08/22 12:10:00".
Qui lui a donné naissance ?

# ausearch -sc settimeofday --comm "chkcache_proces"
----
time->Thu Aug 22 12:10:00 2019
type=PROCTITLE msg=audit(1566465000.000:479630): proctitle="/usr/local/bin/oscam"
type=SYSCALL msg=audit(1566465000.000:479630): arch=c000003e syscall=164 success=yes exit=0 a0=7fde0dfc6e60 a1=0 a2=136cf a3=713ba56 items=0 ppid=3081 pid=3088 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts20 ses=68149 comm="chkcache_proces" exe="/usr/local/bin/oscam" key=(null)

/usr/local/bin/oscam - notre parasite a été trouvé. Malgré son comportement « malveillant », il est impossible de refuser le système d'accès conditionnel, mais j'aimerais quand même savoir oscam, WTF ?

La réponse se trouve rapidement dans sources:

#if defined(CLOCKFIX)
if (tv.tv_sec > lasttime.tv_sec || (tv.tv_sec == lasttime.tv_sec && tv.tv_usec >= lasttime.tv_usec)) // check for time issues!
{
  lasttime = tv; // register this valid time
}
  else
{
  tv = lasttime;
  settimeofday(&tv, NULL); // set time back to last known valid time
  //fprintf(stderr, "*** WARNING: BAD TIME AFFECTING WHOLE OSCAM ECM HANDLING, SYSTEMTIME SET TO LAST KNOWN VALID TIME **** n");
}

Comme c'est mignon ici commenté doubler avertissement...

Source: habr.com

Ajouter un commentaire