Kommunikation mit Openhab bricht ab - NEU

sathya · August 16, 2018, 9:04pm

Ich meine die Richtung von Homegear zu OpenHAB (also vor allem die event()-Pakete). Aktuell muss ich nach jedem Paket die Verbindung schließen - das sorgt bei vielen Ereignissen natürlich für viele TIME_WAIT. Wenn ich das nicht tue, ist diese beim Folgepaket nicht mehr offen - die Verbindung ist also OpenHAB-seitig geschlossen worden. socketMaxAlive ist für die Richtung von OpenHAB zu Homegear. Diese Verbindung ist mit den Standardeinstellungen tatsächlich auch 15 Minuten geöffnet.

gerrieg · August 18, 2018, 7:37am

Achso diese Richtung. OK, schaue ich mir demnächst an.

sathya · August 20, 2018, 11:39am

@job, @s4ndst0rm,

das sollten wir abwarten. Ich kann mir gut vorstellen, dass das das Problem löst.

job · August 21, 2018, 2:43pm

Mir ist gerade aufgefallen, dass ich das Problem erzeugen kann. Ich muss einfach nur homegear neu starten, während openHAB läuft. Das System fängt sich erst wieder, wenn ich openHAB neu starte. Die Verbindung wird zwar immer wieder aufgebaut, aber noch während der Aufbau läuft wieder abgebrochen.

@sathya, @gerrieg soll ich euch logs von einem solchen Zyklus schicken? Auf welchen loglevel soll ich das dann einstellen?

sathya · August 21, 2018, 3:18pm

Hallo @job,

Sehr gerne! Auf Loglevel 5. Ich schaue auch bei mir mal, ob ich das Problem so reproduziert bekomme - das würde das Lösen drastisch vereinfachen.

Vielen Dank und viele Grüße

Sathya

sathya · August 21, 2018, 4:33pm

Also auf Anhieb kann ich das Problem hier leider mit dem beschriebenen Weg nicht reproduzieren.

job · August 21, 2018, 7:04pm

Hi @sathya,

ich habe hier ca. 10 Wand- und 15 Heizkörper-Thermostate, dazu noch Bewegungsmelder, Fensterkontakte etc. Die brauchen einige Zeit, bis die wieder von openHAB aktiviert/deaktiviert werden.
Ich werde das Problem später (vielleicht erst morgen) reproduzieren und dir das Log schicken.

Viele Grüße

Joachim

gerrieg · August 22, 2018, 1:59pm

Probiert mal diese Version bitte: Download

Die Sockets bleiben jetzt offen und werden erst nach (default) 15 Minuten geschlossen. Ihr könnt das mit dem socketMaxAlive Parameter auch noch selber einstellen.

@job
Das mit dem Homegear restart schau ich mir auch an.

job · August 22, 2018, 2:24pm

Vielen Dank. Ich werde heute abend zuerst das Log mit der alten Version (openHAB 2.3) produzieren und danach versuchen, ob ich das mit dieser Version auch noch reproduzieren kann. Soll ich einen speziellen Loglevel für openHAB einstellen? Ich kann leider kein Trace für das ganze Binding einstellen, dann reagiert mein RaspberryPi nicht mehr, weil so viel geloggt wird.

gerrieg · August 22, 2018, 2:30pm

Soll ich einen speziellen Loglevel für openHAB einstellen?

Momentan mal nicht.

Übrigens, hab gerade den reconnect getestet. Hab einfach das Netzwerk getrennt. Ging alles offline, dann Netzwerk wieder aktiviert und es ging alles brav wieder online. Allerdings mit Raspberrymatic getestet, der code ist für Homegear allerdings der Selbe.

sathya · August 22, 2018, 4:34pm

Bei mir leider genauso. Ich hoffe mit Hilfe des Logs von @job können wir das Problem identifizieren.

s4ndst0rm · August 22, 2018, 6:09pm

