Blocking DNS in HttpUtils_NonblockingGet

rudolfkoenig · 03 Juli 2016, 11:57:48

Die Loesung ist mAn einfach: man setzt vor dem ersten DevIo_OpenDev ein Flag. Sobald der Flag gesetzt ist, wird kein zweites DevIo_OpenDev versucht, bzw. erst dann, wenn der erste endgueltig gescheitert ist.

Noch einfacher ist es, falls eine staendige Verbindung sinnvoll ist: Define/ReadyFn oeffnet die Verbindung, und WriteFn schreibt nur dann, falls die Verbindung existiert. Falls sie nicht existiert, kann man die Daten sammeln, oder einen Fehler melden.

StefanStrobel · 03 Juli 2016, 12:57:23

Zitat
Die Loesung ist mAn einfach: man setzt vor dem ersten DevIo_OpenDev ein Flag. Sobald der Flag gesetzt ist, wird kein zweites DevIo_OpenDev versucht, bzw. erst dann, wenn der erste endgueltig gescheitert ist.

Genau so würde ich das gerne machen. Die Frage, an der ich nicht weiter komme ist:
Wann ist der erste Verbindungsversuch endgueltig gescheiter?

Nach Aufruf von DevIo_OpenDev ist ja noch alles offen, da es nicht blockiert.
Der Callback wird in den meisten Fällen von DevIo_OpenDev aufgerufen, aber eben nicht in allen Fällen.
Wenn wie bei NEXT_OPEN der Callback nicht aufgerufen wird, weiss ich nicht woran ich erkennen kann, ob der letzte Verbindungsversuch noch läuft ...

Gruss
Stefan

rudolfkoenig · 04 Juli 2016, 09:22:57

ZitatWann ist der erste Verbindungsversuch endgueltig gescheiter?

Die Reihenfolge sollte sein:
- aus dem moduleigenen DefineFn/etc wird DevIo_OpenDev aufrufen
- Verbindungsaufbau geht schief
- DevIo_OpenDev aktiviert readyfnlist
- Callback wird aufgerufen, meldet Fehler
- das Modul-Eigene ReadyFn wird regelmaessig aufgerufen, hier wird DevIo_Opendev auch aufgerufen.
- wenn die Verbindung klappt, wird der callback (aus diesem ReadyFn-DevIo_Opendev) aufgerufen
- wenn nicht, wird nichts aufgerufen.

Falls das nicht der Fall ist, dann bitte melden.

StefanStrobel · 04 Juli 2016, 19:35:47

Zitat
Zitat
Zitat
Die Loesung ist mAn einfach: man setzt vor dem ersten DevIo_OpenDev ein Flag. Sobald der Flag gesetzt ist, wird kein zweites DevIo_OpenDev versucht, bzw. erst dann, wenn der erste endgueltig gescheitert ist.
Genau so würde ich das gerne machen. Die Frage, an der ich nicht weiter komme ist:
Wann ist der erste Verbindungsversuch endgueltig gescheitert?
Die Reihenfolge sollte sein:
- aus dem moduleigenen DefineFn/etc wird DevIo_OpenDev aufrufen
- Verbindungsaufbau geht schief
- DevIo_OpenDev aktiviert readyfnlist
- Callback wird aufgerufen, meldet Fehler
- das Modul-Eigene ReadyFn wird regelmaessig aufgerufen, hier wird DevIo_Opendev auch aufgerufen.
- wenn die Verbindung klappt, wird der callback (aus diesem ReadyFn-DevIo_Opendev) aufgerufen
- wenn nicht, wird nichts aufgerufen.

Falls das nicht der Fall ist, dann bitte melden.

Da sind wir wieder an dem Punkt: wenn (im Fehlerfall) nichts aufgerufen wird, wie bekommt das Modul dann mit dass der letzte Verbindungsversuch endgültig gescheitert ist um daraufhin das Flag zu löschen, so dass beim nächsten Aufruf der Modul-eigenen ReadyFn von dort aus wieder DevIo_OpenDev aufgerufen werden darf?
In der Reihenfolge, die Du gerade beschrieben hast, kommt das mit dem Flag nicht mehr vor.

