OH2 Z-Wave refactoring and testing... and SECURITY

Update: I’m actually going to explore this docker container for OpenZWave to securely include as a workaround. Theoretically, this should let me quickly/easily spin up an OpenZWave container to do this, then scrap it when done. My only worry is the lack of ability to backup my ZStick (windows only it seems from Aeon).

It’s pretty easy to get running. But, the startup command doesn’t work as shown.

docker run -p 8008:8008 --device /dev/ttyUSB0 openzwave-control-panel

To get it running, I needed to change it to this

docker run -p 8008:8008 --device /dev/ttyUSB0 openzwave/openzwave-control-panel

When I included my lock I just grabbed my older Pi that was running OH1.9, plugged the zstick in and did the secure include there. No problems with the 1.9 secure binding, and I have 66 devices and could not get it to include with this binding.

Quick question: Can I use newest (Octoberish/Novemberish) 2.2.0 binding (development snapshot from @chris post)with my standard distribution (raspbian) packaged openhab 2.1.0 ?

I’ll ofcourse uninstall default zwave binding from openhab 2.1.0. My question is about usage of current dev binding with older openhab 2.1.

I’m not sure. I suspect that there have been some changes to ESH since 2.1 was released that might stop it working. You can try - if it throws errors, then the answer is no :wink:

2.2 binding works with openhab 2.1 - at least logs looks normal.

However it didnt resolve my problem I’m trying to debug for half a day already:
I did clean install from scratch, openhab 2.1. I also did full reset (20 seconds button press) of my usb aeotec serial controller). But I can not include any devices (they worked more less ok few months ago). It’s only controller which is visible. even gets some frames, and logs dont show any problems. The only thing I notices suspicious is that in zwave debug log I see both node1 and node255 messages.

Just to be clear: this is not related with 2.2.0 development snapshot. I just tried it to be sure, but the very same problem is with stock openhab 2.1.0

Any clues/suggesstions?

I’m not sure why you think that’s suspicious, but it sounds normal to me.

Not really - sorry. Inclusion is largely handled by the controller - the binding just sets the mode. Can you include using the button on the stick instead?

I noticed that I’ve quit getting updates from my locks. When I ran a debug test I got the following error messages:

04-Nov-2017 16:48:31.126 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 108: Application Command Request (ALIVE:DYNAMIC_VALUES)
04-Nov-2017 16:48:31.129 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 108: Incoming command class COMMAND_CLASS_ALARM, endpoint 0
04-Nov-2017 16:48:31.132 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 108: SECURITY required on COMMAND_CLASS_ALARM
04-Nov-2017 16:48:31.134 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 108: Command Class COMMAND_CLASS_ALARM was required to be security encapsulation but it wasn't! Message dropped.
04-Nov-2017 16:48:31.137 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 108: Commands processed 0.

How could I loose secure communication with these nodes?

Call me old fashioned. I have one controller on my network. So I don’t get why it uses simultaneously both node1 and node255 in logging? :slight_smile:

No. I can not include using button on the stick either. I does not include those two battery operated thermostats. It does react to exclusion with them though: Upon moving stick close the thermostat, and putting stick in exclusion mode, immedietaly after pressing button on the thermostat, I see exclusion confirmation on the stick. But If I’d like to include the device in similar fashion, it does not work. They did work before reinstall. I also replaced batteries in them. THey are different brand (Comet and Stella) so I’m reluctant to blame them.

Whats more interesting: inclusion problems happen only with those two battery operated thermostats. All other power operated devices, can be included within both openhab and stick alone.

It doesnt make sens :frowning:

Of course, I completely rebooted the thermostats, or so I hope I did. Also with completly removing batteries etc.

There are two functions in the controller though - one uses node 1, and one uses node 255 for logging.

My locks all of a sudden quit sending me status changes on the lock_door channel. I still get the raw alarm code updates but even when the door reports through the alarm code that it was unlocked the lock_door channel still reports it as locked.

Here are what I think are all the relative debug log entries to the unlock event:
https://drive.google.com/open?id=19Dom49uwJAS9XzmDg1xj7HvyjINbLzpr

Let me know if I missed any or any other testing you want me to pull logs for. This is for a Kwikset 914TRL

Have you checked the battery level? I had a similar situation happen a little bit back. I was boggled as suddenly the lock would no longer operate via ZWave and I wasn’t getting updates. Turns out that somehow, the battery was low and it was no longer communicating properly. Replaced the batteries and got it back up to 100%, restarted OH for good measure, and suddenly it was communicating again.

1 Like

It’s across the the board though I did change batteries on the one I posted logs for right before hand. I’ll try a system restart to see if that helps.

Thanks.

