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

geek · 22 Juni 2014, 22:59:47

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

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 · 23 Juni 2014, 08:33:27

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 · 23 Juni 2014, 09:11:01

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 · 23 Juni 2014, 11:23:36

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 · 23 Juni 2014, 17:57:37

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 · 23 Juni 2014, 18:55:06

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 · 23 Juni 2014, 21:38:02

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

geek · 23 Juni 2014, 21:41:18

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


$ 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 · 23 Juni 2014, 21:54:26

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 · 23 Juni 2014, 22:15:38

Hi,

so, habe angefangen, code zu lesen.

Wie ich sehe, setzt TcpServer_Open schon

Code Auswählen

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 · 23 Juni 2014, 22:47:32

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 · 24 Juni 2014, 08:40:19

@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 · 24 Juni 2014, 09:14:32

Hi,

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

Code Auswählen

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 · 24 Juni 2014, 09:24:29

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 · 24 Juni 2014, 09:29:43

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

rudolfkoenig · 24 Juni 2014, 12:25:38

@andre: ich habe die Doku so verstanden, dass write nicht blockiert (egal, ob die FD auf nonblocking gesetzt ist oder nicht), wenn select vorher OK liefert. Der write nach diesem select schreibt soviel, wie ohne blockieren moeglich ist. Wenn man write _danach_ (bzw. ohne OK vom select) nochmal aufruft, dann blockiert er sich.

@Elektrolurch: strace -tt -p <pid> -o /tmp/xy

@geek: und das Ganze bitte nochmal mit "tail -50 strace.out" statt egrep.

justme1968 · 24 Juni 2014, 12:49:38

ich bin mir sehr sicher das das nicht so ist. select und write wissen ja nichts voneinander und es wäre nicht intuitiv wenn das verhalten des write vom vorherigen select abhängt und O_NONBLOCK nicht mehr relevant ist.

wenn man z.b. hier liest: http://pubs.opengroup.org/onlinepubs/009604599/functions/pselect.html:

ZitatA descriptor shall be considered ready for writing when a call to an output function with O_NONBLOCK clear would not block, whether or not the function would transfer data successfully.

steht da zwar das O_NONBLOCK nicht gesetzt sein muss. aber es steht auch nicht da wie viele bytes geschrieben werden dürfen und auch nicht das das verhalten des write sich ändert.

zu write steht explizit:

ZitatWhen using non-blocking I/O on objects, such as sockets, that are subject to flow control, write() and writev() may write fewer bytes than requested; the return value must be noted, and the remainder of the operation should be retried when possible.

d.h. das gilt nur wenn O_NONBLOCK gesetzt ist.

select und blocking io passen eigentlich nicht wirklich zusammen. auch wenn es oft geht gibt es unschöne seiteneffekte. siehe z.b. auch hier http://linux.derkeiler.com/Newsgroups/comp.os.linux.development.apps/2008-08/msg00224.html. zwar anderer kontext. aber die anmerkung ist wichtig und an vielen anderen stellen zu finden. auch in der perl doku zu select.

ZitatCorrect. If you want to make sure you don't block in an I/O
operation you must use non-blocking I/O calls. The results of
select() aren't a guarantee, just a very strong hint. Many
people who write apps using select() in combination with
blocking I/O calls will never have any problems, but if you
wan't to do it the "right" way, you use non-blocking I/O.

geek · 24 Juni 2014, 13:37:50

Hi,

ok, hier die letzten 569 zeilen vom letzten select bis zum nächsten write nach dem Hänger.

