Táto triviálna úloha vznikla v jeden piatok popoludní a mala zabrať 2-3 minúty času. Vo všeobecnosti, ako vždy.
Kolega ma požiadal o opravu skriptu na jeho serveri. Urobil som to, podal som mu to a neúmyselne som povedal: „Čas je rýchly o 5 minút. Nechajte server, aby sa postaral o synchronizáciu sám. Ubehla polhodina, hodina a on stále funel a ticho nadával.
„Hlúpe! - Pomyslel som si a prepol na serverovú konzolu - dobre, dám si ešte pár minút prestávku."
Pozrime sa ntp, rdate, sdwdate nie je nainštalovaný timesyncd vypnuté a nespustené.
# 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
Tu si okamžite všimnem, že hardvérový čas je správny: bude ľahšie navigovať ďalej.
Prvá chyba. Sebavedomie
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
Všetko je v poriadku, čas je synchronizovaný, systémový čas zodpovedá hardvérovému. "Vezmi si to," povedal som a vrátil som sa k svojej práci.
„Vezmi si čo? - rozhorčil sa kolega. "Je to rovnaký čas!"
Čím viac riešite typické problémy, tým viac sa vaše myslenie zamračí a už si nemyslíte, že tá stová či tisícina situácia bude iná, ale tentoraz nie.
# 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
Systémový čas je opäť nesprávny.
Skúsme to opäť:
# 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
Urobme to inak:
# 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 takto:
# 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
Čas je nastavený na zlomok sekundy a okamžite sa opäť začne „ponáhľať“.
Zároveň v protokoloch v čase takejto manuálnej zmeny vidíme len systémové hlásenia, že čas sa zmenil, resp. správnym/nesprávnym smerom a občas Opätovná synchronizácia 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
tu
# ps afx | grep "[1]187"
1187 ? Ss 0:02 /lib/systemd/systemd --user
V tomto momente už bolo potrebné hľadať príčinu, no za 18 rokov podávania si mozog nazbieral štatistiky o chybách „času“ a zo zvyku opäť obviňuje synchronizáciu.
Úplne ho vypneme.
# 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
a v denníkoch
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
Opätovná synchronizácia zmizli a inak sú polená nedotknuté.
Kontrola záverov tcpdump na porte 123 na všetkých rozhraniach. Žiadosti nie sú, ale čas stále beží.
Chyba dva. Rush
Do konca pracovného týždňa ostáva hodina a mne sa nechce odchádzať na víkend s triviálnym nevyriešeným problémom (čas v kóde si nevšímajte, článok bol napísaný v nasledujúcich dňoch ).
A tu som sa opäť namiesto hľadania príčiny začal snažiť prísť s vysvetlením výsledku. Hovorím „vynájsť“, pretože bez ohľadu na to, aké logické môže byť vysvetlenie výsledku, ide o chybný prístup k riešeniu problému.
Tento server je streamovací server a konvertuje tok DVB-S2 na IP. DVB-S stream obsahuje časové značky, takže prijímače, multiplexory, scramblery a televízory ich často používajú na synchronizáciu systémových hodín. Ovládače dosky DVB-S sú zabudované v jadre, takže najrýchlejším spôsobom, ako zabezpečiť odstránenie toku DVB-S2, je odpojiť káble prichádzajúce z „doštičiek“. Našťastie je server za stenou, takže nech sa páči.
Samozrejme, ak by protokoly obsahovali to, čo tam má byť, nestalo by sa to, ale o tom opäť na konci článku.
No a keďže sme už odstránili všetky satelitné signály, odstránime aj pozemné – zároveň vytiahneme všetky sieťové káble. Server je odrezaný od vonkajšieho sveta a funguje úplne autonómne, ale systémové hodiny sa stále ponáhľajú.
Pracovný týždeň sa skončil a samotný problém s dátumom a časom nie je kritický, takže môžete ísť domov, ale tu robím novú chybu.
Chyba tri. poradcovia
Nikdy! Nikdy sa nepýtajte na fórach a všeobecných špecializovaných (a la stackoverflow) stránkach, ak si odpoveď na ne vyžaduje viac ako len preštudovanie prvej stránky Google a čítanie jednej manuálovej stránky.
Pošlú vás späť do Googlu, prečítajú si toho istého muža a s obľubou vysvetlia pravidlá fóra/stránky, no nedajú vám odpoveď.
Tu sú niektoré objektívne faktory:
- nikto okrem vás nemôže poznať problém;
- nikto nemôže vykonávať testy za rovnakých podmienok ako vy
a subjektívne:
- možno nedáte všetky vstupy na vyriešenie problému, pretože ste už prišli na „správny“ smer a so zameraním naň prezentujete podstatu problému;
- majster (moderátor, staromilec, admin) má vždy pravdu, ak sa majster mýli... no vieš...
Ak ste sa pri odpovediach na komentáre držali v medziach cenzurovanej slovnej zásoby, tak máte pevné nervy.
rozhodnutie
Nie je potrebné deliť úlohy na jednoduché a zložité.
Prestávame sa spoliehať na svoje skúsenosti, štatistiky, poradcov a začíname „nevysvetľovať“ konečný výsledok, ale dôsledne hľadať príčinu.
Keďže niekto nastavuje čas, musí sa uskutočniť príslušné systémové volanie.
Tak ako v softvérovej dokumentácii sú najlepšími dokumentmi zdroje, tak aj pri správe systému je v našom prípade najlepším pomocníkom audit auditované.
Moment pochybnostíPrešiel som manu, ale nebol som si úplne istý, že čas v Linuxe sa dá nastaviť len clock_settime и nastavený čas dňa, takže pre prvý test som vybral všetky „vhodné“ hovory:
# 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
a vyhadzovanie s390_runtime_instr, stime, timerfd_create, ktorý auditctl nerozpoznal, pôvodne spustil audit vo 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
Po uistení sa, že v umiestneniach denníkov, ktoré ma zaujímajú, nie sú žiadne ďalšie záznamy systémové volania Okrem týchto dvoch som ďalej používal len ich.
Spustenie auditu systémového volania clock_settime и nastavený čas dňa a skúste zmeniť dátum:
# auditctl -a exit,always -S clock_settime -S settimeofday && date -s "2019-08-22 12:10:00" && sleep 5 && auditctl -D
Pridá sa päťsekundové oneskorenie, aby náš „parazit“ zaručene upravil čas.
Pozrime sa na správu:
# 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
Tu vidíme naše dáta a pre nás neznámy chkcache_processes. Skončilo to v prehľade vyššie, pretože aureport zoradil výstup podľa dátumu pri konverzii z binárneho kódu a udalosť nastala v čase, ktorý sme nastavili dátum -s "2019-08-22 12:10:00".
Kto ho splodil?
# 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 - našiel sa náš parazit. Napriek jeho „škodlivému“ správaniu nie je možné odmietnuť systém podmieneného prístupu, ale aj tak by som rád vedel oscam, WTF?
Odpoveď sa rýchlo nájde v
#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");
}
Ako roztomilo to tu vyzerá komentoval riadok POZOR...
Zdroj: hab.com