Help Understanding Log

Paul1964 · 2020-09-21 19:04:45 UTC

This is the start of an incomplete piston to control my IR controlled scene controller via a virtual dimmer and a logitech harmony hub.

I’m using dim levels to represent the presets, so level 1 = scene 1. The relevant logitech activity is switched on, sending the IR code for scene1. It’s then turned off, ready for another activation. No IR code is sent when the activity is turned off.

The piston seems to work ok, however I am confused by the log.
When changing the dim level to 1 when the switch is off, you see the VS turn on immediately. In the log, you see the change dim level, which works fine. Then you see the switch.on event, which I was sort of expecting and have coded to handle. However, the log shows the piston suspended for 10 secs after the on event, and then it evaluates that the switch was not switched on.

I thought the on event may cancel the dim change event to be cancelled, so was thinking I may need to set the TCP, but this doesn’t seem to be the case.

I could do with understanding what’s going on before I add more functionality.

21/09/2020, 19:40:32 +126ms
+1ms ╔Received event [Kitchen Lights].switch = on with a delay of 103ms
+10198ms ║RunTime Analysis CS > 19ms > PS > 10157ms > PE > 22ms > CE
+10199ms ║Piston waited at a semaphore for 10121ms
+10202ms ║Runtime (42019 bytes) successfully initialized in 10157ms (v0.3.110.20191009) (10200ms)
+10203ms ║╔Execution stage started
+10210ms ║║Comparison (enum) on changes_to (string) on = false (0ms)
+10211ms ║║Condition #2 evaluated false (4ms)
+10212ms ║║Condition group #1 evaluated false (state did not change) (6ms)
+10217ms ║║Comparison (enum) on changes_to (string) off = false (0ms)
+10219ms ║║Condition #9 evaluated false (4ms)
+10220ms ║║Condition group #8 evaluated false (state did not change) (5ms)
+10230ms ║║Cancelling condition #31’s schedules…
+10231ms ║║Condition #31 evaluated false (9ms)
+10232ms ║║Cancelling condition #30’s schedules…
+10233ms ║║Condition group #30 evaluated false (state changed) (11ms)
+10235ms ║╚Execution stage complete. (33ms)
+10236ms ╚Event processed successfully (10236ms)
21/09/2020, 19:40:32 +61ms
+1ms ╔Received event [Kitchen Lights].level = 1 with a delay of 61ms
+75ms ║RunTime Analysis CS > 18ms > PS > 38ms > PE > 19ms > CE
+77ms ║Runtime (41942 bytes) successfully initialized in 38ms (v0.3.110.20191009) (76ms)
+78ms ║╔Execution stage started
+90ms ║║Condition #2 evaluated false (7ms)
+91ms ║║Condition group #1 evaluated false (state did not change) (9ms)
+100ms ║║Condition #9 evaluated false (6ms)
+101ms ║║Condition group #8 evaluated false (state did not change) (8ms)
+106ms ║║Comparison (integer) 1 changes = true (1ms)
+107ms ║║Cancelling condition #31’s schedules…
+108ms ║║Condition #31 evaluated true (4ms)
+109ms ║║Cancelling condition #30’s schedules…
+110ms ║║Condition group #30 evaluated true (state changed) (7ms)
+113ms ║║Cancelling statement #32’s schedules…
+118ms ║║Executed virtual command setVariable (2ms)
+131ms ║║Comparison (integer) 1 is_equal_to (integer) 1 = true (2ms)
+133ms ║║Cancelling condition #17’s schedules…
+135ms ║║Condition #17 evaluated true (7ms)
+136ms ║║Cancelling condition #16’s schedules…
+137ms ║║Condition group #16 evaluated true (state changed) (11ms)
+140ms ║║Cancelling statement #18’s schedules…
+277ms ║║Executed physical command [Ftrnx scn1 [Harmony Activity]].on() (132ms)
+278ms ║║Executed [Ftrnx scn1 [Harmony Activity]].on (134ms)
+281ms ║║Executed virtual command [Ftrnx scn1 [Harmony Activity]].wait (1ms)
+282ms ║║Waiting for 2000ms
+2593ms ║║Executed physical command [Ftrnx scn1 [Harmony Activity]].off() (307ms)
+2594ms ║║Executed [Ftrnx scn1 [Harmony Activity]].off (310ms)
+2602ms ║║Comparison (integer) 1 is_equal_to (integer) 2 = false (1ms)
+2603ms ║║Condition #23 evaluated false (6ms)
+2605ms ║║Condition group #22 evaluated false (state did not change) (7ms)
+2608ms ║╚Execution stage complete. (2529ms)
+2609ms ╚Event processed successfully (2610ms)

