Sehr viele Logmeldungen 'await websocket.send(data)'

[Art Mooney]

Hallo zusammen,

seit einigen Tagen ist mein Log-File voll mit untenstehenden Fehlermeldungen. Die hatte ich zuvor auch vereinzelt, aber nun nimmt es etwas überhand. Ich stelle keine Fehlfunktion fest, nur ein sehr unübersichtliches Log-File.

Mir ist auch nicht klar, warum das nun plötzlich so stark auftritt. Ich hatte in den letzten Tagen viel mit Zeitfunktionen (datetime) herumexperimentiert. Die scheinen aber zu funktionieren.

Leider kann ich die Meldung nicht deuten. Offenbar besteht ein Fehler darin, dass eine Verbindung nicht hergestellt werden kann. Will SHNG irgendetwas aus dem Internet abrufen? SHNG ist nicht mit dem Internet verbunden, daher wäre das kein Wunder.

Meine SHNG ist Version 1.8.2, Python 3.7.3, websockets 10.0.

Danke für einen Tipp!

> Traceback (most recent call last):
>   File "/usr/local/smarthome/modules/websocket/__init__.py", line 941, in update_item
>     await websocket.send(msg)
>   File "/home/smarthome/.local/lib/python3.7/site-packages/websockets/legacy/protocol.py", line 619, in send
>     await self.ensure_open()
>   File "/home/smarthome/.local/lib/python3.7/site-packages/websockets/legacy/protocol.py", line 920, in ensure_open
>     raise self.connection_closed_exc()
> websockets.exceptions.ConnectionClosedError: sent 1011 (unexpected error) keepalive ping timeout; no close frame received
2022-03-01  00:31:39 ERROR    modules.websocket   update_item - Error in 'await websocket.send(data)': sent 1011 (unexpected error) keepalive ping timeout; no close frame received
> Traceback (most recent call last):
>   File "/home/smarthome/.local/lib/python3.7/site-packages/websockets/legacy/protocol.py", line 955, in transfer_data
>     await asyncio.shield(self._put_message_waiter)
> concurrent.futures._base.CancelledError

The above exception was the direct cause of the following exception:

> Traceback (most recent call last):
>   File "/usr/local/smarthome/modules/websocket/__init__.py", line 941, in update_item
>     await websocket.send(msg)
>   File "/home/smarthome/.local/lib/python3.7/site-packages/websockets/legacy/protocol.py", line 619, in send
>     await self.ensure_open()
>   File "/home/smarthome/.local/lib/python3.7/site-packages/websockets/legacy/protocol.py", line 920, in ensure_open
>     raise self.connection_closed_exc()
> websockets.exceptions.ConnectionClosedError: sent 1011 (unexpected error) keepalive ping timeout; no close frame received
2022-03-01  00:31:51 WARNING  plugins.database    Skipping dump, since an other database operation running! Data is buffered and dumped later.
2022-03-01  00:31:51 ERROR    modules.websocket   update_item - Error in 'await websocket.send(data)': sent 1011 (unexpected error) keepalive ping timeout; no close frame received
> Traceback (most recent call last):
>   File "/home/smarthome/.local/lib/python3.7/site-packages/websockets/legacy/protocol.py", line 955, in transfer_data
>     await asyncio.shield(self._put_message_waiter)
> concurrent.futures._base.CancelledError

[Msinn]

Websockets werden bisher nur für Verbindungen zur smartVISU (und für die Graphiken in der AdminGUI) genutzt.

Ich habe das auch in den letzten Tagen vermehrt beobachtet. Bei mir besteht ein zeitlicher Zusammenhang mit dem Schlafen gehen/aufwachen meines iPads. Hast Du evtl. auch eine Visu auf einem IOS Gerät im Einsatz?

[Art Mooney]

Danke Msinn, ich nutze tatsächlich ein iPad für meine smartVISU. Heute habe ich den ganzen Tag die Visu nicht benutzt. Eben gerade zum ersten Mal das iPad angemacht und sofort erscheint im Log:

