sensor tripping and untripping constantly from static Z-way device

Plugins & Plugin Development openLuup
1

I’m suddenly getting many messages overflowing my openLuup logs. Device 43 is a door lock through Z-way. During this time nothing is being logged in the Z-way log and everything appears to be running normally. Yet every 2 seconds I see the messages below. How to debug? The logs are rolling fast enough that I haven’t been able to catch if there is something that starts it. I’ll try to restart and debug further. Hints?

2018-03-11 12:52:39.519 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:0 2018-03-11 12:52:39.520 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 1 now: 0 #hooks:0 2018-03-11 12:52:40.030 openLuup.server:: request completed (6313 bytes, 1 chunks, 2123 ms) tcp{client}: 0x16e0050 2018-03-11 12:52:40.566 openLuup.server:: GET /data_request?id=lu_status2&output_format=json&DataVersion=726410221&Timeout=60&MinimumDelay=1500&_=1520789817138 HTTP/1.1 tcp{client}: 0x16e0050 2018-03-11 12:52:41.665 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:0 2018-03-11 12:52:41.666 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 1 now: 0 #hooks:0 2018-03-11 12:52:42.194 openLuup.server:: request completed (6313 bytes, 1 chunks, 1627 ms) tcp{client}: 0x16e0050 2018-03-11 12:52:42.392 openLuup.server:: GET /data_request?id=lu_status2&output_format=json&DataVersion=726410223&Timeout=60&MinimumDelay=1500&_=1520789817139 HTTP/1.1 tcp{client}: 0x16e0050

2

So what did you change just before this started happening?
Does the Smarthome interface show anything unusual about this device?

3

The Smarthome interface doesn’t show anything unusual about this device as far as I can see. I’ve had it for months. And the history page shows no events for this device which is consistent with the Z-way logs - I don’t think it is sending out all of this.

Unfortunately I’ve made several recent changes and didn’t notice this issue immediately, so it’s hard to know exactly what caused it. But here’s a list of what I know has changed:

  • updated openLuup to latest master from relatively old development version
  • added a Z-wave switch
  • added a scene and some startup Lua code
4

Probably the recent openLuup update then. Is it possible for you to roll back to an earlier version and test that?

I have one possible candidate in my mind for this behaviour, but unable to check it out right at the moment sicne I am away from my development system at present.

5

I would need to specify a branch and tag to roll back, correct? I’m looking at the tag list on github and it shows v18.2.26 (latest) and v17.3.9 from March 9, 2017. Is there a way to get anything in between? I can try v17.3.9 and see what it does. Or can I specify a date instead of a tag?

6

From openLuup/AltUI in the Update box, you can only specify a branch (ie. its current state) or a tagged release. mea culpa, there have not been any recent tagged development releases.

You should be able to go into GitHub directly, though, and retrieve absolutely any version of the system from the development branch. The commit comments there identify the significant changes.

However, installing an older system will mean that Plugins page update will not work due to the GitHub security updates. This should not be a problem if you are happy just replacing the whole openLuup/ directory (and saving it elsewhere before you do so!)

7

I went back to v17.3.9 and still see the issue. I can try going back further if you think it might help.

8

went back to v16.12.21 and things are slightly worse. Now 2 variables are doing this. If I don’t start Z-way, I don’t see the problem, but once Z-way is running, I don’t see activity in the Z-way log related to this. It’s quiet.

2018-03-12 21:30:09.043 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.LastTrip was: 1520915311 now: 1520915310 #hooks:0 2018-03-12 21:30:09.049 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:0 2018-03-12 21:30:09.049 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 1 now: 0 #hooks:0 2018-03-12 21:30:09.049 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.LastTrip was: 1520915310 now: 1520915311 #hooks:0 2018-03-12 21:30:11.133 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.LastTrip was: 1520915311 now: 1520915310 #hooks:0 2018-03-12 21:30:11.133 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:0 2018-03-12 21:30:11.134 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 1 now: 0 #hooks:0 2018-03-12 21:30:11.134 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.LastTrip was: 1520915310 now: 1520915311 #hooks:0 2018-03-12 21:30:13.240 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.LastTrip was: 1520915311 now: 1520915310 #hooks:0 2018-03-12 21:30:13.240 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:0 2018-03-12 21:30:13.241 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 1 now: 0 #hooks:0 2018-03-12 21:30:13.241 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.LastTrip was: 1520915310 now: 1520915311 #hooks:0 2018-03-12 21:30:15.306 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.LastTrip was: 1520915311 now: 1520915310 #hooks:0 2018-03-12 21:30:15.306 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:0 2018-03-12 21:30:15.306 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 1 now: 0 #hooks:0 2018-03-12 21:30:15.306 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.LastTrip was: 1520915310 now: 1520915311 #hooks:0

