Pistons no longer running properly?

piston
bug

#1

1) Give a description of the problem
Piston that has been working flawlessly has started playing up in the past 2-3 days.

2) What is the expected behaviour?
The piston runs a goodnight routine, turns certain things off then waits 5 minutes before turning on the security.

3) What is happening/not happening?
The piston is running then gets to the wait and waits 5 minutes, like it should. But when it goes to continue on it just keeps saying pending then the trace goes red and counts up to 30 secs, then the piston just re runs again. I’m running the latest version and I’ve tried rebooting my hub to no avail. I haven’t edited this piston for months and if I change the wait time to something like 10 seconds it works. Every other piston I have that has long waits (2 mins and above) do the same thing. Lights arn’t turning off after their delays.

**4) Post a Green Snapshot of the piston.

5) Attach logs after turning logging level to Full
5/31/2020, 10:21:20 PM +605ms
+1ms ╔Received event [Our Home].execute = recovery with a delay of 191ms
+10193ms ║RunTime Analysis CS > 25ms > PS > 10115ms > PE > 53ms > CE
+10194ms ║Piston waited at a semaphore for 10021ms
+10197ms ║Runtime (43463 bytes) successfully initialized in 10115ms (v0.3.110.20191009) (10196ms)
+10198ms ║╔Execution stage started
+10205ms ║║Comparison (string) :ac1857f99f9b757019e3d3a8116b4661: is (string) :ac1857f99f9b757019e3d3a8116b4661: = true (2ms)
+10207ms ║║Condition #219 evaluated true (4ms)
+10208ms ║║Condition group #null evaluated true (state did not change) (6ms)
+10214ms ║║Comparison (boolean) true is (boolean) true = true (1ms)
+10215ms ║║Condition #130 evaluated true (5ms)
+10216ms ║║Condition group #129 evaluated true (state did not change) (6ms)
+10219ms ║║Cancelling statement #236’s schedules…
+10265ms ║║Executed virtual command sendPushNotification (42ms)
+10283ms ║║Comparison (decimal) 24.6 is_greater_than_or_equal_to (integer) 28 = false (1ms)
+10284ms ║║Condition #225 evaluated false (10ms)
+10285ms ║║Condition group #223 evaluated false (state did not change) (11ms)
+10288ms ║║Cancelling statement #241’s schedules…
+10297ms ║║Skipped execution of physical command [Lounge A/C].off([]) because it would make no change to the device. (4ms)
+10298ms ║║Executed [Lounge A/C].off (5ms)
+10308ms ║║Skipped execution of physical command [Microwave].off([]) because it would make no change to the device. (5ms)
+10309ms ║║Executed [Microwave].off (7ms)
+10319ms ║║Skipped execution of physical command [Water Cooler].off([]) because it would make no change to the device. (5ms)
+10320ms ║║Executed [Water Cooler].off (6ms)
+10323ms ║║Cancelling statement #243’s schedules…
+10326ms ║║Executed virtual command wait (0ms)
+10328ms ║║Requesting a wake up for Sun, May 31 2020 @ 10:26:30 PM AEST (in 300.0s)
+10332ms ║╚Execution stage complete. (134ms)
+10333ms ║Setting up scheduled job for Sun, May 31 2020 @ 10:26:30 PM AEST (in 299.995s)
+10346ms ╚Event processed successfully (10345ms)


#2

