Piston Fires Once in a day, but not a second time

[Sven]

1) Give a description of the problem
So I am new to this and looked through some posts, sorry if I overlooked one with an obvious answer. My piston is set up so that when my phone’s presence changes to “present” it should kick off a few things. Mainly playing a message on all my speakers and then playing my “preset1” on music player 1, which is a stream of the local NPR station.

I’ve found that when I come home for lunch and walk in the door it is playing NPR properly; however, when I get home in the evening it is not playing as it should be.

2) What is the expected behavior?
I expect that it should fire every time my phone’s presence changes to “present”. Meaning I should have NPR playing on music player 1 when I walk in no matter the time or how many times I’ve left and arrived that day.

3) What is happening/not happening?
In the evenings when it does not fire I check my phone’s status in ST and it shows as “Present”, so I don’t think it is that. I also check it shortly after I leave and it shows “away”. So it is changing correctly back and forth based on geolocation. Gotta be something with how I set up the piston that it only kicks it off once.

I’ll add that I found a topic related to “Task Cancellation Policy” where it was recommended to set it to “never”. I’ve just done that and have not had a chance to test it out yet, but wondering if I am on the right track? Before that it was on the default.

4) Post a Green Snapshot of the piston!

[michicago]

Your expectations of your piston are correct for the way it’s written - no need to monkey with the task cancellation policy (really only comes into play when WAIT commands are used).

You’ll need to post logs of the piston executing and failing for anyone to be able to help you, though.

[Sven]

Okay, thank you for looking it over. I’ve reset the task cancellation policy to default and turned on full logging for that piston. Will attempt it later then add the logs.

[Sven]

