HMCCURPC: Multithreaded RPC Server für HMCCU

[zap]

Ich habe gerade ein neues Client Modul für HMCCU eingecheckt (zusammen mit einer neuen Version von HMCCU). Das Modul HMCCURPC stellt einen neuen, Thread basierten RPC-Server für HMCCU zur Verfügung. Die Vorteile:

• Keine Filequeues mehr, dadurch Schonung der SD Karte
• Schnellere Reaktion auf CCU Events durch Verwendung des Standard FHEM I/O Mechanismus. Die Timer basierte Abfrage von CCU Events (konfiguriert über rpcinterval) und die damit einhergehende Verzögerung bei der Reaktion auf Events von einigen Sekunden entfällt.

HINWEIS: DAS MODUL IST NOCH IM BETA STATUS. BENUTZUNG AUF EIGENE GEFAHR! Allerdings läuft es bei mir schon recht stabil.

Das Modul benötigt folgende Perl-Module:

• threads
• Thread::Queue
• Time::HiRes

Zur Verwendung gibt es 2 Möglichkeiten (nach FHEM Update und Neustart):

1. Über das I/O Device (empfohlene Vorgehensweise, Annahme I/O bzw. HMCCU Device = d_ccu). Dabei wird automatisch ein Device mit dem Namen "d_ccu_rpc" vom Typ HMCCURPC angelegt. Dieses Device erbt die Attribute room und group vom I/O Device.

Code Auswählen Erweitern


set d_ccu rpcserver off
attr d_ccu ccuflags extrpc
set d_ccu rpcserver on


2. Über ein manuell definiertes RPC-Device (Annahme I/O Device = d_ccu):

Code Auswählen Erweitern


define d_ccu_rpc HMCCURPC my_ccu_ip_or_name iodev=d_ccu
set d_ccu rpcserver off
attr d_ccu ccuflags extrpc
set d_ccu rpcserver on


Grundsätzlich lässt sich der RPC-Server auch über das HMCCURPC Device starten. Davon rate ich jedoch ab.

Um zum alten integrierten RPC-Server zurückzukehren:

Code Auswählen Erweitern


set d_ccu rpcserver off
attr ccuflags intrpc
set d_ccu rpcserver on


Also: wer möchte bitte mal testen. Wenn das stabil läuft, wird das mittelfristig das Filequeue Verfahren ersetzen.

P.S. Musste einen Trick verwenden, um dem FHEM I/O Prozess die Shared Memory Queue unter zu jubeln, da Threads in FHEM nicht so gern gesehen sind. Optimal wäre, wenn man im I/O Loop von FHEM neben File Descriptoren auch Shared Memory Queues angeben könnte, also statt $hash->{FD} = Descriptor z.B. ein $hash->{TQ} = ThreadQueue. Nur mal so als Denkanstoss

[Raymund]

Teste gerade: läuft. Aber ein rereadcfg führt reproduzierbar zur Endlosschleife mit folgendem Logeintrag:

Code Auswählen Erweitern

2017.03.23 19:25:52 2: CCURPC: I/O error during data processing (select found no reader)

Gruß
Raymund

[zap]

Ist nicht unbedingt eine Endlosschleife. Die Meldung kommt, wenn FHEM beschäftigt ist und keine I/O Operationen ausführen kann. Ich habe gerade ein Update eingecheckt, bei dem die Zahl der Meldungen deutlich reduziert ist. Ggf. werde ich es ganz abschalten, da es eigentlich kein Fehler ist.

Wenn Du Lust hast, kannst Du nach einem rereadcfg einfach mal eine Zeit lang warten ob die Meldungen von alleine aufhören.

UPDATE: Habe rereadconfig noch nie benutzt aber jetzt mal die Commandref gelesen. Übel. Da werden alle Devices gelöscht. Das ist nicht so gut für den laufenden RPC-Server. Ich würde davon abraten, diesen Befehl bei laufendem RPC-Server zu verwenden.

[Raymund]

Läuft jetzt mit der 'alten' Version seit ca. 10 Minuten in der Schleife.

Gruß
Raymund

[zap]

Das fängt sich nicht mehr. Das Problem ist: bei rereadcfg werden die Devices gelöscht. Die RPC Server Threads überstehen das Löschen und versuchen weiterhin, Daten an das HMCCURPC Device zu schicken, das aber nicht mehr existiert. Das funktioniert natürlich nicht und produziert die Fehlermeldung.

Daher: erst RPC Server stoppen. Dann rereadcfg. Ich will aber nicht ausschließen, dass das noch andere Nbeneffekte hat, sogar beim alten RPC Server.

Wozu braucht man eigentlich rereadcfg?

[Raymund]

na, wenn man z.B. die fhem.cfg manuell geändert hat ... mache ich eher selten. War Zufall 😉

Update: ich lese gerade, dass es einen Trigger nach rereadcfg gibt. Vielleicht kann man damit etwas machen. Ich bin nach vielen Jahren in der Entwicklung der Meinung, dass der User damit nicht 'belastet' werden sollte. Oder man entfernt rereadcfg ...

[zap]

Ja, den Trigger gibt es. Allerdings erst nach rereadcf, und dann ist es zu spät.

HMCCU versucht zwar den RPC Server zu stoppen, wenn das Device gelöscht wird. Allerdings läuft dieses Stoppen asynchron in eine separaten Thread/Prozess, d.h. das Device Löschen wartet nicht, bis der RPC Server gestoppt ist. Daher das "Chaos".

Ich sehe keine Möglichkeit, da verlässlich einzugreifen.

[Raymund]

Hallo zap,

wollte Dir aber mal sagen, dass Du hier einen tollen Job machst. Und jetzt wird der RPCServer auch noch schnell ... 

Danke und Grüße
Raymund

[Loredo]

Super klasse, danke für diesen wichtigen Schritt! 

Hatte einige Freezes bei dem vorgehen, was du als Möglichkeit 1 beschreibst:

