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)" .
[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]
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!)
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*/
}
},
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){ }
//);
}
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?
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;
}
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.
[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
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?).
[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.
result = result < now ? (result + exports.ONEDAY) : result;
to this
result = result < now || (result > now && ( result - now < 5000 )) ? (result + exports.ONEDAY) : result;
After the edit the event reschedules correctly when it runs early.
[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