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

DanielMalmgren · August 16, 2018, 5:04am

Hi.
I’m having a deja vu moment here, need someone (@chris?) to help me remember. I know I’ve had this problem before and discussed it somewhere (might be in this thread thousands of posts up or somewhere completely different).

I’m trying to include some new nodes. When I start the inclusion I just get “Z-Wave network inclusion failed” within seconds and nothing gets included at all. I’ve put a short debug log here but I don’t think it says much useful.

I’m on Debian 8, running a current snapshot (Build #1330) of OH and latest version (2.4.0.201808142206) of this binding.

mstormi · August 16, 2018, 6:21am

Here’s a link to my issue that documents it. The channel has always been available, but this firmware did not announce the class so the binding did not use it in mapping items. chris ‘forced’ it to know that class.

mark_leonard_tuil · August 16, 2018, 6:35pm

Hi, I just noticed a strange thing while using the development zwave binding. I have a bunch of Fibaro dimmers. If I send the command 99 to a dimmer. The light then changes to 100, without me giving any command. The log is as follows:

2018-08-16 20:28:08.821 [ome.event.ItemCommandEvent] - Item 'Hal_Dimmer' received command 99
2018-08-16 20:28:08.840 [vent.ItemStateChangedEvent] - Hal_Dimmer changed from 0 to 99
2018-08-16 20:28:09.884 [vent.ItemStateChangedEvent] - Hal_Dimmer changed from 99 to 100

It seems that this is releated to z-wave. If I send the command 99 to a Hue dimmer, it just changes to 99 and doesn’t change to 100.

chris · August 16, 2018, 6:37pm

ZWave protocol doesn’t have the concept of 100, so to avoid even more confusion, the ZWave binding always sets the value to 100 if you set to 99 - it’s normal.

mark_leonard_tuil · August 16, 2018, 6:42pm

Hi Chris,

Thanks for the quick reply. That at least explains it. I thought I was going crazy. I will rewrite my rule to accomodate for this.

Other than this, your current binding works great on my 30+ nodes network.

Thanks for your work

DanielMalmgren · August 17, 2018, 6:29am

Hi again. I gave up and just included by just stopping the binding, unplugging the z-stick and using the physical button on it. Included just fine, but now after waiting +12 hours and doing numerous wakeup attempts it still shows as “Unknown Device”. When I push the wake up button I get the following in my log:

2018-08-16 18:36:09.743 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 04 11 06 56 01 84 07 CC 39 C5
2018-08-16 18:36:09.783 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=17, callback=4, payload=04 11 06 56 01 84 07 CC 39
2018-08-16 18:36:09.831 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=17, callback=4, payload=04 11 06 56 01 84 07 CC 39
2018-08-16 18:36:09.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=17, callback=4, payload=04 11 06 56 01 84 07 CC 39
2018-08-16 18:36:09.875 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 892: [WAIT_DATA] priority=Controller, requiresResponse=true, callback: 0
2018-08-16 18:36:09.893 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 17: Application Command Request (ALIVE:REQUEST_NIF)
2018-08-16 18:36:09.908 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: Decapsulating COMMAND_CLASS_CRC_16_ENCAP
2018-08-16 18:36:09.922 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: COMMAND_CLASS_CRC_16_ENCAP not found
2018-08-16 18:36:09.936 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

Any idea what it means?

chris · August 17, 2018, 8:08am

It likely means that the device doesn’t report CRC_16 in the list of command classes in the NIF. What version of the binding are you using? A recent one, or something older? I’d suggest to try with the latest at the top of this thread so we understand what you are using (if you’re not already of course).

DanielMalmgren · August 17, 2018, 8:14am

Yep, I’m using the one from this thread:

180 │ Active   │  80 │ 2.4.0.201808142206     │ ZWave Binding

chris · August 17, 2018, 9:06am

Ok, thanks. I’ll have a look at this later. I thought that I’d reverted a change that we made a while ago that would have explained this, but maybe not.

jwiseman · August 17, 2018, 11:30pm

Hi Chris,

Thank you for your work on this! Here’s my question . . .

Running OH2.3 on Synology with the included zWave binding your built.

Can I run the new zWave 2.4 binding on a OH2.3 install?

I understand the installation procedure you have posted but not sure about the version difference in case there are includes needed from the core of the OH2.4 core or not?

Best, Jay

JRB123 · August 18, 2018, 1:57am

No issues here after about 4 days. Looking good, thanks!

chris · August 18, 2018, 6:59am

Yes - this should be fine.

Cheers
Chris

chris · August 18, 2018, 7:27am

So, I did remember correctly, and the general code to add unknown classes was re-added into the binding already… This is a special case that wasn’t handled since it’s an encapsulation class - I’ve just modified the code to make this more consistent and I’ll update the binding at some point later today with this fix.

dan12345 · August 19, 2018, 8:01am

Just to note that the 14 August binding is working perfectly for me - all the previous versions with hold-off had been buggy and locked up after 24 hours or so.

Thank you!

Dan

chris · August 19, 2018, 8:58am

Thanks Dan. This is now merged into the master development binding.

For me, I think this is the last outstanding issue before merging this into master - if there are significant outstanding issues that people have, please shout.

DanielMalmgren · August 19, 2018, 10:41am

Did you change anything? Just tried the 2.4.0.201808182253 binding and I still get COMMAND_CLASS_CRC_16_ENCAP not found.

chris · August 19, 2018, 11:27am

Yes, but I’m just wondering if I compiled the main development branch which doesn’t have this fix in it. Just looking at the times of the JAR and the commit, I suspect this is possible…

I’ll do an update now… If it still doesn’t work, can you provide me the log entries around this again as they should change.

Sorry for the hassle…

[edit: updated]

DanielMalmgren · August 19, 2018, 11:53am

No need for feeling sorry, you’re doing a huge job with this binding!

Now it seems it got past that error. I’m still not sure if everything’s working (currently it’s changing back and forth between “Node is not communicating with controller”) but I guess that could be a matter of time so I’ll keep debug logging on and see what happens…

edit: Just for the record, my new nodes are now fully identified by the controller and working fine

mstormi · August 19, 2018, 6:39pm

Using today’s binding, I got

2018-08-19 20:35:11.399 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-08-19 20:35:11.408 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 0A 03 67 66 3B D1
2018-08-19 20:35:11.432 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=16, payload=10 0A 03 67 66 3B
2018-08-19 20:35:11.434 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=16, payload=10 0A 03 67 66 3B
2018-08-19 20:35:11.436 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=16, payload=10 0A 03 67 66 3B
2018-08-19 20:35:11.439 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-08-19 20:35:11.442 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Application Command Request (ALIVE:DYNAMIC_VALUES)
2018-08-19 20:35:11.445 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Incoming command class COMMAND_CLASS_NETWORK_MANAGEMENT_INSTALLATION_MAINTENANCE, endpoint 0
2018-08-19 20:35:11.447 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Command class COMMAND_CLASS_NETWORK_MANAGEMENT_INSTALLATION_MAINTENANCE not found, trying to add it.
2018-08-19 20:35:11.450 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Unsupported command class COMMAND_CLASS_NETWORK_MANAGEMENT_INSTALLATION_MAINTENANCE
2018-08-19 20:35:11.452 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Unsupported Z-Wave command class COMMAND_CLASS_NETWORK_MANAGEMENT_INSTALLATION_MAINTENANCE
2018-08-19 20:35:11.455 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
2018-08-19 20:35:11.458 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Exception processing frame: Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=16, payload=10 0A 03 67 66 3B :
java.lang.NullPointerException: null
        at org.openhab.binding.zwave.internal.protocol.ZWaveNode.processCommand(ZWaveNode.java:1357) [243:org.openhab.binding.zwave:2.4.0.201808191228]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveReceiveThread.run(ZWaveTransactionManager.java:484) [243:org.openhab.binding.zwave:2.4.0.201808191228]
2018-08-19 20:35:11.462 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-08-19 20:35:11.464 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-08-19 20:35:11.475 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 0A 03 67 71 66 9B
2018-08-19 20:35:11.502 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=16, payload=10 0A 03 67 71 66
2018-08-19 20:35:11.504 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=16, payload=10 0A 03 67 71 66
2018-08-19 20:35:11.506 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=16, payload=10 0A 03 67 71 66
2018-08-19 20:35:11.508 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-08-19 20:35:11.511 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 10: Application Command Request (ALIVE:DYNAMIC_VALUES)
2018-08-19 20:35:11.514 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Incoming command class COMMAND_CLASS_NETWORK_MANAGEMENT_INSTALLATION_MAINTENANCE, endpoint 0
2018-08-19 20:35:11.516 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Command class COMMAND_CLASS_NETWORK_MANAGEMENT_INSTALLATION_MAINTENANCE not found, trying to add it.
2018-08-19 20:35:11.518 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 10: Unsupported command class COMMAND_CLASS_NETWORK_MANAGEMENT_INSTALLATION_MAINTENANCE
2018-08-19 20:35:11.521 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: Unsupported Z-Wave command class COMMAND_CLASS_NETWORK_MANAGEMENT_INSTALLATION_MAINTENANCE
2018-08-19 20:35:11.523 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
2018-08-19 20:35:11.528 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Exception processing frame: Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=16, payload=10 0A 03 67 71 66 :
java.lang.NullPointerException: null
        at org.openhab.binding.zwave.internal.protocol.ZWaveNode.processCommand(ZWaveNode.java:1357) [243:org.openhab.binding.zwave:2.4.0.201808191228]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveReceiveThread.run(ZWaveTransactionManager.java:484) [243:org.openhab.binding.zwave:2.4.0.201808191228]

chris · August 19, 2018, 6:43pm

What is node 10? My guess is it’s got a problem as the frame doesn’t look correct. It’s possible though that it’s real and it’s doing something super new?

Probably you need to reset node 10.