HM485 disconnect bei automatisiertem Backup und fehlgeschlagenen HTTPMOD-Abruf

[Svnm]

Hallo zusammen,

folgender Sachverhalt: Ich lasse jeden Sonntag um 3:15 Uhr automatisiert ein Backup ausführen. Leider ist es dann immer so, dass nach dem Backup das HM485-Gateway getrennt wird.
Unglücklicherweise sollte gestern genau diesem Zeitpunkt die Heizung eingeschaltet werden, was leider nicht funktionierte, da das Gateway zu genau diesem Zeitpunkt getrennt war und das DOIF hierzu nicht auslöste.

Das Backup wird durch folgendes DOIF ausgeführt:

Code Auswählen Erweitern

([03:15|1]) (backup,set Push msg 'Fhem' 'Backup durchgeführt' '' -1 '')

Code Auswählen Erweitern

2016.12.05 03:15:00 2: Backup with command: tar -cf - "./CHANGED" "./configDB.pm" "./contrib" "./demolog" "./docs" "./FHEM" "./fhem.cfg" "./fhem.cfg.demo" "./fhem.pl" "./FRITZBox_Telefonbuch.xml" "./log" "./README_DEMO.txt" "./restoreDir" "./unused" "./www" |gzip > /mnt/USB-Stick/Backups/FHEM-20161205_031500.tar.gz
2016.12.05 03:15:26 1: backup done: FHEM-20161205_031500.tar.gz (29160437 Bytes)
2016.12.05 03:15:26 2: Sicherung: backup:
backup done: FHEM-20161205_031500.tar.gz (29160437 Bytes)
2016.12.05 03:15:26 1: 192.168.1.11:1000 disconnected, waiting to reappear (HM485_LAN)
2016.12.05 03:15:27 3: HM485_LAN: connected to device 192.168.1.11:1000
2016.12.05 03:15:27 1: 192.168.1.11:1000 reappeared (HM485_LAN)
2016.12.05 03:15:27 3: HM485_LAN: Lan Device Information
2016.12.05 03:15:27 3: HM485_LAN: Protocol-Version: 01
2016.12.05 03:15:27 3: HM485_LAN: Interface-Type: eQ3-HMW-LGW
2016.12.05 03:15:27 3: HM485_LAN: Firmware-Version: 1.0.4
2016.12.05 03:15:27 3: HM485_LAN: Serial-Number: MEQ0406842
2016.12.05 03:15:27 3: HM485_LAN: Initialize the interface

Führe ich das Backup händisch auf der Weboberfläche per backup aus, kommt es zu keinem Disconnect
Im Log erscheint auch nur:

Code Auswählen Erweitern

2016.12.06 13:14:48 2: Backup with command: tar -cf - "./CHANGED" "./configDB.pm" "./contrib" "./demolog" "./docs" "./FHEM" "./fhem.cfg" "./fhem.cfg.demo" "./fhem.pl" "./FRITZBox_Telefonbuch.xml" "./log" "./README_DEMO.txt" "./restoreDir" "./unused" "./www" |gzip > /mnt/USB-Stick/Backups/FHEM-20161206_131448.tar.gz
Backup done

Dieses Problem habe ich seit Einrichtung von Homematic Wired vor einigen Monaten. Es ist jeden Montag-Morgen das selbe 
Zusätzlich ist mir auch aufgefallen, dass ein Disconnect auftritt, wenn das Modul (via HTTPMOD), welches den Benzinpreis abruft, die Internetseite nicht erreichen kann.

Code Auswählen Erweitern