This is where it first goes bad in the log after a restart of openLuup. As soon as it gets an update from Z-way, it immediately starts toggling the Tripped and LastTrip:

2018-03-12 21:29:00.623 luup.variable_set:5: 43.urn:akbooer-com:serviceId:ZWay1.ZWayVDev_zway_17-0-98_LastUpdate was: 1520914892 now: 1520915310 #hooks:0 2018-03-12 21:29:00.623 luup.variable_set:5: 43.urn:akbooer-com:serviceId:ZWay1.ZWayVDev_zway_17-0-113-7-2-A_LastUpdate was: 1520914892 now: 1520915310 #hooks:0 2018-03-12 21:29:00.623 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.LastTrip was: 1520914892 now: 1520915310 #hooks:0 2018-03-12 21:29:00.624 luup.variable_set:5: 43.urn:akbooer-com:serviceId:ZWay1.ZWayVDev_zway_17-0-113-8-10-A_LastUpdate was: 1520914892 now: 1520915310 #hooks:0 2018-03-12 21:29:00.624 luup.variable_set:5: 43.urn:akbooer-com:serviceId:ZWay1.ZWayVDev_zway_17-0-113-8-11-A_LastUpdate was: 1520914892 now: 1520915310 #hooks:0 2018-03-12 21:29:00.624 luup.variable_set:5: 43.urn:akbooer-com:serviceId:ZWay1.ZWayVDev_zway_17-0-113-9-1-A_LastUpdate was: 1520914892 now: 1520915310 #hooks:0 2018-03-12 21:29:00.624 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:0 2018-03-12 21:29:00.624 luup.variable_set:5: 43.urn:akbooer-com:serviceId:ZWay1.ZWayVDev_zway_17-0-113-9-5-A_LastUpdate was: 1520914892 now: 1520915311 #hooks:0 2018-03-12 21:29:00.625 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 1 now: 0 #hooks:0 2018-03-12 21:29:00.625 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.LastTrip was: 1520915310 now: 1520915311 #hooks:0

9

Well, it seems not to be any changes I have made recently, then. No point in going back further.

I may need more info when I get back to in front of my development system.

10

Would it be possible to try things with your recent Zwave switch removed?

11

Removed both of the devices I had recently added and still seeing these messages pour through. I’m back to only seeing tripped, though. Lasttrip seems to have stopped.

2018-03-13 22:04:19.085 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:0 2018-03-13 22:04:19.085 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 1 now: 0 #hooks:0 2018-03-13 22:04:19.593 openLuup.server:: request completed (6309 bytes, 1 chunks, 1563 ms) tcp{client}: 0x154eaa0 2018-03-13 22:04:20.014 openLuup.server:: GET /data_request?id=lu_status2&output_format=json&DataVersion=3580505&Timeout=60&MinimumDelay=1500&_=1521003052048 HTTP/1.1 tcp{client}: 0x154eaa0 2018-03-13 22:04:21.610 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:0 2018-03-13 22:04:21.611 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 1 now: 0 #hooks:0 2018-03-13 22:04:22.119 openLuup.server:: request completed (6309 bytes, 1 chunks, 2104 ms) tcp{client}: 0x154eaa0 2018-03-13 22:04:23.017 openLuup.server:: GET /data_request?id=lu_status2&output_format=json&DataVersion=3580507&Timeout=60&MinimumDelay=1500&_=1521003052049 HTTP/1.1 tcp{client}: 0x154eaa0 2018-03-13 22:04:24.077 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 0 now: 1 #hooks:0 2018-03-13 22:04:24.078 luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped was: 1 now: 0 #hoo

12

Can you give me the output from this line, run in the Lua Code Test window:

print(pretty(luup.devices[43].services))
13

