Door knock piston that doesn't think any movement is a door knock

WCmore · 2018-05-28 22:48:21 UTC

Thanks for that. I didn’t catch the 9.5 second semaphore delay last time around. That is definitely causing the issue. Can you make the first IF block async. (Only the block “IF door changes to open” should be async) This should hopefully give that block permission to make snappy responses where it is needed most.

leicam4 · 2018-05-29 17:18:03 UTC

I’ve made the updates, and it looks like now I’m getting double semaphore delays. One upon open and one open closing. I feel like this might be a limitation of SmartThings?

5/29/2018, 9:55:17 AM +777ms
+1ms	╔Received event [Front Screen Door].acceleration = inactive with a delay of 910ms
+160ms	║RunTime Analysis CS > 26ms > PS > 41ms > PE > 93ms > CE
+163ms	║Runtime (41966 bytes) successfully initialized in 41ms (v0.3.104.20180323) (160ms)
+164ms	║╔Execution stage started
+178ms	║║Condition #62 evaluated false (7ms)
+180ms	║║Condition group #29 evaluated false (state did not change) (10ms)
+387ms	║║Comparison (enum) inactive changes_to (string) active = false (1ms)
+389ms	║║Condition #89 evaluated false (205ms)
+390ms	║║Condition group #85 evaluated false (state did not change) (206ms)
+400ms	║║Comparison (dynamic) 0 is (integer) 1 = false (2ms)
+402ms	║║Condition #69 evaluated false (7ms)
+404ms	║║Condition group #65 evaluated false (state did not change) (9ms)
+416ms	║║Comparison (enum) closed is (string) closed = true (2ms)
+418ms	║║Condition #84 evaluated true (10ms)
+420ms	║║Condition group #70 evaluated true (state did not change) (13ms)
+423ms	║║Cancelling statement #81's schedules...
+431ms	║║Executed virtual command setVariable (3ms)
+438ms	║║Executed virtual command setVariable (3ms)
+447ms	║║Screen changed to close
+448ms	║║Executed virtual command log (1ms)
+452ms	║╚Execution stage complete. (289ms)
+454ms	╚Event processed successfully (453ms)
5/29/2018, 9:55:04 AM +744ms
+1ms	╔Received event [Front Screen Door].contact = closed with a delay of 778ms
+10153ms	║RunTime Analysis CS > 14ms > PS > 10058ms > PE > 81ms > CE
+10154ms	║Piston waited at a semaphore for 10024ms
+10156ms	║Runtime (42035 bytes) successfully initialized in 10058ms (v0.3.104.20180323) (10154ms)
+10157ms	║╔Execution stage started
+10166ms	║║Comparison (enum) closed changes_to (string) open = false (1ms)
+10167ms	║║Condition #62 evaluated false (4ms)
+10168ms	║║Condition group #29 evaluated false (state did not change) (6ms)
+10178ms	║║Cancelling condition #89's schedules...
+10179ms	║║Condition #89 evaluated false (8ms)
+10180ms	║║Cancelling condition #85's schedules...
+10181ms	║║Condition group #85 evaluated false (state changed) (10ms)
+10188ms	║║Comparison (dynamic) 0 is (integer) 1 = false (2ms)
+10189ms	║║Cancelling condition #69's schedules...
+10190ms	║║Condition #69 evaluated false (6ms)
+10191ms	║║Cancelling condition #65's schedules...
+10192ms	║║Condition group #65 evaluated false (state changed) (8ms)
+10200ms	║║Comparison (enum) closed is (string) closed = true (2ms)
+10201ms	║║Condition #84 evaluated true (6ms)
+10202ms	║║Condition group #70 evaluated true (state did not change) (7ms)
+10204ms	║║Cancelling statement #81's schedules...
+10211ms	║║Executed virtual command setVariable (3ms)
+10217ms	║║Executed virtual command setVariable (2ms)
+10224ms	║║Screen changed to close
+10225ms	║║Executed virtual command log (1ms)
+10228ms	║╚Execution stage complete. (71ms)
+10229ms	╚Event processed successfully (10229ms)
5/29/2018, 9:55:04 AM +727ms
+1ms	╔Received event [Front Screen Door].acceleration = active with a delay of 811ms
+136ms	║RunTime Analysis CS > 24ms > PS > 51ms > PE > 61ms > CE
+138ms	║Runtime (41969 bytes) successfully initialized in 51ms (v0.3.104.20180323) (136ms)
+140ms	║╔Execution stage started
+154ms	║║Condition #62 evaluated false (8ms)
+155ms	║║Condition group #29 evaluated false (state did not change) (9ms)
+161ms	║║Comparison (enum) active changes_to (string) active = true (1ms)
+163ms	║║Cancelling condition #89's schedules...
+164ms	║║Condition #89 evaluated true (5ms)
+165ms	║║Cancelling condition #85's schedules...
+165ms	║║Condition group #85 evaluated true (state changed) (8ms)
+168ms	║║Cancelling statement #86's schedules...
+171ms	║║Executed virtual command wait (0ms)
+172ms	║║Waiting for 1500ms
+1680ms	║║Executed virtual command setVariable (3ms)
+1687ms	║║Accel changed to Active
+1688ms	║║Executed virtual command log (1ms)
+1695ms	║║Comparison (dynamic) 1 is (integer) 1 = true (2ms)
+1697ms	║║Cancelling condition #69's schedules...
+1698ms	║║Condition #69 evaluated true (6ms)
+1702ms	║║Comparison (dynamic) 0 is (integer) 0 = true (1ms)
+1704ms	║║Condition #92 evaluated true (6ms)
+1705ms	║║Cancelling condition #65's schedules...
+1706ms	║║Condition group #65 evaluated true (state changed) (14ms)
+1708ms	║║Cancelling statement #66's schedules...
+1727ms	║║Executed virtual command sendSMSNotification (12ms)
+1734ms	║║Executed virtual command setVariable (4ms)
+1741ms	║║SMS sent
+1742ms	║║Executed virtual command log (1ms)
+1753ms	║║Comparison (enum) closed is (string) closed = true (1ms)
+1754ms	║║Cancelling condition #84's schedules...
+1755ms	║║Condition #84 evaluated true (9ms)
+1756ms	║║Cancelling condition #70's schedules...
+1757ms	║║Condition group #70 evaluated true (state changed) (12ms)
+1759ms	║║Cancelling statement #81's schedules...
+1766ms	║║Executed virtual command setVariable (3ms)
+1772ms	║║Executed virtual command setVariable (3ms)
+1779ms	║║Screen changed to close
+1780ms	║║Executed virtual command log (2ms)
+1783ms	║╚Execution stage complete. (1644ms)
+1784ms	╚Event processed successfully (1784ms)
5/29/2018, 9:55:02 AM +516ms
+1ms	╔Received event [Front Screen Door].acceleration = inactive with a delay of 784ms
+137ms	║RunTime Analysis CS > 24ms > PS > 56ms > PE > 57ms > CE
+139ms	║Runtime (41969 bytes) successfully initialized in 56ms (v0.3.104.20180323) (137ms)
+140ms	║╔Execution stage started
+154ms	║║Condition #62 evaluated false (8ms)
+155ms	║║Condition group #29 evaluated false (state did not change) (9ms)
+162ms	║║Comparison (enum) inactive changes_to (string) active = false (1ms)
+163ms	║║Condition #89 evaluated false (4ms)
+164ms	║║Condition group #85 evaluated false (state did not change) (6ms)
+171ms	║║Comparison (dynamic) 0 is (integer) 1 = false (2ms)
+173ms	║║Condition #69 evaluated false (5ms)
+174ms	║║Condition group #65 evaluated false (state did not change) (6ms)
+184ms	║║Comparison (enum) open is (string) closed = false (2ms)
+186ms	║║Condition #84 evaluated false (8ms)
+187ms	║║Condition group #70 evaluated false (state did not change) (10ms)
+189ms	║╚Execution stage complete. (49ms)
+190ms	╚Event processed successfully (190ms)
5/29/2018, 9:54:51 AM +181ms
+1ms	╔Received event [Front Screen Door].contact = open with a delay of 1045ms
+8739ms	║RunTime Analysis CS > 23ms > PS > 8632ms > PE > 85ms > CE
+8740ms	║Piston waited at a semaphore for 8585ms
+8743ms	║Runtime (42031 bytes) successfully initialized in 8632ms (v0.3.104.20180323) (8740ms)
+8744ms	║╔Execution stage started
+8754ms	║║Comparison (enum) open changes_to (string) open = false (1ms)
+8755ms	║║Condition #62 evaluated false (5ms)
+8756ms	║║Condition group #29 evaluated false (state did not change) (6ms)
+8768ms	║║Cancelling condition #89's schedules...
+8768ms	║║Condition #89 evaluated false (8ms)
+8770ms	║║Cancelling condition #85's schedules...
+8770ms	║║Condition group #85 evaluated false (state changed) (11ms)
+8777ms	║║Comparison (dynamic) 0 is (integer) 1 = false (1ms)
+8779ms	║║Cancelling condition #69's schedules...
+8780ms	║║Condition #69 evaluated false (7ms)
+8781ms	║║Cancelling condition #65's schedules...
+8782ms	║║Condition group #65 evaluated false (state changed) (9ms)
+8790ms	║║Comparison (enum) open is (string) closed = false (1ms)
+8791ms	║║Condition #84 evaluated false (6ms)
+8792ms	║║Condition group #70 evaluated false (state did not change) (8ms)
+8795ms	║╚Execution stage complete. (51ms)
+8796ms	╚Event processed successfully (8796ms)
5/29/2018, 9:54:49 AM +574ms
+2ms	╔Received event [Front Screen Door].acceleration = active with a delay of 772ms
+129ms	║RunTime Analysis CS > 24ms > PS > 50ms > PE > 56ms > CE
+132ms	║Runtime (41966 bytes) successfully initialized in 50ms (v0.3.104.20180323) (128ms)
+133ms	║╔Execution stage started
+146ms	║║Condition #62 evaluated false (6ms)
+147ms	║║Condition group #29 evaluated false (state did not change) (8ms)
+153ms	║║Comparison (enum) active changes_to (string) active = true (1ms)
+154ms	║║Cancelling condition #89's schedules...
+155ms	║║Condition #89 evaluated true (5ms)
+156ms	║║Cancelling condition #85's schedules...
+157ms	║║Condition group #85 evaluated true (state changed) (8ms)
+159ms	║║Cancelling statement #86's schedules...
+163ms	║║Executed virtual command wait (1ms)
+164ms	║║Waiting for 1500ms
+1670ms	║║Executed virtual command setVariable (3ms)
+1677ms	║║Accel changed to Active
+1678ms	║║Executed virtual command log (1ms)
+1686ms	║║Comparison (dynamic) 1 is (integer) 1 = true (2ms)
+1687ms	║║Cancelling condition #69's schedules...
+1688ms	║║Condition #69 evaluated true (6ms)
+1693ms	║║Comparison (dynamic) 0 is (integer) 0 = true (2ms)
+1694ms	║║Condition #92 evaluated true (5ms)
+1695ms	║║Cancelling condition #65's schedules...
+1696ms	║║Condition group #65 evaluated true (state changed) (15ms)
+1699ms	║║Cancelling statement #66's schedules...
+1719ms	║║Executed virtual command sendSMSNotification (13ms)
+1726ms	║║Executed virtual command setVariable (3ms)
+1733ms	║║SMS sent
+1733ms	║║Executed virtual command log (1ms)
+1744ms	║║Comparison (enum) open is (string) closed = false (2ms)
+1745ms	║║Cancelling condition #84's schedules...
+1746ms	║║Condition #84 evaluated false (9ms)
+1747ms	║║Cancelling condition #70's schedules...
+1748ms	║║Condition group #70 evaluated false (state changed) (11ms)
+1751ms	║╚Execution stage complete. (1619ms)
+1752ms	╚Event processed successfully (1752ms)

