Mal wieder Freitag? Könnte man meinen, aber nein erst Dienstag. Das Monitoring meldet ntp wäre nicht synchron. Die Uhrzeit geht aber richtig. Komisch. Also Zeit der Sache mit der Zeit auf den Grund zu gehen.
Aber egal, hier kommt es gar nicht drauf an ob die Uhrzeit jetzt richtig geht oder nicht: Der Sache sollte man auf den Grund gehen. Hier ein einfacher Leitfaden mit dem man sich auf die Suche nach der Ursache machen kann. Zunächst meldet man sich zum Beispiel via ssh an der Konsole des betroffenen Rechners an.
1. Uhrzeitquellen ermitteln
Das geht an der Konsole rasch und fix wie folgt:
root@ghm ~ # ntpq -p
remote refid st t when poll reach delay offset jitter
==============================================================================
0.ubuntu.pool.n .POOL. 16 p - 64 0 0.000 0.000 0.000
1.ubuntu.pool.n .POOL. 16 p - 64 0 0.000 0.000 0.000
2.ubuntu.pool.n .POOL. 16 p - 64 0 0.000 0.000 0.000
3.ubuntu.pool.n .POOL. 16 p - 64 0 0.000 0.000 0.000
de.pool.ntp.org .POOL. 16 p - 64 0 0.000 0.000 0.000
ntp.ubuntu.com .POOL. 16 p - 64 0 0.000 0.000 0.000
-nbg00.furzone.n 237.17.204.95 2 u 13 64 377 2.696 -0.107 0.226
#ns1.customer-re 192.53.103.108 2 u 12 64 377 10.811 1.154 0.385
+mail.sebi.org 237.17.204.95 2 u 10 64 377 2.753 0.522 0.404
-47.ip-51-75-67. 207.197.87.124 4 u 6 64 377 6.170 -0.790 0.284
-dxb.vaxxi.net 176.96.138.245 3 u 7 64 377 5.246 0.209 0.269
-2a01:4f8:202:14 36.224.68.195 2 u 73 128 377 0.344 -0.302 0.330
*193.24.227.196 .PZF. 1 u 9 64 377 7.340 0.393 0.419
-mc1.root.projec 35.73.197.144 2 u 76 128 377 6.191 -0.331 0.393
-vmd55813.contab 192.53.103.103 2 u 9 64 377 14.178 0.867 0.411
-shout.ovh 131.188.3.220 2 u 68 128 377 2.701 0.441 0.532
+2a03:4000:28:36 85.25.213.41 3 u 2 64 377 2.740 -0.096 0.242
Das -p steht für peers. Mit -pn hätte man die numerische Ansicht, also keine DNS-Namen in der ersten Spalte. In diesem Beispiel habe ich mal eine etwas längere Liste genommen. Interessant ist das Zeichen vor der ersten Spalte. Die wichtigsten hierbei sind:
+ Dieser Server könnte verwendet werden
* Dieser Server wird verwendet
- Dieser Server wurde aussortiert
Leerzeichen: Dieser Server ist nicht erreichbar.
Weitere Details gefällig? Die finden sich zum Beispiel hier: http://doc.ntp.org/4.1.0/ntpq.htm.
Für uns wichtig: Es sollte eine Zeitquelle mit dem * geben. Wenn ja, dann ist alles wunderbar.
Nur ist es leider so, dass man das so nicht immer antrifft. In internen Netzen hinter Firewalls erlebe ich oft genug, dass es nur einen NTP-Server als Zeitquelle gibt. Und wenn dieser nach der Initialisierungsphase immer noch mit Leerzeichen angezeigt wird, wird es Zeit der Sache genauer auf den Grund zu gehen. Das könnte dann wie folgt aussehen:
ntpq> peers
remote refid st t when poll reach delay offset jitter
==============================================================================
2.time.domain 192.53.103.104 2 u 268 1024 377 0.222 0.046 0.485
ntpq>
Zu diesem Aufruf: Ich habe lediglich ntpq an der Konsole eingegeben und an der folgenden Befehlseingabe das Schlüsselwort peers. Das hätte ich auch schneller haben können wie bereits oben gezeigt: ntpq -p.
Aber was sieht man? Nur eine Zeitquelle und die hat trotz einem guten Stratum von 2 (die st Spalte) nur ein Leerzeichen davor.
Details zum Begriff Stratum gefällig? Eine kurze Einführung gibt es hier: https://de.wikipedia.org/wiki/Network_Time_Protocol#Grundlagen. Mehr Details gefällig? Die gibt es hier: http://www.ntp.org/ntpfaq/NTP-s-algo.htm.
2. Analyse
ntpq habe ich bereits gezeigt. Dieses Tool ist Mittel der Wahl zur Fehlersuche. Also rasch nochmals gestartet und folgende beiden Kommandos ausgeführt: as für associations. In dieser Übersicht erhält man die für weitere Recherchen notwendige assid. Du hast nachgelesen was +, -, * und so weiter in der Liste der peers bedeutet? Dann wirst Du alte Bekannte in der Spalte condition wieder erkennen. Das sieht dann zum Beispiel so aus:
ntpq> as ind assid status conf reach auth condition last_event cnt =========================================================== 1 26914 901a yes yes none reject sys_peer 1 ntpq>
In diesem Beispiel gehe ich wieder der Annahme, dass bereits ntpq gestartet wurde. Interessant ist die assid 26914. Unter condition steht reject. Aber das wussten wir ja bereits.
Mit rv bzw. readvars kann man sich nun weiter Details zur ermittelten assid anzeigen lassen:
rv 26914 associd=26914 status=901a conf, reach, sel_reject, 1 event, sys_peer, srcadr=<snip>, srcport=123, dstadr=<snip>, dstport=123, leap=00, stratum=2, precision=-23, rootdelay=18.784, rootdisp=25.986, refid=192.53.103.104, reftime=e2d36804.31d83086 Tue, Aug 4 2020 6:52:20.194, rec=e2d36ab6.efc51cfc Tue, Aug 4 2020 7:03:50.936, reach=377, unreach=0, hmode=3, pmode=4, hpoll=10, ppoll=10, headway=0, flash=400 peer_dist, keyid=0, offset=0.046, delay=0.222, dispersion=19.105, jitter=0.485, xleave=0.019, filtdelay= 0.22 0.22 0.24 0.26 0.28 0.27 0.29 0.27, filtoffset= -0.08 0.05 0.17 0.35 0.51 0.65 0.78 0.68, filtdisp= 0.00 15.81 31.26 46.74 62.76 79.05 95.06 110.49
Für die Bedeutung sämtlicher Variablen sei im Moment auf die ntp Dokumentation verwiesen. Interessant ist in unserem Fall das was bei flash steht: 400 peer_dist. Zusammengefasst bedeutet dies, dass die maximale Zeit erreicht wurde die der gegenüberliegende Server brauchen darf für seine Antwort. Die Gründe hierfür können die Serverlast zum einen, die Netzwerklast zum anderen sein.
Details zum flash status finden sich hier: http://doc.ntp.org/4.2.6p5/decode.html. Weitere Infos zu maxdist mit dem man die maximale Wartezeit beeinflussen kann finden sich hier: http://doc.ntp.org/current-stable/miscopt.html.
Noch eine kurze Anmerkung zum rv: Wenn man die assid weglässt oder auf 0 setzt werden die eigenen Variablen ausgegeben.
3. Ursache und Lösung
Da der Rest im Netzwerk zu dem Zeitpunkt sauber läuft liegt die Ursache vermutlich wo anders. Also zum Zeitpunkt mal auf dem Ziel-NTP-Server umgeschaut. Und siehe da, da reichte ein einfacher top um die Ursache zu finden: Das Backup lastete die Prozessoren aus. Kaum war das Backup vorbei lief NTP wieder sauber.
Was kann man dagegen machen? Zum einen könnte man das Backup entsprechend ändern, dass es weniger CPU-Ressourcen verbraucht. Das geht aber normalerweise zu Kosten der Laufzeit und ist sicherlich nicht überall umsetzbar. Die pragmatischste Lösung wäre ein weiterer NTP-Server. Solange die zu unterschiedlichen Zeiten ihr Backup am laufen haben ist immer mindestens ein Server uneingeschränkt erreichbar. Und das hilft sogar außerhalb vom Backup bei so Begriffen wie „Wartungsarbeiten“ oder dem weniger schönen „Ausfall“…
Und gleich nochmals
Ok, einer geht noch. Ein Fall der in meinem Umfeld viel öfters vorkommt als der oben beschriebene. Werfen wir einen Blick auf folgende Ausgabe der peers:
ntpq> peers
remote refid st t when poll reach delay offset jitter
==============================================================================
1xx.xx.xxx.x .INIT. 16 u - 1024 0 0.000 0.000 0.000
+ftp.xxx.xxx 192.53.103.104 2 u 730 1024 377 0.254 -0.046 0.226
+ptbtime1.ptb.de .PTB. 1 u 139 1024 377 18.605 -0.019 0.106
*ptbtime2.ptb.de .PTB. 1 u 556 1024 377 18.704 -0.029 0.104
+ptbtime3.ptb.de .PTB. 1 u 455 1024 377 18.567 -0.029 1.859
+ns.xxx.xxx 192.53.103.108 2 u 97 1024 377 0.272 0.103 0.138
Eigentlich ein Traum: Von einem mal abgesehen könnten alle Server als Uhrzeitquelle verwendet werden. Und ein * ist mittendrin. Alles wunderbar. Trotzdem schauen wir nochmals genauer die erste Zeile an: Ein Leerzeichen und die refid bleibt auf .INIT. stehen. Da das hier nur einer ist wäre das nicht so wild. Wenn es bei allen Servern so aussieht, dann wäre das weniger gut.
Und wie geht es weiter? Genauso wie oben. Also mit as die assid ermittelt und via rv die Variablen anzeigen lassen:
ntpq> as ind assid status conf reach auth condition last_event cnt =========================================================== 1 9501 8011 yes no none reject mobilize 1 2 9502 941a yes yes none candidate sys_peer 1 3 9503 94fa yes yes none candidate sys_peer 15 4 9504 96fa yes yes none sys.peer sys_peer 15 5 9505 94fa yes yes none candidate sys_peer 15 6 9506 9414 yes yes none candidate reachable 1 ntpq> rv 9501 associd=9501 status=8011 conf, sel_reject, 1 event, mobilize, srcadr=1xx.xx.xxx.x, srcport=123, dstadr=xxx.xxx.xxx.xxx, dstport=123, leap=11, stratum=16, precision=-24, rootdelay=0.000, rootdisp=0.000, refid=INIT, reftime=00000000.00000000 Thu, Feb 7 2036 7:28:16.000, rec=00000000.00000000 Thu, Feb 7 2036 7:28:16.000, reach=000, unreach=43552, hmode=3, pmode=0, hpoll=10, ppoll=10, headway=0, flash=1600 peer_stratum, peer_dist, peer_unreach, keyid=0, offset=0.000, delay=0.000, dispersion=15937.500, jitter=0.000, xleave=0.010, filtdelay= 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00, filtoffset= 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00, filtdisp= 16000.0 16000.0 16000.0 16000.0 16000.0 16000.0 16000.0 16000.0 ntpq>
Bei flash steht dieses mal deutlich mehr drin: peer_stratum, peer_dist und peer_unreach. Der Code 1600 ist die Summe der einzelnen Codes 200, 400 und 1000. Diese Werte finden sich unter anderem im bereits weiter oben genannten Link http://doc.ntp.org/4.2.6p5/decode.html wieder.
peer_dist und peer_stratum sind jetzt eher als Folgefehler zu betrachten. peer_unreach ist da schon viel eindeutiger. Und in der Tat hat hier die Firewall ein Streich gespielt. Es ist schon einige Mal vorgekommen, dass die Kollegen von der Firewall vergessen haben, dass NTP Anfragen zwar auf Port 123/udp gehen, jedoch auch von Port 123 kommen.
Fazit
Egal was für ein Problem man mit NTP hat: Mehr Hinweise erhält man wenn man die Synchronisierungsserver anzeigen lässt, zu den Problemfällen die Verknüpfungsids ermittelt und zu diesen die Variablen ausliest (peers, as und rv). Der Rest ist dann Stückwerk und Auswertung der Fakten. Die Vorarbeit ist bereits erfolgreich erledigt.