Piston creating ghost actions?


#1

1) Give a description of the problem
Switch activated twice, yet piston only seems to fire once.

2) What is the expected behavior?
Switch should activate once at 9AM and then not again until 30 mins before sunset.

3) What is happening/not happening?
I have setup a piston to open some curtains at 9AM and then close them again at 30 mins before sunset. Curtain movement is triggered by a fibaro FGS-222 relay turning on. The relay is programmed to auto turn off after 5 seconds. At the programmed time the relay turns on and the curtains open. The problem is that on some days about a minute later the relay turns on again and closes them. This had been working flawlessly for months when this issue started to happen so I re-wrote the piston from scratch to use timers instead if firing “if time is x”. I have not seen any change though.

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


5) Attach any logs (From ST IDE and by turning logging level to Full)

( 20/04/2019, 09:01:35 +672ms
+1ms ╔Received event [Home 2].time = 1555747200000 with a delay of 95672ms
+462ms ║RunTime Analysis CS > 240ms > PS > 184ms > PE > 37ms > CE
+465ms ║Runtime (40360 bytes) successfully initialized in 184ms (v0.3.10a.20190223) (462ms)
+466ms ║╔Execution stage started
+468ms ║╚Execution stage complete. (3ms)
+471ms ║Setting up scheduled job for Sat, Apr 20 2019 @ 7:03:00 PM BST (in 36083.858s), with 2 more jobs pending
+482ms ╚Event processed successfully (482ms)
20/04/2019, 09:01:07 +246ms
+1ms ╔Received event [Home 2].execute = recovery with a delay of 61ms
+95ms ║RunTime Analysis CS > 20ms > PS > 39ms > PE > 36ms > CE
+98ms ║Runtime (40351 bytes) successfully initialized in 39ms (v0.3.10a.20190223) (96ms)
+99ms ║╔Execution stage started
+120ms ║║Condition #16 evaluated false (7ms)
+121ms ║║Condition group #15 evaluated false (state did not change) (9ms)
+124ms ║╚Execution stage complete. (25ms)
+127ms ║Setting up scheduled job for Sat, Apr 20 2019 @ 7:03:00 PM BST (in 36112.628s), with 2 more jobs pending
+138ms ╚Event processed successfully (138ms)
20/04/2019, 09:00:52 +757ms
+1ms ╔Received event [Home 2].time/recovery = 1555747252756 with a delay of 1ms
+453ms ║RunTime Analysis CS > 243ms > PS > 166ms > PE > 43ms > CE
+455ms ║Runtime (40365 bytes) successfully initialized in 166ms (v0.3.10a.20190223) (453ms)
+457ms ║╔Execution stage started
+482ms ║║Comparison (boolean) true is (boolean) true = true (3ms)
+484ms ║║Condition #3 evaluated true (9ms)
+486ms ║║Condition group #2 evaluated true (state did not change) (10ms)
+489ms ║║Cancelling statement #6's schedules...
+14322ms ║║Executed physical command [Lounge Curtain Motor].on() (13828ms)
+14323ms ║║Executed [Lounge Curtain Motor].on (13831ms)
+14328ms ║╚Execution stage complete. (13871ms)
+14331ms ║Setting up scheduled job for Sat, Apr 20 2019 @ 7:03:00 PM BST (in 36112.913s), with 2 more jobs pending
+14341ms ╚Event processed successfully (14341ms)
20/04/2019, 09:00:55 +727ms
+1ms ╔Received event [Home 2].execute = recovery with a delay of 56ms
+7357ms ║RunTime Analysis CS > 17ms > PS > 7303ms > PE > 36ms > CE
+7358ms ║Piston waited at a semaphore for 7262ms
+7360ms ║Runtime (40426 bytes) successfully initialized in 7303ms (v0.3.10a.20190223) (7358ms)
+7361ms ║╔Execution stage started
+7382ms ║║Condition #16 evaluated false (7ms)
+7384ms ║║Condition group #15 evaluated false (state did not change) (9ms)
+7386ms ║╚Execution stage complete. (25ms)
+7389ms ║Setting up scheduled job for Sat, Apr 20 2019 @ 9:00:00 AM BST (in 1s), with 2 more jobs pending
+7398ms ╚Event processed successfully (7398ms)

Here is the ST event log for the device.

My thoughts are that this may have something to do with the last section starting and the large delay of 95672ms ?

Any help appreciated.


#2

I see your piston is only turning on the light. The event log shows two off commands were sent in the logs you attached. Do you have any routine, Smart light rule, custom Automation or piston that turns the light off?


#3

The Fibaro module is programmed to turn off automatically after 5 seconds. What you see in the logs is the result of this auto-off just as you would if it were turned off via a local switch. I am lost as to why it should turn on a second time when I can’t see that in the webcore logs. There is nothing else that would cause it to turn on.


#4

I think if you increase the auto-turn off it should solve the problem. (12 seconds or more)


#5

Thanks. I have made that adjustment. Were you thinking that Webcore was seeing the switch as off, thinking it hadn’t tuned it on and issuing a second instruction?


#6

Well, I was just trying to rule that out. WebCoRE has approximately a ten second timeout for semaphore delays, so by increasing the auto-off to 12 seconds or more, we will know for sure.


#7

Nope, didn’t fix it. :frowning:

Here is the log sequence from this morning. The additional events after the piston completes is on action and schedules the next one are a bit baffling. Especially the long delay of 82031ms?

22/04/2019, 09:01:22 +32ms
+0ms ╔Received event [Home 2].time = 1555920000000 with a delay of 82031ms
+527ms ║RunTime Analysis CS > 321ms > PS > 159ms > PE > 47ms > CE
+530ms ║Runtime (40359 bytes) successfully initialized in 159ms (v0.3.10a.20190223) (528ms)
+532ms ║╔Execution stage started
+535ms ║╚Execution stage complete. (3ms)
+537ms ║Setting up scheduled job for Mon, Apr 22 2019 @ 7:06:00 PM BST (in 36277.432s), with 2 more jobs pending
+549ms ╚Event processed successfully (550ms)
22/04/2019, 09:01:02 +588ms
+1ms ╔Received event [Home 2].execute = recovery with a delay of 65ms
+94ms ║RunTime Analysis CS > 19ms > PS > 39ms > PE > 36ms > CE
+97ms ║Runtime (40350 bytes) successfully initialized in 39ms (v0.3.10a.20190223) (95ms)
+98ms ║╔Execution stage started
+119ms ║║Condition #16 evaluated false (7ms)
+120ms ║║Condition group #15 evaluated false (state did not change) (9ms)
+123ms ║╚Execution stage complete. (25ms)
+126ms ║Setting up scheduled job for Mon, Apr 22 2019 @ 7:06:00 PM BST (in 36297.287s), with 2 more jobs pending
+136ms ╚Event processed successfully (136ms)
22/04/2019, 09:00:43 +834ms
+0ms ╔Received event [Home 2].time/recovery = 1555920043833 with a delay of 0ms
+520ms ║RunTime Analysis CS > 201ms > PS > 283ms > PE > 36ms > CE
+523ms ║Runtime (40364 bytes) successfully initialized in 283ms (v0.3.10a.20190223) (521ms)
+524ms ║╔Execution stage started
+547ms ║║Comparison (boolean) true is (boolean) true = true (2ms)
+549ms ║║Condition #3 evaluated true (7ms)
+550ms ║║Condition group #2 evaluated true (state did not change) (9ms)
+553ms ║║Cancelling statement #6's schedules...
+18594ms ║║Executed physical command [Lounge Curtain Motor].on() (18036ms)
+18596ms ║║Executed [Lounge Curtain Motor].on (18040ms)
+18602ms ║╚Execution stage complete. (18079ms)
+18605ms ║Setting up scheduled job for Mon, Apr 22 2019 @ 7:06:00 PM BST (in 36297.562s), with 2 more jobs pending
+18614ms ╚Event processed successfully (18615ms)
22/04/2019, 09:00:46 +195ms
+0ms ╔Received event [Home 2].execute = recovery with a delay of 66ms
+7933ms ║RunTime Analysis CS > 18ms > PS > 7872ms > PE > 43ms > CE
+7934ms ║Piston waited at a semaphore for 7835ms
+7937ms ║Runtime (40425 bytes) successfully initialized in 7872ms (v0.3.10a.20190223) (7935ms)
+7938ms ║╔Execution stage started
+7960ms ║║Condition #16 evaluated false (8ms)
+7962ms ║║Condition group #15 evaluated false (state did not change) (9ms)
+7964ms ║╚Execution stage complete. (27ms)
+7967ms ║Setting up scheduled job for Mon, Apr 22 2019 @ 9:00:00 AM BST (in 1s), with 2 more jobs pending
+7976ms ╚Event processed successfully (7976ms)

#8

To make sense of the logs, it helps if you post the latest green snapshot with TRACE turned on.

This shows grey numbers at the end of each line
temp
which coincide with the condition numbers found in your log.


#9

Here you go.


#10

Thanks! It seems you have some horrendous lag in your home network… A 9:00 event happened 43 seconds late, and then 46, 62, and finally 82 seconds later than the scheduled time. This is an indication that there is too much traffic passing thru your SmartThings hub. (there’s likely programming in another piston that is causing spam around 9AM)

Two thoughts come to mind:
(1) Change the 9 o’clock event a few minutes (in either direction) so it runs when no other piston is scheduled to run
(2) Pause this piston, wait ten seconds, and then resume it. This one time thing should delete (clear) out any redundancies in the scheduled wakeups.


#11

Thanks for the help. Curiously it worked perfectly this morning without any changes. Here is the single log entry from 9AM. I will do the pause and see what else could be going on at 9AM.

23/04/2019, 08:59:59 +163ms
+0ms ╔Received event [Home 2].time = 1556006400000 with a delay of -838ms
+307ms ║RunTime Analysis CS > 86ms > PS > 153ms > PE > 68ms > CE
+311ms ║Runtime (40357 bytes) successfully initialized in 153ms (v0.3.10a.20190223) (308ms)
+312ms ║╔Execution stage started
+336ms ║║Comparison (boolean) true is (boolean) true = true (2ms)
+339ms ║║Condition #3 evaluated true (7ms)
+341ms ║║Condition group #2 evaluated true (state did not change) (10ms)
+345ms ║║Cancelling statement #6's schedules...
+19245ms ║║Executed physical command [Lounge Curtain Motor].on() (18896ms)
+19247ms ║║Executed [Lounge Curtain Motor].on (18900ms)
+19251ms ║╚Execution stage complete. (18939ms)
+19254ms ║Setting up scheduled job for Tue, Apr 23 2019 @ 7:08:00 PM BST (in 36461.584s), with 2 more jobs pending
+19262ms ╚Event processed successfully (19262ms)

#12

Unfortunately I am still having intermittent issues with this. The piston fired twice this morning, causing the switch to activate twice. As you can see from the log below there were 3 event sequences around 9AM. When it works OK there is only 1 event sequence that closely resembles the middle one. I think the problem is related to the massive semaphore delay of 9268ms. I suspect somewhere a part of the code recovers after this time and because my requested action is momentary it ‘thinks’ the event has not run and runs it again?

09/05/2019, 09:01:15 +248ms
+1ms ╔Received event [Home 2].execute = recovery with a delay of 60ms
+98ms ║RunTime Analysis CS > 15ms > PS > 44ms > PE > 39ms > CE
+101ms ║Runtime (40350 bytes) successfully initialized in 44ms (v0.3.10a.20190223) (98ms)
+102ms ║╔Execution stage started
+124ms ║║Condition #16 evaluated false (7ms)
+125ms ║║Condition group #15 evaluated false (state did not change) (10ms)
+129ms ║╚Execution stage complete. (28ms)
+131ms ║Setting up scheduled job for Thu, May 9 2019 @ 7:33:00 PM BST (in 37904.622s), with 2 more jobs pending
+144ms ╚Event processed successfully (143ms)
09/05/2019, 09:00:58 +657ms
+1ms ╔Received event [Home 2].time/recovery = 1557388858656 with a delay of 0ms
+584ms ║RunTime Analysis CS > 340ms > PS > 206ms > PE > 39ms > CE
+587ms ║Runtime (40364 bytes) successfully initialized in 206ms (v0.3.10a.20190223) (584ms)
+589ms ║╔Execution stage started
+619ms ║║Comparison (boolean) true is (boolean) true = true (2ms)
+621ms ║║Condition #3 evaluated true (9ms)
+623ms ║║Condition group #2 evaluated true (state did not change) (11ms)
+627ms ║║Cancelling statement #6’s schedules…
+16410ms ║║Executed physical command [Lounge Curtain Motor].on() (15777ms)
+16412ms ║║Executed [Lounge Curtain Motor].on (15781ms)
+16419ms ║╚Execution stage complete. (15830ms)
+16424ms ║Setting up scheduled job for Thu, May 9 2019 @ 7:33:00 PM BST (in 37904.921s), with 2 more jobs pending
+16432ms ╚Event processed successfully (16432ms)
09/05/2019, 09:00:59 +929ms
+1ms ╔Received event [Home 2].execute = recovery with a delay of 66ms
+9368ms ║RunTime Analysis CS > 18ms > PS > 9311ms > PE > 39ms > CE
+9369ms ║Piston waited at a semaphore for 9268ms
+9372ms ║Runtime (40425 bytes) successfully initialized in 9311ms (v0.3.10a.20190223) (9370ms)
+9373ms ║╔Execution stage started
+9395ms ║║Condition #16 evaluated false (8ms)
+9396ms ║║Condition group #15 evaluated false (state did not change) (10ms)
+9399ms ║╚Execution stage complete. (27ms)
+9402ms ║Setting up scheduled job for Thu, May 9 2019 @ 9:00:00 AM BST (in 1s), with 2 more jobs pending
+9411ms ╚Event processed successfully (9411ms)


#13

In your latest log, I only see one command issued to Lounge Curtain Motor…
(although it stalled 16 seconds before sending)

Maybe repost a green snapsnot that matches the log?


#14

Here is a green snapshot and a screenshot from the classic app showing the rogue firing. You can ignore the events at 9:47 as this was me manually opening the curtains.



#15

Did you follow my earlier advice to delay your other programming (auto-turn-off) ???
Ideally, it should be after this piston runs to completion.


Edit:
I just noticed that you have not touched this piston in six weeks, so I am going to drop out on this one.
(if you aren’t trying to find a resolution, they why should I?)


#16

Not sure why you feel that way!

In answer you your questions, yes, I did increase the auto-turn-off, pause the piston and it seemed to help. I also tried to reduce the load on the hub by investigating other pistons and automations (reducing where possible).

The piston is pretty simple, has not changed much in many months and up until recently was working fine. In addition to increasing the auto-off I also made changes elsewhere to see if anything else could be causing this.

This is a very intermittent issue and things have been a lot more reliable reliable recently. In fact, based on the logs I think the today is the first time since April 29th. When it works correctly, the additional event sequences (timed this morning at 09:00:59 and 09:01:15) do not occur. I think this is what is causing the extra “on” command to be sent, but I have no idea how to fix it and did not want to go making changes to the piston without some guidance as to what was causing this.


#17

I apologize if I mis-read your intentions. This has happened to me a few times in the past, and I really try to learn from my mistakes when moving forward.

If you are serious about getting this to work smoothly, I would try my initial two ideas. (slightly more dramatic this time)

(1) In your piston, change the 9:00 a couple of minutes in either direction. (IE: 8:58 or 9:02) This (hopefully) means the piston will fire when no other piston is active.

(2) Increase the delay for the auto-shutoff command (not seen here) well after the piston has completed all of it’s tasks. I originally said 12 seconds or more, but for troubleshooting, it might be best to make it longer than a minute. (since your piston is so s-l-o-w to fire)
IE: 09:01:22 Received event [Home 2].time

To be honest, I would probably move the auto-shutoff programming to this piston here in webCoRE, since you will have more control over it, but it’s possible that we can resolve this without taking this last step.


For future reference, as far as logs go, the log in webCoRE shows what webCoRE received and sent, which is very helpful when diagnosing a piston. The logs shown in the ST app don’t show me enough information to be helpful to me… but the listed events in the IDE can be quite revealing:
account.smartthings.com > My Devices > Lounge Curtain Motor > List Events


#18

Firstly, thanks for helping on this.

Here is the IDE event log for the device for the time of the last issue.

2019-05-09 9:01:31.627 AM BST
1 day ago
DEVICE switch off Lounge Curtain Motor switch is off
2019-05-09 9:01:16.279 AM BST
1 day ago
DEVICE switch on Lounge Curtain Motor switch is on
2019-05-09 9:00:59.491 AM BST
1 day ago
APP_COMMAND on New Curtain Auto sent on command to Lounge Curtain Motor
2019-05-09 9:00:39.917 AM BST
1 day ago
DEVICE switch off Lounge Curtain Motor switch is off
2019-05-09 9:00:24.892 AM BST
1 day ago
DEVICE switch on Lounge Curtain Motor switch is on
2019-05-09 9:00:00.686 AM BST
1 day ago
APP_COMMAND on New Curtain Auto sent on command to Lounge Curtain Motor

The device is a child device and is Switch 1 on a Fibaro FGS-222 relay. The relay has an auto-timer function inbuilt that was set to 15 seconds during this sequence. The off events you see are simply the DTH reading the status of the switch changing to off by the inbuilt timer.

There were no other pistons timed for 9AM and I double checked no other hourly pistons could fire at 9AM. I’ll go ahead and adjust the time to 08:58 anyway. I have also extended the auto-off timer to 2 minutes to give the piston plenty of time to complete.


#19

My fingers are crossed…

I wonder why it takes 17-24 seconds for the motor to turn on after the command is sent?!?


#20

Have you tried putting your ‘Time’ inside the IF statement? This is what I do, and I’ve yet to have issues with timing.

Example: