Probleme mit CCU-Historian im Zusammenspiel mit CL-Studio seit Update 3.71.12.20231014 und später

[snirk]

Hallo,

seit dem Oktoberupdate 3.71.12.20231014 hat meine RaspberryMatic Probleme nach dem Neustart die zusammenhängen mit CCU-Historian und dem Addon CL-Studio (Homeputer, Firma CL-Control, aktuell V4.34).

Im Log von CCU-Historian finden sich folgende Einträge zu Exceptions, die auftreten:

Code: Alles auswählen

2024-03-11 12:21:27|INFO   |Starting base services
2024-03-11 12:21:28|INFO   |Connecting to database
2024-03-11 12:21:47|INFO   |Starting database web server
2024-03-11 12:21:47|INFO   |Setting up device 1
2024-03-11 12:21:47|INFO   |Creating HM script client for http://127.0.0.1:8181/tclrega.exe
2024-03-11 12:21:47|INFO   |Setting up plug-in 1
2024-03-11 12:21:47|INFO   |Configured following interfaces: BidCos-RF, HmIP-RF, SysVar, CUxD
2024-03-11 12:21:47|INFO   |Starting interfaces
2024-03-11 12:21:47|INFO   |Starting BIN-RPC server on port 2099
2024-03-11 12:21:47|INFO   |Starting XML-RPC server on port 2098
2024-03-11 12:21:47|SEVERE |Exception: Server returned HTTP response code: 503 for URL: http://127.0.0.1:2001
2024-03-11 12:21:47|SEVERE |Detail: java.io.IOException: Server returned HTTP response code: 503 for URL: http://127.0.0.1:2001
	at mdz.hc.itf.hm.HmXmlRpcClient.init(HmXmlRpcClient.groovy:55)
	at mdz.hc.itf.hm.HmXmlRpcInterface.init(HmXmlRpcInterface.groovy:123)
	at mdz.hc.itf.hm.HmXmlRpcInterface$_start_closure1.doCall(HmXmlRpcInterface.groovy:78)
	at mdz.hc.itf.hm.HmXmlRpcInterface$_start_closure1.doCall(HmXmlRpcInterface.groovy)
	at mdz.Exceptions.lambda$0(Exceptions.java:84)
	at mdz.Exceptions.catchToLog(Exceptions.java:74)
	at mdz.Exceptions.catchToLog(Exceptions.java:84)
	at mdz.hc.itf.hm.HmXmlRpcInterface.start(HmXmlRpcInterface.groovy:78)
	at mdz.hc.itf.Manager$_start_closure1.doCall(Manager.groovy:58)
	at mdz.hc.itf.Manager.start(Manager.groovy:56)
	at mdz.ccuhistorian.HistorianSystem.<init>(HistorianSystem.groovy:39)
	at mdz.ccuhistorian.Main.start(Main.groovy:100)
	at mdz.ccuhistorian.Main$_run_closure4.doCall(Main.groovy:77)
	at mdz.ccuhistorian.Main$_run_closure4.doCall(Main.groovy)
	at mdz.Exceptions.lambda$0(Exceptions.java:84)
	at mdz.Exceptions.catchToLog(Exceptions.java:74)
	at mdz.Exceptions.catchToLog(Exceptions.java:84)
	at mdz.ccuhistorian.Main.run(Main.groovy:77)
	at mdz.ccuhistorian.Main.main(Main.groovy:45)
