search

Skylar-Tech / node-red-contrib-matrix-chat

Matrix chat server support for Node-RED
GNU General Public License v3.0
31 stars 10 forks source link

NodeRed Getting Multiple Repeated Messages From Nodes #36

Open Ryonez opened 2 years ago

Ryonez commented 2 years ago

This is an odd one.

It seems that nodes will duplicate messages, and that can snowball down the line.

I'm looking at one message getting 4 triggers on a Receive node then 9 from the Room User List it's linked to.

It's not wholly consistent either.

Trigger messages (and response to the one set to respond): image

The Flows: image

Flow Code:

```json [ { "id": "af9a42c4da8726ea", "type": "matrix-receive", "z": "60339a6fa3ae56a7", "name": "Ping", "server": "", "roomId": "", "acceptText": true, "acceptEmotes": true, "acceptStickers": true, "acceptReactions": true, "acceptFiles": true, "acceptImages": true, "x": 100, "y": 1012, "wires": [ [ "e4b73d13036940f6" ] ] }, { "id": "d083f1b20f40f726", "type": "matrix-receive", "z": "60339a6fa3ae56a7", "name": "Other Testing", "server": "", "roomId": "", "acceptText": true, "acceptEmotes": true, "acceptStickers": true, "acceptReactions": true, "acceptFiles": true, "acceptImages": true, "x": 109.5, "y": 811, "wires": [ [ "606970b0770ab888", "7502f29121a84165" ] ] }, { "id": "606970b0770ab888", "type": "switch", "z": "60339a6fa3ae56a7", "name": "Command Function", "property": "payload", "propertyType": "msg", "rules": [ { "t": "eq", "v": "s-users", "vt": "str" }, { "t": "eq", "v": "r-users", "vt": "str" } ], "checkall": "true", "repair": false, "outputs": 2, "x": 296.5, "y": 811, "wires": [ [ "b4dfcb88a9bd1a61" ], [ "4a22dfa44a915d68", "50ce404dd5d819ae" ] ] }, { "id": "b4dfcb88a9bd1a61", "type": "matrix-synapse-users", "z": "60339a6fa3ae56a7", "name": "", "server": "", "x": 570.5, "y": 775, "wires": [ [ "5be3f7b22cbab39e", "2e795181cbdd92a9" ], [] ] }, { "id": "a2bf7ff592d05ce1", "type": "matrix-send-message", "z": "60339a6fa3ae56a7", "name": "Send HTML Notice", "server": "", "roomId": "", "messageType": "m.notice", "messageFormat": "html", "x": 952.5, "y": 806, "wires": [ [], [] ] }, { "id": "5be3f7b22cbab39e", "type": "function", "z": "60339a6fa3ae56a7", "name": "", "func": "let new_payload = '

    ';\nmsg.payload.users.forEach(function(user, index){\n new_payload += '
  • '+ JSON.stringify(user, null, 2).replace(/(?:\\r\\n|\\r|\\n)/g, \"\\n
    \"); + '
    • '\n});\nmsg.payload = new_payload + '
';\n\nreturn msg;", "outputs": 1, "noerr": 0, "initialize": "", "finalize": "", "libs": [], "x": 829.5, "y": 754, "wires": [ [ "a2bf7ff592d05ce1" ] ] }, { "id": "f813ce2610c98750", "type": "comment", "z": "60339a6fa3ae56a7", "name": "Response to \"s-users\" with full server user list", "info": "", "x": 557.5, "y": 720, "wires": [] }, { "id": "0c27f5356d7e856b", "type": "comment", "z": "60339a6fa3ae56a7", "name": "Response to \"r-users\" with room user list", "info": "", "x": 569.5, "y": 893, "wires": [] }, { "id": "4a22dfa44a915d68", "type": "matrix-room-users", "z": "60339a6fa3ae56a7", "name": "", "server": "", "roomId": "", "x": 558, "y": 834, "wires": [ [ "2e795181cbdd92a9" ], [] ] }, { "id": "e4b73d13036940f6", "type": "switch", "z": "60339a6fa3ae56a7", "name": "msg.payload == \"ping\"", "property": "payload", "propertyType": "msg", "rules": [ { "t": "eq", "v": "ping", "vt": "str" } ], "checkall": "true", "repair": false, "outputs": 1, "x": 325.5, "y": 1020, "wires": [ [ "4214bb4d742d8d5b" ] ] }, { "id": "7940da0c776d33dc", "type": "matrix-send-message", "z": "60339a6fa3ae56a7", "name": "", "server": "", "roomId": "", "messageType": "m.text", "messageFormat": "", "x": 725, "y": 1015, "wires": [ [], [] ] }, { "id": "4214bb4d742d8d5b", "type": "function", "z": "60339a6fa3ae56a7", "name": "", "func": "msg.payload = \"pong\"\nreturn msg;", "outputs": 1, "noerr": 0, "initialize": "", "finalize": "", "libs": [], "x": 535, "y": 1013, "wires": [ [ "78d47c18f303939e", "7940da0c776d33dc" ] ] }, { "id": "78d47c18f303939e", "type": "debug", "z": "60339a6fa3ae56a7", "name": "", "active": true, "tosidebar": true, "console": false, "tostatus": false, "complete": "true", "targetType": "full", "statusVal": "", "statusType": "auto", "x": 684, "y": 1103, "wires": [] }, { "id": "2e795181cbdd92a9", "type": "debug", "z": "60339a6fa3ae56a7", "name": "", "active": true, "tosidebar": true, "console": false, "tostatus": false, "complete": "true", "targetType": "full", "statusVal": "", "statusType": "auto", "x": 853, "y": 876, "wires": [] }, { "id": "7502f29121a84165", "type": "debug", "z": "60339a6fa3ae56a7", "name": "", "active": true, "tosidebar": true, "console": false, "tostatus": false, "complete": "true", "targetType": "full", "statusVal": "", "statusType": "auto", "x": 159, "y": 912, "wires": [] }, { "id": "50ce404dd5d819ae", "type": "debug", "z": "60339a6fa3ae56a7", "name": "", "active": false, "tosidebar": true, "console": false, "tostatus": false, "complete": "true", "targetType": "full", "statusVal": "", "statusType": "auto", "x": 475, "y": 941, "wires": [] } ] ```