2017.03.25 09:20:44.906 2: HMCCURPC: RPC server thread started for interface HmIP-RF with TID=3
2017.03.25 09:20:45.169 2: HMCCURPC: Callback server CB2010 created. Listening on port 7420
2017.03.25 09:20:45.169 2: HMCCURPC: Adding callback for events for server CB2010
2017.03.25 09:20:45.169 2: HMCCURPC: Adding callback for new devices for server CB2010
2017.03.25 09:20:45.169 2: HMCCURPC: Adding callback for deleted devices for server CB2010
2017.03.25 09:20:45.169 2: HMCCURPC: Adding callback for modified devices for server CB2010
2017.03.25 09:20:45.169 2: HMCCURPC: Adding callback for replaced devices for server CB2010
2017.03.25 09:20:45.169 2: HMCCURPC: Adding callback for readded devices for server CB2010
2017.03.25 09:20:45.169 2: HMCCURPC: Adding callback for list devices for server CB2010
2017.03.25 09:20:45.170 2: CCURPC: CB2010 accepting connections. TID=3
2017.03.25 09:21:19.961 2: HMCCURPC: RPC server thread started for interface VirtualDevices with TID=4
2017.03.25 09:21:19.961 2: CCURPC: Initializing RPC server CB9292 for interface VirtualDevices
2017.03.25 09:21:20.126 2: HMCCURPC: Callback server CB9292 created. Listening on port 14702
2017.03.25 09:21:20.126 2: HMCCURPC: Adding callback for events for server CB9292
2017.03.25 09:21:20.126 2: HMCCURPC: Adding callback for new devices for server CB9292
2017.03.25 09:21:20.126 2: HMCCURPC: Adding callback for deleted devices for server CB9292
2017.03.25 09:21:20.126 2: HMCCURPC: Adding callback for modified devices for server CB9292
2017.03.25 09:21:20.126 2: HMCCURPC: Adding callback for replaced devices for server CB9292
2017.03.25 09:21:20.126 2: HMCCURPC: Adding callback for readded devices for server CB9292
2017.03.25 09:21:20.126 2: HMCCURPC: Adding callback for list devices for server CB9292
2017.03.25 09:21:20.127 2: CCURPC: CB9292 accepting connections. TID=4
2017.03.25 09:21:20.962 1: HMCCURPC: RPC server(s) starting
2017.03.25 09:21:21.291 1: Perfmon: possible freeze starting at 09:20:03, delay is 78.291
2017.03.25 09:21:31.348 1: HMCCURPC: Received SL event. RPC server DATA enters server loop
2017.03.25 09:21:31.348 1: HMCCURPC: Received SL event. RPC server CB2001 enters server loop
2017.03.25 09:21:31.349 1: HMCCURPC: Received SL event. RPC server CB2010 enters server loop
2017.03.25 09:21:31.349 1: HMCCURPC: Received SL event. RPC server CB9292 enters server loop
2017.03.25 09:21:31.349 1: HMCCURPC: All threads working
2017.03.25 09:21:31.349 1: HMCCURPC: Registering callback http://192.168.178.2:7411/fh2001 with ID CB2001 at http://192.168.6.31:2001/
2017.03.25 09:21:31.361 1: CCURPC: CB2001 ListDevices. Sending init to HMCCU
2017.03.25 09:21:31.623 1: HMCCURPC: RPC callback with URL http://192.168.178.2:7411/fh2001 registered
2017.03.25 09:21:31.623 1: HMCCURPC: Registering callback http://192.168.178.2:7420/fh2010 with ID CB2010 at http://192.168.6.31:2010/
2017.03.25 09:21:31.652 1: HMCCURPC: RPC callback with URL http://192.168.178.2:7420/fh2010 registered
2017.03.25 09:21:31.652 1: HMCCURPC: Registering callback http://192.168.178.2:14702/fh9292 with ID CB9292 at http://192.168.6.31:9292/groups
2017.03.25 09:21:32.009 2: CCURPC: CB2001 NewDevice received 156 device specifications
2017.03.25 09:21:32.194 1: CCURPC: CB2010 ListDevices. Sending init to HMCCU
2017.03.25 09:21:32.201 1: CCURPC: CB9292 ListDevices. Sending init to HMCCU
2017.03.25 09:21:32.318 2: CCURPC: CB9292 NewDevice received 9 device specifications
2017.03.25 09:21:41.693 1: HMCCURPC: RPC callback with URL http://192.168.178.2:14702/fh9292 registered
2017.03.25 09:21:41.693 1: HMCCURPC: Received IN event. RPC server CB2001 running.
2017.03.25 09:21:41.698 1: Perfmon: possible freeze starting at 09:21:22, delay is 19.698
2017.03.25 09:21:43.293 1: HMCCURPC: Received IN event. RPC server CB2010 running.
2017.03.25 09:21:43.293 1: HMCCURPC: Received IN event. RPC server CB9292 running.
2017.03.25 09:21:43.293 1: HMCCURPC: All RPC servers running
2017.03.25 09:21:44.173 2: HMCCURPC: Updated devices. Success=24 Failed=0
2017.03.25 09:21:46.272 1: Perfmon: possible freeze starting at 09:21:45, delay is 1.272
2017.03.25 09:21:59.595 1: Perfmon: possible freeze starting at 09:21:57, delay is 2.595
2017.03.25 09:28:58.032 1: Perfmon: possible freeze starting at 09:28:54, delay is 3.788
2017.03.25 09:29:02.283 1: Perfmon: possible freeze starting at 09:28:59, delay is 3.283

[zap]

Habe mich mit Perfmon noch nicht beschäftigt. Heißt das, dass sich FHEM nicht mehr bedienen lässt? Bei mir läuft alles performant.

Kann sein, dass der erste Start etwas holprig ist, weil erst das Device definiert werden muss. Das sollte bei weiteren Starts besser laufen, da es ja gespeichert wird.

Außerdem musst Du bedenken, dass nach dem Start des RPC-Servers alle Datenpunkte von der CCU geholt und aktualisiert werden. Je nach Anzahl Devices kann das auch 1-3 Sekunden dauern.

[Loredo]

Habe mich mit Perfmon noch nicht beschäftigt. Heißt das, dass sich FHEM nicht mehr bedienen lässt?

Ja, 78 Sekunden ging gar nix mehr.

Kann sein, dass der erste Start etwas holprig ist, weil erst das Device definiert werden muss. Das sollte bei weiteren Starts besser laufen, da es ja gespeichert wird.

Der heutige Neustart lief soweit ok ab.
Diese Meldung ist mir aufgefallen:

2017.03.26 11:41:23.932 2: HMCCURPC: Starting thread for data processing
2017.03.26 11:41:24.141 2: HMCCURPC: Started thread for data processing. TID=1
2017.03.26 11:41:24.141 2: CCURPC: Thread DATA processing RPC events. TID=1
2017.03.26 11:41:26.569 2: HMCCURPC: RPC server thread started for interface BidCos-RF with TID=2
2017.03.26 11:41:26.569 2: CCURPC: Initializing RPC server CB2001 for interface BidCos-RF
2017.03.26 11:41:29.015 2: HMCCURPC: Callback server CB2001 created. Listening on port 7411
2017.03.26 11:41:29.015 2: HMCCURPC: Adding callback for events for server CB2001
2017.03.26 11:41:29.015 2: HMCCURPC: Adding callback for new devices for server CB2001
2017.03.26 11:41:29.015 2: HMCCURPC: Adding callback for deleted devices for server CB2001
2017.03.26 11:41:29.016 2: HMCCURPC: Adding callback for modified devices for server CB2001
2017.03.26 11:41:29.016 2: HMCCURPC: Adding callback for replaced devices for server CB2001
2017.03.26 11:41:29.016 2: HMCCURPC: Adding callback for readded devices for server CB2001
2017.03.26 11:41:29.016 2: HMCCURPC: Adding callback for list devices for server CB2001
2017.03.26 11:41:29.016 2: CCURPC: CB2001 accepting connections. TID=2
2017.03.26 11:41:31.157 2: CCURPC: I/O error during data processing (Select found no reader)
2017.03.26 11:41:37.470 2: HMCCURPC: RPC server thread started for interface HmIP-RF with TID=3
2017.03.26 11:41:37.470 2: CCURPC: Initializing RPC server CB2010 for interface HmIP-RF
2017.03.26 11:41:37.482 2: HMCCURPC: Callback server CB2010 created. Listening on port 7420
2017.03.26 11:41:37.482 2: HMCCURPC: Adding callback for events for server CB2010
2017.03.26 11:41:37.482 2: HMCCURPC: Adding callback for new devices for server CB2010
2017.03.26 11:41:37.482 2: HMCCURPC: Adding callback for deleted devices for server CB2010
2017.03.26 11:41:37.482 2: HMCCURPC: Adding callback for modified devices for server CB2010
2017.03.26 11:41:37.482 2: HMCCURPC: Adding callback for replaced devices for server CB2010
2017.03.26 11:41:37.482 2: HMCCURPC: Adding callback for readded devices for server CB2010
2017.03.26 11:41:37.482 2: HMCCURPC: Adding callback for list devices for server CB2010

[zap]

Die Meldung werde ich abschalten. Ursache: Wenn FHEM mit etwas anderem beschäftigt ist und eine Zeit lang keine I/O Operation ausführen kann, schlägt HMCCURPC seitig das Senden der I/O Notification an FHEM fehl.

Das ist jedoch nicht kritisch, da HMCCURPC intern die Daten puffert und es ein paar Millisekunden später einfach noch mal versucht. Kritisch wird es erst, wenn die Meldung "CCURPC: Size of event queue exceeds ..." kommt. Dann ist nämlich die maximale Puffergröße erreicht und es werden CCU Events verworfen. Falls das mal vorkommt, kann man die Größe der Queue mit dem Attribut rpcQueueSize erhöhen.

BTW: Bin selbst von der schnellen Reaktion des Moduls auf CCU Events überrascht. Aktuell gibt es bei mir eine durchschnittliche Verzögerung zwischen Empfang der Daten durch den RPC-Server und Verarbeitung durch FHEM von 0.18 Sekunden. Scheint mir akzeptabel zu sein

