Actions after "wait" timer do not run. (Detecting presence)

presence
notification

#1

Hi everyone, I am trying to convert a flow from Stringify that I use as my “alarm system” and have had nothing but troubles with WebCoRE so I’m hoping someone can help me figure this out.

Basically, if my front door opens and someone comes in it waits 30 seconds to see if my SmartThings Arrival sensor is present (I give it a buffer as it doesn’t instantly connect sometimes) and if it isn’t, it gives me a push notification. (To prevent false alarms for when I leave, I have an motion sensor at the front door, so if there is motion inside when the door opens, it knows I’m leaving and to not continue further)
IMG_8031

I have spent a week now trying to rebuild variations of this in WebCoRE and never can get it to work, even when I have simplified it and added extra debug messages.

Piston:

What happens: I open the door, and it gives me the push notification #9 and that’s it.

What should happen: after 30 seconds, it should check the state of the presence sensor and give me a notification #17 or #15 but I get neither. (In the future I’d add other things like flashing lights, alarms sounds, etc :slight_smile:)

Looking at the logs, it appears the “Wait 30 seconds” works, but after those 30 seconds are up, it just ends and does not do anything.

Full Log:

5/7/2019, 9:07:23 PM +199ms
+1ms ╔Received event [Home].time = 1557277644790 with a delay of -1592ms
+124ms ║RunTime Analysis CS > 23ms > PS > 81ms > PE > 20ms > CE
+128ms ║Runtime (40540 bytes) successfully initialized in 81ms (v0.3.10a.20190223) (126ms)
+130ms ║╔Execution stage started
+132ms ║╚Execution stage complete. (2ms)
+135ms ╚Event processed successfully (134ms)

5/7/2019, 9:06:58 PM +157ms
+2ms ╔Received event [Front Door Contact].contact = closed with a delay of 790ms
+143ms ║RunTime Analysis CS > 25ms > PS > 99ms > PE > 18ms > CE
+146ms ║Runtime (40541 bytes) successfully initialized in 99ms (v0.3.10a.20190223) (142ms)
+147ms ║╔Execution stage started
+157ms ║║Comparison (enum) closed changes_to (string) open = false (1ms)
+159ms ║║Cancelling condition #2's schedules...
+160ms ║║Condition #2 evaluated false (7ms)
+162ms ║║Cancelling condition #1's schedules...
+163ms ║║Condition group #1 evaluated false (state changed) (10ms)
+166ms ║╚Execution stage complete. (19ms)
+167ms ╚Event processed successfully (167ms)

5/7/2019, 9:06:54 PM +567ms
+2ms ╔Received event [Front Door Contact].contact = open with a delay of 829ms
+142ms ║RunTime Analysis CS > 26ms > PS > 99ms > PE > 18ms > CE
+145ms ║Runtime (40546 bytes) successfully initialized in 99ms (v0.3.10a.20190223) (143ms)
+146ms ║╔Execution stage started
+157ms ║║Comparison (enum) open changes_to (string) open = true (0ms)
+159ms ║║Cancelling condition #2's schedules...
+160ms ║║Condition #2 evaluated true (7ms)
+169ms ║║Comparison (enum) off is (string) off = true (2ms)
+171ms ║║Condition #3 evaluated true (10ms)
+173ms ║║Cancelling condition #1's schedules...
+174ms ║║Condition group #1 evaluated true (state changed) (21ms)
+186ms ║║Comparison (enum) not present is_not (string) present = true (2ms)
+188ms ║║Condition #5 evaluated true (11ms)
+189ms ║║Condition group #4 evaluated true (state did not change) (13ms)
+192ms ║║Cancelling statement #8's schedules...
+212ms ║║Executed virtual command sendPushNotification (14ms)
+216ms ║║Cancelling statement #10's schedules...
+221ms ║║Executed virtual command wait (1ms)
+223ms ║║Requesting a wake up for Tue, May 7 2019 @ 9:07:24 PM EDT (in 30.0s)
+228ms ║╚Execution stage complete. (82ms)
+230ms ║Setting up scheduled job for Tue, May 7 2019 @ 9:07:24 PM EDT (in 29.994s)
+239ms ╚Event processed successfully (239ms)

Any help would be greatly appreciated!

Thanks,

Scott


#2

I think you need to set Task Cancellation Policy to “Never” on the blocks below the WAIT.
(this is because after the wait, the door is no longer changing to open)


#3

Hey man that may have fixed it! Thanks! It took me a while to find WHERE you change the Task Cancellation Policy (the page linked explains the different modes, but not where to change them…for anyone coming across this in a search, you get to it by clicking on an “If”, then click the advanced gear)

