ProHoster > Blog > podávání > Čím jednodušší úkol, tím častěji dělám chyby

Čím jednodušší úkol, tím častěji dělám chyby

Čím jednodušší úkol, tím častěji dělám chyby

Tento triviální úkol vznikl jednoho pátečního odpoledne a měl zabrat 2-3 minuty času. Obecně jako vždy.

Kolega mě požádal, abych opravil skript na jeho serveru. Udělal jsem to, podal jsem mu to a nechtěně upustil: "Čas je rychlý 5 minut." Nechte server, aby synchronizaci zvládl sám. Uplynula půlhodina, hodina a on stále funěl a tiše nadával.

"Hloupý! – pomyslel jsem si a přepnul na serverovou konzoli – dobře, dám si ještě pár minut pauzu.

Díváme se ntp, rdate, sdwdate není instalován timesyncd zakázáno 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

Zde si okamžitě všimnu, že hardwarový čas je správný: bude snazší navigovat dále.

Tady začala série chyb.

První chyba. Sebevědomí

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še je v pořádku, čas je synchronizovaný, systémový čas odpovídá hardwarovému. "Vezmi si to," řekl jsem a vrátil se ke svému podniku.

„Vezmi si co? - rozhořčil se kolega. "Je stejný čas!"

Čím více řešíte typické problémy, tím více se vaše myšlení zamračí a už si nemyslíte, že sté nebo tisící situace bude jiná, ale tentokrát ne.

# 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ět špatný.

Pojď to zkusit 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

Udělejme 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 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

Čas je nastaven na zlomek sekundy a okamžitě začne znovu „spěchat“.

Zároveň v protokolech v době takové ruční změny vidíme pouze systémové hlášení, že se čas změnil, resp. správným/špatným směrem a občas Probíhá opětovná synchronizace ze 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

zde

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

V tuto chvíli již bylo nutné hledat příčinu, ale za 18 let administrace si mozek nashromáždil statistiky o „časových“ chybách a ze zvyku opět obviňuje synchronizaci.
Vypneme úplně. 

# 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 protokolech

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

Probíhá opětovná synchronizace zmizely a jinak jsou klády nedotčené.

Kontrola závěrů tcpdump na portu 123 na všech rozhraních. Nejsou žádné žádosti, ale čas stále utíká.

Chyba dvě. Spěch

Do konce pracovního týdne zbývá hodina a nechce se mi odjíždět na víkend s triviálním nevyřešeným problémem (času v kódu si nevšímejte, článek byl napsán v následujících dnech ).
A opět jsem se místo hledání příčiny začal snažit přijít s vysvětlením výsledku. Říkám „vynalézt“, protože bez ohledu na to, jak logické může být vysvětlení výsledku, je to chybný přístup k řešení problému.

Tento server je streamovací server a převádí DVB-S2 stream na IP. DVB-S stream obsahuje časové značky, takže přijímače, multiplexery, scramblery a televize je často používají k synchronizaci systémových hodin. Ovladače desky DVB-S jsou zabudovány v jádře, takže nejrychlejším způsobem, jak zajistit odstranění toku DVB-S2, je odpojit kabely přicházející z „desek“. Naštěstí je server za zdí, takže budiž.

Samozřejmě, pokud by protokoly obsahovaly to, co by tam mělo být, nestalo by se tak, ale o tom opět na konci článku.

No a když už jsme odstranili všechny satelitní signály, odstraníme i pozemní - zároveň vytáhneme všechny síťové kabely. Server se odřízne od okolního světa a funguje zcela autonomně, ale systémové hodiny stále spěchají.

Pracovní týden je u konce a problém data/času sám o sobě není kritický, takže můžete jít domů, ale tady dělám novou chybu.

Chyba tři. poradci

Nikdy! Nikdy nepokládejte otázky na fórech a obecně specializovaných (a la stackoverflow) stránkách, pokud odpověď na ně vyžaduje více než prostudování první stránky Google a přečtení jedné manuálové stránky.

Pošlou vás zpět do Googlu, přečtou si stejného muže a s oblibou vysvětlí pravidla fóra/stránky, ale nedají vám odpověď.

Zde jsou některé objektivní faktory:

  • nikdo kromě vás nemůže znát problém také;
  • nikdo nemůže provádět testy za stejných podmínek jako ty

a subjektivní:

  • možná neposkytnete všechny podklady pro řešení problému, protože jste již přišli na „správný“ směr a se zaměřením na podstatu problému prezentujete;
  • předák (moderátor, staromilec, admin) má vždycky pravdu, když se předák mýlí... no, znáte to...

Pokud jste se při odpovídání na komentáře drželi v mezích cenzurované slovní zásoby, tak máte pevné nervy.

rozhodnutí

Není potřeba rozdělovat úkoly na jednoduché a složité.

Přestáváme spoléhat na své zkušenosti, statistiky, poradce a začínáme „nevysvětlovat“ konečný výsledek, ale důsledně hledat důvod.

Protože někdo nastavuje čas, musí proběhnout odpovídající systémové volání.

Stejně jako v softwarové dokumentaci jsou nejlepšími dokumenty zdroje, tak i při správě systému je v našem případě nejlepším pomocníkem audit auditováno.

Chvilka pochybnostíProšel jsem manu, ale nebyl jsem si úplně jistý, že čas v Linuxu lze pouze nastavit clock_settime и settimeofday, takže pro první test jsem vybral všechna „vhodná“ 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řazení s390_runtime_instr, stime, timerfd_createkterý auditctl nerozpoznal, původně spustil audit ve tvaru:

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

Poté, co jsem se ujistil, že v umístěních protokolů, které mě zajímají, nejsou žádné další protokoly systémová volání Kromě těchto dvou jsem dále používal pouze je.

Spuštění auditu systémového volání clock_settime и settimeofday a zkuste změnit datum:

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

Je přidáno pětisekundové zpoždění, takže náš „parazit“ zaručeně opraví čas.

Podívejme se na reportáž:

# 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 naše datum a pro nás neznámé chkcache_processes. Skončilo to ve výše uvedené zprávě, protože aureport seřadil výstup podle data při převodu z binárního kódu a událost nastala v čase, který jsme nastavili datum -s "2019-08-22 12:10:00".
Kdo ho porodil?

# 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 - byl nalezen náš parazit. Navzdory jeho „škodlivému“ chování není možné odmítnout systém podmíněného přístupu, ale přesto bych to rád věděl oscam, WTF?

Odpověď je rychle nalezena v zdrojové kódy:

#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 roztomile to tady vypadá okomentoval čára Varování...

Zdroj: www.habr.com

Přidat komentář