orangebucket · 2020-09-21 19:55:56 UTC

Your piston received the dimmer level event first and started executing an instance of the piston.

It then received the switch on event and started up a second instance of the piston. The first instance was still running and when this happens the default behaviour of the piston is to immediately back off for up to ten seconds to give it a chance to finish.

You see it reported that the piston ‘waited at a semaphore’. The code suggests that the piston is in a loop waiting for an indication it can proceed. More often than not it seems to have to wait the full ten seconds(-ish). I don’t know why.

You can ‘enable parallelism’ in the piston settings if you are happy to have multiple instances running at the same time. You just have to figure out if they will interfere with each other, for example by setting local variables.

Semaphore waits can result in events being processed in a different order to the one they are received in.

Paul1964 · 2020-09-21 20:07:25 UTC

Thanks for the explanation, however I’m still confused!

What you describe is the behaviour I would have expected if I’d set the task cancelation policy on the dim change event. I was expecting to have to do this, and started adding some of the code to handle the two instances running together. (the lightsOff variable)

orangebucket · 2020-09-21 20:16:51 UTC

Another thing to appreciate is that the piston itself keeps track of the events it receives in order to evaluate whether a ‘changes’ trigger is true or false. So if a switch goes on / off / on the piston would ideally see the events in that order and see two changes. However a semaphore wait can make it see on / on / off and only see one change.

Paul1964 · 2020-09-21 20:26:54 UTC

I’m not sure why it then evaluates that the switch is off?

The VS started in the off state, with the dim level at 50. I changed the dim level to 1 via the ST app, and nothing else for the duration of the log. As soon as the dim level is set to 1, the VS shows as on on the ST app.

orangebucket · 2020-09-21 20:39:00 UTC

No, it really isn’t.

The Task Cancellation Policy may apply when you have a long ‘wait’ (or something similar like a ‘fade’), where long means five seconds or more (sometimes less if the piston instance has been running for a few seconds already). In order to avoid running out of processing time, the wait is implemented by scheduling a wake up for the end of the wait and exiting. If nothing happens to change things, this ‘scheduled task’ runs, fast forwards past the wait, and continues where it left off.

If another event fires the piston during the wait the new instance may take a different path that results in it not executing the wait. In this case the Task Cancellation Policy says that, by default, the existing scheduled task is cancelled. In effect the wait is cancelled (in reality the piston still wakes up but immediately exits again). The TCP may be adjusted on actions containing waits, or on wait tasks, to prevent the specific scheduled task being cancelled.

So it is a very different thing.

Paul1964 · 2020-09-21 21:02:46 UTC

Thanks for the detailed explanation, its starting to make sense. I think where I’ve used the non default TCP on other pistons is where I have longer waits, probably 1 min plus.

So the learning point for me here, is that if another event occurs which the piston is subscribed to, it is in effect queued until the first instance of the piston completes its 10 sec time slice.

I still don’t understand why the “on” event thinks the switch is off after its semaphore wait. I didn’t turn the switch off again. Unless the device handler does something strange?

orangebucket · 2020-09-21 21:08:45 UTC

It doesn’t, it evaluates if the piston is running because it is processing a switch attribute event (yes), if the value of the attribute in the event is ‘on’ (yes) and if last time it handled the same attribute event it was not ‘on’ (?). I can’t remember how it evaluates when there isn’t a previous value to go by, but it seems to have plumped for false.

It doesn’t check what the current state of the switch is, it is only interested in the event itself.

Once it has seen an ‘off’ it should sort itself out.

