CCU bleibt bei RPCState inactive

michael.schefczyk · 28 Januar 2024, 15:04:49

Liebe Alle,

mein FHEM möchte ich gern von einem RaspberryPi 4 auf einen RaspberryPi 5 umziehen. Das funktioniert - mit Ausnahme der Einbindung meiner CCU3. Die CCU3 ist ein reguläres Exemplar, das bisher schon eingebunden war. Anders als bei diesem Thread https://forum.fhem.de/index.php?topic=108853 liegt es bei mir nicht an Login-Daten, da die Authentifizierung beim XML-RPC API ausgeschaltet ist.

Wenn ich auf dem alten System ein Backup mache, das alte System stoppe und auf dem neuen System das Backup einspiele, lässt sich das neue System starten. Die Voraussetzungen dort liegen vor, insbesondere ist librpc-xml-perl installiert. Alle anderen Dienste von FHEM arbeiten.

Allerdings friert das WEB UI der Homematic CCU3 erst einmal ein und dann gibt es bei FHEM offenbar timeouts.

Bei den RPC-Servern wird angezeigt:

CCU RPC BidCos-RF inactive/OK
CCU RPC HmIP-RF running/OK

im Log liest man:

2024.01.28 14:15:25 2: HMCCURPCPROC [d_rpc001083BidCos_RF] RPC server not running

Ein Lösungsversuch bestand darin, die RPC-Server und die CCU3 zu löschen und neu einzurichten.

Man kommt dann allerdings zum gleichen Ergebnis. Bei der CCU3 wird angezeigt:

PLATFORM rpi3 2024-01-28 14:20:58
PRODUCT ccu3 2024-01-28 14:20:58
VERSION 3.73.9 2024-01-28 14:20:58
count_channels 495 2024-01-28 14:20:58
count_devices 87 2024-01-28 14:20:58
count_groups 8 2024-01-28 14:20:58
count_interfaces 3 2024-01-28 14:20:58
count_programs 11 2024-01-28 14:20:58
rpcstate inactive 2024-01-28 14:21:08
state Initialized 2024-01-28 14:21:08

Das Log deutet m. E. erneut auf Timeouts hin:

2024.01.28 14:22:03 2: HMCCU [ccu] RPC server start: 3 started, 0 already running, 0 failed to start
2024.01.28 14:22:03 2: HMCCURPCPROC [d_rpc001083BidCos_RF] Callback server CB2001001080001083 created. Listening on port 7411
2024.01.28 14:22:03 2: HMCCURPCPROC [d_rpc001083BidCos_RF] CB2001001080001083 accepting connections. PID=1039193
2024.01.28 14:22:03 2: HMCCURPCPROC [d_rpc001083BidCos_RF] RPC server CB2001001080001083 enters server loop
2024.01.28 14:22:03 2: HMCCURPCPROC [d_rpc001083BidCos_RF] Registering callback http://192.168.1.80:7411/fh2001 of type A with ID CB2001001080001083 at http://192.168.1.83:2001
2024.01.28 14:22:03 2: HMCCURPCPROC [d_rpc001083VirtualDevices] Callback server CB9292001080001083 created. Listening on port 14702
2024.01.28 14:22:03 2: HMCCURPCPROC [d_rpc001083VirtualDevices] CB9292001080001083 accepting connections. PID=1039194
2024.01.28 14:22:03 2: HMCCURPCPROC [d_rpc001083HmIP_RF] Callback server CB2010001080001083 created. Listening on port 7420
2024.01.28 14:22:03 2: HMCCURPCPROC [d_rpc001083HmIP_RF] CB2010001080001083 accepting connections. PID=1039195
2024.01.28 14:25:03 2: HMCCURPCPROC [d_rpc001083BidCos_RF] RPC request init failed: RPC::XML::Client::simple_request: RPC::XML::Client::send_request: HTTP server error: read timeout
2024.01.28 14:25:03 2: HMCCURPCPROC [d_rpc001083BidCos_RF] Retrying request init
2024.01.28 14:28:04 2: HMCCURPCPROC [d_rpc001083BidCos_RF] RPC request init failed: RPC::XML::Client::simple_request: RPC::XML::Client::send_request: HTTP server error: read timeout
2024.01.28 14:28:04 2: HMCCURPCPROC [d_rpc001083BidCos_RF] Retrying request init
2024.01.28 14:28:04 1: HMCCURPCPROC [d_rpc001083BidCos_RF] Failed to register callback for ID CB2001001080001083: RPC request init failed: RPC::XML::Client::simple_request: RPC::XML::Client::send_request: HTTP server error: read timeout

