Timingproblem im startup löst manchmal NTP Watchdog aus (Fehlalarm)

Einrichtung, Nutzung und Hilfe zu RaspberryMatic (OCCU auf Raspberry Pi)

Moderatoren: jmaus, Co-Administratoren

Michael K.
Beiträge: 35
Registriert: 05.02.2014, 22:10
Hat sich bedankt: 1 Mal
Danksagung erhalten: 3 Mal

Timingproblem im startup löst manchmal NTP Watchdog aus (Fehlalarm)

Beitrag von Michael K. » 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

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.
Sofort danach führt er alle link-up Aktionen aus. ntpdate scheitert

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)
Hier wird dann die firewall konfiguriert, hier kommt erstmals meine (statische) IP Adresse vor. Ich vermute, erst ab hier hat er raspy Netz.

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.
Hier wird Monit gestartet, der sofort erkennt, dass chronyd nicht läuft. Bis hierher finded sich auch kein Startversuch von chronyd im log.

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'
Hier der erste funktionierende ntpdate Eintrag und danach der erste Start von chronyd

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

und hier die Auslösen des Alarms

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
Dann das Netzwerk

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.
Sofort danach führt er alle link-up Aktionen aus. ntpdate funktioniert. chrondy startet

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)
Interessanterweise wird erst hier die ipv4 Adresse erstmals im log erwähnt

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 
Und am Schluss startet der monit

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

Benutzeravatar
jmaus
Beiträge: 6614
Registriert: 17.02.2015, 14:45
System: Alternative CCU (auf Basis OCCU)
Wohnort: Dresden
Hat sich bedankt: 73 Mal
Danksagung erhalten: 506 Mal
Kontaktdaten:

Re: Timingproblem im startup löst manchmal NTP Watchdog aus (Fehlalarm)

Beitrag von jmaus » 29.10.2020, 12:03

Danke die ausführliche Fehlerbeschreibung.

Benutzt du DHCP oder manuelle/statische IP Vergabe?

Kannst du mal schauen ob du der Datei /etc/network/if-up.d/eQ3StartNetwork in Zeile 214 (https://github.com/jens-maus/RaspberryM ... twork#L214) ein "sleep 5" oder so hinzufügen kannst das dann dazu führen könnte dem Netzwerkinterface/DHCP usw etwas mehr Zeit zu gönnen um die IP auch entsprechend zu bekommen.
RaspberryMatic 3.53.34.20201121 @ ESXi, ~190 Hm-RF/HmIP-RF/HmIPW Geräte, ioBroker – RaspberryMatic GitHub Projekt / Twitter

Michael K.
Beiträge: 35
Registriert: 05.02.2014, 22:10
Hat sich bedankt: 1 Mal
Danksagung erhalten: 3 Mal

Re: Timingproblem im startup löst manchmal NTP Watchdog aus (Fehlalarm)

Beitrag von Michael K. » 29.10.2020, 12:17

IP Adressen sind statisch.

Das sleep bau ich ein, wird aber ein wenig dauern. Kämpfe nämlich damit, dass meine Rega immer noch abstürzt, was sie seit 3.53.30 verlässlich macht. Habe mich jetzt schrittweise bis zur 3.51.6.20200621 vorgearbeitet. Bis dahin alles stabil, ab der 3.53.30 (beide) regelmäßige Abstürze. Habe inzwischen alle Programme deaktiviert, was die Rega aber nicht davon abhält trotzdem regelmäßig abzustürzen. Bin noch in Analyse. Positiv: Ich reboote oft (deshalb ist mir das auch mit dem Watchdog aufgefallen). Mal schaun.

Michael K.
Beiträge: 35
Registriert: 05.02.2014, 22:10
Hat sich bedankt: 1 Mal
Danksagung erhalten: 3 Mal

Re: Timingproblem im startup löst manchmal NTP Watchdog aus (Fehlalarm)

Beitrag von Michael K. » 29.10.2020, 13:11

Hast Du das korrekte remount für mich, weil / und damit 'eQ3StartNetwork' is read only

Benutzeravatar
jmaus
Beiträge: 6614
Registriert: 17.02.2015, 14:45
System: Alternative CCU (auf Basis OCCU)
Wohnort: Dresden
Hat sich bedankt: 73 Mal
Danksagung erhalten: 506 Mal
Kontaktdaten:

Re: Timingproblem im startup löst manchmal NTP Watchdog aus (Fehlalarm)

Beitrag von jmaus » 29.10.2020, 13:14

Michael K. hat geschrieben:
29.10.2020, 13:11
Hast Du das korrekte remount für mich, weil / und damit 'eQ3StartNetwork' is read only
Wie immer:

Code: Alles auswählen

mount -o rw,remount /
RaspberryMatic 3.53.34.20201121 @ ESXi, ~190 Hm-RF/HmIP-RF/HmIPW Geräte, ioBroker – RaspberryMatic GitHub Projekt / Twitter

Michael K.
Beiträge: 35
Registriert: 05.02.2014, 22:10
Hat sich bedankt: 1 Mal
Danksagung erhalten: 3 Mal

Re: Timingproblem im startup löst manchmal NTP Watchdog aus (Fehlalarm)

Beitrag von Michael K. » 29.10.2020, 15:28

So, interessanterweise keine Änderung. Watchdog hat wieder angeschlagen.

/etc/network/if-up.d/eQ3StartNetwork (Ausschnitt)

Code: Alles auswählen

        fi
      ;;
      *)
        touch /var/status/hasLink
      ;;
    esac
  ;;

