Command did not execute twice

[Terminal]

1) Give a description of the problem
This seems to be hit or miss. The command should tell the thermostat to return to the normal schedule each night at 9:10PM. I have two issues, the first being that sometimes when command is sent to the thermostat to resume the schedule it does not take, so I decided to send it twice.

Last night the command was sent at 9:10 but the thermostat did not change, this is an Ecobee issue I think. I can see in the recently tab for the thermostat that the piston sent the command at 9:10.
The piston should have sent the command again 5 minutes later, it did not. The log, shown below, from the night before shows the commend being sent twice but only once last night. Though there are two log entries for last night. Not sure what that means.

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

5) Attach logs after turning logging level to Full
10/25/2019, 9:10:39 PM +660ms
+1ms ╔Received event [Home].time/recovery = 1572052239660 with a delay of 0ms
+439ms ║RunTime Analysis CS > 172ms > PS > 214ms > PE > 53ms > CE
+630ms ║Runtime (38171 bytes) successfully initialized in 214ms (v0.3.110.20191009) (628ms)
+631ms ║╔Execution stage started
+632ms ║╚Execution stage complete. (1ms)
+634ms ║Setting up scheduled job for Sat, Oct 26 2019 @ 9:10:00 PM EDT (in 86359.707s)
+643ms ╚Event processed successfully (642ms)

10/25/2019, 9:10:38 PM +132ms
+1ms ╔Received event [Home].execute = recovery with a delay of 72ms
+139ms ║RunTime Analysis CS > 30ms > PS > 66ms > PE > 43ms > CE
+141ms ║Runtime (38153 bytes) successfully initialized in 66ms (v0.3.110.20191009) (140ms)
+142ms ║╔Execution stage started
+148ms ║║Comparison (time) 76238278 happens_daily_at (time) 76200000 = false (1ms)
+149ms ║║Cancelling condition #2’s schedules…
+150ms ║║Condition #2 evaluated false (4ms)
+151ms ║║Cancelling statement #2’s schedules…
+154ms ║║Requesting time schedule wake up at Sat, Oct 26 2019 @ 9:10:00 PM EDT
+156ms ║║Cancelling condition #1’s schedules…
+157ms ║║Condition group #1 evaluated false (state changed) (11ms)
+159ms ║╚Execution stage complete. (17ms)
+160ms ║Setting up scheduled job for Sat, Oct 26 2019 @ 9:10:00 PM EDT (in 86361.708s)
+168ms ╚Event processed successfully (168ms)

10/24/2019, 9:15:50 PM +353ms
+1ms ╔Received event [Home].time = 1571966151511 with a delay of -1158ms
+749ms ║RunTime Analysis CS > 192ms > PS > 492ms > PE > 64ms > CE
+752ms ║Runtime (38161 bytes) successfully initialized in 492ms (v0.3.110.20191009) (749ms)
+753ms ║╔Execution stage started
+19376ms ║║Executed physical command [Thermostat].resumeProgram() (18603ms)
+19377ms ║║Executed [Thermostat].resumeProgram (18605ms)
+19380ms ║╚Execution stage complete. (18627ms)
+19381ms ║Setting up scheduled job for Fri, Oct 25 2019 @ 9:10:00 PM EDT (in 86030.267s)
+19387ms ╚Event processed successfully (19387ms)

10/24/2019, 9:10:47 PM +896ms
+0ms ╔Received event [Home].time/recovery = 1571965847895 with a delay of 0ms
+631ms ║RunTime Analysis CS > 293ms > PS > 285ms > PE > 54ms > CE
+634ms ║Runtime (38166 bytes) successfully initialized in 285ms (v0.3.110.20191009) (632ms)
+635ms ║╔Execution stage started
+644ms ║║Comparison (time) 76248538 happens_daily_at (time) 76200000 = true (0ms)
+647ms ║║Time restriction check passed
+648ms ║║Condition #2 evaluated true (6ms)
+650ms ║║Cancelling statement #2’s schedules…
+655ms ║║Requesting time schedule wake up at Fri, Oct 25 2019 @ 9:10:00 PM EDT
+663ms ║║Comparison (string) :1c6acd098da7a83d6f6e254290f6eb3d: is (string) :1c6acd098da7a83d6f6e254290f6eb3d: = true (1ms)
+665ms ║║Condition #5 evaluated true (6ms)
+666ms ║║Condition group #1 evaluated true (state did not change) (24ms)
+670ms ║║Cancelling statement #3’s schedules…
+3608ms ║║Executed physical command [Thermostat].resumeProgram() (2931ms)
+3610ms ║║Executed [Thermostat].resumeProgram (2933ms)
+3613ms ║║Executed virtual command [Thermostat].wait (0ms)
+3615ms ║║Requesting a wake up for Thu, Oct 24 2019 @ 9:15:51 PM EDT (in 300.0s)
+3619ms ║╚Execution stage complete. (2984ms)
+3620ms ║Setting up scheduled job for Thu, Oct 24 2019 @ 9:15:51 PM EDT (in 299.995s), with 1 more job pending
+3629ms ╚Event processed successfully (3629ms)

[guxdude]

I think you need to take your wait & resend command out of the if because when it comes back in the time happens daily is no longer true.

[WCmore]

Well, the TCP is set to never, so the code looks good…
(although thermostats are notorious for slow response)

The red flag is that the piston fired (as a recovery) 38 seconds late on the 25th, and then a second later (also as a recovery).

This often means there was a lot of commotion in your home network at the time, and the hub was “busy” doing other things. If you have other pistons running at 9:10, I would change this one to 9:11PM. (or some other time when other pistons are not scheduled.)

Another way to get a safety net, is to create two triggers in the same piston… This way, if one hiccups, the next one should fire from a new trigger.

Something like this:

IF Time happens at 9:11PM
    Then resume program
END IF

IF Time happens at 9:16PM
    Then resume program
END IF

[Terminal]

Nothing else runs at that time, but thanks for the responses. Thanks for verifying the TCP thing, I thought that with that set it should not cancel the statement once started.

I have added a 2nd if statement that does the same thing 5 minutes later. minus the wait and resumeprogram again, so we will see how that goes.