[Loredo]

Die Schnelligkeit ist in der Tat nun super! 

[Chris8888]

Hallo Zap,

ich habe heute mal ein Update durchgeführt.
Ebenfalls habe ich die 3 Module per CPAN nachinstalliert und das Attribute für den neuen RPC-Server gesetzt.

So sieht das Startlog aus:

Code Auswählen Erweitern

2017.03.27 18:45:37 2: HMCCURPC: Starting thread for data processing
2017.03.27 18:45:38 2: HMCCURPC: Started thread for data processing. TID=1
2017.03.27 18:45:38 2: CCURPC: Thread DATA processing RPC events. TID=1
2017.03.27 18:45:39 2: HMCCURPC: RPC server thread started for interface BidCos-RF with TID=2
2017.03.27 18:45:39 2: CCURPC: Initializing RPC server CB2001 for interface BidCos-RF
2017.03.27 18:45:39 2: HMCCURPC: Callback server CB2001 created. Listening on port 7411
2017.03.27 18:45:39 2: HMCCURPC: Adding callback for events for server CB2001
2017.03.27 18:45:39 2: HMCCURPC: Adding callback for new devices for server CB2001
2017.03.27 18:45:39 2: HMCCURPC: Adding callback for deleted devices for server CB2001
2017.03.27 18:45:39 2: HMCCURPC: Adding callback for modified devices for server CB2001
2017.03.27 18:45:39 2: HMCCURPC: Adding callback for replaced devices for server CB2001
2017.03.27 18:45:39 2: HMCCURPC: Adding callback for readded devices for server CB2001
2017.03.27 18:45:39 2: HMCCURPC: Adding callback for list devices for server CB2001
2017.03.27 18:45:39 2: CCURPC: CB2001 accepting connections. TID=2
2017.03.27 18:45:40 2: HMCCURPC: RPC server thread started for interface HmIP-RF with TID=3
2017.03.27 18:45:40 2: CCURPC: Initializing RPC server CB2010 for interface HmIP-RF
2017.03.27 18:45:40 2: HMCCURPC: Callback server CB2010 created. Listening on port 7420
2017.03.27 18:45:40 2: HMCCURPC: Adding callback for events for server CB2010
2017.03.27 18:45:40 2: HMCCURPC: Adding callback for new devices for server CB2010
2017.03.27 18:45:40 2: HMCCURPC: Adding callback for deleted devices for server CB2010
2017.03.27 18:45:40 2: HMCCURPC: Adding callback for modified devices for server CB2010
2017.03.27 18:45:40 2: HMCCURPC: Adding callback for replaced devices for server CB2010
2017.03.27 18:45:40 2: HMCCURPC: Adding callback for readded devices for server CB2010
2017.03.27 18:45:40 2: HMCCURPC: Adding callback for list devices for server CB2010
2017.03.27 18:45:40 2: CCURPC: CB2010 accepting connections. TID=3
2017.03.27 18:45:41 1: HMCCURPC: RPC server(s) starting
2017.03.27 18:45:41 1: HMCCURPC: Received SL event. RPC server DATA enters server loop
2017.03.27 18:45:41 1: HMCCURPC: Received SL event. RPC server CB2001 enters server loop
2017.03.27 18:45:41 1: HMCCURPC: Received SL event. RPC server CB2010 enters server loop
2017.03.27 18:45:41 1: HMCCURPC: All threads working
2017.03.27 18:45:41 1: HMCCURPC: Registering callback http://192.168.100.35:7411/fh2001 with ID CB2001 at http://192.168.100.65:2001/
2017.03.27 18:45:41 1: CCURPC: CB2001 ListDevices. Sending init to HMCCU
2017.03.27 18:45:42 1: HMCCURPC: RPC callback with URL http://192.168.100.35:7411/fh2001 registered
2017.03.27 18:45:42 1: HMCCURPC: Registering callback http://192.168.100.35:7420/fh2010 with ID CB2010 at http://192.168.100.65:2010/
2017.03.27 18:45:42 1: HMCCURPC: RPC callback with URL http://192.168.100.35:7420/fh2010 registered
2017.03.27 18:45:42 1: HMCCURPC: Received IN event. RPC server CB2001 running.
2017.03.27 18:45:42 1: CCURPC: CB2010 ListDevices. Sending init to HMCCU
2017.03.27 18:45:42 2: CCURPC: CB2001 NewDevice received 52 device specifications
2017.03.27 18:45:43 2: CCURPC: CB2010 NewDevice received 93 device specifications
2017.03.27 18:45:45 1: HMCCURPC: Received IN event. RPC server CB2010 running.
2017.03.27 18:45:45 1: HMCCURPC: All RPC servers running
2017.03.27 18:45:46 2: HMCCURPC: Updated devices. Success=11 Failed=0

Soweit sieht es erst einmal gut aus.

Das Device "HMCCURPC" ist running/ok, aber der HMCCU ist immer running/busy.
Ist das richtig so?

Auch bekomme ich bei einigen HmIP-Kommandos folgende Fehlermeldung: zB
2017.03.27 19:03:43 1: HMCCUDEV: HM_Thermostat_Wohnzimmer Execution of CCU script or command failed

Die CCU2 habe ich heute ebenfalls auf 2.27.8 upgedatet (ganz frisch draussen).

Viele Grüße
Christian

[zap]

Dass das I/O Device auf "running/busy" stehen bleibt, ist leider noch ein (kosmetischer) Fehler.
Wenn die Readings der einzelnen Devices automatisch aktualisiert werden ist alles OK. Das Log sieht jedenfalls gut aus.

Für das Device mit der Fehlermeldung kannst Du vielleicht mal ccuflags auf trace setzen. Dann gibt es mehr Infos im Log.

[Chris8888]

Hi,

die Readings werden leider nicht aktualisiert.
Auch kommt ein "Connection lost, retry in 5 seconds" in der FHEM-GUI sobald ich ein Hm-IP-Device anspreche.

Hier das Log von meinem Thermostat nachdem ich in der GUI die Temparatur von 19 auf 20° verstellt habe:

Code Auswählen Erweitern