Code Auswählen

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 1403551281.979282 read(112, "set rollo_mode open\r\n", 256) = 21 <0.000072>
32529 1403551281.980798 gettimeofday({1403551281, 980857}, NULL) = 0 <0.000044>
32529 1403551281.981048 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000060>
32529 1403551281.982619 time(NULL)      = 1403551281 <0.000044>
32529 1403551281.982898 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000045>
32529 1403551282.003949 time(NULL)      = 1403551282 <0.000135>
32529 1403551282.004469 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000104>
32529 1403551282.006668 gettimeofday({1403551282, 6719}, NULL) = 0 <0.000030>
32529 1403551282.006837 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000069>
32529 1403551282.007263 time(NULL)      = 1403551282 <0.000031>
32529 1403551282.007376 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000125>
32529 1403551282.007633 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000039>
32529 1403551282.007967 write(3, "2014.06.23 21:21:22.006 3: rollo"..., 67) = 67 <0.000108>
32529 1403551282.010034 gettimeofday({1403551282, 10084}, NULL) = 0 <0.000031>
32529 1403551282.010191 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000050>
32529 1403551282.010619 time(NULL)      = 1403551282 <0.000025>
32529 1403551282.010726 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000045>
32529 1403551282.010851 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000016>
32529 1403551282.010974 write(3, "2014.06.23 21:21:22.010 5: TXEG "..., 69) = 69 <0.000279>
32529 1403551282.011654 gettimeofday({1403551282, 11754}, NULL) = 0 <0.000028>
32529 1403551282.011886 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000040>
32529 1403551282.012144 time(NULL)      = 1403551282 <0.000024>
32529 1403551282.012251 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000070>
32529 1403551282.012401 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000015>
32529 1403551282.012611 write(3, "2014.06.23 21:21:22.011 5: SW: 0"..., 60) = 60 <0.000015>
32529 1403551282.012689 write(100, "\f\32\0\0\v\356\20\3\1\0\0\0\0\0", 14) = 14 <0.000018>
32529 1403551282.012750 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001164>
32529 1403551282.014020 time(NULL)      = 1403551282 <0.000007>
32529 1403551282.014060 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000015>
32529 1403551282.015776 time(NULL)      = 1403551282 <0.000091>
32529 1403551282.016135 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000059>
32529 1403551282.088859 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000152>
32529 1403551282.089246 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000132>
32529 1403551282.089929 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000079>
32529 1403551282.090231 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000075>
32529 1403551282.090844 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000059>
32529 1403551282.091025 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000019>
32529 1403551282.091175 read(119, "", 8192) = 0 <0.000101>
32529 1403551282.091605 close(119)      = 0 <0.000059>
32529 1403551282.099201 time(NULL)      = 1403551282 <0.000074>
32529 1403551282.099527 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000093>
32529 1403551282.103619 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000046>
32529 1403551282.103883 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000073>
32529 1403551282.104257 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000088>
32529 1403551282.104586 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000075>
32529 1403551282.105892 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000152>
32529 1403551282.106282 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000107>
32529 1403551282.106874 read(119, "", 8192) = 0 <0.000048>
32529 1403551282.108084 close(119)      = 0 <0.000058>
32529 1403551282.109622 time(NULL)      = 1403551282 <0.000073>
32529 1403551282.109874 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000076>
32529 1403551282.111591 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000135>
32529 1403551282.112008 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000060>
32529 1403551282.112295 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000061>
32529 1403551282.112582 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000086>
32529 1403551282.113040 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000074>
32529 1403551282.113295 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000088>
32529 1403551282.113914 read(119, "", 8192) = 0 <0.000046>
32529 1403551282.114250 close(119)      = 0 <0.000349>
32529 1403551282.115521 time(NULL)      = 1403551282 <0.000064>
32529 1403551282.115779 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000095>
32529 1403551282.116533 time(NULL)      = 1403551282 <0.000066>
32529 1403551282.116789 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000079>
32529 1403551282.117376 gettimeofday({1403551282, 117447}, NULL) = 0 <0.000075>
32529 1403551282.117714 time(NULL)      = 1403551282 <0.000047>
32529 1403551282.117978 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000046>
32529 1403551282.122595 time(NULL)      = 1403551282 <0.000091>
32529 1403551282.122965 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000094>
32529 1403551282.124662 gettimeofday({1403551282, 124727}, NULL) = 0 <0.000030>
32529 1403551282.124949 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.001479>
32529 1403551282.126770 time(NULL)      = 1403551282 <0.000014>
32529 1403551282.126879 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000018>
32529 1403551282.127018 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000016>
32529 1403551282.127204 write(3, "2014.06.23 21:21:22.124 3: rollo"..., 60) = 60 <0.000026>
32529 1403551282.127832 gettimeofday({1403551282, 127852}, NULL) = 0 <0.000013>
32529 1403551282.127914 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000017>
32529 1403551282.128072 time(NULL)      = 1403551282 <0.000013>
32529 1403551282.128160 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000016>
32529 1403551282.128313 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000016>
32529 1403551282.128474 write(3, "2014.06.23 21:21:22.127 5: TXEG "..., 69) = 69 <0.000020>
32529 1403551282.128637 gettimeofday({1403551282, 128700}, NULL) = 0 <0.000059>
32529 1403551282.128760 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000017>
32529 1403551282.128913 time(NULL)      = 1403551282 <0.000012>
32529 1403551282.128972 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000016>
32529 1403551282.129099 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000016>
32529 1403551282.129256 write(3, "2014.06.23 21:21:22.128 5: SW: 0"..., 60) = 60 <0.000019>
32529 1403551282.129373 write(100, "\f\32\0\0\v\356\20\1\1\0\0\0\0\0", 14) = 14 <0.000029>
32529 1403551282.129484 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001133>
32529 1403551282.130752 time(NULL)      = 1403551282 <0.000015>
32529 1403551282.130895 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000025>
32529 1403551282.131381 time(NULL)      = 1403551282 <0.000119>
32529 1403551282.131707 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000101>
32529 1403551282.151066 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000015>
32529 1403551282.151129 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000004>
32529 1403551282.151155 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000004>
32529 1403551282.151179 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000004>
32529 1403551282.151215 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000005>
32529 1403551282.151241 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000005>
32529 1403551282.151281 read(119, "", 8192) = 0 <0.000004>
32529 1403551282.151305 close(119)      = 0 <0.000005>
32529 1403551282.151515 time(NULL)      = 1403551282 <0.000004>
32529 1403551282.151538 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000007>
32529 1403551282.151785 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000007>
32529 1403551282.151817 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000004>
32529 1403551282.151838 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000004>
32529 1403551282.151858 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000004>
32529 1403551282.151891 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000004>
32529 1403551282.151939 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000005>
32529 1403551282.151974 read(119, "", 8192) = 0 <0.000004>
32529 1403551282.151996 close(119)      = 0 <0.000005>
32529 1403551282.152185 time(NULL)      = 1403551282 <0.000003>
32529 1403551282.152205 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.152420 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000007>
32529 1403551282.152452 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000004>
32529 1403551282.152472 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000004>
32529 1403551282.152492 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000003>
32529 1403551282.152523 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000004>
32529 1403551282.152544 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000005>
32529 1403551282.152579 read(119, "", 8192) = 0 <0.000004>
32529 1403551282.152616 close(119)      = 0 <0.000004>
32529 1403551282.152838 time(NULL)      = 1403551282 <0.000003>
32529 1403551282.152858 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.152935 time(NULL)      = 1403551282 <0.000003>
32529 1403551282.152955 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.153002 gettimeofday({1403551282, 153007}, NULL) = 0 <0.000003>
32529 1403551282.153036 time(NULL)      = 1403551282 <0.000030>
32529 1403551282.153081 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.154450 time(NULL)      = 1403551282 <0.000006>
32529 1403551282.154500 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000009>
32529 1403551282.154647 gettimeofday({1403551282, 154653}, NULL) = 0 <0.000004>
32529 1403551282.154672 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.154724 time(NULL)      = 1403551282 <0.000004>
32529 1403551282.154742 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.154814 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.154868 write(3, "2014.06.23 21:21:22.154 3: rollo"..., 60) = 60 <0.000008>
32529 1403551282.155038 gettimeofday({1403551282, 155044}, NULL) = 0 <0.000004>
32529 1403551282.155062 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.155108 time(NULL)      = 1403551282 <0.000003>
32529 1403551282.155126 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.155163 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.155209 write(3, "2014.06.23 21:21:22.155 5: TXEG "..., 69) = 69 <0.000006>
32529 1403551282.155243 gettimeofday({1403551282, 155248}, NULL) = 0 <0.000004>
32529 1403551282.155265 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.155308 time(NULL)      = 1403551282 <0.000003>
32529 1403551282.155326 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.155364 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.155409 write(3, "2014.06.23 21:21:22.155 5: SW: 0"..., 60) = 60 <0.000005>
32529 1403551282.155446 write(100, "\f\32\0\0\v\356\20\2\1\0\0\0\0\0", 14) = 14 <0.000012>
32529 1403551282.155482 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001119>
32529 1403551282.156659 time(NULL)      = 1403551282 <0.000004>
32529 1403551282.156683 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000010>
32529 1403551282.156875 time(NULL)      = 1403551282 <0.000003>
32529 1403551282.156895 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.161816 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000016>
32529 1403551282.161878 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000004>
32529 1403551282.161903 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000004>
32529 1403551282.161927 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000005>
32529 1403551282.161962 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000004>
32529 1403551282.161988 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000005>
32529 1403551282.162028 read(119, "", 8192) = 0 <0.000004>
32529 1403551282.162052 close(119)      = 0 <0.000006>
32529 1403551282.162266 time(NULL)      = 1403551282 <0.000004>
32529 1403551282.162289 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000007>
32529 1403551282.162644 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000008>
32529 1403551282.162679 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000004>
32529 1403551282.162715 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000004>
32529 1403551282.162735 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000004>
32529 1403551282.162768 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000004>
32529 1403551282.162790 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000005>
32529 1403551282.162826 read(119, "", 8192) = 0 <0.000004>
32529 1403551282.162849 close(119)      = 0 <0.000004>
32529 1403551282.163075 time(NULL)      = 1403551282 <0.000004>
32529 1403551282.163097 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000006>
32529 1403551282.163314 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000007>
32529 1403551282.163346 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000004>
32529 1403551282.163366 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000004>
32529 1403551282.163386 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000004>
32529 1403551282.163456 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000004>
32529 1403551282.163479 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000005>
32529 1403551282.163515 read(119, "", 8192) = 0 <0.000004>
32529 1403551282.163578 close(119)      = 0 <0.000004>
32529 1403551282.163771 time(NULL)      = 1403551282 <0.000004>
32529 1403551282.163791 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.163862 time(NULL)      = 1403551282 <0.000003>
32529 1403551282.163882 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.163929 gettimeofday({1403551282, 163934}, NULL) = 0 <0.000004>
32529 1403551282.163963 time(NULL)      = 1403551282 <0.000003>
32529 1403551282.163982 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.165611 time(NULL)      = 1403551282 <0.000006>
32529 1403551282.165647 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000009>
32529 1403551282.165825 gettimeofday({1403551282, 165831}, NULL) = 0 <0.000004>
32529 1403551282.165850 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000006>
32529 1403551282.165900 time(NULL)      = 1403551282 <0.000003>
32529 1403551282.165919 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.165957 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.166010 write(3, "2014.06.23 21:21:22.165 3: rollo"..., 73) = 73 <0.000009>
32529 1403551282.166239 gettimeofday({1403551282, 166245}, NULL) = 0 <0.000004>
32529 1403551282.166264 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.166310 time(NULL)      = 1403551282 <0.000003>
32529 1403551282.166328 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.166366 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.166440 write(3, "2014.06.23 21:21:22.166 5: TXEG "..., 69) = 69 <0.000016>
32529 1403551282.166485 gettimeofday({1403551282, 166490}, NULL) = 0 <0.000004>
32529 1403551282.166506 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.166551 time(NULL)      = 1403551282 <0.000004>
32529 1403551282.166569 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.166606 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.166651 write(3, "2014.06.23 21:21:22.166 5: SW: 0"..., 60) = 60 <0.000006>
32529 1403551282.166689 write(100, "\f\32\0\0\v\356\21\1\0\0\0\0\0\0", 14) = 14 <0.000012>
32529 1403551282.166726 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001088>
32529 1403551282.167872 time(NULL)      = 1403551282 <0.000004>
32529 1403551282.167897 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000010>
32529 1403551282.168098 time(NULL)      = 1403551282 <0.000004>
32529 1403551282.168118 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.173853 open("./www/images/openautomation/fts_shutter_60.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000014>
32529 1403551282.173906 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000005>
32529 1403551282.173932 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000004>
32529 1403551282.173955 fstat64(119, {st_mode=S_IFREG|0644, st_size=2912, ...}) = 0 <0.000004>
32529 1403551282.173991 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000004>
32529 1403551282.174017 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 2912 <0.000006>
32529 1403551282.174069 read(119, "", 8192) = 0 <0.000004>
32529 1403551282.174099 close(119)      = 0 <0.000005>
32529 1403551282.174705 time(NULL)      = 1403551282 <0.000004>
32529 1403551282.174729 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000007>
32529 1403551282.175000 open("./www/images/openautomation/fts_shutter_60.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000008>
32529 1403551282.175036 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000004>
32529 1403551282.175057 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000004>
32529 1403551282.175078 fstat64(119, {st_mode=S_IFREG|0644, st_size=2912, ...}) = 0 <0.000004>
32529 1403551282.175110 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000004>
32529 1403551282.175133 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 2912 <0.000005>
32529 1403551282.175205 read(119, "", 8192) = 0 <0.000004>
32529 1403551282.175232 close(119)      = 0 <0.000005>
32529 1403551282.175924 time(NULL)      = 1403551282 <0.000048>
32529 1403551282.176236 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000072>
32529 1403551282.177485 open("./www/images/openautomation/fts_shutter_60.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000061>
32529 1403551282.177815 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000061>
32529 1403551282.178091 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000006>
32529 1403551282.178140 fstat64(119, {st_mode=S_IFREG|0644, st_size=2912, ...}) = 0 <0.000005>
32529 1403551282.178242 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000040>
32529 1403551282.178527 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 2912 <0.000070>
32529 1403551282.178894 read(119, "", 8192) = 0 <0.000039>
32529 1403551282.179351 close(119)      = 0 <0.000030>
32529 1403551282.185634 time(NULL)      = 1403551282 <0.000030>
32529 1403551282.185824 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000018>
32529 1403551282.185996 time(NULL)      = 1403551282 <0.000004>
32529 1403551282.186020 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.186069 gettimeofday({1403551282, 186074}, NULL) = 0 <0.000003>
32529 1403551282.186103 time(NULL)      = 1403551282 <0.000003>
32529 1403551282.186122 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.202997 time(NULL)      = 1403551282 <0.000044>
32529 1403551282.203441 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000108>
32529 1403551282.205548 gettimeofday({1403551282, 205613}, NULL) = 0 <0.000045>
32529 1403551282.206034 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000145>
32529 1403551282.206791 time(NULL)      = 1403551282 <0.000035>
32529 1403551282.206979 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000378>
32529 1403551282.207794 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000104>
32529 1403551282.208675 write(3, "2014.06.23 21:21:22.205 3: rollo"..., 67) = 67 <0.000123>
32529 1403551282.210784 gettimeofday({1403551282, 210831}, NULL) = 0 <0.000024>
32529 1403551282.210955 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000116>
32529 1403551282.211379 time(NULL)      = 1403551282 <0.000043>
32529 1403551282.211529 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000036>
32529 1403551282.211795 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000026>
32529 1403551282.212098 write(3, "2014.06.23 21:21:22.210 5: TXEG "..., 69) = 69 <0.000112>
32529 1403551282.212466 gettimeofday({1403551282, 212509}, NULL) = 0 <0.000031>
32529 1403551282.212616 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000025>
32529 1403551282.212982 time(NULL)      = 1403551282 <0.000034>
32529 1403551282.213222 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000058>
32529 1403551282.213893 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000121>
32529 1403551282.214485 write(3, "2014.06.23 21:21:22.212 5: SW: 0"..., 60) = 60 <0.000119>
32529 1403551282.215063 write(100, "\f\32\0\0\v\356\21\2\1\0\0\0\0\0", 14) = 14 <0.000034>
32529 1403551282.215364 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001160>
32529 1403551282.216777 time(NULL)      = 1403551282 <0.000168>
32529 1403551282.217147 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000075>
32529 1403551282.218093 time(NULL)      = 1403551282 <0.000075>
32529 1403551282.218347 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000090>
32529 1403551282.234962 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000056>
32529 1403551282.235391 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000030>
32529 1403551282.235500 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000026>
32529 1403551282.235608 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000028>
32529 1403551282.235712 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000027>
32529 1403551282.235935 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000045>
32529 1403551282.236335 read(119, "", 8192) = 0 <0.000023>
32529 1403551282.236515 close(119)      = 0 <0.000035>
32529 1403551282.239212 time(NULL)      = 1403551282 <0.000029>
32529 1403551282.239340 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000146>
32529 1403551282.240210 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000063>
32529 1403551282.240633 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000026>
32529 1403551282.240738 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000026>
32529 1403551282.240812 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000029>
32529 1403551282.240900 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000027>
32529 1403551282.240963 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000007>
32529 1403551282.241011 read(119, "", 8192) = 0 <0.000004>
32529 1403551282.241038 close(119)      = 0 <0.000007>
32529 1403551282.241382 time(NULL)      = 1403551282 <0.000044>
32529 1403551282.241607 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000038>
32529 1403551282.245498 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000108>
32529 1403551282.245729 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000028>
32529 1403551282.245829 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000026>
32529 1403551282.245943 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.002991>
32529 1403551282.249301 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000045>
32529 1403551282.249622 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000030>
32529 1403551282.249925 read(119, "", 8192) = 0 <0.000058>
32529 1403551282.250147 close(119)      = 0 <0.000074>
32529 1403551282.250892 time(NULL)      = 1403551282 <0.000045>
32529 1403551282.251097 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000058>
32529 1403551282.252285 time(NULL)      = 1403551282 <0.000104>
32529 1403551282.252561 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000043>
32529 1403551282.252813 gettimeofday({1403551282, 252848}, NULL) = 0 <0.000034>
32529 1403551282.253062 time(NULL)      = 1403551282 <0.000017>
32529 1403551282.253181 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000015>
32529 1403551282.281653 time(NULL)      = 1403551282 <0.000017>
32529 1403551282.281751 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000027>
32529 1403551282.282218 gettimeofday({1403551282, 282239}, NULL) = 0 <0.000014>
32529 1403551282.282300 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000018>
32529 1403551282.282510 time(NULL)      = 1403551282 <0.000013>
32529 1403551282.282574 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000017>
32529 1403551282.282705 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000016>
32529 1403551282.282956 write(3, "2014.06.23 21:21:22.282 3: rollo"..., 76) = 76 <0.000023>
32529 1403551282.283429 gettimeofday({1403551282, 283449}, NULL) = 0 <0.000014>
32529 1403551282.283508 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000018>
32529 1403551282.283663 time(NULL)      = 1403551282 <0.000013>
32529 1403551282.283724 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000016>
32529 1403551282.283904 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000017>
32529 1403551282.284065 write(3, "2014.06.23 21:21:22.283 5: TXEG "..., 69) = 69 <0.000020>
32529 1403551282.284176 gettimeofday({1403551282, 284193}, NULL) = 0 <0.000013>
32529 1403551282.284250 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000017>
32529 1403551282.284401 time(NULL)      = 1403551282 <0.000013>
32529 1403551282.284461 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000017>
32529 1403551282.284589 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000017>
32529 1403551282.284745 write(3, "2014.06.23 21:21:22.284 5: SW: 0"..., 60) = 60 <0.000021>
32529 1403551282.284909 write(100, "\f\32\0\0\v\356\21\4\1\0\0\0\0\0", 14) = 14 <0.000030>
32529 1403551282.285019 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001118>
32529 1403551282.286269 time(NULL)      = 1403551282 <0.000013>
32529 1403551282.286343 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000026>
32529 1403551282.286902 time(NULL)      = 1403551282 <0.000014>
32529 1403551282.286972 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000017>
32529 1403551282.306627 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000016>
32529 1403551282.306690 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000005>
32529 1403551282.306715 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000004>
32529 1403551282.306739 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000005>
32529 1403551282.306775 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000004>
32529 1403551282.306801 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000006>
32529 1403551282.306840 read(119, "", 8192) = 0 <0.000004>
32529 1403551282.306865 close(119)      = 0 <0.000005>
32529 1403551282.307101 time(NULL)      = 1403551282 <0.000004>
32529 1403551282.307124 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000007>
32529 1403551282.307359 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000007>
32529 1403551282.307392 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000004>
32529 1403551282.307412 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000004>
32529 1403551282.307432 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000004>
32529 1403551282.307479 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000004>
32529 1403551282.307501 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000004>
32529 1403551282.307536 read(119, "", 8192) = 0 <0.000004>
32529 1403551282.307558 close(119)      = 0 <0.000004>
32529 1403551282.307752 time(NULL)      = 1403551282 <0.000004>
32529 1403551282.307772 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.307977 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000007>
32529 1403551282.308010 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000028>
32529 1403551282.308054 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000004>
32529 1403551282.308074 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000004>
32529 1403551282.308105 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000004>
32529 1403551282.308126 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000005>
32529 1403551282.308160 read(119, "", 8192) = 0 <0.000004>
32529 1403551282.308183 close(119)      = 0 <0.000004>
32529 1403551282.308375 time(NULL)      = 1403551282 <0.000003>
32529 1403551282.308396 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.308463 time(NULL)      = 1403551282 <0.000004>
32529 1403551282.308482 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.308529 gettimeofday({1403551282, 308534}, NULL) = 0 <0.000004>
32529 1403551282.308562 time(NULL)      = 1403551282 <0.000004>
32529 1403551282.308581 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.309861 time(NULL)      = 1403551282 <0.000006>
32529 1403551282.309897 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000009>
32529 1403551282.310073 gettimeofday({1403551282, 310079}, NULL) = 0 <0.000004>
32529 1403551282.310098 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.310150 time(NULL)      = 1403551282 <0.000004>
32529 1403551282.310168 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.310206 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000004>
32529 1403551282.310259 write(3, "2014.06.23 21:21:22.310 3: rollo"..., 73) = 73 <0.000018>
32529 1403551282.310444 gettimeofday({1403551282, 310450}, NULL) = 0 <0.000015>
32529 1403551282.310479 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.310526 time(NULL)      = 1403551282 <0.000003>
32529 1403551282.310544 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.310582 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.310628 write(3, "2014.06.23 21:21:22.310 5: TXEG "..., 69) = 69 <0.000006>
32529 1403551282.310662 gettimeofday({1403551282, 310667}, NULL) = 0 <0.000004>
32529 1403551282.310684 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.310728 time(NULL)      = 1403551282 <0.000004>
32529 1403551282.310746 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.310783 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.310829 write(3, "2014.06.23 21:21:22.310 5: SW: 0"..., 60) = 60 <0.000005>
32529 1403551282.310866 write(100, "\f\32\0\0\v\356\21\3\1\0\0\0\0\0", 14) = 14 <0.000012>
32529 1403551282.310926 select(0, NULL, NULL, NULL, {0, 1000}) = 0 (Timeout) <0.001080>
32529 1403551282.312065 time(NULL)      = 1403551282 <0.000004>
32529 1403551282.312128 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000011>
32529 1403551282.312285 time(NULL)      = 1403551282 <0.000004>
32529 1403551282.312306 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000005>
32529 1403551282.317384 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000225>
32529 1403551282.318136 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000046>
32529 1403551282.318402 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000064>
32529 1403551282.318748 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000059>
32529 1403551282.319148 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000016>
32529 1403551282.319356 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000073>
32529 1403551282.319546 read(119, "", 8192) = 0 <0.000004>
32529 1403551282.319575 close(119)      = 0 <0.000007>
32529 1403551282.319944 time(NULL)      = 1403551282 <0.000046>
32529 1403551282.320152 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000045>
32529 1403551282.320953 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000060>
32529 1403551282.321256 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000045>
32529 1403551282.321463 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000078>
32529 1403551282.321725 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000045>
32529 1403551282.322158 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000059>
32529 1403551282.322366 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000090>
32529 1403551282.322665 read(119, "", 8192) = 0 <0.000058>
32529 1403551282.322872 close(119)      = 0 <0.000082>
32529 1403551282.325882 time(NULL)      = 1403551282 <0.000027>
32529 1403551282.326040 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000099>
32529 1403551282.330399 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000275>
32529 1403551282.331005 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000058>
32529 1403551282.331269 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000016>
32529 1403551282.331493 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000084>
32529 1403551282.331966 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000046>
32529 1403551282.332203 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000084>
32529 1403551282.332546 read(119, "", 8192) = 0 <0.000063>
32529 1403551282.332819 close(119)      = 0 <0.000074>
32529 1403551282.336921 time(NULL)      = 1403551282 <0.000060>
32529 1403551282.337145 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000059>
32529 1403551282.337769 time(NULL)      = 1403551282 <0.000059>
32529 1403551282.337977 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000078>
32529 1403551282.338508 gettimeofday({1403551282, 338537}, NULL) = 0 <0.000009>
32529 1403551282.338670 time(NULL)      = 1403551282 <0.000045>
32529 1403551282.338877 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000060>
32529 1403551282.341769 time(NULL)      = 1403551282 <0.000095>
32529 1403551282.341964 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000016>
32529 1403551282.344940 gettimeofday({1403551282, 344995}, NULL) = 0 <0.000036>
32529 1403551282.345134 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000025>
32529 1403551282.346902 gettimeofday({1403551282, 346955}, NULL) = 0 <0.000034>
32529 1403551282.347125 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000078>
32529 1403551282.378908 time(NULL)      = 1403551282 <0.000026>
32529 1403551282.379022 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000026>
32529 1403551282.380671 gettimeofday({1403551282, 380724}, NULL) = 0 <0.000027>
32529 1403551282.381052 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000090>
32529 1403551282.381938 time(NULL)      = 1403551282 <0.000029>
32529 1403551282.382129 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000140>
32529 1403551282.382925 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000091>
32529 1403551282.383503 write(3, "2014.06.23 21:21:22.380 3: rollo"..., 66) = 66 <0.000183>
32529 1403551282.387150 time(NULL)      = 1403551282 <0.000149>
32529 1403551282.387592 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000078>
32529 1403551282.388364 gettimeofday({1403551282, 388411}, NULL) = 0 <0.000017>
32529 1403551282.388482 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000158>
32529 1403551282.389082 time(NULL)      = 1403551282 <0.000074>
32529 1403551282.389326 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000075>
32529 1403551282.389925 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000104>
32529 1403551282.390732 write(3, "2014.06.23 21:21:22.388 3: rollo"..., 67) = 67 <0.000068>
32529 1403551282.412364 time(NULL)      = 1403551282 <0.000048>
32529 1403551282.412652 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000035>
32529 1403551282.413391 gettimeofday({1403551282, 413617}, NULL) = 0 <0.000093>
32529 1403551282.413935 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000029>
32529 1403551282.414253 time(NULL)      = 1403551282 <0.000105>
32529 1403551282.414412 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000044>
32529 1403551282.414589 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000017>
32529 1403551282.415548 write(3, "2014.06.23 21:21:22.413 3: rollo"..., 69) = 69 <0.000023>
32529 1403551282.418271 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000107>
32529 1403551282.418649 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000040>
32529 1403551282.418798 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000032>
32529 1403551282.418931 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000092>
32529 1403551282.419187 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000175>
32529 1403551282.419786 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000054>
32529 1403551282.420201 read(119, "", 8192) = 0 <0.000092>
32529 1403551282.420695 close(119)      = 0 <0.000075>
32529 1403551282.421777 time(NULL)      = 1403551282 <0.000060>
32529 1403551282.422063 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000089>
32529 1403551282.423247 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000122>
32529 1403551282.423852 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000196>
32529 1403551282.424313 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000124>
32529 1403551282.424656 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000074>
32529 1403551282.425143 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000048>
32529 1403551282.425352 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000051>
32529 1403551282.425501 read(119, "", 8192) = 0 <0.000018>
32529 1403551282.425832 close(119)      = 0 <0.000056>
32529 1403551282.428687 time(NULL)      = 1403551282 <0.000036>
32529 1403551282.428910 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000039>
32529 1403551282.429824 open("./www/images/openautomation/fts_window_2w.svg", O_RDONLY|O_LARGEFILE) = 119 <0.000103>
32529 1403551282.430227 ioctl(119, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffa6228) = -1 ENOTTY (Inappropriate ioctl for device) <0.000110>
32529 1403551282.430575 _llseek(119, 0, [0], SEEK_CUR) = 0 <0.000139>
32529 1403551282.430928 fstat64(119, {st_mode=S_IFREG|0644, st_size=1001, ...}) = 0 <0.000060>
32529 1403551282.431258 fcntl64(119, F_SETFD, FD_CLOEXEC) = 0 <0.000074>
32529 1403551282.431552 read(119, "<?xml version=\"1.0\" standalone=\""..., 8192) = 1001 <0.000022>
32529 1403551282.432018 read(119, "", 8192) = 0 <0.000045>
32529 1403551282.432207 close(119)      = 0 <0.000028>
32529 1403551282.436674 time(NULL)      = 1403551282 <0.000027>
32529 1403551282.436798 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000026>
32529 1403551282.437907 time(NULL)      = 1403551282 <0.000035>
32529 1403551282.438084 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000106>
32529 1403551282.438690 gettimeofday({1403551282, 438830}, NULL) = 0 <0.000088>
32529 1403551282.439110 time(NULL)      = 1403551282 <0.000073>
32529 1403551282.439454 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000093>
32529 1403551282.440562 write(112, "fhem> ", 6) = 6 <0.000842>
32529 1403551282.442064 write(111, "eg_bd_rollo<<open<<<div id=\"eg_b"..., 20494) = 20494 <0.001029>
32529 1403551282.443845 read(100, "\4\2\1\0\0", 255) = 5 <0.000115>
32529 1403551282.444307 gettimeofday({1403551282, 444375}, NULL) = 0 <0.000143>
32529 1403551282.444573 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000026>
32529 1403551282.444966 time(NULL)      = 1403551282 <0.000037>
32529 1403551282.445121 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000107>
32529 1403551282.445659 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000076>
32529 1403551282.446277 write(3, "2014.06.23 21:21:22.444 5: TRX/R"..., 43) = 43 <0.000027>
32529 1403551282.446702 gettimeofday({1403551282, 446763}, NULL) = 0 <0.000028>
32529 1403551282.446853 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000075>
32529 1403551282.447429 time(NULL)      = 1403551282 <0.000074>
32529 1403551282.447695 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000026>
32529 1403551282.447936 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000018>
32529 1403551282.448156 write(3, "2014.06.23 21:21:22.446 5: TRX: "..., 54) = 54 <0.000023>
32529 1403551282.448288 gettimeofday({1403551282, 448305}, NULL) = 0 <0.000013>
32529 1403551282.448366 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000106>
32529 1403551282.448991 time(NULL)      = 1403551282 <0.000053>
32529 1403551282.449142 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000026>
32529 1403551282.449391 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000045>
32529 1403551282.449732 write(3, "2014.06.23 21:21:22.448 5: TRX_R"..., 54) = 54 <0.000024>
32529 1403551282.450033 gettimeofday({1403551282, 450098}, NULL) = 0 <0.000039>
32529 1403551282.450276 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000039>
32529 1403551282.450758 time(NULL)      = 1403551282 <0.000088>
32529 1403551282.451054 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000089>
32529 1403551282.451622 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000068>
32529 1403551282.451992 write(3, "2014.06.23 21:21:22.450 5: TRX_R"..., 58) = 58 <0.000104>
32529 1403551282.452385 gettimeofday({1403551282, 452483}, NULL) = 0 <0.000095>
32529 1403551282.452824 gettimeofday({1403551282, 452886}, NULL) = 0 <0.000048>
32529 1403551282.453060 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000039>
32529 1403551282.453379 time(NULL)      = 1403551282 <0.000015>
32529 1403551282.453448 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000103>
32529 1403551282.453776 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000059>
32529 1403551282.454372 write(3, "2014.06.23 21:21:22.452 5: TRX_P"..., 52) = 52 <0.000110>
32529 1403551282.454850 gettimeofday({1403551282, 454936}, NULL) = 0 <0.000017>
32529 1403551282.455012 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000026>
32529 1403551282.455380 time(NULL)      = 1403551282 <0.000278>
32529 1403551282.455965 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000091>
32529 1403551282.456588 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000029>
32529 1403551282.457065 write(3, "2014.06.23 21:21:22.454 5: TXEG "..., 52) = 52 <0.000035>
32529 1403551282.458109 gettimeofday({1403551282, 458172}, NULL) = 0 <0.000035>
32529 1403551282.459419 gettimeofday({1403551282, 459472}, NULL) = 0 <0.000027>
32529 1403551282.459740 gettimeofday({1403551282, 459850}, NULL) = 0 <0.000097>
32529 1403551282.460120 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000158>
32529 1403551282.460611 time(NULL)      = 1403551282 <0.000028>
32529 1403551282.460722 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000026>
32529 1403551282.460932 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000101>
32529 1403551282.461378 write(3, "2014.06.23 21:21:22.459 5: TRX_E"..., 91) = 91 <0.000103>
32529 1403551282.461831 gettimeofday({1403551282, 461972}, NULL) = 0 <0.000029>
32529 1403551282.462200 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000138>
32529 1403551282.462884 time(NULL)      = 1403551282 <0.000082>
32529 1403551282.463117 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000026>
32529 1403551282.463387 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000137>
32529 1403551282.463914 write(3, "2014.06.23 21:21:22.461 5: TRX_E"..., 61) = 61 <0.000102>
32529 1403551282.464865 gettimeofday({1403551282, 464929}, NULL) = 0 <0.000036>
32529 1403551282.465075 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000110>
32529 1403551282.465649 time(NULL)      = 1403551282 <0.000075>
32529 1403551282.465916 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000047>
32529 1403551282.466371 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000091>
32529 1403551282.466898 write(3, "2014.06.23 21:21:22.464 5: TRX_E"..., 78) = 78 <0.000113>
32529 1403551282.467432 time(NULL)      = 1403551282 <0.000056>
32529 1403551282.467691 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000059>
32529 1403551282.468239 gettimeofday({1403551282, 468299}, NULL) = 0 <0.000076>
32529 1403551282.468560 gettimeofday({1403551282, 468624}, NULL) = 0 <0.000063>
32529 1403551282.468800 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000089>
32529 1403551282.469324 time(NULL)      = 1403551282 <0.000278>
32529 1403551282.469795 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000046>
32529 1403551282.470246 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0 <0.000075>
32529 1403551282.470813 write(3, "2014.06.23 21:21:22.468 5: TRX_R"..., 40) = 40 <0.000036>
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>

Filedescriptoren sahen beim Hänger wie folgt aus:
[code]COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
perl 32529 fhem cwd DIR 9,16 4096 1105411 /var/opt/fhem
perl 32529 fhem rtd DIR 9,11 1024 2 /
perl 32529 fhem txt REG 9,15 1487332 733808 /usr/bin/perl
perl 32529 fhem mem REG 9,11 95896 105098 /lib/i386-linux-gnu/libz.so.1.2.7
perl 32529 fhem mem REG 9,15 83456 341401 /usr/lib/perl5/auto/Compress/Raw/Zlib/Zlib.so
perl 32529 fhem DEL REG 0,14 12460 /run/nscd/dbPjTKDH
perl 32529 fhem mem REG 9,11 71488 104634 /lib/i386-linux-gnu/i686/cmov/libresolv-2.13.so
perl 32529 fhem mem REG 9,11 22088 104638 /lib/i386-linux-gnu/i686/cmov/libnss_dns-2.13.so
perl 32529 fhem mem REG 9,11 42628 104644 /lib/i386-linux-gnu/i686/cmov/libnss_files-2.13.so
perl 32529 fhem mem REG 9,15 17976 976159 /usr/lib/perl/5.14.2/auto/File/Glob/Glob.so
perl 32529 fhem mem REG 9,15 10888 35400 /usr/lib/perl5/auto/Device/SerialPort/SerialPort.so
perl 32529 fhem mem REG 9,15 17900 69316 /usr/lib/perl/5.14.2/auto/Digest/MD5/MD5.so
perl 32529 fhem mem REG 9,15 13712 1235926 /usr/lib/perl/5.14.2/auto/MIME/Base64/Base64.so
perl 32529 fhem mem REG 9,15 22024 1024152 /usr/lib/perl/5.14.2/auto/List/Util/Util.so
perl 32529 fhem mem REG 9,15 96252 342987 /usr/lib/perl/5.14.2/auto/POSIX/POSIX.so
perl 32529 fhem mem REG 9,15 17884 894245 /usr/lib/perl/5.14.2/auto/IO/IO.so
perl 32529 fhem mem REG 9,15 3456528 32701 /usr/lib/locale/locale-archive
perl 32529 fhem mem REG 9,11 38416 104672 /lib/i386-linux-gnu/i686/cmov/libcrypt-2.13.so
perl 32529 fhem mem REG 9,11 1441960 104678 /lib/i386-linux-gnu/i686/cmov/libc-2.13.so
perl 32529 fhem mem REG 9,11 117009 10467

rudolfkoenig · 24 Juni 2014, 18:18:09

@geek: hast du FHEMWEB ueber HTTPS oder HTTP angesprochen?

geek · 24 Juni 2014, 18:52:29

Hi,

das ist plain HTTP.

Rainer

rudolfkoenig · 12 Juli 2014, 13:37:33

@geek: ich habe das Problem versucht nachzustellen unter OSX und unter Linux (Ubuntu 10.04) ohne Erfolg, FHEM hat sich wie gewuenscht verhalten.

Welches Betriebsystem- bzw. perl-Version verwendest Du auf dem FHEM-Server?
Welches OS und Browser auf dem Client?

Ich habe eine modifizierte fhem.pl Version angehaengt, der auf verbose 1 die Writebuffer Aktivitaeten protokolliert, kannst du bitte das Problem mit diesem fhem.pl nachstellen, und die letzten Zeilen aus dem Log vor dem Haenger hier posten?

geek · 13 Juli 2014, 09:18:45

Hi,

Fhem Server läuft auf debian wheezy mit nem 3.2.0er Kernel Package. Perl ist das dortige v5.14.2.

Client ist ebenfalls debian wheezy mit 3.2.0er Kernel Package. Browser ist der wheezy "iceweasel" version 24.6.0 (also der "firefox" von debian).

Client und Server sind im gleichen Subnetz. Gibt also auch kein Gateway, daß irgendwann wegen fehlendem ARP ein icmp destination unreachable schickt.

Ablauf:

longpoll + longpollSVG eingeschaltet
Rollo overview Seite auf client aufgerufen
ethernet kabel vom client abgezogen (08:36:36)
Rollo status ein paar mal verändert (08:37:10)
fhem hängt im write()
irgendwann fliegt dann auch die MAC vom client aus dem ARP cache des servers
packet capture zeit retransmit der daten
... bis socket in retransmit timeout läuft

Das ist genau das zu erwartende Verhalten wenn vom Client *nichts* (also kein TCP ACK/RST oder ICMP irgendwas) zurück kommt.

Da select() und write() nix voneinander wissen, ist es irgendwie naheliegend, daß select() - wie justme1968 zitiert - nur ein "strong hint" ist .

Code Auswählen

2014.07.13 08:36:09.670 1: WB add: FHEMWEB:192.168.1.12:56844 9235  to initial
2014.07.13 08:36:09.687 1: WB FHEMWEB:192.168.1.12:56844 write, length 9235
2014.07.13 08:36:09.688 1:    write returned 9235
2014.07.13 08:37:10.237 3: rollo eg_bd_rollo: offen -> open
2014.07.13 08:37:10.259 1: WB add: FHEMWEB:192.168.1.12:56844 1007  to initial
2014.07.13 08:37:10.261 3: rollo eg_of_rollo: offen -> open
2014.07.13 08:37:10.274 1: WB add: FHEMWEB:192.168.1.12:56844 1007 to 1007
2014.07.13 08:37:10.275 3: rollo eg_sz_rollo: offen -> open
2014.07.13 08:37:10.281 1: WB add: FHEMWEB:192.168.1.12:56844 1007 to 2014
2014.07.13 08:37:10.283 3: rollo eg_wz_kueche_rollo: offen -> open
2014.07.13 08:37:10.290 1: WB add: FHEMWEB:192.168.1.12:56844 1035 to 3021
2014.07.13 08:37:10.291 3: rollo eg_wz_rollo_giebel: offen -> open
2014.07.13 08:37:10.298 1: WB add: FHEMWEB:192.168.1.12:56844 1035 to 4056
2014.07.13 08:37:10.299 3: rollo eg_wz_terasse_fenster_rollo: offen -> open
2014.07.13 08:37:10.320 1: WB add: FHEMWEB:192.168.1.12:56844 1071 to 5091
2014.07.13 08:37:10.321 3: rollo eg_wz_terasse_tuer_rollo: offen -> open
2014.07.13 08:37:10.328 1: WB add: FHEMWEB:192.168.1.12:56844 1059 to 6162
2014.07.13 08:37:10.332 3: rollo ug_kr_rollo_links: offen -> open
2014.07.13 08:37:10.333 3: rollo ug_kr_rollo_rechts: offen -> open
2014.07.13 08:37:10.335 3: rollo ug_kr_hof_tuer_rollo: offen -> open
2014.07.13 08:37:10.336 1: WB add: FHEMWEB:192.168.1.12:56844 1095 to 7221
2014.07.13 08:37:10.336 1: WB FHEMWEB:192.168.1.12:56844 write, length 8316
2014.07.13 08:37:10.336 1:    write returned 8316
2014.07.13 08:37:10.884 3: rollo eg_bd_rollo: offen -> open
2014.07.13 08:37:10.890 1: WB add: FHEMWEB:192.168.1.12:56844 1007  to initial
2014.07.13 08:37:10.892 3: rollo eg_of_rollo: offen -> open
2014.07.13 08:37:10.899 1: WB add: FHEMWEB:192.168.1.12:56844 1007 to 1007
2014.07.13 08:37:10.900 3: rollo eg_sz_rollo: offen -> open
2014.07.13 08:37:10.907 1: WB add: FHEMWEB:192.168.1.12:56844 1007 to 2014
2014.07.13 08:37:10.908 3: rollo eg_wz_kueche_rollo: offen -> open
2014.07.13 08:37:10.914 1: WB add: FHEMWEB:192.168.1.12:56844 1035 to 3021
2014.07.13 08:37:10.916 3: rollo eg_wz_rollo_giebel: offen -> open
2014.07.13 08:37:10.922 1: WB add: FHEMWEB:192.168.1.12:56844 1035 to 4056
2014.07.13 08:37:10.924 3: rollo eg_wz_terasse_fenster_rollo: offen -> open
2014.07.13 08:37:10.931 1: WB add: FHEMWEB:192.168.1.12:56844 1071 to 5091
2014.07.13 08:37:10.932 3: rollo eg_wz_terasse_tuer_rollo: offen -> open
2014.07.13 08:37:10.939 1: WB add: FHEMWEB:192.168.1.12:56844 1059 to 6162
2014.07.13 08:37:10.943 3: rollo ug_kr_rollo_links: offen -> open
2014.07.13 08:37:10.944 3: rollo ug_kr_rollo_rechts: offen -> open
2014.07.13 08:37:10.945 3: rollo ug_kr_hof_tuer_rollo: offen -> open
2014.07.13 08:37:10.946 1: WB add: FHEMWEB:192.168.1.12:56844 1095 to 7221
2014.07.13 08:37:10.946 1: WB FHEMWEB:192.168.1.12:56844 write, length 8316
2014.07.13 08:52:36.587 1:    write returned 5792
2014.07.13 08:52:36.588 1: Perfmon: possible freeze starting at 08:37:11, delay is 925.588

Code Auswählen

warp:/opt/fhem# date; lsof -ni :8083
Sun Jul 13 08:36:22 CEST 2014
COMMAND  PID USER   FD   TYPE   DEVICE SIZE/OFF NODE NAME
perl    9387 fhem    7u  IPv4 16544581      0t0  TCP *:8083 (LISTEN)
perl    9387 fhem  112u  IPv4 16545589      0t0  TCP 192.168.2.3:8083->192.168.1.12:56844 (ESTABLISHED)
perl    9387 fhem  113u  IPv4 16545590      0t0  TCP 192.168.2.3:8083->192.168.1.12:56845 (ESTABLISHED)
perl    9387 fhem  114u  IPv4 16545591      0t0  TCP 192.168.2.3:8083->192.168.1.12:56846 (ESTABLISHED)
perl    9387 fhem  115u  IPv4 16545592      0t0  TCP 192.168.2.3:8083->192.168.1.12:56847 (ESTABLISHED)
perl    9387 fhem  116u  IPv4 16545593      0t0  TCP 192.168.2.3:8083->192.168.1.12:56848 (ESTABLISHED)
perl    9387 fhem  117u  IPv4 16545594      0t0  TCP 192.168.2.3:8083->192.168.1.12:56849 (ESTABLISHED)

warp:/opt/fhem# date; lsof -ni :8083
Sun Jul 13 08:37:15 CEST 2014
COMMAND  PID USER   FD   TYPE   DEVICE SIZE/OFF NODE NAME
perl    9387 fhem    7u  IPv4 16544581      0t0  TCP *:8083 (LISTEN)
perl    9387 fhem  112u  IPv4 16545589      0t0  TCP 192.168.2.3:8083->192.168.1.12:56844 (ESTABLISHED)
perl    9387 fhem  113u  IPv4 16545590      0t0  TCP 192.168.2.3:8083->192.168.1.12:56845 (ESTABLISHED)
perl    9387 fhem  114u  IPv4 16545591      0t0  TCP 192.168.2.3:8083->192.168.1.12:56846 (ESTABLISHED)
perl    9387 fhem  115u  IPv4 16545592      0t0  TCP 192.168.2.3:8083->192.168.1.12:56847 (ESTABLISHED)
perl    9387 fhem  116u  IPv4 16545593      0t0  TCP 192.168.2.3:8083->192.168.1.12:56848 (ESTABLISHED)
perl    9387 fhem  117u  IPv4 16545594      0t0  TCP 192.168.2.3:8083->192.168.1.12:56849 (ESTABLISHED)

rp:/opt/fhem# netstat -an | grep 8083
tcp        0      0 0.0.0.0:8083            0.0.0.0:*               LISTEN
tcp        0      0 192.168.2.3:8083        192.168.1.12:56849      ESTABLISHED
tcp        0      0 192.168.2.3:8083        192.168.1.12:56847      ESTABLISHED
tcp        0      0 192.168.2.3:8083        192.168.1.12:56848      ESTABLISHED
tcp        0      0 192.168.2.3:8083        192.168.1.12:56846      ESTABLISHED
tcp        0  14108 192.168.2.3:8083        192.168.1.12:56844      ESTABLISHED
tcp        0      0 192.168.2.3:8083        192.168.1.12:56845      ESTABLISHED

Die Statusänderungen machen übrigens soviel Traffic, weil per devStateIcon Icons gesetzt werden:

Code Auswählen

define eg_bd_rollo TRX_LIGHT RFY 0BEE1003 light
attr eg_bd_rollo IODev TXEG
attr eg_bd_rollo bundle eg_rollo
attr eg_bd_rollo devStateIcon (down|close):fts_shutter_100@yellow:open (gap|stop):fts_shutter_60@yellow:open (up|open):fts_window_2w:open
attr eg_bd_rollo eventMap /up:open/down:close/stop:gap/
attr eg_bd_rollo group Rollo
attr eg_bd_rollo icon fts_shutter_100
attr eg_bd_rollo room eg_bd,eg,D_rollo
attr eg_bd_rollo structexclude .*:.*
attr eg_bd_rollo webCmd open:close:gap

Rainer

geek · 13 Juli 2014, 09:43:36

Hi,

Habe mir das gerade mal quick + dirty auf nonblock umgebaut. Das hat keinen Anspruch auf Vollständigkeit - habe nicht geprüft, ob das überall richtig behandelt wird - aber es funktioniert (tm):

Code Auswählen

--- /home/bj/git/fhem/fhem/FHEM/TcpServerUtils.pm       2014-07-09 16:21:52.000000000 +0200
+++ FHEM/TcpServerUtils.pm      2014-07-13 09:27:15.000000000 +0200
@@ -49,9 +49,9 @@
 }
 
 sub
-TcpServer_Accept($$)
+TcpServer_Accept($$;$)
 {
-  my ($hash, $type) = @_;
+  my ($hash, $type, $nonblocking) = @_;

   my $name = $hash->{NAME};
   my @clientinfo = $hash->{SERVERSOCKET}->accept();
@@ -80,6 +80,10 @@
     }
   }

+  if( $nonblocking ){
+    $clientinfo[0]->blocking(0);
+  }
+
   if($hash->{SSL}) {
     # Certs directory must be in the modpath, i.e. at the same level as the
     # FHEM directory
--- /home/bj/git/fhem/fhem/FHEM/01_FHEMWEB.pm   2014-07-09 16:21:52.000000000 +0200
+++ FHEM/01_FHEMWEB.pm  2014-07-13 09:26:47.000000000 +0200
@@ -246,7 +246,7 @@
   my $name = $hash->{NAME};
 
   if($hash->{SERVERSOCKET}) {   # Accept and create a child
-    TcpServer_Accept($hash, "FHEMWEB");
+    TcpServer_Accept($hash, "FHEMWEB", 1);
     return;
   }

damit läufts dann:

Code Auswählen

2014.07.13 09:33:56.423 1: WB add: FHEMWEB:192.168.1.12:56903 9235  to initial
2014.07.13 09:33:56.425 1: WB FHEMWEB:192.168.1.12:56903 write, length 9235
2014.07.13 09:33:56.426 1:    write returned 9235
2014.07.13 09:34:29.429 3: rollo eg_bd_rollo: offen -> open
2014.07.13 09:34:29.439 1: WB add: FHEMWEB:192.168.1.12:56903 1007  to initial
2014.07.13 09:34:29.441 3: rollo eg_of_rollo: offen -> open
2014.07.13 09:34:29.447 1: WB add: FHEMWEB:192.168.1.12:56903 1007 to 1007
2014.07.13 09:34:29.448 3: rollo eg_sz_rollo: offen -> open
2014.07.13 09:34:29.454 1: WB add: FHEMWEB:192.168.1.12:56903 1007 to 2014
2014.07.13 09:34:29.456 3: rollo eg_wz_kueche_rollo: offen -> open
2014.07.13 09:34:29.463 1: WB add: FHEMWEB:192.168.1.12:56903 1035 to 3021
2014.07.13 09:34:29.464 3: rollo eg_wz_rollo_giebel: offen -> open
2014.07.13 09:34:29.470 1: WB add: FHEMWEB:192.168.1.12:56903 1035 to 4056
2014.07.13 09:34:29.472 3: rollo eg_wz_terasse_fenster_rollo: offen -> open
2014.07.13 09:34:29.478 1: WB add: FHEMWEB:192.168.1.12:56903 1071 to 5091
2014.07.13 09:34:29.480 3: rollo eg_wz_terasse_tuer_rollo: offen -> open
2014.07.13 09:34:29.486 1: WB add: FHEMWEB:192.168.1.12:56903 1059 to 6162
2014.07.13 09:34:29.490 3: rollo ug_kr_rollo_links: offen -> open
2014.07.13 09:34:29.491 3: rollo ug_kr_rollo_rechts: offen -> open
2014.07.13 09:34:29.492 3: rollo ug_kr_hof_tuer_rollo: offen -> open
2014.07.13 09:34:29.493 1: WB add: FHEMWEB:192.168.1.12:56903 1095 to 7221
2014.07.13 09:34:29.493 1: WB FHEMWEB:192.168.1.12:56903 write, length 8316
2014.07.13 09:34:29.493 1:    write returned 8316
2014.07.13 09:34:30.036 3: rollo eg_bd_rollo: offen -> open
2014.07.13 09:34:30.042 1: WB add: FHEMWEB:192.168.1.12:56903 1007  to initial
2014.07.13 09:34:30.043 3: rollo eg_of_rollo: offen -> open
2014.07.13 09:34:30.050 1: WB add: FHEMWEB:192.168.1.12:56903 1007 to 1007
2014.07.13 09:34:30.051 3: rollo eg_sz_rollo: offen -> open
2014.07.13 09:34:30.058 1: WB add: FHEMWEB:192.168.1.12:56903 1007 to 2014
2014.07.13 09:34:30.060 3: rollo eg_wz_kueche_rollo: offen -> open
2014.07.13 09:34:30.066 1: WB add: FHEMWEB:192.168.1.12:56903 1035 to 3021
2014.07.13 09:34:30.068 3: rollo eg_wz_rollo_giebel: offen -> open
2014.07.13 09:34:30.074 1: WB add: FHEMWEB:192.168.1.12:56903 1035 to 4056
2014.07.13 09:34:30.075 3: rollo eg_wz_terasse_fenster_rollo: offen -> open
2014.07.13 09:34:30.082 1: WB add: FHEMWEB:192.168.1.12:56903 1071 to 5091
2014.07.13 09:34:30.083 3: rollo eg_wz_terasse_tuer_rollo: offen -> open
2014.07.13 09:34:30.090 1: WB add: FHEMWEB:192.168.1.12:56903 1059 to 6162
2014.07.13 09:34:30.093 3: rollo ug_kr_rollo_links: offen -> open
2014.07.13 09:34:30.094 3: rollo ug_kr_rollo_rechts: offen -> open
2014.07.13 09:34:30.095 3: rollo ug_kr_hof_tuer_rollo: offen -> open
2014.07.13 09:34:30.096 1: WB add: FHEMWEB:192.168.1.12:56903 1095 to 7221
2014.07.13 09:34:30.096 1: WB FHEMWEB:192.168.1.12:56903 write, length 8316
2014.07.13 09:34:30.096 1:    write returned 5792
2014.07.13 09:34:30.245 3: rollo eg_bd_rollo: offen -> open
2014.07.13 09:34:30.263 1: WB add: FHEMWEB:192.168.1.12:56903 1007 to 2524

um 09:33:56 war der initiale request für die overview Seite.
dann wurde wieder Ethernet vom client abgezogen.
um 09:33:56 waren die status updates ...
und der letzte write im obigen log schreibt dann nur soviel in den socket send buffer, wie passt.
fhem hängt sich nicht auf

Rainer

rudolfkoenig · 13 Juli 2014, 14:34:45

Nach meinem Verstaendnis schreibt syswrite() auf einem Netzwerk-Kanal nach einem OK von select soviel, wie moeglich ist, und das ist mindestens 1 Byte. Erst wenn man vorher kein OK vom select bekommen hat, blockiert sich ein write ohne NONBLOCK.

Nun ist das in deinem Fall vermutlich anders, auch wenn ich das bei mir nicht nachstellen kann.
Vermutlich deswegen, weil es noch sein kann, dass nach dem select sonswer vorher auf diesem Kanal Daten schreibt, obwohl ich jetzt nicht wuesste, wer.

Vielen Dank fuer dein Vorschlag, ich gehe ein Stueck weiter, und ich rufe in TcpServer_Accept $clientinfo[0]->blocking(0) immer auf, da ich in FHEM kein Fall vorstellen kann, wo blockieren gewuenscht ist. Die Funktion wird von FHEMWEB, telnet und FRM verwendet. Telnet und FHEMWEB werde ich, falls noetig anpassen und ich hoffe, dass Norbert (FRM) damit auch kein Problem haben wird.
Es schient bei mir auch mit blocking(0) zu funktionieren, ich habe etliche Browser und SSL getestet.

geek · 13 Juli 2014, 16:05:39

Hi,

Ein ok von nem Select() dürfte nur "sicher" sein, wenn man anschließend nur 1 Byte schreibt. Würde ich mich aber auch nicht drauf verlassen.

Wir haben hier einen recht speziellen Fall: Der Client ist im Problemfall ja aus fhem/Server Sicht komplett "tot". Welcher browser/OS da nix zurück schickt dürfte keine Rolle spielen. Sobald vom Client irgendwas zurück kommt (RST, ACK, ICMP, ...) gibt es das Problem nicht. Sprich - solange du noch Kommunikation zwischen Server und Client OS hast, gibts kein Problem. Browser beenden oder Client normal herunterfahren reicht normal nicht, weil die Sockets dann noch zu gemacht werden.

Das fällt wirklich nur auf, wenn du den client bei offener TCP connection vom Netz trennst oder hart ausschaltest (hibernate oder sleep sind vergleichbar). Mittels tcpdump kann man ganz gut schauen ob/was da an Packeten tatsächlich geschickt wird.

Hatte mich nicht getraut das Ausnahmslos in TcpServer_Accept() zu machen weil ich keinen Überblick habe ob alle read()/write() auf diesen Sockets dann auch sauber den gelieferten "EAGAIN" Fehler behandeln (... und ob das in Perl überhaupt nötig ist - habe ich nur in C Erfahrungen mit).

Rainer

rudolfkoenig · 13 Juli 2014, 17:54:44

ZitatSobald vom Client irgendwas zurück kommt (RST, ACK, ICMP, ...) gibt es das Problem nicht.

Ist mir auch klar (ich habe TCP/IP Illustrated auch mal studiert), ich konnte es bei mir aber nicht reproduzieren. Ich habe auf dem Android Geraet WLAN abgeschaltet, das duerfte vergleichbar mit Stecker ziehen sein, im FHEM war die Verbindung weiterhin da. select() hat beim mir so funktioniert wie ich es erwartet habe, und nach eine Weile nichts mehr an den Androiden gesendet. Ist aber auch egal, selbst wenn ich mit meiner Theorie recht haette, existiert das Problem bei dir, und falls die Loesung dir hilft, dann ist es noetig.

Zitatich keinen Überblick habe ob alle read()/write() auf diesen Sockets dann auch sauber den gelieferten "EAGAIN" Fehler behandeln

Ich erwarte keine Probleme, wenn doch, muss gefixed werden.
Blockieren finde ich nicht akzeptabel solange wir im Haupt-Prozess sind und kein Multithreading haben.

hexenmeister · 14 Juli 2014, 22:44:34

Moin zusammen!

Heute nach dem Update hatte ich ein Problem: FHEM lief zwar und auch Telnet-Verbindung war noch einwandfrei, die WebOberfläche ging jedoch nicht mehr. Ich durfte mich noch anmelden (eine Warnung wegen des selbsterstellten SSL-Zertifikat kam auch), dann war die Verbindung unterbrochen (Chrome meldet: Keine Daten empfangen). Getestet mit FireFox (Win7), Chrome (Win7), Chrome (Android). Gleiches Ergebnis.
Log:

Code Auswählen

2014.07.14 22:18:04.400 4: Connection accepted from FHEMWEB:192.168.0.58:62966
2014.07.14 22:18:04.464 4: HTTP FHEMWEB:192.168.0.58:62966 GET /fhem
2014.07.14 22:18:05.198 5: SET: Unknown argument ?, choose one of clear:readings,register,rssi,msgEvents,all getConfig getRe gRaw pair peerBulk peerChan raw regBulk regSet reset sign:on,off unpair
2014.07.14 22:18:05.369 5: SET: Unknown argument ?, choose one of clear:readings,register,rssi,msgEvents,all down getConfig  getRegRaw getSerial inhibit:on,off off on pair pct:slider,0,1,100 peerBulk peerIODev press raw regBulk regSet reset sign:on, off statusRequest stop toggle unpair up
2014.07.14 22:18:05.372 5: SET: Unknown argument ?, choose one of clear:readings,register,rssi,msgEvents,all down getConfig  getRegRaw getSerial inhibit:on,off off on pair pct:slider,0,1,100 peerBulk peerIODev press raw regBulk regSet reset sign:on, off statusRequest stop toggle unpair up
2014.07.14 22:18:05.405 5: SET: Unknown argument ?, choose one of clear:readings,register,rssi,msgEvents,all down getConfig  getRegRaw getSerial inhibit:on,off off on pair pct:slider,0,1,100 peerBulk peerIODev press raw regBulk regSet reset sign:on, off statusRequest stop toggle unpair up

Als Ursache konnte ich die Datei TcpServerUtils.pm ermitteln (die Version 5350 noch funktionsfähig, die 6250 nicht mehr).
Die einzige signifikante Änderung ist in der Zeile 83 zu finden:

Code Auswählen

$clientinfo[0]->blocking(0); # Forum #24799

Ich habe zunächst die alte Datei eingespielt. Aber eine 'richtige' Lösung wäre doch schöner

Habe nur ich das Problem? Was kann ich dagegen tun? Soll ich ergendwas testen/asuprobieren?

Grüße,

Alexander

eppi · 15 Juli 2014, 08:22:25

Hallo

ZitatHabe nur ich das Problem?

Nein, auch ich musste zurück wechseln auf die alte Version (5350) von TcpServerUtils.pm.
Bei mir hat sich beim Klick auf das Icon das DeviceIcon nicht aktualisiert (Gerät hat geschalten), mit der alten Version funktionierte das problemlos.

Meine Konfig des Device:

Code Auswählen

define Kuerbis FS20 2323 61
attr Kuerbis IODev MyCUNO_OG
attr Kuerbis devStateIcon off:icon_aus@red on:icon_ein@green
attr Kuerbis follow-on-for-timer 1
attr Kuerbis model fs20st
attr Kuerbis room Garten

Und FHEM-Web:

Code Auswählen

define WEBphone FHEMWEB 8084 global
attr WEBphone closeConn 1
attr WEBphone iconPath fhemSVG:openautomation:default
attr WEBphone reverseLogs 1
attr WEBphone stylesheetPrefix ios7smallscreen

Getestet habe ich mit FireFox (aktuelle Version) und iOS 7.02
Danke und Gruss Eppi

rudolfkoenig · 15 Juli 2014, 09:23:26

Ich habe die fragliche Zeile erstmal auskommentiert und sie direkt zum upload bereitgestellt, da es offensichtlich viele Leute betrifft.

Und nun zum Einkreisen des Problems, da ich es bei mir so einfach (HTTP bzw. HTTPS, Client FF,Chrome,Safari) nicht nachstellen kann.
- Gibt es nur Probleme mit SSL?
- Welcher OS wird auf dem Server, welcher auf dem Client verwendet?
- Wie "weit" ist der Server vom Client entfernt?
- Wie schnell ist der Client/Server?

hexenmeister · 15 Juli 2014, 09:57:49

Moin!

- Ich verwende ausschliesslich SSL.
- FHEM läuft auf einem RaspberryPi (Raspbian). Clientseitig habe ich es mit Win7 und Android (CyanogenMod 11 und original 4.3.x auf dem Samsung-Tablet) getestet.
- Probleme gab es sowohl bei der direkten Verbindung im LAN als auch von außen (Port-Weiterleitung im Router).
- Der Server ist halt ein Pi. Clients waren ein Core2Duo Win7 Laptop, ein S3 mini und ein Galasy Tab 4.

Andre · 15 Juli 2014, 15:45:20

Hallo,

ich habe heute das gleich Problem gehabt, das Update behebt das Problem. Danke dafür. Immer wenn ich eine Seite aufrufen wollte, hing der Browser, wenn ich dann Stop (im Browser) geklickt habe, war die Seite da. Quasi nicht bedienbar.

Ich habe folgende Konfiguration (nahezu alle kreuz und quer getestet):

- rPi (512MB) mit wheezy
- ClientOS: iOS, Windows, Ubuntu
- Browser: Safari, Chrome
- Problem tritt sowohl im lokalen Netz (Client <-> Server nebeneinander) als auch Remote via UMTS auf.

Zusätzlich ist mir bei der Verwendung via UMTS Karte aufgefallen, dass scheinbar eine Menge Daten über die Leitung gingen. Ich hab mein Limit erreicht...

Ich kann natürlich nicht sicher sagen, ob dies an dem FHEM Problem liegt, aber jetzt ist der Traffic wieder geringer.

HTH

Gruß
André

geek · 15 Juli 2014, 19:18:18

Hi,

ok, so wie's aussieht muß auch in perl EAGAIN bei sysread()/syswrite() behandelt werden - und IO::Socket::SSL braucht auch ne Sonderbehandlung für non-blocking sockets:

http://search.cpan.org/~sullr/IO-Socket-SSL-1.997/lib/IO/Socket/SSL.pod#Using_Non-Blocking_Sockets

Ist also wie Anfangs angedeutet keine triviale Änderung. Mein einfacher Aufruf von ->blocking(0) war halt wirklich nur "quick'n'dirty" zum Eingrenzen des Hängers. Ehrlich gesagt bin ich überrascht daß es bei mir ohne weiter Änderung funktioniert - Sorry, wenn ich das nicht klar zum Ausdruck gebracht habe und deswegen was kaputt gegangen ist.

sorry
Rainer

(der bis zum überschreiten seiner Schmerzschwelle erstmal wieder longpoll aus hat)

herrmannj · 17 Juli 2014, 13:22:45

Hi,

ich häng mich da mal rein weil ich mich eben auch als Betroffener erkannt habe. Allerdings meine ich das longpoll nur EIN symptom (bzw EINE Auswirkung sind).

Fehler insgesamt: fhem stoppt die Auslieferung von Daten: webif hängt, longpoll hängt ....
(kein ssl, gzip deaktiviert)

* Lokal (lokaler Browser: FF14) am dev-notebook (schnell): Fehler tritt sehr selten auf, so selten das ich den erst als dev Fehler von mir vermutet habe.
* Netzwerk (schnell) an anderem Notebook (sauschnell): Wenn pgm2 "große" Seiten ausliefert hängt pgm2 bereits bei der Seitenauslieferung (spoaradisch, häufig, selbstredend nicht sicher reproduzierbar) stehen. Verbindung offen aber fhem schweigt einfach autistisch. edit & add in der Mitte der Seite
* Floorplan, Netzwerk: Fehler tritt extrem selten auf ( he ? basiert doch auf der gleichen Infrastruktur

)
* longpoll: verhält sich analog zum webif: dev-nb: geht meistens. dito floorplan remote (lokal Netz). longpoll im pgm2 Interface: bleibt plötzlich stehen (state 3, also noch offen). Danach Glückspiel: durchaus möglich das einige xx Sekunden später plötzlich die Aktualisierungen nachgereicht werden und die Auslieferung seitens fhem wieder "anspringt".
Gleichzeitig bleibt fhem von anderen clients erreichbar.

Insgesamt recht unbefriedigend und scheinbar auch echt eine never-ending story. $:-\$

Die "neue" tcputils.pm halbiert die Fehler Rate (machts also besser), Fehler bleibt jedoch bestehen !!!

vg
Jörg

justme1968 · 17 Juli 2014, 13:45:41

wenn man in safari 5 oder 6 tabs öffnet bleiben alte und neue tabs komplett hängen und werden erst gefüllt wenn man alte tabs schließt.

gruss
andre

hexenmeister · 17 Juli 2014, 13:51:23

Das mit 5-6 offenen Tabs habe ich schon lange beobachtet (FireFox).

herrmannj · 17 Juli 2014, 13:58:28

Hi Danke,

Zitatwenn man in safari 5 oder 6 tabs öffnet bleiben alte und neue tabs komplett hängen und werden erst gefüllt wenn man alte tabs schließt.

machen alle browser aufgrund einer Beschränkung der offenen connections zu EINEM host. Die zählen pro browser und nicht pro tab!

Als genereller Hinweis gut gemeint jedoch bekannt und beachtet. Mit dem beschriebenen hat das nichts zu tun.

Danke und Grüße
Jörg

justme1968 · 17 Juli 2014, 14:39:07

dann müssten aber die schon offenen tabs unverändert weiter laufen. die bleiben aber auch hängen.

gruss
andre

herrmannj · 17 Juli 2014, 16:27:58

Ah verstehe. Ist das ein fhem spezifisches Verhalten ?

vg
Jörg

rudolfkoenig · 10 August 2014, 13:57:33

@geek: kannst Du bitte alarmTimeout testen? Siehe diese Diskussion.

satprofi · 17 August 2014, 13:09:18

Hallo.
Bin gerade über diesen Thread gestolpert, auch ich habe Probs mit WebIF. Musste immer per telnet fhem killen u. neustarten.
Habe das ganze zufällig einkreisen können, es lag an "myrss". ich hatte als letzte meldung im log immer "xmllist" als fehler, und eine IP meines tablets.
jetzt habe ich myrss deleted und jetzt klappts bisher ohne hänger schon seit 3h.

ich hoffe es bleibt so.

satprofi · 18 August 2014, 17:56:47

hallo.
da heutewieder massenhaft hänger vorhanden, und keiner der tablets rss geladen hatten, bin ich der sache auf den grund gegangen. da kam ich drauf, das ein tablet webviewcontrol noch im hintergrund laufen hatte, das auch diese komische xmllist als cmd sendete. jetzt habe ich webviewcontrol dort beendet und konnte sofort das webif von fhem aufrufen. mal gucken ob dies jetzt für ruhe sorgt.

geek · 03 Dezember 2014, 20:25:30

Hi,

sorry für die späte Rückmeldung... bin leider nicht vorher dazu gekommen, zu testen.

Wie zu erwarten verbessert alarm() die Situation, verhindert kurze Hänger aber nicht komplett. Habe also mal geschaut, ob/wie ich das non-blocking hinbekomme ohne was anderes kaputt zu machen. Wie original beschrieben muss bei non-blocking nach jedem syswrite/-read errno geprüft werden... und im Zusammenhang mit SSL entstehen noch weitere Sonderfälle.

Erstmal zum reproduzieren:

Code Auswählen


# - longpoll einschalten
# - die neuen SVG icons for on/off nehmen - mit den default png icons gibts nicht genug traffic
define WEB FHEMWEB 8183 global
attr WEB iconPath fhemSVG:openautomation:default
attr WEB longpoll 1
attr WEB longpollSVG 1
attr WEB plotfork 1
define WEBS FHEMWEB 8184 global
attr WEBS HTTPS 1
attr WEBS iconPath fhemSVG:openautomation:default
attr WEBS longpoll 1
attr WEBS longpollSVG 1
attr WEBS plotfork 1

# ein paar dummys anlegen (nicht zu viele - sonst gibs andere Probleme)
define bulk01 dummy
...
define bulk29 dummy

# web-browser aufmachen, "Everything" room anzeigen.

# auf client connections "leise" wegwerfen:
iptables -A OUTPUT -j DROP -p tcp --dport 8183:8184

# per telnet updates erzeugen:
set bulk.* on
set bulk.* off

# fhem hängt, Recv-Q ist randvoll:
# netstat -an | grep 8183
Proto Recv-Q Send-Q Local Address           Foreign Address         State      
tcp        0      0 0.0.0.0:8183            0.0.0.0:*               LISTEN     
tcp        0      0 192.168.2.3:8183        192.168.1.12:51428      ESTABLISHED
tcp        0      0 192.168.2.3:8183        192.168.1.12:51427      ESTABLISHED
tcp        0      0 192.168.2.3:8183        192.168.1.12:51423      ESTABLISHED
tcp        0  53576 192.168.2.3:8183        192.168.1.12:51425      ESTABLISHED
tcp        0      0 192.168.2.3:8183        192.168.1.12:51424      ESTABLISHED
tcp        0      0 192.168.2.3:8183        192.168.1.12:51426      ESTABLISHED

Anbei ist ein Patch der in fhem.pl die Basis für nonblocking Sockets legt und diese erstmal nur in fhemweb nutzt. Per default lässt sich non-blocking nicht einschalten ohne was kaputt zu machen. Ähnlich wie fhemweb müßten auch in andere module angepasst werden.

Bei mir tuts - auch mit SSL - aber ich wette nicht alle Situationen reproduzieren zu können. Gerade mit SSL ist das recht ... unübersichtlich.

Ich würde also vorschlagen, daß erstmal von ein paar wagemutigen testen zu lassen bevor ein commit in betracht gezogen wird.

Als nächstes würde ich mir das telnet modul anschauen.

BTW: Beim testen hatte ich auch Probleme, wenn der writebuffer schon 102400 Zeichen lang war - addToWritebuffer wirft dann die neuen Daten kommentarlos weg. Das kann bei großen updates (>40 dummys in obigem config Beispiel) auch ohne hängende connection passieren! Da bin ich noch unentschlossen, wie man das "richtig" verbessert.

rudolfkoenig · 04 Dezember 2014, 21:32:45

Wo kann ich was ueber want_write und want_read nachlesen?

geek · 04 Dezember 2014, 21:52:28

Hi,

in der Doku zu neuerem IO::Socket::SSL gibts die ersten Hinweise: http://search.cpan.org/~sullr/IO-Socket-SSL-2.007/lib/IO/Socket/SSL.pod#Using_Non-Blocking_Sockets (getestet habe ich mit IO::Socket::SSL verision 1.76).

Nach mehrfachem lesen hat mir aber http://stackoverflow.com/questions/3952104/how-to-handle-openssl-ssl-error-want-read-want-write-on-non-blocking-sockets geholfen.

Kurz: Unser select() sagt, daß der TCP socket lese-/schreibfähig ist - weiß aber nicht ob das auch für die dadrüber liegende SSL Session gilt.

Deswegen gibt die SSL Session über den SSL_WANT_READ/_WRITE Umweg zurück, was sie als nächstes tun muß - und bittet uns ihr zu sagen, wann der TCP Socket dafuer bereit ist.

So habe ich das zumindest Verstanden...

Rainer

rudolfkoenig · 05 Dezember 2014, 10:04:43

Da wird aber ueberall von SSL_WANT_READ geredet, und du verwendest want_read, und das habe ich nirgendwo gefunden. Und dieses sleep(1) in fhem.pl stoert mich sehr.
Auf wagemutige Tester brauchst du nicht zu hoffen, das ist einer(!) der Gruende, warum ein developer Zweig fuer FHEM zwecklos ist.

geek · 05 Dezember 2014, 16:51:12

Hi,

want_read und want_write sind in IO::Socket::SSL.pm definiert:

sub want_read { shift->errstr == SSL_WANT_READ }
sub want_write { shift->errstr == SSL_WANT_WRITE }

die beiden Methoden zu verwenden ist deutlich übersichtlicher als die constants nur bei Bedarf zu importieren.

Der sleep findet nur in einem child prozess statt und verhindert ein CPU hog wenn syswrite bei wiederholten Aufrufen EWOULDBLOCK liefert. Einfach wäre, den Socket wieder blocking zu machen - da der Socket aber zwischen parent/child geteilt ist, bin ich nicht sicher ob das nur im child Prozess auf den Filedescriptor wirkt oder auf den Socket. Alternativ müßte dort auch mit select()+want_read/_write gewartet werden.

Wenns keine Tester gibt - wie wird sowas sonst gehandhabt?

Rainer

rudolfkoenig · 05 Dezember 2014, 19:51:53

ZitatWenns keine Tester gibt - wie wird sowas sonst gehandhabt?

Ich teste es bei mir, und danach check ich es ein. Bei Problemen gibts dann ein Aufschrei, und entweder wird es danach gefixt, oder ich nehme die Aenderung zurueck. So war doch hier im Juli auch.

Da es gerade parallel eine weiteres Problem gibt (FHEM-Absturz wg. Wide-Character, siehe http://forum.fhem.de/index.php?topic=29939), wuerde ich diese Aenderung erst mal auf ruhigere Tage verschieben. Kannst du dich (oder sonswer) in ein-zwei Wochen wieder melden?

geek · 05 Dezember 2014, 19:58:40

Hi,

klar - hat Zeit. Gibt ja Workarounds.

Soll ich in der Zeit noch nach ner alternativen Lösung für den sleep() schauen?
... oder Vermeiden, die undokumentierten want_read/_write Methoden zu nutzen?

Rainer

rudolfkoenig · 05 Dezember 2014, 20:45:23

Eigentich beides. Ist zwar nur fuer die Psyche, das ist aber auch wichtig.

geek · 11 Dezember 2014, 23:30:03

Hi,

so... beim Umbauen habe ich mir das noch genauer angeschaut... und noch einige Ecken und Kanten abrunden müssen.

Die meisten zusätlichen Änderungen sind auch ohne non-blocking relevant.

Habe den Patch daher in die einzelnen Schritte aufgeteilt:

fhemweb: minor logging adjustments

add name + pid to logging
provide details on reason for socket close
FHEMWEB/TcpServer: copy SSL to client socket

to simplify checking for SSL use.
will be used extensivly for nonblocking
FHEMWEB: avoid crash on accept error
fhem/FHEMWEB: handle addToWriteBuffer errors

on a full buffer addToWriteBuffer just droppped the data without telling the caller.
this caused strange issues (hanging longpoll,...).
FHEMWEB: fix socket handling when forking

a) while child writes a new request might arrive if client uses pipelining or
b) parent doesn't know about ssl-session changes due to child writing to socket
-> have to close socket in parent... so that its only used in this child.

check for pid in addToWriteBuffer was matching in parent process, only. Renamed "pid" to be more obvious.
prepare writing on non-blocking sockets

converted current blocking writes to use a new function that'll handle this for non-blocking sockets.
fehmweb was also mixing print/syswrite which is considered harmful - not sure if it actually caused issues.
previously write errors weren't handled, either.
made fhemweb sockets non-blocking

Da ich nachträglich Aufgeteilt habe bin ich nicht 100% sicher ob jeder Schritt einzeln funktioniert - im Ganzen läufts bei mir nun aber einwandfrei.

@Rudi: Würde mich freuen wenn du mal drüber schaust und anmerkst was ich noch ändern soll. Ich wette da gibts noch was

BTW: die "TcpServer_WriteBlocking" Aufrufe lassen sich theoretisch 1:1 durch addToWriteBuffer ersetzen... dann könnte aber die Größe des Buffers ein Problem werden. Um 100% nonblocking zu werden wäre das aber eigentlich nötig.

Rainer

geek · 12 Dezember 2014, 07:30:41

Hi,

*argh* - doch noch nicht einwandfrei... kommt noch was.

Rainer

rudolfkoenig · 12 Dezember 2014, 09:05:35

Dann warte ich noch.
Hast Du eine Moeglichkeit dein Patch auch einem Windows Rechner zu testen?
Nonblocking@Windows ist etwas anders.

geek · 12 Dezember 2014, 18:00:15

Hi,

Fehler gefunden: Dicke Finger beim Aufteilen des Patches. Anbei die korrigierte Version.

IO::Socket::SSL sagt, es könne auch Nonblocking mit Windows... ein passendes System habe ich aber leider nicht.

Rainer

rudolfkoenig · 12 Dezember 2014, 20:44:23

Kriege ich bitte ein Patch was man mit patch anwenden kann?

geek · 12 Dezember 2014, 21:05:20

hi,

oh, tut "patch -p1 < nonblocking.diff" nicht? komisch.

Egal - hab's umformattiert, lässt sich jetzt mit "patch -p0 nonblocking-gesamt.patch" am Stück anwenden.

Alternativ sind die einzelnen Änderungen auch in separaten Dateien angehängt - ebenfalls für patch -p0.

Sollte das auch nicht gehen ... mit welchem Fehler steigt patch aus?

Rainer

rudolfkoenig · 12 Dezember 2014, 21:12:55

nonblocking-gesamt.patch hat funktioniert, danke.

rudolfkoenig · 14 Dezember 2014, 16:56:26

Dein Patch ist zwar gross, ich habe aber keine Probleme damit entdecken koennen. Ich habe es eine Weile mit Linux (Ubuntu 14.04), OSX und WinXP getestet, mit und ohne SSL, hauptsaechlich mit fhem.cfg.demo.

Habe es nur kosmetisch geaendert und eingecheckt.