The debug log for these three debug nodes (The log was cleared for this test, note the scrollbar): image

skylord123 commented 2 years ago

I was able to replicate the issue finally. I got a new release coming out today that should fix this. Thanks for the input!

skylord123 commented 2 years ago

Just released 0.3.0 that fixes this problem. I will close this for now, if you still have the problem feel free to re-open the issue.

Ryonez commented 2 years ago

@skylord123 It's not normally possible for users to reopen issues. I cannot in this case for example. I'd like to suggest that issues are left open to give some time to get feedback on if it's actually been resolved.

In this case it seems not to have been sadly, It's seeing a message more than once, and I'm still getting multiple responses.

image

image

Edit: Just confirming, I did update the Palette: image

skylord123 commented 2 years ago

@Ryonez Can you do another test and paste the log output here? I'm wondering if they are duplicating in the log as well.

Ryonez commented 2 years ago

Yup, they are dupped in the logs to.

Relevent Logs:

``` setting pendingEvent status to sending in !BCwBSIvaRXQCucvPCQ:alteria.xyz event ID ~!BCwBSIvaRXQCucvPCQ:alteria.xyz:m1643399173986.6 -> undefined setting pendingEvent status to queued in !BCwBSIvaRXQCucvPCQ:alteria.xyz event ID ~!BCwBSIvaRXQCucvPCQ:alteria.xyz:m1643399173986.6 -> undefined Event sent to !BCwBSIvaRXQCucvPCQ:alteria.xyz with event id $svZ9mch58RR9nlU7irl3IsBxnTnKO6DfyxZYI8lo2H4 setting pendingEvent status to sent in !BCwBSIvaRXQCucvPCQ:alteria.xyz event ID ~!BCwBSIvaRXQCucvPCQ:alteria.xyz:m1643399173954.4 -> $svZ9mch58RR9nlU7irl3IsBxnTnKO6DfyxZYI8lo2H4 setting pendingEvent status to sending in !BCwBSIvaRXQCucvPCQ:alteria.xyz event ID ~!BCwBSIvaRXQCucvPCQ:alteria.xyz:m1643399173971.5 -> undefined 29 Jan 08:46:14 - [info] [matrix-send-message:34aced6aba4130b4] Message sent: pong Got remote echo for event $svZ9mch58RR9nlU7irl3IsBxnTnKO6DfyxZYI8lo2H4 -> $svZ9mch58RR9nlU7irl3IsBxnTnKO6DfyxZYI8lo2H4 old status sent 29 Jan 08:46:14 - [info] [matrix-server-config:nodered-matrix] Received encrypted timeline event [m.text]: (Other Testing) @yoko:alteria.xyz :: pong [LIVE] Event sent to !BCwBSIvaRXQCucvPCQ:alteria.xyz with event id $7qWRFC2vGuK1gbfpI6sSRs4gUnx-ZNM9baCZOR85lko setting pendingEvent status to sent in !BCwBSIvaRXQCucvPCQ:alteria.xyz event ID ~!BCwBSIvaRXQCucvPCQ:alteria.xyz:m1643399173971.5 -> $7qWRFC2vGuK1gbfpI6sSRs4gUnx-ZNM9baCZOR85lko setting pendingEvent status to sending in !BCwBSIvaRXQCucvPCQ:alteria.xyz event ID ~!BCwBSIvaRXQCucvPCQ:alteria.xyz:m1643399173986.6 -> undefined 29 Jan 08:46:14 - [info] [matrix-send-message:34aced6aba4130b4] Message sent: pong Got remote echo for event $7qWRFC2vGuK1gbfpI6sSRs4gUnx-ZNM9baCZOR85lko -> $7qWRFC2vGuK1gbfpI6sSRs4gUnx-ZNM9baCZOR85lko old status sent 29 Jan 08:46:14 - [info] [matrix-server-config:nodered-matrix] Received encrypted timeline event [m.text]: (Other Testing) @yoko:alteria.xyz :: pong [LIVE] Event sent to !BCwBSIvaRXQCucvPCQ:alteria.xyz with event id $A8Fxr6vp5m9RPaTvFYzqe6ACwtWGeT5S05lKxKgYS8E setting pendingEvent status to sent in !BCwBSIvaRXQCucvPCQ:alteria.xyz event ID ~!BCwBSIvaRXQCucvPCQ:alteria.xyz:m1643399173986.6 -> $A8Fxr6vp5m9RPaTvFYzqe6ACwtWGeT5S05lKxKgYS8E 29 Jan 08:46:14 - [info] [matrix-send-message:34aced6aba4130b4] Message sent: pong Got remote echo for event $A8Fxr6vp5m9RPaTvFYzqe6ACwtWGeT5S05lKxKgYS8E -> $A8Fxr6vp5m9RPaTvFYzqe6ACwtWGeT5S05lKxKgYS8E old status sent 29 Jan 08:46:14 - [info] [matrix-server-config:nodered-matrix] Received encrypted timeline event [m.text]: (Other Testing) @yoko:alteria.xyz :: pong [LIVE] ```

