TimeBased Triggers not Executing

hello all,

i do experience since quite a while that some scenes with shedule triggers do not fire.

as example i have one scene at 9am turns on the waterpump … but only if my wife has “late shift” … (simple if-then in luup)
well i ignored this for about 3 weeks and listen every morning the moaming that there is no warm water :stuck_out_tongue:

last night i get to bed arround 2am … and 2 hours later i got shock-waked by my wife because “no warm water”
today i noticed that the 4:00 and the 5:20 scenes also not fire (both are beeing executed only if my wife works “Morning shift”)

the log shows this:

08	02/06/14 5:20:00.100	Scene::RunScene running 39 Zeit 0520 <0x2be79680>
50	02/06/14 5:20:00.101	luup_log:0: Scene 39: Trigger: Schedule 0510 <0x2be79680>
08	02/06/14 5:20:00.202	JobHandler_LuaUPnP::AlarmCallback Ran scene:39 Zeit 0520 / timer:05:20 next at 1391725200 now 1391638800 <0x2be79680>

but the devices stay off.

the scenes are really simple:
4:00 turn on waterpump, and some lights
5:20 turn on the garage and Yard light

here is the luup:

luup.log("Scene 39: Trigger: Schedule 0510")
if ((luup.variable_get("urn:dcineco-com:serviceId:MSwitch1", "Status3", 3) == "1")and(luup.variable_get("urn:upnp-org:serviceId:SwitchPower1", "Status", 61) == "0")) then 
  -- yui hat Fruehschicht und away aus
  -- front licht an
  luup.call_action("urn:upnp-org:serviceId:SwitchPower1","SetTarget",{ newTargetValue="1" },63)
  -- garage licht an
  luup.call_action("urn:upnp-org:serviceId:SwitchPower1","SetTarget",{ newTargetValue="1" },65)
end

if i run the scene manually by just clicking the scene button on the UI … it “just works”
log if manual start:

08	02/06/14 8:46:39.894	JobHandler_LuaUPnP::HandleActionRequest device: 0 service: urn:micasaverde-com:serviceId:HomeAutomationGateway1 action: RunScene <0x31a5a680>
08	02/06/14 8:46:39.895	JobHandler_LuaUPnP::HandleActionRequest argument SceneNum=39 <0x31a5a680>
08	02/06/14 8:46:39.895	Scene::RunScene running 39 Zeit 0520 <0x31a5a680>
50	02/06/14 8:46:39.895	luup_log:0: Scene 39: Trigger: Schedule 0510 <0x31a5a680>
08	02/06/14 8:46:39.896	JobHandler_LuaUPnP::HandleActionRequest device: 63 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x31a5a680>
08	02/06/14 8:46:39.896	JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x31a5a680>
06	02/06/14 8:46:39.897	Device_Variable::m_szValue_set device: 63 service: urn:upnp-org:serviceId:SwitchPower1 variable: Target was: 0 now: 1 #hooks: 0 upnp: 0 v:0x9afef0/NONE duplicate:0 <0x31a5a680>
02	02/06/14 8:46:39.898	ZWJob_SendData  UPDATE MANUAL ROUTE 4=(nil) <0x31a5a680>
08	02/06/14 8:46:39.899	JobHandler_LuaUPnP::HandleActionRequest device: 65 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x31a5a680>
08	02/06/14 8:46:39.899	JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x31a5a680>
06	02/06/14 8:46:39.899	Device_Variable::m_szValue_set device: 65 service: urn:upnp-org:serviceId:SwitchPower1 variable: Target was: 0 now: 1 #hooks: 0 upnp: 0 v:0x9afef0/NONE duplicate:0 <0x31a5a680>
06	02/06/14 8:46:40.241	Device_Variable::m_szValue_set device: 63 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 0 now: 1 #hooks: 6 upnp: 0 v:0x9afed0/NONE duplicate:0 <0x2c219680

any idea ?

doublechecked on the conditions …
they working fine

if ((luup.variable_get("urn:dcineco-com:serviceId:MSwitch1", "Status3", 3) == "1")and(luup.variable_get("urn:upnp-org:serviceId:SwitchPower1", "Status", 61) == "0")) then 
luup.log("BOO")
end

result:

08	02/06/14 8:51:29.949	JobHandler_LuaUPnP::HandleActionRequest device: 0 service: urn:micasaverde-com:serviceId:HomeAutomationGateway1 action: RunLua <0x31a5a680>
08	02/06/14 8:51:29.950	JobHandler_LuaUPnP::HandleActionRequest argument Code=if ((luup.variable_get("urn:dcineco-com:serviceId:MSwitch1", "Status3", 3) == "1")and(luup.variable_get("urn:upnp-org:serviceId:SwitchPower1", "Status", 61) == "0")) then 
luup.log("BOO")
end <0x31a5a680>
50	02/06/14 8:51:29.951	luup_log:0: BOO <0x31a5a680>

i’m out of clues :frowning: (and sleepless)

Maybe it’s time for PLEG … its Status reports make it easy to figure out what is going wrong with your logic.

if and then end
is not very much “logic”

also the scene does work just fine if i click the button … so the logic seems to work fine (it worked for months like this before)

I use a lot of time-based triggers and they work reliably. Did you make sure you are running this everyday? when you open the scene, under schedule, it will show you “last run” is the date and time there correct?

yes they do run every day…
i have confirmed this before writing here. in the trigger window it always show the date correct of the last time it where supposed to run.
even if nothing did happen.

but all it does is:

08	02/06/14 5:20:00.100	Scene::RunScene running 39 Zeit 0520 <0x2be79680>
50	02/06/14 5:20:00.101	luup_log:0: Scene 39: Trigger: Schedule 0510 <0x2be79680>
08	02/06/14 5:20:00.202	JobHandler_LuaUPnP::AlarmCallback Ran scene:39 Zeit 0520 / timer:05:20 next at 1391725200 now 1391638800 <0x2be79680>

zero device activity after this … also no error

yes time triggers are reliable, i have quite some of them and they all work… exept 3 of them.

i just 30 minutes ago added another time trigger to the scene with the error … for 1 minute after now … reloaded waitet one minute … and POOF … it did execute it … very strange that is.

Are you sure it’s not one of the two conditions (A,B) in your if (A AND B) logic that is false at times ?
That’s what PLEG Status report will tell you. Pushing the button and having it work only tells me that they are both true at the time you press the button.
Add the state of each to the log file and you can track if the logic is running and skipping you actions because of the state of one of these.

50	02/06/14 21:54:02.925	luup_log:0: Scene 28: Trigger: Schedule 0400 <0x31a0e680>
50	02/06/14 21:54:02.926	luup_log:0: 3: 1 <0x31a0e680>
50	02/06/14 21:54:02.926	luup_log:0: 61: 0 <0x31a0e680>

looks good to me …
well i made some other changes … like declaring real numbers and so on
and enable debugging …

i will let the ssh terminal open over night with a tail … lets see whats gonna happen
hopefully i have at least better intel from the debug log in a few hours

it turned out, simply deleting the schedule entry … and create a new one at the same time did solve the issue.

mvc support took a week to respond with “Can you also tell me what do you want to accomplish in that scene? You have selectected device no 3 and device no 61, but I cannot find them on your Dashboard.”

:stuck_out_tongue: