Weird happening with subflows. Help needed to make sure what is happening

Sorry, this is not a nice picture.

Slightly birthed from my MQTT thread. But this is now a whole different scenario.

I have a subflow to give me a userfriendly time output.
3 options:
For use in log files. The time/date are formatted for ease of reading.
The second one passes the payload and adds a msg.time for use as you want.
The third is formatted to be used to create file names. (So no /'s or :'s in it.)

Cutting to the chase:
The subflow first:

[{"id":"98a12d23.4caf","type":"subflow","name":"Time Stamp","info":"**3 outputs.  1 - msg.payload holds the time. 2 - msg.time holds the time in a way to be used for reading time in a log file. 3 - outputs nsg.time in a format usable for file names**","category":"","in":[{"x":80,"y":100,"wires":[{"id":"b51453d8.f777"}]}],"out":[{"x":640,"y":180,"wires":[{"id":"537f67d0.440958","port":0},{"id":"b51453d8.f777","port":0}]},{"x":640,"y":230,"wires":[{"id":"b51453d8.f777","port":0},{"id":"436ec434.1175cc","port":0}]},{"x":640,"y":280,"wires":[{"id":"c77ad598.3b98e8","port":0},{"id":"b51453d8.f777","port":0}]}],"env":[],"color":"#FF8888","outputLabels":["For logging use","msg.time","For filename use"],"icon":"node-red/timer.svg"},{"id":"537f67d0.440958","type":"moment","z":"98a12d23.4caf","name":"","topic":"","input":"payload","inputType":"msg","inTz":"Australia/Sydney","adjAmount":0,"adjType":"days","adjDir":"add","format":"YYYY-MM-DD HH:mm:ss","locale":"en_AU","output":"payload","outputType":"msg","outTz":"Australia/Sydney","x":390,"y":180,"wires":[["c77ad598.3b98e8","9a6e708b.c8249"]]},{"id":"c77ad598.3b98e8","type":"string","z":"98a12d23.4caf","name":"","methods":[{"name":"replaceAll","params":[{"type":"str","value":":"},{"type":"str","value":""}]}],"prop":"payload","propout":"payload","object":"msg","objectout":"msg","x":440,"y":280,"wires":[[]]},{"id":"9a6e708b.c8249","type":"change","z":"98a12d23.4caf","name":"TOPIC","rules":[{"t":"move","p":"payload","pt":"msg","to":"time","tot":"msg"}],"action":"","property":"","from":"","to":"","reg":false,"x":220,"y":230,"wires":[["436ec434.1175cc"]]},{"id":"204888d7.8b194","type":"change","z":"98a12d23.4caf","name":"Save","rules":[{"t":"set","p":"payload","pt":"flow","to":"payload","tot":"msg","dc":true}],"action":"","property":"","from":"","to":"","reg":false,"x":220,"y":140,"wires":[["93239165.b7976"]]},{"id":"436ec434.1175cc","type":"change","z":"98a12d23.4caf","name":"Get","rules":[{"t":"set","p":"payload","pt":"msg","to":"payload","tot":"flow"}],"action":"","property":"","from":"","to":"","reg":false,"x":440,"y":230,"wires":[[]]},{"id":"b51453d8.f777","type":"switch","z":"98a12d23.4caf","name":"check topic","property":"topic","propertyType":"msg","rules":[{"t":"eq","v":"TIMESTAMP","vt":"str"},{"t":"else"}],"checkall":"true","repair":false,"outputs":2,"x":200,"y":100,"wires":[[],["204888d7.8b194"]]},{"id":"93239165.b7976","type":"change","z":"98a12d23.4caf","name":"TimeStamp","rules":[{"t":"set","p":"payload","pt":"msg","to":"","tot":"date"}],"action":"","property":"","from":"","to":"","reg":false,"x":200,"y":180,"wires":[["537f67d0.440958"]]},{"id":"87a8a491.9b6fa8","type":"subflow:98a12d23.4caf","z":"c56bddee.ca0a18","name":"","x":780,"y":3020,"wires":[[],["1b15d15.3819a2f"],[]]}]

I finally noticed messages being changed when passing through.
But not all the time and not all messages. So this really took a lot of chasing to catch.
(But have I really caught it, or it is just a ghost?)

(Added later one)
I made the flow below that basically does what happens in the real flow.
But, it doesn't error/have the bad thing happen.

I hope this is the right link.
Post 52

I stuck debug nodes all long the flow.
The messages going into the timestamp node are not the same as the ones coming out, and in a critical way different.

The post pretty well shows that as the messages going in are changed coming out.

But not consistently or always.
So I've maybe found something is broken.
I'm not sure.

Example flow:

