Conditions and Triggers: The difference?

jbrown · 2018-02-20 05:09:08 UTC

does closing it reset that timer by default?

bangali · 2018-02-20 05:33:31 UTC

the timer gets cancelled if the door is closed before 5 mins.

jbrown · 2018-03-08 01:38:54 UTC

Ok I finally caught it with a false alarm and logs turned on! Here’s a quick screenshot of the logs. If there’s another way to share or look at let me know.

jbrown · 2018-03-08 01:40:28 UTC

Sorry, not sure why photos uploaded like that?

bangali · 2018-03-08 01:41:41 UTC

just select the log text and paste it. also please post the piston green snapshot as is with trace on.

jbrown · 2018-03-08 04:34:09 UTC

Log Text:
3/7/2018, 8:33:44 PM +381ms
+1ms ╔Received event [Home].time = 1520472825823 with a delay of -1443ms
+179ms ║RunTime Analysis CS > 24ms > PS > 66ms > PE > 89ms > CE
+182ms ║Runtime (37838 bytes) successfully initialized in 66ms (v0.3.000.20180224) (181ms)
+183ms ║╔Execution stage started
+192ms ║║Cancelling condition #5’s schedules…
+192ms ║║Condition #5 evaluated true (1ms)
+194ms ║║Cancelling condition #1’s schedules…
+195ms ║║Condition group #1 evaluated true (state changed) (4ms)
+197ms ║║Cancelling statement #2’s schedules…
+364ms ║║Executed physical command [SONOS].playTextAndResume([Refrigerator door has been left open, 50]) (158ms)
+365ms ║║Executed [SONOS].playTextAndResume (160ms)
+395ms ║║Executed virtual command [SONOS].sendNotificationToContacts (21ms)
+398ms ║╚Execution stage complete. (215ms)
+400ms ╚Event processed successfully (399ms)
3/7/2018, 8:28:45 PM +451ms
+1ms ╔Received event [Refrigerator].contact = open with a delay of 1070ms
+352ms ║RunTime Analysis CS > 24ms > PS > 233ms > PE > 95ms > CE
+355ms ║Runtime (37843 bytes) successfully initialized in 233ms (v0.3.000.20180224) (353ms)
+356ms ║╔Execution stage started
+369ms ║║Comparison (enum) open stays (string) open = true (2ms)
+371ms ║║Adding a timed trigger schedule for condition 5
+373ms ║║Condition #5 evaluated false (10ms)
+374ms ║║Condition group #1 evaluated false (state did not change) (12ms)
+377ms ║╚Execution stage complete. (21ms)
+379ms ║Setting up scheduled job for Wed, Mar 7 2018 @ 8:33:45 PM EST (in 299.994s)
+388ms ╚Event processed successfully (388ms)
3/7/2018, 8:28:27 PM +923ms
+1ms ╔Received event [Refrigerator].contact = closed with a delay of 256ms
+152ms ║RunTime Analysis CS > 18ms > PS > 47ms > PE > 88ms > CE
+155ms ║Runtime (37840 bytes) successfully initialized in 47ms (v0.3.000.20180224) (154ms)
+156ms ║╔Execution stage started
+167ms ║║Comparison (enum) closed stays (string) open = false (2ms)
+170ms ║║Cancelling any timed trigger schedules for condition 5
+170ms ║║Cancelling statement #5’s schedules…
+171ms ║║Condition #5 evaluated false (9ms)
+172ms ║║Condition group #1 evaluated false (state did not change) (11ms)
+175ms ║╚Execution stage complete. (18ms)
+176ms ╚Event processed successfully (176ms)
3/7/2018, 8:28:23 PM +435ms
+2ms ╔Received event [Refrigerator].contact = open with a delay of 298ms
+192ms ║RunTime Analysis CS > 24ms > PS > 64ms > PE > 103ms > CE
+195ms ║Runtime (37841 bytes) successfully initialized in 64ms (v0.3.000.20180224) (193ms)
+196ms ║╔Execution stage started
+209ms ║║Comparison (enum) open stays (string) open = true (2ms)
+211ms ║║Adding a timed trigger schedule for condition 5
+214ms ║║Condition #5 evaluated false (11ms)
+215ms ║║Condition group #1 evaluated false (state did not change) (13ms)
+218ms ║╚Execution stage complete. (21ms)
+219ms ║Setting up scheduled job for Wed, Mar 7 2018 @ 8:33:23 PM EST (in 299.993s)
+226ms ╚Event processed successfully (226ms)
3/7/2018, 6:48:48 PM +315ms
+1ms ╔Received event [Home].time = 1520466529239 with a delay of -924ms
+156ms ║RunTime Analysis CS > 27ms > PS > 46ms > PE > 82ms > CE
+158ms ║Runtime (37839 bytes) successfully initialized in 46ms (v0.3.000.20180224) (157ms)
+159ms ║╔Execution stage started
+160ms ║╚Execution stage complete. (1ms)
+161ms ╚Event processed successfully (161ms)
3/7/2018, 6:44:04 PM +175ms
+1ms ╔Received event [Refrigerator].contact = closed with a delay of 1293ms
+179ms ║RunTime Analysis CS > 22ms > PS > 64ms > PE > 93ms > CE
+182ms ║Runtime (37841 bytes) successfully initialized in 64ms (v0.3.000.20180224) (179ms)
+182ms ║╔Execution stage started
+191ms ║║Comparison (enum) closed stays (string) open = false (1ms)
+193ms ║║Cancelling any timed trigger schedules for condition 5
+194ms ║║Cancelling statement #5’s schedules…
+194ms ║║Condition #5 evaluated false (7ms)
+195ms ║║Condition group #1 evaluated false (state did not change) (8ms)
+197ms ║╚Execution stage complete. (15ms)
+198ms ╚Event processed successfully (198ms)
3/7/2018, 6:43:49 PM +80ms
+1ms ╔Received event [Refrigerator].contact = open with a delay of 114ms
+144ms ║RunTime Analysis CS > 18ms > PS > 42ms > PE > 84ms > CE
+147ms ║Runtime (37840 bytes) successfully initialized in 42ms (v0.3.000.20180224) (146ms)
+148ms ║╔Execution stage started
+157ms ║║Comparison (enum) open stays (string) open = true (2ms)
+159ms ║║Adding a timed trigger schedule for condition 5
+160ms ║║Condition #5 evaluated false (8ms)
+161ms ║║Condition group #1 evaluated false (state did not change) (9ms)
+163ms ║╚Execution stage complete. (16ms)
+165ms ║Setting up scheduled job for Wed, Mar 7 2018 @ 6:48:49 PM EST (in 299.995s)
+174ms ╚Event processed successfully (174ms)
3/7/2018, 6:43:41 PM +112ms
+1ms ╔Received event [Refrigerator].contact = closed with a delay of 601ms
+183ms ║RunTime Analysis CS > 24ms > PS > 68ms > PE > 92ms > CE
+304ms ║Runtime (37840 bytes) successfully initialized in 68ms (v0.3.000.20180224) (302ms)
+305ms ║╔Execution stage started
+314ms ║║Comparison (enum) closed stays (string) open = false (1ms)
+316ms ║║Cancelling any timed trigger schedules for condition 5
+317ms ║║Cancelling statement #5’s schedules…
+318ms ║║Condition #5 evaluated false (7ms)
+318ms ║║Condition group #1 evaluated false (state did not change) (8ms)
+320ms ║╚Execution stage complete. (15ms)
+322ms ╚Event processed successfully (321ms)
3/7/2018, 6:43:40 PM +81ms
+1ms ╔Received event [Refrigerator].contact = open with a delay of 806ms
+474ms ║RunTime Analysis CS > 21ms > PS > 366ms > PE > 87ms > CE
+477ms ║Runtime (37842 bytes) successfully initialized in 366ms (v0.3.000.20180224) (475ms)
+478ms ║╔Execution stage started
+487ms ║║Comparison (enum) open stays (string) open = true (1ms)
+488ms ║║Adding a timed trigger schedule for condition 5
+490ms ║║Condition #5 evaluated false (7ms)
+491ms ║║Condition group #1 evaluated false (state did not change) (9ms)
+493ms ║╚Execution stage complete. (15ms)
+495ms ║Setting up scheduled job for Wed, Mar 7 2018 @ 6:48:40 PM EST (in 299.995s)
+528ms ╚Event processed successfully (528ms)
3/7/2018, 6:09:35 PM +662ms
+1ms ╔Received event [Home].time = 1520464176898 with a delay of -1236ms
+236ms ║RunTime Analysis CS > 42ms > PS > 71ms > PE > 122ms > CE
+240ms ║Runtime (37841 bytes) successfully initialized in 71ms (v0.3.000.20180224) (237ms)
+241ms ║╔Execution stage started
+242ms ║╚Execution stage complete. (2ms)
+243ms ╚Event processed successfully (243ms)
3/7/2018, 6:04:40 PM +521ms
+1ms ╔Received event [Refrigerator].contact = closed with a delay of 240ms
+201ms ║RunTime Analysis CS > 24ms > PS > 66ms > PE > 112ms > CE
+205ms ║Runtime (37841 bytes) successfully initialized in 66ms (v0.3.000.20180224) (202ms)
+206ms ║╔Execution stage started
+217ms ║║Comparison (enum) closed stays (string) open = false (2ms)
+219ms ║║Cancelling any timed trigger schedules for condition 5
+220ms ║║Cancelling statement #5’s schedules…
+221ms ║║Condition #5 evaluated false (10ms)
+222ms ║║Condition group #1 evaluated false (state did not change) (11ms)
+224ms ║╚Execution stage complete. (19ms)
+226ms ╚Event processed successfully (226ms)
3/7/2018, 6:04:36 PM +487ms
+1ms ╔Received event [Refrigerator].contact = open with a delay of 547ms
+392ms ║RunTime Analysis CS > 23ms > PS > 68ms > PE > 301ms > CE
+395ms ║Runtime (37841 bytes) successfully initialized in 68ms (v0.3.000.20180224) (393ms)
+396ms ║╔Execution stage started
+408ms ║║Comparison (enum) open stays (string) open = true (2ms)
+410ms ║║Adding a timed trigger schedule for condition 5
+413ms ║║Condition #5 evaluated false (11ms)
+414ms ║║Condition group #1 evaluated false (state did not change) (12ms)
+417ms ║╚Execution stage complete. (20ms)
+418ms ║Setting up scheduled job for Wed, Mar 7 2018 @ 6:09:36 PM EST (in 299.993s)
+426ms ╚Event processed successfully (426ms)

