Seite lädt nicht mehr und "modules.websocket.sv Exception"

[wvhn]

Moin,

in den Logs treten dieselben Fehlermeldungen mehrfach auf. Beispiel 'DG.Bad.Heizung.temperatur' zuerst 4 mal und mit dem nächsten Update nach 32 Sekunden sind es 5 mal. ooUrmeloo: schaukelt sich das weiter auf?

Ich stelle dazu mal ein paar Fragen. Sorry, ich habe von dem Thema keine Ahnung, also darf ich so fragen und vlt. hilft es ja, der Ursache auf die Spur zu kommen:

• Warum versucht shNG ein Update mehrfach zu schicken, obwohl smartVISU jedes item nur einmal abonniert?
• Evtl. kommt - laienhaft gesprochen - der update-Mechanismus aus dem Tritt, wenn in schneller Frequenz Einträge in die DB geschrieben und wieder ausgelesen werden?
  Zwar sehen wir oben nur die item-updates, aber alle diese updates müssen in die DB geschrieben werden, die evals werden ausgeführt / ebenfalls in die DB geschrieben und die DB muss prüfen, ob ein update-Intervall für den Plot erreicht ist und das update ggfls. ausführen. Das ist ganz schön viel, wenn mehrere relativ schnell veränderliche Temperatursignale verarbeitet werden müssen.
• Kann es sein, dass hier Kopien von Threads entstehen, die das Problem immer weiter verstärken? Mich erinnert das sehr an den „Berserkermodus“ von Onkelandy, der durch viele Einträge in ein mem-log verursacht wurde und der meines Wissens nach nicht vollständig aufgeklärt werden konnte.

ooUrmeloo In v1.9.5 ist als alte Plugin visu_websocket noch vorhanden. Kannst Du mal das Websocket-Modul durch das Plugin ersetzen und beobachten, ob der Fehler weiterhin auftritt?

Gruß
Wolfram

[ooUrmeloo]

Hi ooUrmeloo,

das ist mir gerade noch eingefallen, wenn im Eval User-Functions oder db-Operationen stattfinden kann die Erzeugung von Worker-Threads eventuell passieren.
Das nutze ich selbst nicht.

Wie das mit den db-Funktionen realisiert ist kann ich im Moment nicht sagen, da muss ich mir den Quellcode vom DB-plugin ansehen.
Wie gestern, mal drüber schlafen :-)

Viele Grüße
Andre

Ich habe mir gestern Abend und heute Mittag mal die Threads mit Deinem Script genauer angeschaut.
Ich denke, ich kann bestätigen, dass alle meine Evals, die eine db Funktion nutzen, einen Worker-Thread erzeugen.

(Apropos ... was ist der Unterschied zwischen "Worker-Threads" und "Main-Threads"? Die o.g. Threads tauchen in beiden Kategorien auf. Ist das normal?
Andere Prozesse tauchen meistens nur im Main auf.)

Meine - oben schon angesprochene - Berechnung von (tägl./wöch./monat./jährl.) Min-/Max-Temperaturen wird immer bei einer Temp-Änderung getriggert, läuft also schon ab und zu mal. Ich mache das bei 11 Temperaturen, d.h., im worst case laufen 88 Threads ... die aber nach <1min abgeschlossen sind.
Darüber hinaus habe ich noch ca. 20 weitere Evals, die auf db zugreifen. Die laufen aber mit einem crontab (täglich, wöch., monatl.), z.B. zur Integration von PV Ertrag oder Verbrauch. Also sagen wir mal, worst case 110-120 (oder Faktor 2 wenn die doppelt zählen s.o.).

Was mir auch aufgefallen ist:
Wenn die evals abgeschlossen sind, werden die Threads idle - so weit so gut. Die idle werden bei Bedarf auch wieder "aufgefüllt", die Anzahl der idle bleibt dann allerdings konstant. D.h., die werden nie reduziert und die max. Anzahl bleibt erhalten. So sieht es zumindest für mich aus.

grafik.png

[ooUrmeloo]