I think that zwave binding logging shows wrongly ‘queue size 0’ after adding message to the queue.
There should be shown ‘1’ not ‘0’.

Full log, look at the last message:

Blockquote
2017-11-06 22:19:45.340 [DEBUG] [ZWaveThingHandler ] - NODE 7: Command received zwave:device:42e5ecf9:node7:thermostat_mode --> 1
2017-11-06 22:19:45.341 [DEBUG] [ThermostatModeCommandClass] - NODE 7: setValueMessage 1, modeType empty false
2017-11-06 22:19:45.341 [DEBUG] [ThermostatModeCommandClass] - NODE 7: Creating new message for application command THERMOSTAT_MODE_SET
2017-11-06 22:19:45.368 [DEBUG] [ZWaveNode ] - NODE 7: Encapsulating message, endpoint 0
2017-11-06 22:19:45.370 [DEBUG] [ZWaveNode ] - NODE 7: SECURITY not supported
2017-11-06 22:19:45.372 [DEBUG] [ZWaveNode ] - NODE 7: Command Class COMMAND_CLASS_THERMOSTAT_MODE is NOT required to be secured
2017-11-06 22:19:45.374 [DEBUG] [ZWaveTransactionManager ] - NODE 7: Adding to device queue
2017-11-06 22:19:45.385 [DEBUG] [ZWaveTransactionManager ] - NODE 7: Added to queue - size 0

The debug logging needs some consolidation. It’s not wrong - it’s just that there are multiple queues and the length given here is a different queue than this message was added to.

I’ve noticed that when I start OH2, I am seeing this error at the top of the log (first line) which I think was mentioned back around post 1042 here in this topic and was subsequently resolved with the latest binding?

But I am pretty current, running OH2 2.2 Build #1072 with the latest 2.2 binding posted here back in October.

2017-11-07 07:37:31.501 [ERROR] [org.openhab.binding.zwave           ] - BundleComponentActivator : Bundle [11] Unexpected failure enabling component holder org.openhab.binding.zwave.ZWaveBindingConstants
java.lang.NoClassDefFoundError: org/eclipse/smarthome/core/i18n/I18nProvider
	at java.lang.Class.getDeclaredMethods0(Native Method) ~[?:?]
	at java.lang.Class.privateGetDeclaredMethods(Class.java:2701) ~[?:?]
	at java.lang.Class.getDeclaredMethods(Class.java:1975) ~[?:?]

@chris I’m seeing some strange behavior with exclusion in build 2.2.0.201710241752 on OH build 1073.

I saw this behavior yesterday when trying to exclude some nodes. I reset the stick, reset the nodes, and deleted the things in order to start as clean as possible.

If I exclude a node, the node appears to be excluded; however,

  • in HABmin, the node is not deleted from the list of things
  • if I delete the thing, then run discovery, the excluded node is discovered and is added to the inbox
  • if I stop/start the binding (from the karaf console), the excluded node is no longer there and is not discoverable

Here’s a link to the log file.
https://drive.google.com/open?id=1USaoVPLb8VL4dSIRgPwwU3_uW-6B3G6P

I saw this behavior first when I excluded node 3, then when I excluded node 4.

  • In the log I can see node 3 being removed at 11:06.
  • Then oddly at 11:08 it shows up in the inbox when I run discovery.
  • Thinking it wasn’t successfully excluded, I tried to exclude it a few more times at 11:08, 11:09, 11:11.
  • At 11:12 I run discovery again, and node 3 shows up.
  • Then I tried to mark it failed and remove it from the controller (which said node 3 wasn’t found)
  • Then I think I deleted the thing again and ran discovery at 11:13, which found node 3 again
  • I stopped and started the binding at 11:15, at which point node 3 was gone

Any thoughts on what’s going on?

That’s correct - the binding doesn’t delete the nodes (it can’t - ESH blocked this functionality a while back!).

The response from the exclude was ignored due to a bug, so the node wasn’t removed from the controller. When you did a discovery again, it was still in the controller list (by controller, I mean the list of nodes in the binding - not the stick) so it got added again. However, the exclude really did work ok, so when you restarted and the binding read the list of nodes, it was gone…

All explainable and I’ll fix the bug - thanks.

Ah, thanks for the reminder. I do recall reading about this a while ago and, at the time, thought it was a bad decision. Now I’m convinced it was a bad decision. :cry:

Yep, that makes sense.

Thanks!

Are you really sure you’re running the security version - or that you don’t have multiple versions running? This bug doesn’t seem to appear in the security version - only the master as far as I can see (I did a search for I18nProvider in the development branch and it doesn’t seem to exist).

FTR The following fixes the issue in master -: