All "waits" PENDING

#1

1) Give a description of the problem
No actions being completed after a wait command. I created this very simple piston to test but getting same result in any piston with a “wait” command.
2) What is the expected behaviour?
Switch will turn off after wait
3) What is happening/not happening?
Switch staying on, red PENDING shows in flow.
4) Post a Green Snapshot of the piston![image|45x37](upload://xK8W

jpeg
Unknown.jpeg.png1178×485 61.9 KB
wMCzoDkDrcB1Jf27yjtZ9bq.png)
(UPLOAD YOUR IMAGE HERE)

5) Attach logs after turning logging level to Full
5/30/2020, 12:48:32 PM +532ms
+1ms ╔Received event [Porch Lights Back Porch Lights].switch = on with a delay of 43ms
+62ms ║RunTime Analysis CS > 14ms > PS > 29ms > PE > 19ms > CE
+65ms ║Runtime (36527 bytes) successfully initialized in 29ms (v0.3.110.20191009) (62ms)
+66ms ║╔Execution stage started
+73ms ║║Comparison (enum) on is (string) on = true (1ms)
+75ms ║║Cancelling condition #2’s schedules…
+76ms ║║Condition #2 evaluated true (5ms)
+77ms ║║Cancelling condition #1’s schedules…
+77ms ║║Condition group #1 evaluated true (state changed) (7ms)
+79ms ║║Cancelling statement #3’s schedules…
+84ms ║║Executed virtual command [Porch Lights Back Porch Lights].wait (0ms)
+85ms ║║Requesting a wake up for Sat, May 30 2020 @ 12:48:52 PM EDT (in 20.0s)
+89ms ║╚Execution stage complete. (24ms)
+90ms ║Setting up scheduled job for Sat, May 30 2020 @ 12:48:52 PM EDT (in 19.996s)
+97ms ╚Event processed successfully (97ms)
5/30/2020, 12:48:25 PM +502ms
+1ms ╔Received event [Porch Lights Back Porch Lights].switch = off with a delay of 64ms
+96ms ║RunTime Analysis CS > 21ms > PS > 52ms > PE > 23ms > CE
+98ms ║Runtime (36522 bytes) successfully initialized in 52ms (v0.3.110.20191009) (95ms)
+98ms ║╔Execution stage started
+105ms ║║Comparison (enum) off is (string) on = false (1ms)
+107ms ║║Cancelling condition #2’s schedules…
+108ms ║║Condition #2 evaluated false (5ms)
+109ms ║║Cancelling condition #1’s schedules…
+109ms ║║Condition group #1 evaluated false (state changed) (7ms)
+111ms ║╚Execution stage complete. (13ms)
+112ms ╚Event processed successfully (112ms)
5/30/2020, 12:48:18 PM +564ms
+1ms ╔Starting piston… (v0.3.110.20191009)
+192ms ║╔Subscribing to devices…
+221ms ║║Subscribing to Porch Lights Back Porch Lights.switch…
+304ms ║╚Finished subscribing (129ms)
+334ms ║Comparison (enum) on is (string) on = true (1ms)
+346ms ╚Piston successfully started (345ms)

REMOVE BELOW AFTER READING
If a solution is found for your question then please mark the post as the solution.

Pistons no longer running properly?
#3

It appears that you did not let your log run long enough…

12:48:18 PM = Piston saved
12:48:25 PM = Switch off, Do nothing
12:48:32 PM = Switch on = Setting up scheduled job for 12:48:52 PM
12:48:52 PM = No log present

#4

Noob.
This better?
|5/30/2020, 1:48:07 PM +879ms|
|+2ms|╔Received event [Porch Lights Back Porch Lights].switch = on with a delay of 57ms|
|+262ms|║RunTime Analysis CS > 19ms > PS > 213ms > PE > 30ms > CE|
|+264ms|║Runtime (36618 bytes) successfully initialized in 213ms (v0.3.110.20191009) (262ms)|
|+265ms|║╔Execution stage started|
|+273ms|║║Comparison (enum) on is (string) on = true (1ms)|
|+275ms|║║Cancelling condition #2’s schedules…|
|+276ms|║║Condition #2 evaluated true (5ms)|
|+277ms|║║Cancelling condition #1’s schedules…|
|+277ms|║║Condition group #1 evaluated true (state changed) (8ms)|
|+279ms|║║Cancelling statement #3’s schedules…|
|+284ms|║║Executed virtual command [Porch Lights Back Porch Lights].wait (1ms)|
|+285ms|║║Requesting a wake up for Sat, May 30 2020 @ 1:48:28 PM EDT (in 20.0s)|
|+294ms|║╚Execution stage complete. (29ms)|
|+295ms|║Setting up scheduled job for Sat, May 30 2020 @ 1:48:28 PM EDT (in 19.991s)|
|+304ms|╚Event processed successfully (304ms)|

