Weird issue with node-red-contrib-queue-gate

General
1

I have a very weird issue with node-red-contrib-queue-gate, in combination with node-red-contrib-simple-gate, which is either a very subtle bug or (just as likely) I am missing something simple. I am including the flow that shows the problem. Sorry it is a little complex but I haven't managed to replicate it with a simpler flow. I have added debug nodes showing what is going into the q-gate and what is coming out. To trigger it hit the test inject button at the top and wait a few seconds. This is what the debug shows.

image
image594Ă—534 43.9 KB

You can see that first a test message is sent into the q-gate node, which queues it, then the flow sends a peek which releases that message. A few seconds later another peek is sent but this time the message that is released has payload "close" and topic "gate_control", but the q-gate node has not been sent any such message. Messages containing that are actually sent into the simple-gate node so I wonder whether there may be some cross coupling between them.

image
image839Ă—468 60.9 KB

[{"id":"e11111db.2371a8","type":"inject","z":"559d36b1.8777a8","name":"test ","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"Test message from tigger","payload":"Test message 1","payloadType":"str","x":130,"y":100,"wires":[["dc8d8fcf.8609d"]]},{"id":"92ac67a3.22c908","type":"gate","z":"559d36b1.8777a8","name":"","controlTopic":"gate_control","defaultState":"open","openCmd":"open","closeCmd":"close","toggleCmd":"toggle","defaultCmd":"default","persist":false,"x":610,"y":340,"wires":[["b3d4b11f.4590e"]]},{"id":"7070c19f.6e9458","type":"change","z":"559d36b1.8777a8","name":"Close gate","rules":[{"t":"set","p":"topic","pt":"msg","to":"gate_control","tot":"str"},{"t":"set","p":"payload","pt":"msg","to":"close","tot":"str"}],"action":"","property":"","from":"","to":"","reg":false,"x":450,"y":300,"wires":[["92ac67a3.22c908"]]},{"id":"eb4bce63.33221","type":"change","z":"559d36b1.8777a8","name":"Open gate","rules":[{"t":"set","p":"topic","pt":"msg","to":"gate_control","tot":"str"},{"t":"set","p":"payload","pt":"msg","to":"open","tot":"str"}],"action":"","property":"","from":"","to":"","reg":false,"x":360,"y":440,"wires":[["92ac67a3.22c908"]]},{"id":"9d581c6e.04601","type":"link out","z":"559d36b1.8777a8","name":"","links":["4f83e1dc.d434d8"],"x":615,"y":200,"wires":[]},{"id":"4f83e1dc.d434d8","type":"link in","z":"559d36b1.8777a8","name":"","links":["a4112796.e7ebb8","9d581c6e.04601"],"x":55,"y":440,"wires":[["f9f1c824.1b4d58"]]},{"id":"7a077cad.8dcab4","type":"change","z":"559d36b1.8777a8","name":"","rules":[{"t":"set","p":"payload","pt":"msg","to":"peek","tot":"str"},{"t":"set","p":"topic","pt":"msg","to":"control","tot":"str"}],"action":"","property":"","from":"","to":"","reg":false,"x":400,"y":340,"wires":[["92ac67a3.22c908"]]},{"id":"dc8d8fcf.8609d","type":"link out","z":"559d36b1.8777a8","name":"","links":["376153ca.1cd5cc"],"x":275,"y":100,"wires":[]},{"id":"aa64620.a132da","type":"debug","z":"559d36b1.8777a8","name":"OUT","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","statusVal":"","statusType":"auto","x":530,"y":120,"wires":[]},{"id":"58decb0a.1a91e4","type":"debug","z":"559d36b1.8777a8","name":"IN","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","statusVal":"","statusType":"auto","x":520,"y":80,"wires":[]},{"id":"87f9c1f7.69612","type":"q-gate","z":"559d36b1.8777a8","name":"q-gate","controlTopic":"control","defaultState":"queueing","openCmd":"open","closeCmd":"close","toggleCmd":"toggle","queueCmd":"queue","defaultCmd":"default","triggerCmd":"trigger","flushCmd":"flush","resetCmd":"reset","peekCmd":"peek","dropCmd":"drop","statusCmd":"status","maxQueueLength":"100","keepNewest":false,"qToggle":false,"persist":false,"x":450,"y":220,"wires":[["7070c19f.6e9458","aa64620.a132da","9d581c6e.04601"]]},{"id":"b3d4b11f.4590e","type":"delay","z":"559d36b1.8777a8","name":"","pauseType":"delay","timeout":"2","timeoutUnits":"seconds","rate":"1","nbRateUnits":"1","rateUnits":"second","randomFirst":"1","randomLast":"5","randomUnits":"seconds","drop":false,"x":640,"y":280,"wires":[["87cf98e2.db4998"]]},{"id":"f9f1c824.1b4d58","type":"delay","z":"559d36b1.8777a8","name":"","pauseType":"delay","timeout":"1","timeoutUnits":"seconds","rate":"1","nbRateUnits":"1","rateUnits":"second","randomFirst":"1","randomLast":"5","randomUnits":"seconds","drop":false,"x":180,"y":440,"wires":[["eb4bce63.33221"]]},{"id":"376153ca.1cd5cc","type":"link in","z":"559d36b1.8777a8","name":"","links":["dc8d8fcf.8609d"],"x":115,"y":240,"wires":[["7a077cad.8dcab4","87cf98e2.db4998","87d74d29.280d18"]]},{"id":"87cf98e2.db4998","type":"function","z":"559d36b1.8777a8","name":"","func":"\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","x":300,"y":220,"wires":[["58decb0a.1a91e4","87f9c1f7.69612"]]},{"id":"87d74d29.280d18","type":"delay","z":"559d36b1.8777a8","name":"","pauseType":"delay","timeout":"5","timeoutUnits":"seconds","rate":"1","nbRateUnits":"1","rateUnits":"second","randomFirst":"1","randomLast":"5","randomUnits":"seconds","drop":false,"x":140,"y":320,"wires":[["7a077cad.8dcab4"]]}]

I am using node-red 1.2.3, nodejs 14.15, q-gate 1.5.0 and simple-gate 0.4.0. I don't think this is a new issue as I first found it on older versions of the nodes (I think).

[Edit] Note that to go round again you will have to do a Restart Flows to get rid of the message in the queue.

2

Indeed.

Well, there is a feedback between the gate and q-gate nodes... I'll take a look and let you know if I figure it out.

3

I think that to see that there is a problem it is only necessary to look at what is going into the q-gate node and what is coming out. It isn't necessary to understand the flow to see that.

Looking at the q-gate node I can't see how the queue can get corrupted unless there is a fundamental issue with context.

4

There is only one _msgid in your debug node outputs. Is it possible that one of the change nodes is actually modifying the message in the queue?

5

Ah, good point, I should have thought of that. I will add a clone somewhere to test it.

6

Yes, that is it, thanks, I need to clone the message before feeding it back round via the gate node.

I am annoyed with myself now for not seeing that hours ago.

I can go back now and get the real flow working.

Thanks again

7

No problem -- except that I wonder whether q-gate ought to clone messages before putting them in the queue, in order to avoid cases like this. Does anyone (including @knolleary / @dceejay) have an opinion on this?

8

In general I think yes it should clone it before storing so it can't be changed under your feet.

1 Like
9

I think I agree, but I want to be sure there are no unpleasant side effects. Unless I can think of a reason not to, I will make the change with the next set of bug fixes.

10

Hi Michael, my 2¢ if you don't mind...

I would recommend making the cloning an option. If users are queuing large objects or something that doesn't play nice with cloning, you could introduce unwanted side effects.

I understand it may be difficult to clearly describe this feature so perhaps leave functionality as it is now (for backwards compatibility) and hide the option under an "advanced" panel (with suitable info tip?)

Something like this...

advanced options

clone messages blah blah blah lengthy description

11

Do the Delay and Trigger nodes clone? They fulfil conceptually similar functions, storing messages and releasing them later.

12

I had thought of that for images (large objects) but not in terms of "doesn't play nice" (functions -- what else?). I'm not sure about the default, though. I think cloning preserves the expected behavior and what @Colin found is actually a bug. (It's hard to imagine an existing flow that relies on modifying queued messages and would be broken by the change.) If cloning were the default, I would keep the checkbox visible with a description that points the user toward memory problems, etc.

13

Modifying a reference item isn't really a bug, it's an awareness thing. Sometimes it is even a feature. (I can give you an example if you need)

I only suggested leaving the default "no clone" so that you don't affect existing installations that don't play nice with cloned messages.

But either way, regardless of the default you choose, I would hope to have the option of cloned vs not cloned.

14

Instead of a tickbox, would it be possible to determine the size of the clone, and if it's larger than 'x' then don't clone?

15

Agreed. Still, you are adding "it might be queued up somewhere" to the list of things requiring increased awareness.

No question cloning should be optional, but right now I would rather see the default prevent things like what happened to @Colin.

Can you explain exactly what you mean here? Are we talking about serialization or something else?

16

Perhaps just issue a warning that you have cloned a large object?

17

Well, what I had in mind was that a msg cloned by RED.util.cloneMessage(msg); would also clone the payload & so would not be able to access internal encapsulated values - but having just stepped through the code, cloneMessage didnt actually clone my payload (payload was still a reference to the original payload) (i assumed it would (you know what they say about assume!!)

So on that, it may well be safe to clone the msg by default. (I might come back to you :stuck_out_tongue: )

Here is the flow I expected to fail if you want to try and understand my mindset (ignore otherwise)

[{"id":"917c2ea3.4bf82","type":"inject","z":"e39accec.112de","name":"","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"abc","payloadType":"str","x":450,"y":180,"wires":[["3471e898.330bb8"]]},{"id":"3471e898.330bb8","type":"function","z":"e39accec.112de","name":"not cloned","func":"var o = function() {\n    var _name = msg.payload\n    return {\n        setName: function getName(n) {\n            _name = n;\n        },\n        getName: function getName() {\n            return _name;\n        }\n    }\n}();\n\nmsg.payload = o\n\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","x":610,"y":180,"wires":[["b794130.4223ef"]]},{"id":"b794130.4223ef","type":"q-gate","z":"e39accec.112de","name":"","controlTopic":"control","defaultState":"queueing","openCmd":"open","closeCmd":"close","toggleCmd":"toggle","queueCmd":"queue","defaultCmd":"default","triggerCmd":"trigger","flushCmd":"flush","resetCmd":"reset","peekCmd":"peek","dropCmd":"drop","statusCmd":"status","maxQueueLength":"100","keepNewest":false,"qToggle":true,"persist":false,"storeName":"default","x":590,"y":260,"wires":[["c6514038.332f8"]]},{"id":"109625ed.3bd0fa","type":"function","z":"e39accec.112de","name":"cloned","func":"var o = function () {\n    _name = msg.payload\n    return {\n        setName: function getName(n) {\n            _name = n;\n        },\n        getName: function getName() {\n            return _name;\n        }\n    }\n}();\n\nmsg.payload = o\nvar clone = RED.util.cloneMessage(msg);\n\nnode.warn(\"Setting clone name to 'i am the clone'\")\nclone.payload.setName(\"i am the clone\")\nnode.warn(\"clone name = \" + clone.payload.getName())\n\nnode.warn(\"Setting original name to 'i am the original'\")\nmsg.payload.setName(\"i am the original\")\nnode.warn(\"orig' name = \" + msg.payload.getName())\n\nnode.warn(\"clone name = \" + clone.payload.getName())\n\nreturn clone;\n","outputs":1,"noerr":0,"initialize":"","finalize":"","x":590,"y":340,"wires":[["b794130.4223ef"]]},{"id":"88d47c77.07bd8","type":"inject","z":"e39accec.112de","name":"","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"def","payloadType":"str","x":450,"y":340,"wires":[["109625ed.3bd0fa"]]},{"id":"c6514038.332f8","type":"function","z":"e39accec.112de","name":"","func":"node.warn(msg.payload.getName())\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","x":760,"y":260,"wires":[["e53858fd.8014d8"]]},{"id":"f6685070.92b62","type":"inject","z":"e39accec.112de","name":"release","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":".","payloadType":"str","x":210,"y":260,"wires":[["b283e8e4.c85228"]]},{"id":"e53858fd.8014d8","type":"debug","z":"e39accec.112de","name":"","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","statusVal":"","statusType":"auto","x":910,"y":260,"wires":[]},{"id":"b283e8e4.c85228","type":"function","z":"e39accec.112de","name":"","func":"node.send({ topic:\"control\", payload:\"open\"})\nnode.send({ topic: \"control\", payload:\"queue\"})\n","outputs":1,"noerr":0,"initialize":"","finalize":"","x":340,"y":260,"wires":[["b794130.4223ef"]]}]
1 Like
18

@colin, yes both the delay and trigger nodes use clone message for this very reason
Eg https://github.com/node-red/node-red/blob/ca4960e097609fdf113d83420a667afbce7f9b6b/packages/node_modules/%40node-red/nodes/core/function/89-delay.js#L167

Personally I think its a bug and should not be an option.

1 Like
19

In the case I found it is actually on the way out that it would have to be cloned, as the corruption is happening to the message left in the queue after it has been peeked (sent out but kept in queue). Perhaps on the way out it is only the peek that needs cloning.

Here is a simple flow to show the problem

image

[{"id":"ccd01e96.4d37b8","type":"inject","z":"bdd7be38.d3b55","name":"Test","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"Test","payloadType":"str","x":110,"y":4700,"wires":[["b53dd1e4.5174","e0b5c60c.fb3d48"]]},{"id":"b53dd1e4.5174","type":"q-gate","z":"bdd7be38.d3b55","name":"","controlTopic":"control","defaultState":"queueing","openCmd":"open","closeCmd":"close","toggleCmd":"toggle","queueCmd":"queue","defaultCmd":"default","triggerCmd":"trigger","flushCmd":"flush","resetCmd":"reset","peekCmd":"peek","dropCmd":"drop","statusCmd":"status","maxQueueLength":"100","keepNewest":false,"qToggle":false,"persist":false,"storeName":"memoryOnly","x":390,"y":4700,"wires":[["cc00a5f2.2aa31"]]},{"id":"e0b5c60c.fb3d48","type":"debug","z":"bdd7be38.d3b55","name":"IN","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"payload","targetType":"msg","statusVal":"","statusType":"auto","x":290,"y":4660,"wires":[]},{"id":"de769761.62496","type":"inject","z":"bdd7be38.d3b55","name":"Reset","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"control","payload":"reset","payloadType":"str","x":110,"y":4780,"wires":[["b53dd1e4.5174"]]},{"id":"1a3eeb2f.9433cd","type":"inject","z":"bdd7be38.d3b55","name":"Peek","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"control","payload":"peek","payloadType":"str","x":110,"y":4740,"wires":[["b53dd1e4.5174"]]},{"id":"cc00a5f2.2aa31","type":"function","z":"bdd7be38.d3b55","name":"","func":"node.warn(`payload in: ${msg.payload}`)\nmsg.payload = \"Oops\"\nreturn","outputs":1,"noerr":0,"initialize":"","finalize":"","x":540,"y":4700,"wires":[[]]}]

Click Test to inject a message then Peek twice to show the problem.

20

err - no - it is the stored value that is being corrupted such that when you ask for it the second time it has been modified - so you need to clone it as you store it so that when asked you get that same clone every time.