Race-condition in presence

[Mattias]

Es gibt in Presence eine Race-Condition, die unter bestimmten Umständen dazu führt, dass von "shutdown restart" nur der Shutdown-Teil ausgeführt wird. Zu der "shutdown restart"-Problematik gab es hier im Forum schon einige Beiträge. Ich vermute, dass es sich um dasselbe Problem handelt das auch bei mir aufgetreten ist.

Das Problem tritt bei mir in Verbindung mit lan-ping auf. (Ich beschreibe am Ende im Detail, wie sich der Fehler reproduzieren lässt).

Ich muss zur Beschreibung des Wie&Warum etwas weiter ausholen da die Angelegenheit etwas komplexer ist und ich die Zeit, die ich selber schon in die Analyse gesteckt habe, dem Modul-Owner gerne ersparen möchte.

lan-ping ist in presence so realisiert dass fhem geforkt wird wenn der presence-Timer triggert, das Ping also ausgeführt werden soll. Der geforkte Child-Prozess seinerseits startet via qx einen weiteren Prozess, nämlich "ping -c4 <ip-adresse>". Die Kommunikation zwischen Parent- und Child-FHEM wird über BlockingCall() (Modul: Blocking.pm) realisiert. BlockingCall() bietet die Möglichkeit, einen Timeout anzugeben, der bei Presence und lan-ping auf 20 Sekunden festgelegt ist.
Auf meinen System, einer Fritz!Box 7390, benötigt ein 'ping -c 4 <ip>' auf eine unerreichbare IP-Adresse ca. 14 Sekunden. Wird während der ersten 12 Sekunden ein 'shutdown restart' ausgeführt, schlägt der restart nachvollziehbar und immer fehl. Das hängt damit zusammen, dass der von BlockingCall() erzeugte (Child-)FHEM-Prozess durch das 'shutdown restart' nicht beendet wird, denn er wartet auf das Ende des Ping-Kommandos.

Der Parent-Prozess wird jedoch durch das shutdown restart beendet und versucht, mit einer Verzögerung von 2 Sekunden, sich selbst neu zu starten. Der Restart wird jedoch abgebrochen, weil FHEM bereits läuft (und auf das Ende des Pings wartet). Warum FHEM sich beim Hochfahren beendet wenn bereits eine Instanz läuft, weiss ich nicht genau. Ich nehme an, dass das Öffnen von Ports oder File-Deskriptoren fehlschlägt, die durch die bereits laufende Instanz noch benutzt werden.

Die Wahrscheinlichkeit, dass das Problem zu beobachten ist, hängt wesentlich von der Anzahl der lan-ping Presence-Definitionen ab, den presence-Timeouts und natürlich der Erreichbarkeit der überwachten Adressen.

Die sauberste Lösung würde meiner Meinung nach darin bestehen, wenn Presence (oder BlockingCall) auf den shutdown-Befehl reagieren, in dem sie laufenden Child-Prozesse abbrechen oder den Shutdown solange aufhalten bis alle Childs beendet wurden.

Um das Problem zu reproduzieren kann folgendermassen vorgegangen werden:
1) Zeile 459 in FHEM/73_presence.pm von
      $temp = qx(ping -c 4 $device);
   ändern in
      $temp = qx(ping -c 4 -w 45 $device);
   So wird Presence angewiesen, 45 Sekunden auf Ping-Antworten zu warten

2) Ein presence Objekt in fhem.cfg konfigurieren dass eine unerreichbare Adresse im lokalen Netz per lan-ping überprüfen soll. (Bei mir: "define testp PRESENCE lan-ping 192.168.1.4 60 60")

3) fhem anhalten und neustarten um die Änderungen zu aktivieren.

4) Presence setzt nach ungefähr 2 Sekunden den ersten Ping-Befehl ab.
   -> Ab diesem Zeitpunkt laufen zwei FHEM-Instanzen ("ps | grep perl")

5) Über FHEMWEB oder auf geeignetem anderem Wege "shutdown restart" eingeben.
   -> Der erste FHEM-Prozess terminiert.
   -> Für ca 2 Sekunden ist der Befehl für den FHEM-Restart sichtbar. (Bei mir: sh -c (sleep 2; exec perl fhem.pl ....) )
   -> Nach etwa 45 Sekunden (gerechnet ab 4) beendet sich der verbliebene FHEM-Prozess, da das Ping-Kommando terminiert.


6) Änderungen aus 1+2 wieder zurücknehmen ;)

[Markus Bloch]

Auch hier hat Rudi die Grundlagen gelegt. Werde ich die nächste Zeit einbringen.

Viele Grüße

Markus

[Markus Bloch]

Ist ab morgen gefixet.

[Mattias]

Hallo Markus,

vielen Dank für deine bisherigen Änderungen. Im Prinzip sieht das auch alles schon ganz fein aus, aber...

Ich habe mein FHEM so konfiguriert, dass es sich jeden Morgen die letzten Änderungen holt und einen shutdown restart ausführt. Seit heute sehe ich folgende Meldungen neu in meinem Logfile:

Code Auswählen Erweitern

2013.04.14 08:01:04 1: update 2 file(s) have been updated.
2013.04.14 08:01:04 1: update A new version of fhem.pl was installed, 'shutdown restart' is required!
2013.04.14 08:05:02 0: Server shutdown
2013.04.14 08:05:04 1: CallBlockingFn: Can't connect to localhost:7072

2013.04.14 08:05:04 1: CallBlockingFn: Can't connect to localhost:7072

2013.04.14 08:05:06 1: Including /var/media/ftp/uStor01/fhem/fhem.cfg

Möglicherweise tue ich dir unrecht, wenn ich einen Zusammenhang mit Presence vermute. Allerdings hab ich genau zwei PRESENCE-Definitionen in meiner Konfiguration, die relativ häufig (alle 60 Sekunden) ausgeführt werden. Ins Blaue fabuliert scheint mir da bei shutdown restart immer noch etwas im Argen zu liegen - so als ob Presence aufgerufen wird, obwohl der shutdown schon läuft (Port nicht mehr offen) oder der restart noch nicht durch ist (Port noch nicht geöffnet). Bestimmt siehst du den Zusammenhang zu deinen oder Rudis Änderungen schneller als ich...

[justme1968]

die meldungen kommen von den geforkten presence instanzen die beim shutdown in einem zustand waren in dem sie sich nicht beenden ließen. die wachen nach einer weile auf und können nichts mehr an den parent melden der ja nicht mehr da ist. danach beenden sie sich einfach. da inzwischen die server ports beim fork geschlossen werden ist das ganze unkritisch und verhindert den neustart nicht mehr. es ist also einfach nur eine meldung über das was passiert und nicht wirklich eine fehlermeldung.

gruss
  andre

[Mattias]

Vielen Dank für die Erklärung, Andre! Scheinbar lässt sich das Phänomen nur dann beobachten, wenn die ping-Kommandos gerade laufen bzw
auf Antworten warten während der restart läuft. Das passt ja auch gut zu deiner Erklärung.

Vom Design her fände ich es allerdings schlüssiger, wenn die Childs beendet würden (oder auf ihr Ende gewartet würde) bevor der Restart durchgeführt würde. Mit der selben Wahrscheinlichkeit mit der die verwaisten Kinder versuchen, mit dem nicht mehr vorhandenen Parent zu reden, könnte auch der Fall eintreten, dass der Restart schon durch ist und der Port wieder offen wäre. Dann würde die InformParent-Funktion die Ergebnisse an den neuen Prozess senden, oder?

Unabhängig davon könnte man das \n aus der Meldung vielleicht noch rausnehmen.