@gerrieg

Ich habe das homematic binding deinstalliert und deine jar Datei ins “addons” Verzeichnis gelegt.
Ich habe allerdings dasselbe Verhalten wie bei der aktuelle 2.4 nightly und bekomme keine Verbindung zu homegear hin:

2018-08-22 20:06:11.762 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'WIRED' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:06:13.770 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'HMIP' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:06:15.775 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'CUXD' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:06:17.780 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'GROUP' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:06:17.781 [INFO ] [ommunicator.AbstractHomematicGateway] - HmGatewayInfo[id=HOMEGEAR,type=Homegear,firmware=0.8.0-2291,address=VBC2688033,wired=false,hmip=false,cuxd=false,group=false]
2018-08-22 20:06:29.864 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'WIRED' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:06:31.873 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'HMIP' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:06:33.880 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'CUXD' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:06:35.883 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'GROUP' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:06:35.884 [INFO ] [ommunicator.AbstractHomematicGateway] - HmGatewayInfo[id=HOMEGEAR,type=Homegear,firmware=0.8.0-2291,address=VBC2688033,wired=false,hmip=false,cuxd=false,group=false]
2018-08-22 20:06:47.987 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'WIRED' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:06:49.992 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'HMIP' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:06:51.999 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'CUXD' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:06:54.006 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'GROUP' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:06:54.007 [INFO ] [ommunicator.AbstractHomematicGateway] - HmGatewayInfo[id=HOMEGEAR,type=Homegear,firmware=0.8.0-2291,address=VBC2688033,wired=false,hmip=false,cuxd=false,group=false]
2018-08-22 20:07:06.096 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'WIRED' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:08.102 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'HMIP' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:10.108 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'CUXD' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:12.114 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'GROUP' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:12.115 [INFO ] [ommunicator.AbstractHomematicGateway] - HmGatewayInfo[id=HOMEGEAR,type=Homegear,firmware=0.8.0-2291,address=VBC2688033,wired=false,hmip=false,cuxd=false,group=false]
2018-08-22 20:07:20.625 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'WIRED' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:21.627 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'HMIP' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:22.631 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'CUXD' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:23.209 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'WIRED' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:23.635 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'GROUP' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:23.636 [INFO ] [ommunicator.AbstractHomematicGateway] - HmGatewayInfo[id=HOMEGEAR,type=Homegear,firmware=0.8.0-2291,address=VBC2688033,wired=false,hmip=false,cuxd=false,group=false]
2018-08-22 20:07:24.214 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'HMIP' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:25.217 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'CUXD' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:26.220 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'GROUP' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:26.221 [INFO ] [ommunicator.AbstractHomematicGateway] - HmGatewayInfo[id=HOMEGEAR,type=Homegear,firmware=0.8.0-2291,address=VBC2688033,wired=false,hmip=false,cuxd=false,group=false]
2018-08-22 20:07:34.731 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'WIRED' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:35.735 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'HMIP' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:36.737 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'CUXD' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:37.315 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'WIRED' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:37.740 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'GROUP' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:37.741 [INFO ] [ommunicator.AbstractHomematicGateway] - HmGatewayInfo[id=HOMEGEAR,type=Homegear,firmware=0.8.0-2291,address=VBC2688033,wired=false,hmip=false,cuxd=false,group=false]
2018-08-22 20:07:38.318 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'HMIP' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:39.320 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'CUXD' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:40.323 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'GROUP' on gateway '284ddaf7' not available, disabling support
2018-08-22 20:07:40.324 [INFO ] [ommunicator.AbstractHomematicGateway] - HmGatewayInfo[id=HOMEGEAR,type=Homegear,firmware=0.8.0-2291,address=VBC2688033,wired=false,hmip=false,cuxd=false,group=false]

homegear.log