in den Logs treten dieselben Fehlermeldungen mehrfach auf. Beispiel 'DG.Bad.Heizung.temperatur' zuerst 4 mal und mit dem nächsten Update nach 32 Sekunden sind es 5 mal. ooUrmeloo: schaukelt sich das weiter auf?

ist mir bisher nicht aufgefallen. Ich habe nicht den EIndruck, dass die Einträge mehr werden oder sich was "aufschaukelt". Muss aber nochmal schauen.

ooUrmeloo In v1.9.5 ist als alte Plugin visu_websocket noch vorhanden. Kannst Du mal das Websocket-Modul durch das Plugin ersetzen und beobachten, ob der Fehler weiterhin auftritt?

Das schaffe ich erst heute Abend.

Apropos ... die websocket Fehler haben sich seit der Verringerung der Plot-Daten reduziert. Heute bisher noch kein einziger.

[AndreK]

Hallo,

ich habe mir das im DB-Plugin angesehen. Das mit "Item.db('min', '1d')" ist "tricky" gelöst. Ist nur ein einzeiliger Eintrag im DB-Plugin.
Im Code steht auch ein Kommentar der darauf schliessen lässt das dies auch für andere schwer nachvollziehbar gewesen ist. - ich habe auch länger als erwartet gesucht :-)

