Power outage recording

The power here fails fairly often. Not every day or even every week but probably every three weeks or so. Sometimes I'm not home so I got curious as to when the power failed and when it came back on. Nothing earth shattering but I wanted to "log" these outages for my own information. I designed a flow to note when the power failed by getting the time every minute and writing to context. Then when power comes on I note the time and subtract the two. I don't need split second timing so this seemed like a reasonable method. The problem is when the power comes back on sometimes I get negative duration numbers. Again sometimes....
I have been over my code and my methodology and I see nothing wrong with either. If someone has a better method I'm all for that but although this isn't life critical I'm now bound and determined to either fix my flow or find a way that does work consistently.

[{"id":"8c2a3f8f.ef9d8","type":"tab","label":"Power Fail","disabled":false,"info":""},{"id":"4861c45c.b4c5ac","type":"ui_template","z":"8c2a3f8f.ef9d8","group":"78f5f4b2.0d39f4","name":"power off duration","order":4,"width":0,"height":0,"format":"<div>\n<md-button class=\"md-button mine-button\"\n    data-payload>{{msg.payload}}\n</md-button>\n</div>","storeOutMessages":true,"fwdInMessages":true,"resendOnRefresh":true,"templateScope":"local","x":910,"y":360,"wires":[[]]},{"id":"6a70b25f.c5427c","type":"ui_template","z":"8c2a3f8f.ef9d8","group":"78f5f4b2.0d39f4","name":"power on time","order":2,"width":0,"height":0,"format":"<div>\n   <md-button class=\"md-button mine-button\"\n    data-topic=\"target\"\n    data-payload=\"1\">{{msg.payload}}\n   </md-button>\n</div>","storeOutMessages":true,"fwdInMessages":true,"resendOnRefresh":true,"templateScope":"local","x":900,"y":320,"wires":[[]]},{"id":"6e54f4cc.bc10f4","type":"ui_template","z":"8c2a3f8f.ef9d8","group":"78f5f4b2.0d39f4","name":"power on header","order":1,"width":0,"height":0,"format":"\n<div>\n   <md-button class=\"md-button mine-button\"\n    data-topic=\"target\"\n    data-payload=\"1\">Power On Time\n   </md-button>\n</div>","storeOutMessages":true,"fwdInMessages":true,"resendOnRefresh":true,"templateScope":"local","x":370,"y":140,"wires":[[]]},{"id":"33c7c87c.f84a28","type":"ui_template","z":"8c2a3f8f.ef9d8","group":"78f5f4b2.0d39f4","name":"Duration of power off header","order":3,"width":0,"height":0,"format":"\n<div>\n   <md-button class=\"md-button mine-button\"\n    data-topic=\"target\"\n    data-payload=\"1\">Power Off Duration\n   </md-button>\n</div>","storeOutMessages":true,"fwdInMessages":true,"resendOnRefresh":true,"templateScope":"local","x":680,"y":140,"wires":[[]]},{"id":"1290440ad0071cae","type":"function","z":"8c2a3f8f.ef9d8","name":"display","func":"let z = flow.get('powerOnTime');\n\nlet y = flow.get('durationTime');\n\nmsga = {\n    payload: z,\n}\n\nmsgb = {\n    payload: y,\n}\n\nnode.status({fill:\"blue\",shape:\"dot\",text:\"duration\"  + y});\n\nreturn [msga,msgb];","outputs":2,"noerr":0,"initialize":"","finalize":"","libs":[],"x":640,"y":340,"wires":[["6a70b25f.c5427c"],["4861c45c.b4c5ac"]]},{"id":"4f71468e6af2473c","type":"function","z":"8c2a3f8f.ef9d8","name":"open gate","func":"msg = {\n    topic: 'control',\n    payload: 'open'\n}\n\nnode.status({fill:\"blue\",shape:\"dot\",text:msg.payload});\n\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":930,"y":500,"wires":[["6d9cd422f6eb8d66"]]},{"id":"6d9cd422f6eb8d66","type":"gate","z":"8c2a3f8f.ef9d8","name":"gate 2","controlTopic":"control","defaultState":"closed","openCmd":"open","closeCmd":"close","toggleCmd":"toggle","defaultCmd":"default","statusCmd":"status","persist":false,"storeName":"default","x":250,"y":340,"wires":[["da8fa542bc9a4a1b"]]},{"id":"e0fe68ba037f8422","type":"link in","z":"8c2a3f8f.ef9d8","name":"power fail power on in","links":["88f921a718be8937"],"x":135,"y":500,"wires":[["1328d2d51c18057b","53ff67ac3914f31d"]]},{"id":"d3d8ea7e47a9bff4","type":"link in","z":"8c2a3f8f.ef9d8","name":"pwr fail minute in","links":["73a9a142252c1869"],"x":135,"y":340,"wires":[["6d9cd422f6eb8d66"]]},{"id":"2768838c8954f069","type":"moment","z":"8c2a3f8f.ef9d8","name":"pwr on","topic":"topic","input":"payload","inputType":"msg","inTz":"America/Devver","adjAmount":0,"adjType":"days","adjDir":"add","format":"ddd MMM DD YYYY H:mm:ss","locale":"en-US","output":"","outputType":"msg","outTz":"America/Denver","x":550,"y":500,"wires":[["abb7e70be6844e3b"]]},{"id":"1328d2d51c18057b","type":"function","z":"8c2a3f8f.ef9d8","name":"pwr on date/time","func":"var d = new Date();\nvar n = d.getTime();\n\nmsg = {\n    payload: n,\n    topic: 'epoch'\n}\n\nflow.set('powerOn',msg.payload);\n\nnode.status({fill:\"blue\",shape:\"dot\",text:msg.payload});\n\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":370,"y":500,"wires":[["2768838c8954f069"]]},{"id":"abb7e70be6844e3b","type":"function","z":"8c2a3f8f.ef9d8","name":"flow pwr on","func":"flow.set('powerOnTime',msg.payload);\n\nnode.status({fill:\"blue\",shape:\"dot\",text:msg.payload});\n\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":730,"y":500,"wires":[["4f71468e6af2473c"]]},{"id":"da8fa542bc9a4a1b","type":"function","z":"8c2a3f8f.ef9d8","name":"set pwr off","func":"var d = new Date();\nvar n = d.getTime();\n\nmsg = {\n    payload: n,\n    topic: 'epoch'\n}\n\n\nflow.set('powerOff',msg.payload);\n\nnode.status({fill:\"blue\",shape:\"dot\",text:msg.payload});\n\n\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":410,"y":340,"wires":[["1290440ad0071cae","d7707b5dfbd8728d"]]},{"id":"d7707b5dfbd8728d","type":"moment","z":"8c2a3f8f.ef9d8","name":"pwr off date/time","topic":"","input":"payload","inputType":"msg","inTz":"America/Denver","adjAmount":0,"adjType":"days","adjDir":"add","format":"ddd MMM DD YYYY H:mm:ss","locale":"en-US","output":"payload","outputType":"msg","outTz":"America/Denver","x":610,"y":240,"wires":[["0ad26863b208a127"]]},{"id":"0ad26863b208a127","type":"function","z":"8c2a3f8f.ef9d8","name":"english pwr off","func":"flow.set('powerOffTime',msg.payload);\n\nnode.status({fill:\"blue\",shape:\"dot\",text:msg.payload});\n\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":840,"y":240,"wires":[[]]},{"id":"53ff67ac3914f31d","type":"function","z":"8c2a3f8f.ef9d8","name":"duration seconds","func":"\nlet z = flow.get('powerOn');\n\nlet y = flow.get('powerOff');\n\nlet w = z - y;\n\nlet x = (w / 1000); //seconds\n\nflow.set('duration',x);\n\nnode.status({fill:\"blue\",shape:\"dot\",text:x});\n\nreturn msg;\n","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":370,"y":580,"wires":[["5cd5862a86d0ce5a"]]},{"id":"5cd5862a86d0ce5a","type":"function","z":"8c2a3f8f.ef9d8","name":"duration time","func":"\nlet z = flow.get('duration');\n\nlet v =secondsToHms(z);\n\nfunction secondsToHms(d) {\n    d = Number(d);\n    var h = Math.floor(d / 3600);\n    var m = Math.floor(d % 3600 / 60);\n    var s = Math.floor(d % 3600 % 60);\n\n    var hDisplay = h > 0 ? h + (h == 1 ? \" hr, \" : \" hrs, \") : \"\";\n    var mDisplay = m > 0 ? m + (m == 1 ? \" min, \" : \" mins, \") : \"\";\n    var sDisplay = s > 0 ? s + (s == 1 ? \" sec\" : \" secs\") : \"\";\n    return hDisplay + mDisplay + sDisplay; \n}\n\nflow.set('durationTime',v);\n\nnode.status({fill:\"blue\",shape:\"dot\",text:v});\n\nreturn null;","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":630,"y":580,"wires":[[]]},{"id":"ee5b8013115e178b","type":"inject","z":"8c2a3f8f.ef9d8","name":"","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"1","payloadType":"num","x":130,"y":580,"wires":[["1328d2d51c18057b","53ff67ac3914f31d"]]},{"id":"300ae3cfa4d6de3e","type":"inject","z":"8c2a3f8f.ef9d8","name":"close","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"1","payloadType":"num","x":90,"y":220,"wires":[["3842d51ff46668ce"]]},{"id":"3842d51ff46668ce","type":"function","z":"8c2a3f8f.ef9d8","name":"","func":"msg = {\n    topic: 'control',\n    payload: 'close'\n}\n\nnode.status({ fill: \"blue\", shape: \"dot\", text: msg.payload });\n\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":270,"y":220,"wires":[["6d9cd422f6eb8d66"]]},{"id":"9c27943a82e3abaf","type":"comment","z":"8c2a3f8f.ef9d8","name":"fires every minute","info":"","x":150,"y":300,"wires":[]},{"id":"5136f83e29ba33de","type":"comment","z":"8c2a3f8f.ef9d8","name":"fires at power on","info":"","x":140,"y":460,"wires":[]},{"id":"78f5f4b2.0d39f4","type":"ui_group","name":"Power","tab":"f31d1a37.01d2","order":1,"disp":false,"width":"6","collapse":false},{"id":"f31d1a37.01d2","type":"ui_tab","name":"Power","icon":"fa-power-off","order":12,"disabled":false,"hidden":false}]

