Kommunikation mit Openhab bricht ab - NEU

s4ndst0rm · August 1, 2018, 8:05am

Hi!

Die Lösung zum Thema

war doch noch nicht final.

Die Fehlermeldungen sind immer noch dieselben (nach 2 Tagen einwandfreier Laufzeit). Der Port 9126 ist aus dem docker Container erreichbar.

Allerdings hat es für mich den Anschein, dass die Verbindungen nicht mehr geschlossen werden.
Wenn ich auf dem Openhab WIndows Server ein “netstat -an” ausführe gibt es eine sehr lange Liste mit dem Port 9126. Sowohl Target als auch als Source.

Warum werden die Verbindungen nicht korrekt geschlossen?

Hier ein Auszug:

 TCP    172.31.2.193:9126      172.31.2.193:55028     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55041     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55044     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55053     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55065     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55066     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55069     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55087     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55088     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55089     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55110     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55114     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55116     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55130     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55133     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55134     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55137     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55156     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55163     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55165     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55176     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55179     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55185     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55187     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55200     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55211     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55212     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55224     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55231     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55233     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55245     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55256     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55257     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55269     HERGESTELLT
  TCP    172.31.2.193:9126      172.31.2.193:55277     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55278     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55287     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55301     HERGESTELLT
  TCP    172.31.2.193:9126      172.31.2.193:55306     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55309     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55323     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55325     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55330     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55348     HERGESTELLT
  TCP    172.31.2.193:9126      172.31.2.193:55349     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55353     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55367     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55371     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55374     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55392     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55395     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55398     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55414     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55418     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55421     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55422     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55443     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55444     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55448     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55464     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55468     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55473     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55488     HERGESTELLT
  TCP    172.31.2.193:9126      172.31.2.193:55494     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55501     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55508     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55514     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55521     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55532     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55544     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55545     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55561     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55565     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55566     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55588     SCHLIESSEN_WARTEN
  TCP    172.31.2.193:9126      172.31.2.193:55589     SCHLIESSEN_WARTEN

VIele Grüße

s4ndst0rm · August 2, 2018, 8:20am

Das Problem lag noch an der Rückmelde IP zwischen Docker und Windows. Wenn ich unter Callback Host in Openhab “host.docker.internal” eintrage werden die Ports sauber geschlossen und es läuft.

sathya · August 2, 2018, 9:16am

Ah ok, perfekt . Ich habe gerade deswegen einen OpenHAB-Test gestartet ;-).

Viele Grüße

Sathya

s4ndst0rm · August 3, 2018, 8:00am

Hi @sathya!

Leider schon wieder zu früh gefreut Es hat 2 Tage perfekt funktioniert. Es waren nur ca. 5-6 connections auf 9126 offen.
Seit gestern Abend sind wieder die Connections auf dem Openhab Host angestiegen bis sich der Docker Container eben selbst beendet hat.

Im Anhang die error Datei.

homegear.err (299,3 KB)

Liegt es evtl. an Openhab, dass die Verbindungen nicht richtig geschlossen werden?

Grüße!

sathya · August 3, 2018, 8:26am

Hallo @s4ndst0rm,

noch kann ich dir nicht sicher sagen, woran es liegt. Ich habe meinen Test hier mal wieder gestartet - hoffentlich kann ich es hier reproduzieren, das wäre das einfachste.

Viele Grüße

Sathya

job · August 3, 2018, 10:26am

Ich habe das Thema auch schon beobachtet. Ich bin mir auch ziemlich sicher, das das Thema schon einmal aufgetaucht und behoben worden ist. Jedenfalls kommen mir die Symptome unglaublich bekannt vor.

Ich setze aktuell 2285 ein, davor hatte ich 2282. Kann aber nicht sagen, ob es damit erst aufgetaucht ist, da ich kurz vorher von Openhabian-Jessi auf Openhabian-Stretch gewechselt bin. (Neuinstallation von allem. ;-))

Bei mir in openHAB stellt sich das so dar:

