longpollSVG Problem mit 01_FHEMWEB.pm r7212

[fhainz]

Hallo Rudi!

Ich hab seit dem FHEMWEB Update auf r7212 ein eigenartiges Problem, tritt nur mit Safari und nur bei gesetztem longpollSVG Attribut.
Wenn in einem Raum mehrere Plots vorhanden sind fangen diese zum Blinken an. Bei einem einzelnen Plot, Raum- oder Detail Ansicht, passiert nichts. Wenn ich die Datei zurückspiele passt wieder alles.

FHEM läuft auch MacMini 10.10.1, schon mehrfach neugestartet
Zugriff mit MacBook Air mit Safari, auch schon mehrfach neugestartet
Mit iOS Safari auch kein Problem.

Hast du eine Idee?

Grüße

[geek]

Hi,

da könnte ein Zusammenhang mit den non-blocking Änderungen bestehen...

Hast du dazu vieleicht ein paar Details zu dem Problem? Ist bei der benutzten fhemweb Instanz SSL aktiv?
Wie sieht's mit Meldungen im Logfile aus?

Bitte auch dem fhemweb mittels verbose 5 Attribut mehr Details entlocken während du das Problem nachstellst.

Rainer

[geek]

Hi,

hmm, bekomme die SVGs nur zum flackern wenn ich böse Dinge tue. Sprich... wenn in den .gplot files nicht wie dokumentiert der devicename steht sondern eine regexp.

Dann macht firefox nach ungefähr 500kb updates vom fhem die connection zu um es nochmal zu probieren. Wie gesagt - böse Dinge die ich da tue - explizit entgegen der Doku.

Normal kann ich das nicht reproduzieren. Brauche also wirklich mehr Details... vieleicht auch ein packet capture?

Rainer

[adson3492]

Ich sehe im Log leider auch nichts besonderes, und habe erstmal keine Idee.

[geek]

Hi,

so, Update... erstmal ein paar Korrekturen:

   
• ist garnicht so böse was ich tue: Der filter=.* wird von fhemweb.js unabhängig vom gplot gesetzt. Das passiert sobald longpollSVG gesetzt ist und ein SVG in der Seite eingebettet ist. Meine "Bösartigkeit" (Pattern statt Device Name im gplot) führt nur dazu dass die SVGs nicht aktuallisiert werden.
• es sind genau 300kb nach denen fhemweb.js die connection zu macht.

Inzwischen ist klar, was bei mir zum flackern führt: Beim Aufbau der longpoll Verbindung wird erstmal mittels FW_roomStatesForInform der Status für alles auf den filter passende geliefert. Darin enthalten sind auch SVG devStateIcons. Passt der longpoll Filter auf sehr viele Devices mit SVG Icons wird die Antwort also schnell seeehr gross. Wie oben beschrieben führt eine übergrosse Antwort dazu, daß fhemweb.js es nochmal probiert. Bei jedem dieser Versuche sieht fhemweb_svg.js die events und lädt die SVGs neu und verursacht das flackern.

Soweit so gut... unklar ist mir aber noch, warum das vorher funktioniert hat. Vor dem change wurde die initiale Antwort komplet an print() gegeben - und wenns schief gegangen ist wurde das still ignoriert. Jetzt wird dagegen sicher gestellt, daß die Daten auch wirklich gesendet werden. Eigentlich hätte das per print aber auch ausgeliefert werden müssen. Untersuche ich noch.

Ich verstehe noch nicht, warum überhaupt mittels FW_roomStatesForInform der initiale Status verteilt wird. @Rudi, kannst du mir da helfen?

Für das identifizierte Problem sehe ich spontan folgende Lösungsoptionen - kann aber nicht einschätzen welche die am wenigsten schlechte ist:

   
• keinen initialen Status mehr ausliefern
• das 300kb Limit in fhemweb.js hochdrehen
• kann man den responseString vieleicht vorzeitig irgendwie freigeben um das im Kommentar erwähnte Memory Problem zu vermeiden
• einen magischen Weg finden, den Filter passender zu gestalten. zB über ein händisch (bahpfui) zu pflegendes Attribut im SVG modul.

Ob das auch Euer Problem ist, weiss ich noch nicht. Ohne Logs ist ausgeschlossen das zu sagen. Also... bitte verbose einschalten und Logs liefern:

Code Auswählen Erweitern

attr TYPE=FHEMWEB verbose 5

Danke

[fhainz]

Hallo!

Sry, ich bin erst jetzt dazu gekommen.

Ist bei der benutzten fhemweb Instanz SSL aktiv?

Nein.

Wie sieht's mit Meldungen im Logfile aus?

