Duplicate SMS Notifications

#1

I have a Piston that has been working well for almost 2 years. About 2 months ago it started something strange.

  • The Piston was designed to open a door (turn on a switch) everyday at 9 minutes past sunrise if the temperature of a device was over 30*. If the door was opened it would send a SMS notification to 2 phones. If the temperature condition was not true, it would send a different SMS notification to those phones and not open the door.

About a month ago, it started sending the same SMS to each phone twice, about a minute or less apart. I really don’t want 2 notices.

In order to get to the bottom of this, I broke up the original Piston removing the Task of sending the SMS notification. I then created a separate Piston that would just send the SMS notification if the switch was on… simple enough. Well… I got 2 SMS notifications this morning.

The simplified Piston and the Logs are attached. Could it be because I’m sending to 2 phones?

Report-1
Report-1.png1172×429 23.4 KB

Logs

9/15/2021, 7:15:59 AM +182ms
+0ms ╔Received event [Home].time = 1631704560000 with a delay of -818ms
+66ms ║RunTime Analysis CS > 39ms > PS > 7ms > PE > 19ms > CE
+68ms ║Runtime (38418 bytes) successfully initialized in 7ms (v0.3.113.20210203) (67ms)
+69ms ║╔Execution stage started
+95ms ║║Comparison (time) 26159255 happens_daily_at (datetime) 1631703660000 = true (0ms)
+96ms ║║Time restriction check passed
+98ms ║║Condition #3 evaluated true (24ms)
+99ms ║║Cancelling statement #3’s schedules…
+102ms ║║Requesting time schedule wake up at Thu, Sep 16 2021 @ 7:16:00 AM EDT
+113ms ║║Comparison (enum) on is (string) on = true (1ms)
+114ms ║║Condition #4 evaluated true (10ms)
+115ms ║║Condition group #1 evaluated true (state did not change) (42ms)
+117ms ║║Cancelling statement #8’s schedules…
+134ms ║║Executed virtual command sendSMSNotification (13ms)
+136ms ║╚Execution stage complete. (67ms)
+137ms ║Setting up scheduled job for Thu, Sep 16 2021 @ 7:16:00 AM EDT (in 86400s)
+144ms ╚Event processed successfully (144ms)
9/15/2021, 7:14:59 AM +155ms
+1ms ╔Received event [Home].time = 1631704500000 with a delay of -845ms
+62ms ║RunTime Analysis CS > 37ms > PS > 7ms > PE > 18ms > CE
+65ms ║Runtime (38423 bytes) successfully initialized in 7ms (v0.3.113.20210203) (64ms)
+66ms ║╔Execution stage started
+95ms ║║Comparison (time) 26099228 happens_daily_at (datetime) 1631703660000 = true (1ms)
+96ms ║║Time restriction check passed
+98ms ║║Cancelling condition #3’s schedules…
+99ms ║║Condition #3 evaluated true (25ms)
+100ms ║║Cancelling statement #3’s schedules…
+103ms ║║Requesting time schedule wake up at Wed, Sep 15 2021 @ 7:16:00 AM EDT
+115ms ║║Comparison (enum) on is (string) on = true (1ms)
+116ms ║║Condition #4 evaluated true (11ms)
+117ms ║║Cancelling condition #1’s schedules…
+118ms ║║Condition group #1 evaluated true (state changed) (46ms)
+120ms ║║Cancelling statement #8’s schedules…
+134ms ║║Executed virtual command sendSMSNotification (9ms)
+137ms ║╚Execution stage complete. (71ms)
+138ms ║Setting up scheduled job for Wed, Sep 15 2021 @ 7:16:00 AM EDT (in 60s)
+146ms ╚Event processed successfully (146ms)

#2

The logs are showing the piston running at 7:15am which is presumably yesterday’s sunrise time + 15 minutes (pistons set their own next scheduled execution as it didn’t yet know about today’s sunrise time). When it runs it picks up today’s sunrise time + 15, which it seems is 7:16am and as that is sufficiently far in the future it is today’s 7:16am that is used. That is all fairly normal stuff as the days shorten so I am surprised you haven’t had issues before.

What is somewhat puzzling me is that the timestamp shown in the condition in the logs is, I think, 7:01am in your timezone and doesn’t change. That might well be sunrise if the offset is handled elsewhere but I’d still expect the comparison to change. I’ve not looked closely for a while though.

