NodeJS setInterval not working for long intervals

[Quagh]

So I have NodeJS 5.1.0 running on my Pi through NVM. I built an alarm clock application and was using node-schedule to trigger a method every day at a certain hour. Worked fine for 1 day, but the second day it didn't trigger anything. They suggested I test it with a regular interval. Turns out that doesn't work as expected either.

Take the following basic example:

Code: Select all

console.log('Setting up a 60-minute interval. It is now %s', (new Date()));

setInterval(function () {
    console.log('60-minute interval trigger! It is now %s', (new Date()));
}, 1000 * 60 * 60);

console.log('BOOTED');

The method never gets triggered.

Now with another example, including a 20-minute timer:

Code: Select all

console.log('Setting up a 20 and 60-minute interval. It is now %s', (new Date()));

setInterval(function () {
    console.log('20-minute interval trigger! It is now %s', (new Date()));
}, 1000 * 60 * 20);

setInterval(function () {
    console.log('60-minute interval trigger! It is now %s', (new Date()));
}, 1000 * 60 * 60);

console.log('BOOTED');

Both trigger as expected.

I have no idea what's causing this issue. Is my node process put to sleep or something if the interval is greater than 20/30 minutes? Does the 20-minute interval keep it awake in the second example? How do I debug this?

[Heater]

Hmm...your first example works fine here:

Code: Select all

$ node -v
v5.1.0
$ node timer.js
Setting up a 60-minute interval. It is now Thu Dec 10 2015 23:48:28 GMT+0200 (EET)
BOOTED
60-minute interval trigger! It is now Thu Dec 10 2015 23:49:28 GMT+0200 (EET)
60-minute interval trigger! It is now Thu Dec 10 2015 23:50:28 GMT+0200 (EET)

[Quagh]

Hmm...your first example works fine here:

Code: Select all

$ node -v
v5.1.0
$ node timer.js
Setting up a 60-minute interval. It is now Thu Dec 10 2015 23:48:28 GMT+0200 (EET)
BOOTED
60-minute interval trigger! It is now Thu Dec 10 2015 23:49:28 GMT+0200 (EET)
60-minute interval trigger! It is now Thu Dec 10 2015 23:50:28 GMT+0200 (EET)

Yeah I know, works fine every minute, every 10, 20, and 30. But 60+ minutes is not working if I don't pair it with another shorter interval. Try the 1 hour script? `1000*60*60` = 1 hour.

[Heater]

Ok. wait a minute, err, hour....

[Quagh]

Sucks to debug tbh :p

Anyhow, is there a possibility my node script is suspended somehow? And maybe the 20-minute intervals are keeping it awake? Tried everything I can think of to find the problem.

[Heater]

I'm still waiting here...

[chrisoh]

The suspense...

[Heater]

Looks good to me.

Code: Select all

$ node timer.js
Setting up a 60-minute interval. It is now Fri Dec 11 2015 00:34:29 GMT+0200 (EET)
BOOTED
$ 60-minute interval trigger! It is now Fri Dec 11 2015 01:34:29 GMT+0200 (EET)

[Quagh]

Welll, I'm out of ideas then! Why doesn't the 60-minute interval work on my Pi?

Raspberry Pi B (first series)
Raspbian 8 Jessie
Node 5.1.0
NVM 0.29.0

[Heater]

OK, I lied last time. I was running your code on a PC.

Now I have run it on Raspbian on a Pi 2.