2016.12.06 03:10:53 3: Tankstelle_HEM: Read callback: request type was update retry 0,
Header: HTTP/1.1 200 OK
Date: Tue, 06 Dec 2016 02:00:13 GMT
Server: Apache/2.2.22 (Ubuntu)
Vary: Accept-Encoding
Content-Type: text/html; charset=utf-8
Connection: close, body empty,
Error: gethostbyname www.clever-tanken.de failed
2016.12.06 03:10:55 1: 192.168.1.11:1000 disconnected, waiting to reappear (HM485_LAN)
2016.12.06 03:11:36 3: HM485_LAN: connected to device 192.168.1.11:1000
2016.12.06 03:11:36 1: 192.168.1.11:1000 reappeared (HM485_LAN)
2016.12.06 03:11:37 3: HM485_LAN: Lan Device Information
2016.12.06 03:11:37 3: HM485_LAN: Protocol-Version: 01
2016.12.06 03:11:37 3: HM485_LAN: Interface-Type: eQ3-HMW-LGW
2016.12.06 03:11:37 3: HM485_LAN: Firmware-Version: 1.0.4
2016.12.06 03:11:37 3: HM485_LAN: Serial-Number: MEQ0406842
2016.12.06 03:11:37 3: HM485_LAN: Initialize the interface
2016.12.06 03:11:38 3: HMW_IO_12_Sw14_DR_MEQ0370248: RESPONSE TIMEOUT for 00012451
2016.12.06 03:11:43 3: HM485_LAN: Initialisierung von Modul 00012451
2016.12.06 03:11:43 3: HMW_IO_12_Sw14_DR_MEQ0370248: Request config for device 00012451
2016.12.06 03:11:43 3: HMW_IO_12_Sw14_DR_MEQ0370248: Lese Eeprom 00012451

Fhem läuft auf einem Raspberry 2. Betriebssystem und Fhem selbst sind auf den neusten Stand. Auf des Raspberry läuft nur Fhem, keine zusätzlichen Programme.
Der Raspberry und das HM485_LAN hängen am selben Switch.

Vielleicht weiß einer von Euch Rat und kann mir hier weiterhelfen, diese Disconnnects abzustellen.
Weitere Daten kann ich gerne zur Verfügung stellen.

Vielen Dank schonmal!

[Thorsten Pferdekaemper]

Hi,
zuerst dachte ich: Alles klar, da dauert irgend etwas zu lange, so dass der HM485_LAN seine Keepalive-Antwort nicht bekommt. Wenn ich mir aber das Coding anschaue, dann werde ich nicht so richtig schlau draus.
Ich bin noch am Forschen, aber ich bin mir ziemlich sicher, dass da irgendwas zu lange blockiert.
Gruß,
   Thorsten

[Thorsten Pferdekaemper]

Hi,
ich habe gestern mal versucht, das Problem nachzuvollziehen. Ich glaube aber, dass Du einen dieser Original-eq3-Buskoppler hast. Den habe ich selbst nie zum Laufen gebracht. Ich habe bei mir ungefähr einmal am Tag ein Disconnect des Funk-HMLANs, aber mein HM485 ist durch nichts aus der Ruhe zu bringen.
Ich glaube nicht, dass der Disconnect durch den "Keepalive"-Mechanismus im 00_HM485_LAN kommt. Ich denke eher, dass das DevIo.pm selbst die Disconnects fabriziert. Ich weiß allerdings nicht, was da schiefgeht. Ich habe die Vermutung, dass es immer dann Probleme macht, wenn eine andere TCP-Verbindung zu lange braucht. Vielleicht kann da noch jemand anders etwas dazu sagen, der sich mit den DevIo-Feinheiten auskennt.
Gruß,
   Thorsten

[Thorsten Pferdekaemper]

So, jetzt habe ich dazu auch mal im Developer-Teil des Forums nachgefragt: https://forum.fhem.de/index.php/topic,62102.0.html.
Gruß,
   Thorsten

[Ralf9]

Vielleicht weiß einer von Euch Rat und kann mir hier weiterhelfen, diese Disconnnects abzustellen.
Weitere Daten kann ich gerne zur Verfügung stellen.

Im "Keepalive"-Mechanismus sind noch Fehler. Ich habe sie in der Version in der Anlage behoben.
Ich habe auch die Log Ausgabe erweitet und das nonblocking connect eingebaut.
Mich würde damit ein log mit verbose 3 interessieren.

So sieht ein log aus bei einem disconnected durch keepalive

Code Auswählen Erweitern