WCmore · 2018-05-30 00:07:36 UTC

Whew… This one has been frustrating. Thanks for your patience.

The last log (2 events) are listed here:

49.574 sec = Screen Acceleration is Active
49.737 sec = Begin 1500 ms Wait
51.181 sec = Screen contact opened
51.244 sec = Set variable ScreenActive = 1
51.292 sec = Sent SMS
59.766 sec = Screen contact open semaphore completed (ACTION CANCELLED)
62.516 sec = Screen Acceleration is Inactive

This one never even detected the door opening

04.727 sec = Screen Acceleration is Active
04.744 sec = Screen contact is closed
04.898 sec = Begin 1500 ms Wait
06.407 sec = Set variable ScreenActive
06.454 sec = SMS sent
06.482 sec = Door seen as closed, so all variables are reset
14.768 sec = Screen contact close semaphore completed
14.955 sec = Door seen as closed, so all variables are reset
17.777 sec = Screen Acceleration is Inactive
18.195 sec = Door seen as closed, so all variables are reset

I left out a bunch of chatter, but it really looks like there are too many things happening simultaneously. (indicated by the semaphore delay) The delay also breaks the logic.

I have a few ideas in my head. But let’s start with the easiest one: Here is what I did below:

I moved the 2nd block to the top
I made the only async block the one with the pause
I set TCP to Never for line 29

