longpoll + ausgeschalteter client + vieeele status updates = fhem hängt.

[geek]

Hi,

hatte die letzten Abende beim finalen "Ausschalten" massive Problem mit fhem und denke das nun auf fhemweb + longpoll eingegrzenzt zu haben:

"strace -tttTf" sagt bei dem Hänger:

Code Auswählen Erweitern

24941 1403467256.931410 write(116, "eg_bd_rollo<<close<<<div id=\"eg_"..., 29619 <unfinished ...>
24941 1403467770.386699 <... write resumed> ) = 13032 <513.455204>

man beachte die timestamps - das sind 513 Sekunden. Kein Wunder daß mir die HMLANs da um die Ohren fliegen.

Filedescriptor 116 gehört zu einem socket der von nem Client/Browser aufgemacht wurde - und wegen longpoll noch offen war.

Relevanter Teil des Ausschaltens läuft etwa so:
- Browser auf Client hat Seite mit Status Überblick offen (Rollo oder Licht oder ....)
- für den Weg zum Bett werden schonmal die Rollos geschlossen und alles unnötige ausgeschaltet (halt bis auf Flur/Bad/Schlafzimmer Beleuchtung). Dabei bekommt der Client ein Kommando fuer Tiefschlaf und ist fortan nicht mehr erreichbar.
- Im Bett angekommen bekommt nochmal alles ein Ausschalt Kommando.

Fhem versucht dem Client also effektiv 2 mal per longpoll updates zuzuschieben... die nicht mehr abgeholt werden weil der Client schon schläft. Netstat (mit SendQ) und lsof output habe ich leider verschludert.

Als Hack habe ich erstmal longpoll ausgeschaltet. Das gleiche Problem gibts aber potentiell auch bei einer offenen telnet session mit laufendem inform timer.

Für eine dauerhafte Lösung fällt mir nur ein, die Sockets mittels fcntl auf O_NONBLOCK zu schalten - dann muss aber auch jedes read/write auf EAGAIN prüfen (autsch).

Rainer

[rudolfkoenig]

Ist fhem&FHEMWEB auf dem aktuellen Stand?

Das Problem habe ich vor ein paar Monaten geloest: die Daten werden erst dann geschrieben, falls select das erlaubt. Damals wurde es auch erfolgreich getestet.

[geek]

Hi,

Hm, das Problem ist erst aufgefallen nach einem update auf "$Id: fhem.pl 6080 2014-06-07 16:12:09Z rudolfkoenig $". Da nutzt du schon den Writebuffer + select.

Getestet habe ich nach roll-back mit "$Id: fhem.pl 5238 2014-03-16 16:23:31Z rudolfkoenig $".

Ich schaue mal, ob ich das nach erneutem update noch reproduzieren kann. Sorry, habe ich verpeilt, das vorm posten zu machen.

danke
Rainer

[Elektrolurch]

Hallo,

ich habe seit einigen Tagen auch so einen Effekt. fhem hängt sich immer dann auf, wenn ich den PC ausgeschaltet habe und die Browsersession noch offen war beim Ruhezustand. Im Mittel dauert es zwei bis vier Stunden und hängt wohl auch von der Seite ab, die als letztes auf war.  Ich habe jetzt mal
attr WEB longpoll 0
attr WEB longpoll 0

gesetzt.
Habe versucht, das Hängenbleiben mit irgendeinem Ereignis zu korrelieren, bislang total vergeblich. Hatte attr global verbose 3
gesetzt und bei den Objekten, die ich ev. auch im Verdacht hatte, so das minütlich log-Einträge geschrieben wurden und da ist natürlich alles drei Tage lang ohne Hängenbleiben durchgelaufen. Heute morgen um 7:00 Uhr dann den loglevel wieder zurückgesetzt und um ca. 8:20 Uhr hing fhem erneut wieder.
"strace" hat ja ziemlich viele Optionen, ich tue mich etwas schwer mit dem Lesen.. (s.u.). Wie muss ich es auf fhem anwenden?
Aus der Optionshilfe von strace werde ich nicht so ganz schlau.

Gruß

Elektrolurch

[rudolfkoenig]