hillbicks commented 2 years ago

I can report the same thing. As a workaround, I'm using the delay node before the sending with action set to rate limit. This way I can limit the notifications to 1 message per 5 seconds for example.

skylord123 commented 2 years ago

@hillbicks @Ryonez Can you both give me the following details to help diagnose this:

I haven't had much success in replicating this issue so I hope the above fixes that.

Thanks :)

Ryonez commented 2 years ago
  • What operating system are you running Node-RED on?

unRaid 6.9.2

  • How did you install Node-RED (in Docker, using apt, manually with NPM, etc)?

Docker

  • What other modules have you installed in Node-RED?
    "@kuehnelbs/node-red-contrib-nextcloud": "~0.1.3",
    "@node-red-contrib-themes/midnight-red": "^1.4.7",
    "json-db-node-red": "~0.5.3",
    "node-red-contrib-basicauth": "~1.0.4",
    "node-red-contrib-bigssh": "~1.2.7",
    "node-red-contrib-discord-advanced": "~3.1.1",
    "node-red-contrib-google": "~0.2.0",
    "node-red-contrib-image-tools": "~2.0.2",
    "node-red-contrib-influxdb": "~0.6.1",
    "node-red-contrib-matrix-chat": "~0.3.0",
    "node-red-contrib-otpauth": "0.0.2",
    "node-red-contrib-plex-ws": "~0.2.4",
    "node-red-contrib-postgres-multi": "~0.2.0",
    "node-red-contrib-spotify": "~0.1.4",
    "node-red-contrib-telegrambot": "~11.2.0",
    "node-red-contrib-twitter-stream": "~1.5.0",
    "node-red-contrib-ui-media": "~1.2.0",
    "node-red-contrib-uibuilder": "~4.1.4",
    "node-red-contrib-uuid": "0.0.4",
    "node-red-dashboard": "~3.1.5",
    "node-red-node-email": "~1.14.0",
    "node-red-node-mongodb": "~0.2.5",
    "node-red-node-mysql": "~1.0.0",
    "node-red-node-rbe": "~0.5.0",
    "node-red-node-sentiment": "~0.1.6",
    "node-red-node-tail": "~0.3.2",
    "passport-keycloak-oauth2-oidc": "^1.0.5"
  • What Matrix server are you using? (if this is self hosted you can just say that but if it's a public server list which server)

alteria.xyz Homeserver located at matrix.alteria.xyz

  • If you self-host list which version of Synapse you are using

matrixdotorg/synapse:latest Current hash: sha256:1776cc2e846d208d62206e81936a10c07f3fdb43c7262b28090dfc0e3bb4d4a9

  • What version is your Node-RED instance?

Node-RED v2.2.0 nodered/node-red:latest-16 Current hash: sha256:28baf510bc5e9ff0e29e34892aa7423a59b29050d8946ffc6e4be354827accab

  • Does this happen in both encrypted and non-encrypted rooms?

Both

Also, it seems to take a bit to trigger at times. When testing today, moving nodes and deploying the flow wasn't enough. I had to disable a debug node, save, reenable it, save again, then the messages started repeating. I normally have this flow disabled atm, and nodered has been restarted since I last looked at this. The flow starts of fine, but as changes are made it starts having the problems.

hillbicks commented 2 years ago

@hillbicks @Ryonez Can you both give me the following details to help diagnose this:

* What operating system are you running Node-RED on?

arch x64

* How did you install Node-RED (in Docker, using apt, manually with NPM, etc)?

installed via npm, current version 2.2

* What other modules have you installed in Node-RED?
google-translate-tts
0.2.1
node-red
2.2.0
node-red-contrib-aftership
0.1.2
node-red-contrib-boolean-logic-ultimate
1.0.39
node-red-contrib-deconz
2.2.1
node-red-contrib-deepstack
0.2.1
node-red-contrib-home-assistant-websocket
0.41.3
node-red-contrib-ical-events
2.1.1
node-red-contrib-image-tools
2.0.2
node-red-contrib-jsonpath
0.1.1
node-red-contrib-light-scheduler
0.0.18
node-red-contrib-looptimer
0.0.8
node-red-contrib-matrix-chat
0.4.6
node-red-contrib-md5file
1.0.0
node-red-contrib-mpd
1.3.0
node-red-contrib-proxmox
0.0.2
node-red-contrib-simple-message-queue
0.2.8
node-red-contrib-spotify
0.1.4
node-red-contrib-sun-position
2.0.6
node-red-contrib-sunevents
3.0.3
node-red-contrib-tasmota
0.9.9
node-red-contrib-telegrambot
11.2.0
node-red-contrib-time-range-switch
1.1.2
node-red-contrib-unifi
0.1.17
node-red-contrib-weekday
0.1.0
node-red-dashboard
3.1.3
node-red-node-base64
0.3.0
node-red-node-xmpp
* What Matrix server are you using? (if this is self hosted you can just say that but if it's a public server list which server)

synapse 1.50.2-1

* If you self-host list which version of Synapse you are using

synapse 1.50.2-1

* What version is your Node-RED instance?

2.2.0

* Does this happen in both encrypted and non-encrypted rooms?

While trying to provide a bit more details I wanted to ensure, that the problem does not come from a different node, so here is a simple test that I did. Matrix receiving node-> debug node with complete msg object. The receiving node listens to a specific room and only on M.text. Send a command in that chat and I'll get 6 debug messages. Sometimes 7. Sometimes 8. All identical, down to the server_ts and message_id.

To debug further, I tried to test it with an encrypted and unencrypted room. For some reason, I can't get the receiving node to listen to an encrypted room. But I can reproduce the issue with an unencrypted room. And it seems to me, the amount of messages the receiving node outputs, increases over time. 

10/02/2022, 13:35:47node: after matrix receive
!wSMFZQdbJOIBYHetIQ:XXXXX.XXX : msg : Object
object
encrypted: false
redacted: false
content: object
msgtype: "m.text"
body: "Vghj"
type: "m.text"
payload: "Vghj"
userId: "@hillbicks:XXXXX.XXX"
topic: "!wSMFZQdbJOIBYHetIQ:XXXXX.XXX"
eventId: "$NrHZg6o6AVQ-dtjmw9UsGJg80ONQgWigvHyvFLrSPyE"
event: object
type: "m.room.message"
sender: "@hillbicks:XXXXX.XXX"
content: object
msgtype: "m.text"
body: "Vghj"
origin_server_ts: 1644496546922
unsigned: object
age: 41
event_id: "$NrHZg6o6AVQ-dtjmw9UsGJg80ONQgWigvHyvFLrSPyE"
room_id: "!wSMFZQdbJOIBYHetIQ:XXXXX.XXX"
_msgid: "3b295d170b287ad8"

I then put a home assistant node in front of it, that outputs when my desk lamp changes states. Put it into the same debug node and I only get one notification per state change. If I add a send message Matrix node to that flow, I only get one message. So I'm pretty sure it is not the sending site, but rather the receiving one that is outputting several messages which then leads the send node to, well, send several messages.

I haven't had much success in replicating this issue so I hope the above fixes that.

Thanks :)

If you need further information from my side, just let me know. Happy to help.

skylord123 commented 2 years ago

If you need further information from my side, just let me know. Happy to help.

Can you start Node-RED, reproduce the issue, then send me the full log? You can send it over matrix to @skylord123:skylar.tech or to my email me@skylar.tech

@Ryonez can you do the same? Your log output above is missing the part where it shows the ping message coming in. It's also possible that during initializing the node is throwing an error so the full log would be helpful.

Before doing the test I would set logging to debug in your settings.js file. Information about how to do this can be found here: https://nodered.org/docs/user-guide/runtime/logging

At first I thought it may have been another module causing the problem. I know that nodered-contrib-signal-client currently uses an old version of proxy-agent that causes problems (I opened an issue here that describes that problem). I don't think another package is causing the problem in this case though. @Ryonez It may be good for you to try spinning up a second node-red container and only installing node-red-contrib-matrix-chat and see if the problem still happens (just as a sanity check so we can rule out other packages being the culprit and since you run in Docker it is super easy to spin up another instance).

Thanks!

hillbicks commented 2 years ago

I.......ehm, should've looked at the logfile earlier it seems. 1.1GB in size :p

I just saw a ton of errors in the logfile about errors uploading keys and broken secure channels. The thing is, I'm pretty sure I only changed the server names in node-red after I reinstalled synapse.

So, let me clear that up first, I'll probably delete the complete matrix configuration again and set it up from scratch, I only have a couple of nodes at the moment. I'll let you know once I've done that.

Sorry, should've checked that earlier!

hillbicks commented 2 years ago

So, after a lot of cleaning up (and one new minor issue that I discovered and reported (#46), I wanted to dig into this again. I deleted the pm2 logfile, restarted nodered.....and I can't reproduce it anymore. I also removed some palettes that I wasn't using anymore and currently this issue is gone.

I'll try again later and give some feedback, just to let you know I haven't forgotten about this ;)

skylord123 commented 2 years ago

@hillbicks which modules did you remove? It's entirely possible one of those was causing the problem.You can view the list you had above before you removed them for reference.

hillbicks commented 2 years ago

node-red-contrib-image-tools node-red-contrib-mpd node-red-node-xmpp

I removed these 3.

I also added a node that responds to any message with a pong, so far it is sending only one pong.

hillbicks commented 2 years ago

@Ryonez Do you still experience this problem? Since my last report I never had another duplicate message. Not sure what the issue exactly was on my side, I also updated synapse as well as removing the the aforementioned addons from node red.

So it seems to solved, at least for me.

Ryonez commented 2 years ago

Sorry, I still haven't had the chance to go over these yet.

Ryonez commented 2 years ago

Alright, set up another node red instance. This one doesn't have issues with multiple pings, even if I install node-red-contrib-image-tools.

That package though is used in my main nodered instance, removal isn't really an option, and I'm not convinced it's an issue as I can't replicate the issue in the new instance of nodered.

I don't have logs ready atm, I don't quite have the energy to go through them right now.

Merikei commented 1 year ago

Think I'm having the same issue

It happens when I modify a sequence containing a receive node and then 'deploy modified flows'. My assumption is that this keeps the old connection to whatever receives messages in Node Red on the backend AND creates a new connection. The Matrix nodes in the modified sequence displays a node status of 'disconnected' while unmodified sequences say connected. (It isn't actually disconnected.) It happens some times and not others so it may be more complex than just modifying the sequence in any way.

Doing a 'deploy full' avoids the issue or fixes it but is itself a problem because it stops everything.

Thanks for this project by the way! :smiley:

Edit: assumption updated based on my newer comment

Merikei commented 1 year ago

Messing around with enabling and disabling a receive node and connected debug node and 'deploy modified flows'. It's now outputting messages several times while other receive nodes are only outputting the same message once.

skylord123 commented 1 year ago

Messing around with enabling and disabling a receive node and connected debug node and 'deploy modified flows'. It's now outputting messages several times while other receive nodes are only outputting the same message once.

Can you check the time on the device you are running Node-RED on? Every time nodes are deployed or NR starts we save the initialized time and only send out messages that are newer than that. If the time on the device is incorrect (even off by some seconds) this could cause messages to reappear since it thinks they are new.

That would only happen on deploy/starting NR though and wouldn't duplicate messages after that. If you have messages being duplicated when not deploying/starting NR there is a good chance that another module you have installed is messing with the requests and I would try spinning up another NR instance without any other modules but this one installed and see if you can still replicate it. I've had to open issues on other NR module that have caused issues like this.