Piston Triggering Twice?

[Ryan780]

1) Give a description of the problem
I am getting double broadcasts to Google Home.

2) What is the expected behavior?
The Piston Fire once.

3) What is happening/not happening?
The piston is firing twice causing two broadcasts.

4) Post a Green Snapshot of the piston

5) Attach any logs (From ST IDE and by turning logging level to Full)
4/12/2018, 8:55:19 AM +245ms
+0ms ╔Received event [Home].time = 1523537720143 with a delay of -899ms
+879ms ║RunTime Analysis CS > 20ms > PS > 826ms > PE > 33ms > CE
+882ms ║Runtime (40787 bytes) successfully initialized in 826ms (v0.3.104.20180323) (880ms)
+883ms ║╔Execution stage started
+906ms ║║Cancelling statement #131’s schedules…
+1400ms ║║Executed physical command [Speech Alerts].off() (491ms)
+1401ms ║║Executed [Speech Alerts].off (492ms)
+1404ms ║║Cancelling statement #167’s schedules…
+1417ms ║║Executed virtual command executePiston (7ms)
+1439ms ║║Cancelling statement #131’s schedules…
+1460ms ║║Executed physical command [Speech Alerts].off() (17ms)
+1461ms ║║Executed [Speech Alerts].off (19ms)
+1464ms ║║Cancelling statement #167’s schedules…
+1476ms ║║Executed virtual command executePiston (7ms)
+1479ms ║╚Execution stage complete. (596ms)
+1480ms ╚Event processed successfully (1480ms)
4/12/2018, 8:55:00 AM +527ms
+1ms ╔Received event [Home].wc_async_reply = httpRequest with a delay of 1ms
+8890ms ║RunTime Analysis CS > 18ms > PS > 8830ms > PE > 41ms > CE
+8891ms ║Piston waited at a semaphore for 8768ms
+8893ms ║Runtime (40811 bytes) successfully initialized in 8830ms (v0.3.104.20180323) (8892ms)
+8894ms ║╔Execution stage started
+8895ms ║╚Execution stage complete. (1ms)
+8897ms ║Setting up scheduled job for Thu, Apr 12 2018 @ 8:55:20 AM EDT (in 10.72s), with 1 more job pending
+8907ms ╚Event processed successfully (8907ms)
4/12/2018, 8:55:00 AM +295ms
+0ms ╔Received event [Home].wc_async_reply = httpRequest with a delay of 0ms
+8990ms ║RunTime Analysis CS > 18ms > PS > 8942ms > PE > 31ms > CE
+8992ms ║Piston waited at a semaphore for 8876ms
+8994ms ║Runtime (40811 bytes) successfully initialized in 8942ms (v0.3.104.20180323) (8992ms)
+8994ms ║╔Execution stage started
+8995ms ║╚Execution stage complete. (1ms)
+8997ms ║Setting up scheduled job for Thu, Apr 12 2018 @ 8:55:20 AM EDT (in 10.852s), with 1 more job pending
+9007ms ╚Event processed successfully (9007ms)
4/12/2018, 8:54:59 AM +119ms
+0ms ╔Received event [Home].time = 1523537700000 with a delay of -882ms
+110ms ║RunTime Analysis CS > 19ms > PS > 68ms > PE > 23ms > CE
+112ms ║Runtime (40737 bytes) successfully initialized in 68ms (v0.3.104.20180323) (111ms)
+113ms ║╔Execution stage started
+123ms ║║Comparison (string) :10ce40f8d22974532815992ec1f4d574: is_not (string) :ee9bdca69a7b039efb14d0cc92a5eae8: = true (2ms)
+124ms ║║Condition #169 evaluated true (5ms)
+125ms ║║Condition group #null evaluated true (state did not change) (6ms)
+131ms ║║Comparison (datetime) 1523537699247 happens_daily_at (datetime) 1523537700000 = true (1ms)
+132ms ║║Time restriction check passed
+133ms ║║Cancelling condition #155’s schedules…
+134ms ║║Condition #155 evaluated true (6ms)
+135ms ║║Cancelling statement #155’s schedules…
+139ms ║║Requesting time schedule wake up at Thu, Apr 12 2018 @ 8:55:00 AM EDT
+142ms ║║Cancelling condition #152’s schedules…
+143ms ║║Condition group #152 evaluated true (state changed) (15ms)
+154ms ║║Comparison (enum) on is (string) on = true (2ms)
+155ms ║║Condition #165 evaluated true (10ms)
+156ms ║║Condition group #153 evaluated true (state did not change) (11ms)
+157ms ║║Cancelling statement #153’s schedules…
+489ms ║║Calculating (string) The meeting + (string) Kick off Presentation Review >> (string) The meeting Kick off Presentation Review
+492ms ║║Calculating (string) The meeting Kick off Presentation Review + (string) is beginning in 5 minutes. >> (string) The meeting Kick off Presentation Review is beginning in 5 minutes.
+963ms ║║Executed physical command [Bathroom Speaker].speak([The meeting Kick off Presentation Review is beginning in 5 minutes.]) (465ms)
+965ms ║║Executed [Bathroom Speaker].speak (469ms)
+975ms ║║Comparison (enum) on is (string) on = true (1ms)
+977ms ║║Condition #166 evaluated true (9ms)
+978ms ║║Condition group #159 evaluated true (state did not change) (10ms)
+979ms ║║Cancelling statement #159’s schedules…
+985ms ║║Calculating (string) http://192.168.1.17:3000/customBroadcast?text=The meeting + (string) Kick off Presentation Review >> (string) http://192.168.1.17:3000/customBroadcast?text=The meeting Kick off Presentation Review
+988ms ║║Calculating (string) http://192.168.1.17:3000/customBroadcast?text=The meeting Kick off Presentation Review + (string) is beginning in 5 minutes.&user=ryan >> (string) http://192.168.1.17:3000/customBroadcast?text=The meeting Kick off Presentation Review is beginning in 5 minutes.&user=ryan
+997ms ║║Sending internal web request to: 192.168.1.17:3000/customBroadcast?text=The%20meeting%20%20Kick%20off%20Presentation%20Review%20is%20beginning%20in%205%20minutes.&user=ryan
+999ms ║║Executed virtual command httpRequest (4ms)
+1015ms ║║Requesting a wake up for Thu, Apr 12 2018 @ 8:55:20 AM EDT (in 20.0s)
+1039ms ║║Comparison (string) :10ce40f8d22974532815992ec1f4d574: is_not (string) :ee9bdca69a7b039efb14d0cc92a5eae8: = true (2ms)
+1041ms ║║Condition #169 evaluated true (6ms)
+1042ms ║║Condition group #null evaluated true (state did not change) (8ms)
+1048ms ║║Comparison (datetime) 1523537700164 happens_daily_at (datetime) 1523537700000 = true (1ms)
+1049ms ║║Time restriction check passed
+1050ms ║║Condition #155 evaluated true (5ms)
+1051ms ║║Cancelling statement #155’s schedules…
+1055ms ║║Condition group #152 evaluated true (state did not change) (11ms)
+1065ms ║║Comparison (enum) on is (string) on = true (2ms)
+1066ms ║║Condition #165 evaluated true (8ms)
+1067ms ║║Condition group #153 evaluated true (state did not change) (9ms)
+1068ms ║║Cancelling statement #153’s schedules…
+1076ms ║║Calculating (string) The meeting + (string) Kick off Presentation Review >> (string) The meeting Kick off Presentation Review
+1079ms ║║Calculating (string) The meeting Kick off Presentation Review + (string) is beginning in 5 minutes. >> (string) The meeting Kick off Presentation Review is beginning in 5 minutes.
+1185ms ║║Executed physical command [Bathroom Speaker].speak([The meeting Kick off Presentation Review is beginning in 5 minutes.]) (103ms)
+1186ms ║║Executed [Bathroom Speaker].speak (105ms)
+1199ms ║║Comparison (enum) on is (string) on = true (2ms)
+1201ms ║║Condition #166 evaluated true (11ms)
+1202ms ║║Condition group #159 evaluated true (state did not change) (13ms)
+1204ms ║║Cancelling statement #159’s schedules…
+1213ms ║║Calculating (string) http://192.168.1.17:3000/customBroadcast?text=The meeting + (string) Kick off Presentation Review >> (string) http://192.168.1.17:3000/customBroadcast?text=The meeting Kick off Presentation Review
+1217ms ║║Calculating (string) http://192.168.1.17:3000/customBroadcast?text=The meeting Kick off Presentation Review + (string) is beginning in 5 minutes.&user=ryan >> (string) http://192.168.1.17:3000/customBroadcast?text=The meeting Kick off Presentation Review is beginning in 5 minutes.&user=ryan
+1226ms ║║Sending internal web request to: 192.168.1.17:3000/customBroadcast?text=The%20meeting%20%20Kick%20off%20Presentation%20Review%20is%20beginning%20in%205%20minutes.&user=ryan
+1229ms ║║Executed virtual command httpRequest (4ms)
+1231ms ║║Requesting a wake up for Thu, Apr 12 2018 @ 8:55:20 AM EDT (in 20.0s)
+1236ms ║╚Execution stage complete. (1123ms)
+1238ms ║Setting up scheduled job for Thu, Apr 12 2018 @ 8:55:20 AM EDT (in 19.787s), with 1 more job pending
+1461ms ╚Event processed successfully (1460ms)