However, it seems to be intermittent. In the below example I tried twice in row. The first time (on the left) it worked perfectly, the second time (on the right) it did the same behavior as my initial attempt without the Task Cancellation Policy. Any ideas?

Thanks,

Scott


#4

I think to be effective, the TCP needs to be changed on the WITH line. I am not sure if doing it on the IF will solve it.

What happened with your right example above is, the door was closed within the 30 second window, so the piston started all over at the top, and since the door was closed, it stopped the rest of the execution.

Making TCP to Never on the WITH blocks below the WAIT should do the trick.
(sorry I forgot to mention that detail before)


#5

I tried changing the TCP for the WITH blocks but it’s still not working. Maybe I did something wrong?

(Screenshot below is from edit mode, as the “N” does not show in the red/green snapshots)

Here is the log:

 5/9/2019, 6:30:32 PM +132ms
    +1ms
    ╔Received event [Home].time = 1557441033239 with a delay of -1108ms
    +360ms
    ║RunTime Analysis CS > 39ms > PS > 122ms > PE > 199ms > CE
    +364ms
    ║Runtime (40529 bytes) successfully initialized in 122ms (v0.3.10a.20190223) (360ms)
    +365ms
    ║╔Execution stage started
    +367ms
    ║╚Execution stage complete. (2ms)
    +369ms
    ╚Event processed successfully (369ms)
    
5/9/2019, 6:30:06 PM +335ms
    +1ms
    ╔Received event [Front Door Contact].contact = closed with a delay of 153ms
    +92ms
    ║RunTime Analysis CS > 16ms > PS > 57ms > PE > 20ms > CE
    +95ms
    ║Runtime (40526 bytes) successfully initialized in 57ms (v0.3.10a.20190223) (93ms)
    +96ms
    ║╔Execution stage started
    +107ms
    ║║Comparison (enum) closed changes_to (string) open = false (0ms)
    +109ms
    ║║Cancelling condition #2's schedules...
    +110ms
    ║║Condition #2 evaluated false (7ms)
    +111ms
    ║║Cancelling condition #1's schedules...
    +112ms
    ║║Condition group #1 evaluated false (state changed) (10ms)
    +115ms
    ║╚Execution stage complete. (19ms)
    +116ms
    ╚Event processed successfully (116ms)
    
5/9/2019, 6:30:02 PM +997ms
    +2ms
    ╔Received event [Front Door Contact].contact = open with a delay of 193ms
    +159ms
    ║RunTime Analysis CS > 26ms > PS > 109ms > PE > 23ms > CE
    +162ms
    ║Runtime (40534 bytes) successfully initialized in 109ms (v0.3.10a.20190223) (158ms)
    +163ms
    ║╔Execution stage started
    +173ms
    ║║Comparison (enum) open changes_to (string) open = true (1ms)
    +175ms
    ║║Cancelling condition #2's schedules...
    +177ms
    ║║Condition #2 evaluated true (7ms)
    +187ms
    ║║Comparison (enum) off is (string) off = true (2ms)
    +189ms
    ║║Condition #3 evaluated true (11ms)
    +191ms
    ║║Cancelling condition #1's schedules...
    +192ms
    ║║Condition group #1 evaluated true (state changed) (24ms)
    +204ms
    ║║Comparison (enum) not present is_not (string) present = true (2ms)
    +206ms
    ║║Condition #5 evaluated true (11ms)
    +208ms
    ║║Condition group #4 evaluated true (state did not change) (12ms)
    +211ms
    ║║Cancelling statement #8's schedules...
    +231ms
    ║║Executed virtual command sendPushNotification (14ms)
    +235ms
    ║║Cancelling statement #10's schedules...
    +240ms
    ║║Executed virtual command wait (0ms)
    +241ms
    ║║Requesting a wake up for Thu, May 9 2019 @ 6:30:33 PM EDT (in 30.0s)
    +247ms
    ║╚Execution stage complete. (85ms)
    +249ms
    ║Setting up scheduled job for Thu, May 9 2019 @ 6:30:33 PM EDT (in 29.994s)
    +258ms
    ╚Event processed successfully (257ms)

IMG_8038

As you can see, I get the first notification (line 51) and then after 30 seconds my Stringify flow works just fine, but the WebCoRE flow still seems to be quitting.


#6

Sorry about that. I just ran a few tests, and apparently the only requirement is to set “TCP to Never” on the WITH that holds the WAIT command. (highlighted below)

Generally speaking, I usually set it for the WAIT and all following blocks…
I thought doing it on the WAIT block was optional, but now I see it is essential.


#7

Hmm, I moved the TCP to never on only the wait, but its still not working

The logs seem to indicate that it did sent the push notification? But I only got the first, not the second.