Auch wenn die Verbindung nicht aufgebaut wird oder im Fehlerfall wird ja bisher schon in fast allen Fällen der Callback aufgerufen:

Zeile 250:

Code Auswählen


if($hash->{DevIoJustClosed}) {
    delete $hash->{DevIoJustClosed};
    return &$doCb(undef);
}

Zeile 341:

Code Auswählen


return &$doCb($err ? $err : &$doTailWork());

oder ausserhalb des TCP-Bereichs in Zeile 267:

Code Auswählen


if($@) {
      Log3 $name, 1, $@;
      return &$doCb($@);
}

Daher fände ich es nur konsequent wenn auch in Zeile 306 der Callback aufgerufen würde. Das würde mein Problem lösen - ich könnte im Callback das Flag löschen und es würde der Programmlogik des obigen Fragments (ab Zeile 250) entsprechen.

Code Auswählen


if($hash->{NEXT_OPEN} && time() < $hash->{NEXT_OPEN}) {
      return undef;
      # hier würde ich mir genauso wie oben bei if($hash->{DevIoJustClosed}) statt dem einfachen return einen Aufruf des Callback wünschen:
      # return &$doCb(undef);
}

Ich hoffe ich konnte mein Anliegen doch noch verständlich erklären.

Gruss
Stefan

rudolfkoenig · 05 Juli 2016, 10:06:29

Nicht wirklich, ich habe dein Wunsch aber trotzdem eingecheckt, da (wie du es gezeigt hast) das Verhalten auch an anderen Stellen inkonsequent ist, und mir die Zeit/Energie/Lust fehlt, alles auf "sauber" umzubauen.

betateilchen · 05 Juli 2016, 20:59:02

Hallo Rudi,

die aktuell in SVN vorhandene Version der DevIo.pm sorgt zuverlässig dafür, dass mein fhem nicht mehr startet.

Mit der Version

Code Auswählen

DevIo.pm 11732 2016-07-02 17:41:31Z rudolfkoenig

ist alles wieder in bester Ordnung.

rudolfkoenig · 05 Juli 2016, 21:53:59

Ich fuerchte, wenn ich nicht mehr Details kriege, wird es dabei bleiben.

betateilchen · 05 Juli 2016, 22:10:53

Ok, dann musst Du es eben morgen fixen, wenn nach dem morgendlichen Update (vorhersehbar) noch mehr Leute ein nicht mehr funktionierendes fhem haben. Aber sag dann bitte nicht, Du hättest nichts gewußt

Das System startet, läuft kurze Zeit, stürzt dann ab (ohne dass im Logfile etwas aussergewöhnliches zu erkennen wäre) und landet in der automatischen restart-Schleife von systemd. Dann beginnt das Spiel von vorne.

Ich kann Dir heute leider nicht mehr Details zum Problem liefern, ausser, dass ich das Verhalten heute abend auf drei verschiednenen fhem Installationen hatte, die mit der neusten Version von DevIo.pm arbeiteten. Nach dem Downgrade der Datei auf die angegebene Vorgängerversion liefen alle drei Systeme wieder.

betateilchen · 06 Juli 2016, 11:05:08

Zitat von: betateilchen am 05 Juli 2016, 22:10:53
Ok, dann musst Du es eben morgen fixen, wenn nach dem morgendlichen Update (vorhersehbar) noch mehr Leute ein nicht mehr funktionierendes fhem haben.

q.e.d.

https://forum.fhem.de/index.php/topic,55332.0.html

betateilchen · 06 Juli 2016, 20:38:24

Zitat von: rudolfkoenig am 06 Juli 2016, 13:38:12
Das Problem kam dann, wenn ein per TCP/IP angebundenes Geraet nicht erreichbar war.
Habs vermutlich jetzt gefixt, ...

Hallo Rudi,

ich habe die Änderung nun auch hier erfolgreich getestet, danke.

