Piston triggered but didn't run correctly

guxdude · 2020-03-29 08:03:00 UTC

1) Give a description of the problem
I have a piston that when I go to bed is sup[posed to turn off all the lights. Sometimes, it doesn’t respond correctly top the sim switch change.

2) What is the expected behaviour?
Turn off the lights

3) What is happening/not happening?
Nothing happened. Has anyone seen this? The event is seen but the commands don’t execute.

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

5) Attach logs after turning logging level to Full

Sorry, I didn’t have logging set to full but didn’t expect to catch an error like this. You can see, it got the switch on event and thinks it did everything but obviously didn’t since there were no log messages (see the night before).

3/29/2020, 12:54:02 AM +438ms
+0ms	╔Received event [LV Goodnight].switch = on with a delay of 76ms
+83ms	╚Event processed successfully (83ms)
3/28/2020, 1:45:40 AM +366ms
+1ms	╔Received event [LV Goodnight].switch = off with a delay of 80ms
+89ms	╚Event processed successfully (89ms)
3/28/2020, 1:45:39 AM +657ms
+1ms	╔Received event [LV Goodnight].switch = on with a delay of 114ms
+89ms	║Turning off all the lights...
+600ms	║Sleep tight. Everything is turned off. Sat, Mar 28 2020 @ 1:45:40 AM PDT
+641ms	╚Event processed successfully (641ms)

WCmore · 2020-03-30 06:27:55 UTC

(It feels wrong to say that) hopefully it will act up with logging set to Full…
If it does, please also post a fresh snapshot with Trace turned on.

orangebucket · 2020-03-30 09:10:05 UTC

I’d rather formed the impression, rightly or wrongly, that webCoRE pistons cached events so they could make their own judgement on whether a device attribute had changed. So the obvious thought that the piston believed the switch was already on and so didn’t see the on event as a change is rather contradicted by the lack of any other stray events. Definitely one for a full trace if possible. Also is the ‘sim switch’ a Simulated Switch, a Virtual Switch, or something else, and does its event history match up with what the piston logs show?

guxdude · 2020-03-30 14:17:51 UTC

OK, it happened again last night. Didn’t run the first time but did the second. Based on the logs, @orangebucket was correct that it didn’t believe the state changed (see run at 1:10). This doesn’t make sense, however, based on another piston I have that always makes sure the switch is off (see picture showing device history). I double checked and I used a simulated switch.

