# Inject node runs late sometimes

**URL:** <https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365>\
**Category:** General\
**Created:** [20 July 2020 01:05 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365 "2020-07-20T01:05:58Z")\
**Posts on this page:** 20\
**Page:** 2

<div class="post-metadata">

**Author:** ![ristomatti](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/ristomatti/32/5857_2.png) [@ristomatti](https://discourse.nodered.org/u/ristomatti)\
**Post date:** [24 July 2020 19:31 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/21 "2020-07-24T19:31:43Z")

</div>

A similar result here also. I just dumbly had flogger write json of complete msg objects so not pasting it here.

---

<div class="post-metadata">

**Author:** ![murraybrandon](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/murraybrandon/32/26015_2.png) [@murraybrandon](https://discourse.nodered.org/u/murraybrandon)\
**Post date:** [26 July 2020 23:40 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/22 "2020-07-26T23:40:43Z")

</div>

I was getting:  
09:32:00  
10:32:00  
11:32:00  
12:32:00  
13:32:00  
...  
etc.

But then I did a sudo reboot of the raspberry Pi and it started working fine.  
If it's no trouble, I would appreciate if a few of you could leave the test flows running for 2-3 weeks to see if it happens. So far, it's been a week for me and not happened again.

---

<div class="post-metadata">

**Author:** ![Andrei](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/andrei/32/10446_2.png) [@Andrei](https://discourse.nodered.org/u/Andrei)\
**Post date:** [27 July 2020 01:34 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/23 "2020-07-27T01:34:50Z")

</div>

> [@murraybrandon](#):
>
> I am running Node Red on a Raspberry Pi,

I wonder how the clock in your Raspberry Pi is being updated. If you don´t have a RTC module installed then the update is normally via internet connection. There are a few things that can do wrong with time update.

What is OS version in your Raspberry ? You can check with command line: `lsb_release -a`

What do you get if you issue below command ?

`sudo systemctl status systemd-timesyncd`

---

<div class="post-metadata">

**Author:** ![murraybrandon](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/murraybrandon/32/26015_2.png) [@murraybrandon](https://discourse.nodered.org/u/murraybrandon)\
**Post date:** [27 July 2020 06:24 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/24 "2020-07-27T06:24:36Z")

</div>

That is a good question (see the dump below below).

```auto
pi@raspberrypi:~ $ lsb_release -a
No LSB modules are available.
Distributor ID: Raspbian
Description: Raspbian GNU/Linux 10 (buster)
Release: 10
Codename: buster
pi@raspberrypi:~ $ sudo systemctl status systemd-timesyncd
Warning: The unit file, source configuration file or drop-ins of systemd-timesyncd.service changed on disk. Run 'systemctl daemon-reload' to reload units.
● systemd-timesyncd.service - Network Time Synchronization
   Loaded: loaded (/lib/systemd/system/systemd-timesyncd.service; enabled; vendor preset: enabled)
  Drop-In: /lib/systemd/system/systemd-timesyncd.service.d
           └─disable-with-time-daemon.conf
   Active: active (running) since Thu 2020-07-23 10:23:22 AEST; 4 days ago
     Docs: man:systemd-timesyncd.service(8)
 Main PID: 278 (systemd-timesyn)
   Status: "Synchronized to time server for the first time 193.40.0.5:123 (2.debian.pool.ntp.org)."
    Tasks: 2 (limit: 2200)
   Memory: 3.5M
   CGroup: /system.slice/systemd-timesyncd.service
           └─278 /lib/systemd/systemd-timesyncd

Jul 23 10:23:21 raspberrypi systemd[1]: Starting Network Time Synchronization...
Jul 23 10:23:22 raspberrypi systemd[1]: Started Network Time Synchronization.
Jul 23 10:24:03 raspberrypi systemd-timesyncd[278]: Synchronized to time server for the first time 193.40.0.5:123 (2.debian.pool.ntp.org).

```

---

<div class="post-metadata">

**Author:** ![Andrei](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/andrei/32/10446_2.png) [@Andrei](https://discourse.nodered.org/u/Andrei)\
**Post date:** [27 July 2020 14:50 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/25 "2020-07-27T14:50:12Z")

</div>

> [@murraybrandon](#):
>
> `sudo systemctl status systemd-timesyncd`

Your results tell us that the systemd-timesync daemon is activated. This is good. Also shows that the time was synchronized with a time server a couple of days ago. It will be synchronized again after OS reboot (you know that as you mentioned in the OP that you could solve the issue rebooting the device every night). I understand that you will experience time drift between time syncs.

There is a way to force a time sync without a reboot.

You can do some experimentation with this sequence of commands (thanks if you can share afterwards):

```auto
timedatectl status
timedatectl timesync-status
journalctl -u systemd-timesyncd
sudo systemctl restart systemd-timesyncd

```

The last command is expected to resync.

You can now repeat the first three commands and see if the Raspberry time reflects the actual one (eliminating accumulated diffs).

---

<div class="post-metadata">

**Author:** ![Colin](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/colin/32/17040_2.png) [@Colin](https://discourse.nodered.org/u/Colin)\
**Post date:** [27 July 2020 15:42 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/26 "2020-07-27T15:42:04Z")

</div>

I don't think it is the system time is it? The time readout is correctly shown as 09:32:00 isn't it?  
Also any such error would be seen in the system clock itself (running `date` in a terminal for example).

---

<div class="post-metadata">

**Author:** ![Andrei](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/andrei/32/10446_2.png) [@Andrei](https://discourse.nodered.org/u/Andrei)\
**Post date:** [27 July 2020 16:12 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/27 "2020-07-27T16:12:25Z")

</div>

I am not sure too. What makes me think it is worth investigating are these quoted statements:

> I am sure if I force reboot the device every night it will hide the error

> 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.

> But then I did a sudo reboot of the raspberry Pi and it started working fine.

---

<div class="post-metadata">

**Author:** ![Andrei](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/andrei/32/10446_2.png) [@Andrei](https://discourse.nodered.org/u/Andrei)\
**Post date:** [28 July 2020 20:34 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/28 "2020-07-28T20:34:24Z")

</div>

I programmed on Raspberry Pi to send me a Telegram message every day at 5 pm. I just receive the first message, with a delay of 17 minutes. 😬

The flow inquires the Raspberry Pi clock and send the information along with other data. The clock received in the payload is 5:17pm.

My first thought now is that the issue is not related to the Raspberry Pi clock. Back to the square one in my investigation. Interesting case indeed.

---

<div class="post-metadata">

**Author:** ![murraybrandon](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/murraybrandon/32/26015_2.png) [@murraybrandon](https://discourse.nodered.org/u/murraybrandon)\
**Post date:** [28 July 2020 23:25 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/29 "2020-07-28T23:25:48Z")

</div>

Fantastic that it's not just me! 😉 I have not been able to reproduce it again yet, so I'll be patient.  
If it happens to you again, please log into the Pi console and do a date command to see what time Raspbian thinks it is.

---

<div class="post-metadata">

**Author:** ![Trying\_to\_learn](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/trying_to_learn/32/28400_2.png) [@Trying\_to\_learn](https://discourse.nodered.org/u/Trying_to_learn)\
**Post date:** [29 July 2020 05:49 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/30 "2020-07-29T05:49:04Z")

</div>

Ok, quick thought:

The time it does _what ever_ gets later and later.

In the code when it sends the message, set a part of the message with the time it thinks it is.

The reasoning is:

You want this to happen at (eg) 17:00.

It is happening at 17:15.

**You** know it is 17:15, but does the machine?

If the message which is created at "17:00" has a (human readable) timestamp and it says 17:15...... Then you know the problem is _else where_.

But if it says 17:00 in the message and you see it is 17:15 (or what ever) you know it is clock drift.

That will/would/should go a long way to identify where the problem is.

---

<div class="post-metadata">

**Author:** ![ristomatti](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/ristomatti/32/5857_2.png) [@ristomatti](https://discourse.nodered.org/u/ristomatti)\
**Post date:** [29 July 2020 10:17 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/31 "2020-07-29T10:17:31Z")

</div>

This is not an attempt to solve the issue but more of a related speculation. Has anyone experimented what happens if a Node.js timer has been set using `setTimeout` and the system time is changed while it's running (NTP sync for example)?

From the perspective of the `setTimeout` function's API, I would expect it to trigger approximately after the given time in milliseconds even if the system time changes meanwhile. If this would be the case, then I could very well see it failing as a cron timer which should be tied to a date and time and not how far the scheduled time is related to the start time.

---

<div class="post-metadata">

**Author:** ![Colin](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/colin/32/17040_2.png) [@Colin](https://discourse.nodered.org/u/Colin)\
**Post date:** [29 July 2020 12:37 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/32 "2020-07-29T12:37:44Z")

</div>

That is an interesting thought. I wonder what happens if node red starts up before the network gets going so the time can sync.

---

<div class="post-metadata">

**Author:** ![ristomatti](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/ristomatti/32/5857_2.png) [@ristomatti](https://discourse.nodered.org/u/ristomatti)\
**Post date:** [29 July 2020 13:02 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/33 "2020-07-29T13:02:48Z")

</div>

At least the systemd service description on Linux requires network to start first (when installed using the official install script). But it likely does not guarantee for the time sync service to be started first, let alone a sync to complete first.

---

<div class="post-metadata">

**Author:** ![Andrei](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/andrei/32/10446_2.png) [@Andrei](https://discourse.nodered.org/u/Andrei)\
**Post date:** [29 July 2020 13:27 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/34 "2020-07-29T13:27:10Z")

</div>

> [@Trying\_to\_learn](#):
>
> **You** know it is 17:15, but does the machine?

Hi Andrew, I hear you.

What I did in my first testing was to program the inject node to send a telegram message at 17:00. The inject node is connected to an exec node that read the system time with:

`timedatectl status | grep -i 'local time' | cut -c 28-`

This payload will be sent in a Telegram message.

My mobile phone receives the message at 17:17 and the message content says the system time was 17:17.

Event if the final behaviour is totally unexpected I have no reasons to believe there is any bug in the inject node. I did the above testing in a production machine that is under heavy load (just run Chrome on a Raspian Desktop to get your Raspberry Pi 3 on the knees). I ran the very same flow in a development machine (the difference it is Raspberry Pi 4 - I don´t have right now a spare model 3). The final result is totally different. I am receiving the Telegram notifications exactly at the programmed time (10:00 and the payload says the system time , at the time the message was crafted was 10:00). Keep investigating.

---

<div class="post-metadata">

**Author:** ![Andrei](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/andrei/32/10446_2.png) [@Andrei](https://discourse.nodered.org/u/Andrei)\
**Post date:** [29 July 2020 14:28 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/35 "2020-07-29T14:28:04Z")

</div>

> [@ristomatti](#):
>
> From the perspective of the `setTimeout` function's API, I would expect it to trigger approximately after the given time in milliseconds

Nice and interesting point ! Great insight.

My guess: setTimeout does not read system time for its working. It will launch a callback function within x milliseconds. We both agree on that.

Now, to the second point of your speculation. The inject node uses cron library and cron will read the system time. If I change the system time in the middle (and I understand that the fake clock in the Raspian OS does that from times to times) then we may observe some unexpected behaviour. Indeed good thought. I will try to simulate this case.

Edit: There is already someone digging into this kind of problem in cron library (used by Node-RED).

> <https://github.com/kelektiv/node-cron/issues/514>
>
> Hi, I have been watching a server for quite some time, where sometimes the syste…m time changes by a few seconds. Several times I came across a situation where one of the jobs stopped just at the moment of time change. I researched the library and found the problem:
> If during the execution of the getTimeout function (https://github.com/kelektiv/node-cron/blob/master/lib/time.js#L201) between the calculation of the sendAt time and the current time, the system time moves a few seconds forward, then it can it turns out that timeout is calculated negative and the job will stop with this line (https://github.com/kelektiv/node-cron/blob/master/lib/job.js#L190).
> 
> I created a pr in my repository fork, in which, using the synon, I simulated the time change at the right moment. My job starts every 5 seconds and I move the time 7 seconds forward, after which the job stops.
> https://github.com/psixdev/node-cron/pull/1/files
> 
> I understand that an accidental change in the time on the server is an unlikely event, but I believe that the problem really exists and it is serious. I suppose a similar bug can occur during the transition to daylight saving time (or vice versa), if this transition accidentally coincides with the call to the getTImeout function.
> 
> What do you think about this problem?

---

<div class="post-metadata">

**Author:** ![Colin](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/colin/32/17040_2.png) [@Colin](https://discourse.nodered.org/u/Colin)\
**Post date:** [29 July 2020 15:28 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/36 "2020-07-29T15:28:38Z")

</div>

> [@ristomatti](#):
>
> At least the systemd service description on Linux requires network to start first

Yes, the network service is started, that does not mean WiFi is connected or the internet is accessible.

---

<div class="post-metadata">

**Author:** ![dceejay](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/dceejay/32/38_2.png) [@dceejay](https://discourse.nodered.org/u/dceejay)\
**Post date:** [29 July 2020 15:33 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/37 "2020-07-29T15:33:17Z")

</div>

You could change the service to try to wait for them... but then you get into the situation where it won't start unless they are really running and occasionally you may want to do that... like when/if your internet connection is broken.

And of course (currently at least) there are two times a year when the clock do suddenly shift by an hour...

---

<div class="post-metadata">

**Author:** ![ristomatti](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/ristomatti/32/5857_2.png) [@ristomatti](https://discourse.nodered.org/u/ristomatti)\
**Post date:** [29 July 2020 15:51 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/38 "2020-07-29T15:51:09Z")

</div>

Quite a coincidence since it's been reported 3 hours ago!

---

<div class="post-metadata">

**Author:** ![dceejay](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/dceejay/32/38_2.png) [@dceejay](https://discourse.nodered.org/u/dceejay)\
**Post date:** [29 July 2020 15:55 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/39 "2020-07-29T15:55:07Z")

</div>

> [@ristomatti](#):
>
> reported 3 hours ago!

according to who's clock ... ? 😉

---

<div class="post-metadata">

**Author:** ![Colin](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/colin/32/17040_2.png) [@Colin](https://discourse.nodered.org/u/Colin)\
**Post date:** [29 July 2020 19:56 UTC](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365/40 "2020-07-29T19:56:28Z")

</div>

> [@dceejay](#):
>
> there are two times a year when the clock do suddenly shift by an hour

The system clock doesn't change, just the displayed local time. I assume the inject node (or the module it uses under the hood) copes with DST somehow.

[Previous page](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365.md?page=1)

[Next page](https://discourse.nodered.org/t/inject-node-runs-late-sometimes/30365.md?page=3)