Unwanted delay in executing action

Hello,

I recently connected my doorbell to a relay and the relay to a Z-wave sensor. I set up VeraAlerts to notify me whenever the doorbell rings. I also set up PLEG to execute a couple of actions. First, when the sensor trips it pauses my Sonos zones if music is playing. Next, if it is night, it turns the outside lights on. I tested several times and everything was working as expected. The only problem was on a quick ring of the doorbell, the sensor didn’t always trip. I tried a different sensor which does seem to trip even on the quick rings. So I changed to input trigger in PLEG to be connected to that sensor. The action that pauses the music works fine and executes within a half second. However, the light is now taking 7-10 seconds to turn on whereas it also turned on within about a half second of the doorbell ringing previously. Since all I did was edited the input trigger because I changed sensors, I can’t figure out what went wrong.

I ended up deleting the trigger, conditions and actions and re-adding them. I also added another instance of PLEG for the doorbell, which I wanted to do anyway so I could “bypass” just the doorbell actions easily. Everything related to the doorbell in the other PLEG has been removed and the triggers and conditions in the new one all have different names. I’m still having the same result, music will pause right away but the light still takes 7-10 seconds to turn on. The condition for that is that the doorbell sensor tripped AND that it’s night. I set up the action with another light but had the same result.

I enabled debugging at one point to see if I could figure out what was causing the delay, but I can’t make sense of it. For testing, I changed the light from outside light to an inside light which is listed as Device 12 in the log.