08/22/18 20:08:44.231 RPC Server (Port 2001): Info: Client number 72 is calling RPC method: listBidcosInterfaces (1) Parameters:
08/22/18 20:08:46.714 RPC Server (Port 2001): Info: Connection from ::ffff:172.17.0.1:35298 accepted. Client number: 73
08/22/18 20:08:46.715 RPC Server (Port 2001): Info: RPC server client id for client number 73 is: 64
08/22/18 20:08:46.716 RPC Server (Port 2001): Info: Client number 73 is calling RPC method: getDeviceDescription (1) Parameters:
(String) BidCoS-RF
08/22/18 20:08:46.760 RPC Server (Port 2001): Info: Connection from ::ffff:172.17.0.1:35300 accepted. Client number: 74
08/22/18 20:08:46.762 RPC Server (Port 2001): Info: RPC server client id for client number 74 is: 65
08/22/18 20:08:46.763 RPC Server (Port 2001): Info: Client number 74 is calling RPC method: listBidcosInterfaces (1) Parameters:
08/22/18 20:08:48.283 RPC Server (Port 2001): Info: Connection from ::ffff:172.17.0.1:35302 accepted. Client number: 75
08/22/18 20:08:48.284 RPC Server (Port 2001): Info: RPC server client id for client number 75 is: 66
08/22/18 20:08:48.284 RPC Server (Port 2001): Info: Client number 75 is calling RPC method: init (2) Parameters:
(String) binary://host.docker.internal:9138
08/22/18 20:08:48.285 Info: Client with IP ::ffff:172.17.0.1 is calling "init".
08/22/18 20:08:50.806 RPC Server (Port 2001): Info: Connection from ::ffff:172.17.0.1:35304 accepted. Client number: 76
08/22/18 20:08:50.806 RPC Server (Port 2001): Info: RPC server client id for client number 76 is: 67
08/22/18 20:08:50.807 RPC Server (Port 2001): Info: Client number 76 is calling RPC method: init (2) Parameters:
(String) binary://host.docker.internal:9140
08/22/18 20:08:50.807 Info: Client with IP ::ffff:172.17.0.1 is calling "init".
08/22/18 20:08:58.298 RPC Server (Port 2001): Info: Connection from ::ffff:172.17.0.1:35308 accepted. Client number: 77
08/22/18 20:08:58.299 RPC Server (Port 2001): Info: RPC server client id for client number 77 is: 68
08/22/18 20:08:58.299 RPC Server (Port 2001): Info: Client number 77 is calling RPC method: getDeviceDescription (1) Parameters:
(String) BidCoS-RF
08/22/18 20:08:58.329 RPC Server (Port 2001): Info: Connection from ::ffff:172.17.0.1:35310 accepted. Client number: 78
08/22/18 20:08:58.329 RPC Server (Port 2001): Info: RPC server client id for client number 78 is: 69
08/22/18 20:08:58.330 RPC Server (Port 2001): Info: Client number 78 is calling RPC method: listBidcosInterfaces (1) Parameters:
08/22/18 20:09:00.817 RPC Server (Port 2001): Info: Connection from ::ffff:172.17.0.1:35312 accepted. Client number: 79
08/22/18 20:09:00.818 RPC Server (Port 2001): Info: RPC server client id for client number 79 is: 70
08/22/18 20:09:00.818 RPC Server (Port 2001): Info: Client number 79 is calling RPC method: getDeviceDescription (1) Parameters:
(String) BidCoS-RF
08/22/18 20:09:00.922 RPC Server (Port 2001): Info: Connection from ::ffff:172.17.0.1:35314 accepted. Client number: 80
08/22/18 20:09:00.923 RPC Server (Port 2001): Info: RPC server client id for client number 80 is: 71
08/22/18 20:09:00.924 RPC Server (Port 2001): Info: Client number 80 is calling RPC method: listBidcosInterfaces (1) Parameters:
08/22/18 20:09:02.381 RPC Server (Port 2001): Info: Connection from ::ffff:172.17.0.1:35316 accepted. Client number: 81
08/22/18 20:09:02.382 RPC Server (Port 2001): Info: RPC server client id for client number 81 is: 72
08/22/18 20:09:02.383 RPC Server (Port 2001): Info: Client number 81 is calling RPC method: init (2) Parameters:
(String) binary://host.docker.internal:9140
08/22/18 20:09:02.383 Info: Client with IP ::ffff:172.17.0.1 is calling "init".
08/22/18 20:09:04.966 RPC Server (Port 2001): Info: Connection from ::ffff:172.17.0.1:35318 accepted. Client number: 82
08/22/18 20:09:04.967 RPC Server (Port 2001): Info: RPC server client id for client number 82 is: 73
08/22/18 20:09:04.968 RPC Server (Port 2001): Info: Client number 82 is calling RPC method: init (2) Parameters:
(String) binary://host.docker.internal:9142
08/22/18 20:09:04.969 Info: Client with IP ::ffff:172.17.0.1 is calling "init".
08/22/18 20:09:12.394 RPC Server (Port 2001): Info: Connection from ::ffff:172.17.0.1:35322 accepted. Client number: 83
08/22/18 20:09:12.395 RPC Server (Port 2001): Info: RPC server client id for client number 83 is: 74
08/22/18 20:09:12.395 RPC Server (Port 2001): Info: Client number 83 is calling RPC method: getDeviceDescription (1) Parameters:
(String) BidCoS-RF
08/22/18 20:09:12.427 RPC Server (Port 2001): Info: Connection from ::ffff:172.17.0.1:35324 accepted. Client number: 84
08/22/18 20:09:12.428 RPC Server (Port 2001): Info: RPC server client id for client number 84 is: 75