Okay, after running 13 loops over and over again, the piston finally finished executing. Here is more of my log if it gives any answers. It looks like everything is running properly, even though it isn’t.
I also took a video of the trace so you can see what’s happening:
(https://www.dropbox.com/s/sy8kqcm0twdlw6z/webCoRE%20Dashboard%20-%20Mozilla%20Firefox%202020-05-31%2022-20-35.mp4?dl=0)

5/31/2020, 10:36:00 PM +274ms
+0ms 	╔Received event [Our Home].execute = recovery with a delay of 62ms
+10134ms 	║RunTime Analysis CS > 18ms > PS > 10074ms > PE > 41ms > CE
+10134ms 	║Piston waited at a semaphore for 10014ms
+10137ms 	║Runtime (43465 bytes) successfully initialized in 10074ms (v0.3.110.20191009) (10136ms)
+10138ms 	║╔Execution stage started
+10143ms 	║║Comparison (string) :ac1857f99f9b757019e3d3a8116b4661: is (string) :ac1857f99f9b757019e3d3a8116b4661: = true (1ms)
+10144ms 	║║Condition #219 evaluated true (4ms)
+10145ms 	║║Condition group #null evaluated true (state did not change) (5ms)
+10150ms 	║║Comparison (boolean) false is (boolean) true = false (1ms)
+10152ms 	║║Cancelling condition #130's schedules...
+10152ms 	║║Condition #130 evaluated false (5ms)
+10155ms 	║║Comparison (boolean) false changes_to (boolean) true = false (0ms)
+10157ms 	║║Condition #164 evaluated false (3ms)
+10158ms 	║║Cancelling condition #129's schedules...
+10158ms 	║║Condition group #129 evaluated false (state changed) (11ms)
+10160ms 	║╚Execution stage complete. (23ms)
+10161ms 	╚Event processed successfully (10161ms)
5/31/2020, 10:35:58 PM +428ms
+0ms 	╔Received event [Our Home].execute = recovery with a delay of 106ms
+4901ms 	║RunTime Analysis CS > 19ms > PS > 4841ms > PE > 41ms > CE
+4902ms 	║Piston waited at a semaphore for 4757ms
+4904ms 	║Runtime (43463 bytes) successfully initialized in 4841ms (v0.3.110.20191009) (4903ms)
+4905ms 	║╔Execution stage started
+4910ms 	║║Comparison (string) :ac1857f99f9b757019e3d3a8116b4661: is (string) :ac1857f99f9b757019e3d3a8116b4661: = true (1ms)
+4911ms 	║║Condition #219 evaluated true (4ms)
+4912ms 	║║Condition group #null evaluated true (state did not change) (5ms)
+4917ms 	║║Comparison (boolean) true is (boolean) true = true (2ms)
+4918ms 	║║Cancelling condition #130's schedules...
+4919ms 	║║Condition #130 evaluated true (5ms)
+4920ms 	║║Cancelling condition #129's schedules...
+4920ms 	║║Condition group #129 evaluated true (state changed) (6ms)
+4922ms 	║║Cancelling statement #236's schedules...
+4938ms 	║║Executed virtual command sendPushNotification (12ms)
+4947ms 	║║Comparison (decimal) 24.6 is_greater_than_or_equal_to (integer) 28 = false (1ms)
+4949ms 	║║Condition #225 evaluated false (8ms)
+4950ms 	║║Condition group #223 evaluated false (state did not change) (9ms)
+4952ms 	║║Cancelling statement #241's schedules...
+4959ms 	║║Skipped execution of physical command [Lounge A/C].off([]) because it would make no change to the device. (1ms)
+4959ms 	║║Executed [Lounge A/C].off (3ms)
+4970ms 	║║Skipped execution of physical command [Microwave].off([]) because it would make no change to the device. (5ms)
+4971ms 	║║Executed [Microwave].off (7ms)
+4980ms 	║║Skipped execution of physical command [Water Cooler].off([]) because it would make no change to the device. (4ms)
+4981ms 	║║Executed [Water Cooler].off (6ms)
+4983ms 	║║Cancelling statement #243's schedules...
+4986ms 	║║Executed virtual command wait (1ms)
+4987ms 	║║Requesting a wake up for Sun, May 31 2020 @ 10:41:03 PM AEST (in 300.0s)
+4991ms 	║╚Execution stage complete. (86ms)
+4992ms 	║Setting up scheduled job for Sun, May 31 2020 @ 10:41:03 PM AEST (in 299.997s)
+5004ms 	╚Event processed successfully (5004ms)
5/31/2020, 10:35:58 PM +371ms
+0ms 	╔Received event [Our Home].execute = recovery with a delay of 110ms
+4920ms 	║RunTime Analysis CS > 21ms > PS > 4852ms > PE > 47ms > CE
+4921ms 	║Piston waited at a semaphore for 4759ms
+4923ms 	║Runtime (43463 bytes) successfully initialized in 4852ms (v0.3.110.20191009) (4922ms)
+4924ms 	║╔Execution stage started
+4930ms 	║║Comparison (string) :ac1857f99f9b757019e3d3a8116b4661: is (string) :ac1857f99f9b757019e3d3a8116b4661: = true (1ms)
+4932ms 	║║Condition #219 evaluated true (5ms)
+4933ms 	║║Condition group #null evaluated true (state did not change) (6ms)
+4939ms 	║║Comparison (boolean) true is (boolean) true = true (1ms)
+4940ms 	║║Cancelling condition #130's schedules...
+4941ms 	║║Condition #130 evaluated true (6ms)
+4942ms 	║║Cancelling condition #129's schedules...
+4943ms 	║║Condition group #129 evaluated true (state changed) (8ms)
+4945ms 	║║Cancelling statement #236's schedules...
+4963ms 	║║Executed virtual command sendPushNotification (15ms)
+4975ms 	║║Comparison (decimal) 24.6 is_greater_than_or_equal_to (integer) 28 = false (1ms)
+4976ms 	║║Condition #225 evaluated false (10ms)
+4977ms 	║║Condition group #223 evaluated false (state did not change) (11ms)
+4979ms 	║║Cancelling statement #241's schedules...
+4987ms 	║║Skipped execution of physical command [Lounge A/C].off([]) because it would make no change to the device. (2ms)
+4988ms 	║║Executed [Lounge A/C].off (4ms)
+5000ms 	║║Skipped execution of physical command [Microwave].off([]) because it would make no change to the device. (6ms)
+5001ms 	║║Executed [Microwave].off (8ms)
+5012ms 	║║Skipped execution of physical command [Water Cooler].off([]) because it would make no change to the device. (6ms)
+5013ms 	║║Executed [Water Cooler].off (7ms)
+5015ms 	║║Cancelling statement #243's schedules...
+5018ms 	║║Executed virtual command wait (1ms)
+5019ms 	║║Requesting a wake up for Sun, May 31 2020 @ 10:41:03 PM AEST (in 300.0s)
+5023ms 	║╚Execution stage complete. (99ms)
+5024ms 	║Setting up scheduled job for Sun, May 31 2020 @ 10:41:03 PM AEST (in 299.996s)
+5031ms 	╚Event processed successfully (5031ms)
5/31/2020, 10:36:00 PM +126ms
+1ms 	╔Received event [Our Home].:00c02dcae897081613a7b4837db1597d: = @_GoodnightRunning with a delay of 67ms
+118ms 	║RunTime Analysis CS > 19ms > PS > 60ms > PE > 39ms > CE
+120ms 	║Runtime (43419 bytes) successfully initialized in 60ms (v0.3.110.20191009) (119ms)
+121ms 	║╔Execution stage started
+127ms 	║║Comparison (string) :ac1857f99f9b757019e3d3a8116b4661: is (string) :ac1857f99f9b757019e3d3a8116b4661: = true (1ms)
+128ms 	║║Condition #219 evaluated true (4ms)
+129ms 	║║Condition group #null evaluated true (state did not change) (5ms)
+134ms 	║║Comparison (boolean) false is (boolean) true = false (1ms)
+135ms 	║║Cancelling condition #130's schedules...
+136ms 	║║Condition #130 evaluated false (5ms)
+139ms 	║║Comparison (boolean) false changes_to (boolean) true = false (1ms)
+140ms 	║║Condition #164 evaluated false (3ms)
+141ms 	║║Cancelling condition #129's schedules...
+142ms 	║║Condition group #129 evaluated false (state changed) (11ms)
+144ms 	║╚Execution stage complete. (23ms)
+145ms 	╚Event processed successfully (145ms)
5/31/2020, 10:35:53 PM +85ms
+0ms 	╔Received event [Our Home].time = 1590928332986 with a delay of 220098ms
+162ms 	║RunTime Analysis CS > 23ms > PS > 96ms > PE > 44ms > CE
+165ms 	║Runtime (43388 bytes) successfully initialized in 96ms (v0.3.110.20191009) (163ms)
+166ms 	║╔Execution stage started
+184ms 	║║Cancelling statement #229's schedules...
+196ms 	║║Skipped execution of physical command [Front Living Light].off([]) because it would make no change to the device. (5ms)
+197ms 	║║Executed [Front Living Light].off (7ms)
+434ms 	║║Executed physical command [Gaming Room Light].off() (16ms)
+435ms 	║║Executed [Gaming Room Light].off (18ms)
+446ms 	║║Skipped execution of physical command [Kitchen Light].off([]) because it would make no change to the device. (6ms)
+447ms 	║║Executed [Kitchen Light].off (8ms)
+4829ms 	║║Executed physical command [TV].off() (4379ms)
+4830ms 	║║Executed [TV].off (4379ms)
+4841ms 	║║Comparison (enum) inactive is (string) inactive = true (1ms)
+4844ms 	║║Comparison (enum) inactive is (string) inactive = true (1ms)
+4845ms 	║║Condition #240 evaluated true (13ms)
+4846ms 	║║Condition group #238 evaluated true (state did not change) (14ms)
+4847ms 	║║Cancelling statement #238's schedules...
+4860ms 	║║Skipped execution of physical command [Bedroom Light].off([]) because it would make no change to the device. (6ms)
+4861ms 	║║Executed [Bedroom Light].off (8ms)
+4863ms 	║║Cancelling statement #27's schedules...
+4902ms 	║║Executed virtual command setAlarmSystemStatus (36ms)
+4905ms 	║║Executed virtual command wait (1ms)
+4906ms 	║║Waiting for 2000ms
+6925ms 	║║Executed virtual command sendPushNotification (16ms)
+6929ms 	║║Executed virtual command setVariable (1ms)
+6932ms 	║║Executed virtual command setVariable (1ms)
+6934ms 	║╚Execution stage complete. (6769ms)
+6935ms 	╚Event processed successfully (6935ms)
5/31/2020, 10:27:12 PM +730ms
+0ms 	╔Received event [Our Home].execute = recovery with a delay of 113ms
+161ms 	║RunTime Analysis CS > 26ms > PS > 93ms > PE > 43ms > CE
+164ms 	║Runtime (43383 bytes) successfully initialized in 93ms (v0.3.110.20191009) (163ms)
+165ms 	║╔Execution stage started
+170ms 	║║Comparison (string) :ac1857f99f9b757019e3d3a8116b4661: is (string) :ac1857f99f9b757019e3d3a8116b4661: = true (1ms)
+171ms 	║║Condition #219 evaluated true (4ms)
+172ms 	║║Condition group #null evaluated true (state did not change) (5ms)
+177ms 	║║Comparison (boolean) true is (boolean) true = true (1ms)
+178ms 	║║Condition #130 evaluated true (4ms)
+179ms 	║║Condition group #129 evaluated true (state did not change) (5ms)
+181ms 	║║Cancelling statement #236's schedules...
+201ms 	║║Executed virtual command sendPushNotification (16ms)
+213ms 	║║Comparison (decimal) 24.6 is_greater_than_or_equal_to (integer) 28 = false (1ms)
+215ms 	║║Condition #225 evaluated false (12ms)
+216ms 	║║Condition group #223 evaluated false (state did not change) (13ms)
+218ms 	║║Cancelling statement #241's schedules...
+225ms 	║║Skipped execution of physical command [Lounge A/C].off([]) because it would make no change to the device. (2ms)
+226ms 	║║Executed [Lounge A/C].off (3ms)
+236ms 	║║Skipped execution of physical command [Microwave].off([]) because it would make no change to the device. (5ms)
+237ms 	║║Executed [Microwave].off (6ms)
+248ms 	║║Skipped execution of physical command [Water Cooler].off([]) because it would make no change to the device. (5ms)
+249ms 	║║Executed [Water Cooler].off (6ms)
+251ms 	║║Cancelling statement #243's schedules...
+254ms 	║║Executed virtual command wait (1ms)
+255ms 	║║Requesting a wake up for Sun, May 31 2020 @ 10:32:12 PM AEST (in 300.0s)
+259ms 	║╚Execution stage complete. (95ms)
+260ms 	║Setting up scheduled job for Sun, May 31 2020 @ 10:32:12 PM AEST (in 299.996s)
+269ms 	╚Event processed successfully (269ms)

#3

see


#4

… or summarized here