Widget status.log: Mehrfache identische Einträge

[aschwith]

Hallo zusammen,

ich habe noch ein verstecktes reproduzierbares Problem im Widget status.log gefunden, bei dem Einträge im Widget mehrfach anzeigt werden:

a) In SmartVisu ist eine Seite aktiv geöffnet auf der das Widet status.log verwendet wird.
{{status.log('klingellogger', 'klingellogger', 15) }}

b) Auf SmarthomeNG Seite wird jetzt über eine Logik ein Logeintrag getriggert:
sh.klingellogger.log('Die Klingel wurde betaetigt!', 'info')

c) In der Browserconsole ist die Änderung auch zu sehen:
20:45:54.312 [io.smarthome.py] receiving data: {"name": "klingellogger", "log": [{"time": "2022-07-01T20:45:54.518084", "thread": "klingellogger", "level": "info", "message": "Die Klingel wurde betaetigt!"}], "cmd": "log"}

d) Die Nachricht erscheint mit identischem Datums- und Zeitstempel mehrmals in dem status.log widget.

e) Sobald ich die smartVisu Seite nochmal neu Lade, wird vom Widget korrekterweise der Eintrag nur noch einmal angezeigt.

f) Für die mehrfachen Einträge scheint es eine Systematik zu geben:
War die Liste zuvor leer, wird fälschlicher Weise der Eintrag dreimal angezeigt.
War in der Liste zuvor genau ein Eintrag, wird fälschlicher Weise der Eintrag viermal angezeigt.
Waren in der Liste zuvor genau zwei Einträge, wird fälschlicher Weise der Eintrag fünfmal angezeigt.


Kann jemand von Euch das Problem bei sich auch erkennen? Ich vermute, hier läuft in der Update Funktion des Widgets was verkehrt.

[wvhn]

Ich habe mal versucht, das nachzustellen. Einmal habe ich auf der Statusseite "smarthomeNG" in dem vorhandenen Logger "env.core.log" die o.g. Loggerdaten eingeschmuggelt, indem ich die entsprechenden Zeilen aus dem Treiber io_smarthome.py in der Konsole ausgeführt habe. Die Loggerdaten werden nur einmal angezeigt. Danach habe ich mit dem Widget-Assistent eine neue Seite mit status.log aufgesetzt und wieder Logger-Daten simuliert. Auch hier stimmt die Darstellung.

Kannst Du zu den einzelnen Fällen (d, e, und f) jeweils in der Konsole "widget.buffer" eingeben und hier mal posten, wie das jeweils das log-item registriert ist?

Gruß
Wolfram

[wvhn]

Jetzt kann ich das Problem nachstellen: Statusseite von shNG aufrufen, dann ein zweites Fenster für smartViSU aufmachen und mit dem Widget Assistent ein Widget mit einem nicht existierenden item erstellen und rendern lassen. Dies ergibt einen Eintrag im Log, der auf der ersten Seite mehrfach angezeigt wird.

[aschwith]

Hi Wolfram,

