Scene error when run on schedule

brucehvn · January 28, 2014, 3:52am

I have two scenes I setup to control my front porch light. One turns on the light at 20 minutes after sunset, and the other turns the light off at 1AM. Those scenes were working fine the first couple days, but now I’ve noticed in the last few days that either one or the other doesn’t seem to be working. Today it missed turning the light on. I ran the scene manually about an hour later and the light turned on fine. The switch is a X10 on/off switch, probably an old Leviton model. It’s being controlled by the insteon PLM. Below are some filtered log entries for both when it didn’t work and when I ran it manually.

Automation run:

26	01/27/14 17:41:34.699	INJob_GenericSendFrame::Run job job#112 :x10 level #36 dev:36 (0xb21150) P:50 S:1 sending cmd id 0x63 to node m_bSendToAllNodes 0 m_listIns
teonFrame 2 <0x2ca8b680>
01	01/27/14 17:41:54.803	[[31;1mINJob_GenericSendFrame::Run failed to run job#112 :x10 level #36 dev:36 (0xb21150) P:50 S:1 command 0x63 abort 0 lower priority 0 ret
ries 3 node 6274424[[0m <0x2ca8b680>
26	01/27/14 17:41:54.804	INJob_GenericSendFrame::FindNextFrameToSend job job#112 :x10 level #36 dev:36 (0xb21150) P:50 S:1 reached end <0x2ca8b680>
26	01/27/14 17:41:54.804	INJob_GenericSendFrame::FindNextFrameToSend job job#112 :x10 level #36 dev:36 (0xb21150) P:50 S:1 aborting too many retries for frame comman
d 0x63 (4/3) <0x2ca8b680>
26	01/27/14 17:41:54.805	INJob_GenericSendFrame::FindNextFrameToSend job job#112 :x10 level #36 dev:36 (0xb21150) P:50 S:1 aborting too many retries for frame comman
d 0x63 (4/3) <0x2ca8b680>
26	01/27/14 17:41:54.805	INJob_GenericSendFrame::FindNextFrameToSend job job#112 :x10 level #36 dev:36 (0xb21150) P:50 S:1 reached end <0x2ca8b680>
01	01/27/14 17:41:54.806	[[31;1mINJob_GenericSendFrame::Run failed to run job job#112 :x10 level #36 dev:36 (0xb21150) P:50 S:1 command 0x63 node [[0m <0x2ca8b680>
01	01/27/14 17:41:54.806	[[31;1mINJob_GenericSendFrame::Run failed to run job job#112 :x10 level #36 dev:36 (0xb21150) P:50 S:1 command 0x63 node [[0m <0x2ca8b680>
10	01/27/14 17:41:54.807	Job::m_sNotes_set job#112 :x10 level #36 dev:36 (0xb21150) P:50 S:1 dataversion 819521053 changing from  -to- No response from node ;No resp
onse from node ; <0x2ca8b680>
10	01/27/14 17:41:54.808	Job::m_eJobStatus job job#112 :x10 level #36 dev:36 (0xb21150) P:50 S:2 dataversion 819521054 <0xb21150> m_eJobStatus Failed after 161.67845
9000 seconds callback:0 <0x2ca8b680>
01	01/27/14 17:41:54.810	[[31;1mINJob_GenericSendFrame::Run job job#112 :x10 level #36 dev:36 (0xb21150) P:50 S:2 done, failed 2[[0m <0x2ca8b680>
10	01/27/14 17:41:54.832	JobHandler::Run finished single job job#112 :x10 level #36 dev:36 (0xb21150) P:50 S:0 <0xb21150> <0x2ca8b680>
02	01/27/14 17:41:54.833	[[33;1mJobHandler::PurgeCompletedJobs purge job#112 :x10 level #36 dev:36 (0xb21150) P:50 S:2 x10 level #36 status 2[[0m <0x2ca8b680>
10	01/27/14 17:41:54.834	JobHandler::PurgeCompletedJobs purge job#112 :x10 level #36 dev:36 (0xb21150) P:50 S:2 x10 level #36 status 2 autodelete 1 <0x2ca8b680>

Manual run:

10	01/27/14 18:47:11.269	JobHandler::Run ready to run job#9 :x10 level #36 dev:36 (0xdb4168) P:50 S:0 x10 level #36 status 0 <0xdb4168> priority 50 tNextRunAttempt 0
 <0x2c6f7680>
10	01/27/14 18:47:11.270	Job::m_eJobStatus job job#9 :x10 level #36 dev:36 (0xdb4168) P:50 S:1 dataversion 877139115 <0xdb4168> m_eJobStatus Running after 0.4560000 
seconds callback:0 <0x2c6f7680>
26	01/27/14 18:47:11.270	INJob_GenericSendFrame::Run job job#9 :x10 level #36 dev:36 (0xdb4168) P:50 S:1 sending cmd id 0x63 to node  m_bSendToAllNodes 0 m_listInste
onFrame 2 <0x2c6f7680>
26	01/27/14 18:47:11.406	INJob_GenericSendFrame::Run ran job#9 :x10 level #36 dev:36 (0xdb4168) P:50 S:1 command 0x63 node  <0x2c6f7680>
26	01/27/14 18:47:11.407	INJob_GenericSendFrame::FindNextFrameToSend job job#9 :x10 level #36 dev:36 (0xdb4168) P:50 S:1 found frame command 0x63 <0x2c6f7680>
26	01/27/14 18:47:11.407	INJob_GenericSendFrame::Run job#9 :x10 level #36 dev:36 (0xdb4168) P:50 S:1 found another frame <0x2c6f7680>
10	01/27/14 18:47:11.408	Job::m_eJobStatus job job#9 :x10 level #36 dev:36 (0xdb4168) P:50 S:0 dataversion 877139116 <0xdb4168> m_eJobStatus Queued after 0.142495000
 seconds callback:0 <0x2c6f7680>
10	01/27/14 18:47:11.408	JobHandler::Run finished single job job#9 :x10 level #36 dev:36 (0xdb4168) P:50 S:0 <0xdb4168> <0x2c6f7680>
10	01/27/14 18:47:11.409	JobHandler::Run ready to run job#9 :x10 level #36 dev:36 (0xdb4168) P:50 S:0 x10 level #36 status 0 <0xdb4168> priority 50 tNextRunAttempt 0
 <0x2c6f7680>
10	01/27/14 18:47:11.410	Job::m_eJobStatus job job#9 :x10 level #36 dev:36 (0xdb4168) P:50 S:1 dataversion 877139117 <0xdb4168> m_eJobStatus Running after 0.14513400
0 seconds callback:0 <0x2c6f7680>
26	01/27/14 18:47:11.411	INJob_GenericSendFrame::Run job job#9 :x10 level #36 dev:36 (0xdb4168) P:50 S:1 sending cmd id 0x63 to node  m_bSendToAllNodes 0 m_listInste
onFrame 2 <0x2c6f7680>
26	01/27/14 18:47:16.522	INJob_GenericSendFrame::Run ran job#9 :x10 level #36 dev:36 (0xdb4168) P:50 S:1 command 0x63 node  <0x2c6f7680>
26	01/27/14 18:47:16.523	INJob_GenericSendFrame::FindNextFrameToSend job job#9 :x10 level #36 dev:36 (0xdb4168) P:50 S:1 reached end <0x2c6f7680>
26	01/27/14 18:47:16.523	INJob_GenericSendFrame::FindNextFrameToSend job job#9 :x10 level #36 dev:36 (0xdb4168) P:50 S:1 reached end <0x2c6f7680>
26	01/27/14 18:47:16.524	INJob_GenericSendFrame::Run job job#9 :x10 level #36 dev:36 (0xdb4168) P:50 S:1 done m_bSendToAllNodes 0 bSucceed 1 <0x2c6f7680>
10	01/27/14 18:47:16.537	Job::m_eJobStatus job job#9 :x10 level #36 dev:36 (0xdb4168) P:50 S:4 dataversion 877139130 <0xdb4168> m_eJobStatus Successful after 5.27207
2000 seconds callback:0 <0x2c6f7680>
10	01/27/14 18:47:16.550	JobHandler::Run finished single job job#9 :x10 level #36 dev:36 (0xdb4168) P:50 S:0 <0xdb4168> <0x2c6f7680>
10	01/27/14 18:47:16.551	JobHandler::PurgeCompletedJobs purge job#9 :x10 level #36 dev:36 (0xdb4168) P:50 S:4 x10 level #36 status 4 autodelete 1 <0x2c6f7680>

Anyone have any ideas?

sparkejj · January 28, 2014, 11:25am

When you do it manually, does it work consistently (i.e. multiple times in a row)?

brucehvn · January 28, 2014, 11:48pm

When you do it manually, does it work consistently (i.e. multiple times in a row)?

Actually, that’s a great test. Today, I’ve tried to run the scene manually and even just control the light itself and I’ve run into the same problems every time. I think it’s something to do with the Insteon PLM. I purchased the PLM and the Vera lite at the same time. If I would have known how poorly the Insteon PLM/Vera combination supports the X10 stuff and that there was a CM11a plugin, I probably wouldn’t have gotten the PLM. I’ve been doing some major work on the CM11 plugin to make it more robust and I think I can probably switch all my X10 devices over to use it now. I had planned on just using it for my 2 way devices and dimmers and leaving the on/off stuff using the Insteon, but now it’s starting to make more sense to use the CM11a.

Bruce