setInterval callback function unexpected halt

[newbreach]

There is a setInterval method in the express project. When the project has been running for a month or so, there is no error, the project does not stop, but the callback of the setInterval is no longer executed.

like this :
setInterval(function(){
//do samething
console.log(Date.now());
},500);
A month later, no output is available, but the application process is robust.

[tkarls]

This is interesting. I have an app with some code looking like this:

function doSomething() {
    promiseReturningFunction().then((data) => {
        //do some
    }).catch((error) => {
        //log error
    }).then(() => {
        setTimeout(doSomething, 5000);
    });
}

This is just meant to run these code blocks forever. Then suddenly a few installations stopped working recently. The app still responds to api requests and new timers that are set during for example an api call is executed.

However, the doSomething functions are no longer being exectuted. It is as if the event queue at some point just was emptied or something.

My installations that are having this problem are running node 10.4.1 or 10.6.0 depending on when they were upgraded.

A bug in the core nodejs is not my first thought but I cant find a logical explanation for my app to suddenly drop 5-6 timer constructs like this that has worked for a few years before....

[targos]

@nodejs/timers

[benjamingr]

For what it's worth you are not supposed to rely on timers staying running for a month. That said, I haven't run into this sort of thing before - even on Node servers with an uptime of more than a month.

@tkarls

The app still responds to api requests and new timers that are set during for example an api call is executed.

It is very likely that promiseReturningFunction never fulfilled or that you are returning a promise that was pending forever from either the catch or the then below it - or the then below is never executed.

Also note that is not a great way to write Node.js code (and this is core's fault IMO). Are you using async_hooks and some form of instrumentation? Can you check the logs for unhandledRejections?

[tkarls]

@benjamingr yea that would of course be the obvious conclusion and what I initially thought until I realized it wall all timers at once. I just can't figure out how that problem suddenly occurred on 6 different places in the code.

The "background tasks" are not depending on each other and hasn't been changed for a loong time. Had it been one timer that stopped that's one thing but all at the same time? This was also on 7 different servers running the same app in different locations and with a similar up-time. Like 3-4 weeks or so until the issue occurred.

Perhaps there are a better construct to keep some "background tasks" executing but I thought this was simple enough to do its job.

Not familiar with the async_hooks and logs are not saved (which is a flaw...) :(

[benjamingr]

@tkarls to be clear, I am not accusing you of writing code problematically - I am saying Node should guide users to safer ways to write code and make them "obvious".

If there is a way to get the "unhandledRejection" warnings then there is a very high chance you'll see it there. I've seen this before several times:

• server runs for days.
• there is a networking "hickup" and stuff fails for just a second or two.
• recurring tasks fail, but since Node doesn't exit on promise unhandled rejection warnings the server chugs on.
• Many people don't log warnings in production.

I'm getting "off" timer land and into "promise debugging land" here - just saying this is entirely on our radar and something we're thinking and talking about improving. Also it's possible your problem was entirely different and we do have a bug in setInterval - so take everything I say (guess) with a grain of salt.

Perhaps there are a better construct to keep some "background tasks" executing but I thought this was simple enough to do its job.

Typically, not on the server and using something that does scheduling - either what your cloud provides, crons if you're on a VM, k8s/cron jobs etc. I also warmly recommend turning on warnings (in production) for safety and using an APM (application performance monitoring) tool and setting up alerts for uptime and certain tasks.

Again, I strongly believe this is an issue with Node's user experience (not your or most people's code) and I feel strongly that Node (well, us) should fix it.

[newbreach]

As tkarls says, I have a similar situation; @benjamingr thank you for your advice on coding, but I can't use cron because I use doSomething to trigger about 400-500 milliseconds.

[benjamingr]

@newbreach in a similar situation - what sort of code do you have in the setTimeout?

[tkarls]

@benjamingr no problem, I didn't feel particularly 'accused' because it it was an easy fix I could do to my code I want to know about it so I can fix the problem :D

Thanks for your advises. Using external schedule trigging had not even occurred to me! Today the node process is kept alive using a systemd service that limits memory and tasks and restarts the node process if needed while ensuring always up. I'm sure there are more advanced monitors.

But back to the issue at hand. I hear what you are saying about unhandled rejections but I do have that catch before the then that sets the timer. So any error or exception should be caught I think (I have double checked that all promises are returned and not just created locally too).

One of my "workers" query an api over the network. Another checks a local database and talks to a local service. A third one is querying the NTP status on the server etc. Most of the functions are rather small and easy to overview. So I find it improbable (but I suppose not impossible) that all these functions have a bug in them that manifest at the same time. This happened on several servers during the summer (running 10.4.1-10.6.0) but not on any of our 60+ servers running <= 9.8.0. Granted our sw is also newer on the newer installations but a few of the "workers" hasn't been changed in well over a year.

The only thing that doesn't indicate a bug/change in setTimeout/setInterval to me is probably that there isn't 500 people reporting it already due to node being so popular. Which I can agree is a pretty strong indication too...

I do appreciate you insights and guesses though. That is all I'm doing right now too :)

[newbreach]

@benjamingr

My code logic is probably like this

1. accept the HTTP request and send the message to the TCP client.

2. the request callback method is added to the queue.

3. receive the message of TCP client. If a reply is received, the callback method is removed from the queue and the callback is executed. The content of the callback method is "response.write" ({"success": true}).

4. timer checks whether the request message is more than 40 seconds. If it is over, remove the callback method and execute it.

The part of the code is as follows:

setInterval(function () {
  let cbs = [];
  for (let key of callbackQueue.keys()) {
    let item = callbackQueue.get(key)
    if (item && Date.now() - item.time >= 40000) {
      callbackQueue.delete(key);
      cbs.push(item);
    }
  }
  for (let i in cbs) {
    cbs[i].cb.call(cbs[i].thisArg, new util.BusinessError('network fail', 4001));
  }
}, 200);

thanks！

_{Edit by @Fishrock123 - code formatting}

[newbreach]

Click the mistake, I'm sorry

[benjamingr]

I'm trying to reproduce this (with NODE_DEBUG=*, and the code setInterval(() => console.log('ping', Date.now()), 500);) - I'll see if I can hit it after a day or two. Otherwise I'm not sure how I can do "time dilation" and run it faster in a VM - I'll look into that.

Edit: there appears to be a way to test it in virtualbox if anyone is interested in taking a stab sooner: https://superuser.com/a/1022317/248212

[Fishrock123]

This just became a problem recently? Like, in Node 10 ... or something else?