#5

Again, this log shows the turn on, and the schedule set… but it does not show the wakeup event.

We need to see both… The initial event, as well as when it wakes up 20 seconds later.

#6

I assumed the issue was that the wake up didn’t happen. PENDING normally appears briefly at the end of the wait countdown in a trace, when it is due.

#7

Correct-it stays PENDING and the next event never happens.

#8

It stays PENDING.
The wakeup event never happens.
I posted everything that is in the log.

#9

Can you test again doing these steps please?

  • Clear your current log
  • Turn off the trigger switch
  • Wait 3+ seconds (to give the piston time to settle down)
  • Turn on the trigger switch
  • Wait a full minute
  • Turn off the trigger switch manually (to force a log update)
  • Wait 10+ seconds (to give the log time to settle down)
  • Copy and paste the entire log here
#11

I am having the same problem with all my wait statements.

#12

Oh, I’m so glad I looked on here today. I’m having the same issues with ‘Wait’ today.

#13

There is nothing on the ST status page, but there are several reports of strange behaviour that could be put down to timer events going awol, so I am tempted to think one of the hamsters may have tripped over.

#14

Yup, same for me. All my pistons that rely on time in some way, either “has not changed for 5 seconds” or “wait 2 seconds” are all resulting in pending waits that never trigger, all timeout, and all result in recovery executions of the pistons after some long timeout. These are pistons that worked properly for 2 years running. Something must have changed in webCoRe today.

#15