esac

sleep 5

# init the firewall only in case
# we are in normal startup mode
if [[ "${HM_MODE}" == "NORMAL" ]]; then
  # set firewall rules
  /bin/setfirewall.tcl
  echo -n "firewall, "
fi

# check internet connection
Log-Ausschnitt mit 5 Sekunden Pause gleich am Anfang

Code: Alles auswählen

Oct 29 15:06:44 homematic-ccu2 user.notice kernel: klogd started: BusyBox v1.31.1 (2020-10-24 08:12:48 CEST)
Oct 29 15:06:45 homematic-ccu2 user.info kernel: [   16.517977] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xCDE1
Oct 29 15:06:50 homematic-ccu2 user.info firewall: configuration set
Oct 29 15:06:50 homematic-ccu2 user.info kernel: [   20.752087] NET: Registered protocol family 10
Oct 29 15:06:50 homematic-ccu2 user.info kernel: [   20.757961] Segment Routing with IPv6
Oct 29 15:06:50 homematic-ccu2 user.notice rfkill: block set for type wlan
Oct 29 15:06:50 homematic-ccu2 daemon.info ifplugd(eth0)[517]: ifplugd 0.28 initializing.
Oct 29 15:06:50 homematic-ccu2 daemon.info ifplugd(eth0)[517]: Using interface eth0/BxxxxxxxxxA with driver <smsc95xx> (version: 22-Aug-2005)
Oct 29 15:06:50 homematic-ccu2 daemon.info ifplugd(eth0)[517]: Using detection mode: SIOCETHTOOL
Oct 29 15:06:50 homematic-ccu2 daemon.info ifplugd(eth0)[517]: Initialization complete, link beat detected.
Oct 29 15:06:50 homematic-ccu2 daemon.info ifplugd(wlan0)[521]: ifplugd 0.28 initializing, using NETLINK device monitoring.
Oct 29 15:06:50 homematic-ccu2 daemon.info ifplugd(wlan0)[521]: Using interface wlan0/BxxxxxxxxxF with driver <brcmfmac> (version: 7.45.98.83)
Oct 29 15:06:50 homematic-ccu2 daemon.info ifplugd(wlan0)[521]: Using detection mode: wireless extension
Oct 29 15:06:50 homematic-ccu2 daemon.info ifplugd(wlan0)[521]: Initialization complete, link beat not detected, interface enabled.
Oct 29 15:06:50 homematic-ccu2 daemon.info ifplugd(eth0)[517]: Executing '/etc/ifplugd/ifplugd.action eth0 up'.
Oct 29 15:06:50 homematic-ccu2 daemon.err ntpdate[533]: name server cannot be used: Temporary failure in name resolution (-3)
Oct 29 15:06:50 homematic-ccu2 daemon.err ntpdate[542]: name server cannot be used: Temporary failure in name resolution (-3)
Oct 29 15:06:50 homematic-ccu2 syslog.info syslogd exiting
Oct 29 15:06:50 homematic-ccu2 syslog.info syslogd started: BusyBox v1.31.1
Oct 29 15:06:50 homematic-ccu2 user.notice kernel: klogd started: BusyBox v1.31.1 (2020-10-24 08:12:48 CEST)
Oct 29 15:06:50 homematic-ccu2 daemon.err xinetd[572]: Unable to read included directory: /etc/config/xinetd.d [file=/etc/xinetd.conf] [line=14]
Oct 29 15:06:50 homematic-ccu2 daemon.crit xinetd[572]: 572 {init_services} no services. Exiting...
Oct 29 15:06:51 homematic-ccu2 auth.info sshd[608]: Server listening on 0.0.0.0 port 22.
Oct 29 15:06:51 homematic-ccu2 auth.info sshd[608]: Server listening on :: port 22.
Oct 29 15:06:51 homematic-ccu2 user.info root: Updating RF Lan Gateway Coprocessor Firmware
Oct 29 15:06:51 homematic-ccu2 user.debug update-coprocessor: firmware filename is: coprocessor_update_hm_only.eq3
Oct 29 15:06:51 homematic-ccu2 user.info update-coprocessor: performGatewayCoproUpdate(): updating MEQ1479173
Oct 29 15:06:53 homematic-ccu2 user.info update-coprocessor: Lan Device Information: Protocol-Version: 1 Product-ID: eQ3-HM-LGW Firmware-Version: 1.1.5 Serial Number: MEQ1479173
Oct 29 15:06:55 homematic-ccu2 user.debug update-coprocessor: (MEQ1479173) CCU2CommControllerMod::handleIdentifyEvent(): Coprocessor is in application.
Oct 29 15:06:55 homematic-ccu2 user.debug update-coprocessor: CCU2CoprocessorCommandMod::CCU2CoprocessorCommandMod(): System frame
Oct 29 15:06:55 homematic-ccu2 user.debug update-coprocessor: CCU2CoprocessorCommandMod::isResponseStatusOk(): System status OK
Oct 29 15:06:55 homematic-ccu2 user.debug update-coprocessor: CCU2CommControllerMod::handleIncomingResponse() System response OK
Oct 29 15:06:55 homematic-ccu2 user.debug update-coprocessor: (MEQ1479173) CCU2CommControllerMod::handleIdentifyEvent(): Coprocessor is in application.
Oct 29 15:06:55 homematic-ccu2 user.debug update-coprocessor: CoprocessorUpdate::startApplication():Coprocessor entered application.
Oct 29 15:06:55 homematic-ccu2 user.debug update-coprocessor: CCU2CoprocessorCommandMod::CCU2CoprocessorCommandMod(): System frame
Oct 29 15:06:55 homematic-ccu2 user.debug update-coprocessor: CCU2CoprocessorCommandMod::isResponseStatusOk(): System status OK
Oct 29 15:06:55 homematic-ccu2 user.debug update-coprocessor: CCU2CommControllerMod::handleIncomingResponse() System response OK
Oct 29 15:06:55 homematic-ccu2 user.info update-coprocessor: Version: 1.4.1
Oct 29 15:06:55 homematic-ccu2 user.info update-coprocessor: Coprocessor firmware not necessary.
Oct 29 15:06:55 homematic-ccu2 user.info root: Updating RF Lan Gateway Firmware
Oct 29 15:06:55 homematic-ccu2 user.info update-lgw-firmware: LAN Gateway Firmware Update...
Oct 29 15:06:55 homematic-ccu2 user.info update-lgw-firmware: Gateway MEQ1479173
Oct 29 15:06:56 homematic-ccu2 user.info firewall: configuration set
Oct 29 15:06:56 homematic-ccu2 daemon.warn ifplugd(eth0)[517]: client: eth0: link up, static, firewall, inet up, 192.168.1.8, 
Oct 29 15:06:56 homematic-ccu2 daemon.info ifplugd(eth0)[517]: Program executed successfully.

