RFD-Restart: Lösungsfindung mittels Fehlerprotokoll

[Vyrus_0711]

Hallo alle zusammen,

mein Watchdog hat heute Nacht einen RFD-Restart lokalisiert und das Fehlerprotokoll sieht wie folgt aus:

Code: Alles auswählen

Dec  3 01:19:05 Proxmox-Raspberrymatic kern.info kernel: [719062.383073] rfd[1472]: segfault at 15 ip 0000000000000015 sp 00000000fff2beec error 14 in rfd[8048000+a000] likely on CPU 0 (core 0, socket 0)
Dec  3 01:19:05 Proxmox-Raspberrymatic kern.info kernel: [719062.383097] Code: Unable to access opcode bytes at 0xffffffffffffffeb.
Dec  3 01:19:05 Proxmox-Raspberrymatic local0.err ReGaHss: ERROR: XmlRpc: Error in XmlRpcClient::readHeader: error while reading header (error 104) on fd 6. [error():iseXmlRpc.h:281]
Dec  3 01:19:05 Proxmox-Raspberrymatic local0.warn ReGaHss: WARNING: XMLRPC 'setValue': rpcClient.execute() failed (url: xmlrpc_bin://127.0.0.1:32001, params: {"LEQ0571511:1","PRESS_SHORT",false}, result: nil) [CallXmlrpcMethod():iseXmlRpc.cpp:2612]
Dec  3 01:19:05 Proxmox-Raspberrymatic local0.err ReGaHss: ERROR: XMLRPC 'setValue' call failed (interface: 1034, params: {"LEQ0571511:1","PRESS_SHORT",false}) [CallSetValue():iseXmlRpc.cpp:1515]
Dec  3 01:19:05 Proxmox-Raspberrymatic local0.err ReGaHss: ERROR: rpc.CallSetValue failed; address = LEQ0571511:1 [WriteValue():iseDOMdpHSS.cpp:76]
Dec  3 01:19:05 Proxmox-Raspberrymatic local0.err ReGaHss: ERROR: ScriptRuntimeError: var debug=dom.GetObject("SysVar_SYSTEM_Debug"); debug.State("Programm gestartet: Prog_AA-Garage_Licht: 2. Bedingung"); [ExecError():iseESPexec.cpp:12907]
Dec  3 01:19:05 Proxmox-Raspberrymatic kern.info kernel: [719062.390318] eq3loop: eq3loop_close_slave() mmd_bidcos
Dec  3 01:19:19 Proxmox-Raspberrymatic user.err monit[1703]: 'rfd' process is not running
Dec  3 01:19:19 Proxmox-Raspberrymatic user.info monit[1703]: 'rfd' trying to restart
Dec  3 01:19:19 Proxmox-Raspberrymatic user.info monit[1703]: 'rfd' restart: '/etc/init.d/S61rfd restart'
Dec  3 01:19:19 Proxmox-Raspberrymatic kern.info kernel: [719076.565558] eq3loop: eq3loop_open_slave() mmd_bidcos
Dec  3 01:19:21 Proxmox-Raspberrymatic local0.warn ReGaHss: WARNING: XMLRPC 'setValue': rpcClient.isFault() failed (url: xmlrpc://127.0.0.1:32010, params: {"00259BE995BE9D:18","STATE",true}, result: [faultCode:-1,faultString:"Generic error (UNREACH)"]) [CallXmlrpcMethod():iseXmlRpc.cpp:2618]
Dec  3 01:19:21 Proxmox-Raspberrymatic local0.err ReGaHss: ERROR: XMLRPC 'setValue' call failed (interface: 1035, params: {"00259BE995BE9D:18","STATE",true}) [CallSetValue():iseXmlRpc.cpp:1515]
Dec  3 01:19:21 Proxmox-Raspberrymatic local0.err ReGaHss: ERROR: rpc.CallSetValue failed; address = 00259BE995BE9D:18 [WriteValue():iseDOMdpHSS.cpp:76]
Dec  3 01:19:27 Proxmox-Raspberrymatic local0.warn ReGaHss: WARNING: XMLRPC 'setValue': rpcClient.isFault() failed (url: xmlrpc://127.0.0.1:32010, params: {"00259BE995BE9D:14","STATE",true}, result: [faultCode:-1,faultString:"Generic error (UNREACH)"]) [CallXmlrpcMethod():iseXmlRpc.cpp:2618]
Dec  3 01:19:27 Proxmox-Raspberrymatic local0.err ReGaHss: ERROR: XMLRPC 'setValue' call failed (interface: 1035, params: {"00259BE995BE9D:14","STATE",true}) [CallSetValue():iseXmlRpc.cpp:1515]
Dec  3 01:19:27 Proxmox-Raspberrymatic local0.err ReGaHss: ERROR: rpc.CallSetValue failed; address = 00259BE995BE9D:14 [WriteValue():iseDOMdpHSS.cpp:76]
Dec  3 01:19:39 Proxmox-Raspberrymatic user.err monit[1703]: 'rfd' service restarted 1 times within 1 cycles(s) - exec
Dec  3 01:19:39 Proxmox-Raspberrymatic user.info monit[1703]: 'rfd' exec: '/bin/triggerAlarm.tcl rfd restarted WatchDog: rfd-restart true'
Dec  3 01:19:39 Proxmox-Raspberrymatic user.info monit[1703]: 'rfd' process is running with pid 29793
Dec  3 01:19:39 Proxmox-Raspberrymatic user.info monit[1703]: 'rfd' process is running after previous restart timeout (manually recovered?)

Folgende Informationen zu dem Fehlerprotokoll habe ich für Euch.

Dieser Fehler wurde von mir bereits behoben (falsche Bezeichnung der Systemvariablen):

Code: Alles auswählen

Dec  3 01:19:05 Proxmox-Raspberrymatic local0.err ReGaHss: ERROR: ScriptRuntimeError: var debug=dom.GetObject("SysVar_SYSTEM_Debug"); debug.State("Programm gestartet: Prog_AA-Garage_Licht: 2. Bedingung"); [ExecError():iseESPexec.cpp:12907]

LEQ0571511:1 ist ein Funk-Wandtaster 2-fach (HM-PB-2-WM55):

Code: Alles auswählen

Dec  3 01:19:05 Proxmox-Raspberrymatic local0.err ReGaHss: ERROR: XMLRPC 'setValue' call failed (interface: 1034, params: {"LEQ0571511:1","PRESS_SHORT",false}) [CallSetValue():iseXmlRpc.cpp:1515]

00259BE995BE9D:18 ist ein Schaltaktor 4-fach (HmIP-DRSI4):

Code: Alles auswählen

Dec  3 01:19:21 Proxmox-Raspberrymatic local0.err ReGaHss: ERROR: XMLRPC 'setValue' call failed (interface: 1035, params: {"00259BE995BE9D:18","STATE",true}) [CallSetValue():iseXmlRpc.cpp:1515]

Was hat den restart hervorgerufen?
Wie kann ich das Problem eingrenzen / finden / lösen und natürlich beheben?

Vielen Dank im voraus für Eure Unterstützung!


Gruß
Vyrus_0711

[jmaus]

Was hat den restart hervorgerufen?
Wie kann ich das Problem eingrenzen / finden / lösen und natürlich beheben?

Du kannst da selbst gar nichts beheben und ich bzw das RaspberryMatic Projekt auch nicht. Wie man an den folgenden Zeilen erkennen kann ist der rfd Dienst (der die BidCos-RF Kommunikation managed) einfach mal in einen Bug gerannt bzw ist abgeschmiert:

Code: Alles auswählen

Dec  3 01:19:05 Proxmox-Raspberrymatic kern.info kernel: [719062.383073] rfd[1472]: segfault at 15 ip 0000000000000015 sp 00000000fff2beec error 14 in rfd[8048000+a000] likely on CPU 0 (core 0, socket 0)
Dec  3 01:19:05 Proxmox-Raspberrymatic kern.info kernel: [719062.383097] Code: Unable to access opcode bytes at 0xffffffffffffffeb.

und folgerichtig hat sich dann der WatchDog darum gekümmert das der rfd auch prompt wieder gestartet wird damit alles wieder wie vorher weiterläuft.

Um nun nach der Ursache für diesen Absturz (segfault) in dem rfd Dienst zu suchen müsste man erst einmal schauen/abwarten ob das Problem regelmäßig auftritt bzw reproduzierbar immer durch eine Aktion ausgelöst wird. Dann könnte man mit dieser Info und der "segfault" Info auf eQ3 zugehen damit die im Quellcode von rfd nach der Ursache schauen können, denn der rfd ist leider closed source und daher kann im Rahmen des RaspberryMic Projektes leider kein Bugfixing oder Verbesserungen daran umgesetzt werden und nur eQ3 könnte das beheben.

[Vyrus_0711]

Hallo Jens,

danke für die Antwort!

Mein Watchdog zeigt ca. einmal im Monat diesen Restart an.
Dies ist aber erst seit ca. 1-2 Monaten der Fall, davor kannte ich diese Meldung gar nicht (Sytsem läuft absolut stabil)!

Dieses Phänomen tritt bei mir erst seit Firmware 3.71.12.20230826 (evtl. auch 3.69.7.20230626)
Ich hatte zwischen den genannten Versionen keine weiteren Updates durchgeführt.

Ich werde beim nächsten RFD-Restart die Meldungen abgleichen bzw. hier posten.

Muss ich mir Sorgen machen?

[MichaelN]

Wahrscheinlich ist es dir nicht bewusst, aber durchgängige Schrift in fett oder rot gilt als aggressiv.

[jmaus]

Ja, poste die bitte hier weiter. Vielleicht lässt sich ja ein Pattern erkennen. Auch müsstest du mal schauen ob das immer zur gleichen Zeit bzw. bei einer speziellen Aktion bzw. mit einem speziellen Gerät, etc. passiert und diese Info mit auf den Weg geben.

Weil dann kann ich diese Infos hier gesammelt an meine eQ3 Entwicklerkontakte weiterleiten damit die sich das ggf. mal anschauen können. Und vielleicht tauchen dann hier auch mit der Zeit andere Leidensgenossen auf die diese Abstürze bestätigen können.

[jp112sdl]

Ich werde beim nächsten RFD-Restart die Meldungen abgleichen bzw. hier posten.

Benutzt du Diagramme? Werden die nach einem RFD-Neustart weiterhin aufgezeichnet?

Ich hab noch in Erinnerung, dass die nach einem RFD-Neustart nicht mehr funktionieren, wenn nicht auch zusätzlich der HMIPServer neu gestartet wird.
Der HMIPServer hängt sich beim Start an den RFD um die Events abzufischen. Wenn der RFD neu gestartet wird, erfolgt kein Reconnect. Und das hmserver.log läuft evtl. voll mit Fehlermeldungen, dass der Bidcos Listener keinen Endpunkt mehr hat (oder so ähnlich).

Ich weiß nicht, ob das aktuelle immer noch so ist.

[Vyrus_0711]

Vielen Dank für Eure Informationen!

Benutzt du Diagramme? Werden die nach einem RFD-Neustart weiterhin aufgezeichnet?

Nein, ich verwende keine Diagramme, daher kann ich hierfür keine Antwort geben.

Ja, poste die bitte hier weiter

Ok, werde ich machen.

Wahrscheinlich ist es dir nicht bewusst, aber durchgängige Schrift in fett oder rot gilt als aggressiv.

Nein, war mir nicht bewusst. Ich wollte durch die fette Schrift und die Farbe den Fokus setzen.

Gruß
Vyrus_0711

[Vyrus_0711]

Hallo,

es ist schon wieder passiert.

Wie versprochen der Auszug aus dem Fehlerprotokoll:

Code: Alles auswählen

Dec 19 21:04:09 Proxmox-Raspberrymatic kern.info kernel: [699483.023929] rfd[1472]: segfault at 80 ip 0000000000000080 sp 00000000ffa96b7c error 14 in rfd[8048000+a000] likely on CPU 0 (core 0, socket 0)
Dec 19 21:04:09 Proxmox-Raspberrymatic kern.info kernel: [699483.023962] Code: Unable to access opcode bytes at 0x56.
Dec 19 21:04:09 Proxmox-Raspberrymatic local0.err ReGaHss: ERROR: XmlRpc: Error in XmlRpcClient::readHeader: error while reading header (error 104) on fd 9. [error():iseXmlRpc.h:281]
Dec 19 21:04:09 Proxmox-Raspberrymatic local0.warn ReGaHss: WARNING: XMLRPC 'setValue': rpcClient.execute() failed (url: xmlrpc_bin://127.0.0.1:32001, params: {"LEQ0571511:1","PRESS_SHORT",false}, result: nil) [CallXmlrpcMethod():iseXmlRpc.cpp:2612]
Dec 19 21:04:09 Proxmox-Raspberrymatic local0.err ReGaHss: ERROR: XMLRPC 'setValue' call failed (interface: 1034, params: {"LEQ0571511:1","PRESS_SHORT",false}) [CallSetValue():iseXmlRpc.cpp:1515]
Dec 19 21:04:09 Proxmox-Raspberrymatic local0.err ReGaHss: ERROR: rpc.CallSetValue failed; address = LEQ0571511:1 [WriteValue():iseDOMdpHSS.cpp:76]
Dec 19 21:04:09 Proxmox-Raspberrymatic kern.info kernel: [699483.029072] eq3loop: eq3loop_close_slave() mmd_bidcos
Dec 19 21:04:17 Proxmox-Raspberrymatic user.err monit[1697]: 'rfd' process is not running
Dec 19 21:04:17 Proxmox-Raspberrymatic user.info monit[1697]: 'rfd' trying to restart
Dec 19 21:04:17 Proxmox-Raspberrymatic user.info monit[1697]: 'rfd' restart: '/etc/init.d/S61rfd restart'
Dec 19 21:04:17 Proxmox-Raspberrymatic kern.info kernel: [699490.760474] eq3loop: eq3loop_open_slave() mmd_bidcos
Dec 19 21:04:19 Proxmox-Raspberrymatic local0.warn ReGaHss: WARNING: XMLRPC 'setValue': rpcClient.isFault() failed (url: xmlrpc://127.0.0.1:32010, params: {"00259BE995BE9D:18","STATE",true}, result: [faultCode:-1,faultString:"Generic error (UNREACH)"]) [CallXmlrpcMethod():iseXmlRpc.cpp:2618]
Dec 19 21:04:19 Proxmox-Raspberrymatic local0.err ReGaHss: ERROR: XMLRPC 'setValue' call failed (interface: 1035, params: {"00259BE995BE9D:18","STATE",true}) [CallSetValue():iseXmlRpc.cpp:1515]
Dec 19 21:04:19 Proxmox-Raspberrymatic local0.err ReGaHss: ERROR: rpc.CallSetValue failed; address = 00259BE995BE9D:18 [WriteValue():iseDOMdpHSS.cpp:76]
Dec 19 21:04:37 Proxmox-Raspberrymatic user.err monit[1697]: 'rfd' service restarted 1 times within 1 cycles(s) - exec
Dec 19 21:04:37 Proxmox-Raspberrymatic user.info monit[1697]: 'rfd' exec: '/bin/triggerAlarm.tcl rfd restarted WatchDog: rfd-restart true'
Dec 19 21:04:37 Proxmox-Raspberrymatic user.info monit[1697]: 'rfd' process is running with pid 30025
Dec 19 21:04:37 Proxmox-Raspberrymatic user.info monit[1697]: 'rfd' process is running after previous restart timeout (manually recovered?)

Es könnte mit den Aktoren "LEQ0571511:1" und "00259BE995BE9D:18" zusammenhängen, da Sie in beiden Fällen zu diesem Zeitpunkt im Protokoll erwähnt werden.