12/07/2018, 22:01:27 +974ms
+0ms ╔Starting piston… (v0.3.105.20180628)
+264ms ║╔Subscribing to devices…
+283ms ║║Subscribing to CHRIS’s iPhone.presence…
+354ms ║║Subscribing to Kitchen Speaker…
+355ms ║║Subscribing to My bedroom Speaker…
+356ms ║║Subscribing to Office Speaker…
+357ms ║╚Finished subscribing (105ms)
+381ms ║Cancelling condition #4’s schedules…
+382ms ║Cancelling condition #1’s schedules…
+394ms ╚Piston successfully started (394ms)
12/07/2018, 22:00:04 +61ms
+1ms ╔Received event [Lawrence House].time = 1531447205714 with a delay of -1654ms
+277ms ║RunTime Analysis CS > 26ms > PS > 207ms > PE > 44ms > CE
+280ms ║Runtime (38860 bytes) successfully initialized in 207ms (v0.3.105.20180628) (278ms)
+281ms ║╔Execution stage started
+356ms ║║Executed physical command [Kitchen Speaker].preset1() (55ms)
+357ms ║║Executed [Kitchen Speaker].preset1 (57ms)
+360ms ║║Cancelling statement #7’s schedules…
+382ms ║║Executed virtual command sendPushNotification (10ms)
+385ms ║╚Execution stage complete. (104ms)
+387ms ╚Event processed successfully (388ms)
12/07/2018, 21:59:44 +670ms
+0ms ╔Received event [Lawrence House].test = 1531447184669 with a delay of 0ms
+148ms ║RunTime Analysis CS > 19ms > PS > 100ms > PE > 30ms > CE
+150ms ║Runtime (38851 bytes) successfully initialized in 100ms (v0.3.105.20180628) (149ms)
+151ms ║╔Execution stage started
+162ms ║║Comparison (enum) present is (string) present = true (1ms)
+163ms ║║Condition #4 evaluated true (8ms)
+164ms ║║Condition group #1 evaluated true (state did not change) (8ms)
+165ms ║║Cancelling statement #2’s schedules…
+522ms ║║Executed physical command [Kitchen Speaker].playText([Panties off Bitches, 70]) (343ms)
+523ms ║║Executed [Kitchen Speaker].playText (347ms)
+741ms ║║Executed physical command [My bedroom Speaker].playText([Panties off Bitches, 70]) (215ms)
+742ms ║║Executed [My bedroom Speaker].playText (217ms)
+1026ms ║║Executed physical command [Office Speaker].playText([Panties off Bitches, 70]) (281ms)
+1027ms ║║Executed [Office Speaker].playText (283ms)
+1030ms ║║Cancelling statement #5’s schedules…
+1040ms ║║Executed virtual command [Kitchen Speaker].wait (4ms)
+1042ms ║║Requesting a wake up for Thu, Jul 12 2018 @ 10:00:05 PM EDT (in 20.0s)
+1057ms ║╚Execution stage complete. (906ms)
+1063ms ║Setting up scheduled job for Thu, Jul 12 2018 @ 10:00:05 PM EDT (in 19.982s)
+1071ms ╚Event processed successfully (1071ms)
12/07/2018, 21:58:05 +80ms
+1ms ╔Received event [Lawrence House].time = 1531447086462 with a delay of -1382ms
+10166ms ║RunTime Analysis CS > 37ms > PS > 10095ms > PE > 34ms > CE
+10167ms ║Piston waited at a semaphore for 10024ms
+10170ms ║Runtime (38928 bytes) successfully initialized in 10095ms (v0.3.105.20180628) (10167ms)
+10171ms ║╔Execution stage started
+10172ms ║╚Execution stage complete. (2ms)
+10173ms ╚Event processed successfully (10173ms)
12/07/2018, 21:58:05 +79ms
+1ms ╔Received event [Lawrence House].time = 1531447086462 with a delay of -1383ms
+103ms ║RunTime Analysis CS > 16ms > PS > 57ms > PE > 29ms > CE
+105ms ║Runtime (38848 bytes) successfully initialized in 57ms (v0.3.105.20180628) (103ms)
+106ms ║╔Execution stage started
+173ms ║║Executed physical command [Kitchen Speaker].preset1() (52ms)
+173ms ║║Executed [Kitchen Speaker].preset1 (54ms)
+176ms ║║Cancelling statement #7’s schedules…
+195ms ║║Executed virtual command sendPushNotification (9ms)
+197ms ║╚Execution stage complete. (91ms)
+198ms ╚Event processed successfully (198ms)
12/07/2018, 21:57:45 +522ms
+2ms ╔Received event [Lawrence House].test = 1531447065519 with a delay of 2ms
+93ms ║RunTime Analysis CS > 20ms > PS > 39ms > PE > 32ms > CE
+97ms ║Runtime (38841 bytes) successfully initialized in 39ms (v0.3.105.20180628) (94ms)
+102ms ║╔Execution stage started
+114ms ║║Comparison (enum) present is (string) present = true (1ms)
+115ms ║║Condition #4 evaluated true (9ms)
+116ms ║║Condition group #1 evaluated true (state did not change) (10ms)
+118ms ║║Cancelling statement #2’s schedules…
+457ms ║║Executed physical command [Kitchen Speaker].playText([All Hail the King , 70]) (326ms)
+457ms ║║Executed [Kitchen Speaker].playText (330ms)
+728ms ║║Executed physical command [My bedroom Speaker].playText([All Hail the King , 70]) (268ms)
+729ms ║║Executed [My bedroom Speaker].playText (270ms)
+922ms ║║Executed physical command [Office Speaker].playText([All Hail the King , 70]) (190ms)
+923ms ║║Executed [Office Speaker].playText (192ms)
+926ms ║║Cancelling statement #5’s schedules…
+934ms ║║Executed virtual command [Kitchen Speaker].wait (2ms)
+938ms ║║Requesting a wake up for Thu, Jul 12 2018 @ 9:58:06 PM EDT (in 20.0s)
+964ms ║╚Execution stage complete. (866ms)
+970ms ║Setting up scheduled job for Thu, Jul 12 2018 @ 9:58:06 PM EDT (in 19.972s)
+978ms ╚Event processed successfully (978ms)
12/07/2018, 21:57:39 +429ms
+1ms ╔Starting piston… (v0.3.105.20180628)
+230ms ║╔Subscribing to devices…
+236ms ║║Subscribing to CHRIS’s iPhone.presence…
+302ms ║║Subscribing to Kitchen Speaker…
+303ms ║║Subscribing to My bedroom Speaker…
+304ms ║║Subscribing to Office Speaker…
+305ms ║╚Finished subscribing (87ms)
+329ms ║Comparison (enum) present is (string) present = true (1ms)
+330ms ║Cancelling condition #4’s schedules…
+331ms ║Cancelling condition #1’s schedules…
+344ms ╚Piston successfully started (344ms)
12/07/2018, 21:57:13 +800ms
+1ms ╔Received event [Lawrence House].test = 1531447033800 with a delay of 0ms
+92ms ║RunTime Analysis CS > 14ms > PS > 47ms > PE > 30ms > CE
+94ms ║Runtime (38848 bytes) successfully initialized in 47ms (v0.3.105.20180628) (92ms)
+95ms ║╔Execution stage started
+105ms ║║Condition #4 evaluated false (6ms)
+106ms ║║Condition group #1 evaluated false (state did not change) (7ms)
+108ms ║╚Execution stage complete. (13ms)
+109ms ╚Event processed successfully (109ms)
12/07/2018, 21:56:41 +22ms
+1ms ╔Starting piston… (v0.3.105.20180628)
+159ms ║╔Subscribing to devices…
+181ms ║║Subscribing to CHRIS’s iPhone.presence…
+249ms ║║Subscribing to Kitchen Speaker…
+250ms ║║Subscribing to My bedroom Speaker…
+251ms ║║Subscribing to Office Speaker…
+251ms ║╚Finished subscribing (103ms)
+345ms ║Cancelling condition #4’s schedules…
+346ms ║Cancelling condition #1’s schedules…
+364ms ╚Piston successfully started (362ms)
12/07/2018, 21:41:13 +402ms
+2ms ╔Received event [CHRIS’s iPhone].presence = present with a delay of 113ms
+105ms ║RunTime Analysis CS > 22ms > PS > 62ms > PE > 21ms > CE
+107ms ║Runtime (38734 bytes) successfully initialized in 62ms (v0.3.105.20180628) (104ms)
+108ms ║╔Execution stage started
+116ms ║║Comparison (enum) present changes_to (string) present = true (1ms)
+117ms ║║Cancelling condition #4’s schedules…
+118ms ║║Condition #4 evaluated true (5ms)
+119ms ║║Cancelling condition #1’s schedules…
+119ms ║║Condition group #1 evaluated true (state changed) (7ms)
+121ms ║║Cancelling statement #2’s schedules…
+387ms ║║Executed physical command [Kitchen Speaker].playText([Party Time, 70]) (258ms)
+388ms ║║Executed [Kitchen Speaker].playText (260ms)
+657ms ║║Executed physical command [My bedroom Speaker].playText([Party Time, 70]) (266ms)
+658ms ║║Executed [My bedroom Speaker].playText (267ms)
+906ms ║║Executed physical command [Office Speaker].playText([Party Time, 70]) (245ms)
+907ms ║║Executed [Office Speaker].playText (246ms)
+909ms ║║Cancelling statement #5’s schedules…
+936ms ║║Executed physical command [Kitchen Speaker].preset1() (25ms)
+937ms ║║Executed [Kitchen Speaker].preset1 (26ms)
+939ms ║║Cancelling statement #7’s schedules…
+956ms ║║Executed virtual command sendPushNotification (12ms)
+958ms ║╚Execution stage complete. (850ms)
+959ms ╚Event processed successfully (959ms)
12/07/2018, 21:33:33 +734ms
+2ms ╔Received event [CHRIS’s iPhone].presence = not present with a delay of 83ms
+100ms ║RunTime Analysis CS > 17ms > PS > 62ms > PE > 21ms > CE
+102ms ║Runtime (38728 bytes) successfully initialized in 62ms (v0.3.105.20180628) (99ms)
+103ms ║╔Execution stage started
+111ms ║║Comparison (enum) not present changes_to (string) present = false (1ms)
+112ms ║║Cancelling condition #4’s schedules…
+113ms ║║Condition #4 evaluated false (5ms)
+114ms ║║Cancelling condition #1’s schedules…
+115ms ║║Condition group #1 evaluated false (state changed) (7ms)
+117ms ║╚Execution stage complete. (14ms)
+118ms ╚Event processed successfully (118ms)
12/07/2018, 17:29:14 +774ms
+1ms ╔Received event [CHRIS’s iPhone].presence = present with a delay of 67ms
+95ms ║RunTime Analysis CS > 14ms > PS > 56ms > PE > 25ms > CE
+97ms ║Runtime (38696 bytes) successfully initialized in 56ms (v0.3.105.20180628) (95ms)
+98ms ║╔Execution stage started
+105ms ║║Comparison (enum) present changes_to (string) present = true (0ms)
+107ms ║║Cancelling condition #4’s schedules…
+107ms ║║Condition #4 evaluated true (4ms)
+108ms ║║Cancelling condition #1’s schedules…
+109ms ║║Condition group #1 evaluated true (state changed) (7ms)
+111ms ║║Cancelling statement #2’s schedules…
+375ms ║║Executed physical command [Kitchen Speaker].playText([Panties off Bitches, 70]) (253ms)
+376ms ║║Executed [Kitchen Speaker].playText (255ms)
+563ms ║║Executed physical command [My bedroom Speaker].playText([Panties off Bitches, 70]) (184ms)
+564ms ║║Executed [My bedroom Speaker].playText (186ms)
+771ms ║║Executed physical command [Office Speaker].playText([Panties off Bitches, 70]) (204ms)
+771ms ║║Executed [Office Speaker].playText (205ms)
+774ms ║║Cancelling statement #5’s schedules…
+798ms ║║Executed physical command [Kitchen Speaker].preset1() (22ms)
+798ms ║║Executed [Kitchen Speaker].preset1 (23ms)
+801ms ║║Cancelling statement #7’s schedules…
+812ms ║║Executed virtual command sendPushNotification (7ms)
+814ms ║╚Execution stage complete. (716ms)
+815ms ╚Event processed successfully (815ms)
12/07/2018, 16:20:26 +932ms
+1ms ╔Starting piston… (v0.3.105.20180628)
+190ms ║╔Subscribing to devices…
+211ms ║║Subscribing to CHRIS’s iPhone.presence…
+318ms ║║Subscribing to Kitchen Speaker…
+319ms ║║Subscribing to My bedroom Speaker…
+320ms ║║Subscribing to Office Speaker…
+321ms ║╚Finished subscribing (134ms)
+357ms ╚Piston successfully started (356ms)
Clear Full