5/10/2019, 5:45:15 PM +288ms
+1ms
╔Received event [Home].time = 1557524716295 with a delay of -1008ms
+211ms
║RunTime Analysis CS > 50ms > PS > 134ms > PE > 28ms > CE
+214ms
║Runtime (42478 bytes) successfully initialized in 134ms (v0.3.10a.20190223) (213ms)
+215ms
║╔Execution stage started
+245ms
║║30 sec wait completed
+246ms
║║Executed virtual command log (2ms)
+260ms
║║Comparison (enum) not present is_not (string) present = true (2ms)
+262ms
║║Condition #13 evaluated true (12ms)
+263ms
║║Condition group #12 evaluated true (state did not change) (13ms)
+267ms
║║Cancelling statement #16's schedules...
+294ms
║║Executed virtual command sendPushNotification (21ms)
+303ms
║║Door opened and keys not present after 30 sec
+305ms
║║Executed virtual command log (2ms)
+308ms
║╚Execution stage complete. (93ms)
+310ms
╚Event processed successfully (310ms)

5/10/2019, 5:44:48 PM +504ms
+0ms
╔Received event [Front Door Contact].contact = closed with a delay of 174ms
+97ms
║RunTime Analysis CS > 17ms > PS > 62ms > PE > 18ms > CE
+100ms
║Runtime (42476 bytes) successfully initialized in 62ms (v0.3.10a.20190223) (98ms)
+101ms
║╔Execution stage started
+111ms
║║Comparison (enum) closed changes_to (string) open = false (1ms)
+113ms
║║Cancelling condition #2's schedules...
+115ms
║║Condition #2 evaluated false (7ms)
+116ms
║║Cancelling condition #1's schedules...
+117ms
║║Condition group #1 evaluated false (state changed) (11ms)
+121ms
║╚Execution stage complete. (20ms)
+123ms
║Setting up scheduled job for Fri, May 10 2019 @ 5:45:16 PM EDT (in 27.669s)
+135ms
╚Event processed successfully (136ms)

5/10/2019, 5:44:46 PM +29ms
+1ms
╔Received event [Front Door Contact].contact = open with a delay of 1229ms
+96ms
║RunTime Analysis CS > 17ms > PS > 61ms > PE > 18ms > CE
+178ms
║Runtime (42482 bytes) successfully initialized in 61ms (v0.3.10a.20190223) (176ms)
+179ms
║╔Execution stage started
+191ms
║║Comparison (enum) open changes_to (string) open = true (0ms)
+193ms
║║Cancelling condition #2's schedules...
+194ms
║║Condition #2 evaluated true (8ms)
+203ms
║║Comparison (enum) off is (string) off = true (2ms)
+205ms
║║Condition #3 evaluated true (10ms)
+207ms
║║Cancelling condition #1's schedules...
+208ms
║║Condition group #1 evaluated true (state changed) (22ms)
+219ms
║║Comparison (enum) not present is_not (string) present = true (2ms)
+221ms
║║Condition #5 evaluated true (10ms)
+223ms
║║Condition group #4 evaluated true (state did not change) (11ms)
+226ms
║║Cancelling statement #8's schedules...
+245ms
║║Executed virtual command sendPushNotification (14ms)
+249ms
║║Cancelling statement #10's schedules...
+257ms
║║Begin 30 wait for 30 sec
+259ms
║║Executed virtual command log (2ms)
+263ms
║║Executed virtual command wait (1ms)
+265ms
║║Requesting a wake up for Fri, May 10 2019 @ 5:45:16 PM EDT (in 30.0s)
+270ms
║╚Execution stage complete. (91ms)
+272ms
║Setting up scheduled job for Fri, May 10 2019 @ 5:45:16 PM EDT (in 29.995s)
+279ms
╚Event processed successfully (279ms)

The setup I had in Stringify was so easy and it has always worked without issue. I don’t suppose there is any way to see what code my hub is executing to process the working Stringify flow to compare it to WebCoRE?

PNG


#8

Very strange. I have never seen this before. The good news is that means that webCoRE is doing it’s job correctly. I am not sure why SmartThings is botching up the notification, although to be honest, I’ve never send more than one notification per piston’s execution. (I use logs scattered about to make sure each block runs as expected, and only send one notification as a summary)


I would try here:
account.smartthings.com > Live Logging

You can leave that window open for a bit and test/troubleshoot. It is supposed to log all events.
(Although, I just went to that page, and it is not working at the moment for me)


And lastly, to make a bit more sense of the logs in webCoRE, it helps to turn on TRACE. This adds numbers to the end of each command, which match up with the numbers in the logs. It makes troubleshooting here in webCoRE much easier… (just post a new snapshot if we need to troubleshoot further)


#9

I removed the extra push notifications in favor of log/warn and so far its worked all this weekend so I think this is solved. Thanks for your help, @WCmore!