Is there any particular reason you use the $sunrise variable rather than just sunrise?

#3

Hmmm. I didn’t know there was a sunrise AND a $sunrise. I’ll take a look for it. What is the difference? I’m assuming the $ means something…

And nope… for around 2 years I got 1 SMS every day, no issues… Strange.

Also strange is it being “yesterday’s Sunrise”, as I only created this one last night, and it was already after yesterday’s sunrise…

#4

Leave you piston as it is and just add a new blank timer at the bottom:

Every day at 00:01, do nothing.

This will force the piston to fire up, do nothing, then schedule the correct sunrise time for the day in question. Without this it is using todays sunrise time for tomorrows execution, hence running twice as it fires early and then schedules itself for the correct time on the same day.

#5

I want to make sure I understand this correctly…So the piston fires using yesterday’s sunrise time, say 7:01. And then fires again at the correct sunrise time for today, say 7:02 ?

I love this, but do we have to do this with each of these particular sunrise situations? Or is there a better way to code this?

#6

Correct

I’m afraid it is a limitation on the data provided by ST for the sunrise times, ST does not provide a method for pulling tomorrows sunrise so WC has to make do with todays.

This is often not an issue, i.e. a light getting told to turn on twice in quick succession, but with some pistons it can result in double trigger like you are getting.

I wouldn’t say change them all, just the ones where the limitation is showing itself as a bug.

#7

Hubitat?

#8

Same thing I believe… both pull their sunset / sunrise times from somewhere (ST use ‘The
Weather Channel’, HE not sure)

I’m on HE and I have never seen the issue, but none of my sunset / sunrise pistons act as triggers, only conditions with the pistons triggered by other things. The issue is probably still there, just not effecting me for now.

Raises an interesting question though, considering HE runs offline, I’m not entirely sure how it keeps these times in-sync with the real world. Must periodically pull data from time-to-time.

#9

Thanks for the solution ! @Robin

#10

Question on the solution… I tried to add to the bottom as suggested. I got a big orange error stating timers are meant to be top level statements and not to put in the middle or bottom.

I don’t see how to add it to the top. Should I just re-do the Piston and start with the timer?

#11

You could drag it to the top by toggling the image button and using the grips that appear in the margin, but then your other timer would trigger the same warning.

Just ignore the warning, will work fine.

#12

Problem here:

After adding the “do nothing” at 00:01 to the above Piston, I’m getting the SMS notification at 00:02, something we definitely are not interested in… ugggh! Do you think if I change the trigger to 00:05 it would help? I’m thinking anytime before the actual trigger to send the SMS notices out might work… or not.

