Program not running at specified time

[johnnyt]

Last night the following program did not run:

 

If
       Time is 11:59:58PM

Then
       Send Notification to 'me' content 'Generic Program Log'
       Wait  5 seconds
       Run Program 'Day of Month Advance' (If)

Else
  - No Actions - (To add one, press 'Action')

It's part of the Calendar series of programs although I changed it to run before midnight (and wait 5 seconds so the action takes place after midnight). This is so I can set the feature to "Catch up schedules at restart" - which I learned only goes back to midnight the day of - without the calendar getting advanced again should a restart happen.

 

This is a problem I've seen before - with this program and others - and, for this one, I added 2 notifications, which write to a log, to catch it when it happens. The night before, as with most nights, the following entries appear in my log file:

 

2013/07/10, 00:00:05, Call Day of Month Advance ran True
2013/07/10, 00:00:09, Day of Month Advance ran True

These entries are absent for last night.

 

Also, as those familiar with this series of programs know, there's a mechanism to warn one when the program doesn't run and it's happened 6 times since late January (when I decided to start to keep the emails I receive for reference). See image for the date and time of past occurrences.

 

What's happening?

 

Am on 4.0.5 firmware and GUI

[johnnyt]

looking back the appropriate entries are supposed to look like this:

 

2013/07/07, 23:59:59, Call Day of Month Advance ran True
2013/07/08, 00:00:03, Day of Month Advance ran True

so the problem seems to be that the program trigger is delayed for some reason.

 

how do I avoid that?

 

the weird thing about this is I should have gotten an error yesterday (the 10th)!

[apostolakisl]

Do you have any other programs set to trigger at or just before the time this program triggers? Or any other programs that are running, possibly in some sort of loop? That might explain the delay, but I don't know how to explain a complete failure to run, except if ISY is off at the time.

 

I have had those programs running for a long time (like 3 years) and it has never failed to run, not even once. And you have had 6 in the past 6 months. Of course a failure to run at a specified time would not be specific to any particular program, but I am unaware of any scheduled program not running at the scheduled time on my ISY, though I might not notice some of them failing.

 

I do like your idea to have the program trigger just prior to midnight and execute just after midnight. That is a clever way to leave your "catch up at restart" on without screwing up the date programs. Although I have my ISY on a UPS so it shouldn't be necessary.

 

But ISY just completely blanking on running a scheduled program. . . Hmmm. Another possibility is a bug or error in the firmware. Have you tried updating the firmware? Lastly I suppose there could be a fault in the hardware, but it seems like that would fail more consistently.

 

EDIT: Also, you are quoting the log as your source of runtime. But the log is generated separately. It could be that only the log time is delayed, not the actual run time. Have you checked your "last run time" in your program summary page to see if it is the same as your log time?

[Michel Kohanim]

Hi johnnyt,

 

In addition to suggestions by apostolakisl, please check your logs for any anomalies related to the reported time.

 

With kind regards,

Michel

[Xathros]

Another remote possibility is that NTP is updating the ISY's clock and skipping the trigger time. This would assume that the ISY clockis drifting enough in a 24hr period and that NTP is updating around the same time that your program should trigger.

 

You could disable NTP for a day or two and see how much clock drift you see. Then maybe change the frequency of updates in an attempt to avoid the mindnigt-ish update.

 

-Xathros

[Michel Kohanim]

Hi johnnyt,

 

Xathros has a valid point. And, since there are two other reported issues with clock on 4.0.5 (even though unrelated), it would be great if you could contact us so that we can have a debug version installed and monitor what's going on.

 

With kind regards,

Michel

[apostolakisl]

Certainly if you had your clock set to sync with ntp at or near midnight it would lead credence to this theory.

[johnnyt]

Have you checked your "last run time" in your program summary page to see if it is the same as your log time?

I think I checked last run time and it was the day before. I say "I think" because I rarely look at that as I don't find it useful typically since it changes every time the conditions are evaluated - very few of my programs have only one condition like this one. I rely on notifications to troubleshoot program problems, although they can be delayed. (I wish there was a program log).

 

In addition to suggestions by apostolakisl, please check your logs for any anomalies related to the reported time.

The log doesn't have anything between about 11:50PM and 12:05AM so nothing going on from an insteon traffic perspective. The closest other program runs at 12:00:10 to reset a few variables. It terminates at the same time it starts. Also, I get notified when ISY boots up and I wasn't notified of that. By all indications ISY was running fine at 11:59:58 PM that night.

 

Another remote possibility is that NTP is updating the ISY's clock and skipping the trigger time. This would assume that the ISY clockis drifting enough in a 24hr period and that NTP is updating around the same time that your program should trigger.

 

You could disable NTP for a day or two and see how much clock drift you see. Then maybe change the frequency of updates in an attempt to avoid the mindnigt-ish update.

I disabled ntp sync for about a day and a half and the clock lost maybe 1-2 secs.

 

I had the clock set to sync every 6 hours - at that rate it should have remained pretty close, no? I have no idea when the sync actually occurs (is there a way to know? could there be a way to choose in a future release?)

 

At every 6 hours, if the problem was an NTP sync, it would have happened every day at the same time and I think I would have seen more occurrences of the problem, no?

 