[allrak]

Are you sure the piston is actually firing twice?
I looks like you have 2 statements to broadcast over speakers.
The WITH @speakers, and also the JSON post?

[TN_Oldman]

Not sure if it’s related , but my " date time happens daily @ ??" pistons are also sending double text messages at the appropriate time. It Appears to have started doubling up yesterday.

I haven’t had time to really investigate it yet. Just seemed an odd coincidence that he is using the same trigger as me and we are both getting double results?

[Ryan780]

Yes, one goes to one set of regular dumb speaker and the other broadcasts to google home.

[Ryan780]

Yeah…that is odd. It looks like in the logs it is scheduling another execution for 20 seconds later. I can’t imagine why.

+1015ms ║║Requesting a wake up for Thu, Apr 12 2018 @ 8:55:20 AM EDT (in 20.0s)

[TN_Oldman]

Okay, I just watched mine. It ran the execution twice?

If you don’t mind I’m going to dump my logs here too, because I think we are seeing the same result using the same type trigger.

I used an image vice the actual logs So I could highlight the time check and send parts that are occurring twice? It looks like that is also happening in @Ryan780 piston.

[TN_Oldman]

My piston is VERY simple. It appears to be suffering from same symptoms as Ryan’s.

I wonder if it has something to do with the fact we are using a variable for the time check? Vice a set time.