3/30/2020, 1:13:05 AM +439ms
+2ms ╔Received event [LV Goodnight].switch = off with a delay of 154ms
+105ms ║RunTime Analysis CS &gt; 27ms &gt; PS &gt; 49ms &gt; PE &gt; 29ms &gt; CE
+108ms ║Runtime (43476 bytes) successfully initialized in 49ms (v0.3.110.20191009) (105ms)
+108ms ║╔Execution stage started
+116ms ║║Comparison (enum) off changes_to (string) on = false (0ms)
+118ms ║║Cancelling condition #2's schedules...
+118ms ║║Condition #2 evaluated false (6ms)
+122ms ║║Comparison (string) switch is (string) test = false (1ms)
+123ms ║║Condition #15 evaluated false (4ms)
+124ms ║║Cancelling condition #1's schedules...
+125ms ║║Condition group #1 evaluated false (state changed) (13ms)
+127ms ║╚Execution stage complete. (19ms)
+128ms ╚Event processed successfully (128ms)
3/30/2020, 1:13:03 AM +670ms
+1ms ╔Received event [LV Goodnight].switch = on with a delay of 84ms
+71ms ║RunTime Analysis CS &gt; 16ms &gt; PS &gt; 35ms &gt; PE &gt; 19ms &gt; CE
+73ms ║Runtime (43476 bytes) successfully initialized in 35ms (v0.3.110.20191009) (71ms)
+74ms ║╔Execution stage started
+81ms ║║Comparison (enum) on changes_to (string) on = true (1ms)
+82ms ║║Cancelling condition #2's schedules...
+83ms ║║Condition #2 evaluated true (6ms)
+84ms ║║Cancelling condition #1's schedules...
+85ms ║║Condition group #1 evaluated true (state changed) (8ms)
+87ms ║║Cancelling statement #12's schedules...
+91ms ║║Turning off all the lights...
+92ms ║║Executed virtual command log (1ms)
+94ms ║║Cancelling statement #8's schedules...
+483ms ║║Executed physical command [LV Stair Light].on() (385ms)
+484ms ║║Executed [LV Stair Light].on (387ms)
+486ms ║║Cancelling statement #6's schedules...
+976ms ║║Executed physical command [LV Back Patio Lights].off() (479ms)
+976ms ║║Executed [LV Back Patio Lights].off (481ms)
+981ms ║║Skipped execution of physical command [LV Can Lights (Q1)].off([]) because it would make no change to the device. (2ms)
+982ms ║║Executed [LV Can Lights (Q1)].off (4ms)
+986ms ║║Skipped execution of physical command [LV Counter Lights].off([]) because it would make no change to the device. (2ms)
+987ms ║║Executed [LV Counter Lights].off (4ms)
+992ms ║║Skipped execution of physical command [LV Curio Cabinet (2)].off([]) because it would make no change to the device. (2ms)
+992ms ║║Executed [LV Curio Cabinet (2)].off (4ms)
+1520ms ║║Executed physical command [LV Dining Table].off() (526ms)
+1521ms ║║Executed [LV Dining Table].off (527ms)
+1526ms ║║Skipped execution of physical command [LV Drop Lights (Q2)].off([]) because it would make no change to the device. (2ms)
+1527ms ║║Executed [LV Drop Lights (Q2)].off (4ms)
+1532ms ║║Skipped execution of physical command [LV FR Center Fan].off([]) because it would make no change to the device. (3ms)
+1533ms ║║Executed [LV FR Center Fan].off (5ms)
+1537ms ║║Skipped execution of physical command [LV FR Center Light].off([]) because it would make no change to the device. (2ms)
+1538ms ║║Executed [LV FR Center Light].off (4ms)
+1543ms ║║Skipped execution of physical command [LV FR Corner Light].off([]) because it would make no change to the device. (2ms)
+1543ms ║║Executed [LV FR Corner Light].off (3ms)
+1548ms ║║Skipped execution of physical command [LV FR Outlet].off([]) because it would make no change to the device. (3ms)
+1549ms ║║Executed [LV FR Outlet].off (4ms)
+1554ms ║║Skipped execution of physical command [LV Laundry Room Light].off([]) because it would make no change to the device. (2ms)
+1554ms ║║Executed [LV Laundry Room Light].off (4ms)
+1559ms ║║Skipped execution of physical command [LV LED 1].off([]) because it would make no change to the device. (2ms)
+1560ms ║║Executed [LV LED 1].off (3ms)
+1564ms ║║Skipped execution of physical command [LV Living Room outlet].off([]) because it would make no change to the device. (2ms)
+1565ms ║║Executed [LV Living Room outlet].off (4ms)
+1567ms ║║Cancelling statement #3's schedules...
+1573ms ║║Calculating (string) Sleep tight. Everything is turned off. + (string) Mon, Mar 30 2020 @ 1:13:05 AM PDT &gt;&gt; (string) Sleep tight. Everything is turned off. Mon, Mar 30 2020 @ 1:13:05 AM PDT
+1577ms ║║Sleep tight. Everything is turned off. Mon, Mar 30 2020 @ 1:13:05 AM PDT
+1578ms ║║Executed virtual command [LV Goodnight].log (1ms)
+1582ms ║║Calculating (string) Sleep tight. Everything is turned off. + (string) Mon, Mar 30 2020 @ 1:13:05 AM PDT &gt;&gt; (string) Sleep tight. Everything is turned off. Mon, Mar 30 2020 @ 1:13:05 AM PDT
+1585ms ║║Executed virtual command [LV Goodnight].setState (0ms)
+1602ms ║║Executed virtual command [LV Goodnight].setLocationMode (15ms)
+1626ms ║║Executed physical command [LV Goodnight].off() (22ms)
+1627ms ║║Executed [LV Goodnight].off (24ms)
+1629ms ║╚Execution stage complete. (1556ms)
+1630ms ╚Event processed successfully (1630ms)
3/30/2020, 1:12:27 AM +129ms
+1ms ╔Received event [LV Goodnight].switch = off with a delay of 165ms
+117ms ║RunTime Analysis CS &gt; 45ms &gt; PS &gt; 50ms &gt; PE &gt; 22ms &gt; CE
+119ms ║Runtime (43478 bytes) successfully initialized in 50ms (v0.3.110.20191009) (117ms)
+120ms ║╔Execution stage started
+128ms ║║Comparison (enum) off changes_to (string) on = false (1ms)
+129ms ║║Condition #2 evaluated false (5ms)
+133ms ║║Comparison (string) switch is (string) test = false (1ms)
+134ms ║║Condition #15 evaluated false (4ms)
+135ms ║║Condition group #1 evaluated false (state did not change) (11ms)
+136ms ║╚Execution stage complete. (16ms)
+137ms ╚Event processed successfully (137ms)
3/30/2020, 1:10:27 AM +392ms
+1ms ╔Received event [LV Goodnight].switch = on with a delay of 82ms
+81ms ║RunTime Analysis CS &gt; 23ms &gt; PS &gt; 38ms &gt; PE &gt; 20ms &gt; CE
+84ms ║Runtime (43473 bytes) successfully initialized in 38ms (v0.3.110.20191009) (81ms)
+84ms ║╔Execution stage started
+93ms ║║Comparison (enum) on changes_to (string) on = false (0ms)
+94ms ║║Cancelling condition #2's schedules...
+95ms ║║Condition #2 evaluated false (7ms)
+99ms ║║Comparison (string) switch is (string) test = false (2ms)
+100ms ║║Condition #15 evaluated false (4ms)
+101ms ║║Cancelling condition #1's schedules...
+102ms ║║Condition group #1 evaluated false (state changed) (14ms)
+104ms ║╚Execution stage complete. (20ms)
+105ms ╚Event processed successfully (105ms)
3/29/2020, 1:03:43 AM +477ms
+1ms ╔Received event [LV Goodnight].switch = off with a delay of 83ms
+77ms ║RunTime Analysis CS &gt; 22ms &gt; PS &gt; 36ms &gt; PE &gt; 18ms &gt; CE
+79ms ║Runtime (43443 bytes) successfully initialized in 36ms (v0.3.110.20191009) (78ms)
+80ms ║╔Execution stage started
+87ms ║║Comparison (enum) off changes_to (string) on = false (1ms)
+88ms ║║Condition #2 evaluated false (5ms)
+92ms ║║Comparison (string) switch is (string) test = false (1ms)
+93ms ║║Condition #15 evaluated false (4ms)
+94ms ║║Condition group #1 evaluated false (state did not change) (11ms)
+95ms ║╚Execution stage complete. (16ms)
+96ms ╚Event processed successfully (96ms)
3/29/2020, 1:03:41 AM +241ms
+1ms ╔Received event [LV Goodnight].switch = on with a delay of 80ms
+74ms ║RunTime Analysis CS &gt; 18ms &gt; PS &gt; 37ms &gt; PE &gt; 18ms &gt; CE
+76ms ║Runtime (43442 bytes) successfully initialized in 37ms (v0.3.110.20191009) (74ms)
+77ms ║╔Execution stage started
+85ms ║║Comparison (enum) on changes_to (string) on = true (1ms)
+86ms ║║Cancelling condition #2's schedules...
+87ms ║║Condition #2 evaluated true (6ms)
+88ms ║║Cancelling condition #1's schedules...
+89ms ║║Condition group #1 evaluated true (state changed) (8ms)
+91ms ║║Cancelling statement #12's schedules...
+96ms ║║Turning off all the lights...
+97ms ║║Executed virtual command log (1ms)
+99ms ║║Cancelling statement #8's schedules...
+607ms ║║Executed physical command [LV Stair Light].on() (502ms)
+608ms ║║Executed [LV Stair Light].on (504ms)
+610ms ║║Cancelling statement #6's schedules...
+623ms ║║Skipped execution of physical command [LV Back Patio Lights].off([]) because it would make no change to the device. (3ms)
+624ms ║║Executed [LV Back Patio Lights].off (5ms)
+629ms ║║Skipped execution of physical command [LV Can Lights (Q1)].off([]) because it would make no change to the device. (2ms)
+629ms ║║Executed [LV Can Lights (Q1)].off (3ms)
+634ms ║║Skipped execution of physical command [LV Counter Lights].off([]) because it would make no change to the device. (2ms)
+635ms ║║Executed [LV Counter Lights].off (4ms)
+640ms ║║Skipped execution of physical command [LV Curio Cabinet (2)].off([]) because it would make no change to the device. (3ms)
+641ms ║║Executed [LV Curio Cabinet (2)].off (4ms)
+646ms ║║Skipped execution of physical command [LV Dining Table].off([]) because it would make no change to the device. (3ms)
+647ms ║║Executed [LV Dining Table].off (4ms)
+1517ms ║║Executed physical command [LV Drop Lights (Q2)].off() (868ms)
+1518ms ║║Executed [LV Drop Lights (Q2)].off (870ms)
+1524ms ║║Skipped execution of physical command [LV FR Center Fan].off([]) because it would make no change to the device. (2ms)
+1524ms ║║Executed [LV FR Center Fan].off (4ms)
+1530ms ║║Skipped execution of physical command [LV FR Center Light].off([]) because it would make no change to the device. (3ms)
+1531ms ║║Executed [LV FR Center Light].off (4ms)
+2079ms ║║Executed physical command [LV FR Corner Light].off() (545ms)
+2080ms ║║Executed [LV FR Corner Light].off (547ms)
+2085ms ║║Skipped execution of physical command [LV FR Outlet].off([]) because it would make no change to the device. (3ms)
+2086ms ║║Executed [LV FR Outlet].off (4ms)
+2091ms ║║Skipped execution of physical command [LV Laundry Room Light].off([]) because it would make no change to the device. (3ms)
+2092ms ║║Executed [LV Laundry Room Light].off (5ms)
+2097ms ║║Skipped execution of physical command [LV LED 1].off([]) because it would make no change to the device. (2ms)
+2098ms ║║Executed [LV LED 1].off (3ms)
+2103ms ║║Skipped execution of physical command [LV Living Room outlet].off([]) because it would make no change to the device. (2ms)
+2104ms ║║Executed [LV Living Room outlet].off (4ms)
+2106ms ║║Cancelling statement #3's schedules...
+2112ms ║║Calculating (string) Sleep tight. Everything is turned off. + (string) Sun, Mar 29 2020 @ 1:03:43 AM PDT &gt;&gt; (string) Sleep tight. Everything is turned off. Sun, Mar 29 2020 @ 1:03:43 AM PDT
+2116ms ║║Sleep tight. Everything is turned off. Sun, Mar 29 2020 @ 1:03:43 AM PDT
+2117ms ║║Executed virtual command [LV Goodnight].log (1ms)
+2122ms ║║Calculating (string) Sleep tight. Everything is turned off. + (string) Sun, Mar 29 2020 @ 1:03:43 AM PDT &gt;&gt; (string) Sleep tight. Everything is turned off. Sun, Mar 29 2020 @ 1:03:43 AM PDT
+2125ms ║║Executed virtual command [LV Goodnight].setState (0ms)
+2138ms ║║Executed virtual command [LV Goodnight].setLocationMode (11ms)
+2167ms ║║Executed physical command [LV Goodnight].off() (26ms)
+2167ms ║║Executed [LV Goodnight].off (28ms)
+2170ms ║╚Execution stage complete. (2092ms)
+2171ms ╚Event processed successfully (2170ms)