Wobei ich den Punkt "ein per TCP/IP angebundenes Gerät" nicht nachvollziehen kann, da es auf meinem Entwicklungs-Raspberry ausser einer FHEMWEB und einer telnet Instanz keine anderen TCP/IP basierten Geräte gibt und der Fehler trotzdem auftrat.

Offenbar hatte fhem da eine Auto-Immunkrankheit und war mit sich selbst unverträglich

betateilchen · 07 Juli 2016, 14:10:36

Ich muss das nochmal aufgreifen, auch wenn ich mich fast nicht traue. Irgendwas stimmt immer noch nicht, FHEM2FHEM flutet mir den eventMonitor und das Logfile:

Code Auswählen


2016.07.07 14:00:58 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:58 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:58 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:58 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:58 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:58 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:58 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:58 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:58 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:58 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:58 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:00:59 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)

Vermutlich unnötig, zu sagen, dass mit der bereits erwähnten Version 11732 von DevIo.pm diese Meldungsflut nicht auftritt.

rudolfkoenig · 07 Juli 2016, 14:30:10

Waere ich zu frech, wenn ich ein Log-Ausschnitt mit einem hoeheren verbose-level haben wollte?

betateilchen · 07 Juli 2016, 14:59:28

im Prinzip nicht, aber auch mit global verbose 5 und FHEM2FHEM-device verbose 5 läßt sich auch dem Logfile nicht viel mehr entlocken:

Code Auswählen


2016.07.07 14:44:46 3: FHEM2FHEM opening fhemenocean at 192.168.123.159:7172
2016.07.07 14:44:47 3: FHEM2FHEM device opened (fhemenocean)

2016.07.07 14:46:40 3: FHEM2FHEM opening fhemenocean at 192.168.123.159:7172
2016.07.07 14:46:48 3: FHEM2FHEM device opened (fhemenocean)
2016.07.07 14:49:39 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)
2016.07.07 14:49:39 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)

2016.07.07 14:53:26 3: FHEM2FHEM opening fhemenocean at 192.168.123.159:7172
2016.07.07 14:54:31 1: FHEM2FHEM 192.168.123.159:7172 reappeared (fhemenocean)

Und ich konnte bisher auch die Flut nicht mehr reproduzieren, mehr als zwei Meldungen nacheinander tauchten nicht auf.

Interessanterweise scheint FHEM2FHEM aber kein Log zu schreiben, wenn eine Verbindung verschwindet.

Alles sehr eigenartig.

rudolfkoenig · 07 Juli 2016, 16:10:24

Das Problem gehoert hierher: https://forum.fhem.de/index.php?topic=55194

StefanStrobel · 09 Juli 2016, 13:17:21

Hallo Rudi,

zunächst mal vielen Dank für das Einbauen des Callbacks bei NEXT_OPEN. Im Modbus-Modul habe ich es wie schon gepostet mit einem BUSY_OPENDEV eingebaut. Dabei ist mir aufgefallen, dass es noch eine Art Race Condition im DevIo_OpenDev gibt, die direkt in DevIo behebbar sein sollte.

Als ich testweise das BUSY_OPENDEV Flag weggelassen habe, und der Zielserver nicht existierte, ist einmal in der Minute eine ganze Sequenz von Open-Versuchen gestartet worden. Die Modbus_Ready-Funktion ist ca. 10 mal in der Sekunde aufgerufen worden und hat auch genauso oft DevIo_OpenDev aufgerufen.

Ich vermute, dass es daran liegt, dass NEXT_OPEN erst in doTcpTail gesetzt wird. DevIoOpenDev beendet dann und Fhem ruft gleich wieder Modbus_Ready auf, während der Open-Versuch noch läuft und der Timeout noch nicht erreicht ist.
Als Lösung würde ich NEXT_Open schon setzen wenn das Nonblocking Http_Connect abgesetzt wurde.

Für das Modbus-Modul ist das ganze erst mal kein Problem, da ich ja weitere Aufrufe von DevIo_Opendev in der Modbus_Ready-Funktion über ein eigenes Flag verhindere bis der Callback aufgerufen wurde.

Gruss
Stefan