Salta al contenuto > Blog > Amministrazione > Più è semplice il compito, più spesso sbaglio

Più è semplice il compito, più spesso sbaglio

Più è semplice il compito, più spesso sbaglio

Questo compito banale è nato in uno dei venerdì e avrebbe dovuto richiedere 2-3 minuti di tempo. In sostanza, come sempre.

Un collega mi ha chiesto di sistemare uno script sul suo server. L'ho fatto, gliel'ho restituito e ho lasciato cadere distrattamente: «Il tempo è in anticipo di 5 minuti». È il suo server, se ne occupi da solo con la sincronizzazione. Sono passati mezz'ora, un'ora, e lui continua a brontolare silenziosamente.

«Cretino!», pensai mentre passavo alla console. server — Va bene, mi distacco ancora per un paio di minuti.

Vediamo, ntp, rdate, sdwdate non sono installati, timesyncd è disabilitato e non in esecuzione.

# 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 segnalo subito che l'ora hardware è corretta: sarà più facile orientarsi in seguito.

Da qui è iniziata una serie di errori.

Errore prima. Eccesso di fiducia.

Clack-clack…

# 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

Tutto perfetto, l'orario è stato sincronizzato, quello di sistema corrisponde a quello hardware. «Prenditi tutto», ho lasciato cadere mentre tornavo ai miei affari.

«Cosa prendo?», si è indignato il collega. «Il tempo è quello di prima!»

Più si risolvono compiti standardizzati, più il pensiero si rinchiude, e non si considera che la centesima o millesima situazione possa essere 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 di sistema è di nuovo sbagliata.

Proviamo ancora:

# 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

Facciamo 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 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

Il tempo viene impostato in una frazione di secondo, e subito dopo inizia a «correre» nuovamente.

Allo stesso tempo, nei log, al momento di tale cambiamento manuale, vediamo solo report del sistema che indicano che il tempo è cambiato, rispettivamente in modo corretto/sbagliato, e di rado Resyncing da systemd-timesyncd.

Aug 25 21:18:51 wisi systemd[1]: L'ora è stata cambiata
Aug 25 21:18:51 wisi systemd-timesyncd[29258]: L'ora di sistema è cambiata. Ricomincio a sincronizzarmi.
Aug 25 21:18:51 wisi systemd[1187]: L'ora è stata cambiata
Aug 25 21:18:51 wisi systemd[1]: L'ora è stata cambiata
Aug 25 21:18:51 wisi systemd[1187]: L'ora è stata cambiata

qui

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

A questo punto, avrebbe già dovuto cercare la causa, ma la mente, dopo 18 anni di amministrazione, ha accumulato una statistica di errori del «tempo» e per abitudine accusa di nuovo la sincronizzazione.
La disabilitiamo 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]: L'ora è stata cambiata
Aug 25 21:25:40 wisi systemd[1187]: L'ora è stata cambiata
Aug 25 21:29:30 wisi systemd[1]: L'ora è stata cambiata
Aug 25 21:29:30 wisi systemd[1187]: L'ora è stata cambiata

Resyncing è scomparso e il resto dei log è vergine.

Controlliamo le uscite tcpdump sul porto 123 su tutte le interfacce. Non ci sono richieste, ma il tempo continua a «scappare».

Errore seconda. Fretta.

Manca un'ora alla fine della settimana lavorativa, e andare via per il fine settimana con un compito irrisolto non è piacevole (non fate caso all'ora nel codice, l'articolo è stato scritto nei giorni successivi).
E di nuovo, invece di cercare la causa, ho iniziato a cercare di inventare una spiegazione per il risultato. Dico «inventare» perché, indipendentemente da quanto siano logiche le spiegazioni per il risultato, questo è un approccio errato per risolvere il problema.

