"Error: WARNING: Date in past. Will never be fired." crash inside callback wrapper

[Cyberbeni]

Description

I was using 2.2.0 but cross-checking the code with 3.1.6, this issue still exists.

I have a daily schedule to set up triggers for the day:
https://github.com/Cyberbeni/node-red-contrib-cb-suncron/blob/3b3441c95a0fb4ab2356e906c810d3ef0e8de80f/src/SuncronLocation.ts#L29-L34

Setting up the jobs looks like this: https://github.com/Cyberbeni/node-red-contrib-cb-suncron/blob/3b3441c95a0fb4ab2356e906c810d3ef0e8de80f/src/Suncron.ts#L44-L59

I had this Node-RED crash today at the time that the cron job should have fired (and probably had multiple similar ones in the past as I had some skipped schedules):

9 Dec 15:49:24 - [red] Uncaught Exception:
9 Dec 15:49:24 - [error] Error: WARNING: Date in past. Will never be fired.
    at CT.sendAt (/data/node_modules/cron/lib/time.js:177:12)
    at CT.getTimeout (/data/node_modules/cron/lib/time.js:202:29)
    at Timeout.callbackWrapper [as _onTimeout] (/data/node_modules/cron/lib/job.js:141:36)
    at listOnTimeout (node:internal/timers:559:17)
    at processTimers (node:internal/timers:502:7)

Expected Behavior

If diff is more than 0 but newTimeout would be negative (because slow hardware or whatever), we shouldn't throw an error that can't be handled.

Actual Behavior

Occasional crash with the included call stack.

Possible Fix

Treat this.cronTime.getTimeout() throwing an error as if diff was not more than 0.

Steps to Reproduce

Remove if (diff > 0) check and insert a 1 second sleep before this line to imitate slow hardware:

node-cron/src/job.ts

Line 235 in d614393

let newTimeout = this.cronTime.getTimeout();

Then just setup a job with a single Date and an onTick callback.

Context

see description

Your Environment

• cron version: 2.2.0
• NodeJS version: nodered/node-red:2c51c6aaed04 docker container
• Operating System and version: nodered/node-red:2c51c6aaed04 docker container
• TypeScript version (if applicable): 4.9.5
• Link to your project (if applicable): https://github.com/Cyberbeni/node-red-contrib-cb-suncron

[vy-npn]

I face this issue too, with the difference between luxon.DateTime.local() and the date being 1 millisecond.
cron version: 2.3.1

[sheerlox]

What would be the best behavior in your opinion?

If your software is running on under-sized hardware / having bottlenecks in the implementation, and the planned execution date is missed, should we try to catch back (i.e. execute the tick ASAP)?

Some use cases might not go well with this, and having this error thrown indicates that to maintain consistency in your schedule, you should either upgrade the hardware you're running on or address potential bottlenecks in your software.

Let's get the discussion going on this, please let us know your thoughts.

[Cyberbeni]

My hardware is at 4% CPU usage at all times. From the mdn web docs, I see that the delay passed to setTimeout is a minimum, so if I set a date less than 24 hours away then diff should never be positive, yet it is.

Executing instantly instead of throwing an uncatchable error would be preferred in my case.

[Cyberbeni]

Is there a reason why we are calculating diff instead of just checking remaining > 0 in the first place?

[sheerlox]

Is there a reason why we are calculating diff instead of just checking remaining > 0 in the first place?

From #259:

This patch prevents onTick() to be called twice if setTimeout callback was called earlier than expected due to time adjustment. It just measures how much time passed since we set timeout and if it's less than it should it reschedules onTick call.

---

Executing instantly instead of throwing an uncatchable error would be preferred in my case.

A solution I might think of would be to add a new parameter tolerableDelay (in ms) defaulting to 0 (no breaking change), which would be used somewhat like this:

if (this.realDate) { 
  if (DateTime.local() > date) { 
    if (DateTime.local() > date + tolerableDelay) { 
      throw new CronError('WARNING: Date in past. Will never be fired. Try adjusting the tolerableDelay parameter.'); 
    }

    return date + tolerableDelay;
  }

  return date;
}

This way you could control how much you want to allow executing jobs that missed the execution date.

Does that sound like an acceptable solution to your issue?

Implementation note: we would also need to apply that parameter in other places so it applies to regular cron jobs as well.

[Cyberbeni]

In case of tolerableDelay = Infinity, that results in getTimeout also returning Infinity.

It would fix my issue but it wouldn't fix people randomly running into this issue.

If setTimeout fires after the target date then that already allows infinite delays. It's only in the case of the second measurement inside the same runloop run being negative, while the first being positive when a crash happens instead of just a couple millisecond delay. If I understand how JS+this npm package works currently, let's say we set a cron job to trigger every second and the code being executed by the trigger takes 10 seconds then we constantly get 9-10 second delays and a lot of triggers are getting skipped.

So I think executing instantly in this case is still the best option. (And also most consistent with how things currently work)

[sheerlox]

let's say we set a cron job to trigger every second and the code being executed by the trigger takes 10 seconds then we constantly get 9-10 second delays and a lot of triggers are getting skipped.

We recently added an option to wait for callback completion, but the default behavior remains as before: whatever the time it takes for the callback to complete, the callback will be called every second (in your example). However, if the callback is running some expensive thread-blocking operations, this might affect the execution of the scheduling loop, hence calls to setTimeout, and might introduce a variable delay in the regular execution of the callback.

[sheerlox]

The issue and work we're doing in #805 are somewhat related to that issue.

Here's a draft fix I've pushed to see how things behave in production (#805 is actually very hard to reproduce): sheerlox@187dbe5#diff-a66bffdb979d130e04df61edb944cc04d2fdedf8117ca2732cb6d119d5f5e7b2

[sheerlox]

A discussion is happening on #962 to add a tolerableDelay parameter for regular cron jobs (i.e. not providing a specific date, but a cron expression).

I believe we should be able to use the same parameter(s) for both issues.

[intcreator]

#980 (released in 4.3.0) provides a workaround for this. does this solve your issue @Cyberbeni?

[ancasicolica]

IMHO, cron should not threw an error if the date is in the past. This is a little bit harsh.

I migrated my project from 'node-schedule' to this library because node-schedule is not maintained anymore. But I consider to revert the changes as I have serious problems with this behaviour:

I use this library for "regular" cron jobs (periodic ones) and one time events. With the later I see this exception in one of about 20 usages: instead of executing the function, cron throws an error (which I can't catch, at least I wouldn't know how) and my application restarts due to this error.
I already set the threshold to 2000ms (even I saw in my logs, that < 300ms would be far enough) but I still have this error thrown.

Even worse, for debugging purposes you can't just query the instance for it's data, another error is thrown (which you have to handle again). I also implemented an Error handler, but without effect, the handler is not called, the app crashes before.

I would expect that such errors are only thrown upon request (e.g. by activating them when creating an instance), quering data of a cron job for logging purposes should not throw errors. Or at least the supplied error handler should be called instead of throwing the error when using this handler.

This is how I use it: https://github.com/ancasicolica/ferropoly-main/blob/624d612d2a4a987d93b7ff55e9668298c62c8829/main/lib/gameScheduler.js#L188