cgi-bin/r? liefert leere Response

[mivola]

Hallo,

nach einem Update auf die aktuelle git-Version der CV (develop) habe ich ein Problem mit dem Anzeigen der KNX Stati. Die CV & eibd etc läuft auf dem WireGate (Version 1.4.0).

Folgendes Verhalten:
- Aufruf der Visu: http://wiregateXYZ/visu.git/ (auch mit "forceReload=true")
- die Visu-Elemente werden (sehr) schnell geladen und angezeigt
- jedoch: die Stati (Temperaturen, Ein/Aus) sind undefiniert
- nach ziemlich genau 60 Sekunden werden die Stati korrekt angezeigt (klingt also nach einem Timeout)
- wenn ich zwischendurch das Refresh-Widget benutze, werden die Stati auch sofort korrekt angezeigt
- in der Developer Console sehe ich keine Fehler
- ich sehe folgenden Request: http://wiregate302/cgi-bin/r?s=undef....&a=9/6/74&t=0 welcher mit Response Code 200 innerhalb von 1-2 Sekunden fertig ist
- allerdings: der Response ist leer!
- wenn ich den Request danach manuell im Browser öffne, sehe ich eine korrekte Response: {"d": {"1/1/0":"00",.....,"9/6/251":"00"},"i":49088}
- auch die Requests nach dem 60-Sekunden-Timeout & dem Benutzen des Refresh-Widgets haben eine korrekte Response

- dieselbe Config läuft in einer älteren Version der CV (ca 1 Jahr alt) problemlos
- folgende Unterschiede hab ich festgestellt:
-- sofort nachdem der erste Request fertig ist, wird der nächste gestartet
-- die Request-URL hat einen Unterschied: "r?s=SESSION" statt "r?s=undefined"

- wenn ich die URL mit "enableCache=invalid" aufrufe, wird nur die leere weiße "Loading"-Seite angezeigt und einen Fehler in der Console protokolliert:
ConfigCache.js:91 Uncaught TypeError: Cannot read property 'configSuffix' of undefined
ConfigCache.clear @ ConfigCache.js:91
TemplateEngine @ TemplateEngine.js:117
getInstance @ TemplateEngine.js:1764
(anonymous function) @ main.js:86
execCb @ require-2.1.15.min.js:29
.....

- getestet mit Chromium 51 & Firefox 45.7 auf Windows

Also meine Frage wäre nun also: woran liegt es, dass der erste r?-Request erfolgreich ist, aber keine Response drin ist? Und: warum werden keine Folge-Requests aufgebaut?

Danke und VG
Micha

[XueSheng]

Auf den ersten Blick würde ich sagen, das hört sich danach an (Thread Titel und wesentlicher Inhalt passen in folgendem Link nicht mehr zusammen):
https://knx-user-forum.de/forum/supp...-2-und-rev2742
oder auch
https://github.com/CometVisu/CometVisu/issues/250

[Robert_Mini]

Hallo zusammen!

Ich sehe auch Parallelen zum Problem von XueSheng und mir.
Aber:
- bei mir erfolgt in vielen Fällen kein read request
- nach 60s bzw. Reload ist das Laden der Stati nur manchmal erfolgreich => Refresh teste ich heute noch.
- enableCache=invalid lädt, hat aber keinen Einfluss auf das Laden der Stati

@mivola: kannst auch du einen wireshark protokoll hochladen?

lg
Robert

[Chris M.]

Ich gehe auch davon aus, dass es das gleiche Thema ist. Daher würde es lieber in diesem Thread weiter bearbeiten, da der andere Thread sich nur dorthin entwickelt hat und hier die Beschreibung und der Titel besser passt.

[Robert_Mini]

Hallo zusammen!

Habe grad nochmal eine Stunde herumgetestet:

Aktuelle visu von github mit modifizierter "CometVisuClient.js" => "...git2_special..."
- Lädt wesentlich zuverlässiger
- Manchmal sofort, aber eigentlich immer (10x getestet) nach spätestens 60s.

Aktuelle visu von github mit original "CometVisuClient.js" => "...git2_dev..."
- Lädt selten sofort
- Lädt selten nach 60s
- Manchmal 120s, manchmal 328s, etc.