orangebucket · 2020-03-30 16:28:04 UTC

Looking at the logs, I think the problem might be caused when the switch is turned off about two seconds after being turned on - about the same sort of time the ‘on’ piston takes to run. That is a sample size of one, though.

Perhaps there is a tiny window where the off event doesn’t hit a semaphore and runs in parallel.

guxdude · 2020-03-30 17:10:38 UTC

That particular instance is everything operating correctly. I turn the sim switch on with Alexa which triggers this piston and the last thing this piston does is turn the switch back off. When you look at the prior turn-on run (1:10:27), it doesn’t do anything and then the switch left on gets caught by another piston (1:12:27) as you can also see in the Smartthings app screenshot.

WCmore · 2020-03-30 18:59:20 UTC

When I use a SimSwitch as a “one-way” trigger, I often use the very last command to “reset” the switch back to the default position, to prepare it for the next cycle. (as you have done above)

The one thing I do differently is to make sure a bit of time has passed before flipping that switch. In other words, most of my pistons may be complex, with scattered WAITs etc… so resetting at the end requires no extra code on my part… but, if I had a piston (like yours) that started and ended in under a second, I would likely add a WAIT before sending that final “reset” command.

orangebucket · 2020-03-30 19:05:03 UTC

Ah, I missed the switch being turned off at the bottom. I am still wondering if that is the potential source of a problem though. I am not saying that it should be.