2022-03-05  21:20:00 ERROR    modules.websocket   smartVISU_protocol_v4 exception: received 1005 (no status code [internal]); then sent 1005 (no status code [internal])

ein paar Minuten später - das Ipad ist mittlerweile wieder eingeschlafen - folgt:

2022-03-05  21:22:47 ERROR    modules.websocket   smartVISU_protocol_v4 exception: no close frame received or sent

Ansonsten hat sich die Lage aber wieder beruhigt. Andere Fehlermeldungen gibt es nicht. Die sehr zahlreichen Meldungen sind nicht mehr da. Damit traten sie nur an ein paar Tagen auf. Genaugenommen nur am 28.2. und 1.3., danach nicht mehr.

Wenn es dabei bleibt, ist alles ok.

[Msinn]

Das von Dir beschriebene Verhalten tritt bei mir auch auf seit ich auf IOS 15 upgedated habe. Mit dem Safari von IOS 14 war noch alles ok. Mir ist aber noch nicht klar, was Apple da geändert hat.

[Tom Bombadil]

Ich habe die Meldung seit gestern ab und zu im Log - Client ist Chrome unter Windows.

2022-03-05  10:34:40 WARNING  modules.websocket smartVISU_protocol_v4: Exception in 'await websocket.send(reply)': code = 1001 (going away), no reason - reply = {"cmd": "series", "series": [[1645868080306, 0.0], [1646435756776, 0.0], [1646436180458, 0.0], [1646472880306, 0.0]], "sid": "heizung.stellmotoren.rk2_3pkt.stellsignal|raw|7d|now|100"}

Vorausgegangen ist jedesmal mein alter Freund 'Needing more worker threads' nach einem Neustart (bearbeite gerade Items, daher relative viele Neustarts).

Ich habe auch das Gefühl, dass die Meldung nach jedem Mal 'service smarthome restart' schneller kommt - sonst (im regulären Betrieb ohne Änderungen) kam sie immer einmalig nach 2-3 Tagen Betrieb, ohne dass sie irgendwelche Auswirkungen hatte. Kann es sein, dass wir hier über Memory Leaks & Co. bei Restarts reden, d.h. nicht alle Ressourcen freigegeben werden?

/tom

[Msinn]

Das ist aber eine andere Meldung als die von Art Mooney. Bei Dir ist das Thema, dass eine Serie für einen Plot nicht sauber cecancelt wurde und SmartHomeNG versucht ein Update über die inzwischen geschlossene Websocket Verbindung zu senden.

Das Problem ist bekannt bei der Admin GUI, die die Serien für die Darstellung der Graphen nutzt. Hattest Du evtl. auch die Admin GUI im Einsatz?

[Tom Bombadil]

Ja, hatte ich tatsächlich.

/tom

[wvhn]

Mir ist auch nicht klar, warum das nun plötzlich so stark auftritt. Ich hatte in den letzten Tagen viel mit Zeitfunktionen (datetime) herumexperimentiert. Die scheinen aber zu funktionieren.

IMHO ist das ein Hinweis, dem wir nochmal nachgehen sollten. Das erinnert mich an den sog. "Berserkermodus" von Onkelandy, bei dem die Menge der Fehlermeldungen des Websocket-Moduls sogar shNG zum Neustart gezwungen hat. Dies trat in Verbindung mit dem Log-Widget auf bzw. mit dem Abonnieren von Log-Daten. Da beim Loggen auch jede Menge Zeitstempel verwendet werden, gibt es da vielleicht einen Zusammenhang?

Aus meiner Sicht haben wir derzeit 4 Problemfelder:

1. Beim Neuladen von Visu-Seiten oder beim Übergang zu inaktiven Tabs / Ruhemodus wird der Websocket vom Client einfach ohne abschließenden Handshake gestoppt. Es erfolgt eine Fehlermeldung vom Websocket-Modul im Log, aber das Modul schließt den Socket dann sauber, entfernt den entsprechenden User und stoppt Abonnements von items und series beim Backend.
   --> in diesem Fall kann die Fehlermeldung einfach ignoriert / unterdrückt werden. Ich bin zudem dabei, aus SV heraus den Websocket definiert zu schließen, wo immer das möglich ist.
2. Es gibt vereinzelt Client-Geräte, die den Websocket beim Übergang in den Ruhezustand weiter aufrecht erhalten, aber die empfangenen Daten nicht mehr verarbeiten. Beim Aufwachen der Geräte arbeitet SV dann die Daten in der Warteschlange einzeln ab.
   --> Hier arbeite ich derzeit mit jksd (fhem) und loeserman (shNG) an einer Lösung für den fully-Browser, der vor dem Schlafenlegen noch einen Event feuert, mit dem man den Websocket sauber schließen kann.
3. Meldungen in Verbindung mit dem Admin-Interface. Dort werden beim Start die Serien für mehrere env-Intems per Websocket angefragt. Beim Verlassen der Startseite müssten die Serien wieder gecancelt werden, was offensichtlich nicht passiert.
   --> lästig aber harmlos.
4. Ein erhöhtes Aufkommen der Fehlermeldungen aus dem Websocket-Modul in Verbindung mit abonnierten Log-Daten ("Berserkermodus") und nun offenbar auch bei Verwendung von datetime-Objekten.
   --> nicht harmlos. Hier müssen wir nach shNG-internen Fehlerquellen suchen

Gruß
Wolfram

[whe]

Habe heute einige PyPi updates gemacht u.a. websockets.
vorhin erschien ( in Abewesenheit ) im Log:

2022-03-09  19:14:41 ERROR    modules.websocket   update_item - Error in 'await websocket.send(data)': sent 1011 (unexpected error) keepalive ping timeout; no close frame received
Traceback (most recent call last):
  File "/home/smarthome/.local/lib/python3.7/site-packages/websockets/legacy/protocol.py", line 944, in transfer_data
    message = await self.read_message()
  File "/home/smarthome/.local/lib/python3.7/site-packages/websockets/legacy/protocol.py", line 1013, in read_message
    frame = await self.read_data_frame(max_size=self.max_size)
  File "/home/smarthome/.local/lib/python3.7/site-packages/websockets/legacy/protocol.py", line 1088, in read_data_frame
    frame = await self.read_frame(max_size)
  File "/home/smarthome/.local/lib/python3.7/site-packages/websockets/legacy/protocol.py", line 1147, in read_frame
    extensions=self.extensions,
  File "/home/smarthome/.local/lib/python3.7/site-packages/websockets/legacy/framing.py", line 70, in read
    data = await reader(2)
  File "/usr/lib/python3.7/asyncio/streams.py", line 679, in readexactly
    await self._wait_for_data('readexactly')
  File "/usr/lib/python3.7/asyncio/streams.py", line 473, in _wait_for_data
    await self._waiter
concurrent.futures._base.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/smarthome/modules/websocket/__init__.py", line 919, in update_item
    await websocket.send(msg)
  File "/home/smarthome/.local/lib/python3.7/site-packages/websockets/legacy/protocol.py", line 619, in send
    await self.ensure_open()
  File "/home/smarthome/.local/lib/python3.7/site-packages/websockets/legacy/protocol.py", line 929, in ensure_open
    raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedError: sent 1011 (unexpected error) keepalive ping timeout; no close frame received
2022-03-09  19:51:13 ERROR    modules.websocket   smartVISU_protocol_v4 exception: Client 192.168.178.21:63654 - received 1005 (no status code [internal]); then sent 1005 (no status code [internal])
2022-03-09  19:51:15 NOTICE   lib.smarthome       --------------------   SmartHomeNG restarting, initiated by admin interface   --------------------

ich habe jetzt websockets wieder auf v 10.1 zurück gedreht und Ruhe ist.