perfekt, dass Du es auch nachstellen kannst. Das Konsolenausgabe zu Widget.buffer bringt mich nicht weiter. Hier werden nur Items gelistet, die gar keine Relevanz für das status.log haben. Funktioniert die Kommunikation zwischen status.log und dem SmarthomeNG plugin (z.B. operationlog) überhaupt über ein reguläres Item? Sieht mir gerade nicht danach aus. (Es gibt ja auch für das smarthome log auf der Statusseite kein Zugehöriges Item, in das man z.B. im Admin Interface schauen könnte, oder? Ich verstehe gerade noch nicht, wie der Update Mechanismus hier funktioniert.

[wvhn]

Hi Alex,
leider ist das mit dem Nachstellen doch nicht so einfach. Mein Entwicklungssystem (smartVISU auf PC mit shNG-Backend auf meinem Test-Pi) hat den Fehler nicht. smartVISU develop auf meinem Test-Pi zeigte diesen Fehler zunächst. Nachdem ich in eine Kopie des Treibers ein paar Konsolenausgaben eingebaut habe, ist der Fehler weg - auch nach Zurückwechseln auf den vorherigen Treiber. Lediglich mein Produktiv-Pi (SV3.2.2) zeigt den Fehler noch. Da der Cache aktiviert ist, bekomme ich aber keine Konsolenausgaben...

widget.buffer registriert alles, was an Daten für die Widgets gebraucht wird. Dein item "klingellogger" muss auch dabei sein. Es sollte ein Array sein, dessen Länge die Anzahl der Einträge ist. Beispiel:

Die Logger von shNG schicken beim ersten Abfragen ein JSON mit allen Einträgen und einem Attribut "init":"y". Wenn "init" = "y" ist, schreibt der Treiber io_smarthomeNG.js die Daten per "widget.update(item, data)" in den buffer - mit dem jünsten Eintrag zuerst (index 0). Werden neue Logeinträge über den Websocket übertragen, dann fehlt das "init"-Attribut. In diesem Fall schreibt der Treiber die neuen Einträge in einer Schleife mit der js-Funktion "unshift" an die ersten Stellen im widget.buffer und triggert dann die Update-Methode für das item (ohne Daten, da die ja schon im buffer sind).

Bei meinen Beobachtungen stehen die fälschlich mehrfachen Einträge in widget.buffer. D.h. der Fehler muss schon im Treiber auftreten. Weitere Anhaltspunkte habe ich leider noch nicht.

Gruß
Wolfram

[aschwith]

Hallo Wolfram,

danke für die Erläuterung. Ich habe jetzt auch gesehen, dass man im Debugger den widget.buffer aufklappen kann. Finde dort jetzt auch den Eintrag "klingellogger". Du hast recht, die mehrfachen Einträge tauchen bereits im widget.buffer auf.

Kann ich noch unterstützen und bei mir logs hinzufügen?

[aschwith]

Im Treiber smarthome.py.js habe ich eine Konsolenausgabe hinzugefügt:

case 'log':
    if (data.init) {
        widget.update(data.name, data.log);
    }
    else {

        console.log("[log received without init]: ", data.name, data.log.length);

        var log = widget.get(data.name); // only a reference

        for (var i = 0; i < data.log.length; i++) {
            log.unshift(data.log[i]);

            if (log.length >= 50) {
                log.pop();
            }
        }

        widget.update(data.name);
    }
    break;

Bereits das "else" wird mehrmals mit identischen Werten getriggert. Der Fehler kommt also schon aus dem websocket Treiber von smarthomeNG?

[aschwith]

Msinn, Kannst Du hier unterstützen? Ich habe das Problem bis in den smarthomeNG websocket zurückverfolgt. Die Funktion

async def update_log(self, log_entry):

wird schon mehrmals mit gleichem Inhalt getriggert. Ich habe noch nicht gefunden, wo die log Daten in die Janus Queue geschrieben werden. Geht beim Schreiben in die Queue evtl. schon was schief und Einträge werden gedoppelt?

[aschwith]

wvhn: Die mehrfachen Logeteinträge kommen aus den Tiefen von SmarthomeNG.

@Msinn: Die Einträge werden sogar vor der Janus Queue schon durch mehrfaches Ausführen der module.websocketfunktion "update_visulog" erzeugt. Das Problem ist in der Tat, dass in der Funktion

async def smartVISU_protocol_v4(self, websocket):

    self._sh.add_event_listener(['log'], self.update_visulog)

jedes Mal ein neuer Event Listener angelegt wird, auch wenn dieser schon exisitiert. Sobald mehrere Listerener für das Event "log" exitistieren, werden diese natürlich auch mehrmals getriggert und führen zu den ganzen Problem, siehe oben. Können wir dafür sorgen, dass der Listener definitiv nur einmal registriert wird?

Danke und Gruß
Alex

[Msinn]

Msinn, Kannst Du hier unterstützen? Ich habe das Problem bis in den smarthomeNG websocket zurückverfolgt. Die Funktion

Im Prinzip ja, aber ich bin im Moment beruflich stark eingespannt und komme erst in 3 bis 4 Wochen wieder dazu mich mit SmartHomeNG Themen zu beschäftigen.

[aschwith]

Das ist gar kein Problem. Das Thema hat Zeit. Arbeit geht vor. VG

[wvhn]

aschwith Danke für die Recherche. Hast Du ein Tool, mit dem Du auf dem Websocket mithören kannst? Mich wundert, dass die Konsolenausgabe der Websocket-Message im Event-Handler io.socket.onmessage nur einmal ausgeführt wird, während im selben Handler direkt anschließend im "switch (data.cmd) … case log:" das "else" mehrfach durchlaufen wird.

Hinsichtlich des shNG-Anteils gibt es ein issue im Repo von shNG um das Thema zu Ende zu verfolgen.

Onkelandy vlt. ist damit ein Ansatz für Deinen Berserker-Modus bei Verwendung des Log-Widgets gefunden? Exponentieller (?) Anstieg der Eventhandler bis zum Neustart von shNG?

Gruß
Wolfram

[aschwith]

Hallo Wolfram,

Ich habe ins Develop einen Fix für das smarthomeNg websocket modul geschoben, welches das mehrfache Registrieren des log Handlers verhindert. Vorher wurde bei jedem forcierten Neuladen von Smartvisu ein zusätzlicher identischer Eventhandler registriert und damit jeweils doppelte, dreifache usw. Einträge erzeugt. Das Thema sehe ich damit als gelöst an. Msinn kann den Fix gerne nochmal kritisch begutachten, sobal er Zeit hat.

Ein Tool zum Mithören auf dem Websocket habe ich nicht direkt zur Hand. Meinst du, wir müssen uns deinen Aspekt auf Smartvisu Seite nochmal anschauen?

[aschwith]

Onkelandy Tritt der Berserker Modus bei Dir in letzter Zeit noch auf? Hast du dazu noch die Log Dateien?

Eine Sache ist mir beim Debuggen von obigem Problem noch aufgefallen: Solange ein Loghandler durch eine geöffnete Smartvisu aktiv sind, gibt es die Gefahr, Event Schleifen zu generieren. Beispiel: Tritt im module websocket in der Verarbeitung eines Log Events eine Log Meldung auf (z.B. Warning) auf, triggert dies wiederum die log Event Verarbeitung. So können gefährliche Dauerschleifen entstehen.

[wvhn]

aschwith Problem saß vor dem Rechner. Beim Umstellen auf den geänderten Treiber hatte ich die Ports vom visu_websocket plugin erwischt, da das Websocket-Modul bei mir nicht auf den Standard-Ports läuft.

Somit kann ich 3 Aussagen treffen:

• wenn man die richtigen Ports verwendet, dann ist der Fehler mit dem Websocket Modul eindeutig reproduzierbar
• mit dem visu_websocket-Plugin tritt der Fehler nicht auf
• alle überzähligen Messages auf dem Websocket werden jetzt von der Konsolenausgabe angezeigt. D.h. hier gibt es am Treiber keinen Untersuchungsbedarf mehr.

Um dIe vierte Aussage abschließend zu treffen, ist es noch etwas früh: aktuell behebt Dein Fix auch bei mir den Fehler zuverlässig. Ich teste das weiter.

Vielen Dank!

Gruß
Wolfram