{ ["urn:akbooer-com:serviceId:ZWay1"] = { actions = {}, variable_get = function: 0x1691f60, variable_set = function: 0x1691ec0, variables = { ["ZWayVDev_zway_17-0-113-7-2-A"] = { dev = 43, id = 7, name = "ZWayVDev_zway_17-0-113-7-2-A", old = "EMPTY", set = function: 0x12b0088, srv = "urn:akbooer-com:serviceId:ZWay1", time = 1521003579, value = "off", version = 3579178, watchers = {} }, ["ZWayVDev_zway_17-0-113-7-2-A_LastUpdate"] = { dev = 43, id = 8, name = "ZWayVDev_zway_17-0-113-7-2-A_LastUpdate", old = "1520915310", set = function: 0x12b0088, srv = "urn:akbooer-com:serviceId:ZWay1", time = 1521003584, value = "1521003583", version = 3580119, watchers = {} }, ["ZWayVDev_zway_17-0-113-8-10-A"] = { dev = 43, id = 11, name = "ZWayVDev_zway_17-0-113-8-10-A", old = "EMPTY", set = function: 0x12b0088, srv = "urn:akbooer-com:serviceId:ZWay1", time = 1521003579, value = "off", version = 3579186, watchers = {} }, ["ZWayVDev_zway_17-0-113-8-10-A_LastUpdate"] = { dev = 43, id = 12, name = "ZWayVDev_zway_17-0-113-8-10-A_LastUpdate", old = "1520915310", set = function: 0x12b0088, srv = "urn:akbooer-com:serviceId:ZWay1", time = 1521003584, value = "1521003583", version = 3580121, watchers = {} }, ["ZWayVDev_zway_17-0-113-8-11-A"] = { dev = 43, id = 13, name = "ZWayVDev_zway_17-0-113-8-11-A", old = "EMPTY", set = function: 0x12b0088, srv = "urn:akbooer-com:serviceId:ZWay1", time = 1521003579, value = "off", version = 3579190, watchers = {} }, ["ZWayVDev_zway_17-0-113-8-11-A_LastUpdate"] = { dev = 43, id = 14, name = "ZWayVDev_zway_17-0-113-8-11-A_LastUpdate", old = "1520915310", set = function: 0x12b0088, srv = "urn:akbooer-com:serviceId:ZWay1", time = 1521003584, value = "1521003583", version = 3580122, watchers = {} }, ["ZWayVDev_zway_17-0-113-9-1-A"] = { dev = 43, id = 15, name = "ZWayVDev_zway_17-0-113-9-1-A", old = "EMPTY", set = function: 0x12b0088, srv = "urn:akbooer-com:serviceId:ZWay1", time = 1521003579, value = "on", version = 3579194, watchers = {} }, ["ZWayVDev_zway_17-0-113-9-1-A_LastUpdate"] = { dev = 43, id = 16, name = "ZWayVDev_zway_17-0-113-9-1-A_LastUpdate", old = "1520915310", set = function: 0x12b0088, srv = "urn:akbooer-com:serviceId:ZWay1", time = 1521003584, value = "1521003583", version = 3580123, watchers = {} }, ["ZWayVDev_zway_17-0-113-9-5-A"] = { dev = 43, id = 17, name = "ZWayVDev_zway_17-0-113-9-5-A", old = "EMPTY", set = function: 0x12b0088, srv = "urn:akbooer-com:serviceId:ZWay1", time = 1521003579, value = "off", version = 3579198, watchers = {} }, ["ZWayVDev_zway_17-0-113-9-5-A_LastUpdate"] = { dev = 43, id = 18, name = "ZWayVDev_zway_17-0-113-9-5-A_LastUpdate", old = "1520915311", set = function: 0x12b0088, srv = "urn:akbooer-com:serviceId:ZWay1", time = 1521003584, value = "1521003583", version = 3580125, watchers = {} }, ["ZWayVDev_zway_17-0-128"] = { dev = 43, id = 0, name = "ZWayVDev_zway_17-0-128", old = "EMPTY", set = function: 0x12b0088, srv = "urn:akbooer-com:serviceId:ZWay1", time = 1521003579, value = "83", version = 3579164, watchers = {} }, ["ZWayVDev_zway_17-0-128_LastUpdate"] = { dev = 43, id = 1, name = "ZWayVDev_zway_17-0-128_LastUpdate", old = "1520997358", set = function: 0x12b0088, srv = "urn:akbooer-com:serviceId:ZWay1", time = 1521003584, value = "1521003583", version = 3580127, watchers = {} }, ["ZWayVDev_zway_17-0-98"] = { dev = 43, id = 4, name = "ZWayVDev_zway_17-0-98", old = "EMPTY", set = function: 0x12b0088, srv = "urn:akbooer-com:serviceId:ZWay1", time = 1521003579, value = "open", version = 3579172, watchers = {{ callback = function: 0x146da08, devNo = 3, name = "variableWatchCallback" }} }, ["ZWayVDev_zway_17-0-98_LastUpdate"] = { dev = 43, id = 5, name = "ZWayVDev_zway_17-0-98_LastUpdate", old = "1520999564", set = function: 0x12b0088, srv = "urn:akbooer-com:serviceId:ZWay1", time = 1521003584, value = "1521003583", version = 3580118, watchers = {} } }, watchers = {} }, ["urn:micasaverde-com:serviceId:DoorLock1"] = { actions = {}, variable_get = function: 0x16929e8, variable_set = function: 0x1692ca8, variables = {Status = { dev = 43, id = 6, name = "Status", old = "EMPTY", set = function: 0x12b0088, srv = "urn:micasaverde-com:serviceId:DoorLock1", time = 1521003579, value = "0", version = 3579176, watchers = {} }}, watchers = {{ callback = function: 0x1699f48, devNo = 0, name = "_scene32", silent = true }} }, ["urn:micasaverde-com:serviceId:HaDevice1"] = { actions = {}, variable_get = function: 0x1692210, variable_set = function: 0x16924a0, variables = { BatteryLevel = { dev = 43, id = 2, name = "BatteryLevel", old = "EMPTY", set = function: 0x12b0088, srv = "urn:micasaverde-com:serviceId:HaDevice1", time = 1521003579, value = "83", version = 3579168, watchers = {} }, sl_BatteryAlarm = { dev = 43, id = 3, name = "sl_BatteryAlarm", old = "EMPTY", set = function: 0x12b0088, srv = "urn:micasaverde-com:serviceId:HaDevice1", time = 1521003579, value = "0", version = 3579170, watchers = {} } }, watchers = {} }, ["urn:micasaverde-com:serviceId:SecuritySensor1"] = { actions = {}, variable_get = function: 0x1692a58, variable_set = function: 0x1692fb8, variables = { LastTrip = { dev = 43, id = 10, name = "LastTrip", old = "1520915311", set = function: 0x12b0088, srv = "urn:micasaverde-com:serviceId:SecuritySensor1", time = 1521003584, value = "1521003583", version = 3580120, watchers = {} }, Tripped = { dev = 43, id = 9, name = "Tripped", old = "1", set = function: 0x12b0088, srv = "urn:micasaverde-com:serviceId:SecuritySensor1", time = 1521034350, value = "0", version = 3607900, watchers = {} } }, watchers = {} } }

