Condition not being evaluated correctly

jburgon · 2020-11-05 18:34:03 UTC

1) Give a description of the problem
I’m using the callbacks plugin in Kodi to send playing status updates to Smartthings. This particular piston turns on the lights when the playing status changes to stopped. I only want this happen if a movie was stopped (not a tv show, music, etc.) Kodi sends an event called currentPlayingType called movie when a movie is started (as shown in the logs). So my piston looks at the currentPlayingType and if it was movie for at least one second (I’ve tried longer time frames). This used to work perfectly even after migrating to the new smartthings app then it just stopped working within the last couple of weeks. If I remove the currentPlayingType from the if statement then it works so something seems to be broken with the comparison of the previous currentPlayingType event.

2) What is the expected behaviour?
The lights should turn on when a movie is stopped, but not anything else.

3) What is happening/not happening?
The lights do not turn on when a movie is stopped. I’m not sure if it’s because the currentPlayingType event that updates the status to none is received before the status event of stopped and I don’t know if that’s what the log looked like when it was working.

4) Post a Green Snapshot of the piston

5) Attach logs after turning logging level to Full
11/4/2020, 11:29:28 PM +582ms
+2ms ╔Received event [Shield].status = stopped with a delay of 58ms
+10111ms ║RunTime Analysis CS > 17ms > PS > 10053ms > PE > 41ms > CE
+10112ms ║Piston waited at a semaphore for 10015ms
+10114ms ║Runtime (38183 bytes) successfully initialized in 10053ms (v0.3.110.20191009) (10112ms)
+10115ms ║╔Execution stage started
+10122ms ║║Comparison (string) stopped is (string) stopped = true (1ms)
+10123ms ║║Condition #8 evaluated true (4ms)
+10156ms ║║Comparison (string) None was (string) movie = false (20ms)
+10157ms ║║Condition #9 evaluated false (33ms)
+10158ms ║║Condition group #1 evaluated false (state did not change) (39ms)
+10159ms ║╚Execution stage complete. (44ms)
+10160ms ╚Event processed successfully (10160ms)
11/4/2020, 11:29:28 PM +578ms
+0ms ╔Received event [Shield].currentPlayingType = None with a delay of 41ms
+70ms ║RunTime Analysis CS > 15ms > PS > 24ms > PE > 32ms > CE
+72ms ║Runtime (38112 bytes) successfully initialized in 24ms (v0.3.110.20191009) (71ms)
+73ms ║╔Execution stage started
+85ms ║║Comparison (string) stopped is (string) stopped = true (2ms)
+86ms ║║Cancelling condition #8’s schedules…
+87ms ║║Condition #8 evaluated true (10ms)
+163ms ║║Comparison (string) None was (string) movie = false (73ms)
+165ms ║║Condition #9 evaluated false (77ms)
+166ms ║║Condition group #1 evaluated false (state did not change) (89ms)
+168ms ║╚Execution stage complete. (94ms)
+169ms ╚Event processed successfully (168ms)
11/4/2020, 11:27:14 PM +695ms
+2ms ╔Received event [Shield].currentPlayingType = movie with a delay of 61ms
+93ms ║RunTime Analysis CS > 20ms > PS > 32ms > PE > 41ms > CE
+96ms ║Runtime (38113 bytes) successfully initialized in 32ms (v0.3.110.20191009) (94ms)
+97ms ║╔Execution stage started
+109ms ║║Comparison (string) playing is (string) stopped = false (1ms)
+111ms ║║Condition #8 evaluated false (10ms)
+112ms ║║Condition group #1 evaluated false (state did not change) (12ms)
+113ms ║╚Execution stage complete. (17ms)
+114ms ╚Event processed successfully (114ms)
11/4/2020, 11:27:13 PM +596ms
+1ms ╔Received event [Shield].status = playing with a delay of 46ms
+73ms ║RunTime Analysis CS > 16ms > PS > 25ms > PE > 31ms > CE
+75ms ║Runtime (38102 bytes) successfully initialized in 25ms (v0.3.110.20191009) (74ms)
+76ms ║╔Execution stage started
+84ms ║║Comparison (string) playing is (string) stopped = false (1ms)
+85ms ║║Cancelling condition #8’s schedules…
+86ms ║║Condition #8 evaluated false (6ms)
+87ms ║║Condition group #1 evaluated false (state did not change) (7ms)
+89ms ║╚Execution stage complete. (14ms)
+90ms ╚Event processed successfully (90ms)

REMOVE BELOW AFTER READING

orangebucket · 2020-11-05 19:15:24 UTC

You could perhaps try ‘changes to stop’ so the piston doesn’t get triggered by the change of playing type. As it stands the events arrive milliseconds apart and that causes the second piston instance to wait for ten seconds for the first to finish.

However that just gets rid of unnecessary executions and the actual thing that breaks the piston is the type changing to ‘None’. If the type is ‘None’ then ‘was movie’ is probably going to be false by the time it is checked (‘was movie’ requires it to still be ‘movie’).

It may be that you could simply remove the first condition and just consider what is playing. A switch from ‘movie’ to ‘None’ might well imply a stop. That would make the piston run whenever the type changes and in that instance ‘was movie’ ignores the change that just happened.

jburgon · 2020-11-05 19:34:34 UTC

That’s a good idea. I tried removing the stopped condition, but it still evaluates the condition as false. See log below.

11/5/2020, 12:28:16 PM +762ms
+2ms ╔Received event [Shield].currentPlayingType = None with a delay of 56ms
+86ms ║RunTime Analysis CS &gt; 18ms &gt; PS &gt; 32ms &gt; PE &gt; 36ms &gt; CE
+89ms ║Runtime (37668 bytes) successfully initialized in 32ms (v0.3.110.20191009) (85ms)
+90ms ║╔Execution stage started
+115ms ║║Comparison (string) None was (string) movie = false (17ms)
+116ms ║║Condition #9 evaluated false (22ms)
+117ms ║║Condition group #1 evaluated false (state did not change) (24ms)
+119ms ║╚Execution stage complete. (30ms)
+120ms ╚Event processed successfully (120ms)
11/5/2020, 12:28:09 PM +371ms
+2ms ╔Received event [Shield].currentPlayingType = movie with a delay of 67ms
+93ms ║RunTime Analysis CS &gt; 18ms &gt; PS &gt; 40ms &gt; PE &gt; 34ms &gt; CE
+95ms ║Runtime (37668 bytes) successfully initialized in 40ms (v0.3.110.20191009) (92ms)
+96ms ║╔Execution stage started
+130ms ║║Duration 188ms for is &gt;= 1000ms threshold = false
+131ms ║║Comparison (string) movie was (string) movie = false (29ms)
+132ms ║║Condition #9 evaluated false (33ms)
+133ms ║║Condition group #1 evaluated false (state did not change) (34ms)
+135ms ║╚Execution stage complete. (40ms)
+136ms ╚Event processed successfully (136ms)

jburgon · 2020-11-05 19:41:50 UTC

Interesting. If it’s set to “changes away from” then it works. So ultimately the problem is the order in which the events are received. I’m not sure if something changed that caused the events to happen differently, but I’m understanding this better now.

11/5/2020, 12:37:32 PM +40ms
+1ms ╔Received event [Shield].currentPlayingType = None with a delay of 60ms
+95ms ║RunTime Analysis CS &gt; 20ms &gt; PS &gt; 39ms &gt; PE &gt; 37ms &gt; CE
+98ms ║Runtime (37682 bytes) successfully initialized in 39ms (v0.3.110.20191009) (96ms)
+99ms ║╔Execution stage started
+106ms ║║Comparison (string) None changes_away_from (string) movie = true (1ms)
+107ms ║║Cancelling condition #9's schedules...
+108ms ║║Condition #9 evaluated true (5ms)
+109ms ║║Cancelling condition #1's schedules...
+110ms ║║Condition group #1 evaluated true (state changed) (8ms)
+112ms ║║Cancelling statement #4's schedules...
+150ms ║║Executed physical command [Theater Front Lights].setLevel([25]) (33ms)
+151ms ║║Executed [Theater Front Lights].setLevel (35ms)
+153ms ║║Cancelling statement #10's schedules...
+188ms ║║Executed physical command [Theater Rear Lights].setLevel([50]) (31ms)
+189ms ║║Executed [Theater Rear Lights].setLevel (33ms)
+191ms ║╚Execution stage complete. (93ms)
+192ms ╚Event processed successfully (192ms)
11/5/2020, 12:37:11 PM +985ms
+1ms ╔Received event [Shield].currentPlayingType = movie with a delay of 48ms
+95ms ║RunTime Analysis CS &gt; 19ms &gt; PS &gt; 33ms &gt; PE &gt; 44ms &gt; CE
+98ms ║Runtime (37682 bytes) successfully initialized in 33ms (v0.3.110.20191009) (96ms)
+99ms ║╔Execution stage started
+106ms ║║Comparison (string) movie changes_away_from (string) movie = false (0ms)
+108ms ║║Condition #9 evaluated false (5ms)
+109ms ║║Condition group #1 evaluated false (state did not change) (6ms)
+111ms ║╚Execution stage complete. (12ms)
+112ms ╚Event processed successfully (112ms)

orangebucket · 2020-11-05 20:23:57 UTC

Ah OK I think I know what may have happened.

The ‘was’ comparison works by looking back through the device’s event history. If the piston is currently running because the attribute in the ‘was’ has changed the last entry gets skipped.

Very recently a change was implemented to the event history in SmartThings as part of the process of phasing out the legacy systems. It will now only store entries that match a capability schema. Unfortunately ‘currentPlayingType’ is NOT part of a stock capability and I suspect it is not part of a custom capability either, it is a custom attribute. So it won’t appear in the event history any more.

The ‘changes away from’ will be OK as that is something the piston tracks itself.

jburgon · 2020-11-05 20:29:06 UTC

That’s good to know. Thanks! I figured it was something like that because this worked just fine for so long and then all of the sudden it didn’t work anymore. I now have the piston set up to only look for the currentPlayingType changing away from movie and that is working and doesn’t interfere with any of my other pistons so I’ll go with that for now.