5/30/2020, 7:15:29 PM +473ms
+1ms ╔Received event [Charles St].execute = recovery with a delay of 43ms
+74ms ║RunTime Analysis CS > 20ms > PS > 40ms > PE > 13ms > CE
+76ms ║Runtime (36596 bytes) successfully initialized in 40ms (v0.3.110.20191009) (74ms)
+76ms ║╔Execution stage started
+87ms ║║Comparison (enum) off is (string) on = false (1ms)
+88ms ║║Cancelling condition #2’s schedules…
+89ms ║║Condition #2 evaluated false (9ms)
+90ms ║║Cancelling condition #1’s schedules…
+91ms ║║Condition group #1 evaluated false (state changed) (10ms)
+103ms ║║Skipped execution of physical command [Porch Lights Back Porch Lights].off([]) because it would make no change to the device. (3ms)
+104ms ║║Executed [Porch Lights Back Porch Lights].off (4ms)
+106ms ║╚Execution stage complete. (30ms)
+107ms ╚Event processed successfully (107ms)
5/30/2020, 7:15:29 PM +290ms
+1ms ╔Received event [Porch Lights Back Porch Lights].switch = off with a delay of 50ms
+80ms ║RunTime Analysis CS > 19ms > PS > 46ms > PE > 15ms > CE
+82ms ║Runtime (36610 bytes) successfully initialized in 46ms (v0.3.110.20191009) (80ms)
+83ms ║╔Execution stage started
+91ms ║║Comparison (enum) off is (string) on = false (1ms)
+92ms ║║Cancelling condition #2’s schedules…
+93ms ║║Condition #2 evaluated false (6ms)
+94ms ║║Cancelling condition #1’s schedules…
+95ms ║║Condition group #1 evaluated false (state changed) (7ms)
+108ms ║║Skipped execution of physical command [Porch Lights Back Porch Lights].off([]) because it would make no change to the device. (3ms)
+109ms ║║Executed [Porch Lights Back Porch Lights].off (5ms)
+111ms ║╚Execution stage complete. (28ms)
+112ms ╚Event processed successfully (112ms)
5/30/2020, 7:13:51 PM +732ms
+1ms ╔Received event [Porch Lights Back Porch Lights].switch = on with a delay of 38ms
+188ms ║RunTime Analysis CS > 14ms > PS > 164ms > PE > 10ms > CE
+190ms ║Runtime (36618 bytes) successfully initialized in 164ms (v0.3.110.20191009) (188ms)
+191ms ║╔Execution stage started
+199ms ║║Comparison (enum) on is (string) on = true (2ms)
+200ms ║║Cancelling condition #2’s schedules…
+202ms ║║Condition #2 evaluated true (6ms)
+203ms ║║Cancelling condition #1’s schedules…
+203ms ║║Condition group #1 evaluated true (state changed) (8ms)
+205ms ║║Cancelling statement #3’s schedules…
+210ms ║║Executed virtual command [Porch Lights Back Porch Lights].wait (0ms)
+211ms ║║Requesting a wake up for Sat, May 30 2020 @ 7:14:11 PM EDT (in 20.0s)
+215ms ║╚Execution stage complete. (23ms)
+216ms ║Setting up scheduled job for Sat, May 30 2020 @ 7:14:11 PM EDT (in 19.996s)
+226ms ╚Event processed successfully (225ms)
5/30/2020, 7:13:42 PM +957ms
+1ms ╔Received event [Charles St].execute = recovery with a delay of 47ms
+69ms ║RunTime Analysis CS > 19ms > PS > 39ms > PE > 11ms > CE
+71ms ║Runtime (36602 bytes) successfully initialized in 39ms (v0.3.110.20191009) (70ms)
+72ms ║╔Execution stage started
+82ms ║║Comparison (enum) off is (string) on = false (1ms)
+84ms ║║Condition #2 evaluated false (7ms)
+84ms ║║Condition group #1 evaluated false (state did not change) (9ms)
+86ms ║╚Execution stage complete. (14ms)
+87ms ╚Event processed successfully (87ms)
5/30/2020, 7:13:42 PM +764ms
+1ms ╔Received event [Porch Lights Back Porch Lights].switch = off with a delay of 47ms
+85ms ║RunTime Analysis CS > 22ms > PS > 50ms > PE > 14ms > CE
+87ms ║Runtime (36610 bytes) successfully initialized in 50ms (v0.3.110.20191009) (85ms)
+88ms ║╔Execution stage started
+96ms ║║Comparison (enum) off is (string) on = false (1ms)
+97ms ║║Cancelling condition #2’s schedules…
+98ms ║║Condition #2 evaluated false (6ms)
+99ms ║║Cancelling condition #1’s schedules…
+100ms ║║Condition group #1 evaluated false (state changed) (8ms)
+114ms ║║Skipped execution of physical command [Porch Lights Back Porch Lights].off([]) because it would make no change to the device. (3ms)
+115ms ║║Executed [Porch Lights Back Porch Lights].off (5ms)
+117ms ║╚Execution stage complete. (29ms)
+118ms ╚Event processed successfully (118ms)

Clear

Full

#16

Same problems happening here as described above. It started some weird behaviors and conflicts with multiple things trying to catch up at once. so I had to disable webcoRE for now.

#17

Thanks for taking the time, @fredfon… It seems your issue is similar to the others in this thread…

It set a wakeup for 7:14:11 PM EDT (in 20s), but it was 78 seconds late, as seen in the “recovery” at 7:15:29 PM.

I have absolutely no proof for this, but every time I see delayed WAITs globally, I imagine that some newbie recently created a looping piston… Which could inadvertently, initiate a DoS attack on the SmartThings server… (thereby impacting all of us on the same shard)

#18

Hi WCmore,

Is there anyone we should alert or tag? I’m curious for the future, when things get bad like this, what adequate next steps would be.

As always, thank you for your expertise.

#19

Well, to be honest… When everyone is having the same issue, I usually do not make a single change to any piston.

It likely means either a temporary hiccup, or SmartThings is changing something on their end, and hopefully, we’ll return to our Smart home shortly.

(although it might be wise to post errors to the forum so the ST programmer(s) can get nearly instant feedback to their latest changes)

#20

I did end up changing one piston, and made it robust enough to be executed in less time, and being able to pick back up from a recovery. But that was before I realized it was a webCoRe-wide issue, or rather not my piston’s fault. At this point, I had to pause any delay, wait, or time dependant piston.

#21

Thank You for looking at this.

#22

I can concur that none of my pistons with a ‘wait’ in them (which is pretty much all of them) are working properly. Since it’s affecting many people, I’m not going to change anything to try to fix it on my end but hope something that seems to be fairly large and obvious won’t take long to resolve.