One of the strengths of webCoRE is that it distinguishes between trigger events and conditions. That is something that trips many up with Automations in the ST mobile app which conflate the two.

orangebucket · 2020-09-21 21:20:58 UTC

Yes, it is an attempt to serialise processing. The process limit is actually 20 seconds though, so it can give up waiting.

You will probably come across times when enabling parallelism will be useful. A typical example is when you are combining multiple independent pistons into one for convenience.

Paul1964 · 2020-09-21 21:25:33 UTC

I’ve just tried turning it off, then setting the level to 1 to test the above.

However, it now seems to have received an on event, followed by the dim. In the same way the dim has been ignored after the 10 sec semaphore wait.

This has caused the lights to turn “all on” rather than scene 1 - the piston is not working.

So I assume the DH sends an “on” and a “set level”, but the order webcore receives them is not fixed?

21/09/2020, 22:16:23 +719ms
+1ms ╔Received event [Kitchen Lights].level = 1 with a delay of 70ms
+10195ms ║RunTime Analysis CS &gt; 18ms &gt; PS &gt; 10156ms &gt; PE &gt; 22ms &gt; CE
+10196ms ║Piston waited at a semaphore for 10123ms
+10198ms ║Runtime (42021 bytes) successfully initialized in 10156ms (v0.3.110.20191009) (10196ms)
+10199ms ║╔Execution stage started
+10211ms ║║Cancelling condition #2's schedules...
+10211ms ║║Condition #2 evaluated false (8ms)
+10212ms ║║Cancelling condition #1's schedules...
+10213ms ║║Condition group #1 evaluated false (state changed) (10ms)
+10221ms ║║Condition #9 evaluated false (5ms)
+10222ms ║║Condition group #8 evaluated false (state did not change) (7ms)
+10226ms ║║Comparison (integer) 1 changes = false (0ms)
+10227ms ║║Condition #31 evaluated false (3ms)
+10228ms ║║Condition group #30 evaluated false (state did not change) (4ms)
+10230ms ║╚Execution stage complete. (31ms)
+10231ms ╚Event processed successfully (10232ms)
21/09/2020, 22:16:23 +702ms
+1ms ╔Received event [Kitchen Lights].switch = on with a delay of 67ms
+96ms ║RunTime Analysis CS &gt; 22ms &gt; PS &gt; 42ms &gt; PE &gt; 33ms &gt; CE
+99ms ║Runtime (41944 bytes) successfully initialized in 42ms (v0.3.110.20191009) (97ms)
+100ms ║╔Execution stage started
+111ms ║║Comparison (enum) on changes_to (string) on = true (1ms)
+113ms ║║Cancelling condition #2's schedules...
+115ms ║║Condition #2 evaluated true (8ms)
+120ms ║║Comparison (boolean) true is (boolean) true = true (2ms)
+123ms ║║Condition #3 evaluated true (6ms)
+124ms ║║Cancelling condition #1's schedules...
+125ms ║║Condition group #1 evaluated true (state changed) (19ms)
+129ms ║║Cancelling statement #4's schedules...
+955ms ║║Executed physical command [Ftrnx on [Harmony Activity]].on() (822ms)
+956ms ║║Executed [Ftrnx on [Harmony Activity]].on (824ms)
+959ms ║║Executed virtual command [Ftrnx on [Harmony Activity]].wait (0ms)
+959ms ║║Waiting for 2000ms
+3046ms ║║Executed physical command [Ftrnx on [Harmony Activity]].off() (84ms)
+3047ms ║║Executed [Ftrnx on [Harmony Activity]].off (86ms)
+3053ms ║║Executed virtual command [Ftrnx on [Harmony Activity]].setVariable (2ms)
+3059ms ║║Comparison (enum) on changes_to (string) off = false (0ms)
+3060ms ║║Cancelling condition #9's schedules...
+3061ms ║║Condition #9 evaluated false (5ms)
+3062ms ║║Cancelling condition #8's schedules...
+3063ms ║║Condition group #8 evaluated false (state changed) (8ms)
+3078ms ║║Condition #31 evaluated false (12ms)
+3079ms ║║Condition group #30 evaluated false (state did not change) (14ms)
+3082ms ║╚Execution stage complete. (2981ms)
+3083ms ╚Event processed successfully (3083ms)
21/09/2020, 22:15:38 +113ms
+2ms ╔Received event [Kitchen Lights].switch = off with a delay of 102ms
+69ms ║RunTime Analysis CS &gt; 16ms &gt; PS &gt; 34ms &gt; PE &gt; 18ms &gt; CE
+72ms ║Runtime (41942 bytes) successfully initialized in 34ms (v0.3.110.20191009) (69ms)
+73ms ║╔Execution stage started
+80ms ║║Comparison (enum) off changes_to (string) on = false (0ms)
+81ms ║║Condition #2 evaluated false (4ms)
+82ms ║║Condition group #1 evaluated false (state did not change) (6ms)
+87ms ║║Comparison (enum) off changes_to (string) off = true (1ms)
+88ms ║║Cancelling condition #9's schedules...
+89ms ║║Condition #9 evaluated true (5ms)
+90ms ║║Cancelling condition #8's schedules...
+91ms ║║Condition group #8 evaluated true (state changed) (7ms)
+93ms ║║Cancelling statement #10's schedules...
+174ms ║║Executed physical command [Ftrnx off [Harmony Activity]].on() (79ms)
+175ms ║║Executed [Ftrnx off [Harmony Activity]].on (80ms)
+178ms ║║Executed virtual command [Ftrnx off [Harmony Activity]].wait (1ms)
+179ms ║║Waiting for 2000ms
+2238ms ║║Executed physical command [Ftrnx off [Harmony Activity]].off() (57ms)
+2239ms ║║Executed [Ftrnx off [Harmony Activity]].off (59ms)
+2244ms ║║Executed virtual command [Ftrnx off [Harmony Activity]].setVariable (2ms)
+2252ms ║║Cancelling condition #31's schedules...
+2253ms ║║Condition #31 evaluated false (6ms)
+2254ms ║║Cancelling condition #30's schedules...
+2255ms ║║Condition group #30 evaluated false (state changed) (8ms)
+2256ms ║╚Execution stage complete. (2184ms)
+2257ms ╚Event processed successfully (2257ms)