The async on this first block means the piston will continue on the other blocks the moment the Wait begins… and then come back to Set variable ScreenActive = 1 after the wait. This should get the variables the way you want in a timely fashion.

(I am tempted to change line 45 back to If contact CHANGES TO closed, but maybe test as is first)

leicam4 · 2018-05-31 00:29:40 UTC

I just tested the new piston and unfortunately, I’m still getting the ~9 second semaphore delays. I also tried with the last block switched to “changes to”. It does not change the variable to 0s because of the semaphore delay I’m guessing. This has definitely been very frustrating, but if anything I’ve learned a lot!

5/30/2018, 5:00:32 PM +23ms
+1ms	╔Received event [Front Screen Door].acceleration = active with a delay of 130ms
+86ms	║RunTime Analysis CS > 19ms > PS > 33ms > PE > 34ms > CE
+89ms	║Runtime (41948 bytes) successfully initialized in 33ms (v0.3.104.20180323) (87ms)
+90ms	║╔Execution stage started
+99ms	║║Comparison (enum) active changes_to (string) active = true (1ms)
+100ms	║║Cancelling condition #89's schedules...
+101ms	║║Condition #89 evaluated true (6ms)
+102ms	║║Cancelling condition #85's schedules...
+103ms	║║Condition group #85 evaluated true (state changed) (8ms)
+105ms	║║Cancelling statement #86's schedules...
+108ms	║║Executed virtual command wait (1ms)
+109ms	║║Requesting a wake up for Wed, May 30 2018 @ 5:00:33 PM PDT (in 1.5s)
+121ms	║║Condition #62 evaluated false (6ms)
+122ms	║║Condition group #29 evaluated false (state did not change) (7ms)
+128ms	║║Comparison (dynamic) 1 is (integer) 1 = true (1ms)
+129ms	║║Condition #69 evaluated true (5ms)
+133ms	║║Comparison (dynamic) 1 is (integer) 0 = false (2ms)
+134ms	║║Condition #92 evaluated false (5ms)
+135ms	║║Condition group #65 evaluated false (state did not change) (11ms)
+143ms	║║Condition #84 evaluated false (5ms)
+144ms	║║Condition group #70 evaluated false (state did not change) (7ms)
+147ms	║║Fast executing schedules, waiting for 1464ms to sync up
+1626ms	║║Executed virtual command setVariable (3ms)
+1633ms	║║Accel changed to Active
+1634ms	║║Executed virtual command log (1ms)
+1636ms	║╚Execution stage complete. (1546ms)
+1637ms	╚Event processed successfully (1637ms)
5/30/2018, 5:00:29 PM +749ms
+1ms	╔Received event [Front Screen Door].acceleration = inactive with a delay of 410ms
+78ms	║RunTime Analysis CS > 13ms > PS > 33ms > PE > 32ms > CE
+80ms	║Runtime (41948 bytes) successfully initialized in 33ms (v0.3.104.20180323) (78ms)
+81ms	║╔Execution stage started
+90ms	║║Comparison (enum) inactive changes_to (string) active = false (1ms)
+91ms	║║Condition #89 evaluated false (4ms)
+92ms	║║Condition group #85 evaluated false (state did not change) (6ms)
+101ms	║║Condition #62 evaluated false (6ms)
+113ms	║║Condition group #29 evaluated false (state did not change) (17ms)
+119ms	║║Comparison (dynamic) 1 is (integer) 1 = true (2ms)
+120ms	║║Condition #69 evaluated true (5ms)
+124ms	║║Comparison (dynamic) 1 is (integer) 0 = false (1ms)
+126ms	║║Condition #92 evaluated false (4ms)
+126ms	║║Condition group #65 evaluated false (state did not change) (11ms)
+135ms	║║Condition #84 evaluated false (6ms)
+136ms	║║Condition group #70 evaluated false (state did not change) (7ms)
+138ms	║╚Execution stage complete. (57ms)
+139ms	╚Event processed successfully (139ms)
5/30/2018, 5:00:16 PM +764ms
+2ms	╔Received event [Front Screen Door].contact = closed with a delay of 263ms
+10184ms	║RunTime Analysis CS > 28ms > PS > 10120ms > PE > 36ms > CE
+10185ms	║Piston waited at a semaphore for 10073ms
+10188ms	║Runtime (42021 bytes) successfully initialized in 10120ms (v0.3.104.20180323) (10184ms)
+10188ms	║╔Execution stage started
+10201ms	║║Cancelling condition #89's schedules...
+10202ms	║║Condition #89 evaluated false (8ms)
+10203ms	║║Cancelling condition #85's schedules...
+10204ms	║║Condition group #85 evaluated false (state changed) (11ms)
+10210ms	║║Comparison (enum) closed changes_to (string) open = false (0ms)
+10211ms	║║Condition #62 evaluated false (4ms)
+10212ms	║║Condition group #29 evaluated false (state did not change) (5ms)
+10218ms	║║Comparison (dynamic) 1 is (integer) 1 = true (1ms)
+10219ms	║║Cancelling condition #69's schedules...
+10220ms	║║Condition #69 evaluated true (6ms)
+10224ms	║║Comparison (dynamic) 1 is (integer) 0 = false (2ms)
+10225ms	║║Condition #92 evaluated false (5ms)
+10226ms	║║Condition group #65 evaluated false (state did not change) (12ms)
+10232ms	║║Comparison (enum) closed changes_to (string) closed = false (1ms)
+10234ms	║║Condition #84 evaluated false (4ms)
+10235ms	║║Condition group #70 evaluated false (state did not change) (7ms)
+10237ms	║╚Execution stage complete. (49ms)
+10238ms	╚Event processed successfully (10238ms)
5/30/2018, 5:00:16 PM +639ms
+1ms	╔Received event [Front Screen Door].acceleration = active with a delay of 244ms
+73ms	║RunTime Analysis CS > 12ms > PS > 34ms > PE > 26ms > CE
+75ms	║Runtime (41948 bytes) successfully initialized in 34ms (v0.3.104.20180323) (74ms)
+76ms	║╔Execution stage started
+87ms	║║Comparison (enum) active changes_to (string) active = true (1ms)
+88ms	║║Cancelling condition #89's schedules...
+89ms	║║Condition #89 evaluated true (7ms)
+90ms	║║Cancelling condition #85's schedules...
+91ms	║║Condition group #85 evaluated true (state changed) (9ms)
+93ms	║║Cancelling statement #86's schedules...
+99ms	║║Executed virtual command wait (1ms)
+100ms	║║Requesting a wake up for Wed, May 30 2018 @ 5:00:18 PM PDT (in 1.5s)
+113ms	║║Condition #62 evaluated false (8ms)
+114ms	║║Condition group #29 evaluated false (state did not change) (10ms)
+120ms	║║Comparison (dynamic) 0 is (integer) 1 = false (1ms)
+121ms	║║Condition #69 evaluated false (4ms)
+123ms	║║Condition group #65 evaluated false (state did not change) (6ms)
+132ms	║║Condition #84 evaluated false (5ms)
+132ms	║║Condition group #70 evaluated false (state did not change) (7ms)
+135ms	║║Fast executing schedules, waiting for 1465ms to sync up
+1614ms	║║Executed virtual command setVariable (3ms)
+1620ms	║║Accel changed to Active
+1621ms	║║Executed virtual command log (0ms)
+1623ms	║╚Execution stage complete. (1547ms)
+1624ms	╚Event processed successfully (1624ms)
5/30/2018, 5:00:12 PM +683ms
+1ms	╔Received event [Front Screen Door].acceleration = inactive with a delay of 323ms
+77ms	║RunTime Analysis CS > 13ms > PS > 34ms > PE > 29ms > CE
+79ms	║Runtime (41945 bytes) successfully initialized in 34ms (v0.3.104.20180323) (77ms)
+80ms	║╔Execution stage started
+89ms	║║Comparison (enum) inactive changes_to (string) active = false (0ms)
+91ms	║║Condition #89 evaluated false (5ms)
+92ms	║║Condition group #85 evaluated false (state did not change) (6ms)
+101ms	║║Cancelling condition #62's schedules...
+102ms	║║Condition #62 evaluated false (7ms)
+103ms	║║Cancelling condition #29's schedules...
+104ms	║║Condition group #29 evaluated false (state changed) (10ms)
+110ms	║║Comparison (dynamic) 0 is (integer) 1 = false (1ms)
+112ms	║║Cancelling condition #69's schedules...
+113ms	║║Condition #69 evaluated false (5ms)
+113ms	║║Condition group #65 evaluated false (state did not change) (7ms)
+123ms	║║Condition #84 evaluated false (6ms)
+124ms	║║Condition group #70 evaluated false (state did not change) (7ms)
+126ms	║╚Execution stage complete. (46ms)
+127ms	╚Event processed successfully (127ms)
5/30/2018, 5:00:00 PM +904ms
+1ms	╔Received event [Front Screen Door].contact = open with a delay of 400ms
+8981ms	║RunTime Analysis CS > 37ms > PS > 8913ms > PE > 32ms > CE
+8982ms	║Piston waited at a semaphore for 8851ms
+8984ms	║Runtime (42013 bytes) successfully initialized in 8913ms (v0.3.104.20180323) (8982ms)
+8985ms	║╔Execution stage started
+8999ms	║║Cancelling condition #89's schedules...
+8999ms	║║Condition #89 evaluated false (8ms)
+9000ms	║║Cancelling condition #85's schedules...
+9001ms	║║Condition group #85 evaluated false (state changed) (11ms)
+9007ms	║║Comparison (enum) open changes_to (string) open = true (1ms)
+9008ms	║║Cancelling condition #62's schedules...
+9009ms	║║Condition #62 evaluated true (5ms)
+9010ms	║║Cancelling condition #29's schedules...
+9011ms	║║Condition group #29 evaluated true (state changed) (7ms)
+9013ms	║║Cancelling statement #63's schedules...
+9019ms	║║Executed virtual command setVariable (3ms)
+9026ms	║║Screen changed to Open
+9026ms	║║Executed virtual command log (1ms)
+9033ms	║║Comparison (dynamic) 1 is (integer) 1 = true (1ms)
+9035ms	║║Cancelling condition #69's schedules...
+9035ms	║║Condition #69 evaluated true (6ms)
+9040ms	║║Comparison (dynamic) 1 is (integer) 0 = false (1ms)
+9041ms	║║Cancelling condition #92's schedules...
+9042ms	║║Condition #92 evaluated false (6ms)
+9043ms	║║Condition group #65 evaluated false (state did not change) (13ms)
+9049ms	║║Comparison (enum) open changes_to (string) closed = false (0ms)
+9050ms	║║Condition #84 evaluated false (5ms)
+9051ms	║║Condition group #70 evaluated false (state did not change) (6ms)
+9053ms	║╚Execution stage complete. (68ms)
+9054ms	╚Event processed successfully (9054ms)
5/30/2018, 4:59:59 PM +670ms
+1ms	╔Received event [Front Screen Door].acceleration = active with a delay of 256ms
+101ms	║RunTime Analysis CS > 22ms > PS > 50ms > PE > 29ms > CE
+104ms	║Runtime (41947 bytes) successfully initialized in 50ms (v0.3.104.20180323) (102ms)
+105ms	║╔Execution stage started
+115ms	║║Comparison (enum) active changes_to (string) active = true (0ms)
+116ms	║║Cancelling condition #89's schedules...
+117ms	║║Condition #89 evaluated true (6ms)
+118ms	║║Cancelling condition #85's schedules...
+119ms	║║Condition group #85 evaluated true (state changed) (7ms)
+121ms	║║Cancelling statement #86's schedules...
+126ms	║║Executed virtual command wait (0ms)
+128ms	║║Requesting a wake up for Wed, May 30 2018 @ 5:00:01 PM PDT (in 1.5s)
+140ms	║║Condition #62 evaluated false (6ms)
+140ms	║║Condition group #29 evaluated false (state did not change) (8ms)
+147ms	║║Comparison (dynamic) 0 is (integer) 1 = false (1ms)
+149ms	║║Condition #69 evaluated false (6ms)
+150ms	║║Condition group #65 evaluated false (state did not change) (6ms)
+159ms	║║Condition #84 evaluated false (6ms)
+160ms	║║Condition group #70 evaluated false (state did not change) (7ms)
+163ms	║║Fast executing schedules, waiting for 1466ms to sync up
+1645ms	║║Executed virtual command setVariable (3ms)
+1652ms	║║Accel changed to Active
+1653ms	║║Executed virtual command log (1ms)
+1656ms	║╚Execution stage complete. (1552ms)
+1658ms	╚Event processed successfully (1657ms)

