Help with a piston on hubitat - Wait times

chadmoss · 2019-07-02 21:03:09 UTC

1) Give a description of the problem
I have 2 pistons - 1 that runs, waits 2 min and fires off another piston. That first piston works great. The second piston performs some functions and then waits 4 min before running itself again. The piston works, but something is adding an extra 3 min to the wait time.

2) What is the expected behaviour?
(I expect a notification every 4 min if the criteria is met.

3) What is happening/not happening?
I am getting notifications every 7 min - you can see something on the left after counting down the 4 min (3 triangles) - this lasts for 3 min.

Any ideas what could be causing this?

eibyer · 2019-07-02 21:13:18 UTC

What does the other piston look like?

chadmoss · 2019-07-03 01:14:46 UTC

Sorry - first time really asking for support. What’s the easiest way to show you?

jkp · 2019-07-03 01:24:26 UTC

above the piston, you should see a green camera icon. when you click on that, it creates an image of your piston which you can attach to this post. You may want to show both full pistons and not partial as you did above

chadmoss · 2019-07-03 01:31:54 UTC

The first piston calls the second…thanks in advance!

Here is the first:

Here is the second:

eibyer · 2019-07-03 02:42:47 UTC

Do you happen to have any logs associated with the second piston?

WCmore · 2019-07-03 03:16:12 UTC

Something tells me on your 2nd piston, lines 24-29 will never execute.
(two triggers won’t happen at the same instant)

Another factor that you have in play is using the same global repeatedly in the same piston. Normally, when a piston first starts up, it immediately checks the globals before actually running any code. From that point on, it will not read from or write to them again until the piston has completed all of it’s tasks.

Because of this, I usually update the global with the latest info as my very last command.
(Placing it earlier in the code is misleading since it won’t actually happen until the end anyways)

If I need to store a variable and immediately access it, I always use a local variable.
(a local variable will be seen & available for use on the very next line of code)

For example, the lines:

Set local to "NewData"
Log local

Will log “NewData”

Yet:

Set @global to "NewData"
Log @global

Will log “OldData”

chadmoss · 2019-07-03 12:48:47 UTC

I do:

7/2/2019, 2:13:21 PM +265ms
+15ms ╔Received event [Home - Hubitat].time/recovery = 1562091201242 with a delay of 23ms, canQueue: false, calledMyself: false
+357ms ║RunTime LockT > 264ms > rtDataT > 91ms > pistonT > 49ms 0 > CE
+430ms ║Runtime (11592 bytes) successfully initialized in 91ms (v0.3.10c.20190531)
+463ms ║╔Execution stage started
+468ms ║╚Execution stage complete. (5ms)
+542ms ╚Event processed successfully (540ms)
+14ms ╔Received event [Home - Hubitat].execute = :efe9f4578572ce6555cc938c09b6024a: with a delay of 435ms, canQueue: true, calledMyself: false
+432ms ╚Event queued (431ms)
7/2/2019, 2:11:08 PM +848ms
+15ms ╔Received event [Home - Hubitat].time = 1562091068298 with a delay of 322ms, canQueue: true, calledMyself: false
+355ms ║RunTime LockT > 497ms > rtDataT > 84ms > pistonT > 49ms 0 > CE
+408ms ║Runtime (11583 bytes) successfully initialized in 84ms (v0.3.10c.20190531)
+512ms ║╔Execution stage started
+779ms ║║Calculating (dynamic) 8 + (integer) 4 >> (dynamic) 12
+790ms ║║Executed virtual command setVariable (1ms)
+806ms ║║Executed virtual command executePiston (3ms)
+815ms ║╚Execution stage complete. (303ms)
+880ms ╚Event processed successfully (879ms)
7/2/2019, 2:07:07 PM +496ms
+3ms ╔Received event [Home - Hubitat].execute = :efe9f4578572ce6555cc938c09b6024a: with a delay of 132852ms, canQueue: false, calledMyself: true
+55ms ║RunTime LockT > 19ms > rtDataT > 35ms > pistonT > 9ms 1 > CE
+69ms ║Runtime (11601 bytes) successfully initialized in 35ms (v0.3.10c.20190531)
+114ms ║╔Execution stage started
+224ms ║║Comparison (enum) closed is (string) open = false (4ms)
+233ms ║║Comparison (enum) open is (string) open = true (4ms)
+240ms ║║Condition #2 evaluated true (115ms)
+245ms ║║Condition group #1 evaluated true (state did not change) (120ms)
+252ms ║║Cancelling statement #5’s schedules…
+501ms ║║Calculating (string) Backdoor - Bedroom Left Sensor + (string) has been open for >> (string) Backdoor - Bedroom Left Sensor has been open for
+515ms ║║Calculating (string) Backdoor - Bedroom Left Sensor has been open for + (string) 8 >> (string) Backdoor - Bedroom Left Sensor has been open for 8
+528ms ║║Calculating (string) Backdoor - Bedroom Left Sensor has been open for 8 + (string) minutes at >> (string) Backdoor - Bedroom Left Sensor has been open for 8 minutes at
+541ms ║║Calculating (string) Backdoor - Bedroom Left Sensor has been open for 8 minutes at + (string) 2:07 P.M. >> (string) Backdoor - Bedroom Left Sensor has been open for 8 minutes at 2:07 P.M.
+554ms ║║Calculating (string) Backdoor - Bedroom Left Sensor has been open for 8 minutes at 2:07 P.M. + (string) !! >> (string) Backdoor - Bedroom Left Sensor has been open for 8 minutes at 2:07 P.M.!!
+781ms ║║Executed virtual command sendPushNotification (213ms)
+791ms ║║Executed virtual command wait (1ms)
+798ms ║║Requesting a wake up for Tue, Jul 2 2019 @ 2:11:08 PM EDT (in 240.0s)
+811ms ║╚Execution stage complete. (698ms)
+819ms ║Setting up scheduled job for Tue, Jul 2 2019 @ 2:11:08 PM EDT (in 239.987s)
+933ms ╚Event processed successfully (931ms)
7/2/2019, 2:07:06 PM +134ms
+14ms ╔Received event [Home - Hubitat].time/recovery = 1562090826122 with a delay of 12ms, canQueue: false, calledMyself: false
+338ms ║RunTime LockT > 253ms > rtDataT > 83ms > pistonT > 48ms 0 > CE
+398ms ║Runtime (11592 bytes) successfully initialized in 84ms (v0.3.10c.20190531)
+438ms ║╔Execution stage started
+442ms ║╚Execution stage complete. (4ms)
+502ms ╚Event processed successfully (500ms)
+14ms ╔Received event [Home - Hubitat].execute = :efe9f4578572ce6555cc938c09b6024a: with a delay of 418ms, canQueue: true, calledMyself: false
+467ms ╚Event queued (465ms)
7/2/2019, 2:04:53 PM +757ms
+14ms ╔Received event [Home - Hubitat].time = 1562090693277 with a delay of 253ms, canQueue: true, calledMyself: false
+384ms ║RunTime LockT > 513ms > rtDataT > 95ms > pistonT > 56ms 0 > CE
+447ms ║Runtime (11583 bytes) successfully initialized in 95ms (v0.3.10c.20190531)
+551ms ║╔Execution stage started
+864ms ║║Calculating (dynamic) 4 + (integer) 4 >> (dynamic) 8
+873ms ║║Executed virtual command setVariable (2ms)
+889ms ║║Executed virtual command executePiston (3ms)
+899ms ║╚Execution stage complete. (347ms)
+978ms ╚Event processed successfully (977ms)
7/2/2019, 2:00:51 PM +985ms
+25ms ╔Received event [Home - Hubitat].execute = :ef52a13ba31842d184b7959ccc88bf30: with a delay of 476ms, canQueue: true, calledMyself: false
+349ms ║RunTime LockT > 446ms > rtDataT > 95ms > pistonT > 60ms 0 > CE
+405ms ║Runtime (10596 bytes) successfully initialized in 95ms (v0.3.10c.20190531)
+451ms ║╔Execution stage started
+561ms ║║Comparison (enum) closed is (string) open = false (5ms)
+570ms ║║Comparison (enum) open is (string) open = true (4ms)
+579ms ║║Cancelling condition #2’s schedules…
+584ms ║║Condition #2 evaluated true (122ms)
+590ms ║║Cancelling condition #1’s schedules…
+595ms ║║Condition group #1 evaluated true (state changed) (132ms)
+602ms ║║Cancelling statement #5’s schedules…
+882ms ║║Calculating (string) Backdoor - Bedroom Left Sensor + (string) has been open for >> (string) Backdoor - Bedroom Left Sensor has been open for
+895ms ║║Calculating (string) Backdoor - Bedroom Left Sensor has been open for + (string) 4 >> (string) Backdoor - Bedroom Left Sensor has been open for 4
+908ms ║║Calculating (string) Backdoor - Bedroom Left Sensor has been open for 4 + (string) minutes at >> (string) Backdoor - Bedroom Left Sensor has been open for 4 minutes at
+921ms ║║Calculating (string) Backdoor - Bedroom Left Sensor has been open for 4 minutes at + (string) 2:00 P.M. >> (string) Backdoor - Bedroom Left Sensor has been open for 4 minutes at 2:00 P.M.
+935ms ║║Calculating (string) Backdoor - Bedroom Left Sensor has been open for 4 minutes at 2:00 P.M. + (string) !! >> (string) Backdoor - Bedroom Left Sensor has been open for 4 minutes at 2:00 P.M.!!
+1164ms ║║Executed virtual command sendPushNotification (215ms)
+1170ms ║║executeTask: Execution time exceeded by 168ms, Waiting for 100ms; lastPause: null
+1281ms ║║Executed virtual command wait (1ms)
+1288ms ║║Requesting a wake up for Tue, Jul 2 2019 @ 2:04:53 PM EDT (in 240.0s)
+1305ms ║╚Execution stage complete. (853ms)
+1313ms ║Setting up scheduled job for Tue, Jul 2 2019 @ 2:04:53 PM EDT (in 239.983s)
+1413ms ╚Event processed successfully (1411ms)
7/2/2019, 1:55:12 PM +395ms
+2ms ╔Starting piston… (v0.3.10c.20190531)
+387ms ║╔Subscribing to devices…
+458ms ║╚Finished subscribing (76ms)
+621ms ║Comparison (enum) closed is (string) open = false (4ms)
+629ms ║Comparison (enum) closed is (string) open = false (3ms)
+637ms ║Comparison (enum) closed is (string) open = false (3ms)
+644ms ║Comparison (enum) closed is (string) open = false (3ms)
+652ms ║Comparison (enum) closed is (string) open = false (4ms)
+661ms ║Comparison (enum) closed is (string) open = false (4ms)
+842ms ╚Piston successfully started (840ms)
7/2/2019, 1:53:23 PM +619ms
+3ms ╔Received event [Home - Hubitat].execute = :efe9f4578572ce6555cc938c09b6024a: with a delay of 133571ms, canQueue: false, calledMyself: true
+69ms ║RunTime LockT > 24ms > rtDataT > 43ms > pistonT > 9ms 0 > CE
+78ms ║Runtime (11435 bytes) successfully initialized in 43ms (v0.3.10c.20190531)
+108ms ║╔Execution stage started
+215ms ║║Comparison (enum) closed is (string) open = false (5ms)
+226ms ║║Comparison (enum) closed is (string) open = false (6ms)