orangebucket · 2020-09-21 21:52:25 UTC

Well more often than not things seem to happen in the original order. but clearly not every time.

WCmore · 2020-09-21 21:58:48 UTC

I would encourage you to extend this external logic to wait a bit longer before turning it back off.
(at least a few seconds longer than the very longest this current piston will ever run)

This is to give enough time for the current logic to be fully processed, before a new trigger comes in.

Paul1964 · 2020-09-21 22:07:29 UTC

I’m not sure I follow?

Once the harmony activity for a particular event has been turned on the main work of the piston has been completed. The purpose of the 2 sec wait is to ensure the harmony has carried out its actions, before turning the activity off again. This is just so the same activity can be turned on at a future time, it does not send any further IR codes.

I think my biggest problem (see above) is that the device handler sends a dim & an on event when setting a dim level from off, and the order of these can not be determined. I might have to have a re think on this.

WCmore · 2020-09-21 22:09:57 UTC

My apologies… I missed this. I thought you had programming to “reset” the switch, and I was asking to delay a bit before turning it back off.

Paul1964 · 2020-09-21 22:21:54 UTC

No Problem, your input is always appreciated.

This is turning into quite a challenge, it’s frustrating as it works 90% of the time.

Originally, it seemed to work ok testing the VS through the ST app, but not via alexa. So I was trying to understand the log messages, before seeing what was different when using alexa. I suspected alexa may have been sending separate dim & on events, however it now looks as though that is not the case and the VS sends both. But the order they are received is random.

WCmore · 2020-09-21 22:30:03 UTC

I am curious… Have you tested with a Simulated Switch?
(instead of a virtual one)

They act quite different.

Paul1964 · 2020-09-21 22:39:29 UTC

I created it through the ST IDE, the device type is “virtual dimmer switch”.

There is a “simulated dimmer switch” I’ll try using that and see if its any better/different.

WCmore · 2020-09-21 22:48:35 UTC

