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