chadmoss · 2019-07-03 12:51:40 UTC

I had trouble with local variables, and that’s why I switched. Those lines seem to be working fine though (at least the last lines that run when the piston is called again) - I might need to tweak some of that but that’s not where my problem seems to be now. Just a thought, can a local variable be set to a global variable value? Maybe that would get me around it…

WCmore · 2019-07-03 13:30:35 UTC

Most definitely yes!
(just remember it reads the global at the moment the piston begins, and writes at the very end)

This is the way I usually code. I use local variables for fast processing, and my final command dumps the local into a global for storage

chadmoss · 2019-07-03 13:35:16 UTC

Good to know! Thanks! This is the first time I have used global variables…

chadmoss · 2019-07-03 14:47:09 UTC

Is this the best way to post the logs?

eibyer · 2019-07-03 15:17:43 UTC

That is strange, it seems like the piston skipped the notification but set the variable and executed the piston @ 7/2/2019, 2:04:53 PM. Have you tried to create a bare bones piston to see if it will execute properly how you expected it? I have not used WC on HE heavily.

chadmoss · 2019-07-03 15:19:04 UTC

That’s what I was thinking…seems to do it every time like that.
What do you mean barebones?

eibyer · 2019-07-03 15:20:29 UTC

Just a simple piston that mimics what you’re doing but with maybe a single device, minimal tasks.

chadmoss · 2019-07-03 20:01:25 UTC

I will have to try and lighten it and create one to test. Thanks.

WCmore · 2019-07-03 20:18:59 UTC

I usually Clear the logs, run a test, and then analyze/post the log. This removes the extra clutter, and makes it easier for us to focus on the issue at hand.