ProHoster > Blog > Administrácia > Čím je úloha jednoduchšia, tým častejšie robím chyby

Čím je úloha jednoduchšia, tým častejšie robím chyby

Čím je úloha jednoduchšia, tým častejšie robím chyby

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.

Tu sa začala séria chýb.

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 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");
}

Ako roztomilo to tu vyzerá komentoval riadok POZOR...

Zdroj: hab.com

Pridať komentár