14

AltUI has a watch set on one of the device variables:

[tt]urn:akbooer-com:serviceId:ZWay1 / ZWayVDev_zway_17-0-98[/tt] for “variableWatchCallback”

…looks like the trigger for a scene?

What does it do?

15

That watch was triggering a scene that writes parameters into another device. I deleted all triggers for this scene, reloaded openLuup, yet still the messages continue…

16

I’m obviously struggling with this. I haven’t changed ZWay for around a year, and although I’ve changed openLuup considerably over that time, you’ve found the same behaviour on an older version. This leads me first to suspect something in the actual ZWay system itself, and yet you say there’s no evidence of that. I certainly don’t see that in the logs.

The really odd thing is this pair of entries:

2018-03-12 21:30:09.049   luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.LastTrip was: 1520915310 now: 1520915311 #hooks:0
2018-03-12 21:30:11.133   luup.variable_set:5: 43.urn:micasaverde-com:serviceId:SecuritySensor1.LastTrip was: 1520915311 now: 1520915310 #hooks:0

which shows non-causal behaviour, with the trip time going backwards.

If I had the system in front of me, there would be lots of things to try, but doing this remotely is difficult.

Two things:

[ol][li]can you delete the openLuup device #43. The system should reload twice and restore it. Still problems?[/li]
[li]can I see a full ZWay configuration listing?[/li][/ol]

Get the listing with the HTTP page:

http://openLuupIP:3480/data_request?id=lr_z5

(assuming that your ZWay plugin is device #5)

Thanks.

17

Deleting device #43 in openLuup (not from Z-way) and reloading didn’t help other than changing the number from 43 to 75. Still seeing Tripped toggling.

I’ll have to get the full config for you a bit later. Hopefully it shows you something. thanks.

18

It seems like your browser does some pretty-printing of JSON and the text you sent wasn’t actually valid JSON, so I struggled a bit.

However…

Try the attached L_ZWay.lua file to replace your existing, and give it a go.

Edit: file removed. Correct version now available on GitHub.

19

So far it looks very good, no issues. I used Chrome - next time I’ll use a different browser. My flash card and I thank you!

Any idea how I could have gone so long without seeing this issue and somehow it popped up now? And weird that no one else sees it.

20

on second glance, not so good. Communication to the Z-way server seems to have stopped with this version. Commands don’t get through to it. I had to go back to the older version.