Hi. I have a very simple automation scene that starts gradually turning off my front lights. The scene has been in place for months and I’ve made no recent changes to the VeraLite but in the last week, the scene seems stuck. It runs the first step and then the 2nd step at the 30 minute delay. But then at the hour delay, it reruns the 2nd step and so on until the end of the scene.
Any ideas on why this might be happening or what I can do to fix it? I’ve rebooted the VeraLite, I’ve updated the nodes around the light in question. The only thing that worked partially was when I added messages to the scene to see if it was progressing. That worked the first night but then it went back to just repeating the 2nd step. Here are excerpts from the log that shows what is happening:
06 04/26/14 2:01:19.158 Device_Variable::m_szValue_set device: 3 service: urn:upnp-org:serviceId:Dimming1 variable: e[35;1mLoadLevelStatuse[0m was: 70 now: 50 #hooks: 10 upnp: 0 v:0xab2c28/NONE duplicate:0 <0x2b931680>
06 04/26/14 2:01:19.158 Device_Variable::m_szValue_set device: 3 service: urn:upnp-org:serviceId:SwitchPower1 variable: e[35;1mStatuse[0m was: 1 now: 1 #hooks: 1 upnp: 0 v:0xa9cd60/NONE duplicate:1 <0x2b931680>
04 04/26/14 2:01:19.160 <Job ID="2050" Name="Level 50 node 2" Device="3" Created="2014-04-26 2:01:16" Started="2014-04-26 2:01:18" Completed="2014-04-26 2:01:19" Duration="3.150177000" Runtime="0.274756000" Status="Successful" LastNote="Transmit was ok" Node="2" NodeType="ZWaveDimmableLight" NodeDescription="Front Steps"/> <0x2b931680>
04 04/26/14 2:30:56.245 <Job ID="42" Name="pollnode #2 1 cmds" Device="3" Created="2014-04-26 2:30:56" Started="2014-04-26 2:30:56" Completed="2014-04-26 2:30:56" Duration="0.143470000" Runtime="0.142343000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveDimmableLight" NodeDescription="Front Steps"/> <0x2b271680>
08 04/26/14 2:31:16.100 JobHandler_LuaUPnP::HandleActionRequest device: 3 service: urn:upnp-org:serviceId:Dimming1 action: e[36;1mSetLoadLevelTargete[0m <0x2b271680>
08 04/26/14 2:31:16.101 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=40 <0x2b271680>
06 04/26/14 2:31:16.101 Device_Variable::m_szValue_set device: 3 service: urn:upnp-org:serviceId:Dimming1 variable: e[35;1mLoadLevelTargete[0m was: 50 now: 40 #hooks: 0 upnp: 0 v:0xd15250/NONE duplicate:0 <0x2b271680>
02 04/26/14 2:31:16.102 e[33;1mZWJob_SendData UPDATE MANUAL ROUTE 2=0xd49397e[0m <0x2b271680>
08 04/26/14 2:31:16.103 JobHandler_LuaUPnP::HandleActionRequest device: 39 service: urn:richardgreen:serviceId:VeraAlert1 action: e[36;1mSendAlerte[0m <0x2b271680>
08 04/26/14 2:31:16.115 JobHandler_LuaUPnP::HandleActionRequest argument Message=Reduced to 40 <0x2b271680>
08 04/26/14 2:31:16.116 JobHandler_LuaUPnP::HandleActionRequest argument Recipients= <0x2b271680>
02 04/26/14 2:31:16.113 e[33;1mUPDATE MANUAL ROUTE2 2=0xd49397e[0m <0x2b671680>
02 04/26/14 2:31:16.125 e[33;1mZW_Send_Data node 2 USING ROUTE 255.0.0.0e[0m <0x2b671680>
02 04/26/14 2:31:16.225 e[33;1mUPDATE MANUAL ROUTE2 2=0xd49397e[0m <0x2b671680>
02 04/26/14 2:31:16.226 e[33;1mZW_Send_Data node 2 USING ROUTE 255.0.0.0e[0m <0x2b671680>
06 04/26/14 2:31:16.334 Device_Variable::m_szValue_set device: 3 service: urn:upnp-org:serviceId:Dimming1 variable: e[35;1mLoadLevelStatuse[0m was: 50 now: 40 #hooks: 10 upnp: 0 v:0xd14618/NONE duplicate:0 __LEAK__ this:4096 start:364544 to 0xf0d000 <0x2b271680>
06 04/26/14 2:31:16.334 Device_Variable::m_szValue_set device: 3 service: urn:upnp-org:serviceId:SwitchPower1 variable: e[35;1mStatuse[0m was: 1 now: 1 #hooks: 1 upnp: 0 v:0xcfedf8/NONE duplicate:1 <0x2b271680>
04 04/26/14 2:31:16.336 <Job ID="43" Name="Level 40 node 2" Device="3" Created="2014-04-26 2:31:16" Started="2014-04-26 2:31:16" Completed="2014-04-26 2:31:16" Duration="0.233427000" Runtime="0.222637000" Status="Successful" LastNote="Transmit was ok" Node="2" NodeType="ZWaveDimmableLight" NodeDescription="Front Steps"/> <0x2b271680>
04 04/26/14 3:00:56.227 <Job ID="104" Name="pollnode #2 1 cmds" Device="3" Created="2014-04-26 3:00:56" Started="2014-04-26 3:00:56" Completed="2014-04-26 3:00:56" Duration="0.124794000" Runtime="0.123615000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveDimmableLight" NodeDescription="Front Steps"/> <0x2b271680>
08 04/26/14 3:01:16.100 JobHandler_LuaUPnP::HandleActionRequest device: 3 service: urn:upnp-org:serviceId:Dimming1 action: e[36;1mSetLoadLevelTargete[0m <0x2b271680>
08 04/26/14 3:01:16.101 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=40 <0x2b271680>
06 04/26/14 3:01:16.101 Device_Variable::m_szValue_set device: 3 service: urn:upnp-org:serviceId:Dimming1 variable: e[35;1mLoadLevelTargete[0m was: 40 now: 40 #hooks: 0 upnp: 0 v:0xd15250/NONE duplicate:1 <0x2b271680>
02 04/26/14 3:01:16.102 e[33;1mZWJob_SendData UPDATE MANUAL ROUTE 2=0xd49397e[0m <0x2b271680>
08 04/26/14 3:01:16.103 JobHandler_LuaUPnP::HandleActionRequest device: 39 service: urn:richardgreen:serviceId:VeraAlert1 action: e[36;1mSendAlerte[0m <0x2b271680>
08 04/26/14 3:01:16.103 JobHandler_LuaUPnP::HandleActionRequest argument Message=Reduced to 40 <0x2b271680>
08 04/26/14 3:01:16.103 JobHandler_LuaUPnP::HandleActionRequest argument Recipients= <0x2b271680>
04 04/26/14 3:30:56.237 <Job ID="166" Name="pollnode #2 1 cmds" Device="3" Created="2014-04-26 3:30:56" Started="2014-04-26 3:30:56" Completed="2014-04-26 3:30:56" Duration="0.135516000" Runtime="0.134391000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveDimmableLight" NodeDescription="Front Steps"/> <0x2b271680>
08 04/26/14 3:31:16.100 JobHandler_LuaUPnP::HandleActionRequest device: 3 service: urn:upnp-org:serviceId:Dimming1 action: e[36;1mSetLoadLevelTargete[0m <0x2b271680>
08 04/26/14 3:31:16.101 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=40 <0x2b271680>
06 04/26/14 3:31:16.101 Device_Variable::m_szValue_set device: 3 service: urn:upnp-org:serviceId:Dimming1 variable: e[35;1mLoadLevelTargete[0m was: 40 now: 40 #hooks: 0 upnp: 0 v:0xd15250/NONE duplicate:1 <0x2b271680>
02 04/26/14 3:31:16.102 e[33;1mZWJob_SendData UPDATE MANUAL ROUTE 2=0xd49397e[0m <0x2b271680>
08 04/26/14 3:31:16.103 JobHandler_LuaUPnP::HandleActionRequest device: 39 service: urn:richardgreen:serviceId:VeraAlert1 action: e[36;1mSendAlerte[0m <0x2b271680>
08 04/26/14 3:31:16.103 JobHandler_LuaUPnP::HandleActionRequest argument Message=Reduced to 40 <0x2b271680>
08 04/26/14 3:31:16.103 JobHandler_LuaUPnP::HandleActionRequest argument Recipients= <0x2b271680>
02 04/26/14 3:31:16.124 e[33;1mUPDATE MANUAL ROUTE2 2=0xd49397e[0m <0x2b671680>
02 04/26/14 3:31:16.124 e[33;1mZW_Send_Data node 2 USING ROUTE 255.0.0.0e[0m <0x2b671680>
02 04/26/14 3:31:16.217 e[33;1mUPDATE MANUAL ROUTE2 2=0xd49397e[0m <0x2b671680>
02 04/26/14 3:31:16.218 e[33;1mZW_Send_Data node 2 USING ROUTE 255.0.0.0e[0m <0x2b671680>
06 04/26/14 3:31:16.326 Device_Variable::m_szValue_set device: 3 service: urn:upnp-org:serviceId:Dimming1 variable: e[35;1mLoadLevelStatuse[0m was: 40 now: 40 #hooks: 10 upnp: 0 v:0xd14618/NONE duplicate:1 <0x2b271680>
06 04/26/14 3:31:16.326 Device_Variable::m_szValue_set device: 3 service: urn:upnp-org:serviceId:SwitchPower1 variable: e[35;1mStatuse[0m was: 1 now: 1 #hooks: 1 upnp: 0 v:0xcfedf8/NONE duplicate:1 <0x2b271680>
04 04/26/14 3:31:16.327 <Job ID="167" Name="Level 40 node 2" Device="3" Created="2014-04-26 3:31:16" Started="2014-04-26 3:31:16" Completed="2014-04-26 3:31:16" Duration="0.225075000" Runtime="0.220890000" Status="Successful" LastNote="Transmit was ok" Node="2" NodeType="ZWaveDimmableLight" NodeDescription="Front Steps"/> <0x2b271680>
06 04/26/14 3:31:18.240 Device_Variable::m_szValue_set device: 39 service: urn:richardgreen:serviceId:VeraAlert1 variable: e[35;1mLastMsgSente[0m was: 03:01:18 Sat Apr 26 now: 03:31:18 Sat Apr 26 #hooks: 0 upnp: 0 v:0xd7c970/NONE duplicate:0 <0x2ab3e000>
04 04/26/14 3:31:18.242 <Job ID="168" Name="" Device="39" Created="2014-04-26 3:31:16" Started="2014-04-26 3:31:16" Completed="2014-04-26 3:31:18" Duration="2.137261000" Runtime="2.124839000" Status="Successful" LastNote=""/> <0x2ab3e000>
02 04/26/14 3:31:26.102 e[33;1mZW_Send_Data node 4 USING ROUTE 255.0.0.0e[0m <0x2b671680>
04 04/26/14 3:31:26.236 <Job ID="169" Name="pollnode #4 1 cmds" Device="7" Created="2014-04-26 3:31:26" Started="2014-04-26 3:31:26" Completed="2014-04-26 3:31:26" Duration="0.135351000" Runtime="0.134647000" Status="Successful" LastNote="" Node="4" NodeType="ZWaveDimmableLight" NodeDescription="Silas' Room"/> <0x2b271680>
02 04/26/14 3:31:42.100 e[33;1mLOG_CHECK_MEMORY_LEAK pMem start 0xf0c000 now 0xf55000 last 0xf42000 leaked 299008e[0m __LEAK__ this:77824 start:659456 to 0xf55000 <0x2b271680>
02 04/26/14 3:31:56.103 e[33;1mZW_Send_Data node 6 USING ROUTE 255.0.0.0e[0m <0x2b671680>
04 04/26/14 3:31:56.226 <Job ID="170" Name="pollnode #6 1 cmds" Device="11" Created="2014-04-26 3:31:56" Started="2014-04-26 3:31:56" Completed="2014-04-26 3:31:56" Duration="0.125356000" Runtime="0.124108000" Status="Successful" LastNote="" Node="6" NodeType="ZWaveDimmableLight" NodeDescription="Master Bedroom"/> <0x2b271680>
08 04/26/14 4:01:16.100 JobHandler_LuaUPnP::HandleActionRequest device: 3 service: urn:upnp-org:serviceId:Dimming1 action: e[36;1mSetLoadLevelTargete[0m <0x2b271680>
08 04/26/14 4:01:16.101 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=40 <0x2b271680>
06 04/26/14 4:01:16.101 Device_Variable::m_szValue_set device: 3 service: urn:upnp-org:serviceId:Dimming1 variable: e[35;1mLoadLevelTargete[0m was: 40 now: 40 #hooks: 0 upnp: 0 v:0xd15250/NONE duplicate:1 <0x2b271680>
02 04/26/14 4:01:16.102 e[33;1mZWJob_SendData UPDATE MANUAL ROUTE 2=0xd49397e[0m <0x2b271680>
02 04/26/14 4:01:16.104 e[33;1mUPDATE MANUAL ROUTE2 2=0xd49397e[0m <0x2b671680>
02 04/26/14 4:01:16.104 e[33;1mZW_Send_Data node 2 USING ROUTE 255.0.0.0e[0m <0x2b671680>
02 04/26/14 4:01:16.237 e[33;1mUPDATE MANUAL ROUTE2 2=0xd49397e[0m <0x2b671680>
02 04/26/14 4:01:16.238 e[33;1mZW_Send_Data node 2 USING ROUTE 255.0.0.0e[0m <0x2b671680>
06 04/26/14 4:01:16.346 Device_Variable::m_szValue_set device: 3 service: urn:upnp-org:serviceId:Dimming1 variable: e[35;1mLoadLevelStatuse[0m was: 40 now: 40 #hooks: 10 upnp: 0 v:0xd14618/NONE duplicate:1 <0x2b271680>
06 04/26/14 4:01:16.346 Device_Variable::m_szValue_set device: 3 service: urn:upnp-org:serviceId:SwitchPower1 variable: e[35;1mStatuse[0m was: 1 now: 1 #hooks: 1 upnp: 0 v:0xcfedf8/NONE duplicate:1 <0x2b271680>
04 04/26/14 4:01:16.347 <Job ID="229" Name="Level 40 node 2" Device="3" Created="2014-04-26 4:01:16" Started="2014-04-26 4:01:16" Completed="2014-04-26 4:01:16" Duration="0.245151000" Runtime="0.243208000" Status="Successful" LastNote="Transmit was ok" Node="2" NodeType="ZWaveDimmableLight" NodeDescription="Front Steps"/> <0x2b271680>
And I’m attaching a screen shot of the scene delays: