Good evening, and Merry Christmas. While relaxing tonight I thought I would dig into a source phantom alarms that seem to occur when we get home. In looking at the logs it seems that HSM is trying to arm multiple alarm states at the same time.
Thanks Bruce. Definately some weirdness going on. I judt had an Away event go awry. The hub things its in Away mode (correct) while HSM things it's NIght.
You don't have anything configured to be monitored in HSM it appears to me. You have to go into "Configure Hubitat Safety Monitor" and set up your sensors and whatnot.
I don't believe it will work correctly without devices. You're trying to "arm" nothing. If you don't want to move real devices, then create a couple virtual ones. But you have to have something to arm first.
From a developer standpoint that would be a pretty silly limitation. An alarm state is just a set of monitored device events. If I remove the devices from those states, the states themselves should still be able to activate.
I’m afraid I can’t put HSM into production until I get a clear answer.
How can you have states for nothing? If you have no devices, you have no states to subscribe to. Create virtual devices for testing purposes. Or don't....but if you think about it, it makes sense. How can HSM monitor nothing?
As I would have logically expected, configuring monitored devices had absolutely zero effect on the behavior of HSM arming random, duplicate modes. The issue continues and renders HSM unusable.
|hsmStatus|hsmEvent|armedHome||2018-12-29 10:30:00.554 AM EST|
|---|---|---|---|---|
|hsmSetArm|hsmEvent|armHome||2018-12-29 10:30:00.523 AM EST|
|hsmStatus|hsmEvent|armedHome||2018-12-29 10:30:00.504 AM EST|
|hsmSetArm|hsmEvent|armHome||2018-12-29 10:30:00.492 AM EST|
|hsmStatus|hsmEvent|armedHome||2018-12-29 10:30:00.265 AM EST|
|hsmSetArm|hsmEvent|armHome||2018-12-29 10:30:00.260 AM EST|
|mode|Home is now in Day mode|Day|LOCATION_MODE_CHANGE|2018-12-29 10:30:00.086 AM EST|
|hsmStatus|hsmEvent|armedNight||2018-12-29 10:20:44.501 AM EST|
|hsmSetArm|hsmEvent|armNight||2018-12-29 10:20:44.449 AM EST|
|hsmStatus|hsmEvent|armedHome||2018-12-29 10:20:44.040 AM EST|
I am using only mode manager to manage modes based on presence and/or time of day. I am using the automatic arming feature of HSM so set alarm states based on Mode.
Nothing else is arming HSM, I have no other rules set anywhere else.
Anytime mode manager changes modes I get this undefined behavior. I don’t get it if I manually set HSM states.
I have 3 keypads but nobody is interacting with them. In fact I have them set to require codes. Could there be a driver issue with them?
||securityKeypad|armed night||Keypad, Living Room was armed night [digital]|DEVICE|digital|2018-12-29 10:20:44.547 AM EST|
|---|---|---|---|---|---|---|
|securityKeypad|armed home||Keypad, Living Room was armed home [digital]|DEVICE|digital|2018-12-29 10:20:44.117 AM EST|
|securityKeypad|armed night||Keypad, Living Room was armed night [digital]|DEVICE|digital|2018-12-29 10:20:43.607 AM EST|
|securityKeypad|armed home||Keypad, Living Room was armed home [digital]|DEVICE|digital|2018-12-29 10:20:43.459 AM EST|
|securityKeypad|armed away||Keypad, Living Room was armed away [digital]|DEVICE||2018-12-29 10:20:39.4|
I see the events represented on this one keypad but they’re all “digital” which implies that they received the commands from the hub.
When you arm HSM it sends a command to each keypad to put it into armed mode. The keypad responds with an arm command. That's probably why you are seeing multiple armed Home events.
These should not interfere with the proper functioning of HSM.
I think I will clean that up also, for the next release. There is no reason for it to be armed when it's already armed.
I'm assuming this hasn't been addressed yet? This multiple arming issue has been causing me some headaches for some time and I just now got down to the point where I could pinpoint the problem.
The issue is that when HSM Arms or Disarms, it raises the arm/disarm event multiple times. Therefore any apps or Rule Machine rules that "subscribe" to this event then get fired off multiple times.
For example: I have an automation to lock all doors when HSM is armed (Either home or away). I tried to create a rule in Rule Machine to do this, but the locks would never lock. I suspected it was because RM was trying to lock all 6 locks at the same time, overloading the mesh. So I ended up writing a Groovy app that does a FOR loop through the list of locks, pausing for several seconds in between, and then locking them one at a time. Pausing between each lock helped, but there were still times the locks didn't respond. However if I lock or unlock a lock via the dashboard, or via the lock device driver page, it always works 100% of the time. In addition to the locks not always responding, this also seems to be affecting battery life as each lock is receiving the lock command multiple times in a row causing it to wake up more often than it would normally need to.
The more I troubleshoot the issue I'm realizing that the locks are having issues due to being overwhelmed with commands coming in all at once. I have 4 keypads and 6 door locks. So if you write a Rule Machine rule to lock all doors when HSM armed: The HSM Arm event fires 4 times, and each of those 4 events try to lock all 6 locks simultaneously. The result is an overloaded mesh and locks that A) Don't respond and B) Drop battery life quickly.
Putting the code into a Groovy app with a FOR loop and a pause between each lock has helped tremendously: But each lock was still being hit with 4 back to back lock commands. I realized this after I updated the code to attempt to "retry" failed locks and to send a pushover message if any locks failed. The result was a massive influx of "failed" pushover messages every single time I'd arm HSM:
The screenshot is actually cut off, the messages actually take up another full length screenshot.
I then tried to address this using atomicState: In theory it should be possible to write a value out to atomicState (Such as a timestamp) for the "first" event and then the subsequent invocations would read atomicState, see that another invocation is already running (IE: Check timestamp and if it was in last 5 seconds) and exit... That didn't work either:
def installed()
{
subscribe(presence, "presence", statusHandler)
subscribe(location, "hsmStatus", statusHandler)
}
def statusHandler(evt)
{
def randomThreadID = Math.abs(new Random().nextInt() % 1000) + 1
log.info("triggerTime= '" + atomicState.triggerTime + "', now() = '" + now() + "', now() - triggerTime = '" + now() - atomicState.triggerTime + "'")
if(atomicState.triggerTime && (now() - atomicState.triggerTime) < 5)
{
return
}
atomicState.triggerTime = now()
log.info("Set triggerTime = " + atomicState.triggerTime)
synchronized(this)
{
log.info("Only 1 thread should be here... my random thread ID = " + randomThreadID)
if (evt.value == "present")
{
if (unlock == "Yes")
{
if (locksToUnlock.count{it.currentLock == "unlocked"} != locksToUnlock.size())
{
sendMessage("[N]Unlocking doors at arrival of $evt.linkText")
}
//locksToUnlock.unlock()
for(lock in locksToUnlock)
{
pause(3000)
//sendMessage("Unlocking door at arrival of $evt.linkText")
lock.unlock()
}
}
}
else if(evt.value == "armedAway" || evt.value == "armedHome")
{
if (locksToLock.count{it.currentLock == "locked"} != locksToLock.size())
{
sendMessage("[L]Locking doors after HSM Armed.")
}
pause(5000)
//locksToLock.lock()
for(lock in locksToLock)
{
//sendMessage("Door locked after HSM Armed.")
lock.lock()
pause(5000)
if (lock.currentValue("lock") != "locked")
{
lock.lock()
pause(5000)
}
if (lock.currentValue("lock") != "locked")
{
sendMessage("FAILED to lock ${lock.displayName} after HSM Armed.")
}
}
}
else if(evt.value == "disarmed")
{
sendMessage("[N]HSM was disarmed")
}
log.info("Thread leaving synchronized block: " + randomThreadID)
}
}
But each invocation of the "statusHandler" sees "atomicState.triggerTime" as blank when it executes:
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:30:09.714 pm [info](http://192.168.0.55/installedapp/configure/482)Thread leaving synchronized block: 855
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:30:09.689 pm [info](http://192.168.0.55/installedapp/configure/482)Thread leaving synchronized block: 203
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:30:09.688 pm [info](http://192.168.0.55/installedapp/configure/482)Thread leaving synchronized block: 647
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:30:09.407 pm [info](http://192.168.0.55/installedapp/configure/482)FAILED to lock Living Room Patio Lock after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:30:09.336 pm [info](http://192.168.0.55/installedapp/configure/482)FAILED to lock Living Room Patio Lock after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:30:09.328 pm [info](http://192.168.0.55/installedapp/configure/482)FAILED to lock Living Room Patio Lock after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:30:09.260 pm [info](http://192.168.0.55/installedapp/configure/482)Thread leaving synchronized block: 837
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:30:09.166 pm [info](http://192.168.0.55/installedapp/configure/482)Thread leaving synchronized block: 342
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:30:08.957 pm [info](http://192.168.0.55/installedapp/configure/482)FAILED to lock Living Room Patio Lock after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:30:08.856 pm [info](http://192.168.0.55/installedapp/configure/482)Thread leaving synchronized block: 460
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:30:08.818 pm [info](http://192.168.0.55/installedapp/configure/482)FAILED to lock Living Room Patio Lock after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:30:08.527 pm [info](http://192.168.0.55/installedapp/configure/482)FAILED to lock Living Room Patio Lock after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:58.987 pm [info](http://192.168.0.55/installedapp/configure/482)FAILED to lock Front Door Lock after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:58.858 pm [info](http://192.168.0.55/installedapp/configure/482)FAILED to lock Front Door Lock after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:58.819 pm [info](http://192.168.0.55/installedapp/configure/482)FAILED to lock Front Door Lock after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:58.595 pm [info](http://192.168.0.55/installedapp/configure/482)FAILED to lock Front Door Lock after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:58.487 pm [info](http://192.168.0.55/installedapp/configure/482)FAILED to lock Front Door Lock after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:58.187 pm [info](http://192.168.0.55/installedapp/configure/482)FAILED to lock Front Door Lock after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:48.667 pm [info](http://192.168.0.55/installedapp/configure/482)FAILED to lock Garage Entry Door Lock after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:48.518 pm [info](http://192.168.0.55/installedapp/configure/482)FAILED to lock Garage Entry Door Lock after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:48.488 pm [info](http://192.168.0.55/installedapp/configure/482)FAILED to lock Garage Entry Door Lock after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:48.257 pm [info](http://192.168.0.55/installedapp/configure/482)FAILED to lock Garage Entry Door Lock after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:48.107 pm [info](http://192.168.0.55/installedapp/configure/482)FAILED to lock Garage Entry Door Lock after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:47.818 pm [info](http://192.168.0.55/installedapp/configure/482)FAILED to lock Garage Entry Door Lock after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:18.090 pm [info](http://192.168.0.55/installedapp/configure/482)[L]Locking doors after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:17.916 pm [info](http://192.168.0.55/installedapp/configure/482)Only 1 thread should be here... my random thread ID = 855
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:17.914 pm [info](http://192.168.0.55/installedapp/configure/482)Set triggerTime = 1549924157895
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:17.892 pm [info](http://192.168.0.55/installedapp/configure/482)[L]Locking doors after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:17.857 pm [info](http://192.168.0.55/installedapp/configure/482)triggerTime= '', now() = '1549924157842', now() - triggerTime = '1549924157842'
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:17.813 pm [info](http://192.168.0.55/installedapp/configure/482)[L]Locking doors after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:17.681 pm [info](http://192.168.0.55/installedapp/configure/482)[L]Locking doors after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:17.664 pm [info](http://192.168.0.55/installedapp/configure/482)Only 1 thread should be here... my random thread ID = 647
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:17.663 pm [info](http://192.168.0.55/installedapp/configure/482)Set triggerTime = 1549924157600
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:17.613 pm [info](http://192.168.0.55/installedapp/configure/482)Only 1 thread should be here... my random thread ID = 203
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:17.612 pm [info](http://192.168.0.55/installedapp/configure/482)Set triggerTime = 1549924157556
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:17.578 pm [info](http://192.168.0.55/installedapp/configure/482)triggerTime= '', now() = '1549924157571', now() - triggerTime = '1549924157571'
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:17.576 pm [info](http://192.168.0.55/installedapp/configure/482)triggerTime= '', now() = '1549924157446', now() - triggerTime = '1549924157446'
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:17.415 pm [info](http://192.168.0.55/installedapp/configure/482)[L]Locking doors after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:17.332 pm [info](http://192.168.0.55/installedapp/configure/482)Only 1 thread should be here... my random thread ID = 837
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:17.324 pm [info](http://192.168.0.55/installedapp/configure/482)Set triggerTime = 1549924157247
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:17.254 pm [info](http://192.168.0.55/installedapp/configure/482)triggerTime= '', now() = '1549924157244', now() - triggerTime = '1549924157244'
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:17.125 pm [info](http://192.168.0.55/installedapp/configure/482)Only 1 thread should be here... my random thread ID = 342
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:17.124 pm [info](http://192.168.0.55/installedapp/configure/482)Set triggerTime = 1549924157107
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:17.078 pm [info](http://192.168.0.55/installedapp/configure/482)triggerTime= '', now() = '1549924157076', now() - triggerTime = '1549924157076'
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:16.852 pm [info](http://192.168.0.55/installedapp/configure/482)[L]Locking doors after HSM Armed.
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:16.667 pm [info](http://192.168.0.55/installedapp/configure/482)Only 1 thread should be here... my random thread ID = 460
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:16.665 pm [info](http://192.168.0.55/installedapp/configure/482)Set triggerTime = 1549924156653
[app:482](http://192.168.0.55/logs#app482)2019-02-11 04:29:16.648 pm [info](http://192.168.0.55/installedapp/configure/482)triggerTime= '', now() = '1549924156645', now() - triggerTime = '1549924156645'
You can see that multiple threads appear to be entering the synchronized block of code, and none of them appear to be correctly reading the atomicState.
I sent an email to the support email address for this issue as well. There's a cascading effect of problems here:
1.) HSM triggers the "arm/disarm" multiple times
2.) atomicState doesn't seem to be working.
3.) "synchronized" keyword (Which should prevent multiple groovy threads from running the same block of code at the same time) doesn't seem to help either.
Hoping someone can help me figure out how to proceed from here.
No, this was addressed some time ago. It does not arm if already armed in that condition, e.g. Intrusion-Away. Have you looked at the app events for HSM? This would be shown there. Please show me events where it is sending the arm event multiple times. I assume you are on 2.0.5?
No, that is not readily apparent given the complexity of what you're talking about. Have you done a simple test of atomicState? I'm not aware of any issues with it, and we do use it in several apps. Hard to analyze this from afar.
This just looked a lot like the issue described earlier in this thread where multiple keypads were causing HSM to arm multiple times. Given the similarity I just assumed it was the same issue but that was just an assumption.
I mean, all I'm doing is setting a value in atomicState and then trying to read it later, and it's blank. Let me try and show you a more straightforward way, here's a screenshot of the "state" of the simple app I wrote.
So this seems pretty straightforward to me: At this point in time the value of "atomicState.triggerTime" was set to 1549925437950 as we saw in the screenshot above. But when I print that value using log.info it comes out as a blank value. It should have printed triggerTime = '1549925437950' rather than triggerTime = ''.
The atomicState is being set properly since it shows up when you look at the application state in the web interface... but it's returning a blank value when being accessed for the first time by a new invocation of the app triggered by HSM.
After running the app, if I go back to the application state I can see that the triggerTime was properly updated:
Well, these are both rather bizarre. It appears that something is firing multiple simultaneous instances of HSM, each of which is arming HSM. It uses a conventional state variable to determine if it is armed already or not, not atomicState. So it is conceivable that is happening. But, 6 different instances in one second? Were those all that happened at that time?
I wonder if it's in some sort of event loop with the keypads.