Verbindung zu Homegear verloren
Verbindung zu Homegear weider hergestellt
Alle Geräte werden wieder übertragen
Bevor alle Geräte wieder im Status “online” sind gibt es wieder:
Verbindung zu Homegear verloren

Das einzige was hilft, ist ein Neustart von openHAB.

sathya · August 3, 2018, 11:04am

Falls ihr es generiert bekommt: Könnt ihr mir noch einmal ein vollständiges Log auf Loglevel 4 posten (mit Nennung des Ausfallzeitpunktes, damit ich die Stelle schnell finde)?

s4ndst0rm · August 5, 2018, 7:50am

homegear.err (14,6 KB)
homegear.log (2,0 MB)
ports.txt (23,7 KB)

Hi @sathya,

im Anhang Logfiles auf dl4. Es lief einen Tag problemlos. Der Fehler begann 05.08.18 8:32.
Ab hier wird in Openhab homegear und dementsprechend alle Things als offline gekennzeichnet.

Weiterhin werden wieder extrem viele Ports nicht geschlossen (siehe ports.txt).

Die Kommunikation zu homegear funktioniert noch. Ich kann also die als offline gekennzeichneten Things steuern. Homegear meldet aber keinen Status mehr an openhab zurück.

Ein Neustart des Containers hat hier auch nicht geholfen. Ich musste openhab neustarten.

Meinen Container starte ich so:

docker run -d --rm -v E:\Docker\homegear\etc:/etc/homegear:Z -v E:\Docker\homegear\lib:/var/lib/homegear:Z -v E:\Docker\homegear\log:/var/log/homegear:Z -e TZ=Europe/Berlin -p 2001:2001 -p 2002:2002 -p 2003:2003 --name homegear homegear/homegear:nightly --restart always

sathya · August 6, 2018, 7:10am

Hallo @s4ndst0rm,

das Log hilft!!! OpenHAB versucht sich neu zu verbinden, während Homegear noch auf eine Antwort vom vorherigen init wartet - welche nie kommt. Die vom aktuellen init kommt dann ebenfalls ins Timeout.

Probier mal Folgendes, bevor ich den Quelltext anpasse:

Öffne die rpcclients.conf
Ergänze folgenden Abschnitt am Ende der Datei:

[OpenHAB]
hostname = host.docker.internal
timeout = 5000

Das reduziert den Timeout für den angegebenen Host auf 5 Sekunden. Falls das das Problem löst, passe ich den Quelltext für OpenHAB an bzw. überlege mir eine allgemeinere Lösung.

Viele Grüße

Sathya

s4ndst0rm · August 6, 2018, 9:33am

Test läuft… Ich melde mich.

s4ndst0rm · August 6, 2018, 9:35am

Hallo @sathya,

es hat eine Veränderung gebracht allerdings nicht positiv

Homegear+Openhab um 10:53 neugestartet mit neuem Parameter. 11:24 gleicher Fehler. Die offenen Ports sind auch schon da.

Das Timeout hat es also deutlich beschleunigt.

Gruß

sathya · August 6, 2018, 10:22am

Dann nimm mal 10 Sekunden (also timeout = 10000). Wenn der Fehler wieder auftritt, poste noch einmal das Log auf Loglevel 4 - mal sehen, woran es dann liegt. Wir bekommen das Problem schon gelöst ;-).

s4ndst0rm · August 6, 2018, 11:57am

homegear.err (19,8 KB)
homegear.log (151,7 KB)

Leider geht es mit 10 Sekunden auch nicht.
Im Anhang die Logfiles.

Die Fehler mit dem Lan-Gateway sind von einem Firmwareupdate eines Switches. Die kannst du ignorieren.

sathya · August 7, 2018, 10:36am

Mist, mein Fehler . Homegear versucht mehrere Reconnects. Setze es noch einmal auf 5 Sekunden und unter timeout retries = 1. Also:

[OpenHAB]
hostname = host.docker.internal
timeout = 5000
retries = 1

Viele Grüße