Questo server è un server di streaming e converte il flusso DVB-S2 in IP. Nel flusso DVB-S ci sono dei timestamp, quindi i ricevitori, i multiplexers, i descrambler e le televisioni li usano spesso per sincronizzare gli orari di sistema. I driver per le schede DVB-S sono compilati nel kernel, quindi il modo più veloce per eliminare garantitamente il flusso DVB-S2 è disconnettere i cavi provenienti dalle «antenne». Fortunatamente, il server è dall'altra parte del muro, quindi va bene così.

Certo, se nei log ci fosse stato ciò che doveva esserci, ciò non sarebbe accaduto, ma di questo, ancora una volta, alla fine dell'articolo.

E dato che abbiamo già rimosso tutti i segnali satellitari, rimuoviamo anche quelli terrestri — nel frattempo disconnettiamo tutti i cavi di rete. Il server diventa scollegato dal mondo esterno e funziona assolutamente autonomamente, ma gli orari di sistema continuano a correre.

La settimana lavorativa è finita, e la questione della data/ora non è critica, quindi si può semplicemente andare a casa, ma qui commetto un nuovo errore.

Errore terzo. Consigliatori.

Mai! Mai chiedere domande sui forum e su siti specializzati (tipo stackoverflow) se la risposta richiede più che consultare i risultati della prima pagina di Google e leggere una pagina del manuale.

Ti rimanderanno a Google, a leggere sempre lo stesso manuale e spiegheranno in modo popolare le regole del forum/sito, ma non daranno una risposta.

Qui ci sono sia fattori oggettivi:

  • nessuno oltre a te può conoscere il problema altrettanto bene;
  • nessuno può eseguire test nelle stesse condizioni che hai tu

sia che soggettivi:

  • puoi non fornire tutti i dati per risolvere il compito, perché hai già pensato a una «direzione» corretta e stai esponendo la sostanza della domanda basandoti su di essa;
  • il moderatore (admin, veterano, moderatore) ha sempre ragione, se il moderatore ha torto... beh, lo sai...

Se nei commenti di risposta sei rimasto nei limiti del linguaggio civile, significa che hai nervi di ferro.

Soluzione

Non bisogna dividere i compiti in semplici e complessi.

Smettiamo di fare affidamento sulla nostra esperienza, statistica, consiglieri e iniziamo a non «spiegare» il risultato finale, ma a cercare sistematicamente la causa.

Se qualcuno imposta l'ora, deve esserci una corrispondente chiamata di sistema.

Come dice la documentazione del software, i migliori documenti sono i codici sorgente; così, nella gestione dei sistemi, il miglior aiuto è l'audit, nel nostro caso. auditd.

Un attimo di dubbioHo dato un'occhiata ai manuali, ma non ero del tutto sicuro che l'ora in Linux potesse essere impostata solo con clock_settime e settimeofday, quindi per il primo test ho scelto tutte le chiamate 'appropriate':

# 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 scartando s390_runtime_instr, stime, timerfd_create, che auditctl non ho riconosciuto, ho inizialmente avviato un audit in forma di:

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

Assicurandomi che nei log che mi interessano non ci siano altri syscalls oltre a questi due, ho poi utilizzato solo loro.

Avviamo l'audit delle chiamate di sistema clock_settime e settimeofday e proviamo 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

È stato aggiunto un ritardo di cinque secondi per garantire che il nostro 'parassita' corregga 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 nostro date e l'ignoto chkcache_proces. È apparso nel rapporto sopra, poiché aureport ha ordinato l'output per data durante la conversione da formato binario, e l'evento è avvenuto nell'ora che abbiamo impostato. date -s '2019-08-22 12:10:00'.
Chi l'ha generato?

# 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 'maligno', non si può rinunciare al sistema di accesso condizionato, ma vorrei comunque sapere, oscam, WTF?

La risposta è stata trovata rapidamente in sorgenti:

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

Com'è carina qui la riga commentata warning’a…

Fonte: habr.com

Acquista hosting affidabile per siti web con protezione DDoS, server VPS VDS 🔥 Acquista hosting affidabile per siti web con protezione DDoS, server VPS VDS | ProHoster