Timed events not always running correctly


#1

1) Give a description of the problem
I have setup a piston that runs at various times during the day which either sets a heating TRV to on and a temperature or switches it to off/eco ie lower temperature. The program is split into two, ie at certain times it runs part of the code and at other the other part of the code. This is controlled by setting the varible “Off” to true or false at the trigger time…

2) What is the expected behaviour?
I would expect the code to run the correct part of the code depending on the time it was triggered at.

3) What is happening/not happening?
Often it is running correctly. But sometimes eg today at 9am it turned the heating up rather than down. The piston status/logging shows it did indeed set the TRV up to 25c but I can’t see why it did that when the logic (I think) says turn the TRV down.

**4) Post a Green Snapshot of the piston![image|45x37]

5) Attach logs after turning logging level to Full

12/18/2020, 9:00:51 AM +125ms
+0ms	╔Received event [Home].time = 1608282051989 with a delay of -865ms
+288ms	║RunTime Analysis CS > 114ms > PS > 113ms > PE > 61ms > CE
+291ms	║Runtime (47544 bytes) successfully initialized in 113ms (v0.3.10e.20190628) (289ms)
+292ms	║╔Execution stage started
+512ms	║║Executed physical command [Bedroom 1 TRV].booston() (134ms)
+513ms	║║Executed [Bedroom 1 TRV].booston (136ms)
+525ms	║║Calculating (string) Fri, Dec 18 2020 @ 9:00:51 AM GMT + (string) Set Temperature to >> (string) Fri, Dec 18 2020 @ 9:00:51 AM GMT Set Temperature to
+528ms	║║Calculating (string) Fri, Dec 18 2020 @ 9:00:51 AM GMT Set Temperature to + (string) 25 >> (string) Fri, Dec 18 2020 @ 9:00:51 AM GMT Set Temperature to 25
+531ms	║║Calculating (string) Fri, Dec 18 2020 @ 9:00:51 AM GMT Set Temperature to 25 + (string) with Boost >> (string) Fri, Dec 18 2020 @ 9:00:51 AM GMT Set Temperature to 25 with Boost
+535ms	║║Executed virtual command [Bedroom 1 TRV].setState (1ms)
+542ms	║║Calculating (string) Bedroom 1 TRV: Set Temperature to + (string) 25 >> (string) Bedroom 1 TRV: Set Temperature to 25
+545ms	║║Calculating (string) Bedroom 1 TRV: Set Temperature to 25 + (string) With Boost >> (string) Bedroom 1 TRV: Set Temperature to 25 With Boost
+549ms	║║Bedroom 1 TRV: Set Temperature to 25 With Boost
+552ms	║║Executed virtual command [Bedroom 1 TRV].log (4ms)
+666ms	║╚Execution stage complete. (375ms)
+672ms	║Setting up scheduled job for Fri, Dec 18 2020 @ 12:00:00 PM GMT (in 10748.204s), with 6 more jobs pending
+680ms	╚Event processed successfully (681ms)
12/18/2020, 9:00:38 AM +155ms
+1ms	╔Received event [Home].time = 1608282039538 with a delay of -1383ms
+10270ms	║RunTime Analysis CS > 93ms > PS > 10107ms > PE > 70ms > CE
+10271ms	║Piston waited at a semaphore for 10082ms
+10274ms	║Runtime (47622 bytes) successfully initialized in 10107ms (v0.3.10e.20190628) (10272ms)
+10275ms	║╔Execution stage started
+10276ms	║╚Execution stage complete. (1ms)
+10279ms	║Setting up scheduled job for Fri, Dec 18 2020 @ 9:00:51 AM GMT (in 3.556s), with 7 more jobs pending
+10288ms	╚Event processed successfully (10288ms)
12/18/2020, 9:00:38 AM +114ms
+1ms	╔Received event [Home].time = 1608282039538 with a delay of -1424ms
+320ms	║RunTime Analysis CS > 118ms > PS > 129ms > PE > 73ms > CE
+323ms	║Runtime (47545 bytes) successfully initialized in 129ms (v0.3.10e.20190628) (321ms)
+324ms	║╔Execution stage started
+8869ms	║║Executed physical command [Bedroom 1 TRV].setHeatingSetpoint([25.0]) (8508ms)
+8870ms	║║Executed [Bedroom 1 TRV].setHeatingSetpoint (8510ms)
+8873ms	║║Executed virtual command [Bedroom 1 TRV].wait (0ms)
+8875ms	║║Requesting a wake up for Fri, Dec 18 2020 @ 9:00:51 AM GMT (in 5.0s)
+8880ms	║╚Execution stage complete. (8555ms)
+8883ms	║Setting up scheduled job for Fri, Dec 18 2020 @ 9:00:51 AM GMT (in 4.993s), with 7 more jobs pending
+8911ms	╚Event processed successfully (8911ms)
12/18/2020, 9:00:32 AM +313ms
+1ms	╔Received event [Home].execute = recovery with a delay of 50ms
+87ms	║RunTime Analysis CS > 15ms > PS > 13ms > PE > 59ms > CE
+90ms	║Runtime (47533 bytes) successfully initialized in 13ms (v0.3.10e.20190628) (88ms)
+91ms	║╔Execution stage started
+101ms	║║Comparison (enum) on is (string) on = true (1ms)
+102ms	║║Condition #63 evaluated true (8ms)
+103ms	║║Condition group #null evaluated true (state did not change) (9ms)
+105ms	║║Cancelling statement #81's schedules...
+108ms	║║Executed virtual command wait (0ms)
+109ms	║║Waiting for 2000ms
+2114ms	║║Comparison (time) 32434425 happens_daily_at (time) 27000000 = false (0ms)
+2116ms	║║Cancelling condition #46's schedules...
+2116ms	║║Condition #46 evaluated false (4ms)
+2117ms	║║Cancelling statement #46's schedules...
+2120ms	║║Requesting time schedule wake up at Sat, Dec 19 2020 @ 7:30:00 AM GMT
+2125ms	║║Comparison (time) 32434436 happens_daily_at (time) 79200000 = false (0ms)
+2126ms	║║Condition #76 evaluated false (4ms)
+2127ms	║║Cancelling statement #76's schedules...
+2130ms	║║Requesting time schedule wake up at Fri, Dec 18 2020 @ 10:00:00 PM GMT
+2132ms	║║Cancelling condition #45's schedules...
+2133ms	║║Condition group #45 evaluated false (state changed) (21ms)
+2137ms	║║Comparison (time) 32434449 happens_daily_at (time) 32400000 = false (0ms)
+2139ms	║║Condition #50 evaluated false (3ms)
+2140ms	║║Cancelling statement #50's schedules...
+2143ms	║║Requesting time schedule wake up at Sat, Dec 19 2020 @ 9:00:00 AM GMT
+2147ms	║║Comparison (time) 32434458 happens_daily_at (time) 43200000 = false (0ms)
+2148ms	║║Condition #77 evaluated false (3ms)
+2149ms	║║Cancelling statement #77's schedules...
+2152ms	║║Requesting time schedule wake up at Fri, Dec 18 2020 @ 12:00:00 PM GMT
+2156ms	║║Comparison (time) 32434467 happens_daily_at (time) 57600000 = false (1ms)
+2157ms	║║Condition #78 evaluated false (3ms)
+2158ms	║║Cancelling statement #78's schedules...
+2161ms	║║Requesting time schedule wake up at Fri, Dec 18 2020 @ 4:00:00 PM GMT
+2165ms	║║Comparison (time) 32434476 happens_daily_at (time) 60000 = false (0ms)
+2166ms	║║Condition #79 evaluated false (3ms)
+2168ms	║║Cancelling statement #79's schedules...
+2171ms	║║Requesting time schedule wake up at Sat, Dec 19 2020 @ 12:01:00 AM GMT
+2175ms	║║Comparison (time) 32434486 happens_daily_at (time) 5400000 = false (0ms)
+2176ms	║║Condition #80 evaluated false (3ms)
+2177ms	║║Cancelling statement #80's schedules...
+2180ms	║║Requesting time schedule wake up at Sat, Dec 19 2020 @ 1:30:00 AM GMT
+2182ms	║║Condition group #49 evaluated false (state did not change) (47ms)
+2189ms	║║Comparison (boolean) false is (boolean) true = false (2ms)
+2190ms	║║Condition #56 evaluated false (5ms)
+2191ms	║║Condition group #55 evaluated false (state did not change) (7ms)
+2205ms	║║Calculating (integer) 25 - (integer) 4 >> (integer) 21
+2208ms	║║Comparison (decimal) 20.87 is_less_than_or_equal_to (integer) 21 = true (2ms)
+2209ms	║║Condition #26 evaluated true (16ms)
+2210ms	║║Condition group #25 evaluated true (state did not change) (17ms)
+2212ms	║║Cancelling statement #29's schedules...
+2219ms	║║Skipped execution of physical command [Bedroom 1 TRV].auto([]) because it would make no change to the device. (4ms)
+2220ms	║║Executed [Bedroom 1 TRV].auto (6ms)
+2223ms	║║Executed virtual command [Bedroom 1 TRV].wait (0ms)
+2224ms	║║Requesting a wake up for Fri, Dec 18 2020 @ 9:00:39 AM GMT (in 5.0s)
+2234ms	║╚Execution stage complete. (2143ms)
+2237ms	║Setting up scheduled job for Fri, Dec 18 2020 @ 9:00:39 AM GMT (in 4.988s), with 7 more jobs pending
+2246ms	╚Event processed successfully (2246ms)
12/18/2020, 9:00:26 AM +111ms
+0ms	╔Received event [Home].time/recovery = 1608282026105 with a delay of 5ms
+252ms	║RunTime Analysis CS > 96ms > PS > 97ms > PE > 60ms > CE
+256ms	║Runtime (47544 bytes) successfully initialized in 97ms (v0.3.10e.20190628) (255ms)
+257ms	║╔Execution stage started
+270ms	║║Comparison (enum) on is (string) on = true (1ms)
+272ms	║║Condition #63 evaluated true (10ms)
+273ms	║║Condition group #null evaluated true (state did not change) (11ms)
+275ms	║║Cancelling statement #81's schedules...
+278ms	║║Executed virtual command wait (1ms)
+279ms	║║Waiting for 2000ms
+2285ms	║║Comparison (time) 32428394 happens_daily_at (time) 27000000 = false (1ms)
+2286ms	║║Cancelling condition #46's schedules...
+2287ms	║║Condition #46 evaluated false (5ms)
+2288ms	║║Cancelling statement #46's schedules...
+2292ms	║║Requesting time schedule wake up at Sat, Dec 19 2020 @ 7:30:00 AM GMT
+2296ms	║║Comparison (time) 32428405 happens_daily_at (time) 79200000 = false (0ms)
+2298ms	║║Condition #76 evaluated false (4ms)
+2299ms	║║Cancelling statement #76's schedules...
+2302ms	║║Requesting time schedule wake up at Fri, Dec 18 2020 @ 10:00:00 PM GMT
+2304ms	║║Cancelling condition #45's schedules...
+2305ms	║║Condition group #45 evaluated false (state changed) (23ms)
+2310ms	║║Comparison (time) 32428419 happens_daily_at (time) 32400000 = true (0ms)
+2311ms	║║Time restriction check passed
+2313ms	║║Cancelling condition #50's schedules...
+2314ms	║║Condition #50 evaluated true (5ms)
+2315ms	║║Cancelling statement #50's schedules...
+2319ms	║║Requesting time schedule wake up at Sat, Dec 19 2020 @ 9:00:00 AM GMT
+2322ms	║║Cancelling condition #49's schedules...
+2323ms	║║Condition group #49 evaluated true (state changed) (14ms)
+2325ms	║║Cancelling statement #39's schedules...
+2328ms	║║Executed virtual command setVariable (1ms)
+2335ms	║║Comparison (boolean) true is (boolean) true = true (2ms)
+2336ms	║║Cancelling condition #56's schedules...
+2337ms	║║Condition #56 evaluated true (6ms)
+2339ms	║║Cancelling condition #55's schedules...
+2340ms	║║Condition group #55 evaluated true (state changed) (9ms)
+2343ms	║║Cancelling statement #57's schedules...
+6005ms	║║Executed physical command [Bedroom 1 TRV].configure() (3657ms)
+6006ms	║║Executed [Bedroom 1 TRV].configure (3659ms)
+6009ms	║║Executed virtual command [Bedroom 1 TRV].wait (1ms)
+6010ms	║║Requesting a wake up for Fri, Dec 18 2020 @ 9:00:42 AM GMT (in 10.0s)
+6072ms	║╚Execution stage complete. (5815ms)
+6076ms	║Setting up scheduled job for Fri, Dec 18 2020 @ 9:00:42 AM GMT (in 9.936s), with 7 more jobs pending
+6083ms	╚Event processed successfully (6083ms)
12/18/2020, 7:30:21 AM +65ms
+1ms	╔Received event [Home].time = 1608276622889 with a delay of -1824ms
+113ms	║RunTime Analysis CS > 20ms > PS > 22ms > PE > 71ms > CE
+116ms	║Runtime (47517 bytes) successfully initialized in 22ms (v0.3.10e.20190628) (114ms)
+117ms	║╔Execution stage started
+2241ms	║║Executed physical command [Bedroom 1 TRV].booston() (2088ms)
+2242ms	║║Executed [Bedroom 1 TRV].booston (2091ms)
+2250ms	║║Calculating (string) Fri, Dec 18 2020 @ 7:30:23 AM GMT + (string) Set Temperature to >> (string) Fri, Dec 18 2020 @ 7:30:23 AM GMT Set Temperature to
+2253ms	║║Calculating (string) Fri, Dec 18 2020 @ 7:30:23 AM GMT Set Temperature to + (string) 25 >> (string) Fri, Dec 18 2020 @ 7:30:23 AM GMT Set Temperature to 25
+2256ms	║║Calculating (string) Fri, Dec 18 2020 @ 7:30:23 AM GMT Set Temperature to 25 + (string) with Boost >> (string) Fri, Dec 18 2020 @ 7:30:23 AM GMT Set Temperature to 25 with Boost
+2259ms	║║Executed virtual command [Bedroom 1 TRV].setState (1ms)
+2266ms	║║Calculating (string) Bedroom 1 TRV: Set Temperature to + (string) 25 >> (string) Bedroom 1 TRV: Set Temperature to 25
+2269ms	║║Calculating (string) Bedroom 1 TRV: Set Temperature to 25 + (string) With Boost >> (string) Bedroom 1 TRV: Set Temperature to 25 With Boost
+2273ms	║║Bedroom 1 TRV: Set Temperature to 25 With Boost
+2275ms	║║Executed virtual command [Bedroom 1 TRV].log (3ms)
+2289ms	║╚Execution stage complete. (2172ms)
+2294ms	║Setting up scheduled job for Fri, Dec 18 2020 @ 9:00:00 AM GMT (in 5376.642s), with 6 more jobs pending
+2301ms	╚Event processed successfully (2301ms)
12/18/2020, 7:30:11 AM +119ms
+0ms	╔Received event [Home].time = 1608276612686 with a delay of -1568ms
+157ms	║RunTime Analysis CS > 46ms > PS > 51ms > PE > 61ms > CE
+160ms	║Runtime (47517 bytes) successfully initialized in 51ms (v0.3.10e.20190628) (159ms)
+161ms	║╔Execution stage started
+6764ms	║║Executed physical command [Bedroom 1 TRV].setHeatingSetpoint([25.0]) (6568ms)
+6765ms	║║Executed [Bedroom 1 TRV].setHeatingSetpoint (6570ms)
+6768ms	║║Executed virtual command [Bedroom 1 TRV].wait (1ms)
+6769ms	║║Requesting a wake up for Fri, Dec 18 2020 @ 7:30:22 AM GMT (in 5.0s)
+6774ms	║╚Execution stage complete. (6613ms)
+6778ms	║Setting up scheduled job for Fri, Dec 18 2020 @ 7:30:22 AM GMT (in 4.993s), with 7 more jobs pending
+6784ms	╚Event processed successfully (6784ms)
12/18/2020, 7:29:59 AM +80ms
+1ms	╔Received event [Home].time = 1608276600000 with a delay of -921ms
+161ms	║RunTime Analysis CS > 18ms > PS > 24ms > PE > 119ms > CE
+163ms	║Runtime (47508 bytes) successfully initialized in 24ms (v0.3.10e.20190628) (161ms)
+164ms	║╔Execution stage started
+178ms	║║Comparison (enum) on is (string) on = true (2ms)
+179ms	║║Condition #63 evaluated true (9ms)
+180ms	║║Condition group #null evaluated true (state did not change) (10ms)
+183ms	║║Cancelling statement #81's schedules...
+186ms	║║Executed virtual command wait (0ms)
+187ms	║║Waiting for 2000ms
+2192ms	║║Comparison (time) 27001270 happens_daily_at (time) 27000000 = true (1ms)
+2193ms	║║Time restriction check passed
+2196ms	║║Cancelling condition #46's schedules...
+2197ms	║║Condition #46 evaluated true (6ms)
+2197ms	║║Cancelling statement #46's schedules...
+2200ms	║║Requesting time schedule wake up at Sat, Dec 19 2020 @ 7:30:00 AM GMT
+2203ms	║║Cancelling condition #45's schedules...
+2204ms	║║Condition group #45 evaluated true (state changed) (15ms)
+2206ms	║║Cancelling statement #35's schedules...
+2218ms	║║Executed virtual command setVariable (2ms)
+2223ms	║║Comparison (time) 27001301 happens_daily_at (time) 32400000 = false (0ms)
+2224ms	║║Condition #50 evaluated false (4ms)
+2225ms	║║Cancelling statement #50's schedules...
+2228ms	║║Requesting time schedule wake up at Fri, Dec 18 2020 @ 9:00:00 AM GMT
+2232ms	║║Comparison (time) 27001310 happens_daily_at (time) 43200000 = false (0ms)
+2234ms	║║Condition #77 evaluated false (3ms)
+2235ms	║║Cancelling statement #77's schedules...
+2237ms	║║Requesting time schedule wake up at Fri, Dec 18 2020 @ 12:00:00 PM GMT
+2242ms	║║Comparison (time) 27001320 happens_daily_at (time) 57600000 = false (0ms)
+2243ms	║║Condition #78 evaluated false (4ms)
+2244ms	║║Cancelling statement #78's schedules...
+2247ms	║║Requesting time schedule wake up at Fri, Dec 18 2020 @ 4:00:00 PM GMT
+2252ms	║║Comparison (time) 27001330 happens_daily_at (time) 60000 = false (1ms)
+2253ms	║║Condition #79 evaluated false (3ms)
+2255ms	║║Cancelling statement #79's schedules...
+2257ms	║║Requesting time schedule wake up at Sat, Dec 19 2020 @ 12:01:00 AM GMT
+2262ms	║║Comparison (time) 27001340 happens_daily_at (time) 5400000 = false (0ms)
+2263ms	║║Cancelling condition #80's schedules...
+2264ms	║║Condition #80 evaluated false (4ms)
+2265ms	║║Cancelling statement #80's schedules...
+2268ms	║║Requesting time schedule wake up at Sat, Dec 19 2020 @ 1:30:00 AM GMT
+2270ms	║║Cancelling condition #49's schedules...
+2271ms	║║Condition group #49 evaluated false (state changed) (51ms)
+2278ms	║║Comparison (boolean) false is (boolean) true = false (1ms)
+2279ms	║║Cancelling condition #56's schedules...
+2280ms	║║Condition #56 evaluated false (6ms)
+2281ms	║║Cancelling condition #55's schedules...
+2282ms	║║Condition group #55 evaluated false (state changed) (9ms)
+2298ms	║║Calculating (integer) 25 - (integer) 4 >> (integer) 21
+2301ms	║║Comparison (decimal) 15.59 is_less_than_or_equal_to (integer) 21 = true (1ms)
+2302ms	║║Condition #26 evaluated true (18ms)
+2303ms	║║Condition group #25 evaluated true (state did not change) (19ms)
+2306ms	║║Cancelling statement #29's schedules...
+8599ms	║║Executed physical command [Bedroom 1 TRV].auto() (6291ms)
+8600ms	║║Executed [Bedroom 1 TRV].auto (6293ms)
+8604ms	║║Executed virtual command [Bedroom 1 TRV].wait (0ms)
+8605ms	║║Requesting a wake up for Fri, Dec 18 2020 @ 7:30:12 AM GMT (in 5.0s)
+8862ms	║╚Execution stage complete. (8697ms)
+8866ms	║Setting up scheduled job for Fri, Dec 18 2020 @ 7:30:12 AM GMT (in 4.741s), with 7 more jobs pending
+8873ms	╚Event processed successfully (8873ms)