WCmore · 2018-05-31 19:35:44 UTC

That semaphore is going to be the death of me, LOL

The good news is, you did NOT get the unwanted SMS message!!
(Personally, I never worry about the semaphore unless I have errors)

Here is the latest analysis of your most recent log:

59.670 sec = Screen Acceleration is Active
59.798 sec = Requesting a wake up in 1.5 secs
61.315 sec = Set variable ScreenActive = 1

60.904 sec = Screen contact opened
69.886 sec = Screen contact opened semaphore complete
69.923 sec = Set variable ScreenOpen = 1

72.683 sec = Screen Acceleration is Inactive

The screen opened within the 1500ms time range (barely), but the semaphore forced a delay that we do not want. Also, for some reason, the door never registered as close, so the variables did not reset for the next test.

76.639 sec = Screen Acceleration is Active
76.739 sec = Requesting a wake up in 1.5 secs
78.253 sec = Set variable ScreenActive = 1

76.764 sec = Screen contact closed
86.949 sec = Screen contact closed semaphore complete
86.949 sec = Screen contact closed variables did NOT reset

89.749 sec = Screen Acceleration is Inactive

92.023 sec = Screen Acceleration is Active
92.132 sec = Requesting a wake up in 1.5 secs
93.649 sec = Set variable ScreenActive = 1

