To proste zadanie pojawiło się w jeden z piątkowych dni i miało zająć 2-3 minuty. Generalnie, jak zawsze.
Kolega poprosił mnie o poprawienie skryptu na jego serwerze. Zrobiłem, oddałem mu, rzucając mimochodem: „Czas się spieszy o 5 minut”. To jego serwer, niech sam się zajmie synchronizacją. Minęło pół godziny, godzina, a on nadal stęka i cicho przeklina.
„Bezmyślny! — pomyślałem, przełączając się na konsolę serwera — cóż, odłączę się jeszcze na parę minut.”
Spójrzmy, ntp, rdate, sdwdate nie są zainstalowane, timesyncd jest 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 zaznaczę, że czas sprzętowy jest poprawny: na jego podstawie będzie łatwiej się dalej orientować.
Od tego zaczęła się seria błędów.
Błąd pierwszy. Zbytnia pewność siebie
Klik, klik…
# 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 w porządku, czas się zsynchronizował, systemowy pokrywa się z sprzętowym. „Bierz”, — rzuciłem i wróciłem do swoich spraw.
„Co bierz? — oburzył się kolega. — Czas jest ten sam!”
Im więcej rozwiązujesz typowych zadań, tym bardziej myślenie staje się sztywne i już nie myślisz, że setna lub 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 znowu jest niepoprawny.
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
A 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 ustawia się na ułamek sekundy, a następnie znowu zaczyna się „śpieszyć”.
Przy tym w logach, w momencie takiej ręcznej zmiany, widzimy jedynie raporty systemu, że czas się zmienił, odpowiednio w dobrym/złym kierunku i od czasu do czasu Resyncing z systemd-timesyncd.
Aug 25 21:18:51 wisi systemd[1]: Czas został zmieniony
Aug 25 21:18:51 wisi systemd-timesyncd[29258]: Czas systemowy został zmieniony. Resynchronizacja.
Aug 25 21:18:51 wisi systemd[1187]: Czas został zmieniony
Aug 25 21:18:51 wisi systemd[1]: Czas został zmieniony
Aug 25 21:18:51 wisi systemd[1187]: Czas został zmieniony
tutaj
# ps afx | grep "[1]187"
1187 ? Ss 0:02 /lib/systemd/systemd --user
W tym momencie już należało szukać przyczyny, ale mózg przez 18 lat administrowania nagromadził statystykę błędów „czasu” i z przyzwyczajenia znowu obwinia synchronizację.
Wyłączymy ją 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]: Czas został zmieniony
Aug 25 21:25:40 wisi systemd[1187]: Czas został zmieniony
Aug 25 21:29:30 wisi systemd[1]: Czas został zmieniony
Aug 25 21:29:30 wisi systemd[1187]: Czas został zmieniony
Resyncing zniknął i w innych logach jest perfekcyjnie czysty.
Sprawdzamy wyniki tcpdump na porcie 123 na wszystkich interfejsach. Żadne zapytania nie występują, ale czas nadal „ucieka”.
Błąd drugi. Pośpiech
Do końca tygodnia roboczego zostało godzinę, a nie chce się iść na weekend z głupim nierozwiązanym zadaniem (nie zwracaj uwagi na czas w kodzie, artykuł był pisany w kolejnych dniach).
I znów, zamiast szukać przyczyny, zacząłem wymyślać wyjaśnienie wyniku. Mówię „wymyślać”, ponieważ, niezależnie od tego, jak logiczne by były wyjaśnienia wyniku, to błędne podejście do rozwiązania problemu.
Ten serwer jest serwerem strumieniowym i przekształca strumień DVB-S2 w IP. Strumień DVB-S zawiera znaczniki czasowe, dlatego odbiorniki, multipleksery, scrambler'y i telewizory często je wykorzystują do synchronizacji zegarów systemowych. Sterowniki kart DVB-S są skompilowane w jądrze, więc najszybszym sposobem, aby niezawodnie usunąć strumień DVB-S2, jest odłączenie kabli idących z „talerzy”. Na szczęście serwer jest za ścianą, więc tak to ma być.
Oczywiście, gdyby w logach było to, co powinno być, to by się nie wydarzyło, ale o tym, znów, na końcu artykułu.
Skoro już usunęliśmy wszystkie sygnały satelitarne, usuniemy też naziemne — przy okazji wyciągając wszystkie kable sieciowe. Serwer zostaje odcięty od zewnętrznego świata i działa całkowicie autonomicznie, ale zegary systemowe wciąż się spieszą.
Tydzień roboczy dobiegł końca, a sam problem związany z datą / czasem nie jest krytyczny, więc można po prostu pójść do domu, ale tu popełniam nowy błąd.
Błąd trzeci. Doradcy
Nigdy! Nigdy nie zadawaj pytań na forach i stronach ogólnotechnicznych (a la stackoverflow), jeśli odpowiedź na nie wymaga więcej niż przestudiowanie wyników z pierwszej strony Google i przeczytanie jednej strony man’a.
Zostaniesz odesłany z powrotem do Google, aby przeczytać ten sam man i popularnie wyjaśnią zasady forum / strony, ale nie dadzą odpowiedzi.
Są tu zarówno obiektywne czynniki:
- nikt poza tobą nie zna problemu tak dobrze;
- nikt nie może przeprowadzić testów w takich samych warunkach jak ty;
jak i subiektywne:
- możesz nie ujawniać wszystkich danych do rozwiązania problemu, ponieważ już wymyśliłeś „prawidłowy” kierunek i przedstawiasz sedno pytania opierając się na nim;
- starszy (moderator, stażysta, administrator) zawsze ma rację, jeśli starszy się myli… no wiesz jak to jest…
Jeżeli w odpowiedzi na komentarze pozostaliśmy w ramach cenzuralnego języka, to znaczy, że masz mocne nerwy.
Rozwiązanie
Nie dziel zadań na proste i skomplikowane.
Przestaniemy polegać na swoim doświadczeniu, statystyce, doradcach i zaczynamy nie „wyjaśniać” końcowego wyniku, a następnie systematycznie szukać przyczyny.
Jeśli ktoś ustawia czas, to musi nastąpić odpowiedni wywołanie systemowe.
Jak w dokumentacji oprogramowania najlepsze dokumenty – to źródła, tak w administracji systemu najlepszym pomocnikiem jest audyt, w naszym przypadku auditd.
Moment niepewnościPrzejrzałem dokumentację, ale nie byłem do końca pewien, że czas w systemie Linux można ustawić tylko clock_settime i settimeofday, dlatego 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 odrzucając s390_runtime_instr, stime, timerfd_create, których auditctl nie uznał, 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 utimesUpewniając się, że w interesujących mnie miejscach logów nie ma innych syscalls poza tymi dwoma, następnie użyłem tylko ich.
Uruchamiamy audyt wywołań systemowych clock_settime i settimeofday i próbujemy zmienić datę:
# auditctl -a exit,always -S clock_settime -S settimeofday && date -s "2019-08-22 12:10:00" && sleep 5 && auditctl -D
Pięciosekundowe opóźnienie dodane, aby nasz „parazyt” z pewnością skorygował czas.
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 nasz date i nieznany nam chkcache_proces. Znalazł się w powyższym raporcie, ponieważ aureport posortował wyjście według daty podczas przekształcania z formatu binarnego, a zdarzenie miało miejsce w ustalonym przez nas czasie date -s "2019-08-22 12:10:00".
Kto go stworzył?
# 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 — nasz parazyt odnaleziony. Pomimo jego „złośliwego” zachowania nie można zrezygnować z systemu dostępu warunkowego, ale mimo wszystko chciałbym wiedzieć, oscam, WTF?
Odpowiedź szybko znaleziona 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że uroczo prezentuje się tutaj zakomentowana linia ostrzeżenia…
Źródło: habr.com
