Inject node runs late sometimes

General
1

Hi folks, I have set up the Inject node to trigger an audible reminder using Google Home at 3.55pm on a Tuesday. But sometimes (not every day) it happens a random time later, say 4.10pm! I am running Node Red on a Raspberry Pi, native not in a Docker container. Here is some simplified code that triggers at 4pm to reproduce the problem easily:

[{"id":"d3d44654.2e41c8","type":"inject","z":"f72ea602.fbc808","name":"@4pm every day","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"00 16 * * *","once":false,"onceDelay":0.1,"x":150,"y":3500,"wires":[["3f8a3ffb.d100e"]]},{"id":"3f8a3ffb.d100e","type":"time-switch","z":"f72ea602.fbc808","name":"Within 5 minutes of 4pm?","lat":"-37.87555","lon":"145.17484","startTime":"15:55","endTime":"16:05","startOffset":0,"endOffset":0,"x":390,"y":3500,"wires":[[],["eed4650a.44d748"]]},{"id":"9822f822.511558","type":"comment","z":"f72ea602.fbc808","name":"Detection of the problem where triggers start late.","info":"","x":220,"y":3460,"wires":[]},{"id":"eed4650a.44d748","type":"moment","z":"f72ea602.fbc808","name":"inject timestamp","topic":"","input":"","inputType":"date","inTz":"Australia/Melbourne","adjAmount":"10","adjType":"hours","adjDir":"add","format":"","locale":"en_GB","output":"now","outputType":"msg","outTz":"Australia/Melbourne","x":640,"y":3500,"wires":[["d9b4caa.f1b4338"]]},{"id":"d9b4caa.f1b4338","type":"change","z":"f72ea602.fbc808","name":"\"4pm Time Sync error\"","rules":[{"t":"set","p":"payload","pt":"msg","to":"'4pm Time Sync error. now:' & now & ', epoch: ' & payload","tot":"jsonata"}],"action":"","property":"","from":"","to":"","reg":false,"x":840,"y":3500,"wires":[["3dcc11fe.a196ee","3471e8bf.728518","a1e84ac.13cb2b8"]]},{"id":"a1e84ac.13cb2b8","type":"debug","z":"f72ea602.fbc808","name":"TIME SYNC ERROR","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"payload","targetType":"msg","x":1080,"y":3500,"wires":[]}]

Example output:
4pm Time Sync error. now:2020-07-18T16:09:31.943Z, epoch: 1595052571937

I am sure if I force reboot the device every night it will hide the error but I would prefer not to do that if this is just masking a bug in the inject node. Also, the time does sync itself again at some point so this error doesn't present itself every day. Node that the example output above was generated at 4:09 pm real time.

Any ideas?

2

I think you are making it more complicated than it needs to be.

I just imported the flow.

What is this time-switch node? Why do you have it and what does it do?

BIG PROBLEM!

The inject node is set to inject at 16:00 not 15:55 so there's the first problem.

Why are you using the moment node?

Well, this is because it is triggered at 16:00 (not 15:55) and the payload is what you have in the change node.

Seen here:
'4pm Time Sync error. now:' & now & ', epoch: ' & payload

The extra 10 minutes.... Well, I think there are other problems you need to address before you worry about that. (Like the time in the inject node and when it is activated.)

It is done every day, not Tuesday

Look at the inject node. Every day is ticked.

3

Ah yes, sorry I missed out on the context I had in my brain ;), The code provided is a simplified example only that is intended to reproduce the problem for everyone easily. It runs every day at 4pm exactly.

The Time Switch node:
Only passes through to the alternate flow if the trigger happens more than 5 minutes before or after 4pm. This node provides the independent proof that the trigger doesn't run accurately at 4pm all the time. Note that it is configured for my latitude and longitude.

The Moment node
The Moment node is just for my text message so I can see a locally formatted time instead of just the epoch. I wanted to see if the time reported by epoch and Moment were different.

To reproduce the problem, you should be able to add the example code to your node red configuration without affecting any other flows, as long as you have Time Switch and Moment node installed as well.
Time Switch is pretty useful if you don't want to get notifications at certain times of the day when babies are usually sleeping etc.

4

And the time-switch node?

Really all you need is the inject node.

Adding more nodes complicates what you describe as needing done.

5

Ah, good point. I have amended the earlier post to make it a bit clearer why.

6

Have a look at this way.

You will need: simple-time installed:

Simpletime

[{"id":"7b6a4e99.e1a528","type":"change","z":"2a10ff07.234f98","name":"GOOD","rules":[{"t":"set","p":"payload","pt":"msg","to":"Good","tot":"str"}],"action":"","property":"","from":"","to":"","reg":false,"x":500,"y":610,"wires":[["ba896bfb.d1af","ab0b58c9.982fe8"]]},{"id":"25128646.a0694a","type":"switch","z":"2a10ff07.234f98","name":"","property":"myminute","propertyType":"msg","rules":[{"t":"lte","v":"5","vt":"num"},{"t":"gte","v":"55","vt":"num"},{"t":"else"}],"checkall":"true","repair":false,"outputs":3,"x":330,"y":650,"wires":[["7b6a4e99.e1a528"],["7b6a4e99.e1a528"],["6045d420.bbf9ec"]]},{"id":"ba896bfb.d1af","type":"debug","z":"2a10ff07.234f98","name":"Message","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"payload","targetType":"msg","x":700,"y":650,"wires":[]},{"id":"ab0b58c9.982fe8","type":"moment","z":"2a10ff07.234f98","name":"","topic":"","input":"","inputType":"msg","inTz":"","adjAmount":0,"adjType":"days","adjDir":"add","format":"","locale":"","output":"","outputType":"msg","outTz":"","x":680,"y":570,"wires":[[]]},{"id":"60223ab3.08a14c","type":"simpletime","z":"2a10ff07.234f98","name":"","x":170,"y":650,"wires":[["25128646.a0694a"]]},{"id":"6045d420.bbf9ec","type":"change","z":"2a10ff07.234f98","name":"BAD","rules":[{"t":"set","p":"payload","pt":"msg","to":"Bad","tot":"str"}],"action":"","property":"","from":"","to":"","reg":false,"x":500,"y":680,"wires":[["ba896bfb.d1af"]]},{"id":"c378395d.49cb2","type":"inject","z":"2a10ff07.234f98","name":"","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"","once":false,"onceDelay":0.1,"x":160,"y":610,"wires":[["60223ab3.08a14c"]]}]

The moment node is there for time formatting and ongoing use.

1 Like
7

Neat! simple-time is a pretty handy alternative to Moment which is really heavyweight, I will use it instead, thanks for the tip!

I'd love to hear if anyone can reproduce the triggering problem with inject though.

1 Like
8

As Node-Red is async' it could be many things that are causing it.

The nodes after the inject could also be causing problems. Dunno.

But maybe cut/paste from the real flow you may get better help. Unless the example posted also suffers the same, then it is hard to say.

9

Yes, the example suffers exactly the same intermittent problem. I believe somehow the timer that the inject node uses is out of sync with the system time after a day or two. My Node Red instance is doing quite a lot, but I don't know how to fix it easily.

10

I don't think so. But I am at the bottom of the food chain on that.

I think there is something else happening.

I just hope someone else who is smarter than me can come here and help.
I'm out of options.

11

Have you been able to monitor the system any time the problem has occurred? Is everything else running on your flows while it happens or could Node-RED be busy processing a singe synchronous task at the given time (parsing a huge file or something like that)? As Node.js is single threaded, any scheduled code can only run on their turn.

IIRC inject node uses cron Node.js library for the scheduled tasks so if the system is not busy, this could also be an upstream problem with the library.

12

Nothing special happening in my flows at the time that I can see - not sure what a Node.js blocked event queue looks like though or how I would identify when it is happening. Is there a way to put a start/stop timer on a suspect flow?

I found a good diagram and article about the Event Loop model here: https://itnext.io/multi-threading-and-multi-process-in-node-js-ffa5bb5cde98

1_evOcy9n3vslkDt0Mj8mBYw
1_evOcy9n3vslkDt0Mj8mBYw1600Ă—480 79.9 KB

So what you are saying is that although the Node.js cron implementation request may have triggered at 4pm, it doesn't actually execute in a spare thread until some time later (4:09pm) because all the threads are busy doing other things? 9 minutes is a long wait for a thread.

Is there a way in Node Red to get a view of how many free threads there are in the pool at any time?

I have a few ideas where the trouble could be:

  • Webhooks not being closed by the client
  • A poorly coded node somewhere which prevents a thread completing (unlikely, since the Node Red instance runs for months without needing a reboot and there's no obvious exceptions in the logs)
  • Using the persist node every five minutes to store my graph data (1000 data points). I don't think this would take very long.
  • Too many flows in general (six very full tabs of them!). I can't see any places they would block because they are usually just processing an IOT event.
  • Dashboard buttons that accept events from IOT devices to customise what is printed on the button, then wait for user input, then call themselves to refresh their displayed text and icons.

Of course the easiest solution would be to have the reminder for the piano lesson go half an hour before, but I've seen a few references in the Forum to similar problems with Inject. I am curious if people add the example I posted to their flows and can reproduce it.

It seems similar to this issue from stackoverflow:

13

A quick reply without reading the linked article.

It was just one theory but this could happen if there was a single thing processing for 9 minutes. It does sound unlikely though if you know none of your flows is doing any heavy processing.

There is only a single thread but most I/O operations are asynchronous. So when you copy a file or send data over to the network this usually happens asynchronously. Simplified: the event loop continues to the next task and resumes the code at that point when the copy/transfer is completed.

You could for example add an inject node to send once a minute and have a debug node print a line on Node-RED logs. You can then check if there's an entry for every minute during the time you get the late response. If the minutely logs continue, then the event loop is not blocked.

Using inject node to test inject node might sound silly but I've understood the timers repeated in this manner use the basic setInterval JavaScript function and not the cron library.

1 Like
14

Maybe @dceejay could give a better insight which underlying implementation is used for daily inject node triggers?

15

I think cron is beeing used for those but as far as i can see from the cron npm modules code it also uses setTimeout() and setIntervall() in the background to achieve its functionality.
So in the end it comes down to setTimeout() but unleast something is going really wrong i cant imagine a delay as big as this happening.

16

I have an update on this issue. It looks like some kind of clock issue which resolves itself if I do a sudo reboot of the Raspberry Pi. I noticed that with the following test code, it was injecting every hour at exactly 32 minutes past the hour (e.g. 1:32pm, 2:32pm my time) and then simpletime reported the time being 32 minutes past the hour which followed the flow into Time Sync Error.
(In those tests that were 32 minutes out, the injected timestamp of the message also reflected an epoch time 32 minutes past the hour). The time was 1:32 etc. in my local time.

So this rules out some kind of randomly long-running node or flow. Because the problem triggered every hour with exactly 32 minutes out. It also couldn't be a daylight savings error either because that would be exactly 30 or 60 minutes.

Here is the example code.

[{"id":"d3d44654.2e41c8","type":"inject","z":"f72ea602.fbc808","name":"@8am every day","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"00 08 * * *","once":false,"onceDelay":0.1,"x":150,"y":3540,"wires":[["c90b11be.a78da"]]},{"id":"9822f822.511558","type":"comment","z":"f72ea602.fbc808","name":"Detection of the problem where triggers start late.","info":"","x":220,"y":3460,"wires":[]},{"id":"d9b4caa.f1b4338","type":"change","z":"f72ea602.fbc808","name":"\"On-the-hour Time Sync error\"","rules":[{"t":"set","p":"payload","pt":"msg","to":"'On-the-hour Time Sync error. now:' & myrawdate & ', epoch: ' & payload","tot":"jsonata"}],"action":"","property":"","from":"","to":"","reg":false,"x":950,"y":3520,"wires":[["3471e8bf.728518","a1e84ac.13cb2b8"]]},{"id":"549d4b73.609684","type":"inject","z":"f72ea602.fbc808","name":"Test it","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"","once":false,"onceDelay":0.1,"x":110,"y":3500,"wires":[["c90b11be.a78da"]]},{"id":"a1e84ac.13cb2b8","type":"debug","z":"f72ea602.fbc808","name":"TIME SYNC ERROR","active":true,"tosidebar":true,"console":true,"tostatus":false,"complete":"true","targetType":"full","x":1270,"y":3520,"wires":[]},{"id":"c90b11be.a78da","type":"simpletime","z":"f72ea602.fbc808","name":"","x":390,"y":3500,"wires":[["5ea8459d.4d869c"]]},{"id":"5ea8459d.4d869c","type":"switch","z":"f72ea602.fbc808","name":"Within 5 minutes of the hour?","property":"myminute","propertyType":"msg","rules":[{"t":"lte","v":"5","vt":"num"},{"t":"gte","v":"55","vt":"num"},{"t":"else"}],"checkall":"true","repair":false,"outputs":3,"x":640,"y":3500,"wires":[["e722190d.3d4988"],["e722190d.3d4988"],["d9b4caa.f1b4338"]]},{"id":"d3c8425a.61cd3","type":"inject","z":"f72ea602.fbc808","name":"@9am every day","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"00 09 * * *","once":false,"onceDelay":0.1,"x":150,"y":3580,"wires":[["c90b11be.a78da"]]},{"id":"3fafa0a2.5d626","type":"inject","z":"f72ea602.fbc808","name":"@10am every day","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"00 10 * * *","once":false,"onceDelay":0.1,"x":150,"y":3620,"wires":[["c90b11be.a78da"]]},{"id":"a2621243.26fc","type":"inject","z":"f72ea602.fbc808","name":"@11am every day","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"00 11 * * *","once":false,"onceDelay":0.1,"x":150,"y":3660,"wires":[["c90b11be.a78da"]]},{"id":"cd85323.1e85bd","type":"inject","z":"f72ea602.fbc808","name":"@noon every day","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"00 12 * * *","once":false,"onceDelay":0.1,"x":150,"y":3700,"wires":[["c90b11be.a78da"]]},{"id":"5afa93e9.26110c","type":"inject","z":"f72ea602.fbc808","name":"@1pm every day","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"00 13 * * *","once":false,"onceDelay":0.1,"x":150,"y":3740,"wires":[["c90b11be.a78da"]]},{"id":"4e9b6032.247c9","type":"inject","z":"f72ea602.fbc808","name":"@2pm every day","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"00 14 * * *","once":false,"onceDelay":0.1,"x":150,"y":3780,"wires":[["c90b11be.a78da"]]},{"id":"aa03e57d.1a3518","type":"inject","z":"f72ea602.fbc808","name":"@3pm every day","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"00 15 * * *","once":false,"onceDelay":0.1,"x":150,"y":3820,"wires":[["c90b11be.a78da"]]},{"id":"f245d62d.c7fc28","type":"inject","z":"f72ea602.fbc808","name":"@4pm every day","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"00 16 * * *","once":false,"onceDelay":0.1,"x":150,"y":3860,"wires":[["c90b11be.a78da"]]},{"id":"81b5cbb4.65f428","type":"inject","z":"f72ea602.fbc808","name":"@5pm every day","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"00 17 * * *","once":false,"onceDelay":0.1,"x":150,"y":3900,"wires":[["c90b11be.a78da"]]},{"id":"dad6d00c.24d93","type":"inject","z":"f72ea602.fbc808","name":"@6pm every day","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"00 18 * * *","once":false,"onceDelay":0.1,"x":150,"y":3940,"wires":[["c90b11be.a78da"]]},{"id":"e722190d.3d4988","type":"debug","z":"f72ea602.fbc808","name":"TIME SYNC OK","active":true,"tosidebar":true,"console":true,"tostatus":false,"complete":"true","targetType":"full","x":1250,"y":3480,"wires":[]}]

I'd love to see if anyone can just leave it running and see if it triggers for them, and on which OS.
Next time it happens I will have a look at the system time on the Pi, but I am pretty confident it will be correct. After all, the simpletime node injects the correct real world time.

17

I will leave it running with a little modification, i will append the time of every inject to a file and come back in a day or two.
This is really strange as i have for example a subflow task scheduler which is based on setTimeout which on one of my pis has been running daily tasks with second accuracy for a hundred days on end.
So i’m really interested in the outcome. I will run your flow on a Pi 4 with Buster and the latest and greatest nodered 1.1.2

18

I also set a similar mod as @JGKK. I've never user flogger before so let's see if I got it right. I'll check when I'll see the next comment on this thread.

19

The flow is running on my production Node-RED on a Raspi 3 and a Test Node-RED on a Debian running on a HP Microserver. Both show 10-17 milliseconds on the Debian and 40-41 milliseconds on the Pi after the full hour since 2 p.m. Nothing to worry about :wink:

20

First day:

09:00:00
10:00:00
11:00:00
12:00:00
13:00:00
14:00:00
15:00:00
16:00:00
17:00:00
18:00:00

looks good to me so far