Inject node not executing at specified time

[cpiekacz]

I don’t know what’s going on, but all of my inject nodes that are set to run in the morning (e.g. 7am on weekdays or 9am everyday) are not being executed. I have no idea why and I don’t know how to diagnose it.

What’s even more puzzling is that when I create a new node during the day to at specific hour (let’s say in 5 minutes or something), it usually gets executed. And on top of that, one day last week those nodes fired up, even though the day before and the following days they did not.

Do you guys have any idea what the hell is going on or any clues what to check?

[JGKK]

I think the first action would be to make sure it’s actually the inject nodes which fail and not something else down the line.
You could write a timestamp to a file and see if that actually happens.
You can use a function node or a moment node connected to the inject node to create a human readable time output and connect this to a file node set to append to file and add enter to every input.
This way you will get a line for every time it fired in the file.
That way you can narrow it down to if the inject node is actually the one at fault.
Also interesting would be to look in the log of the machine and see if nodered restarted unexpectedly or a connection was lost.
Does the action you expect not happen at all or delayed?

Johannes

[Colin]

If you decide it is definitely the Inject nodes, then do they eventually run or do they never run?
If they do run but at the wrong time then is the system running node-red connected via WiFi? If so it could be that you are hitting a known issue with using the Inject node in that way that if node red starts up before the system clock is synced (which can happen if the connection is via wifi) then the inject nodes may trigger at the wrong time. This is particularly noticable on something like a Pi that does not have a hardware clock so on power up it may be well off. If you restart node-red then the problem will go away (until the next power cycle).

If it is this problem then a good solution is to use node-red-contrib-cron-plus which does not suffer from this problem.

[cpiekacz]

I can see that node did not fire as there are no status messages under the following nodes, meaning they have not been fired at all since restart. The idea with logging the timestamp to a file is good one though, I'll use it in the future. I'm running the node in a VM, but I've checked the time and timezone and all is in sync so it's not a problem. For now I decided to try node-red-contrib-cron-plus (thanks a lot @Colin) as this is exactly what I was looking for! Thank you both for chiming in.

[JGKK]

@cpiekacz

no status messages under the following nodes

That is not a good indicator. Status messages are at best a tool to give quick glance state information. They are not a good persistent debug tool as just one example should nodered crash and restart unexpectedly you would loose the status information too.
It would be nice to get to the bottom of this as this would be a serious bug for an important core node like the inject.
If you have the time it would be nice if you could debug this I can provide a logging flow in a few hours when im home if you want.

[cpiekacz]

OK, I will add logging to the file to verify it. Although I'm sure that the inject node did not fire as my devices were not turned on, nor the notification was sent to my phone (from few different flows, so it's not that only one inject node is not working). When I click on the node to invoke it manually everything works as expected, that's why I'm sure it's the inject nodes fault, not the flow itself.

[JGKK]

I would probably more expect a problem with the virtual machine or a freeze or something. Do you see anything unexpected in the logs?

Edit:
I also forgot to ask, which version of node.js and nodered are you running?

[cpiekacz]

I'm using node-red 1.2.5, it's running as a part of HASS.io addon. As for the node.js, I'm not sure when to check it. The same thing with logs, I also can't find it anywhere. As tips?

[cpiekacz]

Updated to 1.2.7 yesterday but the bug is still there. Here's the flow:

[{"id":"a3348e2c.a9997","type":"api-current-state","z":"f78679f0.c6c6f8","name":"Anyone home","server":"ba0d3ced.3f2b6","version":1,"outputs":2,"halt_if":"on","halt_if_type":"str","halt_if_compare":"is","override_topic":false,"entity_id":"binary_sensor.anyone_home","state_type":"str","state_location":"payload","override_payload":"msg","entity_location":"data","override_data":"msg","blockInputOverrides":false,"x":360,"y":200,"wires":[["86da21aa.bc5dc"],[]]},{"id":"86da21aa.bc5dc","type":"api-call-service","z":"f78679f0.c6c6f8","name":"Turn on","server":"ba0d3ced.3f2b6","version":1,"debugenabled":false,"service_domain":"switch","service":"turn_on","entityId":"switch.coffee_maker","data":"","dataType":"json","mergecontext":"","output_location":"","output_location_type":"none","mustacheAltTags":false,"x":540,"y":200,"wires":[[]]},{"id":"6be55c90.9e09d4","type":"cronplus","z":"f78679f0.c6c6f8","name":"Everyday at 9am","outputField":"payload","timeZone":"Europe/Warsaw","persistDynamic":false,"commandResponseMsgOutput":"output1","outputs":1,"options":[{"name":"Everday at 9am","topic":"timestamp","payloadType":"date","payload":"","expressionType":"cron","expression":"0 0 9 * * *","location":"","offset":"0","solarType":"all","solarEvents":"sunrise,sunset"}],"x":130,"y":200,"wires":[["d7084310.10f1e","a3348e2c.a9997"]]},{"id":"5a0a0f59.75099","type":"inject","z":"f78679f0.c6c6f8","name":"Everyday at 9am","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"00 09 * * *","once":false,"onceDelay":0.1,"topic":"Inject test #1 (inject / everyday at 9am)","payload":"","payloadType":"date","x":130,"y":340,"wires":[["d73d2baa.6c0208"]]},{"id":"7ec14de8.1977b4","type":"file","z":"f78679f0.c6c6f8","name":"","filename":"/share/node-red-debug.log","appendNewline":true,"createDir":false,"overwriteFile":"false","encoding":"none","x":700,"y":400,"wires":[[]]},{"id":"bdf58f65.ce754","type":"change","z":"f78679f0.c6c6f8","name":"","rules":[{"t":"set","p":"payload","pt":"msg","to":"msg.payload & \" - \" & msg.topic","tot":"jsonata"}],"action":"","property":"","from":"","to":"","reg":false,"x":440,"y":340,"wires":[["bc8546a5.3cb1f8","7ec14de8.1977b4"]]},{"id":"bc8546a5.3cb1f8","type":"debug","z":"f78679f0.c6c6f8","name":"","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"payload","targetType":"msg","statusVal":"","statusType":"auto","x":650,"y":340,"wires":[]},{"id":"d73d2baa.6c0208","type":"moment","z":"f78679f0.c6c6f8","name":"","topic":"","input":"payload","inputType":"msg","inTz":"Europe/Warsaw","adjAmount":0,"adjType":"days","adjDir":"add","format":"","locale":"C","output":"","outputType":"msg","outTz":"Europe/Warsaw","x":420,"y":280,"wires":[["bdf58f65.ce754"]]},{"id":"d7084310.10f1e","type":"change","z":"f78679f0.c6c6f8","name":"","rules":[{"t":"set","p":"topic","pt":"msg","to":"Inject test #2 (cronplus / everyday at 9am)","tot":"str"}],"action":"","property":"","from":"","to":"","reg":false,"x":200,"y":280,"wires":[["d73d2baa.6c0208"]]},{"id":"ba0d3ced.3f2b6","type":"server","name":"Home Assistant","addon":true}]

And here is the dump from log file:

~ $ cat /share/node-red-debug.log 
2021-01-23T08:00:00.088Z - Inject test #2 (cronplus / everyday at 9am)

As you can see it's missing the line from inject node. I'm going to report it on github.