Eintrag im hmserver.log (I/O exception (java.net.NoRouteToHostException) caught when connecting to...)

[Baxxy]

Hallo und guten Morgen,
bei einer routinemäßigen Prüfung des Logfiles der CCU mit Raspberrymatic 3.47.18.20190918 ist mir folgender Eintrag, der alle paar Sekunden erscheint, aufgefallen.

Code: Alles auswählen

Sep 28 01:05:25 org.apache.http.impl.client.DefaultHttpClient INFO  [vert.x-worker-thread-15] I/O exception (java.net.NoRouteToHostException) caught when connecting to {}->http://192.168.113.10:2000: No route to host (Host unreachable) 
Sep 28 01:05:25 org.apache.http.impl.client.DefaultHttpClient INFO  [vert.x-worker-thread-15] Retrying connect to {}->http://192.168.113.10:2000 
Sep 28 01:05:28 org.apache.http.impl.client.DefaultHttpClient INFO  [vert.x-worker-thread-15] I/O exception (java.net.NoRouteToHostException) caught when connecting to {}->http://192.168.113.10:2000: No route to host (Host unreachable) 
Sep 28 01:05:28 org.apache.http.impl.client.DefaultHttpClient INFO  [vert.x-worker-thread-15] Retrying connect to {}->http://192.168.113.10:2000 
Sep 28 01:05:32 org.apache.http.impl.client.DefaultHttpClient INFO  [vert.x-worker-thread-15] I/O exception (java.net.NoRouteToHostException) caught when connecting to {}->http://192.168.113.10:2000: No route to host (Host unreachable)