2024-03-11 12:21:47|SEVERE |Exception: Server returned HTTP response code: 503 for URL: http://127.0.0.1:2010
2024-03-11 12:21:47|SEVERE |Detail: java.io.IOException: Server returned HTTP response code: 503 for URL: http://127.0.0.1:2010
	at mdz.hc.itf.hm.HmXmlRpcClient.init(HmXmlRpcClient.groovy:55)
	at mdz.hc.itf.hm.HmXmlRpcInterface.init(HmXmlRpcInterface.groovy:123)
	at mdz.hc.itf.hm.HmXmlRpcInterface$_start_closure1.doCall(HmXmlRpcInterface.groovy:78)
	at mdz.hc.itf.hm.HmXmlRpcInterface$_start_closure1.doCall(HmXmlRpcInterface.groovy)
	at mdz.Exceptions.lambda$0(Exceptions.java:84)
	at mdz.Exceptions.catchToLog(Exceptions.java:74)
	at mdz.Exceptions.catchToLog(Exceptions.java:84)
	at mdz.hc.itf.hm.HmXmlRpcInterface.start(HmXmlRpcInterface.groovy:78)
	at mdz.hc.itf.Manager$_start_closure1.doCall(Manager.groovy:58)
	at mdz.hc.itf.Manager.start(Manager.groovy:56)
	at mdz.ccuhistorian.HistorianSystem.<init>(HistorianSystem.groovy:39)
	at mdz.ccuhistorian.Main.start(Main.groovy:100)
	at mdz.ccuhistorian.Main$_run_closure4.doCall(Main.groovy:77)
	at mdz.ccuhistorian.Main$_run_closure4.doCall(Main.groovy)
	at mdz.Exceptions.lambda$0(Exceptions.java:84)
	at mdz.Exceptions.catchToLog(Exceptions.java:74)
	at mdz.Exceptions.catchToLog(Exceptions.java:84)
	at mdz.ccuhistorian.Main.run(Main.groovy:77)
	at mdz.ccuhistorian.Main.main(Main.groovy:45)
