workflow issue

pls90 · December 22, 2016, 8:43pm

with the christmas holiday ahead I finally find some time to adress some of my ha issues ;D
I have a workflow that indicates my cat entering or leaving the house.
This is done with 2 motion sensors. If the inner sensor is tripped before the outer the cat is leaving and vice versa.
Only about 50% of the time the indication (leaving/entering) is correct.
I wonder if this is caused by the lack of time resolution.
In the timeline the entering / leaving trigger has mostly the same timestamp (hh:mm:ss) (my cat is a fast little devil).
There seems to be no higher resolution than seconds.
If this is true this could be the cause of my issues.
@amg could you please comment?

Also: I wonder if i could simply my workflow by using some lua.
In PLEG this was quite simple, e.g. for leaving i used

(t_cat_flap_outer_trip;t_cat_flap_inner_trip<20) and t_cat_flap_inner_trip

What would that be in lua?
I have no idea how to transfer the timestamp of the tripped variable of my device “sensor cat flap inner” into a lua expression.
Any hints are greatly appreciated!

phillid2 · December 23, 2016, 12:15am

If the cat is using a typical cat door with a horizontal hinge across the top, perhaps something to detect the door tilting will work: https://www.amazon.com/Ecolink-Intelligent-Technology-Components-TILT-ZWAVE2-ECO/dp/B00HGVJRX2

Depending on the swing of the door, it can report comings and goings.

pls90 · December 23, 2016, 8:24am

didn’t know there were tilt sensors 8-). I built my setup with a binary sensor with 2 inputs and 2 cheap china motion sensors. Had it working flawlessly under PLEG, only after moving to openluup and altui i have some hickups. this is actually the only logig still running on PLEG. Would love to get it going nicely and then remove my last PLEG from vera. sigh.

pls90 · December 23, 2016, 7:13pm

OK, it happend again, workflow not working as expected.
As you can see from the PLEG timestamp screenshot the outer sensor was tripped first, then the inner sensor, so the cat was entering.
Workflow said “cat leaving”.
I tried to capture a screenshot of the timeline, but i am unable since 45 min to access openluup via browser.
I had altui and the workflow in question opened on the browser of my phone before this happened, so I tried to get some info from there.
Message of the workflow page is “Os command request failed (returned error)” and “Controller did not respond”.
This unresponsiveness was the reason I shut down openluup 2 months ago.
Now over the holiday I’m trying to tackle the issue.
Please find attached the workflow and the log a couple of minutes after the cat entered.
Sadly, in neither of the rotated logs is the initial entering visible.
The time stamp it all started was 19:14.

Edit:
Now I was able to load the UI again, I didn’t do a luupreload. Came back by itself.

pls90 · December 23, 2016, 7:22pm

an additional bit of information:
on the timeline (attached) under “watches” there are both trips visible, but under “security” there is only an event for the inner sensor. Shouldn’t there be also 2 entries?

Also, a bit after the cat came in there is a huge number entries with “motion detected” - “no motion” - “motion detected” - “no motion” and so on, multiples within the same second.
This is a different sensor, nothing to do with the cat flap.

pls90 · December 24, 2016, 12:04pm

solved the problem with not being able to access altui.
CPU load was 198% because on motion sensor was constantly sending tripped / not tripped.
That kept the workflow quite busy…
Still have no clue about the issue with the triggers for entering / leaving being interpreted incorrectly.

CudaNet · December 24, 2016, 5:32pm

I had the same exact thing happen to me, added a motion sensor to a workflow and when the sensor is tripped CPU’s top out… At first I thought it was something to do with me Workflow logic. Too busy at the moment to analyze.

amg0 · December 24, 2016, 5:50pm

hard to analyze. in doubt, you enable DEBUG mode and analyze workflow transitions in the log
it is normal that the UI does not reflect all changes in real time ( cannot poll too often ) but the underlying workflow is working in real time. there if no latency of 1s or whatever but in fact, when the workflow gets into another state it immediately evalutes new state transitions and if your workflow is not well designed you could end up with 100% cpu situations.

the best is to start simple with only a few states for your inner motion sensor ( just to detect tripped and untripped ) then continue build it up gradually from here

let’s see where this brings you , but in the end, it should work

pls90 · December 26, 2016, 6:20pm

my cat was kind enough to provide more data for analysis.
As you can see from the timestamps of PLEG status, that the outer sensor was tripped first, then the inner sensor.
Workflow announced leaving.
In the log:

[code]10210 = inner
10211 = outer

