"Happens Daily At" events fail almost every time

jeppsenc · 2019-10-17 23:02:35 UTC

I am having a problem with every piston which uses time trigger, whether it be a wait or a “Happens Daily At” event. Usually the piston fails somehow and restarts with “time/restart” or “execute: recovery” as the first item in the log. Here is an example piston which is supposed to set the thermostat to certain temperatures in the last afternoon:

Here are the log results:

|, 4:45:50 PM +680ms|
|+0ms|╔Received event [Jeppsen Home].execute = recovery with a delay of 53ms|
|+148ms|║RunTime Analysis CS &gt; 20ms &gt; PS &gt; 119ms &gt; PE &gt; 10ms &gt; CE|
|+150ms|║Runtime (38483 bytes) successfully initialized in 119ms (v0.3.110.20191009) (149ms)|
|+151ms|║╔Execution stage started|
|+158ms|║║Comparison (time) 60350836 happens_daily_at (time) 60300000 = false (1ms)|
|+160ms|║║Cancelling condition #2's schedules...|
|+160ms|║║Condition #2 evaluated false (4ms)|
|+161ms|║║Cancelling statement #2's schedules...|
|+165ms|║║Requesting time schedule wake up at Fri, Oct 18 2019 @ 4:45:00 PM MDT|
|+167ms|║║Cancelling condition #1's schedules...|
|+168ms|║║Condition group #1 evaluated false (state changed) (13ms)|
|+170ms|║╚Execution stage complete. (19ms)|
|+172ms|║Setting up scheduled job for Fri, Oct 18 2019 @ 4:45:00 PM MDT (in 86349.149s)|
|+181ms|╚Event processed successfully (181ms)|
|10/17/2019, 4:45:32 PM +117ms|
|+1ms|╔Received event [Jeppsen Home].time/recovery = 1571352332117 with a delay of 0ms|
|+517ms|║RunTime Analysis CS &gt; 80ms &gt; PS &gt; 428ms &gt; PE &gt; 9ms &gt; CE|
|+519ms|║Runtime (38497 bytes) successfully initialized in 428ms (v0.3.110.20191009) (517ms)|
|+520ms|║╔Execution stage started|
|+528ms|║║Comparison (time) 60332643 happens_daily_at (time) 60300000 = true (0ms)|
|+530ms|║║Time restriction check passed|
|+531ms|║║Cancelling condition #2's schedules...|
|+532ms|║║Condition #2 evaluated true (6ms)|
|+533ms|║║Cancelling statement #2's schedules...|
|+536ms|║║Requesting time schedule wake up at Fri, Oct 18 2019 @ 4:45:00 PM MDT|
|+539ms|║║Cancelling condition #1's schedules...|
|+540ms|║║Condition group #1 evaluated true (state changed) (14ms)|
|+543ms|║║Cancelling statement #3's schedules...|
|+18384ms|║║Executed physical command [Living Room Thermostat].setHeatingSetpoint([73.0]) (17836ms)|
|+18385ms|║║Executed [Living Room Thermostat].setHeatingSetpoint (17838ms)|
|+18419ms|║║Executed physical command [Living Room Thermostat].setCoolingSetpoint([76.0]) (28ms)|
|+18420ms|║║Executed [Living Room Thermostat].setCoolingSetpoint (31ms)|
|+18423ms|║╚Execution stage complete. (17902ms)|
|+18424ms|║Setting up scheduled job for Fri, Oct 18 2019 @ 4:45:00 PM MDT (in 86349.459s)|
|+18432ms|╚Event processed successfully (18431ms)|
|10/17/2019, 4:42:48 PM +701ms|
|+1ms|╔Received event [Jeppsen Home].test = 1571352168699 with a delay of 2ms|
|+165ms|║RunTime Analysis CS &gt; 22ms &gt; PS &gt; 127ms &gt; PE &gt; 16ms &gt; CE|
|+168ms|║Runtime (38464 bytes) successfully initialized in 127ms (v0.3.110.20191009) (166ms)|
|+170ms|║╔Execution stage started|
|+177ms|║║Comparison (time) 60168876 happens_daily_at (time) 60300000 = false (0ms)|
|+179ms|║║Condition #2 evaluated false (4ms)|
|+183ms|║║Cancelling statement #2's schedules...|
|+186ms|║║Requesting time schedule wake up at Thu, Oct 17 2019 @ 4:45:00 PM MDT|
|+191ms|║║Condition group #1 evaluated false (state did not change) (17ms)|
|+222ms|║╚Execution stage complete. (53ms)|
|+226ms|║Setting up scheduled job for Thu, Oct 17 2019 @ 4:45:00 PM MDT (in 131.074s)|
|+238ms|╚Event processed successfully (238ms)|

jkp · 2019-10-17 23:10:10 UTC

if you login to IDE at https://account.smartthings.com, click on My Hub then click on the name of your Location… do you see the correct sunrise/sunset/ time zone?

jeppsenc · 2019-10-17 23:50:05 UTC

Yes, it’s the correct time zone. Frequently the piston doesn’t execute at all (it did in this case). Instead I get several restarts that do nothing.

ale2999 · 2019-11-02 22:15:45 UTC

I had a piston that used this extensively working well and for the past few weeks it keeps failing. not sure why

Ryan780 · 2019-11-03 14:53:30 UTC

Try using a Timer instead of the happens daily at.

I think the scheduling is different for this trigger as opposed to the happens daily at. You’ll be able to tell though in the top of the piston under the quick facts. You can confirm there if it will execute the next day at the correct time.

nickbits · 2019-11-04 21:43:35 UTC