2024-03-11 12:21:47|INFO   |Connecting to 127.0.0.1:8701
2024-03-11 12:21:47|INFO   |Starting historian
2024-03-11 12:21:48|INFO   |Starting web server
2024-03-11 12:21:48|INFO   |Logging initialized @23877ms to org.eclipse.jetty.util.log.JavaUtilLog
2024-03-11 12:21:48|INFO   |jetty-9.4.53.v20231009; built: 2023-10-09T12:29:09.265Z; git: 27bde00a0b95a1d5bbee0eae7984f891d2d0f8c9; jvm 11.0.22+7-LTS
2024-03-11 12:21:48|INFO   |NO JSP Support for /, did not find org.eclipse.jetty.jsp.JettyJspServlet
2024-03-11 12:21:48|INFO   |DefaultSessionIdManager workerName=node0
2024-03-11 12:21:48|INFO   |No SessionScavenger set, using defaults
2024-03-11 12:21:48|INFO   |node0 Scavenging every 600000ms
2024-03-11 12:21:48|INFO   |Started o.e.j.w.WebAppContext@1a0f349{CCU-Historian Web Application,/,file:///usr/local/addons/ccu-historian/ccu-historian/webapp/,AVAILABLE}
2024-03-11 12:21:48|INFO   |Started ServerConnector@6818fd48{HTTP/1.1, (http/1.1)}{0.0.0.0:8082}
2024-03-11 12:21:48|INFO   |Started @24410ms
2024-03-11 12:21:48|INFO   |Web server port: 8082
2024-03-11 12:21:51|SEVERE |Exception: Server returned HTTP response code: 503 for URL: http://127.0.0.1:8181/tclrega.exe
2024-03-11 12:21:51|SEVERE |Detail: java.io.IOException: Server returned HTTP response code: 503 for URL: http://127.0.0.1:8181/tclrega.exe
	at mdz.hc.itf.hm.HmScriptClient.execute(HmScriptClient.groovy:360)
	at mdz.hc.itf.hm.HmScriptClient.retrieveDevices(HmScriptClient.groovy:216)
	at mdz.hc.itf.hm.HmScriptClient.getModel(HmScriptClient.groovy:305)
	at mdz.hc.itf.hm.HmXmlRpcInterface.updateLogicProperties(HmXmlRpcInterface.groovy:135)
	at mdz.hc.itf.hm.HmXmlRpcInterface.updateProperties(HmXmlRpcInterface.groovy:244)
	at mdz.hc.itf.Manager$_updateProperties_closure4.doCall(Manager.groovy:121)
	at mdz.hc.itf.Manager.updateProperties(Manager.groovy:118)
	at mdz.ccuhistorian.Historian.update(Historian.groovy:157)
	at mdz.ccuhistorian.Historian$_updateDataPointMeta_closure4$_closure13.doCall(Historian.groovy:115)
	at mdz.ccuhistorian.Historian$_updateDataPointMeta_closure4$_closure13.doCall(Historian.groovy)
	at mdz.Exceptions.lambda$0(Exceptions.java:84)
	at mdz.Exceptions.catchToLog(Exceptions.java:74)
	at mdz.Exceptions.catchToLog(Exceptions.java:84)
	at mdz.ccuhistorian.Historian$_updateDataPointMeta_closure4.doCall(Historian.groovy:111)
	at mdz.ccuhistorian.Historian.updateDataPointMeta(Historian.groovy:110)
	at mdz.ccuhistorian.Historian$_run_closure3.doCall(Historian.groovy:104)
	at mdz.ccuhistorian.Historian$_run_closure3.doCall(Historian.groovy)
	at mdz.Exceptions.lambda$0(Exceptions.java:84)
	at mdz.Exceptions.catchToLog(Exceptions.java:74)
	at mdz.Exceptions.catchToLog(Exceptions.java:84)
	at mdz.ccuhistorian.Historian.run(Historian.groovy:103)
2024-03-11 12:21:51|SEVERE |Exception: Server returned HTTP response code: 503 for URL: http://127.0.0.1:8181/tclrega.exe
2024-03-11 12:21:51|SEVERE |Detail: java.io.IOException: Server returned HTTP response code: 503 for URL: http://127.0.0.1:8181/tclrega.exe
	at mdz.hc.itf.hm.HmScriptClient.execute(HmScriptClient.groovy:360)
	at mdz.hc.itf.hm.HmScriptClient.retrieveDevices(HmScriptClient.groovy:216)
	at mdz.hc.itf.hm.HmScriptClient.getModel(HmScriptClient.groovy:305)
	at mdz.hc.itf.hm.HmXmlRpcInterface.updateLogicProperties(HmXmlRpcInterface.groovy:135)
	at mdz.hc.itf.hm.HmXmlRpcInterface.updateProperties(HmXmlRpcInterface.groovy:244)
	at mdz.hc.itf.Manager$_updateProperties_closure4.doCall(Manager.groovy:121)
	at mdz.hc.itf.Manager.updateProperties(Manager.groovy:118)
	at mdz.ccuhistorian.Historian.update(Historian.groovy:157)
	at mdz.ccuhistorian.Historian$_updateDataPointMeta_closure4$_closure13.doCall(Historian.groovy:115)
	at mdz.ccuhistorian.Historian$_updateDataPointMeta_closure4$_closure13.doCall(Historian.groovy)
	at mdz.Exceptions.lambda$0(Exceptions.java:84)
	at mdz.Exceptions.catchToLog(Exceptions.java:74)
	at mdz.Exceptions.catchToLog(Exceptions.java:84)
	at mdz.ccuhistorian.Historian$_updateDataPointMeta_closure4.doCall(Historian.groovy:111)
	at mdz.ccuhistorian.Historian.updateDataPointMeta(Historian.groovy:110)
	at mdz.ccuhistorian.Historian$_run_closure3.doCall(Historian.groovy:104)
	at mdz.ccuhistorian.Historian$_run_closure3.doCall(Historian.groovy)
	at mdz.Exceptions.lambda$0(Exceptions.java:84)
	at mdz.Exceptions.catchToLog(Exceptions.java:74)
	at mdz.Exceptions.catchToLog(Exceptions.java:84)
	at mdz.ccuhistorian.Historian.run(Historian.groovy:103)
2024-03-11 12:21:51|SEVERE |Exception: Server returned HTTP response code: 503 for URL: http://127.0.0.1:8181/tclrega.exe
2024-03-11 12:21:51|SEVERE |Detail: java.io.IOException: Server returned HTTP response code: 503 for URL: http://127.0.0.1:8181/tclrega.exe
	at mdz.hc.itf.hm.HmScriptClient.execute(HmScriptClient.groovy:360)
	at mdz.hc.itf.hm.HmScriptClient.getSystemVariables(HmScriptClient.groovy:60)
	at mdz.hc.itf.hm.HmSysVarInterface.getCache(HmSysVarInterface.groovy:79)
	at mdz.hc.itf.hm.HmSysVarInterface.getAllDataPoints(HmSysVarInterface.groovy:140)
	at mdz.ccuhistorian.Historian.browse(Historian.groovy:125)
	at mdz.ccuhistorian.Historian$_updateDataPointMeta_closure4$_closure13.doCall(Historian.groovy:113)
	at mdz.ccuhistorian.Historian$_updateDataPointMeta_closure4$_closure13.doCall(Historian.groovy)
	at mdz.Exceptions.lambda$0(Exceptions.java:84)
	at mdz.Exceptions.catchToLog(Exceptions.java:74)
	at mdz.Exceptions.catchToLog(Exceptions.java:84)
	at mdz.ccuhistorian.Historian$_updateDataPointMeta_closure4.doCall(Historian.groovy:111)
	at mdz.ccuhistorian.Historian.updateDataPointMeta(Historian.groovy:110)
	at mdz.ccuhistorian.Historian$_run_closure3.doCall(Historian.groovy:104)
	at mdz.ccuhistorian.Historian$_run_closure3.doCall(Historian.groovy)
	at mdz.Exceptions.lambda$0(Exceptions.java:84)
	at mdz.Exceptions.catchToLog(Exceptions.java:74)
	at mdz.Exceptions.catchToLog(Exceptions.java:84)
	at mdz.ccuhistorian.Historian.run(Historian.groovy:103)

Prinzipiell funktioniert CCU-Historian, aber es werden z.B. keine Systemvariablen aufgezeichnet.

Deinstalliere ich CL-Studio, treten keine Fehler beim Start von CCU-Historian auf, zumindest bei ersten Tests. Das Fehlerbild scheint prinzipiell mal mit CL-Studio zusammen zu hängen.

Wenn ich CCU-Historian nach den Fehlermeldungen im Log in der Bash stoppe und neu starte, treten keine Fehlermeldungen mehr auf beim Hochfahren von CCU-Historian. Ein verzögerter Start von CCU-Historian würde das Problem wohl umgehen. In dem Fall werden dann auch wieder Systemvariablen von CCU-Historian in der DB aufgezeichnet.

Scheinbar gibt es hier Timing-Probleme beim Start der CCU und den installierten anderen Komponenten.

Für ca. zwei Wochen lief alles auch ohne Probleme und stabil mit der Nov-Version 3.73.9.20231130 (ich hatte ein Fallback gemacht von 3.73.9.20240130), dies wurde dann aber durch einen Stromausfall zunichte gemacht, der die DB von CCU-Historian zerschossen hat. Nach dem Einspielen DB-Sicherung der Nacht vorher konnte ich diesen fehlerfreien/stabilen Zustand nicht mehr herstellen und reproduzieren.

Nachdem ich die Probleme nicht beseitigen konnte musste ich wieder ein Fallback auf die August-Version 3.71.12.20230826 machen, damit läuft alles fehlerfrei. Von Versionen der anderen Komponenten (CCU-Historian und CL-Studio) scheint das Fehlerbild unabhängig.

Möglicherweise hängen die Probleme mit folgenden Changelog-Eintrag zur Version 3.71.12.20231014 zusammen:

"lighttpd startup/config wurde so geändert, dass der Statuscode "503 Service unavailable" zurückgegeben wird, wenn der CCU-Start noch nicht abgeschlossen ist. Dies sollte mögliche Laufzeitprobleme verhindern, falls externe Engines wie ioBroker oder HomeAssistant versuchen, remoteAPI-Ports zu verwenden, wenn nicht alle CCU-Dienste ordnungsgemäß gestartet sind. Außerdem lassen wir jetzt nur noch bestimmte Abfrage-URLs für Port 8181/48181 zu."

Kennt jemand diese Problematik und weiẞ was zu tun ist?
Gibt es für CCU-Historian Parameter, an denen man in der Config schrauben kann?

Bitte keine Vorschläge wie CCU-Historian auf eine andere Hardware zu verlegen etc, sondern (einfache) Workarounds oder konkrete Hinweise, ohne alles komplett umzubauen.

Danke und Grüsse

[Mathias]

In neueren RaspberryMatic Versionen ist der Zugriff auf die Schnittstellenprozesse während des Hochfahrens der CCU nicht mehr möglich. Die Fehlermeldungen sollten nach ein paar Minuten nicht mehr auftreten, und der CCU-Historian dann normal arbeiten.

Siehe auch Beitrag unter RaspberryMatic.

Den CCU-Historian kann ich aber anpassen, sodass er auf die Verfügbarkeit der Prozesse wartet.

[snirk]

das wäre sehr gut CCU-Historian entsprechend anzupassen.

Trotz umfangreicher Recherche habe ich keine Lösung für dieses Problem gefunden.

Prinzipiell startet CCU-Historian ja auch, und es scheint auch zu arbeiten, aber es werden z.B. keine Systemvariablen in der DB aufgezeichnet, das war das erste, was mir aufgefallen war.

Meine Vermutung ist dass dies mit den Exceptions zusammenhängt, die mit dem geänderten Startverhalten von RM zusammenhängen.

Abhilfe schafft eben momentan einfach nur CCU-Historian händisch zu stoppen und wieder zu starten, was keine dauerhafte Lösung ist.

[Baxxy]

Ich denke es kommt nur in bestimmten AddOn-Konstellationen zu Problemen.
Ich habe hier 3 Systeme (1x Live, 2x Test) auf denen Historian problemlos lauft.

[Mathias]

Die Fehlermeldung konnte ich ebenfalls nicht reproduzieren.

In neueren RaspberryMatic Versionen ist der Zugriff auf die Schnittstellenprozesse während des Hochfahrens der CCU nicht mehr möglich. Davon ist der CCU-Historian aber nicht betroffen, weil Add-Ons als letztes gestartet.

Die Ursache für Dein Problem ist also weiterhin unklar.

[Baxxy]

weil Add-Ons als letztes gestartet

Hmm,
in S99SetupLEDs wird S50lighttpd reload ausgeführt um den lighttpd mit freigegeben Ports zu reloaden.
Das kommt aber nach S98StartAddons.

[snirk]

Die Fehlermeldung konnte ich ebenfalls nicht reproduzieren.

In neueren RaspberryMatic Versionen ist der Zugriff auf die Schnittstellenprozesse während des Hochfahrens der CCU nicht mehr möglich. Davon ist der CCU-Historian aber nicht betroffen, weil Add-Ons als letztes gestartet.

Die Ursache für Dein Problem ist also weiterhin unklar.

Das Problem lässt sich aber eindeutig bei mir reproduzieren, es ist permanent da.

Falls ich in irgendeinerweise bei der Analyse unterstützen kann, wenn Du Logs braucht, Konfigurationsdateien, etc... einfach Bescheid geben.

Ich besitze eine zweite fast identische Zentrale zum Testen (statt Pi4 ein Pi5, 3.75.6.20240316, sonst alles gleich), bei der dieses Verhalten auftritt, für den Fall dass nicht reversible Tests vorgenommen werden sollen.

Weitere Addons, die in meiner Zentrale installiert sind, falls es hilft: CUx-Daemon, CuXd-Highcharts (gehört ja zu CCU-Historian), E-Mail, XML-API).