Die release 0.10.0 ist ähnlich "...0.10.0..."

Hier nochmal der Link zu meiner Dropbox mit den Wireshark Files:
https://www.dropbox.com/sh/lldzqubmu...8BOy0zcLa?dl=0

Screenshot zur Übersicht, immer mit Datum voran.

Der Refresh funktioniert bei mir nicht wirklich. Sehe auch kein read, das damit ausgelöst wird?!

lg
Robert

[Chris M.]

OK; schön zu sehen, dass das einen Einfluss hat.

Gerade habe ich mich mit einem der 0.10 Captures (den mit 250s) beschäftigt:
Schaue ich mir das Read mit Paket 2626 (bei 4,2s) an, so sehe ich, dass der Server mit 4320 (5,14s) und 4352 (5,19s) antwortet. Diese Antwort scheint mit dem zweiten Paket (also dem 4352) final beendet zu sein, da dort nur noch ein "0\r\n\r\n" geschickt wird, was wohl bei einem "Transfer-Encoding:chunked" das inhaltliche Ende kennzeichnet.
Mit Paket 5055 (12,46s) schickt der Server noch das FIN, ACK um die TCP-Verbindung zu beenden, was der Browser mit 5057 (12,46s) seinerseits mit FIN, ACK bestätigt.

Erst mit Paket 5261 (64,2s) kommt das nächste r.

=> Frage 1: Warum dauert es von 4352 bis 5055, also gut 7 Sekunden, bis der Server nach dem letzten Paket auch die Verbindung schließt?
(Evtl. ist das Absicht wegen Keep-Alive oder so? Ich bin hier auf diesen OSI-Schichten nicht wirklich firm...)
=> Frage 2: Warum braucht der Client von 5055 (oder gar 4352?) bis 5261, also 50 oder gar 60 Sekunden, bis ein neues r abgesetzt wird?

Da die Frage 1 rein auf dem Server und Backend basiert, das hier aber nicht geändert wurde, können wir diese Fragestellung hier erst mal hinten anstellen.
Die Antwort auf Frage 2 dürfte die Antwort auf das hier beschriebene Problem sein, insb. scheint hier das Verhalten zwischen 0.9.2 und 0.10.0 unterschiedlich zu sein
=> Ich werde mal diesbezüglich den 0.10.0 Client reviewen

Zum Refresh: Bitte merken, und nach Lösung des Aufstartthemas nochmal in Erinnerung rufen

[Chris M.]

Noch eine Frage: Robert_Mini XueSheng verwendet ihr enableQueue?

[Robert_Mini]

Ich rufe die Cometvisu ohne weitere Parameter in der URL auf (nur config=...).
lg Robert

[XueSheng]

Aufruf bei mir auch nur mit "?config=".

[peuter]

Ihr könntet das Ganze mal mir der aktuellen 0.11.0-dev Version ausprobieren. Die ist zwar eigentlich noch zu frisch für solche Spielchen, aber einen Versuch wäre es trotzdem mal wert. Dazu einfach den aktuellsten Nighly Build herunterladen https://bintray.com/peuter/CometVisu...0320200544.zip und dann installieren wie ein normales Release.

Wenn Eure Config darin fehlerfrei lädt gut, wenn Ihr dann auch noch das Problem nachstellen könnt noch besser, dann könnt Ihr nämlich mal folgendes tun (bitte im Chrome Browser machen):

1. Visu mit zusätzlichem URL-Parameter &reporting=true neu laden
2. Warten bis das Problem auftritt
3. Browser-Console öffnen (mit F12) und dort downloadLog() eingeben und die Datei die dann heruntergeladen wird mir zukommen lassen.

Zur Erklärung: Damit wird sämtliche Kommunikation zwischen CometVisu + Backend aufgezeichnet inkl. Benutzerinteraktionen (also Klicks irgendwohin usw.) und das kann ich dann bei mir abspielen (im Grunde wie ein Video, nur dass das Ganze in echt simuliert wird). In der Hoffnung das der Fehler dadurch irgendwie sichtbarer wird und mit dem gewonnenen Erkenntnissen auch im aktuellen Release gefixt werden kann.

