Fehler websocket, Log läuft voll

[Onkelandy]

Heute war es wieder besonders dramatisch. 2 Restarts innerhalb von 15 Minuten. Das Log liegt bei 420MB!!
Dabei habe ich definitiv nirgendswo aktiv die Smartvisu genutzt. Auf dem iphone war in Chrome ein Tab offen, Chrome dann aber im Hintergrund.

modules.websocket update_log - Error in 'await websocket.send(data)': no close frame received or sent

und min. 20 Zeilen pro Fehlermeldung, das Ganze 100fach, bis es dann mal zu viel wird.

[Msinn]

Kannst Du dann auf Netzwerkebene mal schauen, wer bei Dir eine Websocket Verbindung zu SmartHomeNG aufbaut?

[wvhn]

Auf dem iphone war in Chrome ein Tab offen, Chrome dann aber im Hintergrund.

Im Log müsstest Du sehen, ob die Verbindung zu Chrome beendet wurde. Bei Safari wird eine Websocket-Verbindung aufgebaut, sobald Safari im Vordergrund ist - auch wenn der Tab mit smartVISU gerade nicht der aktive Tab ist. Geht das iPhone in den Ruhezustand oder wechsle ich für längere Zeit von Safari auf eine andere App, wird die Verbindung beendet und der User entfernt. Dies wird im Log registriert.

Zur Eingrenzung der Fehlerquellen: Ich nutze nicht das Image. Mein Webserver ist Apache2 und die Plugins sind überschaubar: knx, smartvisu, database, uzsu und cli. Auf beiden Raspberries mit shNG v1.8.2 und SV v3.1 bzw. v3.1.a tritt der Fehler nicht auf.

Gruß
Wolfram

[Onkelandy]

Hmmm, ich hab jetzt mal probiert, alles mit diesem Modul hier zu loggen: https://github.com/Refinitiv/ngx_htt...et_stat_module
Nach langem Hin und Her hat es geklappt. Allerdings hat es seither 7 Neustarts und teils sogar Reboots gegeben.
Wie könnte ich das Ganze denn am besten noch protokollieren..? Ich vermute am ehesten mit Wireshark?

[Onkelandy]

Ich hab nun einen anderen Fork des websocket log modules kompiliert und es scheint ziemlich zuverlässig zu klappen.
Gestern gab es ein paar Neustarts von shng auf Grund der obigen Fehler, ua. um 5:28 Uhr nachts. Da hat definitiv niemand irgendwas mit der Visu gemacht und die letzte Interaktion lag wohl min. 2-3 Stunden in der Vergangenheit.

Laut Websocket Log gab es auch tatsächlich keine Anfrage, die Verbindung wurde eigentlich geschlossen und zur relevanten Zeit auch nicht mehr geöffnet.

Sun, 31 Oct 2021 03:14:59 GMT: packet of type 8 received from upstream, packet size is 24.
Sun, 31 Oct 2021 03:14:59 GMT: Connection closed.
Sun, 31 Oct 2021 07:15:11 GMT: Connection opened.
Sun, 31 Oct 2021 07:15:31 GMT: packet of type 9 received from upstream, packet size is 4.

Man sieht also, dass zwischen 4:14 und 08:15 nix passiert ist. Und trotzdem gab's wieder websocket Wahnsinn
Ich dreh jetzt die nginx Timeouts nochmals höher und schau weiter..

[Msinn]

Wenn es in der Zeit zwischen 4:14 und 8:15 die Meldungen aus dem Websocket Modul gab, sieht das im Moment so aus, als wäre der Connection Close von 4:14:59 nicht beim Websocket Modul angekommen.

Dreh mal den Loglevel des websocket Moduls hoch. Dann siehst Du im Wiederholungsfall Logeinträge für das Öffnen und Schließen der Verbindungen in SmartHomeNG.

[Hochpass]

Ich hatte heute wieder einen Neustart. Was mir jetzt aufgefallen ist, es ist immer passiert als ich hohe Buslast hatte bzw. unser Auto PV geführt läd und SHNG die Leistung steuert.

[Onkelandy]

Bei mir trat es heute wieder 2 Mal auf - ohne ersichtlichen Grund. Definitiv keine höhere Buslast, diesmal passierte es aber wohl immerhin nur beim Aufruf der SV (es gab ja auch schon genug Geister-Restarts mitten in der Nacht..)

