Scheduling event error

[redpoll123]

A scheduled event was missed several times due to a "SCHEDULING EVENT ERROR".

I did not see any conflicts/collisions with other events or node activity in the log at those times,
so was wondering about the message  "cannot schedule event in ... (less than 1s)" .
 

Code: [Select]

[08-15-19_06:55:23.110] [LOG]    post: /home/pi/gateway/data/db/0068_RSSI.bin[1565880923,-90]
[08-15-19_06:55:23.115] [LOG]       [68] DB-Updates:1
[08-15-19_07:01:59.451] [LOG]    **** RUNNING SCHEDULED EVENT - nodeId:2 event:raspberry_Poll7_AM_Post...
[08-15-19_07:01:59.455] [ERROR]  **** SCHEDULING EVENT ERROR - nodeId:2 event:raspberry_Poll7_AM_Post cannot schedule event in 545ms (less than 1s)
[08-15-19_07:03:20.745] [LOG]    >: [155] 25.64cm BAT:3.62   [RSSI:-65][ACK-sent]

[Felix]

Some details about the event would be helpful.
And the code.
Actually, everything related to that event so I don't ask twice.

[redpoll123]

The event raspberry_Poll7_AM_Post runs once a day and
sends a html request to a cell phone which in turn sends SMS text "Gateway OK".
It has worked well just had several instances, recently, that did not go through and saw this error.

Here is the event and also the request function.
 
(Thank you duane1 for pointing out the Tasker app!)

Code: [Select]

raspberry_Poll7_AM_Post: {
    label: 'Send Gateway AOK HTML POST @ 7 AM every day',
    icon: 'clock',
    descr: 'Send HTML POST every day at 7 AM to show Gateway is still running ',
    nextSchedule: function(node) {
        return exports.timeoutOffset(7, 2);
    }, //ie 7:00 (7am)
    scheduledExecute: function(node) {

        exports.taskerRequest('alarming=Gateway OK @ ' + (new Date().toLocaleTimeString() + ' : '));
        //         db.update({ _id: node._id }, { $set : node}, {}, function (err, numReplaced) { console.log('   ['+node._id+'] DB-Updates:' + numReplaced);}); 
        /*save lastSMS timestamp to DB*/

    }
},

Code: [Select]

exports.taskerRequest = function(triggerWord) {
	var phoneIP = settings.general.ipPhone.value;
    request.post({ 
         headers: {'content-type' : 'application/x-www-form-urlencoded'},
         url:'http://'+phoneIP,     // Galaxy S3
         body: triggerWord },
         function(error,response,body){ }
      );
    //request.post({ 
        //headers: {'content-type' : 'application/x-www-form-urlencoded'},
        //url:'http://192.168.1.127:8765',     // ZTE Maven 
        //body: triggerWord },
        //function(error,response,body){ } 
    //);
  
  }

[Felix]

What type of Pi are you using?
Does this happen the first time this event runs? (ex. after a gateway app restart)
Or does it happen randomly (without gateway app restarts)?

I'm not quite sure what might cause it. It's suggesting some discrepancy in how the next run timestamp is calculated.
Could you try replacing the timeoutOffset function with this, and see if it makes any difference?

Code: [Select]

exports.timeoutOffset = function(hour, minute, second, offset) {
  var result = new Date().setHours(hour,minute,second || 0, 0);
  var now = new Date().getTime();
  result = result < now ? (result + exports.ONEDAY) : result;
  result -= now;
  if (exports.isNumeric(offset)) result += offset;
  return result;
}

[redpoll123]

Pi 3 running Stretch with Gateway ver 9.0.0 (built on Pi3 B+ then the sdcard moved to a Pi 3)

Happened as first time and also after event had run OK previously.

Changed the timeoutOffset function and will let it run.

[redpoll123]

The timeoutOffset function was replaced and the Scheduling event error still happens occasionally.
The error also happens on another gateway running on a Pi Zero W.

This log entry shows an instance where the event runs and evidently the event is scheduled a second later which then runs and is scheduled again with the correct time.

Code: [Select]