2016.12.07 20:47:15.559 3 : HM485_LAN2: KeepAliveCheckRetry 0
2016.12.07 20:47:15.559 3 : HM485_LAN2: keepalive retry = 0
2016.12.07 20:47:36.565 3 : HM485_LAN2: KeepAliveCheckRetry 1
2016.12.07 20:47:36.565 3 : HM485_LAN2: keepalive retry = 1
2016.12.07 20:47:57.573 3 : HM485_LAN2: KeepAliveCheckRetry 2
2016.12.07 20:47:57.573 3 : HM485_LAN2: keepalive retry = 2
2016.12.07 20:48:18.583 3 : HM485_LAN2: KeepAliveCheckRetry 3
2016.12.07 20:48:18.583 3 : HM485_LAN2: keepalive retry count reached. Disonnect
2016.12.07 20:48:18.583 1 : 192.168.0.94:1000 disconnected, waiting to reappear (HM485_LAN2)
2016-12-07 20:48:18.585 HM485_LAN HM485_LAN2 DISCONNECTED
2016.12.07 20:48:26.596 3 : HM485_LAN2: LAN_Connect: connect to http://192.168.0.94:1000 timed out
2016.12.07 20:50:34.067 3 : HM485_LAN2: connected to device 192.168.0.94:1000
2016.12.07 20:50:34.071 1 : 192.168.0.94:1000 reappeared (HM485_LAN2)
2016-12-07 20:50:34.073 HM485_LAN HM485_LAN2 CONNECTED
2016.12.07 20:50:34.074 3 : HM485_LAN2: Lan Device Information
...
2016.12.07 20:50:34.074 3 : HM485_LAN2: Initialize the interface

Gruß Ralf

[Thorsten Pferdekaemper]

Hi,

ich glaube, dass im vorliegenden Fall der Disconnect gar nicht vom Keepalive-Mechanismus kommt. Das liegt vor Allem daran, dass er gar nicht funktioniert. Ich denke vielmehr, dass die Disconnects direkt vom DevIo.pm getriggert werden. Mir ist es nur nicht gelungen, das nachzuvollziehen.

Was ich jetzt im anderen Thread erfahren habe: Das backup-Kommando geht nicht in den Hintergrund, wenn es durch, at, notify oder auch DOIF aufgerufen wird. Das bedeutet (laut der Log-Ausgabe am Anfang dieses Threads), dass das System 26 Sekunden blockiert war. Es ist kein Wunder, dass das Probleme macht, aber nicht einmal hier konnte ich ein Disconnect provozieren.
Ich würde allerdings dennoch die Sache mit dem backup anders machen.

...ich werde aber weiterforschen.

Gruß,
   Thorsten

[Thorsten Pferdekaemper]

Hi,
ich habe jetzt mal eine fiese Vermutung. Wir reden hier von einem Original-eq3-Gateway. Ich glaube, dass das Teil so ungefähr alle 20 Sekunden eine "Keepalive"-Message braucht. Wenn die nicht einigermaßen pünktlich kommt (ich glaube, es gehen auch mal 30 Sekunden), dann schließt das Ding von sich aus die Verbindung. D.h. es können "schon" 10 Sekunden Blockieren in FHEM reichen, um die Verbindung zu verlieren.
...wie gesagt, nur eine Vermutung.
Dass das backup wahrscheinlich etwa 26 Sekunden blockiert wissen wir ja schon. Beim HTTPMOD bin ich mir nicht so sicher. Da kommt's vielleicht darauf an, warum ein Aufruf nicht klappt.
Gruß,
    Thorsten

[r00t2]

...Was ich jetzt im anderen Thread erfahren habe: Das backup-Kommando geht nicht in den Hintergrund, wenn es durch, at, notify oder auch DOIF aufgerufen wird. ...
Ich würde allerdings dennoch die Sache mit dem backup anders machen. ...

Da ich im Dev Forum nicht posten kann frage ich hier mal mit nach.
Auf meinem RPi2 dauert das Backup ebenfalls knapp 30s - was schon ein ziemlich langes "Blocking" des Systems ist. Welche anderen Möglichkeiten gibt es, das Backup zeitgesteuert _und_ im Hintergrund durchzuführen?

