"connection closed" - Miniserver connection error: Socket Error: read ECONNRESET (1006)

DSew20 commented 2 years ago

Hello - has anybody noticed that the MiniServer connection keeps dropping in / out?

I seem to be getting connection issues every few minutes. The error message shown under each node is "connection closed". I also get the following error in the debug console:

"Miniserver connection error: Socket Error: read ECONNRESET (1006)"

This code has been so stable for as long as I can remember. But, it seems to be having issues at the moment. I'm on the latest version of node-red-contrib-loxone (v10.12), v2.05 of Node Red and the latest MiniServer version (v13.06.29).

Any thoughts on how to isolate / fix the problem?

DSew20 commented 2 years ago

Hello - does anybody have any ideas as to why the connection keeps closing? To add to above, I have updated Note-Red to v2.2.2. The issue remains.

This had all been working great for months. But, for some reason, the connection keeps dropping. It connects, works ok, then connection closes / drops. Any ideas how to troubleshoot / fix?

codmpm commented 2 years ago

Hey @DSew20,

we will have a look into this but we currently have time constraints. @codmdu could you maybe give this a look?

gahujipo commented 2 years ago

I think this issue describes the same problem as in #73

centauri commented 2 years ago

Got the same error. Node red is constantly rebooting

WebSocket error:  Socket Error: undefined ERR_STREAM_WRITE_AFTER_END 1006
15 Sep 00:16:26 - [error] [loxone-miniserver:xxxxxxxxxxxxxxx] Miniserver connection error: Socket Error: undefined ERR_STREAM_WRITE_AFTER_END (1006)
Websocket Connection closed:  1006 Socket Error: undefined ERR_STREAM_WRITE_AFTER_END
15 Sep 00:16:26 - [info] [loxone-miniserver:xxxxxxxxxxxxxxx] connection closed: Socket Error: undefined ERR_STREAM_WRITE_AFTER_END (1006)
15 Sep 00:16:26 - [info] [loxone-miniserver:xxxxxxxxxxxxxxx] connection closed: reconnecting
15 Sep 00:16:26 - [info] [loxone-miniserver:xxxxxxxxxxxxxxx] Miniserver connected (192.168.2.1:80) using Token-Enc
WebSocket error:  Socket Error: undefined ERR_STREAM_WRITE_AFTER_END 1006
15 Sep 00:16:26 - [error] [loxone-miniserver:xxxxxxxxxxxxxxx] Miniserver connection error: Socket Error: undefined ERR_STREAM_WRITE_AFTER_END (1006)
Websocket Connection closed:  1006 Socket Error: undefined ERR_STREAM_WRITE_AFTER_END
15 Sep 00:16:26 - [info] [loxone-miniserver:xxxxxxxxxxxxxxx] connection closed: Socket Error: undefined ERR_STREAM_WRITE_AFTER_END (1006)
15 Sep 00:16:26 - [info] [loxone-miniserver:xxxxxxxxxxxxxxx] connection closed: reconnecting
15 Sep 00:16:26 - [info] [loxone-miniserver:xxxxxxxxxxxxxxx] Miniserver connected (192.168.2.1:80) using Token-Enc
WebSocket error:  Socket Error: undefined ERR_STREAM_WRITE_AFTER_END 1006
15 Sep 00:16:26 - [error] [loxone-miniserver:xxxxxxxxxxxxxxx] Miniserver connection error: Socket Error: undefined ERR_STREAM_WRITE_AFTER_END (1006)
Websocket Connection closed:  1006 Socket Error: undefined ERR_STREAM_WRITE_AFTER_END
15 Sep 00:16:26 - [info] [loxone-miniserver:xxxxxxxxxxxxxxx] connection closed: Socket Error: undefined ERR_STREAM_WRITE_AFTER_END (1006)
15 Sep 00:16:26 - [info] [loxone-miniserver:xxxxxxxxxxxxxxx] connection closed: reconnecting
15 Sep 00:16:26 - [info] [loxone-miniserver:xxxxxxxxxxxxxxx] connection closed: reconnecting
15 Sep 00:16:26 - [info] [loxone-miniserver:xxxxxxxxxxxxxxx] connection closed: reconnecting
15 Sep 00:16:26 - [info] [loxone-miniserver:xxxxxxxxxxxxxxx] connection closed: reconnecting
15 Sep 00:16:26 - [info] [loxone-miniserver:xxxxxxxxxxxxxxx] connection closed: reconnecting
15 Sep 00:16:26 - [red] Uncaught Exception:
15 Sep 00:16:26 - [error] TypeError: Cannot read properties of undefined (reading 'closeDescription')
    at Connection.<anonymous> (/data/node_modules/node-lox-ws-api/lib/Connection.js:64:62)
    at WebSocketClient.emit (node:events:527:28)
    at WebSocketClient.emit (node:domain:475:12)
    at ClientRequest.handleRequestError (/data/node_modules/websocket/lib/WebSocketClient.js:227:14)
    at ClientRequest.emit (node:events:527:28)
    at ClientRequest.emit (node:domain:475:12)
    at Socket.socketErrorListener (node:_http_client:454:9)
    at Socket.emit (node:events:527:28)
    at Socket.emit (node:domain:475:12)
    at emitErrorNT (node:internal/streams/destroy:157:8)
    at emitErrorCloseNT (node:internal/streams/destroy:122:3)
    at processTicksAndRejections (node:internal/process/task_queues:83:21)