[08-31-19_06:12:16.275] [INFO]   NEW CONNECTION FROM 192.168.1.2
[08-31-19_07:04:58.131] [LOG]    **** RUNNING SCHEDULED EVENT - nodeId:2 event:raspberry_Poll7_AM_Post...
[08-31-19_07:04:58.285] [LOG]    **** SCHEDULING EVENT - nodeId:2 event:raspberry_Poll7_AM_Post to run in ~1s
[08-31-19_07:04:58.371] [LOG]       [2] DB-Updates:1
[08-31-19_07:05:00.004] [LOG]    **** RUNNING SCHEDULED EVENT - nodeId:2 event:raspberry_Poll7_AM_Post...
[08-31-19_07:05:00.020] [LOG]    **** SCHEDULING EVENT - nodeId:2 event:raspberry_Poll7_AM_Post to run in ~23h59m
[08-31-19_07:05:00.048] [LOG]       [2] DB-Updates:1

[redpoll123]

Created a workaround for the scheduling event error.

Debug comments were added to the timeoutOffset function.
The log shows the reason the event scheduling fails.
The event runs a second or so earlier than the actual scheduled time, (why?).

Code: [Select]

[09-13-19_07:01:59.501] [LOG]    **** RUNNING SCHEDULED EVENT - nodeId:2 event:raspberry_Poll7_AM_Post...
[09-13-19_07:01:59.644] [INFO]   hour is 7 minute is 2 second is undefined
[09-13-19_07:01:59.646] [INFO]   result new Date.setHours is  1568386920646
[09-13-19_07:01:59.648] [INFO]   now Date.getime  is          1568386919648
[09-13-19_07:01:59.651] [INFO]   result + ONEDAY  is          1568386920646
[09-13-19_07:01:59.653] [INFO]   result -= now is             998
[09-13-19_07:01:59.655] [INFO]   result += offset is          998
[09-13-19_07:01:59.657] [ERROR]  **** SCHEDULING EVENT ERROR - nodeId:2 event:raspberry_Poll7_AM_Post cannot schedule event in 998ms (less than 1s)

Changed this line in the timeoutOffset function.

 

Code: [Select]

result = result < now ? (result + exports.ONEDAY) : result;

 
to this
 
 

Code: [Select]

result =  result < now  || (result > now && ( result - now < 5000 )) ? (result + exports.ONEDAY) : result;

After the edit the event reschedules correctly when it runs early.

Code: [Select]

[09-24-19_07:04:59.653] [LOG]    **** RUNNING SCHEDULED EVENT - nodeId:2 event:raspberry_Poll7_AM_Post...
[09-24-19_07:04:59.675] [INFO]   hour is 7 minute is 5 second is undefined
[09-24-19_07:04:59.678] [INFO]   result new Date.setHours is  1569337500000
[09-24-19_07:04:59.681] [INFO]   now Date.getime  is          1569337499681
[09-24-19_07:04:59.684] [INFO]   result + ONEDAY  is          1569423900000
[09-24-19_07:04:59.687] [INFO]   result -= now is             86400319
[09-24-19_07:04:59.690] [INFO]   result += offset is          86400319
[09-24-19_07:04:59.693] [LOG]    **** SCHEDULING EVENT - nodeId:2 event:raspberry_Poll7_AM_Post to run in ~24h

[Felix]

Thank you, I will have to try this. I see 2 things that may be of concern:

1) drifting ... as these event scheduling conditions offsets occur, the shifting of 7AM can add up, I suspect a second every now and then won't impact something that is just ~"7AM" and not "7:00:00AM"
2) with this change events cannot be scheduled at a frequency of more than 5s. In all cases such a thing would probably be bad anyway. But worth mentioning.

As for the cause - I'm not sure why. It may not be from the code itself - maybe it's node being run as a process with preempting of other processes causing that code to execute too late. 

[redpoll123]

 >> 2) with this change events cannot be scheduled at a frequency of more than 5s

I was aware of that, personally never saw a need to schedule events that frequently, yet!

Usually there are no other log entries before/after/during these times.