ProHoster > Blog > Administration > Je einfacher die Aufgabe ist, desto hÀufiger mache ich Fehler

Je einfacher die Aufgabe ist, desto hÀufiger mache ich Fehler

Je einfacher die Aufgabe ist, desto hÀufiger mache ich Fehler

Diese triviale Aufgabe entstand an einem der Freitage und sollte 2-3 Minuten in Anspruch nehmen. Im Großen und Ganzen wie immer.

Ein Kollege bat mich, ein Skript auf seinem Server zu verbessern. Ich machte es, reichte es ihm ein und murmelte beilĂ€ufig: „Die Zeit lĂ€uft 5 Minuten vor.“ Es ist sein Server, er kann sich um die Synchronisation kĂŒmmern. Eine halbe Stunde, eine Stunde verging, und er tĂŒftelt immer noch und flucht leise.

„Dummkopf! - dachte ich, als ich zur Konsole wechselte. Server — nun gut, ich reiße mich noch ein paar Minuten los."

Wir schauen nach, ntp, rdate, sdwdate sind nicht installiert, timesyncd ist deaktiviert und lÀuft nicht.

# 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

Hier möchte ich gleich anmerken, dass die Hardware-Zeit korrekt ist: daran lÀsst sich leichter orientieren.

Von hier aus begann die Kette der Fehler.

Erster Fehler. Selbstsicherheit.

Klick-klick


# 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

Alles in Ordnung, die Zeit wurde synchronisiert, die Systemzeit stimmt mit der Hardware-Zeit ĂŒberein. „Nimm es“, murmelte ich und kehrte zu meinen Angelegenheiten zurĂŒck.

„Was soll ich nehmen? - empörte sich der Kollege. - Die Zeit ist die alte!“

Je mehr man standardisierte Aufgaben löst, desto mehr verengt sich das Denken, und man denkt nicht daran, dass die hundertste oder tausendste Situation anders sein könnte, aber nicht diesmal.

# 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

Die Systemzeit ist wieder falsch.

Versuchen wir es noch einmal:

# 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

Gehen wir es anders an:

# 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

Und so:

# 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

Die Zeit wird in einem Bruchteil einer Sekunde eingestellt und beginnt sofort wieder „vorzulaufen“.

Dabei sehen wir in den Logs, zum Zeitpunkt dieser manuellen Änderung, nur Systemberichte, dass die Zeit geĂ€ndert wurde, entsprechend in die richtige/falsche Richtung und gelegentlich Resyncing von systemd-timesyncd.

Aug 25 21:18:51 wisi systemd[1]: Zeit wurde geÀndert
Aug 25 21:18:51 wisi systemd-timesyncd[29258]: Systemzeit geÀndert. Resyncing.
Aug 25 21:18:51 wisi systemd[1187]: Zeit wurde geÀndert
Aug 25 21:18:51 wisi systemd[1]: Zeit wurde geÀndert
Aug 25 21:18:51 wisi systemd[1187]: Zeit wurde geÀndert

hier

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

In diesem Moment hĂ€tte ich bereits nach der Ursache suchen mĂŒssen, aber der Verstand hat in 18 Jahren Admin-Erfahrung Statistiken ĂŒber „Zeit“-Fehler gesammelt und macht aus Gewohnheit wieder die Synchronisation verantwortlich.
Wir schalten sie vollstÀndig ab.

# 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

und in den Logs

Aug 25 21:25:40 wisi systemd[1]: Zeit wurde geÀndert
Aug 25 21:25:40 wisi systemd[1187]: Zeit wurde geÀndert
Aug 25 21:29:30 wisi systemd[1]: Zeit wurde geÀndert
Aug 25 21:29:30 wisi systemd[1187]: Zeit wurde geÀndert

Resyncing fehlte und der Rest der Logs ist ohne Makel.

Wir prĂŒfen die Ausgaben tcpdump ĂŒber den 123. Port auf allen Schnittstellen. Es gibt keine Anfragen, aber die Zeit „lĂ€uft“ immer noch weg.

Zweiter Fehler. Eile.

Bis zum Ende der Arbeitswoche bleibt eine Stunde, und ich möchte mit einer lÀppischen ungelösten Aufgabe nicht ins Wochenende gehen (beachtet nicht die Zeit im Code, der Artikel wurde in den folgenden Tagen geschrieben).
Und wieder, anstatt die Ursache zu suchen, begann ich, eine ErklĂ€rung fĂŒr das Ergebnis zu erfinden. Ich sage „erfinden“, weil, egal wie logisch die ErklĂ€rungen fĂŒr das Ergebnis auch sein mögen, dies ein fehlerhafter Ansatz zur Problemlösung ist.