15 Sep 00:16:32 - [info] 
Welcome to Node-RED
===================
15 Sep 00:16:32 - [info] Node-RED version: v3.0.2
15 Sep 00:16:32 - [info] Node.js  version: v16.16.0
15 Sep 00:16:32 - [info] Linux 4.19.118-v7l+ arm LE
15 Sep 00:16:34 - [info] Loading palette nodes

UtechtDustin commented 1 year ago

I'm not able to reproduce it right now, can somebody please add the following line console.log(">>>", this._ws.connection.closeDescription) to the file USER-DIR/.node-red/node_modules/node-red-contrib-loxone/node_modules/node-lox-ws-api/lib/Connection.js between line 146 and line 147. (Right after Connection.prototype.send = function (message) {).

After that restart node-red and copy & paste the log to this issue. Thanks in advance.

3HMonkey commented 1 year ago

Hey I checked this, it is "null".

UtechtDustin commented 1 year ago

@3HMonkey Thank you, is it always null ? The first 3-4 lines should be null, but is it also null when the error occurs ?

3HMonkey commented 1 year ago

Let me setup a plain process.

This is the clean start without a flow which is working great.

Starting as a systemd service.
2 Nov 09:23:37 - [info]
Willkommen bei Node-RED
===================
2 Nov 09:23:37 - [info] Node-RED Version: v3.0.2
2 Nov 09:23:37 - [info] Node.js  Version: v18.12.0
2 Nov 09:23:37 - [info] Linux 5.10.103-v7+ arm LE
2 Nov 09:23:42 - [info] Paletten-Nodes werden geladen
2 Nov 09:23:48 - [info] Dashboard version 2.30.0 started at /ui
2 Nov 09:23:49 - [info] Einstellungsdatei: /home/pi/.node-red/settings.js
2 Nov 09:23:49 - [info] Kontextspeicher: default [module=memory]
2 Nov 09:23:49 - [info] Benutzerverzeichnis: /home/pi/.node-red
2 Nov 09:23:49 - [warn] Projekte deaktiviert: editorTheme.projects.enabled=false
2 Nov 09:23:49 - [warn] Name der Flows-Datei nicht festgelegt. Name wird unter Verwendung des Hostnamens generiert.
2 Nov 09:23:49 - [info] Flow-Datei: /home/pi/.node-red/flows_raspberrypi.json
2 Nov 09:23:49 - [warn] Vorhandene 'flow'-Datei enthält ungültigen JSON-Code
2 Nov 09:23:49 - [info] Server wird jetzt auf http://127.0.0.1:1880/ ausgeführt
2 Nov 09:23:49 - [warn]
---------------------------------------------------------------------
Die Datei mit den Flow-Credentials wird mit einem vom System
generierten Schlüssel verschlüsselt.
Wenn der vom System generierte Schlüssel aus irgendeinem Grund
verloren geht, kann die Datei mit den Credentials nicht
wiederhergestellt werden. Sie muss dann gelöscht und die
Credentials müssen erneut eingestellt werden.
Es sollte ein eigener Schlüssel mit Hilfe der Option
'credentialSecret' in der Einstellungsdatei vorgegeben werden.
Node-RED wird dann die Datei mit den Flow-Credentials
bei der nächsten Übernahme (deploy) einer Änderung erneut
verschlüsseln.
---------------------------------------------------------------------
2 Nov 09:23:49 - [info] Flows werden gestartet
2 Nov 09:23:49 - [info] Flows sind gestartet

