Just trying to find out if anybody else who has PLEG actions with multiple delays, if they are having trouble with them firing at the proper time. I know it has something to do with PLEG because I duplicated the same exact actions and delays from scenes that have been working fine. I use PLEG for conditions and the RunScene function to initiate the scene. That works fine. But when I try to create a PLEG that incorporates the same actions and delays so that I do not have to call an external scene it doesn’t work properly. The actions fire too quickly before the set delays.
Post a status report and a debug log for your PLEG. Indicate which action is having the problem.
I will be happy to look at it.
I was just going to create a post reporting similar behavior and found this so I’m going to keep it in one thread. Richard, I use PLEG and Vera Alerts extensively. Without them Vera wouldn’t be nearly as useful. Just wanted to say thanks.
Ok, so let me describe my problem. I have a condition that will raise 5 blinds in my house. I have tried raising them all at once and only one would go up. I tried adding a delay and then two will go up the first one when the condition is fired and the last one (10 second delay). I have separated each “blind up” command with a 2 second delay. My blinds are devices using HEK’s MySensors arduino plugin so I thought it might have something to do with that but I can manually put them up with a 1 second delay. I did a little quick testing this weekend and found that the entry isn’t even showing up in Vera’s logs so it leads me to think this may be something with PLEG. Here is the Vera log.
02 06/14/14 7:26:26.921 ZW_Send_Data node 2 USING ROUTE 255.56.44.54 <0x2bcdd680>
04 06/14/14 7:26:27.091 <0x2b8dd680>
02 06/14/14 7:26:44.102 ZW_Send_Data node 5 USING ROUTE 255.100.27.91 <0x2bcdd680>
04 06/14/14 7:26:44.241 <0x2b8dd680>
08 06/14/14 7:27:08.926 JobHandler_LuaUPnP::HandleActionRequest device: 13 service: urn:rts-services-com:serviceId:ProgramLogicC action: RunAction <0x2e4dd680>
08 06/14/14 7:27:08.926 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=13 <0x2e4dd680>
08 06/14/14 7:27:08.926 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:rts-services-com:serviceId:ProgramLogicC <0x2e4dd680>
08 06/14/14 7:27:08.927 JobHandler_LuaUPnP::HandleActionRequest argument action=RunAction <0x2e4dd680>
08 06/14/14 7:27:08.927 JobHandler_LuaUPnP::HandleActionRequest argument conditionName=cRaiseBlinds <0x2e4dd680>
08 06/14/14 7:27:08.927 JobHandler_LuaUPnP::HandleActionRequest argument rand=0.915665555279702 <0x2e4dd680>
06 06/14/14 7:27:08.933 Device_Variable::m_szValue_set device: 13 service: urn:rts-services-com:serviceId:ProgramLogicC variable: ActionsMap was: {_c1LROutletOn= {Start ='1391264928', Next = 2},} now: {cRaiseBlinds= {Start ='1402752428', Next = 2},_c1LROutletOn= {Start ='1391264928', Next = 2},} #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b1aa000>
08 06/14/14 7:27:08.960 JobHandler_LuaUPnP::HandleActionRequest device: 99 service: urn:upnp-org:serviceId:WindowCovering1 action: Up <0x2b1aa000>
50 06/14/14 7:27:08.961 luup_log:27: Arduino: Sending: 30;1;1;29; <0x2b1aa000>
08 06/14/14 7:27:08.962 JobHandler_LuaUPnP::HandleActionRequest device: 113 service: urn:upnp-org:serviceId:WindowCovering1 action: Up <0x2b1aa000>
50 06/14/14 7:27:08.963 luup_log:27: Arduino: Sending: 30;9;1;29; <0x2b1aa000>
08 06/14/14 7:27:08.964 JobHandler_LuaUPnP::HandleActionRequest device: 102 service: urn:upnp-org:serviceId:WindowCovering1 action: Up <0x2b1aa000>
50 06/14/14 7:27:08.965 luup_log:27: Arduino: Sending: 30;2;1;29; <0x2b1aa000>
04 06/14/14 7:27:08.967 <0x2b1aa000>
50 06/14/14 7:27:10.220 luup_log:27: Arduino: Set Var: 30;1;1;3;100 <0x2f0dd680>
50 06/14/14 7:27:10.221 luup_log:27: Arduino: Setting variable 'LoadLevelStatus' to value '100' <0x2f0dd680>
50 06/14/14 7:27:10.221 luup_log:27: Arduino: urn:upnp-org:serviceId:Dimming1,LoadLevelStatus, 100, 99 <0x2f0dd680>
50 06/14/14 7:27:10.221 luup_log:27: Arduino: urn:micasaverde-com:serviceId:HaDevice1,LastUpdate, 1402752430, 99 <0x2f0dd680>
06 06/14/14 7:27:10.222 Device_Variable::m_szValue_set device: 99 service: urn:micasaverde-com:serviceId:HaDevice1 variable: LastUpdate was: 1402745567 now: 1402752430 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2f0dd680>
50 06/14/14 7:27:10.223 luup_log:27: Arduino: urn:micasaverde-com:serviceId:HaDevice1,LastUpdate, 1402752430, 97 <0x2f0dd680>
06 06/14/14 7:27:10.223 Device_Variable::m_szValue_set device: 97 service: urn:micasaverde-com:serviceId:HaDevice1 variable: LastUpdate was: 1402745577 now: 1402752430 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2f0dd680>
50 06/14/14 7:27:10.224 luup_log:27: Arduino: urn:micasaverde-com:serviceId:HaDevice1,LastUpdateHR, 07:27 AM, 97 <0x2f0dd680>
06 06/14/14 7:27:10.224 Device_Variable::m_szValue_set device: 97 service: urn:micasaverde-com:serviceId:HaDevice1 variable: LastUpdateHR was: 05:32 AM now: 07:27 AM #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2f0dd680>
02 06/14/14 7:27:14.102 ZW_Send_Data node 6 USING ROUTE 255.100.27.91 <0x2bcdd680>
04 06/14/14 7:27:14.231 <0x2b8dd680>
06 06/14/14 7:27:18.101 Device_Variable::m_szValue_set device: 13 service: urn:rts-services-com:serviceId:ProgramLogicC variable: ActionsMap was: {cRaiseBlinds= {Start ='1402752428', Next = 2},_c1LROutletOn= {Start ='1391264928', Next = 2},} now: {cRaiseBlinds= {Start ='1402752428', Next = 3},_c1LROutletOn= {Start ='1391264928', Next = 2},} #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2c2dd680>
08 06/14/14 7:27:18.102 JobHandler_LuaUPnP::HandleActionRequest device: 100 service: urn:upnp-org:serviceId:WindowCovering1 action: Up <0x2c2dd680>
50 06/14/14 7:27:18.103 luup_log:27: Arduino: Sending: 30;3;1;29; <0x2c2dd680>
06 06/14/14 7:27:18.104 Device_Variable::m_szValue_set device: 13 service: urn:rts-services-com:serviceId:ProgramLogicC variable: ActionsMap was: {cRaiseBlinds= {Start ='1402752428', Next = 3},_c1LROutletOn= {Start ='1391264928', Next = 2},} now: {_c1LROutletOn= {Start ='1391264928', Next = 2},} #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2c2dd680>
08 06/14/14 7:27:18.105 JobHandler_LuaUPnP::HandleActionRequest device: 102 service: urn:upnp-org:serviceId:WindowCovering1 action: Up <0x2c2dd680>
50 06/14/14 7:27:18.106 luup_log:27: Arduino: Sending: 30;2;1;29; <0x2c2dd680>
50 06/14/14 7:27:19.360 luup_log:27: Arduino: Set Var: 30;3;1;3;100 <0x2f0dd680>
50 06/14/14 7:27:19.361 luup_log:27: Arduino: Setting variable 'LoadLevelStatus' to value '100' <0x2f0dd680>
50 06/14/14 7:27:19.361 luup_log:27: Arduino: urn:upnp-org:serviceId:Dimming1,LoadLevelStatus, 100, 100 <0x2f0dd680>
50 06/14/14 7:27:19.362 luup_log:27: Arduino: urn:micasaverde-com:serviceId:HaDevice1,LastUpdate, 1402752439, 100 <0x2f0dd680>
06 06/14/14 7:27:19.362 Device_Variable::m_szValue_set device: 100 service: urn:micasaverde-com:serviceId:HaDevice1 variable: LastUpdate was: 1402745577 now: 1402752439 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2f0dd680>
50 06/14/14 7:27:19.363 luup_log:27: Arduino: urn:micasaverde-com:serviceId:HaDevice1,LastUpdate, 1402752439, 97 <0x2f0dd680>
06 06/14/14 7:27:19.363 Device_Variable::m_szValue_set device: 97 service: urn:micasaverde-com:serviceId:HaDevice1 variable: LastUpdate was: 1402752430 now: 1402752439 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2f0dd680>
50 06/14/14 7:27:19.364 luup_log:27: Arduino: urn:micasaverde-com:serviceId:HaDevice1,LastUpdateHR, 07:27 AM, 97 <0x2f0dd680>
06 06/14/14 7:27:20.609 Device_Variable::m_szValue_set device: 24 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: LastWakeup was: 1402748801 now: 1402752440 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b8dd680>
02 06/14/14 7:27:20.611 ZWJob_GetNodeDetails::ZWJob_GetNodeDetails skipping return_route for 18 2/1/-1 job job#7 :getnodedetails_ri_wake 18 dev:24 (0x10bb148) P:50 S:0 <0x2b8dd680>
02 06/14/14 7:27:20.612 ZWJob_SendData UPDATE MANUAL ROUTE 18=(nil) <0x2b8dd680>
02 06/14/14 7:27:20.614 ZW_Send_Data node 18 NO ROUTE (nil) <0x2bcdd680>
02 06/14/14 7:27:21.040 ZW_Send_Data node 18 NO ROUTE (nil) <0x2bcdd680>
06 06/14/14 7:27:21.470 Device_Variable::m_szValue_set device: 24 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1402745167 now: 1402752441 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b8dd680>
06 06/14/14 7:27:21.470 Device_Variable::m_szValue_set device: 24 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryLevel was: 100 now: 100 #hooks: 1 upnp: 0 v:0xa059e8/NONE duplicate:1 <0x2b8dd680>
04 06/14/14 7:27:21.471 <0x2b8dd680>
06 06/14/14 7:27:21.540 Device_Variable::m_szValue_set device: 24 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: LastRouteUpdate was: 1402703616 now: 1402752441 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2bcdd680>
Thoughts? Let me know if you need more info.