[Sven]

So I pasted the log above.

When I arrived after work it sent me the notification, but the kitchen speaker wasn’t playing.

Later in the evening I left again to run to the store and when I returned (around 21:41) it again sent me the notification, but still no speaker playing when I walked in. So it seems the piston fires, but issues with the speaker.

So then I started to play around with it and test it, so I changed the trigger of “changes to” to a condition of “is” present (since it wouldn’t test properly without doing this). I also put a “wait” statement of 20 seconds before the do preset1 task.

I tested it using the “test” button twice with these changes and it worked perfectly both times.

I changed it back to a trigger of “changes to”, but don’t feel like leaving again tonight to test it.

Hopefully the logs will be of use though.

[michicago]

So then I started to play around with it and test it, so I changed the trigger of “changes to” to a condition of “is” present (since it wouldn’t test properly without doing this). I also put a “wait” statement of 20 seconds before the do preset1 task.

I think this is your key - you were sending two commands to whatever “music player 1” is, which would be sent at almost the same time to your player. The way command forces a delay.

For the WAIT to work with a trigger, you’ll have to make one more change. Click on the action (or group of actions) where your WAIT command is. In the dialog box that opens up, click the gear cog at the bottom to expand settings. In there, change your Task Cancellation Policy to Never Cancel Tasks… and you should be good to go.

[Sven]

Sounds good. Thank you again. I’ve changed that Task Cancellation Policy as seen below, so we’ll see how it behaves when I arrive today. Really appreciate your time.

[Sven]

So just to follow up I’ve now left and come back twice and it was working as expected with the new code above. Thanks so much for your insight @michicago