9/18/2021, 7:18:59 AM +59ms
+1ms ╔Received event [Home].time = 1631963940000 with a delay of -941ms
+50ms ║RunTime Analysis CS > 23ms > PS > 5ms > PE > 22ms > CE
+52ms ║Runtime (38806 bytes) successfully initialized in 5ms (v0.3.113.20210203) (51ms)
+53ms ║╔Execution stage started
+79ms ║║Comparison (time) 26339119 happens_daily_at (time) 1631963040000 = true (1ms)
+80ms ║║Time restriction check passed
+81ms ║║Cancelling condition #3’s schedules…
+82ms ║║Condition #3 evaluated true (23ms)
+83ms ║║Cancelling statement #3’s schedules…
+88ms ║║Requesting time schedule wake up at Sun, Sep 19 2021 @ 7:19:00 AM EDT
+97ms ║║Comparison (enum) on is (string) on = true (2ms)
+98ms ║║Condition #4 evaluated true (8ms)
+99ms ║║Cancelling condition #1’s schedules…
+100ms ║║Condition group #1 evaluated true (state changed) (41ms)
+102ms ║║Cancelling statement #8’s schedules…
+153ms ║║Executed virtual command sendSMSNotification (47ms)
+156ms ║╚Execution stage complete. (103ms)
+158ms ║Setting up scheduled job for Sun, Sep 19 2021 @ 12:01:00 AM EDT (in 60120s), with 1 more job pending
+165ms ╚Event processed successfully (165ms)
9/18/2021, 12:02:36 AM +85ms
+0ms ╔Received event [Home].execute = recovery with a delay of 55ms
+50ms ║RunTime Analysis CS > 21ms > PS > 6ms > PE > 23ms > CE
+52ms ║Runtime (38798 bytes) successfully initialized in 6ms (v0.3.113.20210203) (51ms)
+53ms ║╔Execution stage started
+77ms ║║Comparison (time) 156144 happens_daily_at (time) 1631963040000 = false (0ms)
+79ms ║║Cancelling condition #3’s schedules…
+80ms ║║Condition #3 evaluated false (21ms)
+81ms ║║Cancelling statement #3’s schedules…
+85ms ║║Requesting time schedule wake up at Sat, Sep 18 2021 @ 7:19:00 AM EDT
+88ms ║║Cancelling condition #1’s schedules…
+89ms ║║Condition group #1 evaluated false (state changed) (29ms)
+112ms ║║Comparison (enum) off is_not (string) on = true (1ms)
+113ms ║║Condition #5 evaluated true (23ms)
+114ms ║║Condition group #2 evaluated true (state did not change) (25ms)
+116ms ║║Cancelling statement #6’s schedules…
+127ms ║║Executed virtual command sendSMSNotification (6ms)
+131ms ║╚Execution stage complete. (78ms)
+133ms ║Setting up scheduled job for Sat, Sep 18 2021 @ 7:19:00 AM EDT (in 26183s), with 1 more job pending
+143ms ╚Event processed successfully (143ms)
9/18/2021, 12:02:35 AM +679ms
+0ms ╔Received event [Home].time = 1631937660000 with a delay of 95679ms
+100ms ║RunTime Analysis CS > 68ms > PS > 7ms > PE > 25ms > CE
+103ms ║Runtime (38804 bytes) successfully initialized in 7ms (v0.3.113.20210203) (102ms)
+104ms ║╔Execution stage started
+114ms ║╚Execution stage complete. (11ms)
+116ms ║Setting up scheduled job for Sat, Sep 18 2021 @ 7:18:00 AM EDT (in 26124s), with 1 more job pending
+123ms ╚Event processed successfully (123ms)

ScreenShot
ScreenShot.png1171×325 16.6 KB

#13

What has happened there is that the timer for your piston has arrived 95 seconds late for whatever reason and that has caused a recovery event to be sent. Your piston is not sympathetic to recovery events.

Every time a piston executes it will run some additional code that checks whether any scheduled timers for other pistons are more than 30 seconds late. There is also a general recovery routine that runs regularly (you’ll see it mentioned in the webCoRE SmartApp settings) and does the same thing. If any timers are found running late, a recovery event is sent to the piston to make it execute. That allows the piston to schedule its next execution - something that would not otherwise have happened unless the timer did eventually turn up.

However the piston may do other things you don’t want it to when the recovery is processed. A useful tip with any piston is to try it with the ‘Test’ button to see what happens. If it is something undesirable then a recovery event is likely to have the same effect.

In your case the timer event did run correctly, but a fraction of a second later the recovery event arrived. Just as it would if you pressed the ‘Test’ button, your piston did what it was told. It checked if the time was sunrise+15 and it wasn’t, so it moved on to the else and checked if the switch was not on and indeed it wasn’t on. So it sent you a notification. It also made sure the next run was scheduled.

What you really need for your ‘if’ is

if time happens daily at 15 minutes past sunrise
then
    if switch 4 switch is on
    then send SMS to say the door is open
    else send SMS to say the door is not open
    endif
endif

That way both the texts are conditional on the time.

#14

Thanks for the help @orangebucket. This Piston was originally as you are suggesting. (See 1st Piston screenshot). I ran it both ways, $sunrise, and sunrise. The original problem was that i was getting duplicate SMS notifications 1 minute apart at the correct time. @Robin suggested the “do nothing” that solved the duplicate SMS problem at the correct time, but created an SMS message at 00:02. (Undesirable)

I almost always use the test button, and in this case it didn’t trigger an SMS because neither time was true.

#15

It’s your use of ‘else if’… the recovery definitely triggered it. The switch was off so the ‘else if’ ran.

I prefer to use if / else, rather than ‘else if’. I also prefer to use ‘every day’ instead of ‘IF time happens daily’

Note that each block of ‘Every day’, in the purple brackets, effectively runs as independent piston / sandbox, one running will never trigger the other. And ‘test’ will never trigger anything.

Try this piston:

image
image.png1178×536 28.3 KB

#16

I’ll try tonight… We’ll know soon… I think your explanation makes sense!!

#17

It worked perfectly! THANK YOU!!