Sathya

s4ndst0rm · August 7, 2018, 1:33pm

homegear.err (58,6 KB)
homegear.log (733,8 KB)

@sathya

Diesmal hat es länger gehalten…

job · August 7, 2018, 1:38pm

Ich teste es gerade mit folgenden Werten:

[OpenHAB]
hostname = 10.10.10.10
timeout = 30000
retries = 1

Positiv ist schonmal, dass openHAB sich nach dem Neustart von Homegear wieder synchronisiert hat. Vorher half in diesem Fall nur ein Neustart von openHAB.

sathya · August 7, 2018, 2:30pm

Hallo @s4ndst0rm,

ok, jetzt läuft es wie erwartet - schade, dass der Fehler noch auftritt:

8/07/18 13:59:24.317 RPC client: Info: Reading from RPC server timed out. Server: host.docker.internal
08/07/18 13:59:24.317 Removing server "RF-51D140F6-BDA2-EA3E-ACE3-97D6CBC77848" after trying to send a packet 1 times. Server has to send "init" again.
08/07/18 13:59:34.325 RPC Server (Port 2001): Info: Client number 476 is calling RPC method: init (2) Parameters:

Heißt: Timeout und Anschließend Verbindungstrennung. Erst danach folgt das init(). So soll es eigentlich sein. Ich grübel und recherchiere mal, woran es liegen konnte. Die Info hilft aber bereits gewaltig.

Danke auch @job für’s Testen!!!

Viele Grüße

Sathya

sathya · August 7, 2018, 3:51pm

Hallo @s4ndst0rm, hallo @job,

ich vermute, das Problem hängt damit zusammen, dass OpenHAB ping() direkt im Anschluss an das init() ausführt:

08/06/18 13:54:13.489 RPC Server (Port 2001): Info: Client number 585 is calling RPC method: init (2) Parameters:
(String) binary://host.docker.internal:9126
(String) RF-51D140F6-BDA2-EA3E-ACE3-97D6CBC77848
(Integer) 34
08/06/18 13:54:13.489 Info: Client with IP ::ffff:172.17.0.1 is calling "init".
08/06/18 13:54:13.490 Info: Adding server "binary://host.docker.internal".
08/06/18 13:54:13.490 Info: Settings for host "host.docker.internal" found in "rpcclients.conf".
08/06/18 13:54:13.490 Info: Calling init methods on server "binary://host.docker.internal".
08/06/18 13:54:13.522 RPC Server (Port 2001): Info: Connection from ::ffff:172.17.0.1:41790 accepted. Client number: 586
08/06/18 13:54:13.523 RPC Server (Port 2001): Info: RPC server client id for client number 586 is: 101
08/06/18 13:54:13.523 RPC Server (Port 2001): Info: Client number 586 is calling RPC method: ping (2) Parameters:
(String) 51D140F6-BDA2-EA3E-ACE3-97D6CBC77848
08/06/18 13:54:23.555 RPC client: Info: Reading from RPC server timed out. Server: host.docker.internal

Es gibt jetzt zwei Möglichkeiten: Entweder an der Stelle sendet Homegear keine Antwort, obwohl eine erwartet wird oder Homegear sendet eine Antwort und OpenHAB antwortet dann nicht mehr auf die Init-Anfragen von Homegear. Zunächst einmal gehe ich von letzterem aus. Ich habe den Quelltext bereits angepasst, Homegear kompiliert und ein neues Nightly-Docker-Image erzeugt. Wenn ihr es einmal testen könntet, wäre das ganz klasse! Falls es jetzt funktioniert super, falls nicht, wäre ein Log auf Loglevel 5 klasse. Da werden die Pakete mitgeloggt.

Viele Grüße

Sathya

s4ndst0rm · August 7, 2018, 4:31pm

@sathya

Hört sich gut an! Ich spiele den Container gleich ein. Mit welchem timeout? 30000?

sathya · August 7, 2018, 4:47pm

Ja, es sollte auch mit 30000 funktionieren.