Benutzeravatar
jmaus
Beiträge: 6614
Registriert: 17.02.2015, 14:45
System: Alternative CCU (auf Basis OCCU)
Wohnort: Dresden
Hat sich bedankt: 73 Mal
Danksagung erhalten: 506 Mal
Kontaktdaten:

Re: Timingproblem im startup löst manchmal NTP Watchdog aus (Fehlalarm)

Beitrag von jmaus » 29.10.2020, 15:45

Hmm, komisch. Editier mal die Datei /etc/ifplugd/ifplugd.conf und änder die ARGS= Zeile wie folgt ab:

Code: Alles auswählen

ARGS="-fwI -u0 -d10"
D.h. also ein "w" hinzufügen.
RaspberryMatic 3.53.34.20201121 @ ESXi, ~190 Hm-RF/HmIP-RF/HmIPW Geräte, ioBroker – RaspberryMatic GitHub Projekt / Twitter

Michael K.
Beiträge: 35
Registriert: 05.02.2014, 22:10
Hat sich bedankt: 1 Mal
Danksagung erhalten: 3 Mal

Re: Timingproblem im startup löst manchmal NTP Watchdog aus (Fehlalarm)

Beitrag von Michael K. » 29.10.2020, 16:59

Gemacht

Code: Alles auswählen