I am not sure if this is a second test, or just part two of the same test…
(Maybe you just held the screen open for 17 seconds, and then let it close.)

Also, I went back thru the last two days of your logs, and not once did I find where the Screen door closing reset your variables.
Condition group #70 evaluated false (state did not change)
This will affect any future tests.

Sooo, long story short, I loaded your latest piston, and made a few tiny adjustments to it:

Contact sensors are now looking for IS open or close
Forced subscription to those two cases and never cancel
I moved the Async to the WITH statement, instead of the IF

I hope this will do what you need. If not, I may have to break up your piston into two pistons to get around the semaphore issue.

One small request I have though. For future testing, can you make sure that the variables are both at 0 (or blank) prior to running the test. (If a previous test failed, the numbers may start off wrong, and that would affect the current test) You do not have to do this on a brand new piston because no numbers have been set yet. Only on subsequent testing until we are sure the door closing did a successful reset of both variables to 0.

Thanks

leicam4 · 2018-06-02 22:13:56 UTC

Just tested the new piston. I’m still getting a semaphore delay. It seemed like it was working at first. That is, when I moved the screen door then opened. I did not receive the notification. Even after the acceleration went back to inactive state… but then right when I knocked on the screen door, I got the notification.

Maybe it’s just asking too much of webcore?