Keine Auffälligkeiten mit verbose 3. Das Log mit verbose 5 hänge ich an.

Ich verstehe noch nicht ganz was du mit "böser" syntax meinst. Kannst du mir vielleicht zeigen was du meinst?

Code Auswählen Erweitern

# Created by FHEM/98_SVG.pm, 2014-05-18 10:15:33
set terminal png transparent size <SIZE> crop
set output '<OUT>.png'
set xdata time
set timefmt "%Y-%m-%d_%H:%M:%S"
set xlabel " "
set title '<L1>'
set ytics
set y2tics
set grid ytics
set ylabel "Aktuell"
set y2label "Aktuell"
set yrange [0:1000]
set y2range [0:1000]

#FileLog 4:stromverbrauchAllgemein.power\x3a::$fld[3]>300?300:$fld[3]
#FileLog 4:stromverbrauchAllgemein.power\x3a::$fld[3]>500?500:$fld[3]
#FileLog 4:stromverbrauchAllgemein.power\x3a::
#FileLog 4:stromverbrauchAllgemein.power\x3a::
#FileLog 4:stromverbrauchAllgemein.power\x3a::

plot "<IN>" using 1:2 axes x1y2 title '0 - 300 W' ls l1fill lw 0.2 with lines,\
     "<IN>" using 1:2 axes x1y2 title '300 - 500 W' ls l4fill lw 0.2 with lines,\
     "<IN>" using 1:2 axes x1y2 title '> 500 W' ls l0fill lw 0.2 with lines,\
     "<IN>" using 1:2 axes x1y2 title '.' ls l4fill lw 0.2 with lines,\
     "<IN>" using 1:2 axes x1y2 title '.' ls l7 lw 0.2 with lines
Ich bin mir auch (fast) sicher das ich die Plots damals mit Buttom "Create SVG Plot" angelegt hab. Die Plots bearbeite ich immer mit dem Plot Editor. Die .gplot Dateien greife ich nie an.

Grüße

[geek]

Hi,

so, kein SSL ist gut. Dann ists keine der dafür nötigen Sonderbehandlungen. Dein Log sagt, du läufst in das Problem was ich beschrieben habe: Die wiederholten XHR requests und das EOF (client hat connection zu gemacht) zeigen das.

"böse" syntax haste nicht. In deinem gplot steht ja "stromverbrauchAllgemein.irgendwas". Der Devicename ist also drin. Mein Kommentar war auch eher an die gegebenenfalls mitlesenden Entwickler gerichtet. Egal. spielt hier jetzt auch keine Rolle mehr.

Damit haben wir geklärt was dein jetztiges Problem ist und welche Optionen es zum reparieren gibt.
@Rudi: Mir fehlt da etwas der Überblick welche Option am sinnvollsten ist - baue aber gerne einen patch wenn ich die Richtung weiß.

Wenn du magst kannst du ja mal in  www/pgm2/fhemweb.js das Limit in Zeile 117 hochdrehen:

Code Auswählen Erweitern


  // reset the connection to avoid memory problems
  if(FW_pollConn.responseText.length > 300*1024)

Danach die Seite neu laden ... und schauen obs besser wird. Wie der Kommentar sagt, ist das aber auch nicht ohne Probleme.

Völlig unklar ist mir dagegen warum das vorher funktioniert hat. Kannst du mir vieleicht von "vorher" ein verbose 5 log schicken?

Ich hänge auch mal 2 verschiedene Versionen von 01_FHEMWEB.pm mit debug code an. Wenn's geht würde ich mich da auch jeweils über ein verbose 5 log freuen.

Rainer

[herrmannj]

Hallo geek,

könnte das evtl hiermit zu tun haben ?
http://forum.fhem.de/index.php/topic,23774.msg183266.html#msg183266

vg
jörg

[geek]

Hi,

ja, laut svn blame ist das in r6243 eingepflegt worden - und das Referenziert deinen Thread.

JavaScript hab' ich bisher immer n großen Bogen drum gemacht... aber wenn der responseText readonly ist, lässt sich das auf dem client nicht fixen. Dann muß dem server beigebracht werden, initial nur events auszuliefern die seit dem generieren der Seite oder dem letzten longpoll entstanden sind.

Selbst wenn man dashboard, longpollSVG und floorplan (...) ne Möglichkeit gibt, ihren ".*" filter durch was selektiveres zu ersetzen, ist das nur ein Aufschub des Problems.

Ich schau mal, ob ich die events nach ner timestamp filtern kann.

Rainer

[herrmannj]

doch, doch - der patch ist leider nicht eingecheckt sondern nur ein Teil davon, meiner Meinung nach auch fehlerhaft.