Fang mal mit "strace -p <fhem-pid>" an, Ctrl-C beendet dann nur strace, und nicht FHEM.
Bedenke: strace ist fuer den laufenden Prozess eine erhebliche Bremse.

[Elektrolurch]

ok. Da ja der Prozeß immer noch läuft, wenn fhem hängt, brauche ich es ja dann erst aufzurufen.
Und dann leite ich die Ausgabe von strace um in eine Datei und poste das Ergebnis.

[Dr. Boris Neubert]

Und nimm noch die Optionen für Timestamp und Dauer des Systemaufrufs dazu...
Boris

[geek]

Hi,

so, gerade mit update von heute morgen getestet - und kann das nach belieben reproduzieren.
- client 192.168.1.12 geht mit browser auf rollo übersicht
- netzkabel abziehen
- ein paar mal status aller rollos updaten (hier noch ohne event-on-change)
- fhem hängt

Code Auswählen Erweitern


$ strace strace -tttTf -p $fhempid
...
32529 1403551282.471733 write(109, "eg_bd_rollo<<open<<<div id=\"eg_b"..., 20494) = 20272 <922.898807>
32529 1403552205.371339 write(115, "eg_bd_rollo<<open<<<div id=\"eg_b"..., 20494) = 20494 <0.000733>

$ lsof -p $fhempid
...
perl    32529 fhem  109u  IPv4 3312253       0t0     TCP 192.168.2.3:8083->192.168.1.12:39489 (ESTABLISHED)

$ netstat -an | egrep '(Send|192.168.1.12:39489)'
Proto Recv-Q Send-Q Local Address           Foreign Address         State     
tcp        0  30519 192.168.2.3:8083        192.168.1.12:39489      ESTABLISHED

Versionen:

fhem> version
# $Id: fhem.pl 6080 2014-06-07 16:12:09Z rudolfkoenig $
# $Id: 01_FHEMWEB.pm 6090 2014-06-09 10:25:11Z rudolfkoenig $
...


select() hat also gemeldet, der FD ist schreibbar, fhem versucht 20494 bytes zu schreiben - die aber nicht mehr in die sendQ passen. Darauf hängt der socket bis die Verbindung in Retransmit Timeouts läuft und abgebrochen wird. Erst dann meldet write zurück, dass nur 20272 Bytes geschrieben werden konnten und fhem kann weiter machen.

Rainer

[Dr. Boris Neubert]

Ich kann ein ähnliches Problem berichten: wenn mein WLAN-Bilderrahmen das Megabyte an Daten nicht aufnimmt, hängt Fhem im socket write (Modul RSS= Plugin zu FHEMWEB, bei der Auslieferung der der Datei). Dann ist Fhem bis zu einer Minute blockiert.

Ich hatte dazu mal einen Patch gepostet, der das Symptom behandelt, indem analog plotfork _Alles_ in einem nebenläufigen Kindprozess ausgeliefert wird.

Grüße
Boris

[geek]

Hi,

so, habe angefangen, code zu lesen.

Wie ich sehe, setzt TcpServer_Open schon

Code Auswählen Erweitern

Blocking  => ($^O =~ /Win/ ? 1 : 0), # Needed for .WRITEBUFFER@darwin

Nach meinem Verständnis wird das aber beim accept nicht durchgereicht. Das gilt so also nur für den Listen Socket - und da zieht der im comment erwähnte write buffer eh nicht.

Man könnte also probieren, nach dem accept den neuen IO::Socket mittels ->blocking(0) auch non-blocking IO zu bekommen. Setzt aber vorraus, das der Rest des codes damit umgehen kann - da fehlt mir der Überblick.

Intern machen ->blocking Methode und Blocking Parameter vom Konstruktor den Anfangs angesprochenen fcntl.

Rainer

[Elektrolurch]

Hallo,

da ich jetzt auch seit einigen Tagen mit den "Hängenbleibern" von fhem kämpfe und die Ursache nicht feststellen kann, hier mal einige Fakten, wie es bei mir aussieht:

