Vorgestern ist auf meinem Testsystem aus heiterem Himmel die ReGaHSS "abgestürzt", ich bezeiche das im weiteren Verlauf als "Kammerflimmern".
Gemerkt hatte ich erst nichts, wunderte mich aber das der SDV mit dem ich gerade an einem Script zur Ausgabe von Kanalnamen tüftelte, laufend von der Zentrale getrennt wurde. Bin mir aber recht sicher das das Script nicht der Auslöser war.
Einzige weitere Interaktion kurz vor dem stottern der Verbindung war das hochladen der PSM Firmware 2.18.14.
2. Fehlerbeschreibung
Manch einer kennt es... "Die RaspberryMatic ist noch nicht bereit..." also der Zugriff auf die WebUI quasi unmöglich.
Quasi deshalb weil ich immer ein ca. 2-3s "Fenster" hatte (dank bösem Auto-Login) um auf die Startseite und mit Glück in eine der Unterkategorien zu kommen. Letztlich aber ein sinnloses Unterfangen.
Per ssh auf die RM ging weiterhin problemlos und mittels htop war erstmal nichts wirklich auffälliges zu erkennen.
Also mal den Live-View des SysLog-Servers angeworfen und da kam der Salat.
Der Beginn des Kammerflimmerns:
Code: Alles auswählen
2020-11-23T15:40:05.066757+01:00 test-ccu-raspimatic-pi4b.fritz.box node-red[1548]: [ccu-connection:localhost] Interface ReGaHSS disconnected
2020-11-23T15:40:05.070296+01:00 test-ccu-raspimatic-pi4b.fritz.box node-red[1548]: [ccu-connection:localhost] getRegaVariables Error: connect ECONNREFUSED 127.0.0.1:8183
2020-11-23T15:40:05.077427+01:00 test-ccu-raspimatic-pi4b.fritz.box node-red[1548]: [ccu-connection:localhost] getRegaPrograms Error: connect ECONNREFUSED 127.0.0.1:8183
2020-11-23T15:40:09+01:00 test-ccu-raspimatic-pi4b.fritz.box cuxd[917]: sendbinrpc(127.0.0.1:31999) - write() Connection refused
2020-11-23T15:40:09+01:00 test-ccu-raspimatic-pi4b.fritz.box cuxd[917]: disable events to 127.0.0.1:31999
2020-11-23T15:40:14+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1579]: 'ReGaHss' process is not running
2020-11-23T15:40:14+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1579]: 'ReGaHss' trying to restart
2020-11-23T15:40:14+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1579]: 'ccu-historian' stop: '/etc/config/rc.d/ccu-historian stop'
2020-11-23T15:40:14+01:00 test-ccu-raspimatic-pi4b.fritz.box ccu-historian: Stopping
2020-11-23T15:40:14+01:00 test-ccu-raspimatic-pi4b.fritz.box ccu-historian: Stopped
2020-11-23T15:40:19+01:00 test-ccu-raspimatic-pi4b.fritz.box cuxd[917]: sendbinrpc(127.0.0.1:2099) - write() Connection refused
2020-11-23T15:40:21+01:00 test-ccu-raspimatic-pi4b.fritz.box rfd: XmlRpcClient error calling event({[methodName:"event",params:{"1007","LEQ0995080:2","ACTUAL_TEMPERATURE",21.000000}]}) on binary://127.0.0.1:31999/RPC2:
2020-11-23T15:40:21+01:00 test-ccu-raspimatic-pi4b.fritz.box rfd: XmlRpc transport error
2020-11-23T15:40:21+01:00 test-ccu-raspimatic-pi4b.fritz.box rfd: XmlRpcClient error calling event({[methodName:"event",params:{"1007","LEQ0995080:2","ACTUAL_HUMIDITY",53.000000}]}) on binary://127.0.0.1:31999/RPC2:
2020-11-23T15:40:21+01:00 test-ccu-raspimatic-pi4b.fritz.box rfd: XmlRpc transport error
2020-11-23T15:40:21+01:00 test-ccu-raspimatic-pi4b.fritz.box rfd: XmlRpcClient error calling event({[methodName:"event",params:{"1007","LEQ0995080:2","SET_TEMPERATURE",10.000000}]}) on binary://127.0.0.1:31999/RPC2:
2020-11-23T15:40:21+01:00 test-ccu-raspimatic-pi4b.fritz.box rfd: XmlRpc transport error
2020-11-23T15:40:21+01:00 test-ccu-raspimatic-pi4b.fritz.box cuxd[917]: sendbinrpc(127.0.0.1:2099) - write() Connection refused
2020-11-23T15:40:25+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1579]: 'ccu-jack' stop: '/etc/config/rc.d/ccu-jack stop'
2020-11-23T15:40:25+01:00 test-ccu-raspimatic-pi4b.fritz.box ccu-jack: Stopping
2020-11-23T15:40:25+01:00 test-ccu-raspimatic-pi4b.fritz.box ccu-jack: Stopped
2020-11-23T15:40:26+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1579]: 'ReGaHss' restart: '/etc/init.d/S70ReGaHss restart'
2020-11-23T15:40:29+01:00 test-ccu-raspimatic-pi4b.fritz.box cuxd[917]: sendbinrpc(127.0.0.1:2099) - write() Connection refused
2020-11-23T15:40:31+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1579]: 'ReGaHss' process is running with pid 26760
2020-11-23T15:40:31+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1579]: 'ccu-historian' start: '/etc/config/rc.d/ccu-historian start'
2020-11-23T15:40:31+01:00 test-ccu-raspimatic-pi4b.fritz.box ccu-historian: Starting
2020-11-23T15:40:31+01:00 test-ccu-raspimatic-pi4b.fritz.box ccu-historian: Started
2020-11-23T15:40:31+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1579]: 'ccu-jack' start: '/etc/config/rc.d/ccu-jack start'
2020-11-23T15:40:31+01:00 test-ccu-raspimatic-pi4b.fritz.box ccu-jack: Starting
2020-11-23T15:40:35.112126+01:00 test-ccu-raspimatic-pi4b.fritz.box node-red[1548]: [ccu-connection:localhost] Interface ReGaHSS connected
2020-11-23T15:40:35+01:00 test-ccu-raspimatic-pi4b.fritz.box rfd: XmlRpcClient error calling event({[methodName:"event",params:{"1007","JPTH10I065:1","TEMPERATURE",20.200000}]}) on binary://127.0.0.1:31999/RPC2:
2020-11-23T15:40:35+01:00 test-ccu-raspimatic-pi4b.fritz.box rfd: XmlRpc transport error
2020-11-23T15:40:35+01:00 test-ccu-raspimatic-pi4b.fritz.box rfd: XmlRpcClient error calling event({[methodName:"event",params:{"1007","JPTH10I065:1","HUMIDITY",61}]}) on binary://127.0.0.1:31999/RPC2:
2020-11-23T15:40:35+01:00 test-ccu-raspimatic-pi4b.fritz.box rfd: XmlRpc transport error
2020-11-23T15:40:35+01:00 test-ccu-raspimatic-pi4b.fritz.box cuxd[917]: sendbinrpc(127.0.0.1:2099) - write() Connection refused
2020-11-23T15:40:36+01:00 test-ccu-raspimatic-pi4b.fritz.box cuxd[917]: sendbinrpc(127.0.0.1:2099) - write() Connection refused
2020-11-23T15:40:39+01:00 test-ccu-raspimatic-pi4b.fritz.box cuxd[917]: sendbinrpc(127.0.0.1:2099) - write() Connection refused
2020-11-23T15:40:41+01:00 test-ccu-raspimatic-pi4b.fritz.box rfd: XmlRpcClient error calling event({[methodName:"event",params:{"1007","LEQ0995080:1","TEMPERATURE",21.000000}]}) on binary://127.0.0.1:31999/RPC2:
2020-11-23T15:40:41+01:00 test-ccu-raspimatic-pi4b.fritz.box rfd: XmlRpc transport error
2020-11-23T15:40:41+01:00 test-ccu-raspimatic-pi4b.fritz.box rfd: XmlRpcClient error calling event({[methodName:"event",params:{"1007","LEQ0995080:1","HUMIDITY",53}]}) on binary://127.0.0.1:31999/RPC2:
2020-11-23T15:40:41+01:00 test-ccu-raspimatic-pi4b.fritz.box rfd: XmlRpc transport error
2020-11-23T15:40:41+01:00 test-ccu-raspimatic-pi4b.fritz.box cuxd[917]: sendbinrpc(127.0.0.1:2099) - write() Connection refused
2020-11-23T15:40:42+01:00 test-ccu-raspimatic-pi4b.fritz.box cuxd[917]: sendbinrpc(127.0.0.1:2099) - write() Connection refused
2020-11-23T15:40:43+01:00 test-ccu-raspimatic-pi4b.fritz.box cuxd[917]: INIT 'binary://127.0.0.1:2099' 'CUxD'
2020-11-23T15:40:46+01:00 test-ccu-raspimatic-pi4b.fritz.box ccu-jack: Started
2020-11-23T15:41:03+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1579]: 'ReGaHss' service restarted 1 times within 1 cycles(s) - exec
2020-11-23T15:41:03+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1579]: 'ReGaHss' exec: '/bin/triggerAlarm.tcl ReGaHss restarted WatchDog-Alarm'
2020-11-23T15:41:03+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1579]: 'ReGaHss' process is not running
2020-11-23T15:41:03+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1579]: 'ReGaHss' trying to restart
2020-11-23T15:41:03+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1579]: 'ccu-historian' stop: '/etc/config/rc.d/ccu-historian stop'
2020-11-23T15:41:03+01:00 test-ccu-raspimatic-pi4b.fritz.box ccu-historian: Stopping
2020-11-23T15:41:03+01:00 test-ccu-raspimatic-pi4b.fritz.box ccu-historian: Stopped
2020-11-23T15:41:03+01:00 test-ccu-raspimatic-pi4b.fritz.box cuxd[917]: INIT 'binary://127.0.0.1:2099' '(null)'
2020-11-23T15:41:04+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1579]: 'ccu-jack' stop: '/etc/config/rc.d/ccu-jack stop'
2020-11-23T15:41:04+01:00 test-ccu-raspimatic-pi4b.fritz.box ccu-jack: Stopping
2020-11-23T15:41:04+01:00 test-ccu-raspimatic-pi4b.fritz.box ccu-jack: Stopped
2020-11-23T15:41:05.138977+01:00 test-ccu-raspimatic-pi4b.fritz.box node-red[1548]: [ccu-connection:localhost] Interface ReGaHSS disconnected
2020-11-23T15:41:05.139969+01:00 test-ccu-raspimatic-pi4b.fritz.box node-red[1548]: [ccu-connection:localhost] getRegaVariables Error: connect ECONNREFUSED 127.0.0.1:8183
2020-11-23T15:41:05.146244+01:00 test-ccu-raspimatic-pi4b.fritz.box node-red[1548]: [ccu-connection:localhost] getRegaPrograms Error: connect ECONNREFUSED 127.0.0.1:8183
2020-11-23T15:41:05+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1579]: 'ReGaHss' restart: '/etc/init.d/S70ReGaHss restart'
2020-11-23T15:41:09+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1579]: 'ReGaHss' process is running with pid 26967
2020-11-23T15:41:09+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1579]: 'ReGaHss' process is running after previous restart timeout (manually recovered?)
Da die WebUI nicht mehr bedienbar war erfolgte der Neustart mittels reboot über die Konsole.
Gebracht hat das nichts da die Zentrale nicht mehr sauber hochfuhr und die LED des RPI-RF-MOD im Rhythmus von blau zu rot zu blau usw. wechselte.
Also poweroff per Konsole.
4. Backup
Sind ja für die letzten 30 Tage vorhanden.
Also schnell ne frische SD mit RM 3.53.34.20201121 geflashed, das letzte Backup von 0:07 Uhr eingespielt und nach dem Reboot... Kammerflimmern
Selbes Spiel mit dem ältesten Backup 3.53.30.20200919-2020-10-27-0007. Nach Reboot... Kammerflimmern
Kurios.
5. Backupsss
Anschließend habe ich Stichprobenweise 5 verschiedene Backups (3.53.30.20200919, 3.53.34.2020xxx - Nightlys und 3.53.34.20201121) auf verschiedenen System (Pi4B, Pi3B+, ova) mit und ohne Funkmodul getestet. Bei allen nach Reboot... Kammerflimmern
Getestet wurde auch ein 3.53.30.20200919 Backup in die gleiche RM Version einzuspielen... gleiches Ergebnis.
Einzig eine alte Krücke von Backup (3.51.6.20200420-2020-05-29-1601) funktioniert auf allen Systemen.
Noch Kurioser.
6. Safe Mode
Um Auszuschließen das irgendwelche AddOns Amok laufen habe ich mal den Safe-Mode über das Recovery-System probiert.
Der besagt ja das die Zentrale ohne AddOns gestartet wird.
Leider halten sich da diverse AddOns nicht dran.
Auffällig wurden hier der ccu-historian und der ccu-jack welche weiter ihren Dienst verrichten (wollen).
Ein netter Spielverderber in doppelter Hinsicht ist leider auch RedMatic. Installiert war v7.1.1.
Zum einen ignoriert auch RedMatic den Safe Mode. Zum anderen hatte ich arge Probleme mit dem reduzierten Backup.
Hiermit wird der Monit quasi außer Gefecht gesetzt wenn das AddOn nicht "vollständig" ist.
Code: Alles auswählen
2020-11-23T17:07:28+01:00 test-ccu-raspimatic-pi4b.fritz.box : starting pid 1236, tty '/dev/null': '/usr/bin/monit -Ic /etc/monitrc'
2020-11-23T18:07:28+01:00 test-ccu-raspimatic-pi4b.fritz.box monit: /usr/local/etc/monit-redmatic.cfg:6: Program does not exist: '/etc/config/rc.d/redmatic'
2020-11-23T18:07:28+01:00 test-ccu-raspimatic-pi4b.fritz.box monit: /usr/local/etc/monit-redmatic.cfg:7: Program does not exist: '/etc/config/rc.d/redmatic'
2020-11-23T18:07:28+01:00 test-ccu-raspimatic-pi4b.fritz.box monit: /usr/local/etc/monit-redmatic.cfg:8: Program does not exist: '/etc/config/rc.d/redmatic'
2020-11-23T18:07:28+01:00 test-ccu-raspimatic-pi4b.fritz.box monit: /usr/local/etc/monit-redmatic.cfg:20: Program does not exist: '/usr/local/addons/redmatic/bin/monit-du'
2020-11-23T18:07:28+01:00 test-ccu-raspimatic-pi4b.fritz.box monit: A 'check program' statement requires the program to exist '/usr/local/addons/redmatic/bin/monit-du'
2020-11-23T17:07:29+01:00 test-ccu-raspimatic-pi4b.fritz.box : process '/usr/bin/monit -Ic /etc/monitrc' (pid 1236) exited. Scheduling for restart.
2020-11-23T17:07:29+01:00 test-ccu-raspimatic-pi4b.fritz.box : starting pid 1239, tty '/dev/null': '/usr/bin/monit -Ic /etc/monitrc'
2020-11-23T18:07:29+01:00 test-ccu-raspimatic-pi4b.fritz.box monit: /usr/local/etc/monit-redmatic.cfg:6: Program does not exist: '/etc/config/rc.d/redmatic'
2020-11-23T18:07:29+01:00 test-ccu-raspimatic-pi4b.fritz.box monit: /usr/local/etc/monit-redmatic.cfg:7: Program does not exist: '/etc/config/rc.d/redmatic'
2020-11-23T18:07:29+01:00 test-ccu-raspimatic-pi4b.fritz.box monit: /usr/local/etc/monit-redmatic.cfg:8: Program does not exist: '/etc/config/rc.d/redmatic'
2020-11-23T18:07:29+01:00 test-ccu-raspimatic-pi4b.fritz.box monit: /usr/local/etc/monit-redmatic.cfg:20: Program does not exist: '/usr/local/addons/redmatic/bin/monit-du'
2020-11-23T18:07:29+01:00 test-ccu-raspimatic-pi4b.fritz.box monit: A 'check program' statement requires the program to exist '/usr/local/addons/redmatic/bin/monit-du'
2020-11-23T17:07:30+01:00 test-ccu-raspimatic-pi4b.fritz.box : process '/usr/bin/monit -Ic /etc/monitrc' (pid 1239) exited. Scheduling for restart.
Erst durch löschen von /usr/local/etc/monit-redmatic.cfg und Reboot war Ruhe.
Dann konnte ich auch ccu-historian und ccu-ack über den Monit beenden. Und die Zentrale flimmerte dann mehr oder weniger ohne AddOns.
Gebracht hat auch der Safe Mode nichts. Das Ding will einfach nicht mehr.
7. Beobachtung des Patienten
Momentan ist das letzte Backup auf einer .ova RM 3.53.34.20201121 ohne Funkmodul eingespielt. Normal gebootet und die AddOns händisch deaktiviert. Was im Log zu sehen ist verheißt nichts gutes.
Code: Alles auswählen
2020-11-25T17:12:53+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1037]: 'ReGaHss' process is not running
2020-11-25T17:12:53+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1037]: 'ReGaHss' trying to restart
2020-11-25T17:12:53+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1037]: 'ReGaHss' restart: '/etc/init.d/S70ReGaHss restart'
2020-11-25T17:13:04+01:00 test-ccu-raspimatic-pi4b.fritz.box kernel: [ 233.684774] ReGaHss[1640]: segfault at f6e14eec ip 00000000f7a54c34 sp 00000000f6e14e80 error 6 in libc-2.31.so[f7a10000+14b000]
2020-11-25T17:13:04+01:00 test-ccu-raspimatic-pi4b.fritz.box kernel: [ 233.684786] Code: e9 fa fe ff ff 90 55 89 e5 57 e8 a8 67 0d 00 81 c7 e7 e3 17 00 56 53 81 ec dc 04 00 00 8b 75 08 8b 87 f8 fe ff ff 80 7e 46 00 <89> 85 84
fb ff ff 65 8b 00 89 85 80 fb ff ff 75 20 8b 97 d8 fe ff
2020-11-25T17:13:14+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1037]: 'ReGaHss' service restarted 1 times within 1 cycles(s) - exec
2020-11-25T17:13:14+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1037]: 'ReGaHss' process is not running
2020-11-25T17:13:14+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1037]: 'ReGaHss' trying to restart
2020-11-25T17:13:14+01:00 test-ccu-raspimatic-pi4b.fritz.box monit[1037]: 'ReGaHss' restart: '/etc/init.d/S70ReGaHss restart'
2020-11-25T17:13:25+01:00 test-ccu-raspimatic-pi4b.fritz.box kernel: [ 254.556977] ReGaHss[1702]: segfault at f6db4eec ip 00000000f7a03c34 sp 00000000f6db4e80 error 6 in libc-2.31.so[f79bf000+14b000]
2020-11-25T17:13:25+01:00 test-ccu-raspimatic-pi4b.fritz.box kernel: [ 254.556990] Code: e9 fa fe ff ff 90 55 89 e5 57 e8 a8 67 0d 00 81 c7 e7 e3 17 00 56 53 81 ec dc 04 00 00 8b 75 08 8b 87 f8 fe ff ff 80 7e 46 00 <89> 85 84
fb ff ff 65 8b 00 89 85 80 fb ff ff 75 20 8b 97 d8 fe ff
Warum mein Testsystem die Hufe hochgerissen hat kann ich nicht erklären. Das ganze ist schon etwas ärgerlich aber zu verschmerzen. Dadurch das alles separat mit dem SDV gebackupped wurde hält sich der Rekonstruktionsaufwand für mich zum Glück in Grenzen.
Was ich hingegen nicht verstehe ist, warum alle meine Backups (bis auf das Uralte) anscheinend korrumpiert sind.
Das Ursprungssystem lief ja bis zum Zeitpunkt des ReGaHss-Absturzes ohne Auffälligkeiten und ließ sich auch immer problemlos updaten.
Die Probleme mit dem Safe Mode sind eher ein separates Thema das wohl am besten direkt in den entsprechenden Unterforen / GitHub besprochen wird.
Und falls nun jemand mit lesen hier angekommen ist und die entscheidende Frage vermisst hat... hier kommt sie.
Geht da noch was zu retten