Stoppen und neu starten lässt sich die ccu3 in FHEM dann auch nicht wirklich. Auf das Attribut zum Aus- und Einschalten der RPC-Server erfolgt keine wirkliche Reaktion. Das ccu-Device kann man nicht stoppen, weil dann angezeigt wird: HMCCU: ccu Stop of RPC server failed

Versteht jemand, wo die Timeouts passieren und wie man sie verhindern kann bzw. was man sonst tun muss, um FHEM auf einen neuen Server zu migrieren?

Danke

Michael Schefczyk

zap · 28 Januar 2024, 20:52:43

Firewall der CCU?
HTTPS auf der CCU aktiv?

Sind Attribute bei HMCCU oder HMCCURPCPROC Devices gesetzt (keine FHEM Standard Attribute) ?

michael.schefczyk · 31 Januar 2024, 07:00:41

Danke ZAP!

Der Zugriff auf die gleiche CCU3 von meinem Rasbperry Pi 4 mit 32 bit architektur (arhmhf) funktioniert problemlos. Nach Backup und Restore geht es mit der unveränderten CCU3 vom Raspberry Pi 5 nicht - es kommt dann zu den Timeouts.

Bei der CCU3 ist die Firewall-Richtlinie "Ports offen" Der Zugriff ist eingeschränkt, umfasst aber die IP-Adressen 192.168.0.0/16 und damit alle Geräte in meinem LAN. Das Kreuz bei "Umleitung auf HTTPS aktiv" ist nicht gesetzt.

Meine Homematic IP-Geräte sind HMCCUDEV. Ein Gerät ist HMCCUCHN. Es sind auch Philips Hue-Geräte verbunden - soll ich die aus dem System entfernen?

Die Attribute sind m. E. Standard:

Bei HMCCU:
- ccuaggregate (umfassender Text)
- ccudef-substitute AES_KEY!(0|false):off,(1|true):on;;LOWBAT,LOW_BAT!(0|false):ok,(1|true):low;;UNREACH!(0|false):alive,(1|true):dead;;MOTION!(0|false):noMotion, (1|true):motion;;DIRECTION!0:stop,1:up,2:down,3:undefined;;WORKING!0:false,1:true;;INHIBIT!(0|false):unlocked,(1|true):locked
- ccuflags procrpc
- event-on-change-reading .*
- rpcinterfaces BidCos-RF,HmIP-RF
- rpcserver on
- stateFormat rpcstate/state
- stripnumber 1

Bei HMCCURPCPROC:
- alias
- eventMap /rpcserver on:on/rpcserver off:off/
- stateFormat rpcstate/state
- verbose 2

passibe · 31 Januar 2024, 14:58:53

Kannst du dich per SSH auf die ccu einloggen und mal das CCU-Log mitlesen (zu dem Zeitpunkt wo die Timeouts passieren)? Eventuell steht dort ja etwas erhellendes ...

michael.schefczyk · 01 Februar 2024, 07:55:01

Danke passibe!

Das Log kann ich via SSH und via Webmin lesen. Ich habe es noch einmal ausprobiert. Das Ergebnis ist ein Log wie in meiner e-Mail vom 28.01.2024:

HMCCURPCPROC [d_rpc ... BidCos_RF] Failed to register callback for ID ...: RPC request init failed: RPC::XML::Client::simple_request: RPC::XML::Client::send_request: HTTP server error: read timeout

Auf mich wirkt es so, als würde das Timeout auf der CCU3 selbst erfolgen. Während das Problem entsteht, kann man dort das Webinterface nicht vollständig erreichen. In der Mitte des Bildschirms bleibt ein Homematic-Logo mit weißem Hintergrund stehen, das man sonst nach dem Login nur ganz kurz sieht.

Muss ich das vorher dort angemeldete FHEM-System auf der CCU3 vorher in irgendeiner Weise deregistrieren/abmelden? Mir ist nur eingefallen, das vorher verwendete FHEM-System auszuschalten und die CCU3 neu zu starten. Das bringt aber nichts. Kann das Problem mit der 64-Bit-Architektur des Raspberry Pi 3 zu tun haben?

zap · 01 Februar 2024, 20:58:06

Das ist der FHEM Log. Gibts Fehler im CCU Log /var/log/messages ?