Das Problem könnte mglw daran liegen das der longpoll nach 300k brutal zurückgesetzt wird ohne das geprüft wird ob die letzte Nachricht komplett ist.

Es gibt ja keine Garantie das der XHR state 3 nur dann aufgerufen wird wenn das letzte event auch komplett im Puffer liegt.

Das Szenario das der Schere des Zensors zum Opfer gefallen ist lautet so:

fhemweb liefert die events als stream, ein event ist zur Hälfte ausgeliefert, XHR triggert stage 3, fhemweb.js sieht die Schwelle von 300k überschritten und macht den cut im longpoll. Das könntest du das jetzt unbewusst (und schuldlos) durch Deinen patch getriggert haben, evtl entsteht ja ein Zeitslot innerhalb eines events (puffer voll, Teilauslieferung, dann zweiter step). Schlussendlich ist mMn nirgendwo spezifiziert zu welchem Zeitpunkt der XHR den stage 3 weiterreicht.

Das ist nur ein Verdacht, beim überfliegen des threads schien mir ein Zusammenhang aber sehr möglich.

In der Konsequenz würde ein hoch setzen der 300k Schwelle das Problem nur verlagern - imho korrekt ist einzig den Longpoll (clientseitig) nur dann zu schliessen wenn das letzte event komplett empfangen und verarbeitet ist (lastchar "\n").

Generell darf die Menge der Daten (sprich filter .*) keine Rolle spielen, warum auch. Gemessen an der zur Verfügung stehenden Bandbreite ist das doch ein Klacks.

vg
Jörg

[geek]

Hi,

wenn ich deinen patch richtig verstanden habe, löst der nur das Speicherproblem wenn die events natürlich über die Zeit entstanden sind.

Hier ist aber das Problem, daß fhem beim connect schon so viel ausliefert, daß das limit überschritten wird. Sprich, selbst wenn der client erst die initialen events komplett verarbeitet bevor er die connection zu macht, entsteht das gleiche problem beim nächsten connect wieder wenn fhem wieder die gleiche riesen-antwort als Begrüßung schickt.

Vorraussetzung ist also, daß fhem den Status von sehr vielen Devices per longpoll ausliefern soll... also wenn der filter auf sehr viele devices passt (zb. das .* von longpollSVG, floorplan oder dashboard). Per longpoll werden aber auch die SVG devStateIcons ausgeliefert ... und damit wird die initiale Response von fhem auch schon bei einer überschaubaren Anzahl Devices zu groß.

Habe die initiale Response auf nen commit zurückgeführt, der das Loch zwischen Generierung der Seite und erstem XHR request schließt. Kann man also nicht rauswerfen - sondern muß "repariert" werden.

Vor meiner Änderung wurde die initiale reponse am Stück mittels "print" auf den blocking Socket geschrieben... Ob das erfolgreich war wurde nicht geprüft.

Nach der Änderung werden die Daten so lange an syswrite gegeben, bis alles geschrieben ist. Der Rest von meinem Patch hat keine Auswirkung auf diesen codepfad.

Möglich ist also eigentlich nur, daß print nicht alles ausgeliefert hat. Kann ich bei mir aber nicht reproduzieren, bei mir tut das auch vor der Änderung nicht. Ich verstehe ehrlich gesagt auch nicht warum print auf einem blocking socket Daten hätte unterschlagen sollen.

Rainer

[geek]

Hi,

so, anbei ist ein Patch als "proof of concept". Erstmal nur das Senden der initialen Informs ab einer Timestamp (mit fallback auf now-5sec). Apply geht mit "patch -p1 < initial-longpoll-proof-of-concept.diff" im fhem Verzeichniss.

Theoretisch reicht das so... verpasst aber Informs wenn der client > 5sec zwischen Generieren der Seite und erstem longpoll Request braucht. Ebenso verpasst der client Informs wenn zwischen 2 longpolls mehr als 5sec vergehen.

Beides ist nicht sooo trivial zu fixen (zumindest nicht für mich als javascript/html Noob):

• Wo kann fhem beim Generieren einer Seite die Timestamp unterbringen dass der Client die sieht? Das müßte dann an allen Stellen passieren, die longpoll aktivieren (schneller grep finden neben FHEMWEB auch FLOORPLAN).
• Die Informs für STATE haben keine Timestamp vom Server. Nimmt der Client seine eigene Timestamp vom Empfang eines Informs erfasst das also nicht die Zeit von Versand + Auswertung.

Rainer

[herrmannj]

Hallo Rainer,