Dieser Server ist ein Streaming-Server und wandelt den DVB-S2-Stream in IP um. Im DVB-S-Stream sind Zeitstempel vorhanden, daher verwenden EmpfĂ€nger, Multiplexer, Scrambler und Fernseher sie hĂ€ufig zur Synchronisierung der Systemuhren. Die Treiber fĂŒr DVB-S-Platten sind im Kernel integriert, weshalb der schnellste Weg, um den DVB-S2-Stream sicher zu entfernen, darin besteht, die vom „Antennen“ kommenden Kabel zu trennen. GlĂŒcklicherweise ist der Server hinter der Wand, also sei es so.

NatĂŒrlich, wenn in den Logs das gewesen wĂ€re, was dort sein sollte, hĂ€tte dies nicht stattgefunden, aber dazu spĂ€ter mehr am Ende des Artikels.

Nun, da wir alle Satellitensignale entfernt haben, entfernen wir auch die terrestrischen — wĂ€hrend wir alle Netzwerkkabel herausziehen. Der Server wird von der Außenwelt abgeschnitten und arbeitet absolut autonom, aber die Systemuhr geht trotzdem immer noch vor.

Die Arbeitswoche ist vorbei, und die Frage nach dem Datum/Zeit ist fĂŒr ihn nicht kritisch, daher kann ich einfach nach Hause gehen, aber hier mache ich einen neuen Fehler.

Dritter Fehler. RatschlÀge

Frag niemals Fragen in Foren und auf allgemein spezialisierten (wie stackoverflow) Webseiten, wenn die Antwort darauf mehr erfordert als das Studium der Ergebnisse der ersten Google-Seite und das Lesen einer Seite der man-Seite.

Man wird Sie zurĂŒck zu Google schicken, um die gleiche man-Seite zu lesen und wird Ihnen die Regeln des Forums/der Seite anschaulich erklĂ€ren, aber keine Antwort geben.

Hier gibt es sowohl objektive Faktoren:

  • Niemand kann das Problem so gut kennen wie Sie selbst;
  • Niemand kann Tests unter denselben Bedingungen wie Sie durchfĂŒhren;

sowie subjektive:

  • Sie könnten nicht alle Informationen fĂŒr die Lösung des Problems bereitstellen, weil Sie bereits in die „richtige“ Richtung denken und die Frage entsprechend prĂ€sentieren;
  • Der Vorsteher (Moderator, Alteingesessener, Admin) hat immer recht, wenn der Vorsteher unrecht hat... nun, Sie wissen schon...

Wenn Sie in den Kommentareantworten im Rahmen der zensierten Sprache geblieben sind, dann haben Sie starke Nerven.

Lösung

Es ist nicht nötig, Aufgaben in einfache und schwierige zu unterteilen.

Hören Sie auf, sich auf Ihre Erfahrungen, Statistiken, RatschlĂ€ge zu verlassen, und beginnen Sie nicht, das endgĂŒltige Ergebnis zu „erklĂ€ren“, sondern die Ursache systematisch zu suchen.

Wenn jemand die Zeit festlegt, muss also ein entsprechender Systemaufruf stattfinden.

Wie in der Softwaredokumentation, dass die besten Dokumente die Quellcodes sind, so ist im Systemadministration der beste Helfer das Audit, in unserem Fall auditd.

Ein Moment des ZweifelsIch habe die Man-Seiten durchgesehen, war aber mir nicht ganz sicher, dass die Zeit in Linux nur ĂŒber clock_settime und settimeofdaygesetzt werden kann, deshalb habe ich fĂŒr den ersten Test alle "geeigneten" Aufrufe gewĂ€hlt:

# 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

und habe s390_runtime_instr, stime, timerfd_create, die auditctl nicht akzeptiert hat. Ich habe das Audit zunÀchst wie folgt gestartet:

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

Nachdem ich sichergestellt habe, dass an den fĂŒr mich interessanten Stellen der Logs keine anderen syscalls außer diesen beiden vorhanden sind, habe ich nur sie verwendet.

Wir starten das Audit der Systemaufrufe clock_settime und settimeofday und versuchen, das Datum zu Àndern:

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

Eine fĂŒnfsekĂŒndige Verzögerung wurde hinzugefĂŒgt, damit unser "Parasit" die Zeit garantiert korrigiert.

Wir sehen den Bericht:

# 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

Hier sehen wir unser date und uns unbekannte chkcache_proces. Er tauchte im obigen Bericht auf, da aureport die Ausgabe nach Datum sortiert hat, als sie aus dem BinÀrformat umgewandelt wurde, und das Ereignis fand zu der von uns festgelegten Zeit statt. date -s "2019-08-22 12:10:00".
Wer hat ihn erschaffen?

# 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 — Unser Parasit wurde gefunden. Trotz seines "schĂ€dlichen" Verhaltens kann man nicht auf das Zugangssystem verzichten, aber es wĂ€re doch schön zu wissen, oscam, WTF?

Die Antwort wurde schnell in den Quellcodes:

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

gefunden. Wie nett sieht hier die auskommentierte Zeile des Warnhinweises


Quelle: habr.com

60GB SSD 8Gb DDR4