1. Das Hängenbleiben von fhem passiert nur, wenn ich den PC ausgeschaltet habe, bzw. Ruhezustand gefahren habe.
2. Update-Stand aktuell.
3. Verwendet werden die httputils für ein eigenes Modul seit ca. 2 Monaten. Keine Fehlermeldungen, Zugriff im non-blocking Mode.
4. Das Hängenbleiben ist mit keinerlei Event in Verbindung zu bringen. Kann 20 Minuten nach dem letzten Zugriff von fhem passieren, oder auch um 2:00 Uhr nachts. Nachdem ich drei Tage lang den loglevel hoch gesetzt hatte und kein Hängenbleiben passierte, habe ich den loglevel wieder auf 1 gesetzt und eineStunde später hing fhem wieder.

Was ich auch registriert habe, sind relativ lange, und schwankende Reaktionszeiten von fhem auf fs20-Befehle:

Code:
sub TestFS20($)
{
my ($w) = @_;

my ($s, $ms) = gettimeofday();
my $t1 = $s + ($ms / 1000000); # 10 msec
if($w > 0)
{
fhem("set Bu_Deckenlampe ein");
fhem("set Bu_LampeGalerie1 ein");
fhem("set Bu_LampeGalerie2 ein");
}
if ($w == 2)
{
fhem("set Bu_Deckenlampe aus");
fhem("set Bu_LampeGalerie1 aus");
fhem("set Bu_LampeGalerie2 aus");
}

($s, $ms) = gettimeofday();
my $t2 = $s + ($ms / 1000000); # 10 msec
return "gemessene Zeit: " . sprintf("%.2f",$t2 - $t1);

} # end sub TestFS20

Für 0 kommt 0.00 zurück.
Fürs Einschalten der drei FS20 schon ca. 0.8.
Für Ein- und Ausschalten 1.8 Sekunden. Deutlich zu lang.
Frage mich, wo man je Schaltvorgang ca. 0.3 Sekunden verbrät?
Die Zeiten werden dann auch länger, wenn ich den Test mehrmals hinter einander ausführe.
Allerdings wird nachts um 2:00 Uhr nichts geschaltet und trotzdem bleibt fhem irgendwo hängen.
Speicherplatz ist im übrigen auf der fb3790 genügend frei, daran kann es nicht liegen.

Also die httputils oder irgendwo etwas in der event-Queu?

[rudolfkoenig]

@geek: kannst du bitte ein paar Zeilen mehr strace Output aufzeichnen, um zu sehen, ob vor dem write ein select durchgefuehrt wird? Ich tippe auf nein. Wenn deine Theorie stimmt, und write trotz select direkt blockiert, dann waere das ein Linux Bug, und daran glaube ich noch nicht.

@Elektrolurch: Jede gesendete FS20 Nachricht braucht zwar etwa 0.3 Sekunden, das wird aber in FHEM nicht durch aktives Warten geloest. Ich tippe auf irgendwelche Notifies, und sowas kann man mit "attr global verbose 5" gut sehen.

[geek]

Hi,

"egrep 'write.109|select' strace.out" liefert kurz vorm Hänger:

Code Auswählen Erweitern