[allrak]

I ran the following as a test and it performed as expected, only one “testing” was sent to my sonos.

I’m using a local variable as opposed to a global

EDIT: yeah, this does seem strange… Even though I got only one event on the speaker, it looks like it sent it twice in the logs?

4/12/2018, 11:00:59 AM +123ms
+0ms ╔Received event [Home].time = 1523545260000 with a delay of -878ms
+133ms ║RunTime Analysis CS > 21ms > PS > 44ms > PE > 68ms > CE
+135ms ║Runtime (37547 bytes) successfully initialized in 44ms (v0.3.104.20180323) (134ms)
+136ms ║╔Execution stage started
+146ms ║║Comparison (datetime) 1523545259266 happens_daily_at (time) 39660000 = true (0ms)
+148ms ║║Time restriction check passed
+149ms ║║Cancelling condition #4’s schedules…
+150ms ║║Condition #4 evaluated true (7ms)
+151ms ║║Cancelling statement #4’s schedules…
+163ms ║║Requesting time schedule wake up at Thu, Apr 12 2018 @ 11:01:00 AM EDT
+168ms ║║Cancelling condition #1’s schedules…
+169ms ║║Condition group #1 evaluated true (state changed) (26ms)
+171ms ║║Cancelling statement #2’s schedules…
+312ms ║║Executed physical command [Sonos - Portable].playText([testing]) (134ms)
+313ms ║║Executed [Sonos - Portable].playText (136ms)
+316ms ║║Fast executing schedules, waiting for 562ms to sync up
+889ms ║║Comparison (datetime) 1523545260009 happens_daily_at (time) 39660000 = true (1ms)
+890ms ║║Time restriction check passed
+891ms ║║Condition #4 evaluated true (6ms)
+892ms ║║Cancelling statement #4’s schedules…
+898ms ║║Condition group #1 evaluated true (state did not change) (13ms)
+901ms ║║Cancelling statement #2’s schedules…
+993ms ║║Executed physical command [Sonos - Portable].playText([testing]) (88ms)
+994ms ║║Executed [Sonos - Portable].playText (90ms)
+997ms ║╚Execution stage complete. (861ms)
+999ms ╚Event processed successfully (1000ms)

[TN_Oldman]

Yes it does, look like ours where it sent the command twice??

[TN_Oldman]

Nobody’s got anything? No Ideas?

@Robin or any of the other Webcore Guru’s offer any help or explain why this has started recently?

[Robin]

No idea?

@webCoRE_Minions

[bangali]

ST is firing the time trigger a minute early. so at the end of the piston execution when the time trigger gets scheduled again its rescheduled for the same time as it was just triggered for causing the piston to execute twice.

seems like ST is compensating for all those times when they fired time triggers a minute or more late.

[TN_Oldman]

@bangali, @Robin Thank you for the reply.

Is any of the Minions in semi contact with smarthings staff? Possibly let them know there is side effects to their recent changes?

[Robin]

Possible fix might be to add a few minutes wait at the end of your piston so it won’t subscribe the next run straight away.

Maybe @ady624 could give them a nudge.

@ST_Staff

[Ryan780]

That’s a good idea! Would I have to change cancellation policy or anything like that to get that to work right? (I still don’t get that part 100% yet.) Thanks so much for your help.

Also, evidently this is affecting SmartLighting automations as well. Someone on the main forum posted about his SmartLighting programs executing 2 mins early. Sounds kind of related.

[eibyer]

Bad case of premature execution

[Ryan780]

LMAO…I was wondering if someone was going to go there. I’m glad I’m not the only perv that thought that and proud that I held out saying it longer than at least one other person. Thanks @eibyer, I don’t feel quite so bad now.

[TN_Oldman]

Just wanted to update, I only got single messages today. No doubles like the last couple of days.

[Ryan780]

I tried this and the piston is still triggering twice. Do I need to change cancellation policy or some other setting to not have the piston trigger twice?

[TN_Oldman]

I have days I get one message and others I get duplicates. Nothing changes in the piston. So I assume it’s a smarthings issue.