[Thorsten Pferdekaemper]

Hi,
das gehört zwar nicht so ganz hierher, aber der OP hat anscheinend sowieso ein bisschen das Interesse verloren.
Also ich mache das Backup mit rsync und cron, also gar nicht per fhem.
Gruß,
   Thorsten

[r00t2]

Hi und danke für die (halb-OT) Antwort!

[Thorsten Pferdekaemper]

Ich habe den Eindruck, dass der OP das Interesse an der Sache verloren hat.
Falls sonst noch jemand einen halbwegs funktionierenden eq3-HMLAN hat und vielleicht ein ähnliches Problem vermutet, dann bitte mal melden. Vielleicht können wir das Problem doch lösen.
Gruß,
   Thorsten

[twix]

Hallo,

ich weiss nicht, ob es hilft, aber ich habe das Problem, das wenn meine Modbus TCP abfrage schief geht auch häufig mein HMLAN auf disconnect geht.

Gruss,
Rainer.

[Thorsten Pferdekaemper]

Hi,
anscheinend macht 00_HMLAN.pm auch irgend so einen Keepalive-Kram etwa alle 25 Sekunden. Ich habe aber keine Ahnung, ob der (Funk-)HMLAN das wirklich braucht.
...mal Martin fragen. Ich mache ihn mal darauf aufmerksam.
Gruß,
   Thorsten

[Svnm]

Hallo zusammen,

ich hätte nicht gedacht, dass in so kurzer Zeit schon so viele Beiträge geschrieben werden. Mir ist leider sehr viel dazwischen gekommen, deshalb konnte ich erst heute wieder im Forum vorbeischauen.
Vielen Dank Thorsten für deine großen Mühe und deine in Anspruch genommene Zeit! Das gilt natürlich auch für die vielen anderen aus diesem Thread
Selbstverständlich bin ich weiterhin an einer Lösung interessiert.

Ich kann per rsync die Daten des Ordners /fhem sichern und stattdessen das DOIF mit dem backup deaktivieren. Damit wäre diesem Problem Abhilfe geschaffen, wobei dann aber die mögliche Ursache weiterhin unbehandelt ist.

Schließlich kommt es sowohl sporadisch bei dem HTTPMOD, als auch bei dem Wetter-Modul zu Abbrüchen.

Code Auswählen Erweitern

2016.12.06 03:19:43 3: Wetter: gethostbyname query.yahooapis.com failed
2016.12.06 03:19:45 1: 192.168.1.11:1000 disconnected, waiting to reappear (HM485_LAN)
2016.12.06 03:19:45 3: HM485_LAN: connected to device 192.168.1.11:1000
2016.12.06 03:19:45 1: 192.168.1.11:1000 reappeared (HM485_LAN)
2016.12.06 03:19:45 3: HM485_LAN: Lan Device Information
2016.12.06 03:19:45 3: HM485_LAN: Protocol-Version: 01
2016.12.06 03:19:45 3: HM485_LAN: Interface-Type: eQ3-HMW-LGW
2016.12.06 03:19:45 3: HM485_LAN: Firmware-Version: 1.0.4
2016.12.06 03:19:45 3: HM485_LAN: Serial-Number: MEQ0406842
2016.12.06 03:19:45 3: HM485_LAN: Initialize the interface

Wie schon richtig vermutet, verwende ich die Original-Komponenten von EQ3, dass heißt sowohl das Gateway, die Bus-Teilnehmer und auch der Bus-Abchlusswiderstand sind von Homematic-Wired.

Ihr scheint ja schon sehr viel unternommen zu haben um der Ursache auf die Spur zu kommen. Wie kann ich euch hier weiterhelfen? Und welche Daten kann ich euch noch bereitstellen?

Herzlichen Dank 

[Svnm]

Ich habe jetzt nochmal die Datei von Ralf eingebaut.
Es bringt leider keine Verbesserung. Weiterhin wird bei DOIF-gesteuerten backup die Verbindung getrennt.