To trywialne zadanie powstało pewnego piątkowego popołudnia i powinno zająć 2-3 minuty. Generalnie jak zawsze.
Kolega poprosił mnie o naprawienie skryptu na jego serwerze. Zrobiłem to, podałem mu i niechcący upuściłem: „Czas leci o 5 minut szybko”. Pozwól serwerowi zająć się samą synchronizacją. Minęło pół godziny, godzina, a on nadal sapał i cicho przeklinał.
"Głupi! — pomyślałem, przełączając się na konsolę serwera — OK, zrobię sobie jeszcze kilka minut przerwy.
Patrzymy ntp, rdate, sdwdate nie zainstalowany synchronizacja czasu wyłączony i nie działa.
# 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
Tutaj od razu zauważę, że czas sprzętowy jest prawidłowy: łatwiej będzie nawigować dalej.
I tu zaczęła się seria błędów.
Pierwszy błąd. Pewność siebie
Kliknij-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
Wszystko ok, czas zsynchronizowany, czas systemowy zgodny ze sprzętowym. – Weź to – powiedziałem i wróciłem do swoich spraw.
„Bierz co? - kolega był oburzony. „To ten sam czas!”
Im częściej rozwiązujesz typowe problemy, tym bardziej Twoje myślenie staje się mętne i nie myślisz już, że setna czy tysięczna sytuacja będzie inna, ale nie tym razem.
# 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
Czas systemowy znów jest błędny.
Spróbujmy jeszcze raz:
# 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
Zróbmy to inaczej:
# 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
Ale tak:
# 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
Czas ustawiony jest na ułamek sekundy i natychmiast zaczyna znowu „biec”.
Jednocześnie w logach w momencie takiej ręcznej zmiany widzimy jedynie raporty systemowe, że czas zmienił się odpowiednio w dobrą/niewłaściwą stronę i sporadycznie Ponowna synchronizacja z 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
tutaj
# ps afx | grep "[1]187"
1187 ? Ss 0:02 /lib/systemd/systemd --user
W tym momencie trzeba było już szukać przyczyny, ale przez 18 lat administracji mózg zgromadził statystyki dotyczące błędów „czasowych” i z przyzwyczajenia ponownie obwinia synchronizację.
Wyłączmy to całkowicie.
# 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
i w logach
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
Ponowna synchronizacja zniknął, a poza tym dzienniki są nieskazitelne.
Sprawdzanie wniosków tcpdump na porcie 123 na wszystkich interfejsach. Nie ma żadnych próśb, ale czas wciąż ucieka.
Błąd drugi. Pośpiech
Do końca tygodnia pracy została godzina, a nie chcę wyjeżdżać na weekend z banalnym, nierozwiązanym problemem (nie zwracajcie uwagi na godzinę w kodzie, artykuł był pisany w kolejnych dniach ).
I tu znowu, zamiast szukać przyczyny, zacząłem próbować wymyślić wyjaśnienie wyniku. Mówię „wymyślić”, ponieważ niezależnie od tego, jak logiczne może być wyjaśnienie wyniku, jest to błędne podejście do rozwiązania problemu.
Ten serwer jest serwerem przesyłania strumieniowego i konwertuje strumień DVB-S2 na IP. Strumień DVB-S zawiera znaczniki czasu, dlatego odbiorniki, multipleksery, szyfratory i telewizory często wykorzystują je do synchronizacji zegara systemowego. Sterowniki karty DVB-S są wbudowane w jądro, więc najszybszym sposobem na usunięcie strumienia DVB-S2 jest odłączenie kabli wychodzących z „płyt”. Na szczęście serwer jest za ścianą i niech tak będzie.
Oczywiście gdyby w logach było zawarte to co powinno się tam znajdować to by do tego nie doszło, ale o tym jeszcze raz na końcu artykułu.
No cóż, skoro usunęliśmy już wszystkie sygnały satelitarne, usuniemy także naziemne – jednocześnie wyciągamy wszystkie kable sieciowe. Serwer zostaje odcięty od świata zewnętrznego i działa całkowicie autonomicznie, lecz zegar systemowy wciąż się śpieszy.
Tydzień pracy dobiegł końca, a sama kwestia daty/godziny nie jest krytyczna, więc możesz po prostu wrócić do domu, ale tutaj popełniam nowy błąd.
Błąd trzeci. Doradcy
Nigdy! Nigdy nie zadawaj pytań na forach i ogólnie wyspecjalizowanych stronach (a la stackoverflow), jeśli odpowiedź na nie wymaga czegoś więcej niż przestudiowania pierwszej strony Google i przeczytania jednej strony podręcznika.
Odeślą Cię z powrotem do Google, przeczytają tego samego człowieka i popularnie wyjaśnią zasady obowiązujące na forum/stronie, ale nie dadzą Ci odpowiedzi.
Oto kilka obiektywnych czynników:
- nikt oprócz Ciebie nie może znać problemu;
- nikt nie jest w stanie przeprowadzić testów w takich samych warunkach jak Twoje
i subiektywne:
- możesz nie dać całego wkładu w rozwiązanie problemu, ponieważ już wyznaczyłeś „właściwy” kierunek i przedstawiasz istotę problemu skupiając się na nim;
- majster (moderator, weteran, admin) ma zawsze rację, jeśli majster się myli... no cóż, wiadomo...
Jeśli odpowiadając na komentarze, mieściłeś się w granicach cenzurowanego słownictwa, to masz mocne nerwy.
decyzja
Nie ma potrzeby dzielenia zadań na proste i złożone.
Przestajemy polegać na naszym doświadczeniu, statystykach, doradcach i zaczynamy nie „wyjaśniać” efektu końcowego, ale konsekwentnie szukać przyczyny.
Ponieważ ktoś ustawia czas, musi nastąpić odpowiednie wywołanie systemowe.
Tak jak w dokumentacji oprogramowania najlepszymi dokumentami są źródła, tak w administracji systemem najlepszym asystentem jest w naszym przypadku audyt audytowane.
Chwila zwątpieniaPrzejrzałem manę, ale nie byłem do końca pewien, czy czas w Linuksie można ustawić tylko zegar_ustawionyczas и ustaw porę dnia, więc do pierwszego testu wybrałem wszystkie „odpowiednie” wywołania:
# 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
i odrzucanie s390_runtime_instr, stime, timerfd_create, Który audytctl nie rozpoznałem, początkowo uruchomiłem audyt w postaci:
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 utimesPo upewnieniu się, że w interesujących mnie lokalizacjach nie ma innych logów wywołania systemowe Oprócz tych dwóch, dalej korzystałem tylko z nich.
Uruchamianie audytu wywołań systemowych zegar_ustawionyczas и ustaw porę dnia i spróbuj zmienić datę:
# auditctl -a exit,always -S clock_settime -S settimeofday && date -s "2019-08-22 12:10:00" && sleep 5 && auditctl -D
Dodano pięciosekundowe opóźnienie, aby nasz „pasożyt” miał gwarancję prawidłowego wskazania czasu.
Zobaczmy raport:
# 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
Tutaj widzimy nasze dane i nieznane nam chkcache_processes. Znalazło się to w powyższym raporcie, ponieważ aureport posortował dane wyjściowe według daty podczas konwersji z pliku binarnego, a zdarzenie miało miejsce w momencie, gdy ustawiliśmy data -s "2019-08-22 12:10:00".
Kto go urodził?
# 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 - znaleziono naszego pasożyta. Pomimo „złośliwego” zachowania nie można odrzucić systemu dostępu warunkowego, ale nadal chciałbym wiedzieć Oscam, WTF?
Odpowiedź można szybko znaleźć w :
#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");
}
Jak tu słodko wygląda skomentował linia ostrzeżenie...
Źródło: www.habr.com