All my “happen daily at” pistions started to become super unreliable about 1-2 weeks ago. Most never fire at the time but have a recovery event 1-20 minutes later which doesn’t cause the event code to run. I made a test piston with 1 timer and it seemed to work ok but when I added 6 total, about half would miss. So I think something is overloaded somewhere. They have bee working fine for the last year up until last week.

LuckyDuck · 2019-11-05 03:47:24 UTC

This. Even though it shows that it will execute the next time at the correct time, it doesn’t. This happen both with a set time and with sunset/sunrise.

diverdavis · 2019-11-05 13:47:40 UTC

I’m having the same issue here. No problems for over a year and now is has pretty much quit working 100%. My time zone is correct.

Here are my logs for something that should have happened this morning at 7am.

11/5/2019, 7:00:30 AM +608ms
+1ms ╔Received event [Home].execute = recovery with a delay of 204ms
+106ms ║RunTime Analysis CS > 23ms > PS > 42ms > PE > 40ms > CE
+109ms ║Runtime (43503 bytes) successfully initialized in 42ms (v0.3.110.20191009) (108ms)
+110ms ║╔Execution stage started
+116ms ║║Comparison (time) 25230722 happens_daily_at (time) 25200000 = false (0ms)
+118ms ║║Condition #51 evaluated false (4ms)
+119ms ║║Cancelling statement #51’s schedules…
+122ms ║║Requesting time schedule wake up at Wed, Nov 6 2019 @ 7:00:00 AM EST
+124ms ║║Condition group #43 evaluated false (state did not change) (10ms)
+129ms ║║Comparison (time) 25230735 happens_daily_at (time) 39600000 = false (0ms)
+131ms ║║Condition #137 evaluated false (4ms)
+132ms ║║Cancelling statement #137’s schedules…
+135ms ║║Requesting time schedule wake up at Tue, Nov 5 2019 @ 11:00:00 AM EST
+137ms ║║Condition group #134 evaluated false (state did not change) (10ms)
+142ms ║║Comparison (time) 25230748 happens_daily_at (time) 68400000 = false (0ms)
+143ms ║║Condition #47 evaluated false (4ms)
+144ms ║║Cancelling statement #47’s schedules…
+147ms ║║Requesting time schedule wake up at Tue, Nov 5 2019 @ 7:00:00 PM EST
+149ms ║║Condition group #44 evaluated false (state did not change) (10ms)
+154ms ║║Comparison (time) 25230760 happens_daily_at (time) 55800000 = false (0ms)
+156ms ║║Condition #86 evaluated false (3ms)
+157ms ║║Cancelling statement #86’s schedules…
+160ms ║║Requesting time schedule wake up at Tue, Nov 5 2019 @ 3:30:00 PM EST
+162ms ║║Condition group #82 evaluated false (state did not change) (10ms)
+166ms ║╚Execution stage complete. (57ms)
+168ms ║Setting up scheduled job for Tue, Nov 5 2019 @ 11:00:00 AM EST (in 14369.224s), with 3 more jobs pending
+176ms ╚Event processed successfully (176ms)

WCmore · 2019-11-05 19:28:58 UTC

It looks like it did run at 7AM, but all of the conditional checks returned “false”, so no commands were sent.

 ║║Condition #51 evaluated false
 ║║Condition group #43 evaluated false (state did not change)
 ║║Condition #137 evaluated false
 ║║Condition group #134 evaluated false (state did not change)
 ║║Condition #47 evaluated false 
 ║║Condition group #44 evaluated false (state did not change) 
 ║║Condition #86 evaluated false
 ║║Condition group #82 evaluated false (state did not change)

diverdavis · 2019-11-05 19:53:25 UTC

Strange. Its just turning on a switch at 7am and that should have been true (it has been for the last year). I did have one other condition but it was also true.

I would have expected to see a “Time restriction check passed” in the logs
+110ms ║╔Execution stage started
+116ms ║║Comparison (time) 25230722 happens_daily_at (time) 25200000 = false (0ms)
+118ms ║║Condition #51 evaluated false (4ms)
+119ms ║║Cancelling statement #51’s schedules…

It did work at 11am

WCmore · 2019-11-05 19:55:41 UTC

The piston ran 30.7 seconds late, so the two times did not match.
(25,230,722 - 25,200,000 = 30,722)

diverdavis · 2019-11-05 20:05:55 UTC

Also to add that it’s not just the one piston. I have around 5 different pistons that all seem to fail to execute “some” of the times.

WCmore · 2019-11-05 20:24:52 UTC

Yes. Recently, there has been some changes to the base code at SmartThings…

I have been biting my tongue, and forcing myself to not touch old reliable pistons that have been acting up lately. (often seen as a “Recovery” in the logs)

diverdavis · 2019-11-05 20:35:44 UTC

Thanks! That makes sense. Can anything be done or is it on the Smartthings platform?

Something interesting is that I have the same piston run at 11am and it worked. Here is want I see from the logs and it looks like it’s out by 37 seconds but still worked.

Comparison (time) 39637267 happens_daily_at (time) 39600000 = true (0ms)
+558ms ║║Time restriction check passed
+559ms ║║Cancelling condition #137’s schedules…
+560ms ║║Condition #137 evaluated true (6ms)

WCmore · 2019-11-05 20:41:50 UTC

Parts of the base code was “fixed” about 17 hours ago for my location… but not every time based code is reliable yet.

Hopefully, they are just testing new code, and it will be resolved soon.

diverdavis · 2019-11-06 13:54:39 UTC

So it looks like everything is working again for me. All my pistons fired correctly over the last 12 hours or so. Thanks again for the help.