job · August 23, 2018, 1:13pm

Schlechte Nachricht von mir. Im Rahmen meiner Gateway Installation bin ich auf die 0.8.0-2299 gewechselt. Mit dieser Version konnte ich den Abbruch nicht mehr reproduzieren. Zumindest nicht mit frisch gestartetem openHAB. Ich werde es heute nochmal probieren.

@sathya, hat sich zwischen 2285 und 2299 irgendwas diesbezüglich geändert?

gerrieg · August 23, 2018, 2:06pm

@job
Ja, Du hast Recht … sorry. Habe mir jetzt mal ein ordentliches (Docker) Homegear Testsystem hergerichtet. Diese Version habe ich jetzt getestet und die funktioniert bei mir: Download

sathya · August 23, 2018, 4:33pm

Nein, der hier relevante Quelltext ist unverändert. Komisch, dass es jetzt klappt…

job · August 23, 2018, 9:35pm

Hat “leider” doch geklappt, die Logs habe ich in einer PN geschickt.

s4ndst0rm · August 24, 2018, 1:26pm

@gerrieg
Auch diese Version verbindet sich bei mir nicht mit homegear. Ich nutze die Openhab 2.3 stable. Ist das okay? Muss ich noch etwas beachten ?

gerrieg · August 24, 2018, 6:09pm

Das Homematic binding wurde in 2.4 von openHab nach Eclipse Smarthome migriert. Theoretisch hat sich nur das Package geändert:
org.openhab.binding.homematic -> org.eclipse.smarthome.binding.homematic

Aber momentan ist da wohl etwas in Durcheinander. Es gibt mehrere Probleme. Ob das 2.4-Snapshot auch in 2.3 funktioniert kann ich nicht sagen, da kenne ich den openHab core Teil zu wenig.

Wenn ich das Binding in der Entwicklungsumgebung starte, funktioniert es. Wenn ich den aktuellen 2.4’er Snapshot nehme und meine Version einspiele dann komischerweise nicht.

Es gibt jetzt zwei PullRequests:

Ich würde sagen, warten wir die beiden mal ab und dann probieren wir die Snapshot wieder. Vielleicht klappte es ja dann damit.