6/2/2018, 2:15:15 PM +263ms
+1ms	╔Received event [Front Screen Door].acceleration = inactive with a delay of 706ms
+118ms	║RunTime Analysis CS > 18ms > PS > 48ms > PE > 53ms > CE
+121ms	║Runtime (41940 bytes) successfully initialized in 48ms (v0.3.104.20180323) (119ms)
+122ms	║╔Execution stage started
+132ms	║║Comparison (enum) inactive changes_to (string) active = false (1ms)
+134ms	║║Cancelling condition #89's schedules...
+134ms	║║Condition #89 evaluated false (6ms)
+135ms	║║Cancelling condition #85's schedules...
+136ms	║║Condition group #85 evaluated false (state changed) (8ms)
+147ms	║║Comparison (enum) closed is (string) open = false (2ms)
+148ms	║║Condition #62 evaluated false (9ms)
+149ms	║║Condition group #29 evaluated false (state did not change) (10ms)
+156ms	║║Comparison (dynamic) 1 is (integer) 1 = true (1ms)
+158ms	║║Cancelling condition #69's schedules...
+159ms	║║Condition #69 evaluated true (7ms)
+163ms	║║Comparison (dynamic) 0 is (integer) 0 = true (1ms)
+165ms	║║Condition #92 evaluated true (6ms)
+166ms	║║Cancelling condition #65's schedules...
+167ms	║║Condition group #65 evaluated true (state changed) (15ms)
+169ms	║║Cancelling statement #66's schedules...
+187ms	║║Executed virtual command sendSMSNotification (12ms)
+193ms	║║Executed virtual command setVariable (3ms)
+200ms	║║SMS sent
+201ms	║║Executed virtual command log (1ms)
+212ms	║║Comparison (enum) closed is (string) closed = true (1ms)
+214ms	║║Condition #84 evaluated true (9ms)
+215ms	║║Condition group #70 evaluated true (state did not change) (11ms)
+217ms	║║Cancelling statement #81's schedules...
+223ms	║║Executed virtual command setVariable (3ms)
+229ms	║║Executed virtual command setVariable (3ms)
+236ms	║║Screen is closed - Variables reset
+237ms	║║Executed virtual command log (1ms)
+240ms	║╚Execution stage complete. (118ms)
+241ms	╚Event processed successfully (241ms)
6/2/2018, 2:15:02 PM +305ms
+1ms	╔Received event [Front Screen Door].acceleration = active with a delay of 709ms
+126ms	║RunTime Analysis CS > 26ms > PS > 53ms > PE > 47ms > CE
+129ms	║Runtime (41942 bytes) successfully initialized in 53ms (v0.3.104.20180323) (127ms)
+130ms	║╔Execution stage started
+141ms	║║Comparison (enum) active changes_to (string) active = true (0ms)
+142ms	║║Cancelling condition #89's schedules...
+143ms	║║Condition #89 evaluated true (7ms)
+144ms	║║Cancelling condition #85's schedules...
+145ms	║║Condition group #85 evaluated true (state changed) (9ms)
+148ms	║║Cancelling statement #86's schedules...
+152ms	║║Executed virtual command wait (1ms)
+153ms	║║Requesting a wake up for Sat, Jun 2 2018 @ 2:15:03 PM PDT (in 1.5s)
+168ms	║║Comparison (enum) closed is (string) open = false (2ms)
+170ms	║║Condition #62 evaluated false (10ms)
+171ms	║║Condition group #29 evaluated false (state did not change) (12ms)
+178ms	║║Comparison (dynamic) 0 is (integer) 1 = false (2ms)
+180ms	║║Condition #69 evaluated false (6ms)
+181ms	║║Condition group #65 evaluated false (state did not change) (8ms)
+192ms	║║Comparison (enum) closed is (string) closed = true (2ms)
+193ms	║║Condition #84 evaluated true (9ms)
+194ms	║║Condition group #70 evaluated true (state did not change) (10ms)
+197ms	║║Cancelling statement #81's schedules...
+204ms	║║Executed virtual command setVariable (3ms)
+210ms	║║Executed virtual command setVariable (3ms)
+218ms	║║Screen is closed - Variables reset
+219ms	║║Executed virtual command log (2ms)
+223ms	║║Fast executing schedules, waiting for 1432ms to sync up
+1676ms	║║Executed virtual command setVariable (3ms)
+1684ms	║║Accel changed to Active
+1685ms	║║Executed virtual command log (1ms)
+1689ms	║╚Execution stage complete. (1559ms)
+1690ms	╚Event processed successfully (1690ms)
6/2/2018, 2:15:00 PM +240ms
+1ms	╔Received event [Front Screen Door].acceleration = inactive with a delay of 740ms
+93ms	║RunTime Analysis CS > 19ms > PS > 34ms > PE > 40ms > CE
+95ms	║Runtime (41939 bytes) successfully initialized in 34ms (v0.3.104.20180323) (94ms)
+96ms	║╔Execution stage started
+106ms	║║Comparison (enum) inactive changes_to (string) active = false (1ms)
+107ms	║║Condition #89 evaluated false (5ms)
+108ms	║║Condition group #85 evaluated false (state did not change) (6ms)
+118ms	║║Comparison (enum) closed is (string) open = false (1ms)
+120ms	║║Condition #62 evaluated false (9ms)
+121ms	║║Condition group #29 evaluated false (state did not change) (10ms)
+127ms	║║Comparison (dynamic) 0 is (integer) 1 = false (1ms)
+129ms	║║Cancelling condition #69's schedules...
+130ms	║║Condition #69 evaluated false (5ms)
+131ms	║║Cancelling condition #65's schedules...
+131ms	║║Condition group #65 evaluated false (state changed) (8ms)
+141ms	║║Comparison (enum) closed is (string) closed = true (1ms)
+143ms	║║Condition #84 evaluated true (9ms)
+144ms	║║Condition group #70 evaluated true (state did not change) (10ms)
+146ms	║║Cancelling statement #81's schedules...
+153ms	║║Executed virtual command setVariable (3ms)
+158ms	║║Executed virtual command setVariable (3ms)
+165ms	║║Screen is closed - Variables reset
+166ms	║║Executed virtual command log (1ms)
+168ms	║╚Execution stage complete. (72ms)
+170ms	╚Event processed successfully (169ms)
6/2/2018, 2:14:47 PM +318ms
+2ms	╔Received event [Front Screen Door].contact = closed with a delay of 717ms
+10165ms	║RunTime Analysis CS > 28ms > PS > 10095ms > PE > 41ms > CE
+10166ms	║Piston waited at a semaphore for 10046ms
+10168ms	║Runtime (42014 bytes) successfully initialized in 10095ms (v0.3.104.20180323) (10165ms)
+10169ms	║╔Execution stage started
+10183ms	║║Cancelling condition #89's schedules...
+10184ms	║║Condition #89 evaluated false (9ms)
+10185ms	║║Cancelling condition #85's schedules...
+10186ms	║║Condition group #85 evaluated false (state changed) (11ms)
+10193ms	║║Comparison (enum) closed is (string) open = false (1ms)
+10195ms	║║Condition #62 evaluated false (6ms)
+10196ms	║║Condition group #29 evaluated false (state did not change) (7ms)
+10203ms	║║Comparison (dynamic) 1 is (integer) 1 = true (2ms)
+10204ms	║║Cancelling condition #69's schedules...
+10205ms	║║Condition #69 evaluated true (6ms)
+10210ms	║║Comparison (dynamic) 0 is (integer) 0 = true (2ms)
+10211ms	║║Cancelling condition #92's schedules...
+10212ms	║║Condition #92 evaluated true (6ms)
+10213ms	║║Cancelling condition #65's schedules...
+10214ms	║║Condition group #65 evaluated true (state changed) (16ms)
+10217ms	║║Cancelling statement #66's schedules...
+10235ms	║║Executed virtual command sendSMSNotification (12ms)
+10242ms	║║Executed virtual command setVariable (4ms)
+10249ms	║║SMS sent
+10250ms	║║Executed virtual command log (2ms)
+10258ms	║║Comparison (enum) closed is (string) closed = true (2ms)
+10260ms	║║Condition #84 evaluated true (6ms)
+10261ms	║║Condition group #70 evaluated true (state did not change) (7ms)
+10263ms	║║Cancelling statement #81's schedules...
+10269ms	║║Executed virtual command setVariable (3ms)
+10275ms	║║Executed virtual command setVariable (3ms)
+10282ms	║║Screen is closed - Variables reset
+10283ms	║║Executed virtual command log (1ms)
+10286ms	║╚Execution stage complete. (117ms)
+10287ms	╚Event processed successfully (10287ms)
6/2/2018, 2:14:47 PM +238ms
+2ms	╔Received event [Front Screen Door].acceleration = active with a delay of 696ms
+106ms	║RunTime Analysis CS > 17ms > PS > 51ms > PE > 37ms > CE
+108ms	║Runtime (41944 bytes) successfully initialized in 51ms (v0.3.104.20180323) (105ms)
+110ms	║╔Execution stage started
+120ms	║║Comparison (enum) active changes_to (string) active = true (1ms)
+121ms	║║Cancelling condition #89's schedules...
+122ms	║║Condition #89 evaluated true (6ms)
+123ms	║║Cancelling condition #85's schedules...
+124ms	║║Condition group #85 evaluated true (state changed) (9ms)
+127ms	║║Cancelling statement #86's schedules...
+131ms	║║Executed virtual command wait (0ms)
+132ms	║║Requesting a wake up for Sat, Jun 2 2018 @ 2:14:48 PM PDT (in 1.5s)
+146ms	║║Comparison (enum) closed is (string) open = false (2ms)
+148ms	║║Cancelling condition #62's schedules...
+148ms	║║Condition #62 evaluated false (11ms)
+150ms	║║Cancelling condition #29's schedules...
+150ms	║║Condition group #29 evaluated false (state changed) (13ms)
+158ms	║║Comparison (dynamic) 0 is (integer) 1 = false (2ms)
+159ms	║║Condition #69 evaluated false (5ms)
+160ms	║║Condition group #65 evaluated false (state did not change) (7ms)
+170ms	║║Comparison (enum) closed is (string) closed = true (2ms)
+172ms	║║Cancelling condition #84's schedules...
+173ms	║║Condition #84 evaluated true (9ms)
+174ms	║║Cancelling condition #70's schedules...
+175ms	║║Condition group #70 evaluated true (state changed) (12ms)
+177ms	║║Cancelling statement #81's schedules...
+186ms	║║Executed virtual command setVariable (6ms)
+193ms	║║Executed virtual command setVariable (3ms)
+200ms	║║Screen is closed - Variables reset
+201ms	║║Executed virtual command log (1ms)
+205ms	║║Fast executing schedules, waiting for 1427ms to sync up
+1648ms	║║Executed virtual command setVariable (3ms)
+1656ms	║║Accel changed to Active
+1657ms	║║Executed virtual command log (1ms)
+1659ms	║╚Execution stage complete. (1550ms)
+1661ms	╚Event processed successfully (1661ms)
6/2/2018, 2:14:43 PM +237ms
+2ms	╔Received event [Front Screen Door].acceleration = inactive with a delay of 703ms
+106ms	║RunTime Analysis CS > 24ms > PS > 50ms > PE > 32ms > CE
+109ms	║Runtime (41943 bytes) successfully initialized in 50ms (v0.3.104.20180323) (107ms)
+110ms	║╔Execution stage started
+119ms	║║Comparison (enum) inactive changes_to (string) active = false (0ms)
+121ms	║║Condition #89 evaluated false (5ms)
+122ms	║║Condition group #85 evaluated false (state did not change) (7ms)
+133ms	║║Comparison (enum) open is (string) open = true (2ms)
+134ms	║║Condition #62 evaluated true (9ms)
+135ms	║║Condition group #29 evaluated true (state did not change) (11ms)
+138ms	║║Cancelling statement #63's schedules...
+145ms	║║Executed virtual command setVariable (3ms)
+151ms	║║Screen is Open
+152ms	║║Executed virtual command log (1ms)
+159ms	║║Comparison (dynamic) 0 is (integer) 1 = false (1ms)
+161ms	║║Cancelling condition #69's schedules...
+162ms	║║Condition #69 evaluated false (6ms)
+163ms	║║Condition group #65 evaluated false (state did not change) (8ms)
+173ms	║║Comparison (enum) open is (string) closed = false (1ms)
+174ms	║║Condition #84 evaluated false (8ms)
+175ms	║║Condition group #70 evaluated false (state did not change) (10ms)
+177ms	║╚Execution stage complete. (68ms)
+178ms	╚Event processed successfully (178ms)
6/2/2018, 2:14:31 PM +874ms
+2ms	╔Received event [Front Screen Door].contact = open with a delay of 1013ms
+8747ms	║RunTime Analysis CS > 18ms > PS > 8697ms > PE > 32ms > CE
+8748ms	║Piston waited at a semaphore for 8641ms
+8751ms	║Runtime (42010 bytes) successfully initialized in 8697ms (v0.3.104.20180323) (8748ms)
+8752ms	║╔Execution stage started
+8766ms	║║Cancelling condition #89's schedules...
+8767ms	║║Condition #89 evaluated false (9ms)
+8768ms	║║Cancelling condition #85's schedules...
+8769ms	║║Condition group #85 evaluated false (state changed) (11ms)
+8777ms	║║Comparison (enum) open is (string) open = true (2ms)
+8779ms	║║Cancelling condition #62's schedules...
+8780ms	║║Condition #62 evaluated true (7ms)
+8781ms	║║Cancelling condition #29's schedules...
+8782ms	║║Condition group #29 evaluated true (state changed) (9ms)
+8784ms	║║Cancelling statement #63's schedules...
+8791ms	║║Executed virtual command setVariable (2ms)
+8798ms	║║Screen is Open
+8799ms	║║Executed virtual command log (1ms)
+8808ms	║║Comparison (dynamic) 1 is (integer) 1 = true (1ms)
+8809ms	║║Cancelling condition #69's schedules...
+8810ms	║║Condition #69 evaluated true (7ms)
+8815ms	║║Comparison (dynamic) 1 is (integer) 0 = false (2ms)
+8817ms	║║Condition #92 evaluated false (5ms)
+8818ms	║║Condition group #65 evaluated false (state did not change) (14ms)
+8826ms	║║Comparison (enum) open is (string) closed = false (2ms)
+8828ms	║║Cancelling condition #84's schedules...
+8829ms	║║Condition #84 evaluated false (7ms)
+8830ms	║║Cancelling condition #70's schedules...
+8831ms	║║Condition group #70 evaluated false (state changed) (10ms)
+8833ms	║╚Execution stage complete. (82ms)
+8835ms	╚Event processed successfully (8835ms)
6/2/2018, 2:14:30 PM +266ms
+1ms	╔Received event [Front Screen Door].acceleration = active with a delay of 684ms
+85ms	║RunTime Analysis CS > 18ms > PS > 42ms > PE > 25ms > CE
+89ms	║Runtime (41947 bytes) successfully initialized in 42ms (v0.3.104.20180323) (86ms)
+90ms	║╔Execution stage started
+100ms	║║Comparison (enum) active changes_to (string) active = true (1ms)
+102ms	║║Cancelling condition #89's schedules...
+103ms	║║Condition #89 evaluated true (7ms)
+104ms	║║Cancelling condition #85's schedules...
+105ms	║║Condition group #85 evaluated true (state changed) (9ms)
+107ms	║║Cancelling statement #86's schedules...
+111ms	║║Executed virtual command wait (1ms)
+112ms	║║Requesting a wake up for Sat, Jun 2 2018 @ 2:14:31 PM PDT (in 1.5s)
+126ms	║║Comparison (enum) closed is (string) open = false (1ms)
+127ms	║║Condition #62 evaluated false (10ms)
+128ms	║║Condition group #29 evaluated false (state did not change) (11ms)
+135ms	║║Comparison (dynamic) 0 is (integer) 1 = false (2ms)
+136ms	║║Condition #69 evaluated false (5ms)
+137ms	║║Condition group #65 evaluated false (state did not change) (6ms)
+147ms	║║Comparison (enum) closed is (string) closed = true (2ms)
+149ms	║║Condition #84 evaluated true (8ms)
+150ms	║║Condition group #70 evaluated true (state did not change) (9ms)
+152ms	║║Cancelling statement #81's schedules...
+158ms	║║Executed virtual command setVariable (3ms)
+163ms	║║Executed virtual command setVariable (2ms)
+170ms	║║Screen is closed - Variables reset
+171ms	║║Executed virtual command log (1ms)
+174ms	║║Fast executing schedules, waiting for 1438ms to sync up
+1628ms	║║Executed virtual command setVariable (3ms)
+1635ms	║║Accel changed to Active
+1636ms	║║Executed virtual command log (1ms)
+1639ms	║╚Execution stage complete. (1549ms)
+1640ms	╚Event processed successfully (1639ms)
6/2/2018, 2:13:53 PM +773ms
+168ms	║Screen is closed - Variables reset