To be honest, I avoid virtual devices like the plague, and only use Simulated ones.
(my last link goes into more details)

Paul1964 · 2020-09-21 23:00:14 UTC

I’ve always used virtual switches, I guess because when I was starting out I used the virtual device creator smart app, at that time I didn’t know you could create them through the IDE

I looked at your post, and with my knowledge couldn’t really see a big difference between the two, although I thought a local DH handler on the VS would give it an advantage? So not sure what the main advantage of the simulated switches are.

However, I’ll take your advice and try the simulated switch, I’ll report back my findings.

Paul1964 · 2020-09-21 23:14:49 UTC

I’ve tried the simulated switch, it seems as random as the virtual switch.

Below are 2 logs.both times the sim switch was at 50% & off, then changed to 1%. In the first example a dim was followed by an on, in the second the dim followed the on.

22/09/2020, 00:07:35 +513ms
+1ms ╔Received event [Kitchen Lights2].switch = on with a delay of 62ms
+10087ms ║RunTime Analysis CS &gt; 18ms &gt; PS &gt; 10050ms &gt; PE &gt; 20ms &gt; CE
+10088ms ║Piston waited at a semaphore for 10018ms
+10090ms ║Runtime (42326 bytes) successfully initialized in 10050ms (v0.3.110.20191009) (10088ms)
+10091ms ║╔Execution stage started
+10098ms ║║Comparison (enum) on changes_to (string) on = false (1ms)
+10099ms ║║Condition #2 evaluated false (4ms)
+10100ms ║║Condition group #1 evaluated false (state did not change) (5ms)
+10105ms ║║Comparison (enum) on changes_to (string) off = false (0ms)
+10107ms ║║Condition #9 evaluated false (4ms)
+10108ms ║║Condition group #8 evaluated false (state did not change) (5ms)
+10117ms ║║Cancelling condition #31's schedules...
+10118ms ║║Condition #31 evaluated false (7ms)
+10119ms ║║Cancelling condition #30's schedules...
+10119ms ║║Condition group #30 evaluated false (state changed) (9ms)
+10121ms ║╚Execution stage complete. (30ms)
+10122ms ╚Event processed successfully (10123ms)
22/09/2020, 00:07:35 +510ms
+1ms ╔Received event [Kitchen Lights2].level = 1 with a delay of 48ms
+63ms ║RunTime Analysis CS &gt; 14ms &gt; PS &gt; 27ms &gt; PE &gt; 21ms &gt; CE
+65ms ║Runtime (42249 bytes) successfully initialized in 27ms (v0.3.110.20191009) (63ms)
+66ms ║╔Execution stage started
+78ms ║║Condition #2 evaluated false (7ms)
+80ms ║║Condition group #1 evaluated false (state did not change) (8ms)
+88ms ║║Cancelling condition #9's schedules...
+89ms ║║Condition #9 evaluated false (7ms)
+91ms ║║Cancelling condition #8's schedules...
+92ms ║║Condition group #8 evaluated false (state changed) (9ms)
+97ms ║║Comparison (integer) 1 changes = true (1ms)
+99ms ║║Cancelling condition #31's schedules...
+100ms ║║Condition #31 evaluated true (5ms)
+101ms ║║Cancelling condition #30's schedules...
+102ms ║║Condition group #30 evaluated true (state changed) (8ms)
+105ms ║║Cancelling statement #32's schedules...
+110ms ║║Executed virtual command setVariable (3ms)
+117ms ║║Comparison (integer) 1 is_equal_to (integer) 1 = true (1ms)
+119ms ║║Cancelling condition #17's schedules...
+120ms ║║Condition #17 evaluated true (7ms)
+122ms ║║Cancelling condition #16's schedules...
+123ms ║║Condition group #16 evaluated true (state changed) (9ms)
+125ms ║║Cancelling statement #18's schedules...
+266ms ║║Executed physical command [Ftrnx scn1 [Harmony Activity]].on() (138ms)
+267ms ║║Executed [Ftrnx scn1 [Harmony Activity]].on (140ms)
+270ms ║║Executed virtual command [Ftrnx scn1 [Harmony Activity]].wait (0ms)
+271ms ║║Waiting for 2000ms
+2321ms ║║Executed physical command [Ftrnx scn1 [Harmony Activity]].off() (47ms)
+2322ms ║║Executed [Ftrnx scn1 [Harmony Activity]].off (49ms)
+2330ms ║║Comparison (integer) 1 is_equal_to (integer) 2 = false (1ms)
+2331ms ║║Condition #23 evaluated false (5ms)
+2333ms ║║Condition group #22 evaluated false (state did not change) (7ms)
+2336ms ║╚Execution stage complete. (2269ms)
+2337ms ╚Event processed successfully (2337ms)