Ich könnte mir auch vorstellen, dass das Problem verschwindet wenn ich nicht CL-Studio deinstalliere, sondern ein anderes Addon. Ich vermute dass es sich in meiner Konfiguration einfach um eine ungünstige Konstellation handelt, bzw. event. irgendwelche Timing-Probleme. Für ca. zwei Wochen lief ja zwischendrin nach mehreren Switches zwischen den RM-Versionen meine Zentrale auch ohne Probleme mit 3.73.9.20231130 bis zu dem Stromausfall.

Mit dem Entwickler von CL-Studio hatte ich schon Kontakt und hatte Tests im Startverhalten CL-Studio vorgenommmen, dies hatte kein Erfolg gebracht.

Vielleicht hast Du ja auch einen Tipp für mich, wie ich den Start von CCU-Historian durch manuellen Eingriff testweise verzögern kann, denn wenn ich CCU-Historian später manuell stoppe und wieder starte, dann kommen keine Exceptions mehr und funktioniert (Systemvariablen werden dann auch wieder aufgezeichnet).

[Mathias]

in S99SetupLEDs wird S50lighttpd reload ausgeführt um den lighttpd mit freigegeben Ports zu reloaden.
Das kommt aber nach S98StartAddons.

Danke, so genau habe ich nicht nachgeschaut.

