node-red-node-xmpp crash

BeaverUI commented 2 years ago

Which node are you reporting an issue on?

node-red-node-xmpp

What are the steps to reproduce?

configure everything
connect to a MUC room with xmpp in and xmpp out
shut down XMPP server

What happens?

node-red service crashes entirely, or
node-red service becomes unresponsive

What do you expect to happen?

have the XMPP clients try to reconnect every 10 seconds or so, and...
...most importantly: dont let node-red crash!

Please tell us about your environment:

[ ] Node-RED version: latest (2.1.5)
[ ] Node.js version: 16.13.2
[ ] Platform/OS: Ubuntu Server 20.04
[ ] Browser: Firefox
[ ] XMPP plugin: latest

hardillb commented 2 years ago

Is there anything in the Node-RED log (the console output not the debug sidebar) when it crashes?

BeaverUI commented 2 years ago

I've got this in syslog:

17:10:47 systemd[1]: Started LSB: Start/stop openfire jabber server. NOTE: here I stop OpenFire

Then the thing goes ballistic: 17:10:48 node-red[190463]: 13 Jan 17:10:48 - [info] [xmpp out:XMPP transmit] Error: connect ECONNREFUSED HIDDEN IP:5222 17:10:48 node-red[190463]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1161:16) 17:10:48 node-red[190463]: 13 Jan 17:10:48 - [info] [xmpp in:NAS messages XMPP] XMPP Error: Error: connect ECONNREFUSED HIDDEN IP:5222 17:10:48 node-red[190463]: 13 Jan 17:10:48 - [info] [xmpp out:XMPP transmit] Error: connect ECONNREFUSED HIDDEN IP:5222 17:10:48 node-red[190463]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1161:16) 17:10:48 node-red[190463]: 13 Jan 17:10:48 - [info] [xmpp out:XMPP transmit] Error: connect ECONNREFUSED HIDDEN IP:5222 17:10:48 node-red[190463]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1161:16) 17:10:49 node-red[190463]: 13 Jan 17:10:49 - [info] [xmpp out:XMPP transmit] Error: connect ECONNREFUSED HIDDEN IP:5222 17:10:49 node-red[190463]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1161:16) 17:10:49 node-red[190463]: 13 Jan 17:10:49 - [info] [xmpp out:XMPP transmit] Error: connect ECONNREFUSED HIDDEN IP:5222 17:10:49 node-red[190463]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1161:16) 17:10:49 node-red[190463]: 13 Jan 17:10:49 - [info] [xmpp in:NAS messages XMPP] XMPP Error: Error: connect ECONNREFUSED HIDDEN IP:5222 17:10:49 node-red[190463]: 13 Jan 17:10:49 - [info] [xmpp out:XMPP transmit] Error: connect ECONNREFUSED HIDDEN IP:5222 17:10:49 node-red[190463]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1161:16) 17:10:49 node-red[190463]: 13 Jan 17:10:49 - [info] [xmpp-server:52fa80979f65b5c4] b5165f1cd028a58e sent a message to the xmpp server 17:10:49 node-red[190463]: 13 Jan 17:10:49 - [red] Uncaught Exception: 17:10:49 node-red[190463]: 13 Jan 17:10:49 - [error] TypeError: Cannot read properties of null (reading 'write') 17:10:49 node-red[190463]: at /home/node-red/.node-red/node_modules/node-red-node-xmpp/node_modules/@xmpp/connection/index.js:333:19 17:10:49 node-red[190463]: at new Promise () 17:10:49 node-red[190463]: at Client.write (/home/node-red/.node-red/node_modules/node-red-node-xmpp/node_modules/@xmpp/connection/index.js:325:12) 17:10:49 node-red[190463]: at Client.send (/home/node-red/.node-red/node_modules/node-red-node-xmpp/node_modules/@xmpp/connection/index.js:313:16) 17:10:49 node-red[190463]: at Client.send (/home/node-red/.node-red/node_modules/node-red-node-xmpp/node_modules/@xmpp/client-core/lib/Client.js:12:42) 17:10:49 node-red[190463]: at XmppOutNode._inputCallback (/home/node-red/.node-red/node_modules/node-red-node-xmpp/92-xmpp.js:766:26) 17:10:49 node-red[190463]: at /usr/lib/node_modules/node-red/node_modules/@node-red/runtime/lib/nodes/Node.js:204:26 17:10:49 node-red[190463]: at Object.trigg17:10:49 node-red[190463]: 13 Jan 17:10:49 - [error] TypeError: Cannot read properties of null (reading 'write') 17:10:49 node-red[190463]: at /home/node-red/.node-red/node_modules/node-red-node-xmpp/node_modules/@xmpp/connection/index.js:333:19 17:10:49 node-red[190463]: at new Promise () 17:10:49 node-red[190463]: at Client.write (/home/node-red/.node-red/node_modules/node-red-node-xmpp/node_modules/@xmpp/connection/index.js:325:12) 17:10:49 node-red[190463]: at Client.send (/home/node-red/.node-red/node_modules/node-red-node-xmpp/node_modules/@xmpp/connection/index.js:313:16) 17:10:49 node-red[190463]: at Client.send (/home/node-red/.node-red/node_modules/node-red-node-xmpp/node_modules/@xmpp/client-core/lib/Client.js:12:42) 17:10:49 node-red[190463]: at XmppOutNode._inputCallback (/home/node-red/.node-red/node_modules/node-red-node-xmpp/92-xmpp.js:766:26) 17:10:49 node-red[190463]: at /usr/lib/node_modules/node-red/node_modules/@node-red/runtime/lib/nodes/Node.js:204:26 17:10:49 node-red[190463]: at Object.trigger (/usr/lib/node_modules/node-red/node_modules/@node-red/util/lib/hooks.js:149:13) 17:10:49 node-red[190463]: at XmppOutNode.Node._emitInput (/usr/lib/node_modules/node-red/node_modules/@node-red/runtime/lib/nodes/Node.js:196:11) 17:10:49 node-red[190463]: at XmppOutNode.Node.emit (/usr/lib/node_modules/node-red/node_modules/@node-red/runtime/lib/nodes/Node.js:180:25) 17:10:49 systemd[1]: node-red.service: Main process exited, code=exited, status=1/FAILURE