#2

It looks like the 9am time event didn’t arrive and your piston received two recovery events - one from another piston that was running at the time, and one from webCoRE’s timed recovery process thing. Your piston seems to default to turning the heat on when it runs so it did.


#3

Thank you for looking. I’m not sure I completely understand the explanation, or at least why the 9am event did not arrive and it had two recovery events. I’m assuming this is a problem/fault with Webcore/Smartthings rather than my Piston.

I’ll try restructuring it a little and at least make it default to turning the heat down. But this is happening quite often so a bit of a shame you can’t depend on timed events in Webcore/Smartthings.


#4

The recovery events are the easier of the two to explain. Pistons can only have one future timed execution actually scheduled in SmartThings at a time. Every time the piston executes it works out when the next time it needs to run is and creates/updates the schedule in SmartThings for that time. If, for some reason, it doesn’t receive the time event when it asked for it there is a potential problem. It doesn’t have a timed execution scheduled and so is entirely dependent on receiving some other kind of untimed event (such as a device attribute change) if it is ever to run again.

This is where recovery events come in. Every single piston that you run will look to see if there are any other pistons that are overdue a timer event by thirty seconds or more, and any that are found are sent a recovery event so they can fire up and schedule a new execution. As you may not have pistons running frequently, there is also an optional recovery procedure that can run regularly at one of a range of intervals from five minutes to three hours. You’ll see the setting for it in the webCoRE SmartApp on the ST mobile app. It does the same thing, though the event looks different (one is a time/recovery event and the other an execute event with a value of recovery).

Although they can kickstart your piston, they can also make a mess if the piston doesn’t do something sensible when they are received. In that respect they are not dissimilar to the effect of hitting the Test button for your piston. If you can make your piston do something unwanted by hitting the Test button at the wrong time, the recovery events have the potential to cause a similar problem.

As to why there is a missing time event in the first place (or one that is delayed by more than 30 seconds), now there is the mystery. I wouldn’t say it is something you see regularly, routinely or frequently, but neither would I bat an eyelid any time it happened. At one point all my motion sensors were failing most nights because they never received the time event needed to make them go inactive. Then the problem just went away.


#5

Thank you for that explanation, very useful. Its certainly improving my understanding of how Webcore works, and how to diagnose issues.
I’m in the process now of restructuring my Pistons to work better with timed events.