Rule Machine Announce HSM State

vasilios · May 2, 2022, 8:27pm

Hey all, trying a simple (I thought) rule to basically announce the HSM state on a Google Mini as it changes. It works fine for "arming", "armed" but then when it goes to "disarmed", I am getting the "armed" message (HSM does disarm correctly).

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:06.223 pm [info](https://<hubitat>/installedapp/configure/1358)Action: END-IF

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:06.221 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: END-IF~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:06.218 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: Speak on Office Mini(volume: 80): 'Alarm has been Disarmed.'~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:06.214 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: IF (HSM status is Disarmed(T) [TRUE]) THEN~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:06.193 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: ELSE~~ (skipping)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:06.191 pm [info](https://<hubitat>/installedapp/configure/1358)Action: END-IF

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:06.188 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: Speak on Office Mini(volume: 80): 'Alarm has been Armed Home.'~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:06.184 pm [info](https://<hubitat>/installedapp/configure/1358)Action: IF (HSM status is Armed Home(F) [FALSE]) THEN (skipping)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:06.155 pm [info](https://<hubitat>/installedapp/configure/1358)Action: ELSE (do actions)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:06.103 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: Speak on Office Mini(volume: 80): 'Arming Alarm in 15 seconds.'~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:06.098 pm [info](https://<hubitat>/installedapp/configure/1358)Action: IF (HSM status is Delayed Arming Home(F) [FALSE]) THEN (skipping)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:05.952 pm [info](https://<hubitat>/installedapp/configure/1358)Triggered
[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:05.945 pm [info](https://<hubitat>/installedapp/configure/1358)Action: END-IF

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:05.943 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: END-IF~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:05.940 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: Speak on Office Mini(volume: 80): 'Alarm has been Disarmed.'~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:05.935 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: IF (HSM status is Disarmed(T) [TRUE]) THEN~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:05.931 pm [info](https://<hubitat>/installedapp/configure/1358)Event: hsmStatus disarmed

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:05.909 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: ELSE~~ (skipping)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:05.905 pm [info](https://<hubitat>/installedapp/configure/1358)Action: END-IF

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:05.865 pm [info](https://<hubitat>/installedapp/configure/1358)Action: Speak on Office Mini(volume: 80): 'Alarm has been Armed Home.'

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:05.860 pm [info](https://<hubitat>/installedapp/configure/1358)Action: IF (HSM status is Armed Home(T) [TRUE]) THEN

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:05.838 pm [info](https://<hubitat>/installedapp/configure/1358)Action: ELSE (do actions)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:05.835 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: Speak on Office Mini(volume: 80): 'Arming Alarm in 15 seconds.'~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:05.831 pm [info](https://<hubitat>/installedapp/configure/1358)Action: IF (HSM status is Delayed Arming Home(F) [FALSE]) THEN (skipping)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:05.761 pm [info](https://<hubitat>/installedapp/configure/1358)Triggered

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:09:05.748 pm [info](https://<hubitat>/installedapp/configure/1358)Event: hsmStatus armedHome

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:52.795 pm [info](https://<hubitat>/installedapp/configure/1358)Action: END-IF

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:52.792 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: END-IF~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:52.789 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: Speak on Office Mini(volume: 80): 'Alarm has been Disarmed.'~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:52.785 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: IF (HSM status is Disarmed(F) [FALSE]) THEN~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:52.763 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: ELSE~~ (skipping)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:52.761 pm [info](https://<hubitat>/installedapp/configure/1358)Action: END-IF

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:52.733 pm [info](https://<hubitat>/installedapp/configure/1358)Action: Speak on Office Mini(volume: 80): 'Alarm has been Armed Home.'

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:52.728 pm [info](https://<hubitat>/installedapp/configure/1358)Action: IF (HSM status is Armed Home(T) [TRUE]) THEN

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:52.706 pm [info](https://<hubitat>/installedapp/configure/1358)Action: ELSE (do actions)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:52.703 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: Speak on Office Mini(volume: 80): 'Arming Alarm in 15 seconds.'~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:52.699 pm [info](https://<hubitat>/installedapp/configure/1358)Action: IF (HSM status is Delayed Arming Home(F) [FALSE]) THEN (skipping)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:52.563 pm [info](https://<hubitat>/installedapp/configure/1358)Triggered

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:52.536 pm [info](https://<hubitat>/installedapp/configure/1358)Event: hsmStatus armedHome

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:37.797 pm [info](https://<hubitat>/installedapp/configure/1358)Action: END-IF

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:37.794 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: END-IF~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:37.791 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: Speak on Office Mini(volume: 80): 'Alarm has been Disarmed.'~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:37.786 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: IF (HSM status is Disarmed(F) [FALSE]) THEN~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:37.764 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: ELSE~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:37.762 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: END-IF~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:37.759 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: Speak on Office Mini(volume: 80): 'Alarm has been Armed Home.'~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:37.754 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: IF (HSM status is Armed Home(F) [FALSE]) THEN~~ (skipped)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:37.732 pm [info](https://<hubitat>/installedapp/configure/1358)~~Action: ELSE~~ (skipping)

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:37.603 pm [info](https://<hubitat>/installedapp/configure/1358)Action: Speak on Office Mini(volume: 80): 'Arming Alarm in 15 seconds.'

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:37.598 pm [info](https://<hubitat>/installedapp/configure/1358)Action: IF (HSM status is Delayed Arming Home(T) [TRUE]) THEN

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:37.448 pm [info](https://<hubitat>/installedapp/configure/1358)Triggered

[app:1358](https://<hubitat>/logs#pastapp1358)2022-05-02 04:08:37.432 pm [info](https://<hubitat>/installedapp/configure/1358)Event: hsmStatus armingHome

Screenshot 2022-05-02 160959

bertabcd1234 · May 2, 2022, 8:50pm

That should work,* but it looks like your rule is triggering very quickly in succession (disarmed at 4:09:05.931 after being armed for armedHome at 04:09:05.758). What's changing HSM status here, and why is it happening so fast? The second half of your logs (from triggering on armed home to finishing execution after triggering on disarmed) takes less than half a second. My guess is that all states were not updated by the time the IF THEN... was reached, so the evaluation was not yet accurate and the results were therefore unexpected. I would try to pinpoint that issue and fix the likely problem that way.

If that doesn't help, two more ideas:

Post a screenshot or description of your full rule, including triggers and actions (not just actions)
Screenshots of logs are easier to read that raw copy/paste and are more likely to get better help

Additionally, if you're unsure about what's causing the quick re-triggering, sharing any HSM-related app or rule setups may also be useful.

*EDIT: Nevermind,I didn't notice the double "ELSE." My brain filled in ELSE-IFs, which is what I'd use.

vasilios · May 2, 2022, 8:55pm

Hi, thanks for the response. So the full rule is:

I tested this by going into the HSM app and clicking "Arm Home", which triggered the mini to Speak "Arming Home in 15 seconds." Once it's Armed, it announces "Alarm is now Armed Home". After a few seconds I click on Disarm, and it immediately announces "Alarm is now Armed Home" with no other messages. HSM disarms a second later. FWIW I don't see an HSM for "Disarming", so I can't announce on that, but that's beside the problem.

vasilios · May 2, 2022, 8:59pm

I'm wondering if there's a race condition, where disarming causes HSM status to trigger a change before it's actually changed, so it's still in an Armed Home state. I can try maybe adding a 1s delay after change before evaluating what the status actually is to see if that helps (if that's even possible).

bertabcd1234 · May 2, 2022, 9:02pm

Look at the timestamps: the logs say HSM is becoming armedHome at 04:09:06.748, and your rule is triggering shortly thereafter (and, I assume working as expected). But then at 04:09:05.931, it is becoming disarmed. As expected, your rule triggers again. However, my guess, again, is that because these events (and rule executions) happened so quickly, the HSM state was not fully updated by the time it was read in your actions in that last execution, at least not when it reached the first conditional action, thus causing unexpected results.

It does say that HSM is disarmed at that point in your logs but it's skipping the actions anyway, so this is somewhat of a guess, but you could test it by just slowing down the re-triggering of the rule. If this is you manually changing HSM state, just wait a second or two (instead of a fraction of a second ) before disarming it again to test. If this is an app/automation, that will need to be figured out.

If that doesn't help, it's possible there's just something corrupted with the rule. Your rule looks correct, but removing and re-creating it might help in case there's just something wrong beyond fixing at this point.

vasilios · May 2, 2022, 9:07pm

I did wait a few seconds between states.
What I don't understand is why there are two "Armed Home" triggers. Again, click on Arm Home, it triggers Arming, which is fine, then triggers Armed Home, which is fine. Then I wait a few seconds, and if I click on Disarm, the trigger is Armed Home again... this doesn't make sense and sounds like a bug? Or maybe there should be a second "Armed Home" trigger after the first one for some technical reason (and I should wait longer)?

bertabcd1234 · May 2, 2022, 9:12pm

OK, now the logs are making more sense. It's possible that changing to "Disarmed" causes an inadvertent "armedHome" event to occur first (possibly only if you are already in the armedHome state). If you have any apps (including rules) that modify HSM state, then disabling, pausing, or removing them to test--and see if this still happens--would be a good idea. (I do have a spare hub I can test this on to see if it's a problem with a "bare" setup where nothing would be automating HSM, but that's not something I'm able to try at this moment, and I'm not sure it's something I've seen reported before, so it seems unlikely.)

If this is indeed the problem, that may fix the behavior here. But the question is still why that is happening..

vasilios · May 2, 2022, 9:17pm

Thanks, it would be great if someone could perform a sanity check. I don't have any rules controlling HSM AFAIK (just checked) but I will check again. My family just opened all the doors for some fresh air so I need to take a break from playing around with the alarm system for a bit.

Will update after I've had some more time to test (if adding a delay, or simply waiting longer helps).

jkister · May 3, 2022, 5:24am

I’m up past my bedtime, but it looks like your rule has two ELSE statements in there for the same IF. Is rule machine not showing a syntax error ?

bertabcd1234 · May 3, 2022, 5:50am

That's a good catch. I didn't see that and if it "works" at all, if expect it to just use the first (and skip anything else since it's already done one branch of that IF THEN and will only execute zero or one).

My brain saw these as ELSE-IFs, which is what I'd recommend to the OP.

vasilios · May 4, 2022, 2:12am

Sorry my coding logic brain thought I created ELSE-IFS... does ELSE + IF work differently? I'll see if there's an ELSE-IF condition. Is it too much to ask for CASE?

bertabcd1234 · May 4, 2022, 3:18am

I don't think there is anything you can do with switch/case that you can't do with IF THEN/ELSE-IF/ELSE, just a different syntax. But the format you probably want is ELSE-IF instead of ELSE and IF separately, though you can create more or less equivalent logic in some cases; however, only one ELSE is per IF-THEN is valid, though, so what you have above definitely won't work.

vasilios · May 6, 2022, 5:04am

So I updated the rules to use the new ELSE-IF conditionals:

It hasn't changed what happens with the behavior. I waited for a long while before disarming. Immediately upon hitting the disarm button in HSM it announces "Alarm has been armed home" which it will do after the countdown when I actually arm. The second message doesn't play. For some reason, disarming triggers a change but it's in an "Armed State" before triggering a "Disarmed" state somewhere in the middle. The disarmed message never plays. I think this is a bug at this point, no?

bertabcd1234 · May 6, 2022, 5:45am

Action logs would be helpful to confirm that behavior, but it does seem that, like before, your HSM might be sending an unexpected "armed" state event immediately before disarming (and sending that event), which would indeed be unexpected--assuming you don't have any unusual rules or HSM configuration that might be causing this on its own. A delay might help work around this problem if it's just quick successive re-triggering that is causing this oddity, likely a byproduct of simultaneous or nearly so execution, but trying to identify the underlying issue might be better in any case. It's not something I've seen reported before, but would be pretty easy for someone to test on a hub they aren't using HSM on (maybe me when I have more time :D).