Più il compito è semplice, più spesso commetto errori

Più il compito è semplice, più spesso commetto errori

Questo compito banale è sorto un venerdì pomeriggio e avrebbe dovuto richiedere 2-3 minuti di tempo. In generale, come sempre.

Un collega mi ha chiesto di correggere lo script sul suo server. L'ho fatto, gliel'ho consegnato e inavvertitamente ho lasciato cadere: "Il tempo è veloce di 5 minuti". Lascia che sia il server a gestire la sincronizzazione stessa. Passò mezz'ora, un'ora e lui continuava a sbuffare e imprecare in silenzio.

"Stupido! - ho pensato, passando alla console del server - okay, mi prenderò una pausa ancora per un paio di minuti.

Guarda ntp, rdate, sdwdate non installato timesyncd disabilitato e non funzionante.

# 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

Qui noto subito che l'ora hardware è corretta: sarà più semplice navigare ulteriormente.

Da qui è iniziata la serie di errori.

Il primo errore. Fiducia in se stessi

Clic-clac...

# 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

Va tutto bene, l'ora è sincronizzata, l'ora del sistema corrisponde a quella dell'hardware. "Prendilo", dissi e tornai ai miei affari.

“Prendere cosa? - il collega era indignato. "È la stessa ora!"

Più risolvi problemi tipici, più il tuo pensiero diventa annebbiato e non pensi più che la centesima o la millesima situazione sarà diversa, ma non questa volta.

# 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

L'ora del sistema è di nuovo sbagliata.

Proviamo di nuovo:

# 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

Facciamolo diversamente:

# 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

E qui così:

# 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

L'ora viene impostata per una frazione di secondo e immediatamente ricomincia a "correre".

Allo stesso tempo, nei registri, al momento di tale modifica manuale, vediamo solo i rapporti di sistema che indicano che l'ora è cambiata, rispettivamente, nella direzione giusta/sbagliata e occasionalmente Risincronizzazione da 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

qui

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

A questo punto era già necessario cercarne il motivo, ma in 18 anni di somministrazione il cervello ha accumulato statistiche sugli errori “temporali” e, per abitudine, incolpa nuovamente la sincronizzazione.
Spegniamolo completamente.

# 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

e nei log

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

Risincronizzazione scomparso e per il resto i tronchi sono incontaminati.

Verifica delle conclusioni tcpdump sulla porta 123 su tutte le interfacce. Non ci sono richieste, ma il tempo scorre ancora.

Errore due. Fretta

Manca un'ora alla fine della settimana lavorativa, e non voglio partire per il fine settimana con un banale problema irrisolto (non fate attenzione all'ora nel codice, l'articolo è stato scritto nei giorni successivi ).
E anche qui, invece di cercarne il motivo, ho cominciato a cercare di trovare una spiegazione al risultato. Dico “inventare” perché non importa quanto logica possa essere la spiegazione del risultato, è un approccio errato per risolvere il problema.

Questo server è un server di streaming e converte il flusso DVB-S2 in IP. Il flusso DVB-S contiene timestamp, quindi ricevitori, multiplexer, scrambler e televisori spesso li utilizzano per sincronizzare l'orologio del sistema. I driver della scheda DVB-S sono integrati nel kernel, quindi il modo più veloce per garantire che il flusso DVB-S2 venga rimosso è scollegare i cavi provenienti dalle “piastre”. Fortunatamente, il server è dietro il muro, quindi così sia.

Naturalmente, se i registri avessero contenuto ciò che dovrebbe esserci, ciò non sarebbe accaduto, ma ne parleremo più avanti alla fine dell'articolo.

Ebbene, poiché abbiamo già rimosso tutti i segnali satellitari, rimuoveremo anche quelli terrestri, allo stesso tempo staccheremo tutti i cavi di rete. Il server viene isolato dal mondo esterno e funziona in modo completamente autonomo, ma l'orologio di sistema va ancora di fretta.

La settimana lavorativa è finita e il problema di data/ora in sé non è critico, quindi puoi semplicemente tornare a casa, ma qui commetto un nuovo errore.

Errore tre. Consiglieri

Mai! Non porre mai domande su forum e siti specializzati in generale (a la StackOverflow) se la risposta richiede più dello studio della prima pagina di Google e della lettura di una pagina man.

Ti rimanderanno a Google, leggeranno lo stesso uomo e spiegheranno popolarmente le regole del forum/sito, ma non ti daranno una risposta.

Ecco alcuni fattori oggettivi:

  • nessuno tranne te può conoscere il problema;
  • nessuno può condurre test nelle stesse condizioni delle tue

e soggettivo:

  • potresti non fornire tutti gli input per risolvere il problema, perché hai già trovato la direzione “giusta” e stai presentando l’essenza del problema concentrandoti su di essa;
  • il caposquadra (moderatore, veterano, amministratore) ha sempre ragione, se il caposquadra ha torto... beh, sai...

Se, rispondendo ai commenti, sei rimasto entro i limiti del vocabolario censurato, allora hai i nervi saldi.

Soluzione

Non è necessario dividere i compiti in semplici e complessi.

Smettiamo di fare affidamento sulla nostra esperienza, sulle statistiche, sui consulenti e iniziamo a non “spiegare” il risultato finale, ma a cercarne costantemente la ragione.

Poiché qualcuno imposta l'ora, deve verificarsi la chiamata di sistema corrispondente.

Proprio come nella documentazione del software i migliori documenti sono i sorgenti, così nell'amministrazione del sistema il miglior assistente è l'audit, nel nostro caso auditd.

Un momento di dubbioHo esaminato il mana, ma non ero del tutto sicuro che l'ora in Linux potesse essere impostata solo clock_settime и settimeofday, quindi per la prima prova ho scelto tutti i nominativi “adatti”:

# 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

e scartare s390_runtime_instr, stima, timerfd_create, che auditctl non l’ha riconosciuto, inizialmente ha avviato un audit nella forma:

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

Dopo essermi assicurato che non siano presenti altri log nelle posizioni dei log che mi interessano chiamate di sistema Oltre a questi due, li ho usati ulteriormente.

Esecuzione di un controllo delle chiamate di sistema clock_settime и settimeofday e prova a cambiare la data:

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

Viene aggiunto un ritardo di cinque secondi in modo che il nostro "parassita" sia sicuro di correggere l'ora.

Guardiamo il rapporto:

# 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

Qui vediamo il ns quando e a noi sconosciuti chkcache_processes. È finito nel report sopra perché aureport ha ordinato l'output per data durante la conversione da binario e l'evento si è verificato nel momento in cui abbiamo impostato data -s "2019/08/22 12:10:00".
Chi lo ha partorito?

# 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 - Il nostro parassita è stato trovato. Nonostante il suo comportamento “dannoso”, è impossibile rifiutare il sistema di accesso condizionato, ma vorrei comunque saperlo oscam, che cavolo?

La risposta si trova rapidamente in Codici di origine:

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

Quanto è carino qui commentata linea avvertimento...

Fonte: habr.com

Aggiungi un commento