Notice how the carriage returns are missing in the output (I'm talking to the Pi over SSH)

How are you talking to your Pi?

Perhaps it does work but you a not seeing the output for some reason.

Code: Select all

pi@raspberrypi:~ $ uname -a
Linux raspberrypi 4.1.13-v7+ #826 SMP PREEMPT Fri Nov 13 20:19:03 GMT 2015 armv7l GNU/Linux
pi@raspberrypi:~ $ cat /etc/issue
Raspbian GNU/Linux 8 \n \l

pi@raspberrypi:~ $ node -v
v5.1.0
pi@raspberrypi:~ $ date
Fri 11 Dec 06:02:06 UTC 2015
pi@raspberrypi:~ $ node timer.js 
Setting up a 60-minute interval. It is now Fri Dec 11 2015 06:02:20 GMT+0000 (UTC)
BOOTED
60-minute interval trigger! It is now Fri Dec 11 2015 08:34:30 GMT+0200 (EET)
                                                                             60-minute interval trigger! It is now Fri Dec 11 2015 09:34:30 GMT+0200 (EET)
              60-minute interval trigger! It is now Fri Dec 11 2015 10:34:30 GMT+0200 (EET)
                                                                                           60-minute interval trigger! It is now Fri Dec 11 2015 11:34:30 GMT+0200 (EET)

[Quagh]

It runs fine here everywhere too, just not on the Pi. Kind of the issue :p I'm going to follow up on your suggestion and write some text to a file or something, so I know it's not just the output.

I'm using SSH btw.

[Heater]

This is very strange.

Can you try changing your message to:

Code: Select all

console.log('60-minute interval trigger! It is now', new Date());

or

Code: Select all

console.log('60-minute interval trigger! It is now', new Date(), '\r');

[Quagh]

Used the following code to write to a file. Doesn't get triggered. As I suspected anyway, as node-schedule didn't even trigger intervals in my application where I executed other functions too (not just logging). So it's not the logging that doesn't work, it's the interval itself.

Code: Select all

var fs = require('fs');

console.log('[Job19] Setting up a 60-minute interval to write to a file. It is now %s', (new Date()));

var log = function () {
    var string = '[Job19] 60-minute interval trigger! It is now ' + (new Date());
    
    console.log(string);
    
    fs.appendFile('job19.log', string + '\n', function (err) {
        if (err) {
            console.log('[Job19] Error writing to file job19.log');
        }
    });
};

setInterval(log, 1000 * 60 * 60);

console.log('[Job19] BOOTED');

log();

[Heater]

Weirder and weirder. We have the same node version, and the same Raspbian Jessie and the same JS code as posted here. Have you done an apt-get update, apt-get upgrade recently? I have.

[Quagh]

Weirder and weirder. We have the same node version, and the same Raspbian Jessie and the same JS code as posted here. Have you done an apt-get update, apt-get upgrade recently? I have.

I've recently updated the firmware after I flashed my SD card with the latest Raspbian. Did run an update and upgrade during that process.

Anyhow, super weird! Tried my original script again, with node-schedule. Runs just fine when I schedule a 20 minute interval alongside of it to keep my process awake (I guess). Nooo idea what's causing this, it's a clean Raspbian, NVM, and NodeJS install :/

Code: Select all

[Job21] Running a node-schedule job every hour with an interval wake script Fri Dec 11 2015 15:57:53 GMT+0100 (CET)
[Job21] Alarm triggered! It is now Fri Dec 11 2015 16:00:00 GMT+0100 (CET)
[Job21] Interval wake trigger! It is now Fri Dec 11 2015 16:17:53 GMT+0100 (CET)
[Job21] Interval wake trigger! It is now Fri Dec 11 2015 16:37:53 GMT+0100 (CET)
[Job21] Interval wake trigger! It is now Fri Dec 11 2015 16:57:54 GMT+0100 (CET)
[Job21] Alarm triggered! It is now Fri Dec 11 2015 17:00:00 GMT+0100 (CET)
[Job21] Interval wake trigger! It is now Fri Dec 11 2015 17:17:54 GMT+0100 (CET)
[Job21] Interval wake trigger! It is now Fri Dec 11 2015 17:37:54 GMT+0100 (CET)
[Job21] Interval wake trigger! It is now Fri Dec 11 2015 17:57:54 GMT+0100 (CET)
[Job21] Alarm triggered! It is now Fri Dec 11 2015 18:00:00 GMT+0100 (CET)

[Heater]

Now you have done it. I copied and pasted you new code with logging to file in it to my Pi. Sure enough an hour and a half later there is no console message and the log file has not been updated.

What on earth?

[Quagh]

Now you have done it. I copied and pasted you new code with logging to file in it to my Pi. Sure enough an hour and a half later there is no console message and the log file has not been updated.

What on earth?

Seems to be similar to my case. First few runs a few weeks ago went great. Stopped working altogether about a week or two ago, without anything changed. Go figure! I don't know if this is related to just the Raspberry Pi, but even then I can't find any similar issue and I've been searching for a while.

[Heater]

Just updated node to version v5.2.0. Still did not trigger.

Might be time to report a bug to the node.js project. But I want to investigate a bit further first.

[Quagh]

Do you think it's a node.js bug since the issue only occurs on a Raspberry Pi? I also thought setInterval() was vanilla javascript?

[Heater]

setInterval is indeed a JS thing. But it's all C++ underneath.

You have a point, this could be a bug in node, or the underlying V8 Javascript engine, or the event library they are using. We need to poke at it some more to try and find out.

[Quagh]

In what way can we further debug this?

I'm not sure if this is even related, but during occasional SSH sessions, my byobu/screen/tmux clock sometimes counts seconds faster than it should. It counts fast for 2 seconds (2 seconds = one second then) every 2 seconds. Again, not sure if related but I think anything helps at this point.

[chrisoh]

I just tried it with node 5.2 both on OSX and Jessie Lite on Pi and the 20 minute and 60 minute run fine here.

[Quagh]

I just tried it with node 5.2 both on OSX and Jessie Lite on Pi and the 20 minute and 60 minute run fine here.

Try the 60-minute interval on its own today for a while (without the 20-minute) and try the same again tomorrow or even later if you can. That was my workflow and that's how it stopped working.

[Heater]

Mine is Jessie Lite as well.

This is very weird, did work initially then didn't.

I have a few more idea for tests to do. Then it's time to file a bug report.

[chrisoh]

I just tried it with node 5.2 both on OSX and Jessie Lite on Pi and the 20 minute and 60 minute run fine here.

Try the 60-minute interval on its own today for a while (without the 20-minute) and try the same again tomorrow or even later if you can. That was my workflow and that's how it stopped working.

Will do, I'll post back..