WCmore · 2018-06-03 05:43:42 UTC

Wasn’t this our goal all along?!? I mean, I can honestly say that I never look at semaphore delays if the piston is doing what I want…

leicam4 · 2018-06-04 13:51:21 UTC

Oops. I meant to say that the notification received was a delayed response from the first acceleration active immediately followed by screen door open. It coincidentally sent this first notification right after the second acceleration active only. The second notification was sent a little after for the second acceleration active only.

I have never really looked in depth into any of the logs until after trying to set up these pistons for the screen door. For all I know, I have semaphore delays in all my other pistons, but I never really checked because they all seem to work ok…more or less. There are some hiccups here and there.

This entire exercise, though, has been so helpful to me anyway when I try to create future pistons or revisit older pistons.

WCmore · 2018-06-05 03:12:22 UTC

I appreciate your positive outlook, even though so far, I feel like I have let you down…

I do not have an extra sensor to test this specifically, but I have created two tiny pistons, and all of my simulations have been 100% successful.

I am kind of disappointed we could not get this to work in one piston, but hopefully these work for you. To test, you will first need to make an integer global variable called @screenActive. The beauty is the second piston will check each time the screen goes active or inactive… but only sends the SMS when the screen is active and closed (in 100% of my testing)

The 6 log commands I inserted are handy to keep during your testing, but they aren’t needed once you are happy with it.

Also, don’t forget to pause any other pistons that may be monitoring the screen door, so as to not cause a conflict. (or needless semaphore delay)

(You will need to import both of these pistons to test)