[{"id":"98a12d23.4caf","type":"subflow","name":"Time Stamp","info":"**3 outputs.  1 - msg.payload holds the time. 2 - msg.time holds the time in a way to be used for reading time in a log file. 3 - outputs nsg.time in a format usable for file names**","category":"","in":[{"x":80,"y":100,"wires":[{"id":"b51453d8.f777"}]}],"out":[{"x":640,"y":180,"wires":[{"id":"537f67d0.440958","port":0},{"id":"b51453d8.f777","port":0}]},{"x":640,"y":230,"wires":[{"id":"b51453d8.f777","port":0},{"id":"436ec434.1175cc","port":0}]},{"x":640,"y":280,"wires":[{"id":"c77ad598.3b98e8","port":0},{"id":"b51453d8.f777","port":0}]}],"env":[],"color":"#FF8888","outputLabels":["For logging use","msg.time","For filename use"],"icon":"node-red/timer.svg"},{"id":"537f67d0.440958","type":"moment","z":"98a12d23.4caf","name":"","topic":"","input":"payload","inputType":"msg","inTz":"Australia/Sydney","adjAmount":0,"adjType":"days","adjDir":"add","format":"YYYY-MM-DD HH:mm:ss","locale":"en_AU","output":"payload","outputType":"msg","outTz":"Australia/Sydney","x":390,"y":180,"wires":[["c77ad598.3b98e8","9a6e708b.c8249"]]},{"id":"c77ad598.3b98e8","type":"string","z":"98a12d23.4caf","name":"","methods":[{"name":"replaceAll","params":[{"type":"str","value":":"},{"type":"str","value":""}]}],"prop":"payload","propout":"payload","object":"msg","objectout":"msg","x":440,"y":280,"wires":[[]]},{"id":"9a6e708b.c8249","type":"change","z":"98a12d23.4caf","name":"TOPIC","rules":[{"t":"move","p":"payload","pt":"msg","to":"time","tot":"msg"}],"action":"","property":"","from":"","to":"","reg":false,"x":220,"y":230,"wires":[["436ec434.1175cc"]]},{"id":"204888d7.8b194","type":"change","z":"98a12d23.4caf","name":"Save","rules":[{"t":"set","p":"payload","pt":"flow","to":"payload","tot":"msg","dc":true}],"action":"","property":"","from":"","to":"","reg":false,"x":220,"y":140,"wires":[["93239165.b7976"]]},{"id":"436ec434.1175cc","type":"change","z":"98a12d23.4caf","name":"Get","rules":[{"t":"set","p":"payload","pt":"msg","to":"payload","tot":"flow"}],"action":"","property":"","from":"","to":"","reg":false,"x":440,"y":230,"wires":[[]]},{"id":"b51453d8.f777","type":"switch","z":"98a12d23.4caf","name":"check topic","property":"topic","propertyType":"msg","rules":[{"t":"eq","v":"TIMESTAMP","vt":"str"},{"t":"else"}],"checkall":"true","repair":false,"outputs":2,"x":200,"y":100,"wires":[[],["204888d7.8b194"]]},{"id":"93239165.b7976","type":"change","z":"98a12d23.4caf","name":"TimeStamp","rules":[{"t":"set","p":"payload","pt":"msg","to":"","tot":"date"}],"action":"","property":"","from":"","to":"","reg":false,"x":200,"y":180,"wires":[["537f67d0.440958"]]},{"id":"91100cee56080bc8","type":"subflow:98a12d23.4caf","z":"c56bddee.ca0a18","name":"","x":830,"y":3440,"wires":[[],["8ad1490198aa65dd"],[]]},{"id":"10e10d6dddcb6f09","type":"inject","z":"c56bddee.ca0a18","name":"","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"","payloadType":"date","x":525.5555267333984,"y":3398.8888206481934,"wires":[["eaa79608a1039501"]]},{"id":"8ad1490198aa65dd","type":"debug","z":"c56bddee.ca0a18","name":"","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","statusVal":"","statusType":"auto","x":990,"y":3440,"wires":[]},{"id":"eaa79608a1039501","type":"function","z":"c56bddee.ca0a18","name":"","func":"msg.payload = {\n    \"Foo1\":\"This is message 1\"\n}\n\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":665.5555267333984,"y":3398.8888206481934,"wires":[["91100cee56080bc8"]]},{"id":"ed43a81d6c1eb613","type":"function","z":"c56bddee.ca0a18","name":"","func":"msg.payload = {\n    \"Foo1\":\"This is message 2\"\n}\n\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":665.5555267333984,"y":3448.8888206481934,"wires":[["91100cee56080bc8"]]},{"id":"be45998c047525f9","type":"inject","z":"c56bddee.ca0a18","name":"","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"","payloadType":"date","x":525.5555267333984,"y":3448.8888206481934,"wires":[["ed43a81d6c1eb613"]]},{"id":"88811bb87213f436","type":"function","z":"c56bddee.ca0a18","name":"1","func":"msg = {\"topic\":\"STATUS/WIFIDEVICEID\",\"payload\":\"{\\\"WIFI_DEVICE\\\":\\\"TimePi\\\",\\\"IP_Address\\\":\\\"192.168.0.99\\\",\\\"Sent\\\":\\\"2022-03-04 11:52:02\\\"}\"}\nreturn msg;\n","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":655.5555267333984,"y":3528.8888206481934,"wires":[["91100cee56080bc8"]]},{"id":"1bbfb630a83eb34a","type":"function","z":"c56bddee.ca0a18","name":"2","func":"msg = {\"topic\":\"STATUS/WIFIDEVICEID\",\"payload\":\"{\\\"WIFI_DEVICE\\\":\\\"BedPi\\\",\\\"IP_Address\\\":\\\"192.168.0.83\\\",\\\"Sent\\\":\\\"2022-03-04 11:52:02\\\"}\"}\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":655.5555267333984,"y":3568.8888206481934,"wires":[["91100cee56080bc8"]]},{"id":"1a774c1781552d6d","type":"function","z":"c56bddee.ca0a18","name":"3","func":"msg = {\"topic\":\"STATUS/WIFIDEVICEID\",\"payload\":\"{\\\"WIFI_DEVICE\\\":\\\"TelePi\\\",\\\"IP_Address\\\":\\\"192.168.0.93\\\",\\\"Sent\\\":\\\"2022-03-04 11:52:02\\\"}\"}\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":655.5555267333984,"y":3608.8888206481934,"wires":[["91100cee56080bc8"]]},{"id":"296a72c2f5c45660","type":"function","z":"c56bddee.ca0a18","name":"4","func":"msg = {\"topic\":\"STATUS/WIFIDEVICEID\",\"payload\":\"{\\\"WIFI_DEVICE\\\":\\\"GPS\\\",\\\"IP_Address\\\":\\\"192.168.0.155\\\"}\"}\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":655.5555267333984,"y":3648.8888206481934,"wires":[["91100cee56080bc8"]]},{"id":"6fe7813002dffefd","type":"inject","z":"c56bddee.ca0a18","name":"","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"","payloadType":"date","x":515.5555267333984,"y":3528.8888206481934,"wires":[["88811bb87213f436"]]},{"id":"40e742fb36ea6bda","type":"inject","z":"c56bddee.ca0a18","name":"","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"","payloadType":"date","x":515.5555267333984,"y":3568.8888206481934,"wires":[["1bbfb630a83eb34a"]]},{"id":"69a1bf2fc28e46b2","type":"inject","z":"c56bddee.ca0a18","name":"","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"","payloadType":"date","x":515.5555267333984,"y":3608.8888206481934,"wires":[["1a774c1781552d6d"]]},{"id":"1acd745e3149e010","type":"inject","z":"c56bddee.ca0a18","name":"","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"","payloadType":"date","x":515.5555267333984,"y":3648.8888206481934,"wires":[["296a72c2f5c45660"]]},{"id":"e04ed4f11944f815","type":"comment","z":"c56bddee.ca0a18","name":"Proof of concept","info":"","x":610,"y":3360,"wires":[]},{"id":"099b1cf6c1d7d1c9","type":"comment","z":"c56bddee.ca0a18","name":"Problems","info":"","x":580,"y":3490,"wires":[]}]

What I saw happening is that there were the 4 messages going into the node.
But when they came out their device name was not the same as it was going in.

This has caused me a lot of grief.

The top two inject nodes show you a Proof of concept and a complex message gets through unchanged.

The lower 4 inject nodes are copies of the messages going in.

On testing a couple of times (of course) they worked.

But to put it out there.....

And looking at that link/thread...
What else could I be missing?

Best I can see it is something to do with the subflow.

I sat there for about 20 minutes and a text editor collating the messages from the side window.
After all that, I saw that what was going in was NOT what was coming out and parts of the message had been changed - for reason/s unknown to me.

Thanks very much in advance for help.

Hi Andrew, this is a common pitfall of using context + asynchronous processes - when it is not necessary.

In simple terms, when 2 msgs arrive in your subflow in quick concession, the payload you store in flow.payload is updated by the 2nd msg and is then applied to the 1st msg

PROOF Your subflow vs my modified version (not using context)...

Updated Subflow

Items changed ...

  • change node 'save'
  • change node 'get'
[{"id":"ea4c0247439a4f0a","type":"subflow","name":"Time Stamp (2)","info":"**3 outputs.  1 - msg.payload holds the time. 2 - msg.time holds the time in a way to be used for reading time in a log file. 3 - outputs nsg.time in a format usable for file names**","category":"","in":[{"x":80,"y":100,"wires":[{"id":"c652c017772e746d"}]}],"out":[{"x":640,"y":180,"wires":[{"id":"11d31e72e9e6efd2","port":0},{"id":"c652c017772e746d","port":0}]},{"x":640,"y":230,"wires":[{"id":"c652c017772e746d","port":0},{"id":"b87362142aacfecb","port":0}]},{"x":640,"y":280,"wires":[{"id":"0bfc1ccb9e5a2129","port":0},{"id":"c652c017772e746d","port":0}]}],"env":[],"color":"#FF8888","outputLabels":["For logging use","msg.time","For filename use"],"icon":"node-red/timer.svg"},{"id":"11d31e72e9e6efd2","type":"moment","z":"ea4c0247439a4f0a","name":"","topic":"","input":"payload","inputType":"msg","inTz":"Australia/Sydney","adjAmount":0,"adjType":"days","adjDir":"add","format":"YYYY-MM-DD HH:mm:ss","locale":"en_AU","output":"payload","outputType":"msg","outTz":"Australia/Sydney","x":390,"y":180,"wires":[["0bfc1ccb9e5a2129","6d98c0e06ccb6ad8"]]},{"id":"0bfc1ccb9e5a2129","type":"string","z":"ea4c0247439a4f0a","name":"","methods":[{"name":"replaceAll","params":[{"type":"str","value":":"},{"type":"str","value":""}]}],"prop":"payload","propout":"payload","object":"msg","objectout":"msg","x":440,"y":280,"wires":[[]]},{"id":"6d98c0e06ccb6ad8","type":"change","z":"ea4c0247439a4f0a","name":"TOPIC","rules":[{"t":"move","p":"payload","pt":"msg","to":"time","tot":"msg"}],"action":"","property":"","from":"","to":"","reg":false,"x":220,"y":230,"wires":[["b87362142aacfecb"]]},{"id":"be17b2ddd2419f8d","type":"change","z":"ea4c0247439a4f0a","name":"Save","rules":[{"t":"set","p":"origPayload","pt":"msg","to":"payload","tot":"msg","dc":true}],"action":"","property":"","from":"","to":"","reg":false,"x":220,"y":140,"wires":[["4ef466d92e42d925"]]},{"id":"b87362142aacfecb","type":"change","z":"ea4c0247439a4f0a","name":"Get","rules":[{"t":"set","p":"payload","pt":"msg","to":"origPayload","tot":"msg"}],"action":"","property":"","from":"","to":"","reg":false,"x":440,"y":230,"wires":[[]]},{"id":"c652c017772e746d","type":"switch","z":"ea4c0247439a4f0a","name":"check topic","property":"topic","propertyType":"msg","rules":[{"t":"eq","v":"TIMESTAMP","vt":"str"},{"t":"else"}],"checkall":"true","repair":false,"outputs":2,"x":200,"y":100,"wires":[[],["be17b2ddd2419f8d"]]},{"id":"4ef466d92e42d925","type":"change","z":"ea4c0247439a4f0a","name":"TimeStamp","rules":[{"t":"set","p":"payload","pt":"msg","to":"","tot":"date"}],"action":"","property":"","from":"","to":"","reg":false,"x":200,"y":180,"wires":[["11d31e72e9e6efd2"]]},{"id":"d2b6a96451037ba7","type":"subflow:ea4c0247439a4f0a","z":"bd35015ba96e019f","name":"","x":1900,"y":800,"wires":[[],["e7ffd856ca1c2d0f"],[]]}]

{{@Steve-Mcl }}

Thanks.

I was suspicious but wasn't confident enough to really believe that.

I thought (and you know what he did....) that subflows kind of looked after themselves.

But I guess there are limits.

I can't sleep and it is 23:30 local here.

I'll download your modified subflow and learn from it.

Very good!

I was suspicious that may be how you did it.
:wink:

Too easy.

Now rolling the changes out to all the machines.

Well they do. but if you misuse context, this is the result.

In order to understand the issue you need to either be aware of what happens under the hood OR follow best practices.

1st best practice : "Dont use context unless there is no other way"
2nd best practice : "If you use context, consider what would happen if 2 or more messages arrive in quick succession"

I do agree.

I didn't think - at the time - to move the payload to another name and just keep it with the message.

And please understand this subflow was written probably a few years ago when I was REALLY at the bottom of the learning curve.

I guess this (problem) has been sneaking up on me for a while now as I have been getting weird messages slowly more and more.

Probably because every now and then I would get a burst of messages and it would throw that subflow.

Again: Thanks for that. It is probably a page one mistake. But I guess sometimes you have to make the mistake to learn from it.

This topic was automatically closed 14 days after the last reply. New replies are no longer allowed.