Dann ist aber wiederum eine andere Erklärung möglich:

In der Regel benötigt der CCU-Historian einige Sekunden um zu starten. Bis dahin ist die Firewall offen. Das funktioniert aber nur, wenn nach dem CCU-Historian keine anderen Add-Ons das Öffnen der Firewall weiter verzögern. Ich nehme daher an, dass CL-Studio nach dem Historian gestartet wird.

Eine einfache Startverzögerung in der Datei /usr/local/etc/config/rc.d/ccu-historian hilft nicht. Da dadurch auch der Start der nachfolgenden Add-Ons verzögert wird.

Lösung: RaspberryMatic startet die Add-Ons erst, wenn die Firewall offen ist. Ich mache dazu mal einen Eintrag auf GitHub.

Trotzdem sollten die Gerätedatenpunkte nach ein paar Minuten aufgezeichnet werden. Ansonsten müsstest Du mal eine Log-Datei zur Verfügung stellen. Das Vorgehen bitte hier und hier nachlesen.

[snirk]

Lösung: RaspberryMatic startet die Add-Ons erst, wenn die Firewall offen ist. Ich mache dazu mal einen Eintrag auf GitHub.

Danke. Wäre schön wenn das den Fehler behebt, sonst werde ich weiterhin auf 3.71.12.20230826 bleiben müssen.