Infos zur Umgebung: Die CCU (RPi3B mit RPI-RF-MOD) steht im Ferienhäuschen und ist per VPN (über's Mobilfunknetz) mit dem Heimnetz verbunden. Normalerweise greife ich vom Laptop zu Hause (IP: 192.168.113.10) auf die CCU zu. Hauptsächlich über die WebUI und mit Black's SDV. Getestet habe ich aber auch mal den Homematic Manager, AIO Creator Neo und sogar den HausMeister(Windows-App).

Ist mein Laptop zu Hause eingeschalten verschwindet der Fehler. Sobald er aber im StandBy ist gehen die Einträge wieder los und schreiben das Log voll. Das kann ich auch nachvollziehen, Irgendwas auf der CCU will mit irgendwas auf meinem Laptop kommunizieren und wenn der Aus ist schlägt das natürlich fehl.

In Verdacht habe ich den Homematic Manager. Ist der auf dem Laptop aktiv bekomme ich in Black's SDV unter CCU Diagnostics --> Systemübersicht folgendes:

Nach dem beenden des Homematic Managers und folgendem Eintrag im Log...

Code: Alles auswählen

Sep 28 08:14:38 de.eq3.cbcs.legacy.bidcos.rpc.internal.LegacyNotificationHandler WARN  [vert.x-worker-thread-1] Remove interface: hmm_HmIP http URL: http://192.168.113.10:2000 from client list because of communication problem

sieht es dann so aus:

Es verbleibt ein Verweis auf die IP-Adresse des Laptops zu Hause und ist möglicherweise die Ursache des Problems.

Gefühlt zehrt dieses ständige "Nach-Hause-Telefonieren" an meinem Datenvolumen und ich möchte es irgendwie loswerden. Leider bin ich etwas ratlos wo ich ansetzen soll.

Zur Analyse hänge ich mal das (gekürzte) Logfile an. Sollte das komplette Log benötigt werden würde ich es per PN senden.
Relevante Zeiten im Log:
Sep 28 01:05:25 - Schlafenszeit, Laptop aus
Sep 28 07:49:31 - zu früh aufgestanden, Laptop an
Sep 28 08:03:15 - Homematic Manager gestartet
Sep 28 08:14:38 - Homematic Manager beendet

Beste Grüße
Baxxy

[Baxxy]

Ein weiterführender Test mit einer lokalen CCU ergab, das der Homematic Manager tatsächlich (indirekt) daran beteiligt ist.

Beim starten des HM Managers geschieht auf beiden CCU's dasselbe.
per VPN angebundene CCU:

Code: Alles auswählen

Sep 28 08:03:15 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO  [vert.x-eventloop-thread-1] (un)registerCallback on VirtualDeviceHandlerRega called from url: http://192.168.113.10:2000 
Sep 28 08:03:15 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO  [vert.x-eventloop-thread-1] Added InterfaceId: hmm_VirtualDevices 
Sep 28 08:03:15 de.eq3.ccu.virtualdevice.service.internal.rega.BackendWorker INFO  [vert.x-worker-thread-16] Execute BackendCommand: de.eq3.ccu.virtualdevice.service.internal.rega.BackendUpdateDevicesCommand 
Sep 28 08:03:15 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO  [vert.x-worker-thread-1] (un)registerCallback on LegacyServiceHandler called from url: http://192.168.113.10:2000 
Sep 28 08:03:15 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO  [vert.x-worker-thread-1] init finished 
Sep 28 08:03:15 de.eq3.cbcs.legacy.bidcos.rpc.internal.InterfaceInitializer INFO  [vert.x-worker-thread-4] Added InterfaceId: hmm_HmIP 
Sep 28 08:03:16 de.eq3.ccu.virtualdevice.service.internal.rega.BackendUpdateDevicesCommand INFO  [vert.x-worker-thread-16] updateDevicesForClient -> 35 device addresses will be added

lokale CCU:

Code: Alles auswählen

Sep 28 10:32:45 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO  [vert.x-worker-thread-1] (un)registerCallback on LegacyServiceHandler called from url: http://192.168.113.10:2000 
Sep 28 10:32:45 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO  [vert.x-worker-thread-1] init finished 
Sep 28 10:32:45 de.eq3.cbcs.legacy.bidcos.rpc.internal.InterfaceInitializer INFO  [vert.x-worker-thread-4] Added InterfaceId: hmm_HmIP 
Sep 28 10:32:45 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO  [vert.x-eventloop-thread-5] (un)registerCallback on VirtualDeviceHandlerRega called from url: http://192.168.113.10:2000 
Sep 28 10:32:45 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO  [vert.x-eventloop-thread-5] Added InterfaceId: hmm_VirtualDevices 
Sep 28 10:32:45 de.eq3.ccu.virtualdevice.service.internal.rega.BackendWorker INFO  [vert.x-worker-thread-16] Execute BackendCommand: de.eq3.ccu.virtualdevice.service.internal.rega.BackendUpdateDevicesCommand 
Sep 28 10:32:45 de.eq3.cbcs.legacy.bidcos.rpc.internal.DeviceUtil INFO  [vert.x-worker-thread-4] updateDevicesForClient hmm_HmIP -> 52 device addresses will be added

Aber beim beenden des HM Managers gibt es Unterschiede.
per VPN angebundene CCU: (ca. 5 Minuten nach beenden des HM Managers)

Code: Alles auswählen

Sep 28 08:14:38 de.eq3.cbcs.legacy.bidcos.rpc.internal.LegacyNotificationHandler WARN  [vert.x-worker-thread-1] Remove interface: hmm_HmIP http URL: http://192.168.113.10:2000 from client list because of communication problem

lokale CCU: (einige Sekunden nach beenden des HM Managers)

Code: Alles auswählen

Sep 28 10:42:47 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO  [vert.x-worker-thread-0] (un)registerCallback on LegacyServiceHandler called from url: http://192.168.113.10:2000 
Sep 28 10:42:47 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO  [vert.x-worker-thread-0] Removed InterfaceId: hmm_HmIP 
Sep 28 10:42:47 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO  [vert.x-eventloop-thread-5] (un)registerCallback on VirtualDeviceHandlerRega called from url: http://192.168.113.10:2000 
Sep 28 10:42:47 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO  [vert.x-worker-thread-0] init finished 
Sep 28 10:42:47 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO  [vert.x-eventloop-thread-5] Removed InterfaceId:

Obwohl die entfernte CCU (über das VPN) vollen Zugriff auf das Heimnetz hat und auch die lokale Firewall (für diese Tests) aus war scheint da irgendwas zu hängen.

Grüße
Baxxy

[hobbyquaker]

Ich vermute dass da der Timeout im Homematic-Manager für den "de-init" (der beim Beenden ausgeführt wird) auf VirtualDevices zu kurz ist. Scheinbar dauert das über die VPN Verbindung etwas länger und der hm-manager geht da "zu ungeduldig" zu Werke.

Ich hätte allerdings gehofft dass das kein Problem ist da Inits von Clients die nicht mehr Antworten nach ein paar fehlgeschlagenen Versuchen vom Schnittstellenprozess (in dem Fall hmipserver/VirtualDevices) beendet werden sollten, im Log erscheint dann "Remove interface: ... from client list because of communication problem".

Das Problem hier ist dass der hmipserver das wohl für den Init auf Port 2010 (Init id hmm_HmIP) tut - aber nicht für den Init auf Port 9292 (Init id hmm_VirtualDevices).

Ich denke hier sollten 2 Aktionen erfolgen: Einmal ein Bugreport im OCCU Repo dass der VirtualDevices Teil vom hmipserver Inits nicht rauswirft wenn ein Client nicht mehr Antwortet sowie ein Bugreport im homematic-manager Repo damit ich nicht vergess im nächsten Release den de-init Timeout zu erhöhen.

[Baxxy]

Hallo hobbyquaker,
vielen Dank für deine ausführliche und auch für mich verständliche Antwort. Wenn ich die Tage Zeit finde werde ich die entsprechenden Bugreports anlegen. Wäre das hier: https://github.com/eq-3/occu/issues und hier: https://github.com/hobbyquaker/homematic-manager/issues richtig. Ich bin nicht so firm mit Github und hoffe das ich auch in deutsch etwas hinterlassen kann und deine Antwort hier verlinken darf.

Grüße
Baxxy

Nachtrag: Ich habe das Problem durch Neustart der entfernten CCU und "nichtbenutzen" des HM Managers temporär gelöst.

[hobbyquaker]

Ich bin nicht so firm mit Github und hoffe das ich auch in deutsch etwas hinterlassen kann und deine Antwort hier verlinken darf.

Klar, kannst gerne Verlinken. Im OCCU Issue Tracker kannst Du imho problemlos auch auf Deutsch posten, ist sowieso die Muttersprache der Leute die das hoffentlich lesen

Habe den "De-Init" Timeout des Hm-Managers mit Version 2.5.1 nun von 5 auf 15 Sekunden erhöht. Könnte helfen das Problem bei Dir zu vermeiden, aber garantieren kann ich das leider nicht. Dass der hmipserver auf dem VirtualDevices Interface die Inits von Clients die nicht mehr erreichbar sind nicht rauswirft ist aus meiner Sicht der eigentliche Bug der gefixt werden müsste.

[Baxxy]

Hallo hobbyquaker,
den Bugreport im OCCU-Repo habe ich erstellt. Mal schauen ob er verständlich genug ist und sich damit jemand befasst.
Da du ja schon eine neue Version mit verändertem TimeOut erstellt hast, spare ich mir den Bugreport im homematic-manager Repo.
Ich würde die neue Version auch gerne testen, wenn es (für den Fall das der TimeOut nicht funktioniert) eine Möglichkeit gibt den "De-Init" manuell (also per Console z.B.) auszuführen. Neustart der CCU oder des HmIP-Servers möchte ich momentan vermeiden das das Ferienhäuschen, trotz miesem Wetter, von Gästen bewohnt wird.

Grüße
Baxxy