Snapshot:

I should note that I can verify the fridge was completely shut and had been for at least a minute or so before the announcement went off. I can also verify that it had not been left open for 5 mins prior to that at any point this evening.

bangali · 2018-03-08 05:29:16 UTC

thanks. here is a trimmed down version of the log:

3/7/2018, 8:33:44 PM +381ms
+1ms	╔Received event [Home].time = 1520472825823 with a delay of -1443ms
+179ms	║RunTime Analysis CS > 24ms > PS > 66ms > PE > 89ms > CE
+182ms	║Runtime (37838 bytes) successfully initialized in 66ms (v0.3.000.20180224) (181ms)
+183ms	║╔Execution stage started
+192ms	║║Cancelling condition #5’s schedules…
+192ms	║║Condition #5 evaluated true (1ms)
+194ms	║║Cancelling condition #1’s schedules…
+195ms	║║Condition group #1 evaluated true (state changed) (4ms)
+197ms	║║Cancelling statement #2’s schedules…
+364ms	║║Executed physical command [SONOS].playTextAndResume([Refrigerator door has been left open, 50]) (158ms)
+365ms	║║Executed [SONOS].playTextAndResume (160ms)
+395ms	║║Executed virtual command [SONOS].sendNotificationToContacts (21ms)
+398ms	║╚Execution stage complete. (215ms)
+400ms	╚Event processed successfully (399ms)