passibe · 02 Februar 2024, 14:47:34

Eventuell auch noch /var/log/hmserver.log überprüfen ...

michael.schefczyk · 04 Februar 2024, 19:27:48

Sorry, im zweiten Anlauf habe ich nun die Logs auf der CCU3 selbst angeschaut. Nochmals vielen Dank an zap und passible!

Auf meinem alten System (Raspi 4) habe ich noch einmal ein Backup gemacht und auf dem neuen System (Raspi 5) wieder entpackt. Im ersten Schritt habe ich fhem auf dem alten System mit systemctl stop fhem gestoppt und dann wieder gestartet. Danach gibt es keine Auffälligkeiten bei /var/log/messages. Man sieht dort lediglich die ssh-Verbindung. Bei /var/log/hmserver.log gibt es eine Auffälligkeit & auch hier friert das Web UI der CCU3 beim Start eine Zeitlang ein:

2024-02-04 19:09:24,458 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO [vert.x-eventloop-thread-0] getDeviceDescription: Found no matching device description for address HU-Hue Play 1
2024-02-04 19:09:24,465 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO [vert.x-eventloop-thread-0] getDeviceDescription: Found no matching device description for address HU-Hue Play 2
2024-02-04 19:09:24,472 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO [vert.x-eventloop-thread-0] getDeviceDescription: Found no matching device description for address HU-Hue Play 3
2024-02-04 19:09:24,478 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO [vert.x-eventloop-thread-0] getDeviceDescription: Found no matching device description for address HU-Hue Play 4
2024-02-04 19:09:24,487 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO [vert.x-eventloop-thread-0] getDeviceDescription: Found no matching device description for address HU-Hue Play 5

Die Brücke zur Philips Hue benötige ich eigentlich nicht. Wahrscheinlich sollte ich die Verbindung und alle Devices einmal löschen, um das Problem aus der Welt zu haben. Vielleicht ist die Hue-Verbindung auch nicht für Backup und Restore geeignet.

Wenn ich danach das alte System stoppe und das neue System starte, gibt es keine Auffälligkeiten in den Logs: Nichts bei /var/log/messages und alle 5 Minuten einen Eintrag bei /var/log/hmserver.log
2024-02-04 19:16:01,036 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO [vert.x-eventloop-thread-7] SYSTEM: 0 Accesspoints in Queue
2024-02-04 19:16:01,036 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO [vert.x-eventloop-thread-7] SYSTEM: Permanent-/Burstlistener Handler utilization: 0/50 used
2024-02-04 19:16:01,037 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO [vert.x-eventloop-thread-7] SYSTEM: Eventlistener Handler utilization: 0/50 used
2024-02-04 19:21:01,036 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO [vert.x-eventloop-thread-7] SYSTEM: 0 Accesspoints in Queue
2024-02-04 19:21:01,037 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO [vert.x-eventloop-thread-7] SYSTEM: Permanent-/Burstlistener Handler utilization: 0/50 used
2024-02-04 19:21:01,037 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO [vert.x-eventloop-thread-7] SYSTEM: Eventlistener Handler utilization: 0/50 used

Es bliebt "nur" das Problem bestehen, dass CCU RPC BidCos-RF meldet "inactive/OK"

Das alte System muss man doch nicht stärker bei de CCU3 deregistrieren oder abmelden oder diese neu starten, oder?

Mein erster Schritt wird sein, die Verbindung zu Hue zu entfernen. Gibt es weitere Ratschläge? Sollte ich versuchen, anstelle eines Raspberry Pi 5 noch einmal einen Raspberry Pi 4 neu aufzusetzen, um diesbezügliche Risiken auszuschließen?

P.S: Wenn man das neue System stoppt, erscheint bei /var/log/hmserver.log noch (obwohl BidCos-RF doch inactive war):
2024-02-04 19:26:42,320 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO [vert.x-worker-thread-2] (un)registerCallback on LegacyServiceHandler called from url: http://192.168.1.80:7420/fh2010
2024-02-04 19:26:42,322 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO [vert.x-worker-thread-2] Removed InterfaceId: CB2010001080001083

P.P.S: Das Entfernen der nicht benötigten Hue-Integration - bei der einige virtuelle Geräte nur mit einem Skript gelöscht werden können - erzeugt keinen Unterschied.

Einige weitere Abschnitte aus dem hmserver.log

nach dem Start von FHEM auf dem neuen Raspberry Pi 5