Trotzdem sollten die Gerätedatenpunkte nach ein paar Minuten aufgezeichnet werden. Ansonsten müsstest Du mal eine Log-Datei zur Verfügung stellen. Das Vorgehen bitte hier und hier nachlesen.

Gerätedatenpunkte werden auch normal aufgezeichnet, das ist kein Problem. Nur Systemvariablen, zumindest meine Selbsterstellten eben nicht, aber gerade die sind wichtig für mich in der Aufzeichnung. Das Problem bleibt dauerhaft und behebt sich leider nicht nach ein paar Minuten. Nur ein manueller Stop und Start von CCU-Historian hilft hier dann.

Ich werde die CCU-Historian-Konfig für Logging mal auf

Code: Alles auswählen

logSystem.fileLevel=Level.FINEST  
logSystem.binRpcLevel=Level.FINER  
logSystem.fileLimit=10000000

stellen und meine Testzentrale ein bis zwei Stunden laufen lassen.

[Baxxy]

Wenn du fit auf der ssh-Konsole bist kannst du testweise die Boot-Portsperre "aushebeln".

Du brauchst eine ausführbare:

Code: Alles auswählen

/usr/local/etc/rc.prelocal

Da rein kommt:

Code: Alles auswählen

#!/bin/sh
touch /var/status/startupFinished

Dadurch startet der Webserver direkt ohne gesperrte Ports, also so wie früher. Weil er denkt der Bootprozess ist abgeschlossen.
Kannst du ja mal testen.
Rückgängig machen dann durch löschen der /usr/local/etc/rc.prelocal oder auskommentieren des Inhalts.