This is not always reproducible, sometimes it keeps spitting out the ECONNREFUSED at an incredible rate, which freezes Node-RED almost to a halt.

BeaverUI commented 2 years ago

One thing I notice regarding reconnection, is that the default reconnect period is 1 second, while the connection timeout of the node is 60 seconds. This might cause at least part of the issues.

The reconnect timeout can be set in packages/reconnect (see https://github.com/xmppjs/xmpp.js/tree/main/packages/reconnect). The connection timeout is hardcoded in the node source code (while I don't know whether this value is actually supported, since I can't find it in the declarations of xmmpjs). I couldn't get a higher reconnect timeout to work by myself yet, though, it remains hammering the reconnect attempts.

lu4t commented 2 years ago

xmpp node is crashing node-red I got this on the logs:

"Unknown error: StreamError: policy-violation - Too many unacked stanzas"

21 Aug 11:47:56 - [error] [xmpp in:7fef6170bdaf5d29] Unknown error: StreamError: policy-violation - Too many unacked stanzas 21 Aug 11:47:56 - [error] [xmpp out:39d00c59f7cace81] Unknown error: StreamError: policy-violation - Too many unacked stanzas 21 Aug 11:47:56 - [error] [xmpp out:39d00c59f7cace81] Unknown error: StreamError: policy-violation - Too many unacked stanzas 21 Aug 11:47:56 - [error] [xmpp in:7fef6170bdaf5d29] Unknown error: StreamError: policy-violation - Too many unacked stanzas 21 Aug 11:47:57 - [red] Uncaught Exception: 21 Aug 11:47:57 - [error] Error: write ECONNRESET at WriteWrap.onWriteComplete [as oncomplete] (node:internal/stream_base_commons:98:16)

After this the system crashes (running on docker).

lu4t commented 2 years ago

I believe this started to happen right after a debug node was connected to the second output of a xmpp-in node.

This is a second crash error, just in case it brings more light:

21 Aug 11:57:03 - [error] [xmpp in:7fef6170bdaf5d29] Unknown error: StreamError: policy-violation - Too many unacked stanzas 21 Aug 11:57:03 - [error] [xmpp out:39d00c59f7cace81] Unknown error: StreamError: policy-violation - Too many unacked stanzas 21 Aug 11:57:03 - [error] [xmpp in:7fef6170bdaf5d29] Unknown error: StreamError: policy-violation - Too many unacked stanzas 21 Aug 11:57:04 - [red] Uncaught Exception: 21 Aug 11:57:04 - [error] Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed at new NodeError (node:internal/errors:371:5) at errorBuffer (node:internal/streams/writable:517:14) at afterWrite (node:internal/streams/writable:501:5) at onwrite (node:internal/streams/writable:477:7) at WriteWrap.onWriteComplete [as oncomplete] (node:internal/stream_base_commons:91:12)

dceejay commented 2 years ago

Do you know how your server is configured as that error is due to a limit being exceeded on the server - eg see https://github.com/processone/ejabberd/issues/2615

lu4t commented 2 years ago

No details on the xmpp server side, as it's a public server (at jabber.org). I saw the thread you added before posting the node-red crash here and guessed that's the root cause, but I raised the issue cause node-red will enter in a crash loop if the xmpp node is installed and is set to get connected to a server with this config. The weird thing is this happened after 24 hours, when I did some changes on the config of the node; so I guessed the stanza missconfig on the server is affecting the node-red xmpp client only sometimes.

dceejay commented 2 years ago

can you paste the complete error stack ? and which version of the xmpp node are you using ? Thanks

lu4t commented 2 years ago

xmpp node version 0.6.0

unfortunatelly I cannot get more logs than the ones I posted before, everytime I re-enable the xmpp node enabled, node-red crashes.

These are the lines I got on the last test some minutes ago, logs start when I click on "Deploy" after enabling the nodes:

24 Aug 14:38:42 - [info] Starting modified flows 24 Aug 14:38:42 - [info] Started modified flows 24 Aug 14:38:44 - [error] [xmpp in:7fef6170bdaf5d29] Unknown error: StreamError: policy-violation - Too many unacked stanzas 24 Aug 14:38:44 - [error] [xmpp out:39d00c59f7cace81] Unknown error: StreamError: policy-violation - Too many unacked stanzas 24 Aug 14:38:44 - [error] [xmpp in:7fef6170bdaf5d29] Unknown error: StreamError: policy-violation - Too many unacked stanzas 24 Aug 14:38:44 - [error] [xmpp in:7fef6170bdaf5d29] Unknown error: StreamError: policy-violation - Too many unacked stanzas 24 Aug 14:38:45 - [red] Uncaught Exception: 24 Aug 14:38:45 - [error] Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed at new NodeError (node:internal/errors:371:5) at errorBuffer (node:internal/streams/writable:517:14) at afterWrite (node:internal/streams/writable:501:5) at onwrite (node:internal/streams/writable:477:7) at WriteWrap.onWriteComplete [as oncomplete] (node:internal/stream_base_commons:91:12)

after this, node-red enters into an endless crash loop (on docker).

dceejay commented 2 years ago

OK - hmm - we have event handlers in place for the xmpp object .on("error"... so not sure why it isn't catching them unless the underlying library isn't calling it correctly.

christf commented 2 months ago

I am getting crashes of node-red due to xmpp as well. For me the symptom is

5 Aug 23:31:00 - [error] TypeError: Cannot read properties of null (reading 'write')
    at /data/node_modules/node-red-node-xmpp/node_modules/@xmpp/connection/index.js:333:19
    at new Promise (<anonymous>)
    at Client.write (/data/node_modules/node-red-node-xmpp/node_modules/@xmpp/connection/index.js:325:12)
    at Client.send (/data/node_modules/node-red-node-xmpp/node_modules/@xmpp/connection/index.js:313:16)
    at Client.send (/data/node_modules/node-red-node-xmpp/node_modules/@xmpp/client-core/lib/Client.js:12:42)
    at XmppOutNode._inputCallback (/data/node_modules/node-red-node-xmpp/92-xmpp.js:846:30)
    at /usr/src/node-red/node_modules/@node-red/runtime/lib/nodes/Node.js:214:26
    at Object.trigger (/usr/src/node-red/node_modules/@node-red/util/lib/hooks.js:166:13)
    at XmppOutNode.Node._emitInput (/usr/src/node-red/node_modules/@node-red/runtime/lib/nodes/Node.js:206:11)
    at XmppOutNode.Node.emit (/usr/src/node-red/node_modules/@node-red/runtime/lib/nodes/Node.js:190:25)

At this point I cannot be sure if it is exactly the same thing. It does happen during startup though, and it seems to be a race on initializing xmpp before the first message is meant to be sent.

Also, what is the recovery process? If a flow is causing crashes it is not possible to change the flow to avoid the symptom because the server is not up.

Edit: nevermind. I manually edited the flow using a texteditor.

dceejay commented 2 months ago

Hi, would be helpful if you could try adding some debug for me please. Find 92-xmpp.js file in your .node-red/node_modules/node-red-node-xmpp directory Edit it and add a line of debug log after line 765

        node.on("input", function(msg) {
            node.log("XMPP Status "+xmpp.status)
            var to = ....

Then restart Node-RED... It should output the state of the xmpp connection every time a message is sent so we can prove if it's a startup timing issue.

Then the question is what to do about it. In general most nodes that do this sort of thing will raise an error rather than try to queue any messages as there is no guarantee that the connection will ever come good and any queue could then blow up.

christf commented 2 months ago

sure thing, thank you for your help!

this is the output:

6 Aug 19:07:57 - [info] [ssh-v3:RaspberryPi3] Ssh client ready
6 Aug 19:07:57 - [info] [xmpp out:56f4a48f98cf87b6] XMPP Status disconnect
6 Aug 19:07:57 - [red] Uncaught Exception:
6 Aug 19:07:57 - [error] TypeError: Cannot read properties of null (reading 'write')
    at /data/node_modules/node-red-node-xmpp/node_modules/@xmpp/connection/index.js:333:19
    at new Promise (<anonymous>)
    at Client.write (/data/node_modules/node-red-node-xmpp/node_modules/@xmpp/connection/index.js:325:12)
    at Client.send (/data/node_modules/node-red-node-xmpp/node_modules/@xmpp/connection/index.js:313:16)
    at Client.send (/data/node_modules/node-red-node-xmpp/node_modules/@xmpp/client-core/lib/Client.js:12:42)
    at XmppOutNode._inputCallback (/data/node_modules/node-red-node-xmpp/92-xmpp.js:847:30)
    at /usr/src/node-red/node_modules/@node-red/runtime/lib/nodes/Node.js:214:26
    at Object.trigger (/usr/src/node-red/node_modules/@node-red/util/lib/hooks.js:166:13)
    at XmppOutNode.Node._emitInput (/usr/src/node-red/node_modules/@node-red/runtime/lib/nodes/Node.js:206:11)
    at XmppOutNode.Node.emit (/usr/src/node-red/node_modules/@node-red/runtime/lib/nodes/Node.js:190:25)

a bit above, I can see:

6 Aug 19:07:57 - [info] [xmpp out:56f4a48f98cf87b6] XMPP Status open
6 Aug 19:07:57 - [info] [mqtt-broker:70a785b74df8a48d] Connected to broker: nodeRed@mqtt://mq.xxxx.com:1883
6 Aug 19:07:57 - [error] [xmpp out:56f4a48f98cf87b6] Unknown error: Error: 140073524054832:error:1409442E:SSL routines:ssl3_read_bytes:tlsv1 alert protocol version:../deps/openssl/openssl/ssl/record/rec_layer_s3.c:1564:SSL alert number 70

6 Aug 19:07:57 - [error] [xmpp out:56f4a48f98cf87b6] Bad xmpp configuration; service: xmpp://xmpp.xxxx.com:5222 jid: yyy@xxxx.com
6 Aug 19:07:57 - [warn] [xmpp out:56f4a48f98cf87b6] Error: 140073524054832:error:1409442E:SSL routines:ssl3_read_bytes:tlsv1 alert protocol version:../deps/openssl/openssl/ssl/record/rec_layer_s3.c:1564:SSL alert number 70

6 Aug 19:07:57 - [warn] [xmpp out:56f4a48f98cf87b6] Error: 140073524054832:error:1409442E:SSL routines:ssl3_read_bytes:tlsv1 alert protocol version:../deps/openssl/openssl/ssl/record/rec_layer_s3.c:1564:SSL alert number 70

6 Aug 19:07:57 - [warn] ..... (other unrelated debug info from my function-nodes)

maybe that is related. It is odd though because most of the time, this just works. And neither of the following applications complains:

conversations
profanity
yaxim

Then the question is what to do about it. In general most nodes that do this sort of thing will raise an error rather than try to queue any messages as there is no guarantee that the connection will ever come good and any queue could then blow up.

I'd say: first things first: Let's find a way this crash does not occur. Once there, we can still consider the tricky cases on whether messages should get queued or not. For now, I think logging an error and discarding the message is fine.

dceejay commented 2 months ago

Error 70 seems to be associated with something trying to use an old unsupported cipher eg TLS1.1 - but if that is the case I'm not sure why it would work sometimes for you and sometimes not.

What is the status reported if you do manage to send successfully ? is it "connected" rather than just "open" or "disconnect" ?

christf commented 2 months ago

It is indeed "connected"

node-red / node-red-nodes