node-red-nodes icon indicating copy to clipboard operation
node-red-nodes copied to clipboard

node-red-node-xmpp crash

Open BeaverUI opened this issue 2 years ago • 10 comments

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

BeaverUI avatar Jan 13 '22 18:01 BeaverUI

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

hardillb avatar Jan 13 '22 19:01 hardillb

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 avatar Jan 14 '22 09:01 BeaverUI

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.

BeaverUI avatar Jan 14 '22 09:01 BeaverUI

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 avatar Aug 21 '22 11:08 lu4t

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)

lu4t avatar Aug 21 '22 12:08 lu4t

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

dceejay avatar Aug 23 '22 14:08 dceejay

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.

lu4t avatar Aug 24 '22 08:08 lu4t

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

dceejay avatar Aug 24 '22 10:08 dceejay

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).

lu4t avatar Aug 24 '22 14:08 lu4t

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.

dceejay avatar Aug 24 '22 14:08 dceejay