def _single(self, func, start, end='now', item=None):
        """
        As far as it has been checked, this method is never called.
        It is attached to the item object but no other plugin is known that calls this method.

Bei jeder Aktualisierung des Items erfolgt ein Versuch für einen Dump - Soll heißen - alle nicht geschriebenen Werte sollen in die DB geschrieben werden um aktuelle Werte zu erhalten - mach ja Sinn - das gleiche passiert, so weit ich das im Quellcode interpretieren kann auch bei der Abfrage von "Series".
Was ich bisher nicht nachvollziehen konnte sind die Worker-Threads - im Moment keine Idee wo die tatsächlich erstellt werden.

Ich habe zwar keine belegbaren Hinweise, aber ich vermute es kommt zu einem "aufschaukeln" zwischen "_dump" und "_series", ich versuche hier näher an die Ursache zu gelangen.

Eine weitere Vermutung (ohne Beleg) ist, dass durch einen abgebrochenen Dump ein "None" an das Websocket-Moduel geht, welches dann einen 1001er schmeißt.
Ist nur eine Vermutung, schau ich mir auch nochmal an.

Für Hinweise aus allen Richtungen bin ich offen 😁

Viele Grüße
Andre

[ooUrmeloo]

ooUrmeloo In v1.9.5 ist als alte Plugin visu_websocket noch vorhanden. Kannst Du mal das Websocket-Modul durch das Plugin ersetzen und beobachten, ob der Fehler weiterhin auftritt?

Sorry, da muss ich jetzt doch mal wieder doof nachfragen, bevor ich was "kaputt" mach.
Einfach das visu_websocket Plugin aktivieren? Oder muss ich das Websocket Modul irgendwie "händisch" deaktivieren vorher?

[ooUrmeloo]

Ich konnte heute übrigens die websocket Fehler reproduzierbar "provozieren", und zwar sowohl mobil / WLAN als auch PC /LAN:
1. Cache über das Web-IF löschen
2. Seite einfach neu laden (z.B. sys.stats)

--> laden ging ewig und websocket Fehler im log.
Zusätzlich sind die Threads angestiegen. Leider hatte ich vergessen, die mit zu loggen ... hole ich nochmal nach.

Außerdem habe ich noch festgestellt, dass es zwei unterschiedliche "Typen" von websocket 1001 Fehlern gibt:

einen "await websocket.send(data)":

2024-01-24  21:52:30 NOTICE   modules.websocket.sv update_item: Error sending {'cmd': 'item', 'items': [['OG.Gaeste.Heizung.temperatur', 19.0]]} - to THINK.fritz.box (192.168.178.20:53076), smartVISU v3.4.0, Firefox 121  -  Error in 'await websocket.send(data)': received 1001 (going away); then sent 1001 (going away)

und einen "await websocket.send(reply)":

2024-01-24  21:35:58 WARNING  modules.websocket.sv Exception in 'await websocket.send(reply)': received 1001 (going away); then sent 1001 (going away) - reply = {"cmd": "series", "series": [[1706042066205, 0.68], [1706042488005, 0.49], [1706043389875, 0.53], [1706044291857, 0.41], [1706045195384, 0.53], [1706045796410, 0.56], [1706046697961, 0.5], [1706047600004, 0.47], [1706048502347, 0.77], [1706049404403, 0.85], [1706050306313, 0.87], [1706051209369, 0.99], [1706051813190, 0.88], [1706052715025, 0.7], [1706053618087, 0.72], [1706054520534, 1.28], [1706055424877, 1.61], [1706056339446, 1.56], [1706057254547, 0.83], [1706057856295, 0.65], [1706058759540, 0.66], [1706059663539, 0.94], [1706060564999, 0.4], [1706061467488, 0.69], [1706062368980, 0.59], [1706063272734, 0.44], [1706064207270, 0.81], [1706064775775, 0.51], [1706065679725, 0.33], [1706066581916, 0.3], [1706067483932, 0.28], [1706068394988, 0.85], [1706069298129, 0.41], [1706070201422, 0.36], [1706071103404, 0.43], [1706071709727, 1.16], [1706072616887, 0.63], [1706073518429, 0.59], [1706074427066, 0.72], [1706075330895, 1.04], [1706076234877, 0.49], [1706077138955, 0.58], [1706077739848, 0.25], [1706078642268, 0.26], [1706079544200, 0.36], [1706080448549, 0.49], [1706081350127, 0.34], [1706082251994, 0.19], [1706083153926, 0.22], [1706084055931, 0.4], [1706084658507, 0.35], [1706085561949, 0.36], [1706086464783, 0.25], [1706087366791, 0.23], [1706088268620, 0.26], [1706089173000, 0.48], [1706090074853, 0.56], [1706090981796, 0.89], [1706091584690, 0.89], [1706092499117, 1.13], [1706093405071, 0.87], [1706094317190, 0.6], [1706095220861, 0.57], [1706096124674, 0.81], [1706097035680, 1.4], [1706097644521, 1.18], [1706098550741, 0.78], [1706099459039, 0.83], [1706100369171, 1.08], [1706101290528, 1.35], [1706102188537, 1.32], [1706102797435, 1.43], [1706103730586, 1.2], [1706104601727, 0.55], [1706105505051, 0.55], [1706106410019, 1.41], [1706107322882, 1.23], [1706108232396, 0.68], [1706108835713, 0.58], [1706109741784, 1.02], [1706110651361, 0.76], [1706111560019, 1.02], [1706112465817, 0.96], [1706113376447, 0.89], [1706114279362, 0.53], [1706114882453, 0.95], [1706115788356, 1.36], [1706116693702, 0.57], [1706117600268, 1.08], [1706118503678, 1.08], [1706119406937, 0.49], [1706120317033, 1.3], [1706120928469, 1.36], [1706121844686, 1.31], [1706122754640, 1.59], [1706123658202, 0.99], [1706124564709, 1.2], [1706125468308, 0.62], [1706126370030, 0.65], [1706127272858, 0.23], [1706127874365, 0.76]], "sid": "env.system.load|avg|1d|now|100"} to THINK.fritz.box (192.168.178.21:52820), smartVISU v3.4.0, Firefox 121
2024-01-24  21:35:59 WARNING  modules.websocket.sv Exception in 'await websocket.send(reply)': received 1001 (going away); then sent 1001 (going away) - reply = {"cmd": "series", "series": [[1706042158974, 87.0], [1706042487953, 87.0], [1706043389841, 87.0], [1706044291823, 87.0], [1706045195214, 87.0], [1706045796356, 87.0], [1706046697928, 87.0], [1706047599969, 87.0], [1706048502262, 87.0], [1706049404351, 87.0], [1706050306259, 87.0], [1706051209311, 87.0], [1706051813129, 87.0], [1706052714993, 87.32], [1706053618034, 88.0], [1706054520447, 89.5], [1706055424775, 95.0], [1706056339343, 95.0], [1706057254481, 95.0], [1706057856231, 95.0], [1706058759438, 95.0], [1706059663463, 95.0], [1706060564915, 95.0], [1706061467407, 97.0], [1706062368948, 97.0], [1706063272696, 97.0], [1706064207158, 98.0], [1706064775742, 98.0], [1706065679693, 98.0], [1706066581877, 98.0], [1706067483900, 98.0], [1706068394886, 98.0], [1706069298095, 98.0], [1706070201389, 98.0], [1706071103364, 98.0], [1706071709511, 98.0], [1706072616835, 98.0], [1706073518397, 98.0], [1706074426994, 98.0], [1706075330775, 98.0], [1706076234843, 98.0], [1706077138874, 98.0], [1706077739816, 98.0], [1706078642227, 98.0], [1706079544163, 98.0], [1706080448467, 98.0], [1706081350090, 98.0], [1706082251963, 98.0], [1706083153887, 98.0], [1706084055893, 98.0], [1706084658474, 98.0], [1706085561916, 98.0], [1706086464748, 98.0], [1706087366759, 98.0], [1706088268587, 98.0], [1706089172928, 98.0], [1706090074813, 98.0], [1706090981738, 98.0], [1706091584646, 98.0], [1706092499030, 98.0], [1706093405002, 98.0], [1706094317059, 98.0], [1706095220783, 98.0], [1706096124587, 98.0], [1706097035596, 98.0], [1706097644365, 98.0], [1706098550667, 98.0], [1706099458867, 98.0], [1706100369096, 98.0], [1706101290147, 98.58], [1706102188425, 99.0], [1706102797300, 99.34], [1706103730160, 105.0], [1706104601680, 105.0], [1706105505018, 105.0], [1706106409923, 105.0], [1706107322762, 105.0], [1706108232311, 105.0], [1706108835621, 105.0], [1706109741703, 105.0], [1706110651205, 105.0], [1706111559903, 105.0], [1706112465772, 105.65], [1706113376374, 106.0], [1706114279322, 106.0], [1706114882229, 106.0], [1706115788283, 106.0], [1706116693660, 106.0], [1706117600021, 106.0], [1706118503633, 106.64], [1706119406885, 107.0], [1706120316743, 107.0], [1706120928320, 107.0], [1706121844436, 107.31], [1706122754544, 110.97], [1706123658162, 113.0], [1706124564647, 113.0], [1706125468270, 113.0], [1706126369971, 113.0], [1706127272825, 113.0], [1706127874309, 113.0], [1706128477403, 113.0], [1706128558975, 113.0]], "sid": "env.core.threads|avg|1d|now|100"} to THINK.fritz.box (192.168.178.21:52820), smartVISU v3.4.0, Firefox 121

Keine Ahnung, ob das was hilft.

[wvhn]

Einfach das visu_websocket Plugin aktivieren? Oder muss ich das Websocket Modul irgendwie "händisch" deaktivieren vorher?

Du kannst beide parallel laufen lassen, musst dann aber für das Plugin einen anderen Port in shNG konfigurieren, z.B. 3434 und diesen auf der Config-Seite der Visu einstellen.

[ooUrmeloo]

Zusätzlich sind die Threads angestiegen. Leider hatte ich vergessen, die mit zu loggen ... hole ich nochmal nach.

Hab das nochmal wiederholt mit laufendem Thread-Logger:
Nach dem Cache leeren und Seite neu laden erscheinen sehr vieler meiner Min/Max Temp evals in den Threads, so dass 128 Threads aktiv sind.
Irgendwie werden die evals also getriggert, obwohl ich explizit nicht die Seite aufrufe, auf der die Werte dargestellt sind.

Deshalb noch ein Versuch:
1. Alle items mit der Min/Max Berechnung gelöscht. Dienst neu gestartet.
2. Fehler wieder versucht zu reproduzieren: Cache leeren + Seite neu laden.

--> problemlos: Seite lädt schnell, Threads bleiben bei (für mich niedrigen) 7.

Im log stehen allerdings eine Fehlermeldungen für jedes item:

2024-01-24  22:41:34 ERROR    modules.websocket.sv prepare_monitor: No item 'temperatur.wohnzimmer.min1d' found (requested by client THINK.fritz.box (192.168.178.20:53393), smartVISU v3.4.0, Firefox 121

Was heißt denn "prepare_monitor"? Ich hätte da jetzt eine Fehlermeldung wie den hier erwartet:

2024-01-24  22:53:35 WARNING  lib.metadata        Item 'temperatur', attribute 'aussen': Attribute is undefined and has value 'None' (defined in temperatur.yaml)

Nach dem Test für mich auf jeden Fall klar: das Problem wird wohl durch meine Min/Max Berechnungen verursacht.

[ooUrmeloo]

Du kannst beide parallel laufen lassen, musst dann aber für das Plugin einen anderen Port in shNG konfigurieren, z.B. 3434 und diesen auf der Config-Seite der Visu einstellen.

Das probiere ich morgen mal, ob ich den Fehler auch mit dem Plugin reproduzieren kann ...

[wvhn]

Was heißt denn "prepare_monitor"?

Die Visu sendet alle zu abonnierenden items mit dem "monitor"-Kommando an shNG. Wenn Du das item 'temperatur.wohnzimmer.min1d' noch auf Deiner Visu-Seite stehen hast, dann wird das bei shNG angefragt und ist dort nicht (mehr) bekannt. Daher kommt die Fehlermeldung.

[Msinn]

Im log stehen allerdings eine Fehlermeldungen für jedes item: Code:

2024-01-24 22:41:34 ERROR modules.websocket.sv prepare_monitor: No item 'temperatur.wohnzimmer.min1d' found (requested by client THINK.fritz.box (192.168.178.20:53393), smartVISU v3.4.0, Firefox 121
Was heißt denn "prepare_monitor"?

Prepare_monitor ist eine Funktion die ausgeführt wird, wenn eine Visu Seite ein Item anfordert. Die Fehlermeldung besagt, dass es das angeforderte Item in SmarHomeNG nicht gibt.

[ooUrmeloo]

So, ich habe heute mal das visu_websocket Plugin ausprobiert - wieder mit allen aktivierten Min/Max evals.
Die Seiten laden m.E. immer noch recht langsam aber es kommen keine websocket Fehler. Zumindest konnte ich sie nicht so wie oben provozieren.
Die Threads verhalten sich auf den ersten Blick aber gleich ...

Wieder zurück auf das Websocket Modul -> gleich wieder ca. 50x 1001 Fehler ...

**********
Hat jemand einen besseren Vorschlag, min/max Werte zu bestimmen?

[ooUrmeloo]

Prepare_monitor ist eine Funktion die ausgeführt wird, wenn eine Visu Seite ein Item anfordert. Die Fehlermeldung besagt, dass es das angeforderte Item in SmarHomeNG nicht gibt.

Danke für die Info. Passt ja dann. Hätte nur eine andere Fehlermeldung erwartet.

[aschwith]

Hab das nochmal wiederholt mit laufendem Thread-Logger:
Nach dem Cache leeren und Seite neu laden erscheinen sehr vieler meiner Min/Max Temp evals in den Threads, so dass 128 Threads aktiv sind.
Irgendwie werden die evals also getriggert, obwohl ich explizit nicht die Seite aufrufe, auf der die Werte dargestellt sind.

Diese Info von Dir hat mich stutzig gemacht. Wieso werden die ganzen min/max evals ausgeführt, wenn diese gar nicht für die aktuelle Seite benötigt werden bzw. aboniert sind?

[ooUrmeloo]

Diese Info von Dir hat mich stutzig gemacht. Wieso werden die ganzen min/max evals ausgeführt, wenn diese gar nicht für die aktuelle Seite benötigt werden bzw. aboniert sind?

Na ja, selber nochmal nachgedacht. Die evals werden ja über eine Temperaturänderung getriggert und nicht über den Seitenaufruf. (s.o.)
Würde bedeuten, dass durch einen Neustart oder Cache leeren angestoßen wird?!?

Ich versteh auch immer noch nicht den Zusammenhang:
DB evals -> viele Threads -> hohe Auslastung? -> Laden von Seiten (mit Plots) -> Seite lädt langsam + websocket Fehler

Könnte das auch irgendwie mit dem Cache zusammenhängen?