2017.03.27 19:13:00 1: HMCCUDEV: HM_Thermostat_HWR Execution of CCU script or command failed
2017.03.27 19:30:35 2: HMCCUDEV: Addr=000A9569A3A519:1 Name=HmIP-WTH-2 000A9569A3A519:1
2017.03.27 19:30:35 2: HMCCUDEV: Script response =
<xml><exec>/do.exe</exec><sessionId></sessionId><httpUserAgent>User-Agent: fhem</httpUserAgent><r1>false</r1></xml>
2017.03.27 19:30:35 2: HMCCUDEV: Script =
http://192.168.100.65:8181/do.exe?r1=dom.GetObject("HmIP-RF.000A9569A3A519:1.SET_POINT_TEMPERATURE").State(20.0)
2017.03.27 19:30:35 2: HMCCU: GetAttrSubstitute: subst = SET_POINT_TEMPERATURE!#0-12.0:off,#23.0-40:on;WINDOW_STATE!(0|false):closed,(1|true):open;LOW_BAT!(0|false):ok,(1|true):low
2017.03.27 19:30:35 2: HMCCU: HM_Thermostat_Wohnzimmer Devlist = 000A9569A3A519
2017.03.27 19:30:35 2: HMCCU: HM_Thermostat_Wohnzimmer Objects = 000A9569A3A519
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, chnadd=000A9569A3A519:0, dpt=UNREACH, value=0
2017.03.27 19:30:35 2: HMCCU: FilterReading rm=1, r=.*, dpt=UNREACH chnflt=.* chnnam=Thermostat-Wohnzimmer:0
2017.03.27 19:30:35 2: HMCCU: FilterReading Check 1 = 1 AND UNREACH = .* OR 1 = 0 AND UNREACH = .*
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, readings=0.UNREACH, orgvalue=0 value=0
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, chnadd=000A9569A3A519:0, dpt=LOW_BAT, value=0
2017.03.27 19:30:35 2: HMCCU: FilterReading rm=1, r=.*, dpt=LOW_BAT chnflt=.* chnnam=Thermostat-Wohnzimmer:0
2017.03.27 19:30:35 2: HMCCU: FilterReading Check 1 = 1 AND LOW_BAT = .* OR 1 = 0 AND LOW_BAT = .*
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, readings=0.LOW_BAT, orgvalue=0 value=ok
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, chnadd=000A9569A3A519:0, dpt=RSSI_DEVICE, value=-42
2017.03.27 19:30:35 2: HMCCU: FilterReading rm=1, r=.*, dpt=RSSI_DEVICE chnflt=.* chnnam=Thermostat-Wohnzimmer:0
2017.03.27 19:30:35 2: HMCCU: FilterReading Check 1 = 1 AND RSSI_DEVICE = .* OR 1 = 0 AND RSSI_DEVICE = .*
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, readings=0.RSSI_DEVICE, orgvalue=-42 value=-42
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, chnadd=000A9569A3A519:0, dpt=OPERATING_VOLTAGE, value=2.9
2017.03.27 19:30:35 2: HMCCU: FilterReading rm=1, r=.*, dpt=OPERATING_VOLTAGE chnflt=.* chnnam=Thermostat-Wohnzimmer:0
2017.03.27 19:30:35 2: HMCCU: FilterReading Check 1 = 1 AND OPERATING_VOLTAGE = .* OR 1 = 0 AND OPERATING_VOLTAGE = .*
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, readings=0.OPERATING_VOLTAGE, orgvalue=2.9 value=2.9
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, chnadd=000A9569A3A519:0, dpt=DUTY_CYCLE, value=0
2017.03.27 19:30:35 2: HMCCU: FilterReading rm=1, r=.*, dpt=DUTY_CYCLE chnflt=.* chnnam=Thermostat-Wohnzimmer:0
2017.03.27 19:30:35 2: HMCCU: FilterReading Check 1 = 1 AND DUTY_CYCLE = .* OR 1 = 0 AND DUTY_CYCLE = .*
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, readings=0.DUTY_CYCLE, orgvalue=0 value=0
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, chnadd=000A9569A3A519:0, dpt=RSSI_PEER, value=-43
2017.03.27 19:30:35 2: HMCCU: FilterReading rm=1, r=.*, dpt=RSSI_PEER chnflt=.* chnnam=Thermostat-Wohnzimmer:0
2017.03.27 19:30:35 2: HMCCU: FilterReading Check 1 = 1 AND RSSI_PEER = .* OR 1 = 0 AND RSSI_PEER = .*
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, readings=0.RSSI_PEER, orgvalue=-43 value=-43
2017.03.27 19:30:35 2: HMCCU: GetAttrSubstitute: subst = SET_POINT_TEMPERATURE!#0-12.0:off,#23.0-40:on;WINDOW_STATE!(0|false):closed,(1|true):open;LOW_BAT!(0|false):ok,(1|true):low
2017.03.27 19:30:35 2: HMCCU: HM_Thermostat_Wohnzimmer Devlist = 000A9569A3A519
2017.03.27 19:30:35 2: HMCCU: HM_Thermostat_Wohnzimmer Objects = 000A9569A3A519
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, chnadd=000A9569A3A519:1, dpt=SWITCH_POINT_OCCURED, value=0
2017.03.27 19:30:35 2: HMCCU: FilterReading rm=1, r=.*, dpt=SWITCH_POINT_OCCURED chnflt=.* chnnam=HmIP-WTH-2 000A9569A3A519:1
2017.03.27 19:30:35 2: HMCCU: FilterReading Check 1 = 1 AND SWITCH_POINT_OCCURED = .* OR 1 = 0 AND SWITCH_POINT_OCCURED = .*
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, readings=1.SWITCH_POINT_OCCURED, orgvalue=0 value=0
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, chnadd=000A9569A3A519:1, dpt=PARTY_MODE, value=0
2017.03.27 19:30:35 2: HMCCU: FilterReading rm=1, r=.*, dpt=PARTY_MODE chnflt=.* chnnam=HmIP-WTH-2 000A9569A3A519:1
2017.03.27 19:30:35 2: HMCCU: FilterReading Check 1 = 1 AND PARTY_MODE = .* OR 1 = 0 AND PARTY_MODE = .*
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, readings=1.PARTY_MODE, orgvalue=0 value=0
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, chnadd=000A9569A3A519:1, dpt=ACTUAL_TEMPERATURE, value=23.5
2017.03.27 19:30:35 2: HMCCU: FilterReading rm=1, r=.*, dpt=ACTUAL_TEMPERATURE chnflt=.* chnnam=HmIP-WTH-2 000A9569A3A519:1
2017.03.27 19:30:35 2: HMCCU: FilterReading Check 1 = 1 AND ACTUAL_TEMPERATURE = .* OR 1 = 0 AND ACTUAL_TEMPERATURE = .*
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, readings=1.ACTUAL_TEMPERATURE, orgvalue=23.5 value=23.5
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, chnadd=000A9569A3A519:1, dpt=HEATING_COOLING, value=0
2017.03.27 19:30:35 2: HMCCU: FilterReading rm=1, r=.*, dpt=HEATING_COOLING chnflt=.* chnnam=HmIP-WTH-2 000A9569A3A519:1
2017.03.27 19:30:35 2: HMCCU: FilterReading Check 1 = 1 AND HEATING_COOLING = .* OR 1 = 0 AND HEATING_COOLING = .*
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, readings=1.HEATING_COOLING, orgvalue=0 value=0
2017.03.27 19:30:35 2: HMCCU: GetAttrSubstitute: subst = SET_POINT_TEMPERATURE!#0-12.0:off,#23.0-40:on;WINDOW_STATE!(0|false):closed,(1|true):open;LOW_BAT!(0|false):ok,(1|true):low
2017.03.27 19:30:35 2: HMCCU: HM_Thermostat_Wohnzimmer Devlist = 000A9569A3A519
2017.03.27 19:30:35 2: HMCCU: HM_Thermostat_Wohnzimmer Objects = 000A9569A3A519
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, chnadd=000A9569A3A519:1, dpt=SET_POINT_TEMPERATURE, value=20.0
2017.03.27 19:30:35 2: HMCCU: FilterReading rm=1, r=.*, dpt=SET_POINT_TEMPERATURE chnflt=.* chnnam=HmIP-WTH-2 000A9569A3A519:1
2017.03.27 19:30:35 2: HMCCU: FilterReading Check 1 = 1 AND SET_POINT_TEMPERATURE = .* OR 1 = 0 AND SET_POINT_TEMPERATURE = .*
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, readings=1.SET_POINT_TEMPERATURE, orgvalue=20.0 value=20.0
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, chnadd=000A9569A3A519:1, dpt=ACTIVE_PROFILE, value=1
2017.03.27 19:30:35 2: HMCCU: FilterReading rm=1, r=.*, dpt=ACTIVE_PROFILE chnflt=.* chnnam=HmIP-WTH-2 000A9569A3A519:1
2017.03.27 19:30:35 2: HMCCU: FilterReading Check 1 = 1 AND ACTIVE_PROFILE = .* OR 1 = 0 AND ACTIVE_PROFILE = .*
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, readings=1.ACTIVE_PROFILE, orgvalue=1 value=1
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, chnadd=000A9569A3A519:1, dpt=BOOST_MODE, value=0
2017.03.27 19:30:35 2: HMCCU: FilterReading rm=1, r=.*, dpt=BOOST_MODE chnflt=.* chnnam=HmIP-WTH-2 000A9569A3A519:1
2017.03.27 19:30:35 2: HMCCU: FilterReading Check 1 = 1 AND BOOST_MODE = .* OR 1 = 0 AND BOOST_MODE = .*
2017.03.27 19:30:35 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, readings=1.BOOST_MODE, orgvalue=0 value=0
2017.03.27 19:30:36 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, chnadd=000A9569A3A519:1, dpt=SET_POINT_MODE, value=0
2017.03.27 19:30:36 2: HMCCU: FilterReading rm=1, r=.*, dpt=SET_POINT_MODE chnflt=.* chnnam=HmIP-WTH-2 000A9569A3A519:1
2017.03.27 19:30:36 2: HMCCU: FilterReading Check 1 = 1 AND SET_POINT_MODE = .* OR 1 = 0 AND SET_POINT_MODE = .*
2017.03.27 19:30:36 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, readings=1.SET_POINT_MODE, orgvalue=0 value=0
2017.03.27 19:30:36 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, chnadd=000A9569A3A519:1, dpt=HUMIDITY, value=30
2017.03.27 19:30:36 2: HMCCU: FilterReading rm=1, r=.*, dpt=HUMIDITY chnflt=.* chnnam=HmIP-WTH-2 000A9569A3A519:1
2017.03.27 19:30:36 2: HMCCU: FilterReading Check 1 = 1 AND HUMIDITY = .* OR 1 = 0 AND HUMIDITY = .*
2017.03.27 19:30:36 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, readings=1.HUMIDITY, orgvalue=30 value=30
2017.03.27 19:30:36 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, chnadd=000A9569A3A519:1, dpt=FROST_PROTECTION, value=0
2017.03.27 19:30:36 2: HMCCU: FilterReading rm=1, r=.*, dpt=FROST_PROTECTION chnflt=.* chnnam=HmIP-WTH-2 000A9569A3A519:1
2017.03.27 19:30:36 2: HMCCU: FilterReading Check 1 = 1 AND FROST_PROTECTION = .* OR 1 = 0 AND FROST_PROTECTION = .*
2017.03.27 19:30:36 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, readings=1.FROST_PROTECTION, orgvalue=0 value=0
2017.03.27 19:30:36 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, chnadd=000A9569A3A519:1, dpt=WINDOW_STATE, value=0
2017.03.27 19:30:36 2: HMCCU: FilterReading rm=1, r=.*, dpt=WINDOW_STATE chnflt=.* chnnam=HmIP-WTH-2 000A9569A3A519:1
2017.03.27 19:30:36 2: HMCCU: FilterReading Check 1 = 1 AND WINDOW_STATE = .* OR 1 = 0 AND WINDOW_STATE = .*
2017.03.27 19:30:36 2: HMCCU: HMCCU_UpdateSingleDevice device=HM_Thermostat_Wohnzimmer, readings=1.WINDOW_STATE, orgvalue=0 value=closed