32529 1403551278.796411 select(120, [6 7 8 9 10 11 100 109 111 112 113 114 115 116 117 118], [109 111 115], NULL, {0, 204629}) = 3 (out [109 111 115], left {0, 204606}) <0.000047>
32529 1403551278.797516 write(109, "eg_bd_rollo<<open<<<div id=\"eg_b"..., 10247) = 10247 <0.000225>
32529 1403551278.799675 select(120, [6 7 8 9 10 11 100 109 111 112 113 114 115 116 117 118], NULL, NULL, {0, 200572}) = 0 (Timeout) <0.201046>
32529 1403551279.008419 select(120, [6 7 8 9 10 11 100 109 111 112 113 114 115 116 117 118], NULL, NULL, {0, 992088}) = 1 (in [100], left {0, 926910}) <0.065485>
32529 1403551279.085804 select(120, [6 7 8 9 10 11 100 109 111 112 113 114 115 116 117 118], NULL, NULL, {0, 914374}) = 1 (in [100], left {0, 59593}) <0.854904>
32529 1403551279.962092 select(120, [6 7 8 9 10 11 100 109 111 112 113 114 115 116 117 118], NULL, NULL, {0, 38537}) = 0 (Timeout) <0.038773>
32529 1403551280.006282 select(120, [6 7 8 9 10 11 100 109 111 112 113 114 115 116 117 118], NULL, NULL, {0, 994380}) = 1 (in [10], left {0, 922653}) <0.072040>
32529 1403551280.112490 select(120, [6 7 8 9 10 11 100 109 111 112 113 114 115 116 117 118], NULL, NULL, {0, 887568}) = 1 (in [11], left {0, 887556}) <0.000017>
32529 1403551280.113870 select(120, [6 7 8 9 10 11 100 109 111 112 113 114 115 116 117 118], NULL, NULL, {0, 886182}) = 1 (in [100], left {0, 191317}) <0.694928>
32529 1403551280.826724 select(120, [6 7 8 9 10 11 100 109 111 112 113 114 115 116 117 118], NULL, NULL, {0, 173758}) = 0 (Timeout) <0.174075>
32529 1403551281.004845 select(120, [6 7 8 9 10 11 100 109 111 112 113 114 115 116 117 118], NULL, NULL, {0, 995939}) = 1 (in [112], left {0, 502746}) <0.493322>
32529 1403551281.533992 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001195>
32529 1403551281.576161 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001099>
32529 1403551281.619030 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001061>
32529 1403551281.685303 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001170>
32529 1403551281.743149 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001124>
32529 1403551281.849409 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001176>
32529 1403551281.891968 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001068>
32529 1403551281.978301 select(120, [6 7 8 9 10 11 100 109 111 112 113 114 115 116 117 118], [109 111 115], NULL, {0, 22351}) = 5 (in [100 112], out [109 111 115], left {0, 22233}) <0.000211>
32529 1403551282.012750 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001164>
32529 1403551282.129484 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001133>
32529 1403551282.155482 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001119>
32529 1403551282.166726 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001088>
32529 1403551282.215364 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001160>
32529 1403551282.285019 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001118>
32529 1403551282.310926 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001080>
32529 1403551282.471733 write(109, "eg_bd_rollo<<open<<<div id=\"eg_b"..., 20494) = 20272 <922.898807>


Der select ist also um 1403551281.978301  gemacht worden und FD 109 ist im Result vorhanden. Danach sind aber weiter selects (als usleep) ausgeführt worden.

Select hatte ja eigentlich recht - 20272 bytes konnten ja geschrieben werden. Nur nicht die gesamten 20494 bytes. Und - wenn ich ehrlich bin - sehe ich auch keinen Weg, wie sich write() auf nem blocking Socket anders verhalten sollte. Der select hat ja keine Möglichkeit zu prüfen, wieviel geschrieben werden soll - und write weiß nicht, daß er nicht blocken soll.

Rainer

[Elektrolurch]

Hallo,
kämpfe auch noch mit dem Hänger.
Nach 16 Stunden normalen Betrieb hing der Prozeß perl startfhem heute morgen zwischen 6:00 und 7:00 Uhr wieder. Zu der Zeit gab es in der Hausautomation keine "außergewöhnlichen" Aktivitäten.
Das einzige was läuft, ist die alle 60 Sekunden gestartete Heizungsanlagen-Abfrage über non-blocking httputils.

ich habe dann strace aufgerufen: strace -p <pid> zeigte nichts an, also wohl keine Endlosschleife.
Ich müsste also jetzt strace mal vor dem Hängenbleiben starten. Leider stelle ich mich etwas dumm an:

strace -p <pid> >./tracebak.txt oder auch mit ">>" lenken die Konsolenausgaben aber nicht um. Die Datei traceback wird erzeugt, bleibt aber leer.
Sorry, meine Unix-Kenntnisse haben vor 25 Jahren Rost angesetzt...
Wie muss es richtig heißen?

Gruß

Elektrolurch

[justme1968]

select für read und write gibt nur an das ein nonblocking read bzw. write nicht blockieren würde. es bedeutet nicht das beliebig viele bytes gelesen oder geschrieben werden können.

ich denke das select für write macht nur sinn wenn es mit einem nonblocking write kombiniert ist das den teil schreibt den es los wird und den rest beim nächsten mal probiert. zumindest dann wenn mehr als nur ein paar byte geschrieben werden.

gruss
  andre