Then I went setting up a new connection for the miniserver which is also working receiving the structure:

After deploying nodered is restarting over and over. Yes, first it is null, then forbidden since it is reaching the reconnect counts:

>>>>>>>> Forbidden - IP 192.168.178.34 temporarily blocked, too many failed login attempts (1)
WebSocket error:  Socket Error: undefined ERR_STREAM_WRITE_AFTER_END 1006
2 Nov 09:38:07 - [error] [loxone-miniserver:a9a0d40ea3ba1692] Miniserver connection error: Socket Error: undefined ERR_STREAM_WRITE_AFTER_END (1006)
Websocket Connection closed:  1006 Socket Error: undefined ERR_STREAM_WRITE_AFTER_END
2 Nov 09:38:07 - [info] [loxone-miniserver:a9a0d40ea3ba1692] connection closed: Socket Error: undefined ERR_STREAM_WRITE_AFTER_END (1006)
2 Nov 09:38:07 - [info] [loxone-miniserver:a9a0d40ea3ba1692] connection closed: reconnecting
2 Nov 09:38:07 - [info] [loxone-miniserver:a9a0d40ea3ba1692] Miniserver connected (192.168.178.38:80) using Token-Enc
>>>>>>>>> Forbidden - IP 192.168.178.34 temporarily blocked, too many failed login attempts (1)
WebSocket error:  Socket Error: undefined ERR_STREAM_WRITE_AFTER_END 1006
2 Nov 09:38:07 - [error] [loxone-miniserver:a9a0d40ea3ba1692] Miniserver connection error: Socket Error: undefined ERR_STREAM_WRITE_AFTER_END (1006)
Websocket Connection closed:  1006 Socket Error: undefined ERR_STREAM_WRITE_AFTER_END
2 Nov 09:38:07 - [info] [loxone-miniserver:a9a0d40ea3ba1692] connection closed: Socket Error: undefined ERR_STREAM_WRITE_AFTER_END (1006)
2 Nov 09:38:07 - [info] [loxone-miniserver:a9a0d40ea3ba1692] connection closed: reconnecting
2 Nov 09:38:07 - [info] [loxone-miniserver:a9a0d40ea3ba1692] Miniserver connected (192.168.178.38:80) using Token-Enc
>>>>>>>>> Forbidden - IP 192.168.178.34 temporarily blocked, too many failed login attempts (1)
WebSocket error:  Socket Error: undefined ERR_STREAM_WRITE_AFTER_END 1006
2 Nov 09:38:07 - [error] [loxone-miniserver:a9a0d40ea3ba1692] Miniserver connection error: Socket Error: undefined ERR_STREAM_WRITE_AFTER_END (1006)
Websocket Connection closed:  1006 Socket Error: undefined ERR_STREAM_WRITE_AFTER_END
2 Nov 09:38:07 - [info] [loxone-miniserver:a9a0d40ea3ba1692] connection closed: Socket Error: undefined ERR_STREAM_WRITE_AFTER_END (1006)
2 Nov 09:38:07 - [info] [loxone-miniserver:a9a0d40ea3ba1692] connection closed: reconnecting
2 Nov 09:38:08 - [info] [loxone-miniserver:a9a0d40ea3ba1692] Miniserver connected (192.168.178.38:80) using Token-Enc
>>>>>>>>> Forbidden - IP 192.168.178.34 temporarily blocked, too many failed login attempts (1)
WebSocket error:  Socket Error: undefined ERR_STREAM_WRITE_AFTER_END 1006
2 Nov 09:38:08 - [error] [loxone-miniserver:a9a0d40ea3ba1692] Miniserver connection error: Socket Error: undefined ERR_STREAM_WRITE_AFTER_END (1006)
Websocket Connection closed:  1006 Socket Error: undefined ERR_STREAM_WRITE_AFTER_END
2 Nov 09:38:08 - [info] [loxone-miniserver:a9a0d40ea3ba1692] connection closed: Socket Error: undefined ERR_STREAM_WRITE_AFTER_END (1006)
2 Nov 09:38:08 - [info] [loxone-miniserver:a9a0d40ea3ba1692] connection closed: reconnecting
2 Nov 09:38:08 - [info] [loxone-miniserver:a9a0d40ea3ba1692] Miniserver connected (192.168.178.38:80) using Token-Enc
>>>>>>>>> Forbidden - IP 192.168.178.34 temporarily blocked, too many failed login attempts (1)
WebSocket error:  Socket Error: undefined ERR_STREAM_WRITE_AFTER_END 1006
2 Nov 09:38:08 - [error] [loxone-miniserver:a9a0d40ea3ba1692] Miniserver connection error: Socket Error: undefined ERR_STREAM_WRITE_AFTER_END (1006)
Websocket Connection closed:  1006 Socket Error: undefined ERR_STREAM_WRITE_AFTER_END
2 Nov 09:38:08 - [info] [loxone-miniserver:a9a0d40ea3ba1692] connection closed: Socket Error: undefined ERR_STREAM_WRITE_AFTER_END (1006)
2 Nov 09:38:08 - [info] [loxone-miniserver:a9a0d40ea3ba1692] connection closed: reconnecting
2 Nov 09:38:08 - [info] [loxone-miniserver:a9a0d40ea3ba1692] connection closed: reconnecting
2 Nov 09:38:08 - [info] [loxone-miniserver:a9a0d40ea3ba1692] connection closed: reconnecting
2 Nov 09:38:08 - [info] [loxone-miniserver:a9a0d40ea3ba1692] connection closed: reconnecting
2 Nov 09:38:08 - [info] [loxone-miniserver:a9a0d40ea3ba1692] connection closed: reconnecting
2 Nov 09:38:08 - [info] [loxone-miniserver:a9a0d40ea3ba1692] connection closed: reconnecting
2 Nov 09:38:08 - [info] [loxone-miniserver:a9a0d40ea3ba1692] connection closed: reconnecting
2 Nov 09:38:08 - [red] Uncaught Exception:
2 Nov 09:38:08 - [error] TypeError: Cannot read properties of undefined (reading 'closeDescription')
    at Connection.<anonymous> (/home/pi/.node-red/node_modules/node-lox-ws-api/lib/Connection.js:64:62)
    at WebSocketClient.emit (node:events:513:28)
    at ClientRequest.handleRequestError (/home/pi/.node-red/node_modules/websocket/lib/WebSocketClient.js:227:14)
    at ClientRequest.emit (node:events:513:28)
    at Socket.socketErrorListener (node:_http_client:494:9)
    at Socket.emit (node:events:513:28)
    at emitErrorNT (node:internal/streams/destroy:151:8)
    at emitErrorCloseNT (node:internal/streams/destroy:116:3)
    at process.processTicksAndRejections (node:internal/process/task_queues:82:21)
nodered.service: Main process exited, code=exited, status=1/FAILURE
nodered.service: Failed with result 'exit-code'.
nodered.service: Service RestartSec=20s expired, scheduling restart.
nodered.service: Scheduled restart job, restart counter is at 8.

UtechtDustin commented 1 year ago

@3HMonkey You're credentials or the ip of the miniserver are wrong

>>>>>>>> Forbidden - IP 192.168.178.34 temporarily blocked, too many failed login attempts (1)

3HMonkey commented 1 year ago

I do not think so since the credentials are stored inside the connection. Also with the wrong credentials it is impossible to parse the structure of the miniserver. Maybe the method changed due to an update of loxone?

UtechtDustin commented 1 year ago

You're right, so we have to figure out why the miniserver returns this message.

Which method to you mean ? We currently run version 13.1.10.19, with correct credentials it works fine for us.

3HMonkey commented 1 year ago

I also thought about that, so I decided updating it today also.

Ill stop the nodered server and wait for the timeout and start it again and provide the logs. Is there a command I can store the logs of node-red into a file?

3HMonkey commented 1 year ago

Here is the full log until it swap to "forbidden"

codmpm / node-red-contrib-loxone

"connection closed" - Miniserver connection error: Socket Error: read ECONNRESET (1006) #74