Weird timer behaviour

I have a task in Node Red that is triggered at a specific time. This has worked OK for several months, but now for some reason stopped working.
The weird thing: when I change the specific time to a few minutes in the future and watch what happens, then the task is executed just fine. But when I log off, it never triggers.
What could be the cause of this?
I run V.1.2.6 on a Raspberry Pi 4.

You will need to supply a bit more information in order to get any hail
1 - how is the task triggered?
2 - have you added or updated anyting in the flows before this started happening
3 - have you updated the OS?
4 - what is the task taking place?
5 - have you looked in the logs to see if there is anything happening about the time it should run?

Can you provide a copy of the flow?

  1. injector node, set to a specific time on every day
  2. the only thing that comes to mind: I have been playing with Aedes as Node-Red based alternative for MQTT. Beside that I did not change MQTT. After a few days I removed all Aedes nodes.
  3. no
  4. it is a Speedtest that I want to run on a daily basis
  5. which logs... ?

flow:

[{"id":"189797d.d35d668","type":"mqtt out","z":"d2ce4406.096a38","name":"","topic":"domoticz/in","qos":"","retain":"","broker":"698d3ae2.89ac94","x":910,"y":440,"wires":[]},{"id":"1b27bfc1.702b","type":"function","z":"d2ce4406.096a38","name":"convert upload","func":"msg.payload = {\"command\":\"udevice\",\"idx\":4187,\"svalue\":((msg.payload).toString())};\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","x":700,"y":400,"wires":[["189797d.d35d668"]]},{"id":"a51d5d7f.c20fc","type":"function","z":"d2ce4406.096a38","name":"convert download","func":"msg.payload = {\"command\":\"udevice\",\"idx\":4188,\"svalue\":((msg.payload).toString())};\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","x":710,"y":440,"wires":[["189797d.d35d668"]]},{"id":"ae6d2d83.01969","type":"function","z":"d2ce4406.096a38","name":"turnoff trigger","func":"msg.payload = {\"command\":\"switchlight\",\"idx\":4190,\"switchcmd\":\"Off\"};\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","x":690,"y":480,"wires":[["189797d.d35d668"]]},{"id":"db285cae.0b6fd","type":"function","z":"d2ce4406.096a38","name":"split speeds up/down","func":"var upload = msg.payload.speeds.download\nvar download = msg.payload.speeds.upload\n\nreturn[{payload:upload},{payload:download}];","outputs":2,"noerr":0,"initialize":"","finalize":"","x":480,"y":440,"wires":[["1b27bfc1.702b"],["a51d5d7f.c20fc","ae6d2d83.01969"]]},{"id":"7eef8f1a.84532","type":"speedtest","z":"d2ce4406.096a38","name":"","serverId":null,"maxTime":5000,"x":280,"y":440,"wires":[["db285cae.0b6fd","b25eda27.441968"]]},{"id":"b25eda27.441968","type":"debug","z":"d2ce4406.096a38","name":"","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"payload","targetType":"msg","statusVal":"","statusType":"auto","x":450,"y":400,"wires":[]},{"id":"23fb0f0d.55217","type":"inject","z":"d2ce4406.096a38","name":"start 07:00","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"00 07 * * *","once":false,"onceDelay":0.1,"topic":"","payload":"","payloadType":"date","x":110,"y":380,"wires":[["7eef8f1a.84532","66657ad5.b708a4"]]},{"id":"66657ad5.b708a4","type":"debug","z":"d2ce4406.096a38","name":"","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"false","statusVal":"","statusType":"auto","x":300,"y":340,"wires":[]},{"id":"698d3ae2.89ac94","type":"mqtt-broker","broker":"localhost","port":"1883","clientid":"","usetls":false,"compatmode":true,"keepalive":"60","cleansession":true,"birthTopic":"","birthQos":"0","birthPayload":"","willTopic":"","willQos":"0","willPayload":""}]

which speedtest node are you using?

Is it possible that speedtest.net has changed something?

Not likely. When I trigger the flow manually, it runs fine.
Also (and this is the really weird part), when I change the trigger time to a few minutes into the future, and watch online what happens, it also runs OK...

Are you sure that it never triggers, rather than triggering at the wrong time of day?

I would bet a beer on this being the result of a known deficiency in the Inject node when used to trigger at a particular time. If node red starts before the network is fully up and the internal clock has been synced via the internet then the inject node starts off thinking it knows what time it is currently and does not resync when when the clock is set. The result is that it does trigger once a day but not at the correct time. A node-red restart fixes it.
This is most likely to happen if the Pi is wifi connected as node-red is likely to start before the wifi has connected.
The problem is in a library that node-red uses which is why it is not a trivial fix. A good solution is to use node-red-contrib-cron-plus.

If you want to check whether this might be the cause then reboot node-red and look in /var/log/syslog. You should easily be able to find the node-red startup message and if you search for Synchronized you should be able to find where the clock was synced and see whether that is around, or even after, node red started.

thank you for this explanaition. I did as you suggested: timestamps in the log are just fine.

Also, if this were the case, why did the trigger run OK when I set it to a few minutes in the future and watched it run just OK? Surely this must mean that the time in the inject node is good!
(BTW, do I get a choice of the beer? :slight_smile: )

Not sure what you mean by that.

When you edit the node it will resync and will then work again till you reboot.

I looked through the entries in the file, and saw nothing out of the ordinary. Times are consecutive.

As for the injector resynching: if that is the case, then it should run right on time after I change the trigger time! I am quite sure it doesn't. But I will leave the system as it is now, and see what happens. I set the trigger time to 07:00.
Also, the results of the speedtest is processed and stored in Domoticz devices. This is how I can see if the speedtest has run: timestamp of last update of the up/download devices that show the values.
Also I have added a trigger from Domoticz into the speedtest node at 06:00. The Domoticz log will show if the values came in at 06:00 and 07:00.

Last bit of confusion (before I turn in, it is getting late): this has worked just fine until about a week ago!!

You have to look at the log after a reboot and find where the clock synchronised (search for Synchronized) and see where that is in relation to when node-red starts up.

Do you mean that it is permanently not triggering now at the right time?
If so then add a debug node connected to the Inject node. Give it a name and set it to output to the console. Then after it has failed to run the speedtest look in syslog at that time and see if the message from the debug node is there.

OK, just to make sure, I've now set it up like this:

  1. at 06:00 Domoticz will trigger the flow;

  2. at 07:00 the injector node will trigger;

  3. at 08:00 a new cron node will trigger.

I'll look forward to the results tomorrow...

Have you added a debug node logging to the console as I suggested?

OK, we're getting somewhere. In all three triggers it results in a "speedtest: no server found".
I checked the speedtest node and found the ID field blak, which probably means it will automatically find a server.
But still it does not. And the weird thing is, when I click the trigger online, it works just fine...

So I have looked for the list of speedtest servers, selected one near to me, and inserted that number in the ID field.
We'll see tomorrow if it works...

Have a look in /var/log/syslog to see if anything unexpected is going on around that time.

What device is this running on? Is it possible it loses its internet connection or something like that when you are not interacting with it? Somebody switching off a wifi repeater overnight or similar.

Nothing unexpected around that time. I can see some MQ messages flowing before and after, so network is definitely there.
I am running a Raspberry-Pi 4B, 8GB, ethernet connected. There is nobody here to disconnect anything.

This morning the trigger ran just fine, but speedtest node gave the same error.
Now that I got this far, I can see that the topic of this thread is wrong: the problem is not with "weird time behaviour", but it should be "weird speedtest node behaviour"!
Brings me to my next conclusion: I run a remote R-Pi 3B in my summer house, with the same speedtest setup. And yes: it also has the same problem...

I think we should consider this thread "closed", and I will start a new topic on speedtest.

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