Hoe eenvoudiger de taak, hoe vaker ik fouten maak

Hoe eenvoudiger de taak, hoe vaker ik fouten maak

Deze triviale taak ontstond op een vrijdagmiddag en had 2-3 minuten moeten duren. Over het algemeen, zoals altijd.

Een collega vroeg mij om het script op zijn server te repareren. Ik deed het, overhandigde het aan hem en liet per ongeluk vallen: "De tijd is 5 minuten snel." Laat de server de synchronisatie zelf afhandelen. Een half uur, een uur ging voorbij, en hij pufte nog steeds en vloekte stilletjes.

"Dom! — Ik dacht, terwijl ik overschakelde naar de serverconsole — oké, ik neem nog een paar minuten pauze.

Wij kijken ntp, rdate, sdwdate niet geïnstalleerd tijdsynchronisatie uitgeschakeld en niet actief.

# 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

Hier merk ik meteen dat de hardwaretijd correct is: het zal gemakkelijker zijn om verder te navigeren.

Dit is waar de reeks fouten begon.

De eerste fout. Zelfvertrouwen

Klik klak...

# 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

Alles is in orde, de tijd is gesynchroniseerd, de systeemtijd komt overeen met die van de hardware. ‘Neem aan,’ zei ik en keerde terug naar mijn werk.

"Pak wat? - de collega was verontwaardigd. "Het is dezelfde tijd!"

Hoe vaker je typische problemen oplost, hoe meer je denken verblindt en je niet meer denkt dat de honderdste of duizendste situatie anders zal zijn, maar deze keer niet.

# 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

De systeemtijd klopt weer niet.

Laten we het opnieuw proberen:

# 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

Laten we het anders doen:

# 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

Maar zo:

# 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

De tijd is ingesteld op een fractie van een seconde en begint onmiddellijk weer te "haasten".

Tegelijkertijd zien we in de logboeken ten tijde van een dergelijke handmatige wijziging alleen systeemmeldingen dat de tijd respectievelijk in de goede/verkeerde richting is veranderd en af ​​en toe Opnieuw synchroniseren van 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

hier

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

Op dit punt was het al nodig om naar de reden te zoeken, maar gedurende 18 jaar administratie hebben de hersenen statistieken verzameld over ‘tijd’-fouten en geven ze, uit gewoonte, opnieuw de schuld aan synchronisatie.
Laten we het volledig uitschakelen.

# 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

en in de logboeken

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

Opnieuw synchroniseren verdwenen en verder zijn de boomstammen ongerept.

Het controleren van de conclusies tcpdump op poort 123 op alle interfaces. Er zijn geen verzoeken, maar de tijd dringt nog steeds.

Fout twee. Haast

Er is nog een uur over tot het einde van de werkweek, en ik wil niet naar het weekend vertrekken met een triviaal onopgelost probleem (let niet op de tijd in de code, het artikel is in de volgende dagen geschreven ).
En ook hier begon ik, in plaats van naar de reden te zoeken, te proberen een verklaring voor het resultaat te bedenken. Ik zeg ‘uitvinden’, want hoe logisch de verklaring voor het resultaat ook mag zijn, het is een gebrekkige benadering om het probleem op te lossen.

Deze server is een streamingserver en converteert de DVB-S2-stream naar IP. De DVB-S-stream bevat tijdstempels, dus ontvangers, multiplexers, scramblers en televisies gebruiken deze vaak om de systeemklok te synchroniseren. DVB-S-kaartstuurprogramma's zijn in de kernel ingebouwd, dus de snelste manier om ervoor te zorgen dat de DVB-S2-stream wordt verwijderd, is door de kabels die van de "platen" komen los te koppelen. Gelukkig staat de server achter de muur, het zij zo.

Als de logboeken hadden vermeld wat er had moeten staan, zou dit natuurlijk niet zijn gebeurd, maar daarover later meer aan het einde van het artikel.