Noch ein Hinweis: In dem Logfile befindet sich Eure komplette Config-Datei. d.h. wer die nicht veröffentlichen möchte sollte das Ganze nicht tun. Außerdem sollten sensible Daten aus den Configs (z.B. irgendwelche Zugangsdaten zu Webcams oder so) entfernt werden.

[peuter]

Oh und noch ein Hinweise vergessen. Wenn Ihr danach im selben Browser die selbe Config mit der aktuellen Release/Git Version ladet, muss auch jedenfall beim erstenmal mit &enableCache=invalid der Cache gelöscht werden.

[Chris M.]

Neben dem, dass die zukünftige 0.11 getestet werden sollte, habe ich einen Verdacht, an was es liegen kann.
=> Bitte in der 0.10.0 die CometVisuClient.js durch die angehängte Datei ersetzen

1. Ist das Problem jetzt gelöst?
2. Was kommt auf der Konsole, insb. wenn es "etwas dauert" bis die Stati da sind?

(Wenn das den Fehler behebt, würde ich noch die Instrumentierung rauswerfen und ein 0.10.1 daraus bauen...)

[mivola]

Neben dem, dass die zukünftige 0.11 getestet werden sollte, habe ich einen Verdacht, an was es liegen kann.
=> Bitte in der 0.10.0 die CometVisuClient.js durch die angehängte Datei ersetzen

1. Ist das Problem jetzt gelöst?
2. Was kommt auf der Konsole, insb. wenn es "etwas dauert" bis die Stati da sind?

(Wenn das den Fehler behebt, würde ich noch die Instrumentierung rauswerfen und ein 0.10.1 daraus bauen...)

Also bei mir funktioniert dieser Fix sehr gut! Der erste Response ist zwar immer noch leer, aber direkt nach dieser Antwort wird ein neuer Request geschickt und der enthält dann auch Daten die umgehend angezeigt werden.

Zuvor hatte ich (aufgrund der Kommentare in Issue 250) bereits folgendes getestet: selbe Config wie bisher, nur die rsslog-Widgets habe ich gelöscht. Und siehe da: die Config zeigt die Stati beinahe "sofort" an. Das liegt wohl daran, dass der erste Response nicht leer ist sondern valide Daten enthält!

Es scheint also 2 Probleme zu geben, aber immerhin ist der erste Fix ja schon in Sichtweite :-)

Danke und VG
Micha

[XueSheng]

Chris M.
Mit der neuen CometVisuClient.js verhält sich die Visu deutlich besser, jedoch scheint das Problem noch nicht gelöst (Browser cache wurde geleert!). Wenn keine Antwort auf t=0 kommt, folgt gleich die nächste Anfrage und die Werte werden schneller nachgeladen (davor immer 1 Minute Wartezeit). In der Console konnte ich jedoch häufiger beobachten, dass die erste Anfrage unbeantwortet bleibt. Angefügt ein Screenshot als Extremfall (wieder eine Häufung von leeren Antworten). Ich musste die Visu jedoch häufiger neuladen, um diese Situation zu erhalten.

Sagt dir der Fehler "preseerror! Read undefined" etwas?


cv.png

[peuter]

Also mit einem selbstgebastelten "Backend" das einfach nur leere Antworten liefert hab ich das nun auch in der 0.10.0 reproduzieren können. In 0.11.0 nicht, von daher vergesst den Vorschlag, das zu testen.

Ich verstehe jetzt zwar den Fehler (leere Response führt zu einem Parser-Error und in dem Fall wird kein neuer Request gesendet, der kommt erst wenn der Watchdog nach 60sec zuschlägt). Aber was ich nicht verstehe, ist warum es in der 0.9.2 funktioniert. Der Code ist an der Stelle der selbe im CometVisu-Client. Dann kann es eigentlich nur an der aktualisierten jQuery Version liegen (0.9.2 => 1.8.3 und 0.10.0 => 2.2.3). Das würde auch erklären warum das in 0.11.0 nicht auftritt, weil dort kein jQuery mehr benutzt wird.

Und was auch ganz interessant zu wissen wäre, ist warum das Backend überhaupt leere Antworten schickt, denn das aus meiner Sicht ist der eigentliche Fehler.