2024-02-04 22:38:34,802 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO [vert.x-worker-thread-4] (un)registerCallback on LegacyServiceHandler called from url: http://192.168.1.80:7420/fh2010
2024-02-04 22:38:34,808 de.eq3.cbcs.legacy.bidcos.rpc.internal.LegacyBackendNotificationHandler INFO [CB2010001080001083_WorkerPool-0] SYSTEM: LegacyBackendNotificationHandler Verticle or Worker started
2024-02-04 22:38:34,811 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO [CB2010001080001083_WorkerPool-0] init finished
2024-02-04 22:38:34,811 de.eq3.cbcs.legacy.bidcos.rpc.internal.InterfaceInitializer INFO [vert.x-worker-thread-0] Added InterfaceId: CB2010001080001083

at io.vertx.core.impl.WorkerContext.lambda$emit$0(WorkerContext.java:59) ~[HMIPServer.jar:?]
at io.vertx.core.impl.WorkerContext$$Lambda$199/0x69505a28.handle(Unknown Source) ~[?

]
at io.vertx.core.impl.WorkerContext.lambda$execute$2(WorkerContext.java:104) ~[HMIPServer.jar:?]
at io.vertx.core.impl.WorkerContext$$Lambda$200/0x69505228.run(Unknown Source) ~[?

]
at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76) ~[HMIPServer.jar:?]
at io.vertx.core.impl.TaskQueue$$Lambda$116/0x6a7ef228.run(Unknown Source) ~[?

]
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[?

]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[?

]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[HMIPServer.jar:?]
at java.lang.Thread.run(Unknown Source) ~[?

]
at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:144) ~[HMIPServer.jar:?]
at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:134) ~[HMIPServer.jar:?]
at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:612) ~[HMIPServer.jar:?]
at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:447) ~[HMIPServer.jar:?]
at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:884) ~[HMIPServer.jar:?]
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82) ~[HMIPServer.jar:?]
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:107) ~[HMIPServer.jar:?]
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:55) ~[HMIPServer.jar:?]
at de.eq3.cbcs.legacy.communication.rpc.internal.transport.http.HttpTransport.sendRequest(HttpTransport.java:106) ~[HMIPServer.jar:?]
... 15 more

Danach bleiben die CCU und CCU RPC BidCos-RF inactive/busy

Wenn man das neue System stoppt und das alte wieder startet, funktioniert wieder alles prima - nur schafft man so leider eben keine Migration.

passibe · 05 Februar 2024, 00:17:59

Danke für die Logs!
Beim Googeln nach der letzten Logzeile vor der Fehlermeldung habe ich folgendes gefunden: https://forum.fhem.de/index.php?topic=127965.msg1224408#msg1224408

Vielleicht ist es ja das und du hast beim Umziehen was bei den IP Adressen verwechselt. Wenn das nicht hilft, gib uns mal bitte ein list aller involvierten Devices.
Klingt ja irgendwie doch nach einem FHEM-seitigen Konfigurationsproblem ...

michael.schefczyk · 05 Februar 2024, 19:22:06

Meinen Fehler habe ich entdeckt - es handelte sich um ein Firewallproblem.

Geöffnet hatte ich die Ports:
- 2001/tcp
- 2010/tcp
-> Die werden offenbar für die rpcserver benötigt und zwar tcp und nicht udp - korrekt?

Übersehen hatte ich aber den Port:
- 7411/tcp
-> Wenn man den auch noch öffnet, funktioniert alles.

Vielen Dank für die Hilfe auf dem Weg!!

michael.schefczyk · 07 Februar 2024, 12:13:47

Eine Nachfrage habe ich noch: Die Freigabe nur der oben bezeichneten Ports genügt nicht, damit das System die Daten aktualisiert. Wenn man die Firewall ausschaltet, funktioniert alles.

Gibt es eine Dokumentation, welche Ports erforderlich sind? Kandiaten sind wohl
- 80/tcp ??
- 2001/udp (nicht nur tcp oder nur udp)
- 2010/udp (nicht nur tcp oder nur udp)
- 7420/tcp

Danke!

passibe · 07 Februar 2024, 12:23:37

Welche Firewall verwendest du denn? UFW schreibt ja z.B. abgelehnte Pakete ins syslog. Würde mir die Firewall logs nehmen und mich einfach daran abarbeiten. Oder halt mit tcpdump/Wireshark mitlesen.
Mir reicht 7420/tcp, aber ich benutze auch nur HmIP-RF ...