06	09/18/13 22:07:41.394	Device_Variable::m_szValue_set device: 36 service: urn:micasaverde-com:serviceId:SecuritySensor1 variable: e[35;1mTrippede[0m was: 0 now: 1 #hooks: 2 upnp: 0 v:0x82e6a0/NONE duplicate:0 <0x2b2a3680>
08	09/18/13 22:07:41.395	JobHandler_LuaUPnP::HandleActionRequest device: 10 service: urn:richardgreen:serviceId:VeraAlert1 action: e[36;1mDeviceNotificatione[0m <0x2b2a3680>
08	09/18/13 22:07:41.396	JobHandler_LuaUPnP::HandleActionRequest argument DeviceID=36 <0x2b2a3680>
08	09/18/13 22:07:41.396	JobHandler_LuaUPnP::HandleActionRequest argument Description=%20Doorbell%20Sensor%20is%20tripped <0x2b2a3680>
08	09/18/13 22:07:41.396	JobHandler_LuaUPnP::HandleActionRequest argument Name=Doorbell <0x2b2a3680>
08	09/18/13 22:07:41.396	JobHandler_LuaUPnP::HandleActionRequest argument Service=urn:micasaverde-com:serviceId:SecuritySensor1 <0x2b2a3680>
07	09/18/13 22:07:41.398	Event::Evaluate 4 Doorbell scene Doorbell is true users:318937 allow:1 <0x2b2a3680>
08	09/18/13 22:07:41.399	Scene::RunScene running 22 Doorbell <0x2b2a3680>
50	09/18/13 22:07:41.399	luup_log:18: PLEG:18:TriggerPropertyUpdate:Tripped <0x2b2a3680>
50	09/18/13 22:07:41.400	luup_log:18: PLEG:18:TPU:Tripped :1=1 <0x2b2a3680>
50	09/18/13 22:07:41.400	luup_log:18: PLEG:18:TriggerPropertyUpdate:Name:DoorRing State:true Device:36 <0x2b2a3680>
50	09/18/13 22:07:41.400	luup_log:18: PLEG:18:EvalConditions:Multi Trigger:DoorRing <0x2b2a3680>
50	09/18/13 22:07:41.402	luup_log:18: PLEG:18:EvalConditions:Condition:GarLights Trigger:DoorRing Result:false <0x2b2a3680>
50	09/18/13 22:07:41.403	luup_log:18: PLEG:18:EvalConditions:Condition:GarLightsOff Trigger:DoorRing Result:false <0x2b2a3680>
50	09/18/13 22:07:41.420	luup_log:18: PLEG:18:EvalConditions:Condition:DoorbellPause Trigger:DoorRing Result:true <0x2b2a3680>
50	09/18/13 22:07:41.430	luup_log:18: PLEG:18:TriggerCondition:DoorbellPause <0x2b2a3680>
06	09/18/13 22:07:41.431	Device_Variable::m_szValue_set device: 18 service: urn:rts-services-com:serviceId:ProgramLogicEG variable: e[35;1mConditionSatisfiede[0m was: None now: DoorbellPause #hooks: 0 upnp: 0 v:0x850008/NONE duplicate:0 <0x2b2a3680>
06	09/18/13 22:07:41.431	Device_Variable::m_szValue_set device: 18 service: urn:rts-services-com:serviceId:ProgramLogicEG variable: e[35;1mLastConditionChangee[0m was: 1379556333 now: 1379556461 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b2a3680>
08	09/18/13 22:07:41.432	JobHandler_LuaUPnP::HandleActionRequest device: 18 service: urn:rts-services-com:serviceId:ProgramLogicC action: e[36;1mRunActione[0m <0x2b2a3680>
08	09/18/13 22:07:41.432	JobHandler_LuaUPnP::HandleActionRequest argument conditionName=DoorbellPause <0x2b2a3680>
50	09/18/13 22:07:41.434	luup_log:18: PLEG:18:EvalConditions:Condition:DBellLights Trigger:DoorRing Result:true <0x2b2a3680>
50	09/18/13 22:07:41.435	luup_log:18: PLEG:18:TriggerCondition:DBellLights <0x2b2a3680>
06	09/18/13 22:07:41.435	Device_Variable::m_szValue_set device: 18 service: urn:rts-services-com:serviceId:ProgramLogicEG variable: e[35;1mConditionSatisfiede[0m was: DoorbellPause now: DBellLights #hooks: 0 upnp: 0 v:0x850008/NONE duplicate:0 <0x2b2a3680>
06	09/18/13 22:07:41.436	Device_Variable::m_szValue_set device: 18 service: urn:rts-services-com:serviceId:ProgramLogicEG variable: e[35;1mLastConditionChangee[0m was: 1379556461 now: 1379556461 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2b2a3680>
08	09/18/13 22:07:41.436	JobHandler_LuaUPnP::HandleActionRequest device: 18 service: urn:rts-services-com:serviceId:ProgramLogicC action: e[36;1mRunActione[0m <0x2b2a3680>
08	09/18/13 22:07:41.436	JobHandler_LuaUPnP::HandleActionRequest argument conditionName=DBellLights <0x2b2a3680>
50	09/18/13 22:07:41.439	luup_log:18: PLEG:18:SaveDB:{{name = 'GarLights', state = false, seq = 1379547922.3422},{name = 'Night', state = true, seq = 1379546699.1218},{name = 'GdrOpen', state = false, seq = 1379547801.9356},{name = 'GdrClosed', state = true, seq = 1379547925.2754},{name = 'GarLightIsOn', state = false, seq = 1379551331.2207},{name = 'lrflon', state = false, seq = 1379556042.4153},{name = 'countdown1', state = false, seq = 1379548042.1034},{name = 'lrfloff', state = true, seq = 1379556044.8055},{name = 'GarLightIsOff', state = true, seq = 1379551348.6405},{name = 'GarLightsOff', state = false, seq = 1379548042.1055},{name = 'DoorbellPause', state = true, seq = 1379556461.4303},{name = 'DBellLights', state = true, seq = 1379556461.4347},{name = 'DoorRing', state = true, seq = 1379556461.4002},} <0x2b2a3680>
06	09/18/13 22:07:41.440	Device_Variable::m_szValue_set device: 18 service: urn:rts-services-com:serviceId:ProgramLogicC variable: e[35;1mObjectStatusMape[0m was: {{name = 'GarLights', state = false, seq = 1379547922.3422},{name = 'Night', state = true, seq = 1379546699.1218},{name = 'GdrOpen', state = false, seq = 1379547801.9356},{name = 'GdrClosed', state = true, seq = 1379547925.2754},{name = 'GarLightIsOn', state = false, seq = 1379551331.2207},{name = 'lrflon', state = false, seq = 1379556042.4153},{name = 'countdown1', state = false, seq = 1379548042.1034},{name = 'lrfloff', state = true, seq = 1379556044.8055},{name = 'GarLightIsOff', state = true, seq = 1379551348.6405},{name = 'GarLightsOff', state = false, seq = 1379548042.1055},{name = 'DoorbellPause', state = false, seq = 1379556323.8591},{name = 'DBellLights', state = false, seq = 1379556323.8634},{name = 'DoorRing', state = false, seq = 1379556323.8408},} now: {{name = 'GarLights', state = false, seq = 1379547922.3422},{name = 'Night', state = true, seq = 1379546699.1218},{name = 'GdrOpen', state = false, seq = 1379547801.9356},{name = 'GdrClosed', state = true, seq = 1379547925.2754},{name = 'GarLightIsOn', state = false, seq = 1379551331.2207},{name = 'lrflon', state = false, seq = 1379556042.4153},{name = 'countdown1', state = false, seq = 1379548042.1034},{name = 'lrfloff', state = true, seq = 1379556044.8055},{name = 'GarLightIsOff', state = true, seq = 1379551348.6405},{name = 'GarLightsOff', state = false, seq = 1379548042.1055},{name = 'DoorbellPause', state = true, seq = 1379556461.4303},{name = 'DBellLights', state = true, seq = 1379556461.4347},{name = 'DoorRing', state = true, seq = 1379556461.4002},} #hooks: 0 upnp: 0 v:0x828a38/NONE duplicate:0 <0x2b2a3680>
06	09/18/13 22:07:41.440	Device_Variable::m_szValue_set device: 36 service: urn:micasaverde-com:serviceId:SecuritySensor1 variable: e[35;1mLastTripe[0m was: 1379556333 now: 1379556461 #hooks: 0 upnp: 0 v:0x830200/NONE duplicate:0 <0x2b2a3680>
06	09/18/13 22:07:41.874	Device_Variable::m_szValue_set device: 36 service: urn:micasaverde-com:serviceId:SecuritySensor1 variable: e[35;1mTrippede[0m was: 1 now: 0 #hooks: 2 upnp: 0 v:0x82e6a0/NONE duplicate:0 <0x2b2a3680>
07	09/18/13 22:07:41.875	Event::Evaluate 4 Doorbell scene Doorbell is false repeat 0/-1 <0x2b2a3680>
50	09/18/13 22:07:41.875	luup_log:18: PLEG:18:TriggerPropertyUpdate:Tripped <0x2b2a3680>
50	09/18/13 22:07:41.876	luup_log:18: PLEG:18:TPU:Tripped :0=1 <0x2b2a3680>
50	09/18/13 22:07:41.876	luup_log:18: PLEG:18:TriggerPropertyUpdate:Name:DoorRing State:false Device:36 <0x2b2a3680>
50	09/18/13 22:07:41.877	luup_log:18: PLEG:18:EvalConditions:Multi Trigger:DoorRing <0x2b2a3680>
50	09/18/13 22:07:41.878	luup_log:18: PLEG:18:EvalConditions:Condition:GarLights Trigger:DoorRing Result:false <0x2b2a3680>
50	09/18/13 22:07:41.879	luup_log:18: PLEG:18:EvalConditions:Condition:GarLightsOff Trigger:DoorRing Result:false <0x2b2a3680>
50	09/18/13 22:07:41.880	luup_log:18: PLEG:18:EvalConditions:Condition:DoorbellPause Trigger:DoorRing Result:false <0x2b2a3680>
50	09/18/13 22:07:41.881	luup_log:18: PLEG:18:EvalConditions:Condition:DBellLights Trigger:DoorRing Result:false <0x2b2a3680>
50	09/18/13 22:07:41.882	luup_log:18: PLEG:18:TriggerCondition:None <0x2b2a3680>
06	09/18/13 22:07:41.882	Device_Variable::m_szValue_set device: 18 service: urn:rts-services-com:serviceId:ProgramLogicEG variable: e[35;1mConditionSatisfiede[0m was: DBellLights now: None #hooks: 0 upnp: 0 v:0x850008/NONE duplicate:0 <0x2b2a3680>
06	09/18/13 22:07:41.883	Device_Variable::m_szValue_set device: 18 service: urn:rts-services-com:serviceId:ProgramLogicEG variable: e[35;1mLastConditionChangee[0m was: 1379556461 now: 1379556461 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2b2a3680>
06	09/18/13 22:07:41.886	RAServerSync::SendAlert ID 1598272134,PK_Alert:1598272134 sync 0xdf8f30 for https://cms2.mios.com/alert?PK_AccessPoint=35005780&HW_Key=<edited_by_admin>&DeviceID=36&LocalDate=2013-09-18%2022:07:41&LocalTimestamp=1379556461&AlertType=3&SourceType=3&Argument=4&Format=&Code=Tripped&Value=1&Description=Doorbell&Users=318937 <0x2b4a3680>
50	09/18/13 22:07:41.887	luup_log:18: PLEG:18:SaveDB:{{name = 'GarLights', state = false, seq = 1379547922.3422},{name = 'Night', state = true, seq = 1379546699.1218},{name = 'GdrOpen', state = false, seq = 1379547801.9356},{name = 'GdrClosed', state = true, seq = 1379547925.2754},{name = 'GarLightIsOn', state = false, seq = 1379551331.2207},{name = 'lrflon', state = false, seq = 1379556042.4153},{name = 'countdown1', state = false, seq = 1379548042.1034},{name = 'lrfloff', state = true, seq = 1379556044.8055},{name = 'GarLightIsOff', state = true, seq = 1379551348.6405},{name = 'GarLightsOff', state = false, seq = 1379548042.1055},{name = 'DoorbellPause', state = false, seq = 1379556461.4303},{name = 'DBellLights', state = false, seq = 1379556461.4347},{name = 'DoorRing', state = false, seq = 1379556461.4002},} <0x2b2a3680>
06	09/18/13 22:07:41.887	Device_Variable::m_szValue_set device: 18 service: urn:rts-services-com:serviceId:ProgramLogicC variable: e[35;1mObjectStatusMape[0m was: {{name = 'GarLights', state = false, seq = 1379547922.3422},{name = 'Night', state = true, seq = 1379546699.1218},{name = 'GdrOpen', state = false, seq = 1379547801.9356},{name = 'GdrClosed', state = true, seq = 1379547925.2754},{name = 'GarLightIsOn', state = false, seq = 1379551331.2207},{name = 'lrflon', state = false, seq = 1379556042.4153},{name = 'countdown1', state = false, seq = 1379548042.1034},{name = 'lrfloff', state = true, seq = 1379556044.8055},{name = 'GarLightIsOff', state = true, seq = 1379551348.6405},{name = 'GarLightsOff', state = false, seq = 1379548042.1055},{name = 'DoorbellPause', state = true, seq = 1379556461.4303},{name = 'DBellLights', state = true, seq = 1379556461.4347},{name = 'DoorRing', state = true, seq = 1379556461.4002},} now: {{name = 'GarLights', state = false, seq = 1379547922.3422},{name = 'Night', state = true, seq = 1379546699.1218},{name = 'GdrOpen', state = false, seq = 1379547801.9356},{name = 'GdrClosed', state = true, seq = 1379547925.2754},{name = 'GarLightIsOn', state = false, seq = 1379551331.2207},{name = 'lrflon', state = false, seq = 1379556042.4153},{name = 'countdown1', state = false, seq = 1379548042.1034},{name = 'lrfloff', state = true, seq = 1379556044.8055},{name = 'GarLightIsOff', state = true, seq = 1379551348.6405},{name = 'GarLightsOff', state = false, seq = 1379548042.1055},{name = 'DoorbellPause', state = false, seq = 1379556461.4303},{name = 'DBellLights', state = false, seq = 1379556461.4347},{name = 'DoorRing', state = false, seq = 1379556461.4002},} #hooks: 0 upnp: 0 v:0x828a38/NONE duplicate:0 <0x2b2a3680>
06	09/18/13 22:07:41.888	Device_Variable::m_szValue_set device: 36 service: urn:micasaverde-com:serviceId:SecuritySensor1 variable: e[35;1mLastTripe[0m was: 1379556461 now: 1379556461 #hooks: 0 upnp: 0 v:0x830200/NONE duplicate:1 <0x2b2a3680>
50	09/18/13 22:07:41.980	luup_log:10: VeraAlert:10:SendAlert:Return:200 <0x2ab70000>
04	09/18/13 22:07:41.981	<Job ID="26" Name="" Device="10" Created="2013-09-18 22:07:41" Started="2013-09-18 22:07:41" Completed="2013-09-18 22:07:41" Duration="0.583530000" Runtime="0.568934000" Status="Successful" LastNote=""/> <0x2ab70000>
50	09/18/13 22:07:41.982	luup_log:18: PLEG:18:RunNext:Condition:DoorbellPause Index:1 <0x2ab70000>
50	09/18/13 22:07:41.983	luup_log:18: PLEG:18:SaveActionDB:{} <0x2ab70000>
06	09/18/13 22:07:41.983	Device_Variable::m_szValue_set device: 18 service: urn:rts-services-com:serviceId:ProgramLogicC variable: e[35;1mActionsMape[0m was: {} now: {} #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2ab70000>
08	09/18/13 22:07:41.983	JobHandler_LuaUPnP::HandleActionRequest device: 32 service: urn:upnp-org:serviceId:AVTransport action: e[36;1mPausee[0m <0x2ab70000>
08	09/18/13 22:07:41.984	JobHandler_LuaUPnP::HandleActionRequest argument InstanceID= <0x2ab70000>
08	09/18/13 22:07:42.010	JobHandler_LuaUPnP::HandleActionRequest device: 33 service: urn:upnp-org:serviceId:AVTransport action: e[36;1mPausee[0m <0x2ab70000>
08	09/18/13 22:07:42.010	JobHandler_LuaUPnP::HandleActionRequest argument InstanceID= <0x2ab70000>
06	09/18/13 22:07:42.355	Device_Variable::m_szValue_set device: 36 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: e[35;1mLastWakeupe[0m was: 1379554876 now: 1379556462 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b2a3680>
02	09/18/13 22:07:42.356	e[33;1mZWJob_SendData  UPDATE MANUAL ROUTE 17=(nil)e[0m <0x2b2a3680>
02	09/18/13 22:07:42.358	e[33;1mZW_Send_Data node 17 NO ROUTE (nil)e[0m <0x2b6a3680>
01	09/18/13 22:07:42.425	e[31;1mgot CANe[0m <0x2baa3680>
02	09/18/13 22:07:42.426	e[33;1mZWaveSerial::Send m_iFrameID 82 got a CAN -- Dongle is in a bad state.  Wait 1 second before continuing to let it try to recover.e[0m <0x2b6a3680>
02	09/18/13 22:07:43.555	e[33;1mZW_Send_Data node 17 NO ROUTE (nil)e[0m <0x2b6a3680>
02	09/18/13 22:07:43.706	e[33;1mZW_Send_Data node 17 NO ROUTE (nil)e[0m <0x2b6a3680>
06	09/18/13 22:07:43.855	Device_Variable::m_szValue_set device: 36 service: urn:micasaverde-com:serviceId:HaDevice1 variable: e[35;1mBatteryDatee[0m was: 1379554877 now: 1379556463 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b2a3680>
06	09/18/13 22:07:43.855	Device_Variable::m_szValue_set device: 36 service: urn:micasaverde-com:serviceId:HaDevice1 variable: e[35;1mBatteryLevele[0m was: 100 now: 100 #hooks: 0 upnp: 0 v:0x80aa00/NONE duplicate:1 <0x2b2a3680>
04	09/18/13 22:07:43.856	<Job ID="29" Name="pollnode_wake #17 3 cmds" Device="36" Created="2013-09-18 22:07:42" Started="2013-09-18 22:07:42" Completed="2013-09-18 22:07:43" Duration="1.500491000" Runtime="1.498975000" Status="Successful" LastNote="" Node="17" NodeType="ZWaveBinarySensor" NodeDescription="Doorbell Sensor"/> <0x2b2a3680>
02	09/18/13 22:07:43.858	e[33;1mUPDATE MANUAL ROUTE2 17=(nil)e[0m <0x2b6a3680>
02	09/18/13 22:07:43.858	e[33;1mZW_Send_Data node 17 NO ROUTE (nil)e[0m <0x2b6a3680>
04	09/18/13 22:07:43.965	<Job ID="30" Name="Wakeup done 17" Device="36" Created="2013-09-18 22:07:42" Started="2013-09-18 22:07:43" Completed="2013-09-18 22:07:43" Duration="1.608952000" Runtime="0.107779000" Status="Successful" LastNote="Transmit was ok" Node="17" NodeType="ZWaveBinarySensor" NodeDescription="Doorbell Sensor"/> <0x2b2a3680>
08	09/18/13 22:07:45.015	JobHandler_LuaUPnP::HandleActionRequest device: 34 service: urn:upnp-org:serviceId:AVTransport action: e[36;1mPausee[0m <0x2ab70000>
08	09/18/13 22:07:45.016	JobHandler_LuaUPnP::HandleActionRequest argument InstanceID= <0x2ab70000>
04	09/18/13 22:07:48.026	<Job ID="27" Name="" Device="18" Created="2013-09-18 22:07:41" Started="2013-09-18 22:07:41" Completed="2013-09-18 22:07:48" Duration="6.592614000" Runtime="6.43239000" Status="Successful" LastNote=""/> <0x2ab70000>
02	09/18/13 22:07:48.026	e[33;1mJobHandler::Run job#28 : dev:18 (0xe058e8) P:50 S:0 is 6.589867000 seconds olde[0m <0x2ab70000>
50	09/18/13 22:07:48.027	luup_log:18: PLEG:18:RunNext:Condition:DBellLights Index:1 <0x2ab70000>
50	09/18/13 22:07:48.027	luup_log:18: PLEG:18:SaveActionDB:{} <0x2ab70000>
06	09/18/13 22:07:48.028	Device_Variable::m_szValue_set device: 18 service: urn:rts-services-com:serviceId:ProgramLogicC variable: e[35;1mActionsMape[0m was: {} now: {} #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2ab70000>
08	09/18/13 22:07:48.028	JobHandler_LuaUPnP::HandleActionRequest device: 12 service: urn:upnp-org:serviceId:SwitchPower1 action: e[36;1mSetTargete[0m <0x2ab70000>
08	09/18/13 22:07:48.028	JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x2ab70000>
06	09/18/13 22:07:48.029	Device_Variable::m_szValue_set device: 12 service: urn:upnp-org:serviceId:SwitchPower1 variable: e[35;1mTargete[0m was: 1 now: 1 #hooks: 0 upnp: 0 v:0x7f7418/NONE duplicate:1 <0x2ab70000>
02	09/18/13 22:07:48.030	e[33;1mZWJob_SendData  UPDATE MANUAL ROUTE 6=(nil)e[0m <0x2ab70000>
04	09/18/13 22:07:48.031	<Job ID="28" Name="" Device="18" Created="2013-09-18 22:07:41" Started="2013-09-18 22:07:48" Completed="2013-09-18 22:07:48" Duration="6.593861000" Runtime="0.4073000" Status="Successful" LastNote=""/> <0x2ab70000>
02	09/18/13 22:07:48.032	e[33;1mUPDATE MANUAL ROUTE2 6=(nil)e[0m <0x2b6a3680>
02	09/18/13 22:07:48.033	e[33;1mZW_Send_Data node 6 NO ROUTE (nil)e[0m <0x2b6a3680>
02	09/18/13 22:07:48.116	e[33;1mUPDATE MANUAL ROUTE2 6=(nil)e[0m <0x2b6a3680>
02	09/18/13 22:07:48.116	e[33;1mZW_Send_Data node 6 NO ROUTE (nil)e[0m <0x2b6a3680>
06	09/18/13 22:07:48.224	Device_Variable::m_szValue_set device: 12 service: urn:upnp-org:serviceId:SwitchPower1 variable: e[35;1mStatuse[0m was: 1 now: 1 #hooks: 5 upnp: 0 v:0x7fc6c0/NONE duplicate:1 <0x2b2a3680>
04	09/18/13 22:07:48.225	<Job ID="31" Name="ON node 6" Device="12" Created="2013-09-18 22:07:48" Started="2013-09-18 22:07:48" Completed="2013-09-18 22:07:48" Duration="0.195735000" Runtime="0.193272000" Status="Successful" LastNote="Transmit was ok" Node="6" NodeType="ZWaveNonDimmableLight" NodeDescription="Hall Light"/> <0x2b2a3680>

Thank you for taking a look at this!

Looks like your actions to device 18 (Sound Device ?) takes some time! Maybe change the order.

<0x2ab70000

Hmm… device 18 is the PLEG plugin. I will try changing the order. I am using the Sonos plugin and the action in PLEG pauses 3 music players. I may just remove that condition/action for now and verify that the light coming on is working as expected. I still can’t figure out what changed from the other day when both actions fired right away.

I removed the pause music action and the light came on immediately, added the pause music back at the end and now they both execute immediately. I’m not sure why the action to pause the music continues for so long but I suppose it should be fine as long as it’s the last action. Thanks!