SmartThings timestamp issue (I think) breaking rules

[bennywy]

I have 50-ish rules in Rule Engine and they have the most part (other than minor SmartThings quirks) have worked flawlessly for years. Within the past couple of weeks, things just don’t seem to work. Either lights don’t turn on or they turn on and won’t turn off. At first I thought it was an issue with the “stay” command (very similar to what this user was having - [Stays on no longer working in rules - #3 by Brian_Taylor]), but now I just think it is an issue with the timestamps that SmartThings is reporting back to Rule Engine.

To isolate the noise, I made a simple automation that triggers based on a motion sensor updating. Then if the motion sensor is active, it turns the light on. If it is inactive, it delays the rule for 15 seconds, checks that the motion has stayed inactive for 10 seconds, and if yes, turns the light off.

The light doesn’t even reliably turn on in the scenario. I believe what’s happening is that the rule is triggered correctly when there is motion. Although the motion should be active, SmartThings reports an inactive motion from slightly earlier (less than a second). In the attached log, you can see that the rule is triggered at 10:13:41 CDT. When the “if motion is active” condition is tested, SmartThings appears to report the motion from just a bit earlier (10:13:02) when the sensor was still inactive, which causes the light to not turn on. Same thing happens in reverse (i.e., triggered by motion inactive, but SmartThings sends an active status from shorter earlier, ending the rule and leaving the light on indefinitely).

I’ve never asked for help on here before, so please let me know if you need anything else to help troubleshoot. I’ve attached screenshots of my rule and the relevant portions of the log. Thanks in advance!

[bennywy]

(post deleted by author)

[bennywy]

(post deleted by author)

[josh]

Hi Benny-
Welcome to community and thanks for posting! Sorry to hear that things aren’t working as expected.

@bennywy

The light doesn’t even reliably turn on in the scenario. I believe what’s happening is that the rule is triggered correctly when there is motion. Although the motion should be active, SmartThings reports an inactive motion from slightly earlier (less than a second)

There’s a better rule design that can be used here. Instead of querying the smart hub for the current state, you can directly use the triggered event in the comparison using a Context Variable for the Event Value. That way the rule is directly comparing against the same event value that triggered the rule rather than trying to query the smart home hub where there could be discrepancies (old values if the new value hasn’t persisted yet, or fast changing new values already reported)

Context Variables (Rule Engine) - SharpTools Knowledge Base

---

@bennywy

At first I thought it was an issue with the “stay” command (very similar to what this user was having - [Stays on no longer working in rules - #3 by Brian_Taylor]), but now I just think it is an issue with the timestamps that SmartThings is reporting back to Rule Engine.

Once the comparison against the triggering event value is fixed, it would be interesting to see the logs for the State Stays nested condition.

It is possible that you’re experiencing a similar issue with the weird timestamp reporting with certain drivers. That issue is specific to State Stays comparisons though as the

Explanation of State Stays and the Trigger Issue (tap to expand)

@josh

…when we checked the details of the rule log showing the state stays failed, we saw that the timestamp of the state was 2 seconds later than the reported event timestamp which is why the system was thinking that another event must have occurred (per the timestamp from the state being later than the original triggering event) and thus the state stays condition wasn’t passed.

@josh

After the specified state stays delay in your rule, the system asks SmartThings for the current state so it can compare the timestamp and make sure it hasn’t changed since the originally received timestamp. Something funky seems to be going on as SmartThings is replying that the timestamp associated with the current state is several minutes after the timestamp of the event that the system received…so the system thinks that another event must have come through since the timestamps are so different.

@josh

Normally when a device reports its state, if it reports the same state again, SmartThings keeps the existing timestamp recorded for the state (even though it might internally record an ‘event’).

It seems like in both of your cases, the state is showing a newer timestamp at a later point when the State Stays part of the rule checks to verify that the current state matches the originally snapshotted state from when the event first came in.

The workaround that I deployed in December is for incorrect timestamps reported within State Stays within the Trigger of a rule. It basically snapshots event values as they come across so it can locally cache its own interpretation of when the state changed rather than having to query the smart hub (SmartThings) to ask for the current state so it can use the reported value + timestamp to determine if the value changed or not (eg. if it’s the same timestamp and value as the original event, then it didn’t change).

For State Stays within a condition, the rule engine must query the hub to ask for the current state (value+timestamp) and then it compares if that timestamp is older than the duration you are interested in.

The approach you used with using a shorter State Stays duration compared to your delay is a good approach as with distributed systems there’s a possibility for slight time skew and such.

[bennywy]

Thank you Josh! Let me educate myself on context variables and try to incorporate it into my test rule. If it fixes my issues, I have a lot of rules to revise . I’ll stop back here if I run into any issues.

[bennywy]

So I implemented the context variable in my rule and that seems to have fixed the light not turning on. But the light still isn’t turning off coming off the 15 second delay. I still have the State Stays within the condition, so it is querying the hub like you said. The attached log is coming off the 15 second delay. Is it reporting back that there was motion within the ten second duration? I can confirm that there was no motion since the rule was triggered by motion being inactive.

Thanks

[josh]

Is this for the rule Stay test rule?

TLDR:

• SmartThings is reporting the old state
• Workaround with distinct triggers (more details below)
  • In Triggers, implement a separate motion = ‘active’ and separate motion stays ‘inactive’ trigger
  • In the Flow compare against the $context.event.value to know what action to take (light on or off)

Recent Executions: Good

Looking at the recent logs, here’s what I see:

• 3:45:17 PM motion = inactive

  • IF Condition not matched (motion = 'active') → ELSE
  • Pausing 15 seconds
  • IF Condition matched (motions stays 'inactive' 10s) → THEN
  • Office Hallway: off()

• 3:54:49 PM motion = active

  • IF Condition matched (motion = 'active') → THEN
  • Office Hallway: setLevel(50)

• 3:54:54 PM motion = inactive

  • IF Condition not matched (motion = 'active') → ELSE
  • Pausing 15 seconds
  • IF Condition matched (motions stays 'inactive' 10s) → THEN
  • Office Hallway: off()

And the same again at the 4:14 PM CDT executions from the active and inactive triggers.

---

Earlier Execution: Failed

It’s not clear to me exactly when the rule was saved, but I’m guessing it was after the 2:46 PM CDT evaluations since those showed the IF Condition being evaluated against the attribute name.

It wasn’t until the first 2:54:50 PM execution that the first IF Condition was evaluated against $context.event.value properly.

• 2:54:50 PM motion = active

  • IF Condition matched (motion = 'active') → THEN
  • Office Hallway: setLevel(50)

• 2:55:01 PM motion = inactive

  • IF Condition not matched (motion = 'active') → ELSE
  • Pausing 15 seconds
  • IF Condition not matched (motions stays 'inactive' 10s) → ELSE

Unfortunately, it seems like it could some sort of delay on the SmartThings side with updating the recorded state.

Time	Step	Description
2:54:49.972	1	active event
2:55:01.000	2	inactive event
2:55:17.901	2c	State Stays check evaluation after delay SmartThings returns the state value/timestamp matching original event 1

Workaround

Since it seems like SmartThings is reporting the old state or is otherwise delayed in updating their internal recording of the state (even though the events are emitting on time), you could split the rule out into two separate rules.

This would take advantage of the enhancements we added to State Stays Triggers which uses its own internal evaluation of ‘State Stays’ based on received events so it doesn’t have to rely on querying the smart home hub for the reported state to determine if the state changed.

It would be two simple rules like:

Rule 1:
Trigger: ‘motion’ changes to ‘active’
Flow: Office Hallway: setLevel(50)

Rule 2:
Trigger: ‘motion’ stays ‘inactive’ for X seconds
Flow: Office Hallway: off()

–

Alternatively, you probably could combine these into a single rule like:

Triggers:

• ‘motion’ changes to ‘active’
• ‘motion’ stays ‘inactive’ for X seconds

Flow

IF $context.event.value = 'active'
  THEN Office Hallway setLevel(50)
  ELSE Office Hallway off()

The idea being that each trigger is distinct enough and covers the exact scenario that each needs to handle – the first trigger is only fired when the motion changes to ‘active’ whereas the second only triggers when the motion stays ‘inactive’.

That enables you to use the $context.event.value to know that it’s either the motion immediately having become active and thus you need to turn the light on or the motion has stayed inactive and thus you want to turn it off.

Basically the immediate change to ‘inactive’ wont ever actually trigger the rule – it has to stay inactive otherwise it wouldn’t trigger the rule.

[bennywy]

Thanks again for all your help! I’m trying to do this in the least painless way as possible since I have soooo many rules that follow a similar framework. I decreased the stay duration so that it only checks for motion for previous ten seconds after a 20 second delay. It isn’t ideal but barely noticeable in practice. I think that gives enough buffer to compensate for the SmartThings recent delays.

I like your alternative recommendation though (the one that comes the two triggers in a single rule). That seems feasible and I may go that route if the delays get any worse.

The context variable is a game changer though so I’m very thankful you steered me down that route. It seems to make things much snappier.

Thanks again!