Hilft dir das?

VG
Christian

[zap]

Hast du die Firewall Regeln in der CCU korrekt eingestellt? Seit dem Firmware Update erforderlich

[Chris8888]

Hi, ja klar. Hatte ich schon nach dem Umstieg auf die 2.27.7.

Wenn ich den RPC-Server wieder auf intern umstelle läuft alles ganz normal.

VG
Christian

[zap]

Die Meldung "HM_Thermostat_HWR Execution of CCU script or command failed" hat nichts mit internem oder externem RPC-Server zu tun. Das funktioniert, sobald du auf intrpc zurück stellst?

[Chris8888]

Korrekt!

Ergänzung: Diese Meldung hatte ich zB auch schon mal, wenn ich per Script einige Kommandos parallel über HMCCU ausgeführt habe.
Ich vermute, durch die hohe Last in FHEM mit dem ext. RPC (Connection lost, Reconnect in 5 Sek)kommt es zum gleichen Sympthom. Ist aber geraten...

VG
Christian

[zap]

Kannst Du folgenden Befehl über das CCU WebGUI ausführen? (Programme und Verknüpfungen > Programme & Zentraleverknüpfungen" Button "Skript testen":

Code Auswählen Erweitern


dom.GetObject("HmIP-RF.000A9569A3A519:1.SET_POINT_TEMPERATURE").State(20.0);


Du wirst keine Ausgabe bekommen. Einfach prüfen, ob die Zieltemperatur geändert wird. Fehler siehst Du nur auf der CCU in der Datei /var/log/messages.

[Chris8888]

Hi,
klappt ohne Probleme.

VG
Christian

[zap]

Mysteriös. Hast Du schon mal die CCU neu gestartet? Vorher den RPC-Server stoppen.

[Chris8888]

Hallo Zap,

gerade gemacht. Keine Veränderung.
Die Readings ändern sich nur, wenn es einen Event des Gerätes gibt. Beim Start ist alles auf "null".
Sobald ich ein Komando absetzen kommt das "connection lost", das Kommando wird aber meistens trotzdem ausgeführt.

Dann habe ich wieder auf den internen Server umgestellt. Läuft sofort.

Dann Update durchgeführt 3.9.011 durchgeführt. Keine Veränderung.
Beim Start des internen Servers taucht jetzt beim Start mehrfach "HMCCU: HMCCU_QueueDeq seperator not found" im Log auf.

Ich habe keine Idee mehr ?!?!

Viele Grüße
Christian

[zap]

Ändern sich nur die Readings der HMIP Devices nach dem Start des RPC Servers nicht oder alle?
Was passiert, wenn du für ein Device get update ausführst? Was bei einem get deviceinfo?
Ich werde heute mal meine CCU auf die neuste Firmware updaten. Vielleicht kann ich das dann nachvollziehen.

[Chris8888]

An der CCU habe ich nur HmIP-Komponenten. Ich habe mal ein wenig weiter getestet:
Ext.Server:
Nach einem Neustart ist alles auf Null, nach ca. 4-5 Min sind aber alle Devices aktuell.
Nach Änderungen direkt am Device: Update in der CCU nach ca 2-3 Sek, fast im gleichen Augenblick kommt in FHEM das "Connections lost..".
Die Readings werden dabei nicht aktuallisiert.
Nach weiteren 4-5 Minuten wird das Reading dann aktuallisiert.

Ein Device get Update aktuallisiert das Reading sofort.
Ein get deviceinfo ändert nichts.

VG
Christian

[Chris8888]

Hallo Zap,

konntest du das Problem nachstellen?

Viele Grüße
Christian

[zap]

Habe gerade das Update auf die 2.27.8 Firmware gemacht. Läuft.

Kann meine HM-IP Devices ohne Probleme ansprechen. Readings werden korrekt aktualisiert, sowohl manuell als auch per externem RPC Server.

Kannst Du bitte mal die Firewall Einstellungen der CCU posten?

[Chris8888]

Klar!

HomeMatic XML-RPC API: Vollzugriff
Remote HomeMatic-Script API: Eingeschränkt

IP-Adressen für den eingeschränkten Zugriff:
192.168.100.1;
192.168.100.0/16

[zap]

Dann hätte ich nur noch 2 Strohhälme im Angebot: trotzdem die Firewall auf Vollzugriff stellen und das Device in der CCU umbenennen (ohne Leerzeichen).

Ich will dir aber keine großen Hoffnungen machen. Ich glaube nicht, dass es hilft.

Wenn du umbenennst, hinterher ein get devicelist machen.

[Chris8888]

Hallo Zap,

danke für deine Mühe!!!!

Firewalleinstellung habe ich geändert, leider ohne Erfolg. Ich versuche die Tage nochmal einen kompletten Reboot.
In der CCU habe ich keine Geräte mit Leerzeichen in den Namen. Ich verwende immer - oder _ dazwischen.

Dann lebe ich damit wohl erst einmal bzw nutze den internen Server wieder.

Wenn du noch eine Idee hast...gerne her damit!

Viele Grüße
Christian

[zap]

Das sieht aber schon nach Leerzeichen aus:

Name=HmIP-WTH-2 000A9569A3A519:1

Nach WTH-2

[Chris8888]

Hallo Zap,

das verstehe ich nicht. Alle meine CCU-Devices haben Namen ohne Leerzeichen.
Bei den einzelnen Kanälen (in deinem Beispiel Kanal 1 meines Wohnzimmer-Thermostats) habe ich die Namen tatsächlich nie angepasst.
Ist das auch notwendig? Die Kanäle spreche ich doch nirgends im Fhem überhaupt an. Die sehe ich doch noch nicht einmal einzeln, oder?

Kannst du mir da auf die Spünge helfen?

Danke!

VG
Christian

PS Gestern Abend ist anscheinend FHEM komplett ausgestiegen. Meine Rollos waren heute morgen noch oben.
Das Log war voll mit diesen Einträgen:
CCURPC: CB2010 maximum queue size reached
CCURPC: Size of event queue exceeds 500

FHEM hat nicht mehr reagiert und ich musste den PI komplett neu starten.
Eine Idee dazu?

[zap]

Datenpunkte sind immer Kanälen zugeordnet und werden daher auch über Kanäle angesprochen. Allerdings verwendet HMCCU dafür die Adresse und nicht den Namen. Daher spielen Leerzeichen im Namen eigntlich keine Rolle. Meine Kanäle haben teilweise auch Leerzeichen und es funktioniert alles. War nur der berühmte letzte Strohhalm.

Die Meldung mit der vollen Queue ist die Wirkung, nicht die Ursache. Die kommt von einem der Threadsnim Hintergrund und meint eigentlich nur, dass FHEM keine Daten mehr abholt. Ursache ist ebene, dass FHEM offensichtlich ausgestiegen ist.

Ich kann mir das alles nicht erklären. Du bist anscheinend der einzige, der diese Probleme hat. Vielleicht liegt es auch an einem anderen Device. Sonst keine Fehler im Log?

Heute oder morgen gibt es eine neue Version. Mach halt mal das Update. Vielleicht hilft es ja.


Auch diese Connection lost Meldungen sind seltsam.

Mein FHEM läuft momentan mit 4 RPC Schnittstellen zur CCU. Darüber melden >60 Geräte mit fast 400 Kanälen ihre Infos an FHEM ohne irgendwelche Hänger oder Performance Probleme. Alles auf einem Raspi 3, der zusätzlich noch einen Apache Webserver drauf hat.

[Chris8888]

Hallo Zap,

kann es ggf. etwas damit zu tun haben das ich nur HmIP-Devices an der CCU habe?
"Normale" HM-Geräte hängen direkt in FHEM. D.h. mein Server läuft nur noch auf Port 2010.

Der Absturz könnte damit zu tun haben das ich an dem Abend meine FAL (Ansteuerung Fussbodenheizung) upgedatet habe.
Das Gerät hat nach dem Reboot normal weitergearbeitet, in der CCU und FHEM sah alles gut aus.
Ich habe dann gestern noch den geplanten Reboot zwecks Aktivierung der Firewall-Regeln durchgeführt, danach war die FAL im Geräteeingang und ich musste es neu akzeptieren. Ich schätze, die FAL ist durch das Update da irgendwie aus der Konfiguration gepflogen und dadurch konnte FHEM/HMCCU nicht mehr sauber darauf zugreifen.

Jetzt sieht alles wieder normal aus.

Aber das Thema "Connection lost" bei ext. Server bleibt.
Andere Fehler habe ich im Log nicht. Alles läuft wie gewohnt extrem stabil.
Dann muss ich halt mit dem int. Server leben, der tut ja auch was er soll.

Viele Grüße
Christian

[mrfloppy]

Habe gestern auf den extRPC umgestellt.
Wollte nur Feedback geben und danke sagen fürs Modul.
Hat auf Anhieb geklappt. Keine Probleme feststellbar.
Außer einmal hatte ich heute

Code Auswählen Erweitern

2017.04.20 08:34:58 2: CCURPC: I/O error during data processing (Select found no reader
sonst bleibt das Logfile leer.

LG Thomas

[zap]

Die Meldung kann ab und zu mal kommen, wenn FHEM sehr beschäftigt ist und die RPC Server Threads ihre Daten nicht los bekommen. Es gehen aber keine Daten verloren, da alle CCU Events in einer Queue gepuffert werden. Die Daten werden dann bei nächster Gelegenheit übermittelt.

[Ralli]

Auf einer alternativen fhem-Installation habe ich versuchsweise HMCCU mit neuem HMRPC installiert. Folgender "Fehler" in Verbindung mit HMW taucht auf, allerdings kommen die Events rein, wie es sein soll:

Code Auswählen Erweitern


2017.04.22 08:05:27.774 1: HMCCURPC: Received IN event. RPC server CB2000 running.
2017.04.22 08:05:27.884 2: CCURPC: CB2000 NewDevice received 94 device specifications
2017.04.22 08:05:27.885 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/88_HMCCURPC.pm line 2106.
2017.04.22 08:05:27.924 2: HMCCURPC: Wrong number of parameters in event ND|CB2000|D|BidCoS-Wir|HMW-RCV-50|3|2.27.8|. Expected 6
2017.04.22 08:05:28.034 2: HMCCURPC: Wrong number of parameters in event ND|CB2000|D|HMW123456|HMW-IO-12-Sw14-DR|12|1.00|. Expected
2017.04.22 08:05:28.035 2: HMCCURPC: Wrong number of parameters in event ND|CB2000|D|HMW654321|HMW-Sen-SC-12-DR|7|3.01|. Expected 6
2017.04.22 08:05:29.262 1: PERL WARNING: Use of uninitialized value $par[1] in hash element at ./FHEM/88_HMCCURPC.pm line 619.


[zap]

Muss ich mir im Detail mal anschauen. Ich habe keine Wired Devices und daher ist diese Schnittstelle für mich etwas Entwicklung im Blindflug. Das Log von dir hilft hier definitv weiter. Anscheinend unterscheiden sich die Wired Events etwas von den anderen.
Scheint aber nur für die NewDevice Events zu gelten, daher funktioniert die Aktualisierung der Datenpunkte bzw Readings

[smart.builder]

Hallo,

der RPC-Server funktionierte auf meinem Raspberry bisher einwandfrei. Nun habe ich mein Fhem auf einen größeren Server umgezogen.
Es läuft alles in einem Docker-Container.
Leider bekomme ich den RPC-Server nicht zum laufen. Sowohl intrpc als auch extrpc startet nicht.

Ich bekomme mit verbose 5 folgende Logeinträge:

Code Auswählen Erweitern


2017.09.14 18:03:20 2: HMCCURPC: Starting thread for data processing
2017.09.14 18:03:20 2: HMCCURPC: Started thread for data processing. TID=4
2017.09.14 18:03:20 2: CCURPC: Thread DATA processing RPC events. TID=4
2017.09.14 18:03:20 2: HMCCURPC: RPC server thread started for interface BidCos-RF with TID=5
2017.09.14 18:03:20 2: CCURPC: Initializing RPC server CB2001 for interface BidCos-RF
2017.09.14 18:03:20 2: HMCCURPC: Callback server CB2001 created. Listening on port 7411
2017.09.14 18:03:20 2: CCURPC: CB2001 accepting connections. TID=5
2017.09.14 18:03:20 2: CCURPC: Initializing RPC server CB2010 for interface HmIP-RF
2017.09.14 18:03:20 2: HMCCURPC: RPC server thread started for interface HmIP-RF with TID=6
2017.09.14 18:03:20 2: HMCCURPC: Callback server CB2010 created. Listening on port 7420
2017.09.14 18:03:20 2: CCURPC: CB2010 accepting connections. TID=6
2017.09.14 18:03:21 1: HMCCURPC: RPC server(s) starting
2017.09.14 18:03:21 1: HMCCURPC: Received SL event. RPC server DATA enters server loop
2017.09.14 18:03:21 1: HMCCURPC: Received SL event. RPC server CB2001 enters server loop
2017.09.14 18:03:21 1: HMCCURPC: Received SL event. RPC server CB2010 enters server loop
2017.09.14 18:03:21 1: HMCCURPC: All threads working
2017.09.14 18:03:21 2: HMCCURPC: Registering callback http://172.19.0.3:7411/fh2001 with ID CB2001 at http://192.168.178.62:2001/
2017.09.14 18:03:21 1: HMCCURPC: RPC callback with URL http://172.19.0.3:7411/fh2001 registered
2017.09.14 18:03:21 2: HMCCURPC: Registering callback http://172.19.0.3:7420/fh2010 with ID CB2010 at http://192.168.178.62:2010/
2017.09.14 18:03:21 1: HMCCURPC: RPC callback with URL http://172.19.0.3:7420/fh2010 registered
2017.09.14 18:04:11 2: HMCCURPC: Checking if all threads are running
2017.09.14 18:04:11 1: HMCCURPC: Only 1 of 3 threads are running. Cleaning up
2017.09.14 18:04:11 1: HMCCURPC: Housekeeping called. Cleaning up RPC environment
2017.09.14 18:04:11 1: HMCCURPC: Deregistering RPC server http://172.19.0.3:7420/fh2010 with ID CB2010 at http://192.168.178.62:2010/
2017.09.14 18:04:11 1: HMCCURPC: RPC callback for server CB2010 deregistered
2017.09.14 18:04:11 1: HMCCURPC: Deregistering RPC server http://172.19.0.3:7411/fh2001 with ID CB2001 at http://192.168.178.62:2001/
2017.09.14 18:04:11 1: HMCCURPC: RPC callback for server CB2001 deregistered
2017.09.14 18:04:11 2: HMCCURPC: Stop I/O handling
2017.09.14 18:04:11 2: HMCCURPC: Close child socket
2017.09.14 18:04:11 2: HMCCURPC: Close parent socket
2017.09.14 18:04:11 2: HMCCURPC: Sending signal INT to thread CB2010 TID=6
2017.09.14 18:04:11 2: HMCCURPC: Sending signal INT to thread DATA TID=4
2017.09.14 18:04:11 2: HMCCURPC: Sending signal INT to thread CB2001 TID=5
2017.09.14 18:04:11 2: CCURPC: DATA stopped event processing. TID=4
2017.09.14 18:04:11 2: CCURPC: RPC server CB2010 stopped handling connections. TID=6
2017.09.14 18:04:12 2: CCURPC: RPC server CB2001 stopped handling connections. TID=5
2017.09.14 18:04:13 2: HMCCURPC: Thread CB2010 with TID=6 is in state stopping. Can't delete it
2017.09.14 18:04:13 2: HMCCURPC: Thread DATA with TID=4 is in state stopping. Can't delete it
2017.09.14 18:04:13 2: HMCCURPC: Thread CB2001 with TID=5 is in state stopping. Can't delete it
   
 
Beim Docker-Container sind die Ports 2000, 2001, 2010, 5544, 8701 freigegeben.
Innerhalb des Containers ist die IP des eth0: 172.19.0.3 
Der Docker-Host hat nach außen hin die IP-Adresse: 192.168.178.61

Beim iobroker gab es anscheinend eine ähnliche Problematik: https://github.com/ioBroker/ioBroker.hm-rpc/issues/37

Kann man da was machen?
Danke!

Gruß
Viktor

[Rewe2000]

Hallo,

habe gestern auch HMCCURPC installiert (Über das I/O Device), nach anfänglichen Problemen mit der Nachinstallation von den Perl Modulen (@betateilchen sei Dank) hat es dann geklappt.
Ein deutlicher Geschwindigkeitsgewinn war sofort feststellbar, alles lief ohne Fehler, so wie es sein sollte.
Auch nach einem "shutdown restart" lief die Kommunikation den ganzen Abend Fehlerfrei.

Danach habe ich in Fhem noch ein "update all" (nach ca einer Woche) ausgeführt, auch nach dem "shutdown restart" tauchten keinerlei Fehler auf.

Dachte mir, jetzt bring ich noch meinen Raspi auf den aktuellen Stand (letztes fehlerfreies Update vor ca. 1 Woche). Nachdem das Update ohne Fehler durchgeführt wurde, habe ich "sudo reboot" ausgeführt.

Folgendes Verhalten lässt sich bei mir immer reproduzieren, nachdem ich den Raspi mit:

Code Auswählen Erweitern

sudo /etc/init.d/fhem stop
sudo reboot

neustarte.

Die WEBserver von Fhem ist zunächst verfügbar (ca. 10-30 Sekunden).
Eine Abfrage vom Raspi aus ergibt:

Code Auswählen Erweitern

sudo /etc/init.d/fhem status
fhem is running

Nach ca. 30 Sekunden ist dieser nicht mehr erreichbar und eine Abrage über Raspi ergibt:

Code Auswählen Erweitern

sudo /etc/init.d/fhem status
fhem is not running

Starte ich dann den Fhem wieder über den Raspi, läuft es absolut Problemlos und ohne Fehler im Log seit über einen Tag.

Code Auswählen Erweitern

sudo /etc/init.d/fhem start
fhem is running

Nur beim Neustart des Raspi gibt es diese anfänglichen Probleme. Das Log zeigt zum Zeitpunkt des Fehlers folgende Einträge in Verbose 2:

Code Auswählen Erweitern

2017.10.11 21:33:30 1: Perfmon: possible freeze starting at 21:33:29, delay is 1.969
2017.10.11 21:40:53 0: Server shutdown
2017.10.11 21:40:53 1: HMCCURPC: Found 3 threads. Stopping ...
2017.10.11 21:40:53 1: HMCCURPC: Deregistering RPC server http://192.168.1.33:7420/fh2010 with ID CB2010 at http://192.168.1.32:2010/
2017.10.11 21:40:53 1: HMCCURPC: RPC callback for server CB2010 deregistered
2017.10.11 21:40:53 1: HMCCURPC: Deregistering RPC server http://192.168.1.33:7411/fh2001 with ID CB2001 at http://192.168.1.32:2001/
2017.10.11 21:40:53 1: HMCCURPC: RPC callback for server CB2001 deregistered
2017.10.11 21:40:53 2: HMCCURPC: Sending signal INT to thread CB2010 TID=3
2017.10.11 21:40:53 2: HMCCURPC: Sending signal INT to thread CB2001 TID=2
2017.10.11 21:40:54 2: CCURPC: RPC server CB2010 stopped handling connections. TID=3
2017.10.11 21:40:54 2: CCURPC: RPC server CB2001 stopped handling connections. TID=2
2017.10.11 21:40:54 1: HMCCURPC: Found 1 threads. Stopping ...
2017.10.11 21:42:26 2: HMCCU: Received no events from interface CB2001 for 29557496.5880101 seconds
Can't locate object method "HMCCURPC_RPC_NUMPORT" via package "2001" (perhaps you forgot to load "2001"?) at ./FHEM/88_HMCCURPC.pm line 654.
2017.10.11 21:44:40 2: Perfmon: ready to watch out for delays greater than one second
2017.10.11 21:44:40 1: Including fhem.cfg
2017.10.11 21:44:41 2: eventTypes: loaded 3244 events from ./log/eventTypes.txt
2017.10.11 21:44:41 2: Switched COC rfmode to HomeMatic
2017.10.11 21:44:43 1: HMCCU: Device CCU2. Initialized version 4.1.001
2017.10.11 21:44:47 1: HMCCU: Read 51 devices with 237 channels from CCU 192.168.1.32
2017.10.11 21:44:49 1: HMCCURPC: Device CCU2_rpc. Initialized version 0.96 beta
2017.10.11 21:44:49 1: Including ./log/fhem.save
2017.10.11 21:44:50 0: HMCCU: Start of RPC server after FHEM initialization in 12 seconds
2017.10.11 21:44:50 1: usb create starting
2017.10.11 21:44:50 1: usb create end
2017.10.11 21:44:50 0: Featurelevel: 5.8
2017.10.11 21:44:50 0: Server started with 271 defined entities (fhem.pl:15182/2017-10-03 perl:5.024001 os:linux user:fhem pid:1413)
2017.10.11 21:44:50 1: Perfmon: possible freeze starting at 21:44:41, delay is 9.991
2017.10.11 21:44:51 1: PERL WARNING: Use of uninitialized value in numeric eq (==) at ./FHEM/36_ModbusTCPServer.pm line 342.
2017.10.11 21:44:51 1: ModbusTCPServer_Parse: bad frame, sent: SimpleWrite [20 10 00 00 00 06] 00 03 20 10 00 05
2017.10.11 21:44:51 1: ModbusTCPServer_Parse: bad frame, received:  [20 10 00 00 00 03] 00 83 02
2017.10.11 21:45:02 2: HMCCURPC: Starting thread for data processing
2017.10.11 21:45:02 2: HMCCURPC: Started thread for data processing. TID=1
2017.10.11 21:45:02 2: CCURPC: Thread DATA processing RPC events. TID=1
2017.10.11 21:45:03 2: HMCCURPC: RPC server thread started for interface BidCos-RF with TID=2
2017.10.11 21:45:03 2: CCURPC: Initializing RPC server CB2001 for interface BidCos-RF
2017.10.11 21:45:03 2: HMCCURPC: Callback server CB2001 created. Listening on port 7411
2017.10.11 21:45:03 2: CCURPC: CB2001 accepting connections. TID=2
2017.10.11 21:45:03 2: HMCCURPC: RPC server thread started for interface HmIP-RF with TID=3
2017.10.11 21:45:03 2: CCURPC: Initializing RPC server CB2010 for interface HmIP-RF
2017.10.11 21:45:03 2: HMCCURPC: Callback server CB2010 created. Listening on port 7420
2017.10.11 21:45:03 2: CCURPC: CB2010 accepting connections. TID=3
2017.10.11 21:45:04 1: HMCCURPC: RPC server(s) starting
2017.10.11 21:45:04 1: HMCCURPC: Received SL event. RPC server DATA enters server loop
2017.10.11 21:45:04 1: HMCCURPC: Received SL event. RPC server CB2001 enters server loop
2017.10.11 21:45:04 1: HMCCURPC: Received SL event. RPC server CB2010 enters server loop
2017.10.11 21:45:04 1: HMCCURPC: All threads working
2017.10.11 21:45:04 2: HMCCURPC: Registering callback http://192.168.1.33:7411/fh2001 with ID CB2001 at http://192.168.1.32:2001/
2017.10.11 21:45:04 1: CCURPC: CB2001 ListDevices. Sending init to HMCCU
2017.10.11 21:45:05 1: HMCCURPC: RPC callback with URL http://192.168.1.33:7411/fh2001 registered
2017.10.11 21:45:05 2: HMCCURPC: Registering callback http://192.168.1.33:7420/fh2010 with ID CB2010 at http://192.168.1.32:2010/
2017.10.11 21:45:05 1: HMCCURPC: RPC callback with URL http://192.168.1.33:7420/fh2010 registered
2017.10.11 21:45:05 1: HMCCURPC: Received IN event. RPC server CB2001 running.
2017.10.11 21:45:05 1: Perfmon: possible freeze starting at 21:45:03, delay is 2.103
2017.10.11 21:45:05 2: CCURPC: CB2001 NewDevice received 69 device and channel specifications
2017.10.11 21:45:05 1: CCURPC: CB2010 ListDevices. Sending init to HMCCU
2017.10.11 21:45:05 1: HMCCURPC: Received IN event. RPC server CB2010 running.
2017.10.11 21:45:05 1: HMCCURPC: All RPC servers running
2017.10.11 21:45:07 2: CCURPC: CB2010 NewDevice received 219 device and channel specifications
2017.10.11 21:45:08 2: HMCCURPC: Updated devices. Success=52 Failed=0


Das Problem tritt definitiv nur beim Neustart des Raspi auf, starte ich danach Fhem über den Raspi neu, läuft Fhem ohne Fehler weiter.

Habt ihr eine Idee woran dies liegen könnte, braucht ihr noch mehr Infos?

Gruß Reinhard

[zap]

Das ist ein Bug in HMCCURPC, der nur in wenigen Fällen auftritt. Daher ist das bisher nicht aufgefallen. Wird zeitnah behoben.

[Rewe2000]

Hallo zap,

nur noch ein kurzer Hinweis, ev. hilft es noch für die Fehlerbehebung (in der alten HMCCURPC - Version).

Der Fehler tritt in gleicher Weise bei mir auf, wenn ich bei laufendem Fhem und RPC Server die CCU2 (habe nur Hardware) neu starte.
Bis Fhem stoppt, kann ich noch HmIP Schalter über Fhem bedienen, aber die Readings (z.B. 4.State) wird dabei nicht mehr aktualisiert.

Gruß Reinhard

[Axxl]

Hallo,

der RPC-Server funktionierte auf meinem Raspberry bisher einwandfrei. Nun habe ich mein Fhem auf einen größeren Server umgezogen.
Es läuft alles in einem Docker-Container.
Leider bekomme ich den RPC-Server nicht zum laufen. Sowohl intrpc als auch extrpc startet nicht.

+1
Ich habe genau das gleiche Problem. Im Docker Container bekomme ich den RPC Server auch nicht zum laufen.

[zap]

Es ist immer hilfreich, wenn ihr bei solchen Problemen die wahrscheinlich vorhandenen Fehlermeldungen im FHEM Logfile mitliefert. Bei einer neuen Linux Installation würde ich erst mal vermuten, dass Perl Module fehlen. Wenn es das nicht ist, kann man das Loglevel beim externen RPC Server auf 4 setzen, dann wird er wesentlich geschwätziger.

[Axxl]

Es ist immer hilfreich, wenn ihr bei solchen Problemen die wahrscheinlich vorhandenen Fehlermeldungen im FHEM Logfile mitliefert. Bei einer neuen Linux Installation würde ich erst mal vermuten, dass Perl Module fehlen. Wenn es das nicht ist, kann man das Loglevel beim externen RPC Server auf 4 setzen, dann wird er wesentlich geschwätziger.

Code Auswählen Erweitern


017.10.20 23:55:24 1: HMCCURPC: RPC server(s) starting
2017.10.20 23:55:24 1: HMCCURPC: Received SL event. RPC server DATA enters server loop
2017.10.20 23:55:24 1: HMCCURPC: Received SL event. RPC server CB2001 enters server loop
2017.10.20 23:55:24 1: HMCCURPC: All threads working
2017.10.20 23:55:24 2: HMCCURPC: Registering callback http://172.17.0.4:7411/fh2001 with ID CB2001 at http://192.168.178.13:2001/
2017.10.20 23:58:25 1: HMCCURPC: Failed to register callback for ID CB2001
2017.10.20 23:58:25 2: HMCCURPC: Checking if all threads are running
2017.10.20 23:58:25 1: HMCCURPC: Only 1 of 2 threads are running. Cleaning up
2017.10.20 23:58:25 1: HMCCURPC: Housekeeping called. Cleaning up RPC environment
2017.10.20 23:58:25 1: HMCCURPC: Deregistering RPC server http://172.17.0.4:7411/fh2001 with ID CB2001 at http://192.168.178.13:2001/

Hab den DockerContainer jetzt mal mit --net=host laufen , und auch den Port 2001 Exposed.
Scheint trotzdem nicht zu klappen "Failed to register callback for ID CB2001" .. alle 5 sekunden startet er neu.
Verbose 4 hat nicht viel mehr Info gebracht.

[zap]

Sieht für mich so aus, als sei die Firewall auf der CCU nicht freigeschaltet. In dem Fall siehe auch Wiki.

Falls es das nicht ist: Starte die CCU neu. Eventuell ist ein Prozess gestorben.

[jojojo]

Das Callback-Interface registriert sich auf die IP des Docker-Containers:

Code Auswählen Erweitern

2017.10.20 23:55:24 2: HMCCURPC: Registering callback http://172.17.0.4:7411/fh2001 with ID CB2001 at http://192.168.178.13:2001/

Das kann nicht funktionieren. Du musst dem RPC-Server die Adresse des Host mitgeben

attr <rpc_device> rpcServerAddr <IP Docker-Host>

und dann den Port (hier 7411) in den Container weiterleiten