Am I better off to sync only once a day? On one hand it would interfere with fewer programs when it does occur but on the other hand the time would be more likely to be off by a few secs when it does sync.

 

Does changing the occurrence of the NTP sync reset the clock? I could use that to pick a time that would not be important.

 

What happens to programs that rely on "Time is Last run" condition of a program if the NTP sync happens to occur and change the clock to just past when that condition would have occurred? I know there were a few times in the past when I would have liked to have a "Time > Last run" - not sure if others have asked for it but maybe this time sync situation points to a requirement for that?

 

Xathros has a valid point. And, since there are two other reported issues with clock on 4.0.5 (even though unrelated), it would be great if you could contact us so that we can have a debug version installed and monitor what's going on.

I may take you up on that. Could it could also be used to track a bigger, long standing problem I've had with IO Lincs that's wasted lots of my cycles over the past couple of years? viewtopic.php?f=27&t=11907

[Xathros]

(I wish there was a program log).

 

There is, sorta...

 

You can use notifications to write directly to a file on the ISY's webserver. Very much like what you are doing now with your notifications but should be 0 latency. I do something very similar with network resources writing to a syslog server running on my RaspberryPi. Makes for lots of network resources or custom notifications but is very useful for debugging purposes.

 

Here is the wiki link for writing to a file: http://wiki.universal-devices.com/index.php?title=ISY-99i_Series_INSTEON:Networking#Create_File_and_Send_Notification

 

-Xathros

[johnnyt]

(I wish there was a program log).

There is, sorta...

 

You can use notifications to write directly to a file on the ISY's webserver. Very much like what you are doing now with your notifications but should be 0 latency. I do something very similar with network resources writing to a syslog server running on my RaspberryPi. Makes for lots of network resources or custom notifications but is very useful for debugging purposes.

 

Here is the wiki link for writing to a file: http://wiki.universal-devices.com/index.php?title=ISY-99i_Series_INSTEON:Networking#Create_File_and_Send_Notification

 

-Xathros

Thanks Xathros. Yes, I was an early adopter of that. Problem is every program you want to monitor has to be set up and the files have to created and managed. I also ran into hassles formatting and "saving as" to excel. Eventually solved but way too much work. What I'd like to see is a program log similar to the insteon activity log, that is built-in and that logs all activity (with perhaps the ability to turn on/off or set log levels like event viewer.) See viewtopic.php?f=7&t=7779 for my wish list. It doesn't appear the current hardware has enough juice, though, and while I'd be happy to pay for more power and have posted about that, it seems no one else would be.

 

Anyway, hopefully I didn't just send my own thread down another road but I wanted to acknowledge your reply.

[Michel Kohanim]

Hi johnnyt,

 

The best thing to do would be to use our debug version (pretty stable).

 

With kind regards,

Michel

[johnnyt]

This happened again last week and today, along with the problem posted here viewtopic.php?f=27&t=12144 that seems related (as of this posting).

 

I will open a ticket to get the debug version.

[arw01]

Just as an aside, I too run the calendar programs for many months and have not had a single instance of them being out of sync. I have had my notifications that go out to texting get delayed many, many hours by the phone company I would assume.

 

if I recall you have a large number of programs? Is there a pattern to the number of days, or weeks, or something consistent to that as to when it fails?

[johnnyt]

Is there a pattern to the number of days, or weeks, or something consistent to that as to when it fails?

I can't find one. I've attached an updated screenshot of the validation emails I get from the program that runs at 1:00AM to check the day of the week and it includes the latest two occurrences. If you see a pattern let me know.

 

Until today I haven't had any other program scheduled to run at the same time. I added one today to fix to other (confirmed unrelated) issue I mention in my last post. I guess I'll get to see if both are affected by this if it happens again.

 

Also, as of tonight I'm running a special firmware version that will provide UDI some debug info. I've added programs to send me a notification every hour hoping that expedites the next occurrence.

[johnnyt]

Would like to tentatively close on this. The problem has not re-occurred at this point and I suspect it won't because I reduced the workload demands I've been placing on ISY.

 

It may yet re-occur but given the additional test programs I've been running to try to cause/observe another instance of the problem and the fact that no one else seems to have encountered the problem I'm thinking it won't happen again with this firmware generation.

 

Briefly, I've been running 4.0.11 (an alpha release with more debug info being captured as I understand it) for well over a month. I also created 24 programs like the following one to run each hour:

 

If
       Time is  1:00:00AM
Then
       Send Notification to 'me' content 'Generic Main Log'
Else
  - No Actions - (To add one, press 'Action')

The notification sends an email and writes to a log using this feature viewtopic.php?f=25&t=10905. Writing to a log file resolved / worked around the issue of an email not making it out, which happened at least half a dozen times. (Thank you UDI for the log feature; it's been a helpful troubleshooting tool)

 

For more info on my workload issues see viewtopic.php?f=27&t=11999#p92535.

 

And the workaround that I suspect fixed the problem is in this post viewtopic.php?f=27&t=11999#p92637

 

I'll report back if something changes.

[Michel Kohanim]

Hi johnnyt,

 

Thanks so very much for the update.

 

With kind regards,

Michel