Das hier ist nun das DEBUG log vom websocket Modul..

Nov 07 23:19:40 CET INFO modules.websocket modules.websocket.websocket_server USER added: ('127.0.0.1', 50170) - local port: 2424 -- (__init__.py:log_connection_event:325)
Nov 07 23:19:40 CET DEBUG modules.websocket modules.websocket.websocket_server Connected USERS: 2 -- (__init__.py:log_connection_event:327)
Nov 07 23:19:40 CET DEBUG modules.websocket modules.websocket.websocket_server - user: ('10.0.0.150', 51132) path: / secure: False -- (__init__.py:log_connection_event:329)
Nov 07 23:19:40 CET DEBUG modules.websocket modules.websocket.websocket_server - user: ('127.0.0.1', 50170) path: / secure: False -- (__init__.py:log_connection_event:329)
Nov 07 23:19:40 CET INFO modules.websocket modules.websocket.websocket_server smartVISU_protocol_v4: Client 127.0.0.1:50170 started -- (__init__.py:smartVISU_protocol_v4:438)
Nov 07 23:19:40 CET INFO modules.websocket modules.websocket.websocket_server 127.0.0.1:50170 sent '{'cmd': 'proto', 'ver': 4}' -- (__init__.py:smartVISU_protocol_v4:451)
Nov 07 23:19:40 CET INFO modules.websocket modules.websocket.websocket_server visu >REPLY: '{'cmd': 'proto', 'ver': 4, 'server': 'module.websocket', 'time': '2021-11-07T23:19:40.217582'}' - to ('127.0.0.1', 50170) -- (__init__.py:smartVISU_protocol_v4:560)
Nov 07 23:19:40 CET INFO modules.websocket modules.websocket.websocket_server 127.0.0.1:50170 sent '{'cmd': 'identity', 'sw': 'smartVISU', 'ver': 'v3.1.a', 'browser': 'Safari', 'bver': '15'}' -- (__init__.py:smartVISU_protocol_v4:451)
Nov 07 23:19:40 CET INFO modules.websocket modules.websocket.websocket_server smartVISU_protocol_v4: Client 127.0.0.1:50170 identified as 'smartVISU v3.1.a' in Browser 'Safari 15' -- (__init__.py:smartVISU_protocol_v4:533)
Nov 07 23:19:40 CET INFO modules.websocket modules.websocket.websocket_server 127.0.0.1:50170 sent '{'cmd': 'log', 'name': 'memory_warn', 'max': '20'}' -- (__init__.py:smartVISU_protocol_v4:451)
Nov 07 23:19:40 CET INFO modules.websocket modules.websocket.websocket_server visu >REPLY: '{'cmd': 'log', 'name': 'memory_warn', 'log': [{'time': datetime.datetime(2021, 11, 7, 21, 37, 15, 70859, tzinfo=tzfile('/usr/share/zoneinfo/Europe/Vienna')), 'thread': 'plugins.ical.iCalRefresh', ... 'level': 'ERROR', 'message': 'Needing more worker threads than the specified maximum of 20! (25 worker threads active)'}], 'init': 'y'}' - to ('127.0.0.1', 50170) -- (__init__.py:smartVISU_protocol_v4:560)
Nov 07 23:20:04 CET ERROR modules.websocket modules.websocket.websocket_server smartVISU_protocol_v4 exception: no close frame received or sent -- (__init__.py:smartVISU_protocol_v4:567)
Nov 07 23:20:04 CET INFO modules.websocket modules.websocket.websocket_server handle_new_connection - Connection to '127.0.0.1:50170' has been terminated in payload protocol or couldn't be established -- (__init__.py:handle_new_connection:297)
Nov 07 23:20:04 CET INFO modules.websocket modules.websocket.websocket_server USER removed: ('127.0.0.1', 50170) - local port: 2424 -- (__init__.py:log_connection_event:325)
Nov 07 23:20:04 CET DEBUG modules.websocket modules.websocket.websocket_server Connected USERS: 1 -- (__init__.py:log_connection_event:327)
Nov 07 23:20:04 CET DEBUG modules.websocket modules.websocket.websocket_server - user: ('10.0.0.150', 51132) path: / secure: False -- (__init__.py:log_connection_event:329)
Nov 07 23:20:04 CET ERROR modules.websocket modules.websocket.websocket_server update_log - Error in 'await websocket.send(data)': no close frame received or sent -- (__init__.py:update_log:946)
Traceback (most recent call last):
File "/home/smarthome/.local/lib/python3.8/site-packages/websockets/legacy/protocol.py", line 944, in transfer_data
message = await self.read_message()
File "/home/smarthome/.local/lib/python3.8/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.8/site-packages/websockets/legacy/protocol.py", line 1089, in read_data_frame
frame = await self.read_frame(max_size)
File "/home/smarthome/.local/lib/python3.8/site-packages/websockets/legacy/protocol.py", line 1144, in read_frame
frame = await Frame.read(
File "/home/smarthome/.local/lib/python3.8/site-packages/websockets/legacy/framing.py", line 70, in read
data = await reader(2)
File "/usr/local/lib/python3.8/asyncio/streams.py", line 721, in readexactly
raise exceptions.IncompleteReadError(incomplete, n)
asyncio.exceptions.IncompleteReadError: 0 bytes read on a total of 2 expected bytes

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 943, in update_log
await websocket.send(msg)
File "/home/smarthome/.local/lib/python3.8/site-packages/websockets/legacy/protocol.py", line 619, in send
await self.ensure_open()
File "/home/smarthome/.local/lib/python3.8/site-packages/websockets/legacy/protocol.py", line 920, in ensure_open
raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedError: no close frame received or sent
Nov 07 23:20:04 CET ERROR modules.websocket modules.websocket.websocket_server update_log - Error in 'await websocket.send(data)': no close frame received or sent -- (__init__.py:update_log:946)
Traceback (most recent call last):
File "/home/smarthome/.local/lib/python3.8/site-packages/websockets/legacy/protocol.py", line 944, in transfer_data
message = await self.read_message()
File "/home/smarthome/.local/lib/python3.8/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.8/site-packages/websockets/legacy/protocol.py", line 1089, in read_data_frame
frame = await self.read_frame(max_size)
File "/home/smarthome/.local/lib/python3.8/site-packages/websockets/legacy/protocol.py", line 1144, in read_frame
frame = await Frame.read(
File "/home/smarthome/.local/lib/python3.8/site-packages/websockets/legacy/framing.py", line 70, in read
data = await reader(2)
File "/usr/local/lib/python3.8/asyncio/streams.py", line 721, in readexactly
raise exceptions.IncompleteReadError(incomplete, n)
asyncio.exceptions.IncompleteReadError: 0 bytes read on a total of 2 expected bytes

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 943, in update_log
await websocket.send(msg)
File "/home/smarthome/.local/lib/python3.8/site-packages/websockets/legacy/protocol.py", line 619, in send
await self.ensure_open()
File "/home/smarthome/.local/lib/python3.8/site-packages/websockets/legacy/protocol.py", line 920, in ensure_open
raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedError: no close frame received or sent

Am Morgen ist was Ähnliches passiert:

Nov 07 08:32:31 CET INFO modules.websocket modules.websocket.websocket_server USER added: ('127.0.0.1', 59412) - local port: 2424 -- (__init__.py:log_connection_event:325)
Nov 07 08:32:31 CET DEBUG modules.websocket modules.websocket.websocket_server Connected USERS: 2 -- (__init__.py:log_connection_event:327)
Nov 07 08:32:31 CET DEBUG modules.websocket modules.websocket.websocket_server - user: ('127.0.0.1', 59412) path: / secure: False -- (__init__.py:log_connection_event:329)
Nov 07 08:32:31 CET DEBUG modules.websocket modules.websocket.websocket_server - user: ('10.0.0.150', 52838) path: / secure: False -- (__init__.py:log_connection_event:329)
Nov 07 08:32:31 CET INFO modules.websocket modules.websocket.websocket_server smartVISU_protocol_v4: Client 127.0.0.1:59412 started -- (__init__.py:smartVISU_protocol_v4:438)
Nov 07 08:32:32 CET INFO modules.websocket modules.websocket.websocket_server 127.0.0.1:59412 sent '{'cmd': 'proto', 'ver': 4}' -- (__init__.py:smartVISU_protocol_v4:451)
Nov 07 08:32:32 CET INFO modules.websocket modules.websocket.websocket_server visu >REPLY: '{'cmd': 'proto', 'ver': 4, 'server': 'module.websocket', 'time': '2021-11-07T08:32:32.126266'}' - to ('127.0.0.1', 59412) -- (__init__.py:smartVISU_protocol_v4:560)
Nov 07 08:32:32 CET INFO modules.websocket modules.websocket.websocket_server 127.0.0.1:59412 sent '{'cmd': 'identity', 'sw': 'smartVISU', 'ver': 'v3.1.a', 'browser': 'Safari', 'bver': '15'}' -- (__init__.py:smartVISU_protocol_v4:451)
Nov 07 08:32:32 CET INFO modules.websocket modules.websocket.websocket_server smartVISU_protocol_v4: Client 127.0.0.1:59412 identified as 'smartVISU v3.1.a' in Browser 'Safari 15' -- (__init__.py:smartVISU_protocol_v4:533)
Nov 07 08:32:32 CET INFO modules.websocket modules.websocket.websocket_server 127.0.0.1:59412 sent '{'cmd': 'log', 'name': 'memory_warn', 'max': '20'}' -- (__init__.py:smartVISU_protocol_v4:451)
Nov 07 08:32:32 CET INFO modules.websocket modules.websocket.websocket_server visu >REPLY: '{'cmd': 'log', 'name': 'memory_warn', 'log': [{'time': datetime.datetime(2021, 11, 7, 7, 55, 15, 687122, tzinfo=tzfile('/usr/share/zoneinfo/Europe/Vienna')), ... 'plugins.uzsu.uzsu_licht.kurve.warm.uzsu', 'level': 'ERROR', 'message': 'Problems assigning dmax: day is out of range for month. Wrong syntax: sunrise-120m<05:30. Should be [H:M<](sunrise|sunset)[+|-][offset][<H:M]'}], 'init': 'y'}' - to ('127.0.0.1', 59412) -- (__init__.py:smartVISU_protocol_v4:560)
Nov 07 08:32:39 CET ERROR modules.websocket modules.websocket.websocket_server smartVISU_protocol_v4 exception: no close frame received or sent -- (__init__.py:smartVISU_protocol_v4:567)
Nov 07 08:32:39 CET INFO modules.websocket modules.websocket.websocket_server handle_new_connection - Connection to '127.0.0.1:59412' has been terminated in payload protocol or couldn't be established -- (__init__.py:handle_new_connection:297)
Nov 07 08:32:39 CET INFO modules.websocket modules.websocket.websocket_server USER removed: ('127.0.0.1', 59412) - local port: 2424 -- (__init__.py:log_connection_event:325)
Nov 07 08:32:39 CET DEBUG modules.websocket modules.websocket.websocket_server Connected USERS: 1 -- (__init__.py:log_connection_event:327)
Nov 07 08:32:39 CET DEBUG modules.websocket modules.websocket.websocket_server - user: ('10.0.0.150', 52838) path: / secure: False -- (__init__.py:log_connection_event:329)
Nov 07 08:32:39 CET ERROR modules.websocket modules.websocket.websocket_server update_log - Error in 'await websocket.send(data)': no close frame received or sent -- (__init__.py:update_log:946)
Traceback (most recent call last):
File "/home/smarthome/.local/lib/python3.8/site-packages/websockets/legacy/protocol.py", line 944, in transfer_data
message = await self.read_message()
File "/home/smarthome/.local/lib/python3.8/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.8/site-packages/websockets/legacy/protocol.py", line 1089, in read_data_frame
frame = await self.read_frame(max_size)
File "/home/smarthome/.local/lib/python3.8/site-packages/websockets/legacy/protocol.py", line 1144, in read_frame
frame = await Frame.read(
File "/home/smarthome/.local/lib/python3.8/site-packages/websockets/legacy/framing.py", line 70, in read
data = await reader(2)
File "/usr/local/lib/python3.8/asyncio/streams.py", line 721, in readexactly
raise exceptions.IncompleteReadError(incomplete, n)
asyncio.exceptions.IncompleteReadError: 0 bytes read on a total of 2 expected bytes

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 943, in update_log
await websocket.send(msg)
File "/home/smarthome/.local/lib/python3.8/site-packages/websockets/legacy/protocol.py", line 619, in send
await self.ensure_open()
File "/home/smarthome/.local/lib/python3.8/site-packages/websockets/legacy/protocol.py", line 920, in ensure_open
raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedError: no close frame received or sent

Das Websocket Modul von NGINX hat Folgendes geloggt (1h zeitversetzt):

Sun, 07 Nov 2021 07:32:31 GMT: Connection opened.
Sun, 07 Nov 2021 07:32:32 GMT: packet of type 1 received from client, packet size is 23.
Sun, 07 Nov 2021 07:32:32 GMT: packet of type 1 received from client, packet size is 81.
Sun, 07 Nov 2021 07:32:32 GMT: packet of type 1 received from client, packet size is 45.
Sun, 07 Nov 2021 07:32:32 GMT: packet of type 1 received from upstream, packet size is 94.
Sun, 07 Nov 2021 07:32:32 GMT: packet of type 1 received from upstream, packet size is 5795.
Sun, 07 Nov 2021 07:32:39 GMT: Connection closed.
Sun, 07 Nov 2021 22:19:40 GMT: Connection opened.
Sun, 07 Nov 2021 22:19:40 GMT: packet of type 1 received from client, packet size is 23.
Sun, 07 Nov 2021 22:19:40 GMT: packet of type 1 received from client, packet size is 81.
Sun, 07 Nov 2021 22:19:40 GMT: packet of type 1 received from client, packet size is 45.
Sun, 07 Nov 2021 22:19:40 GMT: packet of type 1 received from upstream, packet size is 94.
Sun, 07 Nov 2021 22:19:40 GMT: packet of type 1 received from upstream, packet size is 6914.
Sun, 07 Nov 2021 22:20:00 GMT: packet of type 9 received from upstream, packet size is 4.
Sun, 07 Nov 2021 22:20:00 GMT: packet of type 10 received from client, packet size is 4.
Sun, 07 Nov 2021 22:20:04 GMT: Connection closed.

[wvhn]

Es sieht so aus, als ob die Verbindung zu 127.0.0.1:50170 ordnungsgemäß beendet wird und unmittelbar danach die noch offene Verbindung zu 10.0.0.150 abstürzt - mit derselben Fehlermeldung: no close frame received or sent.

127.0.0.1 ist das Tablet, das über den Reverseproxy reinkommt - bei Dir nginx auf dem Raspberry. Deshalb die Adresse des Localhost. Richtig?
Was ist die Adresse 10.0.0.150?

[Onkelandy]

Localhost muss wohl reverse proxy sein, ja - das war in dem Fall das iphone.
10.0.0.150 ist der Raspberry Pi - auf dem läuft alles, SV, shng, nginx, etc.

[wvhn]

Verstehe nicht, warum der Raspberry Pi unter seiner eigenen IP-Adresse eine Websocketverbindung zu sich selbst - also zu dem auf ihm selbst laufenden Websocket-Server - offen haben sollte. Dazu müsste ein Websocket-Client auf dem Pi laufen. Und dafür müsste doch die IP-Adresse wieder localhost (127.0.0.1) sein, oder?

Hab ich da etwas nicht verstanden, oder kann diese Verbindung die Ursache allen Übels sein?

[Onkelandy]

Sehe ich so wie du. Ich schau nochmals die nginx Config Files durch, glaube aber nicht, dass dort die IP angegeben ist. Am ehesten in der shng Config..?

[Msinn]

Was für eine IP Adresse sollte in SmartHomeNG für Websocket denn konfiguriert sein/werden?

Das Websocket Modul bietet nur die Möglichkeit einzuschränken, auf welcher IP Adresse gelauscht werden soll (Standard auf allen IP Adressen des Servers).

[Onkelandy]

Ne, da ist eh nirgends die IP Adresse drin. Auch in der nginx Config steht nirgends 10.0.0.150. Hmmmmm.......

[Onkelandy]

Ich habe inzwischen das Log Widget in Verdacht..

{{ status.log('', 'memory_warn', 20) }}

Ich hab zwar manchmal noch die Close Frame exceptions, aber kein voll laufendes Log, seit ich es raus genommen habe. Kann Zufall sein, vielleicht ist es aber doch auch die Ursache. kunig nutzt du das auch? Könnte sonst mal jemand versuchen, das Widget einzubinden und beobachten?