Timingproblem im startup löst manchmal NTP Watchdog aus (Fehlalarm)
Verfasst: 29.10.2020, 11:48
Ich bekomme manchmal (25%?) beim Boot einen "Chrony-NTP restarted WatchDog-Alarm". Ich vermute ein Timing-Problem beim Boot.
Beide Fälle aktuelle Firmware.
Im Fehlerfall
Hier bootet der raspy und initialisiert den eth0
Sofort danach führt er alle link-up Aktionen aus. ntpdate scheitert
Hier wird dann die firewall konfiguriert, hier kommt erstmals meine (statische) IP Adresse vor. Ich vermute, erst ab hier hat er raspy Netz.
Hier wird Monit gestartet, der sofort erkennt, dass chronyd nicht läuft. Bis hierher finded sich auch kein Startversuch von chronyd im log.
Hier der erste funktionierende ntpdate Eintrag und danach der erste Start von chronyd
und hier die Auslösen des Alarms
Im Regelfall
Zuerst die Firewall (interessanterweise hier mit IPv6)
Dann das Netzwerk
Sofort danach führt er alle link-up Aktionen aus. ntpdate funktioniert. chrondy startet
Interessanterweise wird erst hier die ipv4 Adresse erstmals im log erwähnt
Und am Schluss startet der monit
Beide Fälle aktuelle Firmware.
Im Fehlerfall
Hier bootet der raspy und initialisiert den eth0
Code: Alles auswählen
Oct 29 11:07:57 homematic-ccu2 daemon.info ifplugd(eth0)[511]: ifplugd 0.28 initializing.
Oct 29 11:07:57 homematic-ccu2 daemon.info ifplugd(eth0)[511]: Using interface eth0/<mac-removed> with driver <smsc95xx> (version: 22-Aug-2005)
Oct 29 11:07:57 homematic-ccu2 daemon.info ifplugd(eth0)[511]: Using detection mode: SIOCETHTOOL
Oct 29 11:07:57 homematic-ccu2 daemon.info ifplugd(eth0)[511]: Initialization complete, link beat detected.
Oct 29 11:07:57 homematic-ccu2 daemon.info ifplugd(wlan0)[515]: ifplugd 0.28 initializing, using NETLINK device monitoring.
Oct 29 11:07:57 homematic-ccu2 daemon.info ifplugd(wlan0)[515]: Using interface wlan0/<mac-removed> with driver <brcmfmac> (version: 7.45.98.83)
Oct 29 11:07:57 homematic-ccu2 daemon.info ifplugd(wlan0)[515]: Using detection mode: wireless extension
Oct 29 11:07:57 homematic-ccu2 daemon.info ifplugd(wlan0)[515]: Initialization complete, link beat not detected, interface enabled.
Code: Alles auswählen
Oct 29 11:07:57 homematic-ccu2 daemon.info ifplugd(eth0)[511]: Executing '/etc/ifplugd/ifplugd.action eth0 up'.
Oct 29 11:07:57 homematic-ccu2 daemon.err ntpdate[527]: name server cannot be used: Temporary failure in name resolution (-3)
Oct 29 11:07:57 homematic-ccu2 daemon.err ntpdate[536]: name server cannot be used: Temporary failure in name resolution (-3)
Code: Alles auswählen
Oct 29 11:07:58 homematic-ccu2 user.info firewall: configuration set
Oct 29 11:07:58 homematic-ccu2 daemon.warn ifplugd(eth0)[511]: client: eth0: link up, static, firewall, inet up, 192.168.1.8,
Oct 29 11:07:58 homematic-ccu2 daemon.info ifplugd(eth0)[511]: Program executed successfully.
Code: Alles auswählen
Oct 29 11:08:37 homematic-ccu2 user.info monit[1053]: Starting Monit 5.26.0 daemon with http interface at /var/run/monit.sock
Oct 29 11:08:37 homematic-ccu2 user.info monit[1053]: 'homematic-ccu2' Monit 5.26.0 started
Oct 29 11:08:37 homematic-ccu2 user.err monit[1053]: 'chronyd' process is not running
Oct 29 11:08:37 homematic-ccu2 user.info monit[1053]: 'chronyd' trying to restart
Oct 29 11:08:37 homematic-ccu2 user.info monit[1053]: 'chronyd' restart: '/etc/init.d/S49chrony restart'
Code: Alles auswählen
Oct 29 11:08:49 homematic-ccu2 daemon.notice ntpdate[1069]: step time server 131.188.3.220 offset +0.330211 sec
Oct 29 11:08:49 homematic-ccu2 daemon.info chronyd[1117]: chronyd version 3.5.1 starting (+CMDMON +NTP +REFCLOCK +RTC -PRIVDROP -SCFILTER -SIGND +ASYNCDNS -SECHASH +IPV6 -DEBUG)
Oct 29 11:08:49 homematic-ccu2 user.info monit[1053]: 'chronyd' process is running with pid 1117
Code: Alles auswählen
Oct 29 11:09:04 homematic-ccu2 user.err monit[1053]: 'chronyd' service restarted 1 times within 1 cycles(s) - exec
Oct 29 11:09:04 homematic-ccu2 user.info monit[1053]: 'chronyd' exec: '/bin/triggerAlarm.tcl Chrony-NTP restarted WatchDog-Alarm'
Oct 29 11:09:04 homematic-ccu2 user.info monit[1053]: 'chronyd' process is running after previous restart timeout (manually recovered?)
Im Regelfall
Zuerst die Firewall (interessanterweise hier mit IPv6)
Code: Alles auswählen
Oct 29 10:58:14 homematic-ccu2 user.info firewall: configuration set
Oct 29 10:58:14 homematic-ccu2 user.info kernel: [ 16.433645] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xCDE1
Oct 29 10:58:15 homematic-ccu2 user.info kernel: [ 16.667256] NET: Registered protocol family 10
Oct 29 10:58:15 homematic-ccu2 user.info kernel: [ 16.673327] Segment Routing with IPv6
Code: Alles auswählen
Oct 29 10:58:15 homematic-ccu2 daemon.info ifplugd(eth0)[511]: ifplugd 0.28 initializing.
Oct 29 10:58:15 homematic-ccu2 daemon.info ifplugd(eth0)[511]: Using interface eth0/mac-removed> with driver <smsc95xx> (version: 22-Aug-2005)
Oct 29 10:58:15 homematic-ccu2 daemon.info ifplugd(eth0)[511]: Using detection mode: SIOCETHTOOL
Oct 29 10:58:15 homematic-ccu2 daemon.info ifplugd(eth0)[511]: Initialization complete, link beat detected.
Oct 29 10:58:15 homematic-ccu2 daemon.info ifplugd(wlan0)[515]: ifplugd 0.28 initializing, using NETLINK device monitoring.
Oct 29 10:58:15 homematic-ccu2 daemon.info ifplugd(wlan0)[515]: Using interface wlan0/<mac-removed> with driver <brcmfmac> (version: 7.45.98.83)
Oct 29 10:58:15 homematic-ccu2 daemon.info ifplugd(wlan0)[515]: Using detection mode: wireless extension
Oct 29 10:58:15 homematic-ccu2 daemon.info ifplugd(wlan0)[515]: Initialization complete, link beat not detected, interface enabled.
Code: Alles auswählen
Oct 29 10:58:15 homematic-ccu2 daemon.info ifplugd(eth0)[511]: Executing '/etc/ifplugd/ifplugd.action eth0 up'.
Oct 29 10:58:15 homematic-ccu2 daemon.warn ifplugd(eth0)[511]: client: ifup: interface eth0 already configured
Oct 29 10:58:15 homematic-ccu2 daemon.info ifplugd(eth0)[511]: Program executed successfully.
Oct 29 10:58:25 homematic-ccu2 daemon.notice ntpdate[521]: step time server 90.187.99.165 offset +0.696545 sec
Oct 29 10:58:25 homematic-ccu2 daemon.info chronyd[526]: chronyd version 3.5.1 starting (+CMDMON +NTP +REFCLOCK +RTC -PRIVDROP -SCFILTER -SIGND +ASYNCDNS -SECHASH +IPV6 -DEBUG)
Code: Alles auswählen
Oct 29 10:58:51 de.eq3.cbcs.lib.backbone.lanrouting.UdpServer INFO [vert.x-worker-thread-3] UDP Routing configuration: trying to bind port 43438 on eth0 0.0.0.0 -> 192.168.1.8
Code: Alles auswählen
Oct 29 10:59:05 homematic-ccu2 user.info monit[925]: Starting Monit 5.26.0 daemon with http interface at /var/run/monit.sock
Oct 29 10:59:05 homematic-ccu2 user.info monit[925]: 'homematic-ccu2' Monit 5.26.0 started