HSM Arming Multiple States

jeremy.akers · February 12, 2019, 1:07am

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.

bravenel · February 12, 2019, 1:14am

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.

jeremy.akers · February 12, 2019, 1:51am

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

bjcowles · February 12, 2019, 2:45am

Not sure if it helps or if it's even related, but I noticed all HSM events being duplicated after the 2.0.4.111 update. Didn't cause any problems for me so I just ignored it.