2016-12-24 19:34:05.473 luup.variable_set:5: 10210.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:1
2016-12-24 19:34:05.473 luup.variable_set:5: 10210.urn:micasaverde-com:serviceId:SecuritySensor1.ArmedTripped was: 0 now: 1 #hooks:0
2016-12-24 19:34:05.473 luup.variable_set:5: 10210.urn:micasaverde-com:serviceId:SecuritySensor1.LastTrip was: 1482599741 now: 1482604444 #hooks:0
2016-12-24 19:34:05.474 luup.variable_set:5: 10211.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:1
2016-12-24 19:34:05.474 luup.variable_set:5: 10211.urn:micasaverde-com:serviceId:SecuritySensor1.LastTrip was: 1482599743 now: 1482604439 #hooks:0
2016-12-24 19:34:05.474 luup.variable_set:5: 10211.urn:micasaverde-com:serviceId:SecuritySensor1.ArmedTripped was: 0 now: 1 #hooks:0
2016-12-24 19:34:19.047 luup_log:3: ALTUI: Wkflow - Workflow: 0-30, Valid Transition found:motion_inner, Active State:waiting=>inner tripped
2016-12-24 19:34:19.047 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.Timers was: [] now: [] #hooks:0
2016-12-24 19:34:19.054 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.WorkflowsActiveState was: {“0-3”:“582a5825-8463-4165-847c-3d808246f23f”,“0-44”:“2f001db9-64a3-4bfb-b575-5fc87a5a367f”,“0-36”:"2f65637a-c544-4… now: {“0-3”:“582a5825-8463-4165-847c-3d808246f23f”,“0-44”:“2f001db9-64a3-4bfb-b575-5fc87a5a367f”,“0-36”:"2f65637a-c544-4… #hooks:0
2016-12-24 19:34:19.071 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.Timers was: [] now: [{“armed”:true,“data”:"3#19#8a553840-e2fd-4c11-9eed-4a88ac37f221#c62b0508-54f6-4430-b8e1-5d41fb407e65#a7c462f5-ef75… #hooks:0
2016-12-24 19:34:19.085 luup.watch_callback:: 10211.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped function: 0xe34ec0
2016-12-24 19:34:19.103 luup_log:3: ALTUI: Wkflow - Workflow: 0-30, Valid Transition found:motion_outer, Active State:inner tripped=>notify away
2016-12-24 19:34:19.103 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.Timers was: [{“armed”:true,“data”:"3#19#8a553840-e2fd-4c11-9eed-4a88ac37f221#c62b0508-54f6-4430-b8e1-5d41fb407e65#a7c462f5-ef75… now: [] #hooks:0
2016-12-24 19:34:19.110 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.WorkflowsActiveState was: {“0-3”:“582a5825-8463-4165-847c-3d808246f23f”,“0-44”:“2f001db9-64a3-4bfb-b575-5fc87a5a367f”,“0-36”:"2f65637a-c544-4… now: {“0-3”:“582a5825-8463-4165-847c-3d808246f23f”,“0-44”:“2f001db9-64a3-4bfb-b575-5fc87a5a367f”,“0-36”:"2f65637a-c544-4… #hooks:0
2016-12-24 19:34:19.114 luup.call_action:3: 22.urn:upnp-org:serviceId:IOSPush1.SendPushOverNotification
2016-12-24 19:34:20.118 luup.variable_set:22: 22.urn:upnp-org:serviceId:IOSPush1.TimeSend was: 1482599733 now: 1482604460 #hooks:0[/code]

The workflow works correctly when the cat is entering slowly, when she is fast there seems to be a problem with two consecutive triggers in close timely proximity.
This time there were 5s between trip of outer and inner sensor.

The workflow is quite simple and straight forward.
I don’t think that the problem can be solved by changing workflows.
Just to try a different approach: could I use lua code to evaluate transitions?
Something like

if timestamp_outer_trip < timestamp_inner_trip then "entering"

amg0 · December 26, 2016, 6:38pm

[quote=“pls90, post:9, topic:194845”]my cat was kind enough to provide more data for analysis.
As you can see from the timestamps of PLEG status, that the outer sensor was tripped first, then the inner sensor.
Workflow announced leaving.
In the log:

[code]10210 = inner
10211 = outer

2016-12-24 19:34:05.473 luup.variable_set:5: 10210.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:1
2016-12-24 19:34:05.473 luup.variable_set:5: 10210.urn:micasaverde-com:serviceId:SecuritySensor1.ArmedTripped was: 0 now: 1 #hooks:0
2016-12-24 19:34:05.473 luup.variable_set:5: 10210.urn:micasaverde-com:serviceId:SecuritySensor1.LastTrip was: 1482599741 now: 1482604444 #hooks:0
2016-12-24 19:34:05.474 luup.variable_set:5: 10211.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:1
2016-12-24 19:34:05.474 luup.variable_set:5: 10211.urn:micasaverde-com:serviceId:SecuritySensor1.LastTrip was: 1482599743 now: 1482604439 #hooks:0
2016-12-24 19:34:05.474 luup.variable_set:5: 10211.urn:micasaverde-com:serviceId:SecuritySensor1.ArmedTripped was: 0 now: 1 #hooks:0
2016-12-24 19:34:19.047 luup_log:3: ALTUI: Wkflow - Workflow: 0-30, Valid Transition found:motion_inner, Active State:waiting=>inner tripped
2016-12-24 19:34:19.047 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.Timers was: [] now: [] #hooks:0
2016-12-24 19:34:19.054 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.WorkflowsActiveState was: {“0-3”:“582a5825-8463-4165-847c-3d808246f23f”,“0-44”:“2f001db9-64a3-4bfb-b575-5fc87a5a367f”,“0-36”:"2f65637a-c544-4… now: {“0-3”:“582a5825-8463-4165-847c-3d808246f23f”,“0-44”:“2f001db9-64a3-4bfb-b575-5fc87a5a367f”,“0-36”:"2f65637a-c544-4… #hooks:0
2016-12-24 19:34:19.071 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.Timers was: [] now: [{“armed”:true,“data”:"3#19#8a553840-e2fd-4c11-9eed-4a88ac37f221#c62b0508-54f6-4430-b8e1-5d41fb407e65#a7c462f5-ef75… #hooks:0
2016-12-24 19:34:19.085 luup.watch_callback:: 10211.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped function: 0xe34ec0
2016-12-24 19:34:19.103 luup_log:3: ALTUI: Wkflow - Workflow: 0-30, Valid Transition found:motion_outer, Active State:inner tripped=>notify away
2016-12-24 19:34:19.103 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.Timers was: [{“armed”:true,“data”:"3#19#8a553840-e2fd-4c11-9eed-4a88ac37f221#c62b0508-54f6-4430-b8e1-5d41fb407e65#a7c462f5-ef75… now: [] #hooks:0
2016-12-24 19:34:19.110 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.WorkflowsActiveState was: {“0-3”:“582a5825-8463-4165-847c-3d808246f23f”,“0-44”:“2f001db9-64a3-4bfb-b575-5fc87a5a367f”,“0-36”:"2f65637a-c544-4… now: {“0-3”:“582a5825-8463-4165-847c-3d808246f23f”,“0-44”:“2f001db9-64a3-4bfb-b575-5fc87a5a367f”,“0-36”:"2f65637a-c544-4… #hooks:0
2016-12-24 19:34:19.114 luup.call_action:3: 22.urn:upnp-org:serviceId:IOSPush1.SendPushOverNotification
2016-12-24 19:34:20.118 luup.variable_set:22: 22.urn:upnp-org:serviceId:IOSPush1.TimeSend was: 1482599733 now: 1482604460 #hooks:0[/code]

The workflow works correctly when the cat is entering slowly, when she is fast there seems to be a problem with two consecutive triggers in close timely proximity.
This time there were 5s between trip of outer and inner sensor.

The workflow is quite simple and straight forward.
I don’t think that the problem can be solved by changing workflows.
Just to try a different approach: could I use lua code to evaluate transitions?
Something like

if timestamp_outer_trip < timestamp_inner_trip then "entering"

What exactly is the conditions for the motion_inner and motion_outer ?
it seems that the root cause can be that watches are processed in the order they are notified by VERA ( with luup watch I suppose and like you see in the log ) while the actual order of tripping timestamp is different as you can see in the logs

2016-12-24 19:34:05.473 luup.variable_set:5: 10210.urn:micasaverde-com:serviceId:SecuritySensor1.LastTrip was: 1482599741 now: 1482604444 #hooks:0 2016-12-24 19:34:05.474 luup.variable_set:5: 10211.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:1 2016-12-24 19:34:05.474 luup.variable_set:5: 10211.urn:micasaverde-com:serviceId:SecuritySensor1.LastTrip was: 1482599743 now: 1482604439 #hooks:0

maybe the way is to have a workflow which wait for 2 tripping ( indiferently inner ou outer ) in an interval less than 2 seconds. Once that has happened , then get the actual timestamps to do a diff and decide , based on the sign of the diff , if it is in or out event

potential worfklow
S0 : idle
Transition:
either one trip happens

S1 : one trip happened
Transition:
timer 2 s => go back to idle S0
second trip happens => S2

S2 : 2 trip happenned
motion_in : condition compares the 2 motion timestamps and is inner>outer
motion_out : condition compares the 2 motion timestamps and is outer>inner

pls90 · December 26, 2016, 10:43pm

What exactly is the conditions for the motion_inner and motion_outer ?

please see attached workflow a bit up the thread only condition for motion_inner and motion_outer is the corresponding sensor to be tripped

what troubles me is that in the log the inner sensor is reported to be tripped before the outer sensor although it is the other way round.
10210 = inner
10211 = outer

2016-12-24 19:34:05.473   luup.variable_set:5: 10210.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:1

2016-12-24 19:34:05.474   luup.variable_set:5: 10211.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:1

to me the problem seems to be the wrong order of the tripping of the sensors.
no change in workflow can workaround that issue.

amg0 · December 27, 2016, 12:53pm

[quote=“pls90, post:11, topic:194845”]

What exactly is the conditions for the motion_inner and motion_outer ?

please see attached workflow a bit up the thread
only condition for motion_inner and motion_outer is the corresponding sensor to be tripped

what troubles me is that in the log the inner sensor is reported to be tripped before the outer sensor although it is the other way round.
10210 = inner
10211 = outer

2016-12-24 19:34:05.473   luup.variable_set:5: 10210.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:1

2016-12-24 19:34:05.474   luup.variable_set:5: 10211.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:1

to me the problem seems to be the wrong order of the tripping of the sensors.
no change in workflow can workaround that issue.[/quote]
This is what I explained in the previous post and the workflow change I suggest should work around the issue. Maybe try it and let me know .

pls90 · December 27, 2016, 9:56pm

amg0, I don’t want to be complicated or to seem stubborn here, but I still don’t get it, so please bear with me.
I did think you suggestion through, but I think even you proposal would lead to the same result.

potential worfklow S0 : idle Transition: either one trip happens
S1 : one trip happened
Transition:
timer 2 s => go back to idle S0
second trip happens => S2

I think 2s timer is too short, as the cat usually manages to get in in something between 1s and <10s.
Still, in my example with very short entering time your 2s timer would not have been a problem, workflow would have gone to s1, then s2.

S2 : 2 trip happenned motion_in : condition compares the 2 motion timestamps and is inner>outer motion_out : condition compares the 2 motion timestamps and is outer>inner

In the example the timestamp of inner is 19:34:05.473 and outer is 19:34:05.474
So the proposed comparison would result in outer>inner to be true, which would indicate motion_out = “cat left” which she didn’t.

Am I missing something?

pls90 · December 27, 2016, 10:02pm

when I changed the timing of one of my timers and saved I saw this in the console error log:

2016-12-27T21:39:13.869Z: ALTUI v1.75:Cannot schedule twice the same timer altui-workflow-timer

amg0 · December 28, 2016, 9:15am

[quote=“pls90, post:14, topic:194845”]when I changed the timing of one of my timers and saved I saw this in the console error log:

2016-12-27T21:39:13.869Z: ALTUI v1.75:Cannot schedule twice the same timer altui-workflow-timer

That s fine, it is ? UI message because you switch pages.

amg0 · December 28, 2016, 9:22am

[quote=“pls90, post:13, topic:194845”]amg0, I don’t want to be complicated or to seem stubborn here, but I still don’t get it, so please bear with me.
I did think you suggestion through, but I think even you proposal would lead to the same result.

potential worfklow S0 : idle Transition: either one trip happens
S1 : one trip happened
Transition:
timer 2 s => go back to idle S0
second trip happens => S2

I think 2s timer is too short, as the cat usually manages to get in in something between 1s and <10s.
Still, in my example with very short entering time your 2s timer would not have been a problem, workflow would have gone to s1, then s2.

S2 : 2 trip happenned motion_in : condition compares the 2 motion timestamps and is inner>outer motion_out : condition compares the 2 motion timestamps and is outer>inner

In the example the timestamp of inner is 19:34:05.473 and outer is 19:34:05.474
So the proposed comparison would result in outer>inner to be true, which would indicate motion_out = “cat left” which she didn’t.

Am I missing something?[/quote]
Yes, the time stamp to use for the comparison are the Linux time stamp number in the LastTrip variable, these are in the correct order so time2(outer)-time1(inner) will be >0 if the cat is leaving.

Essentially the key is to let the workflow decide if it is in or out based on the lasttrip and only once both are set.

pls90 · December 29, 2016, 9:07pm

OK amg, understood.
I’d like to give it a try, but …

a) how do I read the timestamp of the variable?
I searched through the wiki and tried this

local ID_inner = 10210 --inner local ID_outer = 10211 --outer local inner, tstamp_inner = luup.variable_get("urn:micasaverde-com:serviceId:SecuritySensor1", "Tripped", ID_inner) or "","" local outer, tstamp_outer = luup.variable_get("urn:micasaverde-com:serviceId:SecuritySensor1", "Tripped", ID_outer) or "","" print("inner: " .. inner .. " timestamp inner: " .. tstamp_inner .. "outer: " .. outer .. " timestamp outer: " .. tstamp_outer)
but it seems that the timestamp is allways nil. On the devices page I can see the last trip date, so there is a way.
I found I could do it like this

local tstamp_inner = luup.variable_get("urn:micasaverde-com:serviceId:SecuritySensor1", "LastTrip", ID_inner) or "" local tstamp_outer = luup.variable_get("urn:micasaverde-com:serviceId:SecuritySensor1", "LastTrip", ID_outer) or ""
but if you want to get the last time a variable has changed, how do you do that in lua?

b) where should I put the code? Is there a way to put lua code in a transition (didn’t find it).
In the on_enter of a state seems to be a section for lua code, but I need something like "if “entering” goto state “notify entering” else goto state “notify away” .
Or do I have to do the notification from within the state action?

Thanks again for your help!

amg0 · December 29, 2016, 10:19pm

[quote=“pls90, post:17, topic:194845”]OK amg, understood.
I’d like to give it a try, but …

a) how do I read the timestamp of the variable?
I searched through the wiki and tried this

local ID_inner = 10210 --inner local ID_outer = 10211 --outer local inner, tstamp_inner = luup.variable_get("urn:micasaverde-com:serviceId:SecuritySensor1", "Tripped", ID_inner) or "","" local outer, tstamp_outer = luup.variable_get("urn:micasaverde-com:serviceId:SecuritySensor1", "Tripped", ID_outer) or "","" print("inner: " .. inner .. " timestamp inner: " .. tstamp_inner .. "outer: " .. outer .. " timestamp outer: " .. tstamp_outer)
but it seems that the timestamp is allways nil. On the devices page I can see the last trip date, so there is a way.
I found I could do it like this

local tstamp_inner = luup.variable_get("urn:micasaverde-com:serviceId:SecuritySensor1", "LastTrip", ID_inner) or "" local tstamp_outer = luup.variable_get("urn:micasaverde-com:serviceId:SecuritySensor1", "LastTrip", ID_outer) or ""
but if you want to get the last time a variable has changed, how do you do that in lua?

b) where should I put the code? Is there a way to put lua code in a transition (didn’t find it).
In the on_enter of a state seems to be a section for lua code, but I need something like "if “entering” goto state “notify entering” else goto state “notify away” .
Or do I have to do the notification from within the state action?

Thanks again for your help![/quote]

yes luup.variable_get(“urn:micasaverde-com:serviceId:SecuritySensor1”, “LastTrip”, ID_outer) is the way.

in a transition you type a lua expression that must be evaluated to true in order to fire the transition, so you can type things like:

tonumber(luup.variable_get("urn:micasaverde-com:serviceId:SecuritySensor1", "LastTrip", ID_outer)) - tonumber(luup.variable_get("urn:micasaverde-com:serviceId:SecuritySensor1", "LastTrip", ID_inner)) >0

pls90 · December 29, 2016, 11:04pm

I just set it up as you suggested, I will report back what the cat makes of it

May I ask how to retrieve the time stamp of the last change of a variable?
I would like to use lua code in a scene instead of a workflow to detect double and tripple clicks of a scene controller.
I used to do this with one line of code in PLEG.
Scene Controller has 3 variables:
LastSceneID, LastSceneTime, sl_SceneActivated.
Code needs to be something like
if (LastSceneTime > sl_SceneActivated) and LastSceneID==“25” then --tripple click
The missing piece is how to get timestamp of change of sl_SceneActivated

amg0 · December 30, 2016, 4:36pm

[quote=“pls90, post:19, topic:194845”]I just set it up as you suggested, I will report back what the cat makes of it

May I ask how to retrieve the time stamp of the last change of a variable?[/quote]
luup.variable_get() returns 2 values, the value and the last change timestamp

I tested this code in the ALTUI test lua window against both a security device and a basic lamp , both calls to variable_get() are properly returning the current value of the variable and the last changed timestamp, so that should work. maybe there is a openluup difference ?

local al,be = luup.variable_get("urn:micasaverde-com:serviceId:SecuritySensor1", "LastTrip", 315) print( al,be ) al,be = luup.variable_get("urn:upnp-org:serviceId:SwitchPower1", "Status", 6) print( al,be ) return true