[schuma]

Bei mir das Gleiche....
Ich gehe jetzt auch zurück auf die 10.1
Mal sehen was passiert.

[wvhn]

Bei mir hat heute erstmalig der "Berserker-Modus" zugeschlagen. Ich versuche gerade eine Seite für die Analyse des Websockets zu bauen, um herauszufinden, warum beim iPad nach längerer Zeit das Wiederverbinden von smartVISU nicht funktioniert.

Die Seite abonniert über das status.log Widget das item "env.core.log". Zum Testen habe ich auf meinem Desktop die Seite geladen und dann aus der Konsole den Websocket mit "io.close()" geschlossen. io.close() ruft die im Websocket-Objekt enthaltene Standard-Methode "close()" auf, die den Websocket geordnet schließen sollte. Anschließend konnte ich den Websocket nicht wieder initialisieren und smarthomeNG hat innerhalb von 12 Minuten über 45000 Zeilen ins Log geschrieben, also rund 5000 mal diese Meldung:

2022-12-12  15:47:27 ERROR    modules.websocket   update_log - Error in 'await websocket.send(data)': code = 1001 (going away), no reason
> Traceback (most recent call last):
>   File "/usr/local/smarthome/modules/websocket/__init__.py", line 1022, in update_log
>     await websocket.send(msg)
>   File "/home/smarthome/.local/lib/python3.7/site-packages/websockets/protocol.py", line 555, in send
>     await self.ensure_open()
>   File "/home/smarthome/.local/lib/python3.7/site-packages/websockets/protocol.py", line 803, in ensure_open
>     raise self.connection_closed_exc()
> websockets.exceptions.ConnectionClosedOK: code = 1001 (going away), no reason​

Ein Neustart von smarthomeNG mit

sudo systemctl restart smarthome

hat zwar das Vollschreiben des Logs beendet, aber der Websocket war immer noch nicht erreichbar. Nach meiner Interpretation der Logmeldungen scheint asyncio nicht zu stoppen gewesen zu sein.

2022-12-12  15:47:46 NOTICE   lib.smarthome       --------------------   Init SmartHomeNG v1.9.3-master (aa143b82a)   --------------------
2022-12-12  15:47:46 NOTICE   lib.smarthome       Running in Python interpreter 'v3.7.3 final', from directory /usr/local/smarthome
2022-12-12  15:47:47 NOTICE   lib.smarthome        - on Linux-5.10.103+-armv6l-with-debian-10.13 (pid=2462)
2022-12-12  15:49:25 ERROR    lib.db              Database [Database]: Could not connect to the database using 'sqlite3': unable to open database file
2022-12-12  15:49:25 CRITICAL plugins.database    Database: Initialization failed: unable to open database file
2022-12-12  15:49:25 NOTICE   lib.smarthome       --------------------   SmartHomeNG restarting, initiated by SmartHomeNG (Database plugin stalled)   --------------------
2022-12-12  15:50:25 NOTICE   lib.smarthome       --------------------   SmartHomeNG stopped   --------------------
2022-12-12  15:50:25 ERROR    asyncio             Task was destroyed but it is pending!
task: <Task pending coro=<Websocket.ws_server() running at /usr/local/smarthome/modules/websocket/__init__.py:265> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0xa94faf50>()]>>
2022-12-12  15:50:25 ERROR    asyncio             Task was destroyed but it is pending!
task: <Task pending coro=<Websocket.ws_server() running at /usr/local/smarthome/modules/websocket/__init__.py:265> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0xa9632af0>()]>>
2022-12-12  15:50:25 ERROR    asyncio             Task was destroyed but it is pending!
task: <Task pending coro=<Websocket.update_visu() running at /usr/local/smarthome/modules/websocket/__init__.py:922> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0xb682ecb0>()]>>
2022-12-12  15:50:25 ERROR    asyncio             Task was destroyed but it is pending!
task: <Task pending coro=<Websocket.update_all_series() running at /usr/local/smarthome/modules/websocket/__init__.py:765> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0xa9512570>()]>>
2022-12-12  15:50:40 NOTICE   lib.smarthome       --------------------   Init SmartHomeNG v1.9.3-master (aa143b82a)   --------------------
2022-12-12  15:50:40 NOTICE   lib.smarthome       Running in Python interpreter 'v3.7.3 final', from directory /usr/local/smarthome
2022-12-12  15:50:41 NOTICE   lib.smarthome        - on Linux-5.10.103+-armv6l-with-debian-10.13 (pid=2627)

