Suddenly can't control switch in piston

photonWelp · 2020-06-20 02:24:42 UTC

1) Give a description of the problem
I have a piston that monitors a switch and if it’s turned on, it starts a timer and turns it off after a set amount of time (normally 20mins). It’s been working great for a couple months and suddenly stopped working. I changed the duration of the timer to 1 min to confirm the issue.

2) What is the expected behaviour?
The switch should turn off after the timer completes.

3) What is happening/not happening?
I see the timer counting when triggered but the switch never turns off.

**4) Post a Green Snapshot

5) Attach logs after turning logging level to Full
6/19/2020, 11:37:41 AM +378ms +0ms ╔Received event [Home].execute = recovery with a delay of 42ms +90ms ║RunTime Analysis CS > 15ms > PS > 37ms > PE > 38ms > CE +93ms ║Runtime (36662 bytes) successfully initialized in 37ms (v0.3.110.20191009) (91ms) +94ms ║╔Execution stage started +104ms ║║Cancelling condition #2’s schedules… +105ms ║║Condition #2 evaluated false (7ms) +107ms ║║Cancelling condition #1’s schedules… +108ms ║║Condition group #1 evaluated false (state changed) (9ms) +110ms ║╚Execution stage complete. (17ms) +111ms ╚Event processed successfully (111ms) 6/19/2020, 11:35:47 AM +853ms +1ms ╔Received event [Downstairs Bath Fan].switch = on with a delay of 64ms +97ms ║RunTime Analysis CS > 17ms > PS > 50ms > PE > 29ms > CE +99ms ║Runtime (36676 bytes) successfully initialized in 50ms (v0.3.110.20191009) (97ms) +100ms ║╔Execution stage started +106ms ║║Comparison (enum) on changes_to (string) on = true (1ms)

+107ms	║║Cancelling condition #2’s schedules…
+108ms	║║Condition #2 evaluated true (5ms)
+109ms	║║Cancelling condition #1’s schedules…
+110ms	║║Condition group #1 evaluated true (state changed) (7ms)
+113ms	║║Cancelling statement #4’s schedules…
+116ms	║║Executed virtual command wait (0ms)
+117ms	║║Requesting a wake up for Fri, Jun 19 2020 @ 11:36:47 AM PDT (in 60.0s)
+121ms	║╚Execution stage complete. (22ms)
+122ms	║Setting up scheduled job for Fri, Jun 19 2020 @ 11:36:47 AM PDT (in 59.996s)
+132ms	╚Event processed successfully (132ms)

**REMOVE BELOW AFTER READING**

WCmore · 2020-06-20 03:04:37 UTC

According to your log, your initial trigger worked perfectly at 11:35:47 AM.
(It set a schedule for 11:36:47 AM)

For some reason, your piston did not run on schedule
WebCoRE caught that 54 seconds later (seen as a “recovery”)
At that time, everything was false, so no action was taken

If you want the “Turn off” to happen no matter what, you can click on the WITH on line 17, and set Task Cancellation Policy to ‘Never’. This will push the final command thru, even if things have ‘changed’.

photonWelp · 2020-06-20 03:56:51 UTC

Ok I tried that and unfortunately it didn’t work. Did I make the change correctly? I did notice that the piston summary showed that after the minute countdown, it counted up to 1 minute and then changed to an eval of false. Seems odd that it consistently misses the timer. I can control the switch from smartthings without issue.

6/19/2020, 8:48:41 PM +435ms +0ms ╔Received event [Home].execute = recovery with a delay of 47ms +95ms ║RunTime Analysis CS > 19ms > PS > 43ms > PE > 33ms > CE +97ms ║Runtime (36655 bytes) successfully initialized in 43ms (v0.3.110.20191009) (96ms) +98ms ║╔Execution stage started +108ms ║║Cancelling condition #2’s schedules… +109ms ║║Condition #2 evaluated false (7ms) +110ms ║║Cancelling condition #1’s schedules… +111ms ║║Condition group #1 evaluated false (state changed) (9ms) +113ms ║╚Execution stage complete. (15ms) +114ms ╚Event processed successfully (114ms) 6/19/2020, 8:46:47 PM +895ms +1ms ╔Received event [Downstairs Bath Fan].switch = on with a delay of 78ms +87ms ║RunTime Analysis CS > 15ms > PS > 39ms > PE > 33ms > CE +89ms ║Runtime (36669 bytes) successfully initialized in 39ms (v0.3.110.20191009) (87ms) +90ms ║╔Execution stage started +97ms ║║Comparison (enum) on changes_to (string) on = true (0ms) +98ms ║║Cancelling condition #2’s schedules… +99ms ║║Condition #2 evaluated true (5ms) +100ms ║║Cancelling condition #1’s schedules… +101ms ║║Condition group #1 evaluated true(state changed) (6ms) +103ms ║║Cancelling statement #4’s schedules… +106ms ║║Executed virtual command wait (0ms) +107ms ║║Requesting a wake up for Fri, Jun 19 2020 @ 8:47:48 PM PDT (in 60.0s) +112ms ║╚Execution stage complete. (21ms) +113ms ║Setting up scheduled job for Fri, Jun 19 2020 @ 8:47:48 PM PDT (in 59.996s) +140ms ╚Event processed successfully (140ms)

WCmore · 2020-06-20 03:59:27 UTC

Sorry, my bad.
I just noticed that TCP needs to be “Never” on the WITH that is holding the WAIT.
(or you can drag & drop the WAIT down inside the other WITH block)

For example:

IF Fan's switch changes to on
Then
    With Fan  (TCP set to Never)
        Wait 1 minute
        Turn off
    END WITH
END IF

Side Note:

I always recommend new users to keep the default “Any interaction”…
(99% of the time, switching to “Physical” or “Programmatic” interaction will not do what you expect)

photonWelp · 2020-06-20 04:26:39 UTC

Thanks, the tcp never on the wait worked. I was able to repeat it twice and both times it turned off under 40s after 1min. It’s really weird that this suddenly started happening. I wonder if the cloud provider under webcore is overtaxed right now which is causing consistent timer misses. That would explain why I’ve never seen it before.

WCmore · 2020-06-20 04:28:29 UTC

Recoveries are often due to congested network…
Sometimes external, but often it is commotion on the home network.

I’m not saying this is you, but common offenders in webCoRE might be:
Loops, Whiles and other poor coding choices that could be spamming the SmartHome…

If we are talking about Smart devices, the “chattiest” might be:
Power related, Lux sensors, or certain motion sensors…

Other heavy bandwidth offenders in the household might be:
Online gaming, Heavy downloading (Bittorrent), HD video streams, etc…

In a nutshell, each one of these impacts the others.