INTERFACES="auto"
ARGS="-fwI -u0 -d10"
ARGS_wlan0="-MwI -u5 -d5"
Wird ein wenig dauern, bis ich rebooten kann (ich muss warten bis die ReGa wieder stürzt. Hab übrigens lange in meinen Programmen gesucht, warum ich eine ReGa Info "metadata property 'MIN' does not exist" regelmäßig im Log hab. Hab die Ursache gefunden :-). Hilft nur nicht weiter).

Benutzeravatar
jmaus
Beiträge: 6614
Registriert: 17.02.2015, 14:45
System: Alternative CCU (auf Basis OCCU)
Wohnort: Dresden
Hat sich bedankt: 73 Mal
Danksagung erhalten: 506 Mal
Kontaktdaten:

Re: Timingproblem im startup löst manchmal NTP Watchdog aus (Fehlalarm)

Beitrag von jmaus » 29.10.2020, 17:05

Michael K. hat geschrieben:
29.10.2020, 16:59
Wird ein wenig dauern, bis ich rebooten kann (ich muss warten bis die ReGa wieder stürzt.
Du kannst gerne die ReGa von Hand in der Konsole einfach mal starten und dort laufen lassen via:

Code: Alles auswählen

monit stop regahss
/bin/ReGaHss -f /etc/rega.conf -l 0 -c
Und dann lässt du es laufen bis es abschmiert, und wenn es dann abraucht und mir dann die letzten Zeilen zukommen lassen damit ich mir das mal anschauen kann was da genau abschmiert.
RaspberryMatic 3.53.34.20201121 @ ESXi, ~190 Hm-RF/HmIP-RF/HmIPW Geräte, ioBroker – RaspberryMatic GitHub Projekt / Twitter

Michael K.
Beiträge: 35
Registriert: 05.02.2014, 22:10
Hat sich bedankt: 1 Mal
Danksagung erhalten: 3 Mal

Re: Timingproblem im startup löst manchmal NTP Watchdog aus (Fehlalarm)

Beitrag von Michael K. » 29.10.2020, 17:16

Da komme ich gerne darauf zurück. Rega vorher stoppen oder einfach drüber starten?

Code: Alles auswählen

/etc/init.d/S70ReGaHss stop

Antworten

Zurück zu „RaspberryMatic“