ich habe Deinen Post leider nicht ganz verstanden ..  aber während ich darüber nachdenke ist mir tatsächlich ein zweites, fundamentales, Problem im longpoll klar geworden (das meinst Du vmtl)

wenn ich deinen patch richtig verstanden habe, löst der nur das Speicherproblem wenn die events natürlich über die Zeit entstanden sind.

evtl. Weil Du gesagt hast das Du um js einen Bogen machst, mache ich einen kurzen Ausflug zum XHR Objekt damit wir den gleichen Stand haben (verzeih mit wenn Du das alles schon weißt)
Das XHR wurde in die browser eingebaut um, idR asynchrony und vom js aus, eine x-beliebige (damals meist XML) Datei vom Server zu holen.

Dazu wird eine ganz normale Anfrage an den Server initiiert und der Server sollte diese Datei am Stück aus liefern. Wenn die Datei komplett geladen ist wird ein event (das ist stage 4) generiert und die Datei kann vom script verarbeitet werden.

Das sich das ganze überhaupt für longpoll verwenden lässt liegt daran das die Entwickler von Mozilla eine Funktion eingebaut haben die während des ladens der Datei ab und zu mal aufgerufen wird. Die war im Ursprung dazu gedacht das der Entwickler einen Fortschrittsbalken anzeigen kann. Deshalb bekommt man in dieser Funktion auch Zugriff auf responseText (der Balken muss ja wissen wie viele kb/mb schon geladen sind).

Der lonpoll (auf Serverseite) macht ja jetzt nichts anderes als eine unendlich große Datei, ganz langsam auszuliefern.

Deshalb entsteht der Speicheraufwand immer "natürlich über die Zeit". Mal schneller, mal langsamer.

Genau genommen haben wir also zwei Probleme:
* das initiale Laden des state (auch svg, völlig korrekt!) ist strukturell (in den longpoll Daten) nicht von der Aktualisierung getrennt.
* beim aktualisieren der states wird nicht darauf geachtet das ein event komplett empfangen wird bevor der longpoll (beim erreichen der Schwelle) den re-connect ausführt.

Die daraus entstehende Schleife hast Du (wenn ich Dich an dieser Stelle richtig verstehe ?) richtig diagnostiziert: nach jedem reconnect werden wieder alle initial states gepusht - die Schwelle wird erreicht - reconnect -  push - reconnect - ...

Wenn man die (300k) - Schwelle höher setzt lassen sich die Auswirkungen (auf #1) vmtl verringern - das Problem bleibt aber bestehen weil es im Design von fhemweb angelegt ist.

vg
jörg

off-topic: ich bin bei dem Thema noch ein wenig emotional weil es "damals" über 2 Monate gedauert bis Rudi (bei allem Respekt und Anerkennung für seine Verdienste) sich den patch überhaupt angeschaut hat - und dann fachlich falsch und unvollständig umgesetzt hat.

Andere Themen (das initial pushen hatte ich damals genau auch, post vom 31.5) gab es nie eine response. ... jquery loader ist, offen gesagt Schrott, - am Ende hat mich das gezwungen ein fhemweb Erweiterungsprojekt in das schon viel Arbeit geflossen war komplett in die Tonne zu treten. Am Ende sind die Wege des Schicksals unergründlich - ich hätte sonst nie das smartVisu Projekt übernommen das heute (völlig unabhängig vom der fhemweb Stabilität) schon eine ganz andere Liga ist.

[geek]

Hi,

ja, hast du richtig verstanden, da sind mehrere Probleme mit fhem/-web (ich würde mich da nicht auf 2 Beschränken )

Was ich sehe, versuche ich zu fixen... und freue mich, wenns nicht nur in meiner lokalen Version ist.

Als ich bei mir die Hänger vom Fhemweb gesehen habe, war das für mich eigentlich nur der Anstoß non-blocking IO zu  reparieren... zumindest in den von mir genutzten modulen. Ist nicht wirklich einfach, weil wir für alles das Rad neu erfinden müssen ... oder man fhem auf eine "gängige" mainloop a'la AnyEvent umbauen müßte.

Habe auch schon begeistert Deinen SmartVisu Thread gesehen

Rainer

[herrmannj]

ja, hast du richtig verstanden, da sind mehrere Probleme mit fhem/-web (ich würde mich da nicht auf 2 Beschränken )

check 

Als ich bei mir die Hänger vom Fhemweb gesehen habe, war das für mich eigentlich nur der Anstoß non-blocking IO zu  reparieren... zumindest in den von mir genutzten modulen. Ist nicht wirklich einfach, weil wir für alles das Rad neu erfinden müssen ... oder man fhem auf eine "gängige" mainloop a'la AnyEvent umbauen müßte.

vg
jörg