Erst ein Stoppen von shNG mit

sudo systemctl stop smarthome

sowie etwas Wartezeit hat das Problem wieder behoben.

Ich habe danach das Log-Widget in meiner Seite deaktiviert und konnte den Fehler damit nicht mehr provozieren. Es muss also einen Zusammenhang mit dem Abonnement von Log-Daten und dem Auftreten der massiven Logmeldungen beim Schließen des Websockets geben.

Gruß
Wolfram

[Art Mooney]

wvhn, könntest Du mir bitte einen Hinweis geben, die ich das Log-Widget deaktivieren kann?

[wvhn]

Indem Du es löschst

Standardmäßig ist das Widget status.log eigentlich nur auf der smarthomeNG-Seite (./pages/base/smarthomeNG.html) aktiv. Da kannst Du es löschen oder auskommentieren.

Gruß
Wolfram

[wvhn]

Moin,

Ich entwickle und teste Erweiterungen für smartVISU auf einem PC mit Apache Webserver und einem Raspi mit smarthomeNG als Backend. Dabei habe ich häufig mehrere Verbindungen offen, z.B. um parallel Tipps fürs Forum zu testen. Dabei bin ich relativ häufig auf der Seite „smarthomeNG“, weil dort die Logmeldungen und 3 Plots vorhanden sind.

Heute hatte ich folgende Meldungen im Log:

2023-01-15  11:20:08 INFO     modules.websocket   update_log: Client 192.168.2.112:56977 is not active any more
2023-01-15  11:20:08 INFO     modules.websocket   update_log: Client 192.168.2.112:57024 is not active any more
2023-01-15  11:20:08 INFO     modules.websocket   update_log: Client 192.168.2.112:57037 is not active any more
2023-01-15  11:20:08 INFO     modules.websocket   update_log: Client 192.168.2.112:57108 is not active any more
​

Das Log habe ich über das Admin-Interface abgerufen und die registrierte Zeit entspricht ungefähr dem Zeitpunkt, an dem ich von der Hauptseite des Admin-Interfaces, auf der die Plots der System-Items abonniert werden, auf die Logs-Seite gewechselt habe (wobei ein Fehler geloggt wird, dass der Client nicht mehr aktiv ist und der User entfernt wird).

Alle vier Verbindungen waren schon vorgestern Nachmittag beendet worden. Dort steht zum Beispiel im Log:

2023-01-13  14:57:43 INFO     modules.websocket   smartVISU_protocol_v4: Client 192.168.2.112:57037 stopped
2023-01-13  14:57:43 INFO     modules.websocket   USER removed: 192.168.2.112:57037 - local port: 2424
….
2023-01-13  14:57:47 INFO     modules.websocket   update_all_series: Client 192.168.2.112:57037 is not active any more #2

Für mich sieht das so aus, als ob die Abonnements der Serien und der Logs nicht beendet werden, wenn ein User entfernt wird. Kann das mit eine Ursache für die sporadischen massenhaften Log-Meldungen sein?

Gruß
Wolfram

[Msinn]

Ich schau da demnächst mal rein.

Im Moment bin ich dabei meine Heizung wieder zum laufen zu bringen. In der Nacht zu gestern ist mein altes Wiregate abgeraucht. Nun bin ich dabei die 1-wire Sensoren auf das SmartHomeNG Plugin umzustellen...