Note: one non core node node-red-contrib-simple-gate
Any input appreciated.
Thanks

What hardware and OS are you running on?
Is the device connected via wi-fi or Ethernet?

Possibly node red is starting up before the internet is up, and specifically before the clock has been synchronised.

Running a Pi4 with Pi OS or raspbian or whatever they call it now. That is an interesting thought about the internet. I would think that the Pi would keep reasonable time over a power outage an assumption that may be entirely wrong. The internet here when power goes out takes a very long time to come up. Perhaps what I need to do is first look at the hardware clock to see if there is some type of power off time keeping. Next, rewrite to check for internet up before I check the time. Some things to think on.

The Pi does not have a hardware clock so the OS makes a guess at the time when it boots (I don't know how). Then that is corrected when the clock is synchronised via the internet.

Running a Pi (or any modern computer/os) on an unreliable power source is perhaps not the best solution. There are many ups hats available which reports the power status over i2c and give you enough battery time to record the power failure and then do a save shutdown. Or use a bigger ups with usb monitoring. I lost more than one sd card or valuable data on unintentional power losses over the years.

Redid the flow to wait for a good ping before it tries to do the time.
As for the power and UPS's, I suppose it would be nice to invest in a few dozen UPS's to support my toys. Not much I can do about the whole house going down, however I have good backups on all my Pi's so if I lose a card or two it doesn't really matter. There really isn't any data per se to lose as all they do is monitor a few things and react accordingly so if a card goes and I stick in a new one it's a hassle but no long term issues. I will however look into a solution when the finance committee (wife) isn't looking too close.

If you look in the nodered.service file, you will see a commented out line that lets it wait until the time is sync'd correctly..... it is left commented out as otherwise it would hang if sync never happens... for a devices that isn't internet connected for example.

Here is a trick i use to find time for power outages.
I read the last line of a log file, the log file must be one that is update frequently and sarts logging after node-red has started. I then parse out the time and date. I add the year and then convert to a timestamp. I then subtract that timestamp from a new timestamp and output the difference in milliseconds

[{"id":"aabb5447.ff2c98","type":"inject","z":"b779de97.b1b46","name":"on reboot","props":[{"p":"payload"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"","payloadType":"str","x":170,"y":3580,"wires":[["504b1895.3296d"]]},{"id":"504b1895.3296d","type":"exec","z":"b779de97.b1b46","command":"tail -1 /data/log/logcat.log","addpay":false,"append":"","useSpawn":"false","timer":"","oldrc":false,"name":"","x":420,"y":3580,"wires":[["ed5ac9e2.9a61"],[],[]]},{"id":"ed5ac9e2.9a61","type":"change","z":"b779de97.b1b46","name":"","rules":[{"t":"set","p":"payload","pt":"msg","to":"$millis() -  $toMillis(\t   $moment().format(\"YYYY\") & \"-\" & \t$join($split($$.payload,\" \", 2), \"T\")\t)\t","tot":"jsonata"}],"action":"","property":"","from":"","to":"","reg":false,"x":680,"y":3540,"wires":[["7cdf69d7.d8478"]]},{"id":"7cdf69d7.d8478","type":"debug","z":"b779de97.b1b46","name":"","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","statusVal":"","statusType":"auto","x":850,"y":3580,"wires":[]}]

Not sure how that helps if the device starts logging before the time sync has occurred. The time stamps in the log will just be wrong.