I do not have devices specified, because I'm trying to sort out this arming issue.
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?
1 Like
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|
Any thoughts @bravenel?
It appears that you have multiple things arming HSM. Why are you arming it with modes?
To get the failure you are describing, what caused it. How did you arm HSM?
1 Like
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.
What about the keypads? It appears that HSM is arming. Why it is arming 3 times bears some investigation. Is it not ending up armed?
Could you show the subscriptions for HSM on the app status page.
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.
-Jeremy
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.
Sure, and yes I'm on 2.0.5:
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.
I'm taking this screenshot before arming HSM:
So the value is 1549925437950 which translates to: Monday, February 11, 2019 4:50:37.950 PM using the Epoch Time Converter online.
Now I arm HSM, and the very first line printed in the log is this:
triggerTime= '', now() = '1549930734371', now() - triggerTime = '1549930734371'
This was printed by this line of code:
log.info("triggerTime= '" + atomicState.triggerTime + "', now() = '" + now() + "', now() - triggerTime = '" + now() - atomicState.triggerTime + "'")
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:
1549930735209 translates to Monday, February 11, 2019 6:18:55.209 PM
This seems like a pretty simple test of atomicState. I'm not sure how to really simplify it much more than that, but I'm open to suggestions.
-Jeremy
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.
Could you look at the device events for one of the keypads, and show me what that shows for the same time you showed here.
Yes. It's usually only 4, which further made me suspect my keypads. (I have 4 keypads) but as I'm looking through the event logs there are times where it's 4, times where it's 2, and times where it's 6, so it's not even consistent.
Sure thing:
FYI: In this particular instance I "armed" HSM via the dashboard, not via any of the keypads, but I have the same problem regardless of how I arm HSM.
On the atomicState side of things, I think I just made a breakthrough: I just did another test of atomicState which is very interesting:
If I use this log.info line, it works:
log.info("atomicState.triggerTime is currently set to: '" + atomicState.triggerTime + "'")
result:
[app:581](http://192.168.0.55/logs#app581)2019-02-11 06:50:03.864 pm [info](http://192.168.0.55/installedapp/configure/581)atomicState.triggerTime is currently set to: '1549932504445'
So it looks like atomicState doesn't like being accessed multiple times in the same line of Groovy code?
If I add both log.info lines back in, IE:
log.info("atomicState.triggerTime is currently set to: '" + atomicState.triggerTime + "'")
log.info("triggerTime= '" + atomicState.triggerTime + "', now() = '" + now() + "', now() - triggerTime = '" + now() - atomicState.triggerTime + "'")
I get:
[app:581](http://192.168.0.55/logs#app581)2019-02-11 06:56:14.796 pm [info](http://192.168.0.55/installedapp/configure/581)triggerTime= '', now() = '1549932974794', now() - triggerTime = '1549932974794'
[app:581](http://192.168.0.55/logs#app581)2019-02-11 06:56:14.793 pm [info](http://192.168.0.55/installedapp/configure/581)atomicState.triggerTime is currently set to: '1549932603877'
So the line that only accesses atomicState once seems to work, the line that accesses it twice returns a blank value.
I tried modifying my IF statement to only access once, but it still doesn't seem to work there. Definitely something funny going on with atomicState though.
Looks like an event loop to me. Would be inconsistent due to multiple instances and varying timing. I'll dig into this tomorrow, and see if I can find the source of the loop, and a fix to stop it.
The atomicState thing is yet another issue, and it's not clear if its related to this event loop or not. We should solve the event loop first, and then see where things stand with atomicState.
Sounds good.
Just to try and help track down the atomicState issue, I wrote a very simple app that subscribes only to a virtual presence sensor to eliminate the event loop from the possibilities:
definition(
name: "Very Simple atomicState Test",
namespace: "jeremyakers",
author: "Jeremy Akers",
description: "Test atomicState",
category: "Safety & Security",
iconUrl: "https://s3.amazonaws.com/smartapp-icons/Convenience/Cat-Convenience.png",
iconX2Url: "https://s3.amazonaws.com/smartapp-icons/Convenience/Cat-Convenience%402x.png"
)
preferences {
section("Parameters: ")
{
input "presence", "capability.presenceSensor", title: "Presence sensors: ", multiple: true
}
}
def installed()
{
subscribe(presence, "presence", statusHandler)
}
def updated()
{
unsubscribe()
subscribe(presence, "presence", statusHandler)
}
def statusHandler(evt)
{
log.info("atomicState.triggerTime is currently set to: '" + atomicState.triggerTime + "'")
log.info("triggerTime= '" + atomicState.triggerTime + "', now() = '" + now() + "', now() - triggerTime = '" + now() - atomicState.triggerTime + "'")
atomicState.triggerTime = now()
log.info("Set triggerTime = " + atomicState.triggerTime)
}
Then just trigger "depart" or "arrive" on the virtual sensor. Seems to reliably reproduce the issue with atomicState failing when accessed multiple times in the same line of code:
[app:580](http://192.168.0.55/logs#app580)2019-02-11 07:45:57.748 pm [info](http://192.168.0.55/installedapp/configure/580)Set triggerTime = 1549935957715
[app:580](http://192.168.0.55/logs#app580)2019-02-11 07:45:57.725 pm [info](http://192.168.0.55/installedapp/configure/580)triggerTime= '', now() = '1549935957705', now() - triggerTime = '1549935957705'
[app:580](http://192.168.0.55/logs#app580)2019-02-11 07:45:57.703 pm [info](http://192.168.0.55/installedapp/configure/580)atomicState.triggerTime is currently set to: '1549935811016'
Hope this helps track it down.
-Jeremy