22/09/2020, 00:11:01 +661ms
+1ms ╔Received event [Kitchen Lights2].level = 1 with a delay of 70ms
+10091ms ║RunTime Analysis CS &gt; 16ms &gt; PS &gt; 10053ms &gt; PE &gt; 23ms &gt; CE
+10092ms ║Piston waited at a semaphore for 10019ms
+10095ms ║Runtime (42329 bytes) successfully initialized in 10053ms (v0.3.110.20191009) (10093ms)
+10095ms ║╔Execution stage started
+10107ms ║║Cancelling condition #2's schedules...
+10108ms ║║Condition #2 evaluated false (8ms)
+10109ms ║║Cancelling condition #1's schedules...
+10110ms ║║Condition group #1 evaluated false (state changed) (11ms)
+10119ms ║║Condition #9 evaluated false (5ms)
+10120ms ║║Condition group #8 evaluated false (state did not change) (8ms)
+10124ms ║║Comparison (integer) 1 changes = false (0ms)
+10126ms ║║Condition #31 evaluated false (3ms)
+10127ms ║║Condition group #30 evaluated false (state did not change) (4ms)
+10128ms ║╚Execution stage complete. (33ms)
+10129ms ╚Event processed successfully (10129ms)
22/09/2020, 00:11:01 +648ms
+1ms ╔Received event [Kitchen Lights2].switch = on with a delay of 71ms
+80ms ║RunTime Analysis CS &gt; 17ms &gt; PS &gt; 43ms &gt; PE &gt; 20ms &gt; CE
+83ms ║Runtime (42252 bytes) successfully initialized in 43ms (v0.3.110.20191009) (81ms)
+84ms ║╔Execution stage started
+91ms ║║Comparison (enum) on changes_to (string) on = true (1ms)
+92ms ║║Cancelling condition #2's schedules...
+93ms ║║Condition #2 evaluated true (5ms)
+97ms ║║Comparison (boolean) true is (boolean) true = true (1ms)
+98ms ║║Condition #3 evaluated true (4ms)
+99ms ║║Cancelling condition #1's schedules...
+100ms ║║Condition group #1 evaluated true (state changed) (12ms)
+102ms ║║Cancelling statement #4's schedules...
+182ms ║║Executed physical command [Ftrnx on [Harmony Activity]].on() (77ms)
+183ms ║║Executed [Ftrnx on [Harmony Activity]].on (79ms)
+186ms ║║Executed virtual command [Ftrnx on [Harmony Activity]].wait (1ms)
+187ms ║║Waiting for 2000ms
+2246ms ║║Executed physical command [Ftrnx on [Harmony Activity]].off() (57ms)
+2247ms ║║Executed [Ftrnx on [Harmony Activity]].off (59ms)
+2252ms ║║Executed virtual command [Ftrnx on [Harmony Activity]].setVariable (2ms)
+2258ms ║║Comparison (enum) on changes_to (string) off = false (0ms)
+2259ms ║║Cancelling condition #9's schedules...
+2260ms ║║Condition #9 evaluated false (5ms)
+2261ms ║║Cancelling condition #8's schedules...
+2262ms ║║Condition group #8 evaluated false (state changed) (8ms)
+2269ms ║║Condition #31 evaluated false (5ms)
+2270ms ║║Condition group #30 evaluated false (state did not change) (6ms)
+2272ms ║╚Execution stage complete. (2189ms)
+2273ms ╚Event processed successfully (2273ms)