WCmore · 2020-03-30 19:10:09 UTC

I admit, I am a bit baffled as to why you have no devices listed in this WITH:

Is this just a browser bug in the display?

guxdude · 2020-03-30 19:39:26 UTC

That’s interesting. That with is supposed to be the same device as defined in the vSwitch variable. That is what shows in my piston. Not sure why I didn’t use the vSwitch variable as above. Just missed it, I guess. That is where I turn off the switch that triggers the piston as I described above.

I added a log of the current event to see if it is coming in with something different that the switch on. We’ll see what happens next time. thanks.

guxdude · 2020-03-30 20:02:51 UTC

Sounds like good advice I should implement. Of course, right now I’m having problems with the piston functioning properly when turning on, not off.

WCmore · 2020-03-30 20:45:45 UTC

I think they are connected… With your current piston, the “on” command, and the “off” command are being sent with very little pause between. (remember the “reset” will re-trigger the piston from the top)

I suspect that adding a few seconds WAIT before the “off” command (final reset) should help your “on” to be more reliable.

Personal Note:

Since your SimSwitch is only used twice in the entire piston, I would likely also drop the {vSwitch} variable, and just call the SimSwitch directly in the trigger and in the WITH at the bottom…

orangebucket · 2020-03-30 21:18:11 UTC

True, but it is the ‘changes to on’ that returns false, and that is a comparison between the value in the event, which is ‘on’, and a cached value of the device state, which should be ‘off’ but it seems might not be.

So we are looking back to the last time the piston would have had any dealings with the switch in an ‘off’ state in order to update the cache and that is the last ‘off’ event. We are seeing that when it was right up the chuff of the ‘on’ event, you get problems (albeit on a single sample), but when it is changed later you are OK. It isn’t at all obvious why that should break things, but assuming there might be a really obscure race condition, trying to change the timing somehow seems worth a try.

guxdude · 2020-03-30 21:55:06 UTC

Makes sense. I will try adding a 5 second wait and see if that resolves the issue. Of course, on a random issue, will take a few days to be sure it’s really working

Thanks @WCmore and @orangebucket!

WCmore · 2020-03-30 23:17:16 UTC

It could be worse… I have many pistons that take a year to fully test!
(and if I make a change to the code, I’ll have to wait another year)