Tato triviální úloha vznikla v jeden z pátků a měla zabrat 2–3 minuty času. Obvyklé to.
Kolega mě požádal, abych upravil skript na jeho serveru. Udělal jsem to, odevzdal a náhodou prohodil: „Čas spěchá o 5 minut.“ Je to jeho server, ať si s tím poradí sám. Půl hodiny, hodina uplynula, a on stále funí a tiše proklíná.
„Nemehlo! — pomyslel jsem si, přepínaje do konzole. serveru — no dobrá, věnuji se tomu ještě na pár minut.
Podíváme se, ntp, rdate, sdwdate není nainstalováno, timesyncd je vypnuto a neběží.
# 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
Hned poznamenám, že hardwarový čas je správný: podle něj se bude lépe orientovat dále.
Odtud začala řada chyb.
Chyba prvá. Přehnaná sebedůvěra
Tuk-tuk…
# 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šechno skvělé, čas se synchronizoval, systémový čas odpovídá hardwarovému. „Vezmi si,“ – prohodil jsem a vrátil se ke svým záležitostem.
„Co si vezmi? — rozhořčil se kolega. — Čas je stejný!“
Čím více řešíš standardní úlohy, tím více se ti zašlapuje myšlení a už nepřemýšlíš, že stotřicátá nebo tisíckráte bude jiná situace, ale tentokrát tomu tak nebylo.
# 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 znovu nesprávný.
Zkusíme to znovu:
# 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
Pojďme na to jinak:
# 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 co 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 se nastavuje na zlomek sekundy a hned zase začíná „spěchat“.
Přitom v logách, v okamžiku tohoto ručního přepnutí vidíme pouze zprávy systému, že čas se změnil, odpovídajícím způsobem do správných/neprávních směrů a příležitostně Resyncing od systemd-timesyncd.
Aug 25 21:18:51 wisi systemd[1]: Čas byl změněn
Aug 25 21:18:51 wisi systemd-timesyncd[29258]: Systémový čas se změnil. Resynchronizuji.
Aug 25 21:18:51 wisi systemd[1187]: Čas byl změněn
Aug 25 21:18:51 wisi systemd[1]: Čas byl změněn
Aug 25 21:18:51 wisi systemd[1187]: Čas byl změněn
zde
# ps afx | grep "[1]187"
1187 ? Ss 0:02 /lib/systemd/systemd --user
V tuto chvíli už bylo nutné hledat příčinu, ale mozek po 18 letech administrace nasbíral statistiku chyb „času“ a automaticky znovu obviňuje synchronizaci.
Vypneme ji naprosto.
# 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 logách
Aug 25 21:25:40 wisi systemd[1]: Čas byl změněn
Aug 25 21:25:40 wisi systemd[1187]: Čas byl změněn
Aug 25 21:29:30 wisi systemd[1]: Čas byl změněn
Aug 25 21:29:30 wisi systemd[1187]: Čas byl změněn
Resyncing zmizel a ostatní logy jsou naprosto čisté.
Kontrolujeme výstupy tcpdump na 123. portu na všech rozhraních. Žádné požadavky nejsou, ale čas stále „utíká“.
Chyba druhá. Spěch
Do konce pracovního týdne zbývá hodina, a nechtějí odejít na víkend s hloupým nevyřešeným úkolem (nevšímejte si času v kódu, článek byl psán v následujících dnech).
A znovu místo toho, abych hledal příčinu, jsem se začal snažit vymyslet vysvětlení výsledku. Říkám „vymyslet“, protože bez ohledu na to, jak logická by byla vysvětlení výsledku, je to chybný přístup k řešení problému.
Tento server je streamovací a převádí proud DVB-S2 na IP. V proudu DVB-S jsou přítomny časové značky, proto je přijímače, multiplexory, skrambler a televize často používají k synchronizaci systémových hodin. Ovladače karet DVB-S jsou zakompilovány v jádře, takže nejrychlejší způsob, jak zaručeně odstranit DVB-S2 proud, je odpojit kabely vedoucí z „talířů“. Naštěstí je server za zdí, takže tomu tak bude.
Samozřejmě, kdyby v logech bylo to, co tam mělo být, k tomu by nedošlo, ale o tom, opět, na konci článku.
A protože jsme už odstranili všechny satelitní signály, odstraníme i pozemní — přitom vytahujeme všechny síťové kabely. Server se stává odříznutým od vnějšího světa a pracuje zcela autonomně, ale systémové hodiny stále spěchají.
Pracovní týden skončil a otázka data/času na něm není kritická, takže můžu prostě jít domů, ale tady dělám novou chybu.
Chyba třetí. Poradci
Nikdy! Nikdy se neptejte na fórech a oborových (jako je stackoverflow) stránkách, pokud odpověď na vaši otázku vyžaduje více než prozkoumat výsledky první stránky Googlu a přečíst si jednu stránku manuálu.
Bude vám doporučeno vrátit se k Googlu, přečíst si ten samý manuál a populárně vám vysvětlí pravidla fóra/webu, ale odpověď nedostanete.
Existují jak objektivní faktory:
- nikdo kromě vás nemůže znát problém tak dobře;
- nikdo nemůže provést testy za podmínek jako máte vy.
Tak i subjektivní:
- můžete nezmínit všechny vstupy pro řešení úlohy, protože jste už vymysleli „správný“ směr a soustředíte se na něj v jádru otázky;
- staršina (moderátor, veterán, administrátor) má vždy pravdu, pokud staršina nemá pravdu… no, víte jak to je…
Pokud jste při odpovídajících komentářích zůstali v mezích slušného vyjadřování, znamená to, že máte silné nervy.
Řešení
Není třeba rozdělovat úkoly na jednoduché a složité.
Přestáváme se spoléhat na svou zkušenost, statistiky, poradce a začínáme ne „vysvětlovat“ konečný výsledek, ale postupně hledat příčinu.
Pokud někdo nastavuje čas, musí dojít k odpovídajícímu systémovému volání.
Jak říká dokumentace k softwaru, nejlepší dokumentace je ta zdrojová, tak v systémovém administrativním procesu je nejlepším pomocníkem audit, v našem případě. auditd.
Chvilka nejistoty.Prošel jsem se po manuálech, ale nebyl jsem si úplně jistý, že čas v Linuxu může být nastaven pouze. clock_settime. a settimeofday., proto jsem pro první test vybral všechna "přiměřená" volání:
# 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 vyřadil s390_runtime_instr, stime, timerfd_create,, které auditctl neuznal, původně jsem spustil audit ve formátu:
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.Ujistil jsem se, že na zajímavých místech logu nejsou další syscalls kromě těchto dvou, a dále jsem použil pouze ty.
Spouštíme audit systémových volání clock_settime. a settimeofday. a pokoušíme se změnit datum:
# auditctl -a exit,always -S clock_settime -S settimeofday && date -s "2019-08-22 12:10:00" && sleep 5 && auditctl -D
Pěti sekundové zpoždění bylo přidáno, aby náš „parazit“ zaručeně upravil čas.
Podíváme se na zprá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
Tady vidíme náš date a nám neznámý chkcache_proces.Objevil se ve výše uvedené zprávě, protože aureport seřadil výstup podle datumu při převodu z binárního formátu a událost se stala v námi nastaveném čase. date -s "2019-08-22 12:10:00"..
Kdo ho stvořil?
# 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 — náš parazit byl nalezen. I přes jeho "škodlivé" chování se nelze vzdát systému podmíněného přístupu, ale přesto bych rád věděl, oscam,, co to do háje?
Odpověď byla rychle nalezena 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");
}
Jak krásně to zde vypadá. komentovaná řádka warning’a.…
Zdroj: habr.com