3/7/2018, 8:28:45 PM +451ms
+1ms	╔Received event [Refrigerator].contact = open with a delay of 1070ms
+371ms	║║Adding a timed trigger schedule for condition 5
+379ms	║Setting up scheduled job for Wed, Mar 7 2018 @ 8:33:45 PM EST (in 299.994s)

3/7/2018, 8:28:27 PM +923ms
+1ms	╔Received event [Refrigerator].contact = closed with a delay of 256ms
+170ms	║║Cancelling any timed trigger schedules for condition 5

3/7/2018, 8:28:23 PM +435ms
+2ms	╔Received event [Refrigerator].contact = open with a delay of 298ms
+211ms	║║Adding a timed trigger schedule for condition 5
+219ms	║Setting up scheduled job for Wed, Mar 7 2018 @ 8:33:23 PM EST (in 299.993s)

3/7/2018, 6:48:48 PM +315ms
+1ms	╔Received event [Home].time = 1520466529239 with a delay of -924ms
+156ms	║RunTime Analysis CS > 27ms > PS > 46ms > PE > 82ms > CE
+158ms	║Runtime (37839 bytes) successfully initialized in 46ms (v0.3.000.20180224) (157ms)
+159ms	║╔Execution stage started
+160ms	║╚Execution stage complete. (1ms)
+161ms	╚Event processed successfully (161ms)