Omdat we alle satellietsignalen al hebben verwijderd, zullen we ook de terrestrische signalen verwijderen - tegelijkertijd trekken we alle netwerkkabels eruit. De server raakt afgesloten van de buitenwereld en werkt volledig autonoom, maar de systeemklok heeft nog steeds haast.

De werkweek is voorbij en het probleem met de datum/tijd zelf is niet van cruciaal belang, dus je kunt gewoon naar huis gaan, maar hier maak ik een nieuwe fout.

Fout drie. Adviseurs

Nooit! Stel nooit vragen op forums en algemeen gespecialiseerde (a la stackoverflow) sites als het antwoord daarop meer vereist dan het bestuderen van de eerste pagina van Google en het lezen van één manpagina.

Ze sturen je terug naar Google, lezen dezelfde man en leggen in de volksmond de regels van het forum/site uit, maar geven je geen antwoord.

Hier zijn enkele objectieve factoren:

  • niemand behalve jijzelf kan het probleem ook kennen;
  • Niemand kan tests uitvoeren onder dezelfde omstandigheden als de jouwe

en subjectief:

  • je geeft misschien niet alle input voor het oplossen van het probleem, omdat je al de ‘juiste’ richting hebt bedacht en de essentie van het probleem presenteert, waarbij je je daarop concentreert;
  • de voorman (moderator, oldtimer, beheerder) heeft altijd gelijk, als de voorman ongelijk heeft... nou ja, je weet wel...

Als je bij het reageren op opmerkingen binnen de grenzen van de gecensureerde woordenschat bent gebleven, dan heb je sterke zenuwen.

beslissing

Het is niet nodig om taken te verdelen in eenvoudig en complex.

We vertrouwen niet langer op onze ervaring, statistieken en adviseurs en beginnen het eindresultaat niet te “verklaren”, maar consequent naar de reden te zoeken.

Omdat iemand de tijd instelt, moet de bijbehorende systeemoproep plaatsvinden.

Net zoals bij softwaredocumentatie de beste documenten de bronnen zijn, zo is in ons geval bij systeembeheer audit de beste assistent gecontroleerd.

Een moment van twijfelIk heb de mana doorgenomen, maar was er niet helemaal zeker van dat de tijd in Linux alleen kan worden ingesteld klok_insteltijd и ingesteldetijd van de dag, dus voor de eerste test heb ik alle “geschikte” oproepen gekozen:

# 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

en weggooien s390_runtime_instr, stime, timerfd_createwelke auditctl herkende het niet, lanceerde aanvankelijk een audit in de vorm:

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

Nadat ik ervoor heb gezorgd dat er geen andere logs zijn op de loglocaties waarin ik geïnteresseerd ben systeemoproepen Naast deze twee heb ik ze alleen verder gebruikt.

Een systeemoproepaudit uitvoeren klok_insteltijd и ingesteldetijd van de dag en probeer de datum te wijzigen:

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

Er wordt een vertraging van vijf seconden toegevoegd, zodat onze “parasiet” gegarandeerd de tijd corrigeert.

Laten we het rapport bekijken:

# 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

Hier zien wij onze gegevens en ons onbekend chkcache_processen. Het kwam in het bovenstaande rapport terecht omdat aureport de uitvoer sorteerde op datum bij het converteren van binair getal, en de gebeurtenis plaatsvond op het tijdstip dat we hadden ingesteld datum -s "2019-08-22 12:10:00".
Wie heeft hem ter wereld gebracht?

# 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 - onze parasiet is gevonden. Ondanks het ‘kwaadwillige’ gedrag is het onmogelijk om het systeem van voorwaardelijke toegang te weigeren, maar ik zou het toch graag willen weten oscam, WTF?

Het antwoord is snel gevonden in broncodes:

#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");
}

Wat ziet het er hier schattig uit commentaar gegeven lijn waarschuwing...

Bron: www.habr.com

Voeg een reactie