Rule Machine Announce HSM State

[vasilios]

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

[bertabcd1234]

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:

1. Post a screenshot or description of your full rule, including triggers and actions (not just actions)
2. 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]

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]

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]

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]

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]

@vasilios

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

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]

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]

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]

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]

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]

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]

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]

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).

[vasilios]

So I've come back to this after a bit and I can say not amount of delay cures the issue. There is something in the sequence that is broken. Even sending a message to my phone (and not playing on the Mini) shows the same behavior. I get duplicate messages. I think it has something to do with having multiple keypads. The first one starts beeping and the countdown begins but there is a delay on the second ones, their countdown starts and ends later. In other words, it's not that the keypad says "start arming" to the hubitat, then the hubitat tells all the keypads to count down, which would be ideal. When I hit Arm on the keypad, it goes into its arming then armed, and the hubitat has to relay this information to other keypads to arm themselves. In fact, it makes a lot of sense now that when I have a contact switch open, HSM fails to arm, but the keypad itself continues down to an Armed state. The other keypads don't arm. If I arm from HSM itself, all keypads count down together, or don't at all if a contact is open. It would be nice to see if there's a way to change the behavior of the keypad to sending a signal to hubitat when the arm button is hit but only start countdown when hubitat itself tells the keypads to arm. I believe this would also eliminate the double message issue.

[bertabcd1234]

What do the logs say is happening? (Enable event, trigger, and action logging.)

[vasilios]

Wow, ok... so I tried testing it tonight and I could not recreate it. I did update hubitat earlier this morning... you can see logs in previous posts, but for whatever reason it's not doing it now. So after not really looking at this for like 2 months, I decide to post then it resolves itself. I'll keep you posted if it happens again, but I think something in the last update or two may have resolved it.

[bertabcd1234]

@vasilios

you can see logs in previous posts

There are no logs that appear to represent the rule you described, since you mentioned adding delays, and there are none in those action logs. Providing the logs (and the new rule both) would be great if there are still problems. (I know it's probably similar to the above, but...)

But ... interesting that it's not doing it now. Glad it's working, I guess. I'd suggest the above if it doesn't.