3/7/2018, 6:44:04 PM +175ms
+1ms	╔Received event [Refrigerator].contact = closed with a delay of 1293ms
+193ms	║║Cancelling any timed trigger schedules for condition 5

3/7/2018, 6:43:49 PM +80ms
+1ms	╔Received event [Refrigerator].contact = open with a delay of 114ms
+159ms	║║Adding a timed trigger schedule for condition 5
+165ms	║Setting up scheduled job for Wed, Mar 7 2018 @ 6:48:49 PM EST (in 299.995s)

3/7/2018, 6:43:41 PM +112ms
+1ms	╔Received event [Refrigerator].contact = closed with a delay of 601ms
+316ms	║║Cancelling any timed trigger schedules for condition 5

3/7/2018, 6:43:40 PM +81ms
+1ms	╔Received event [Refrigerator].contact = open with a delay of 806ms
+488ms	║║Adding a timed trigger schedule for condition 5
+495ms	║Setting up scheduled job for Wed, Mar 7 2018 @ 6:48:40 PM EST (in 299.995s)

3/7/2018, 6:09:35 PM +662ms
+1ms	╔Received event [Home].time = 1520464176898 with a delay of -1236ms
+236ms	║RunTime Analysis CS > 42ms > PS > 71ms > PE > 122ms > CE
+240ms	║Runtime (37841 bytes) successfully initialized in 71ms (v0.3.000.20180224) (237ms)
+241ms	║╔Execution stage started
+242ms	║╚Execution stage complete. (2ms)
+243ms	╚Event processed successfully (243ms)

3/7/2018, 6:04:40 PM +521ms
+1ms	╔Received event [Refrigerator].contact = closed with a delay of 240ms
+219ms	║║Cancelling any timed trigger schedules for condition 5

3/7/2018, 6:04:36 PM +487ms
+1ms	╔Received event [Refrigerator].contact = open with a delay of 547ms
+410ms	║║Adding a timed trigger schedule for condition 5
+418ms	║Setting up scheduled job for Wed, Mar 7 2018 @ 6:09:36 PM EST (in 299.993s)

from this the refrigerator was last opened at 8:28:45 PM but it was not closed. so at 8:33:44 PM i.e. 5 minutes later the announcement was made.

thats not to say you did not close the fridge more likely:

the close event was never received by ST
the close event was never received by the piston

here 1 is more likely than 2.

what kind of contact sensor are you using? a repeater might help if this is happening frequently.

@ipaterson check out the home.time event from 3/7/2018, 6:09:35 PM and 3/7/2018, 6:48:48 PM neither of those events should have been received by the piston because the logs clearly shows those schedules had been canceled at 3/7/2018, 6:04:40 and 3/7/2018, 6:43:41 PM respectively.

i will leave you to dig through the code.

cheers.

jbrown · 2018-03-09 01:15:42 UTC

I am using lowes iris ones. I have about 8-9 of them on the windows on my first floor. My hub is in the same room as the fridge (great room layout), i used to have a lot of interference from my router when it was upstairs ext to hit, but now its over right on a shelf in the open about 20 feet from the fridge. I worked with the ST staff to refine my zigbee network, so I am pretty sure a repeater wouldn’t make much difference.

I wouldn’t say this happens a lot. Maybe once a week and I can’t really find any pattern to it when i do hear the sonos tell me.

I have had some random times when my basement door was telling me it was left open, but i think that was a sensor issue. The sensor would show as open (even tho it was closed). However, I use aeotec z-wave recessed contact sensors.

Is there any way to test the commands being sent? Like would leaving the live logging open on my server be a way of seeing if the sensor is not sending the command vs the piston not receiving from the hub?

I’m open to whatever…

jbrown · 2018-03-09 01:18:43 UTC

What does that home.time value represent?

bangali · 2018-03-09 01:26:29 UTC

sure if you keep ST live logging open on a server and full logging turned on for the piston then that would help triage the issue when it happens again.

jbrown · 2018-03-09 01:27:30 UTC

Not sure if this helps, but here is the log after the event. The next morning i opened it to get a 5 hour energy before work but that never showed in the log, it only shows the close event:

3/8/2018, 7:19:16 AM +671ms
+1ms ╔Received event [Refrigerator].contact = closed with a delay of 114ms
+159ms ║RunTime Analysis CS > 13ms > PS > 44ms > PE > 101ms > CE
+161ms ║Runtime (37836 bytes) successfully initialized in 44ms (v0.3.000.20180224) (159ms)
+162ms ║╔Execution stage started
+173ms ║║Comparison (enum) closed stays (string) open = false (2ms)
+175ms ║║Cancelling any timed trigger schedules for condition 5
+176ms ║║Cancelling statement #5’s schedules…
+177ms ║║Cancelling condition #5’s schedules…
+178ms ║║Condition #5 evaluated false (10ms)
+179ms ║║Cancelling condition #1’s schedules…
+180ms ║║Condition group #1 evaluated false (state changed) (11ms)
+182ms ║╚Execution stage complete. (20ms)
+183ms ╚Event processed successfully (183ms)
3/7/2018, 8:33:44 PM +381ms
+1ms ╔Received event [Home].time = 1520472825823 with a delay of -1443ms
+179ms ║RunTime Analysis CS > 24ms > PS > 66ms > PE > 89ms > CE
+182ms ║Runtime (37838 bytes) successfully initialized in 66ms (v0.3.000.20180224) (181ms)
+183ms ║╔Execution stage started
+192ms ║║Cancelling condition #5’s schedules…
+192ms ║║Condition #5 evaluated true (1ms)
+194ms ║║Cancelling condition #1’s schedules…
+195ms ║║Condition group #1 evaluated true (state changed) (4ms)
+197ms ║║Cancelling statement #2’s schedules…
+364ms ║║Executed physical command [SONOS].playTextAndResume([Refrigerator door has been left open, 50]) (158ms)
+365ms ║║Executed [SONOS].playTextAndResume (160ms)
+395ms ║║Executed virtual command [SONOS].sendNotificationToContacts (21ms)
+398ms ║╚Execution stage complete. (215ms)
+400ms ╚Event processed successfully (399ms)

When I look at the recent events for the fridge contact it does match what is in the log:

bangali · 2018-03-09 01:27:49 UTC

a schedule that was setup for a piston to execute.

bangali · 2018-03-09 01:33:05 UTC

if you go to the contact sensor device in the IDE and click on the list events link towards the bottom of the page do you see both the open and close event? heres a sample from my garage entry door as an example of the open/close events you should be seeing:

ipaterson · 2018-03-09 03:04:47 UTC

I use the Iris contact sensors inside the fridge and freezer as well but only for temperature. Contact was too unreliable but I just assumed it was my clumsy sensor setup.

I’ve noticed many contact sensors occasionally fire off invalid events. Had one wired to a relay on the smoke detectors that was throwing false positives about once a week until I swapped it with a different brand - even still a false positive (gets stuck in the contact state) about once every three months. Probably not related just feeling anecdotal.

I’ll see what I can find… the logs certainly seem contradictory.

jbrown · 2018-03-10 03:19:32 UTC

Wouldn’t i have to have the live logging on when the event happens? I can run it from my server until i have another false alarm. Or is there a way to pull historical events?

bangali · 2018-03-10 04:01:58 UTC

that is the historical events for the device. on mobile.

GeorgeCastanza · 2018-04-15 04:02:26 UTC

I seem to have written a piston that has 4 triggers, and obviously, its not working. Any help on how to go about fixing this. (I dont think conditions will work).

I have a variable @garageDoorShut that is set by another piston, but occasionally, the global variable is not set (zigbee issues), so I did this piston to make sure they stay in sync.

bangali · 2018-04-15 05:54:50 UTC

not sure of your exact requirement … is this what you are looking for?

GeorgeCastanza · 2018-05-22 22:37:43 UTC

Could someone explain what the lightning bolt represents. I was under the impression that it represented triggers, and if I had two triggers in an if statement, then the piston wouldnt fire. (And I’ve been telling this to others on this forum).

However, the help text says that it’s a condition that subscribes to events. Now I’m bamboozled. Does it show conditions or triggers, or both, or something, and is the presence of two lightning bolts in an if statement problematic? (if one doesn’t change the default subscribe method)

I first noticed it when I had some conditions with the lightning bolt, and thought it was an error.

GeorgeCastanza · 2018-05-22 22:43:34 UTC

Thanks for this. I was under the impression that “was” statements were past looking.

Reason for piston: i have a garage door sensor, and I like to be notified when it opens, but more importantly, shuts. My zigbee network is a little flakey and sometimes the zigbee message of the garage door doesnt get through, so I have created this piston to check the status of the garage door contact sensor and a global variable @gargeDoorShut. Another piston actually sets the status of the variable, this piston is only if the zigbee message doesnt get through, and so, if contact sensor and Glorbal variable are different, then I get notified, and the global variable is correctly set to represent the status of the door.