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

[romain]

Finally, after a lot of trials, reboots, resets, reinclude, re-awake… it works !

I do not really understand what finally made the things up.

Thank you for your help.

Regards,

Romain

[paulfaure]

I am using the UI to configure my things. Could never get the text files to
work.

[paulfaure]

Hi @chris
Sorry for the all the messages. I installed a fresh copy of OH 2.3 snapshot, enabled only your latest zwave binding and tested the inclusion. This is the result:
http://www.faure.ca/~paul/openhab.mar1.log

Inclusion doesn’t error out right away, but I still can’t add my lock.

[paulfaure]

When I downgraded to a fresh 2.2.0 stable with no other binding or configuration other than zwave, i got the immediate error upon starting zwave inclusion.

[chris (Chris Jackson)]

@paulfaure

This is the result:

http://www.faure.ca/~paul/openhab.mar1.log

Inclusion doesn’t error out right away, but I still can’t add my lock.

Yes, unfortunately the stick is returning an error immediately when put into inclusion.

While the logs don’t show any other activity, I’m a little suspicious that you are doing this too quickly after starting the binding. While it should (probably) work, there’s often a lot of activity after startup and this might have an impact. Maybe I’m wrong about this and you’re not doing it at startup, but I see the thing types being set, and this normally only happens immediately after start.

[5iver (Scott Rushworth)]

@5iver

I have a rule for this and will create a post to share it. Saves a lot of time if you have more than a couple devices. But still a huge PITA to have to change 30+ temperature scales from Celsius to Fahrenheit. I know it can be done in the rule, but haven’t quite figured it out yet. Sure wish there was a default setting for that…

Here is the rule that I made to automate deleting and rediscovering Zwave Things. I finally figured out how to also reconfigure the temperature scale too!

Rule for deleting and rediscovering Things

OH2 does not currently have a mechanism for updating Thing types. When a binding update includes new or modified Channel definitions, the Thing needs to be manually deleted and recreated in order to use the new/modified Channel. For most bindings, it is not too cumbersome to do this manually. But when you are using the Zwave binding with ~120 devices, this can be a real headache. Here is an example of how I have automated the deletion, rediscovery, and reconfiguration of my Zwave Things. I run t…

[paulfaure]

I waited overnight and still have the error our immediately on OH 2.2.
But somehow this is fixed in OH 2.3 SNAPSHOT which is good. I dont see an error message in habmin.
Should i be using 2.2 or 2.3 snapshot?

[chris (Chris Jackson)]

So long as you’re using the correct version of the binding, I don’t think it should matter. Maybe there were changes to the serial driver that I’m not aware of though, but otherwise either should be fine.

[chris (Chris Jackson)]

Interesting (but good I guess ).

[romain]

Finally (again), it does not work anymore… After a system restart, now the node status is blocked on

Node initialising: REQUEST_NIF

and the famous

NODE 2: SECURITY_ERR No valid NONCE! null

is back at any message reception from the device

[5iver (Scott Rushworth)]

2.3.0.201803032222 … all of the notifications in Habmin are looking like this…

Unrelated uncaught exception too…

Exception in thread "Timer-69" java.lang.NullPointerException
        at org.openhab.binding.zwave.internal.protocol.ZWaveNode$WakeupTimerTask.run(ZWaveNode.java:1438)
        at java.util.TimerThread.mainLoop(Timer.java:555)
        at java.util.TimerThread.run(Timer.java:505)

[chris (Chris Jackson)]

@5iver

Unrelated uncaught exception too…

Interesting - this isn’t a new issue it seems. Do you have any idea what node this is related to, and if so, what the device is? You might find the following debug message logged -:

NODE XX: COMMAND_CLASS_WAKE_UP not found

[chris (Chris Jackson)]

Hopefully these two issues are now resolved.

[5iver (Scott Rushworth)]

@chris

Do you have any idea what node this is related to

It’s a bit of a guess, but… there is a VRMX1 dimmer showing this…

It was still at Request NIF when I woke up. I manually toggled it and it completed initialization. It should look like this…

@chris

COMMAND_CLASS_WAKE_UP not found

Couldn’t find that in the log, but there was a period when I had debug turned off. Found a lot of these though, from all types of battery powered devices…

zwave.log.10:2018-03-03 21:55:11.562 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 100: ArrayIndexOutOfBoundsException COMMAND_CLASS_SECURITY V0 SECURITY_NONCE_REPORT 98 80 : null
zwave.log.11:2018-03-03 22:04:29.625 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 102: ArrayIndexOutOfBoundsException COMMAND_CLASS_BASIC V1 BASIC_REPORT 20 03 : null
zwave.log.12:2018-03-03 22:08:45.216 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 96: ArrayIndexOutOfBoundsException COMMAND_CLASS_SECURITY V0 SECURITY_NONCE_REPORT 98 80 : null
zwave.log.13:2018-03-03 22:15:36.330 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 46: ArrayIndexOutOfBoundsException COMMAND_CLASS_SENSOR_MULTILEVEL V4 SENSOR_MULTILEVEL_REPORT 31 05 01 : null
zwave.log.14:2018-03-03 22:25:16.852 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 100: ArrayIndexOutOfBoundsException COMMAND_CLASS_SECURITY V0 SECURITY_NONCE_REPORT 98 80 : null
zwave.log.19:2018-03-03 23:09:12.172 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 57: ArrayIndexOutOfBoundsException COMMAND_CLASS_SENSOR_MULTILEVEL V0 SENSOR_MULTILEVEL_REPORT 31 05 01 : null
zwave.log.43:2018-03-04 02:27:48.720 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 71: ArrayIndexOutOfBoundsException COMMAND_CLASS_BATTERY V1 BATTERY_REPORT 80 03 : null
zwave.log.27:2018-03-04 00:15:37.911 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 51: ArrayIndexOutOfBoundsException COMMAND_CLASS_SENSOR_MULTILEVEL V4 SENSOR_MULTILEVEL_REPORT 31 05 01 : null

And some of these…

zwave.log.27:2018-03-04 00:39:41.744 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 112: Command class COMMAND_CLASS_SWITCH_ALL not found, trying to add it.
zwave.log.27:2018-03-04 00:39:41.910 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 112: Command class COMMAND_CLASS_SCENE_CONTROLLER_CONF not found, trying to add it.
zwave.log.27:2018-03-04 00:39:41.939 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 112: Command class COMMAND_CLASS_SWITCH_MULTILEVEL not found, trying to add it.
zwave.log.3:2018-03-03 21:12:44.842 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 120: Command class COMMAND_CLASS_SWITCH_MULTILEVEL not found, trying to add it.
zwave.log.31:2018-03-04 01:11:11.924 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 6: Command class COMMAND_CLASS_SENSOR_MULTILEVEL not found, trying to add it.

I tracked one down to this, but the device is a WAPIR motion sensor (no SWITCH_MULTILEVEL), so maybe the messages in the queue got jumbled up?

2018-03-04 00:39:41.933 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 21 00 04 10 70 1B 26 81 29 CD A7 34 46 A6 01 A4 30 F7 3E A1 DD 63 9B 1F 88 19 BB EE 28 C1 A2 EC 8E BB 
2018-03-04 00:39:41.937 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=112, callback=16, payload=10 70 1B 26 81 29 CD A7 34 46 A6 01 A4 30 F7 3E A1 DD 63 9B 1F 88 19 BB EE 28 C1 A2 EC 8E 
2018-03-04 00:39:41.938 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=112, callback=16, payload=10 70 1B 26 81 29 CD A7 34 46 A6 01 A4 30 F7 3E A1 DD 63 9B 1F 88 19 BB EE 28 C1 A2 EC 8E 
2018-03-04 00:39:41.938 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=112, callback=16, payload=10 70 1B 26 81 29 CD A7 34 46 A6 01 A4 30 F7 3E A1 DD 63 9B 1F 88 19 BB EE 28 C1 A2 EC 8E 
2018-03-04 00:39:41.938 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 5643: [WAIT_REQUEST] requiresResponse=true callback: 161
2018-03-04 00:39:41.938 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 112: Application Command Request (ALIVE:REQUEST_NIF)
2018-03-04 00:39:41.939 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 112: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2018-03-04 00:39:41.939 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 112: Command class COMMAND_CLASS_SWITCH_MULTILEVEL not found, trying to add it.
2018-03-04 00:39:41.939 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 112: Creating new instance of command class COMMAND_CLASS_SWITCH_MULTILEVEL
2018-03-04 00:39:41.939 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 112: Command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0 created
2018-03-04 00:39:41.939 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 112: Adding command class COMMAND_CLASS_SWITCH_MULTILEVEL to endpoint 0
2018-03-04 00:39:41.940 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 112: Adding command class COMMAND_CLASS_SWITCH_MULTILEVEL to the list of supported command classes.
2018-03-04 00:39:41.940 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 112: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
2018-03-04 00:39:41.940 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 112: Received COMMAND_CLASS_SWITCH_MULTILEVEL V0 unknown command 129
2018-03-04 00:39:41.940 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 112: Commands processed 1.
2018-03-04 00:39:41.940 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 112: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@fbaa8e6.
2018-03-04 00:39:41.940 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 112: Checking transaction 5643  null.
2018-03-04 00:39:41.940 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 112: Checking transaction : state >> WAIT_REQUEST
2018-03-04 00:39:41.940 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 112: Checking transaction : node  >> 96
2018-03-04 00:39:41.940 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 112: Checking transaction : class >> 38 == null.
2018-03-04 00:39:41.940 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 112: Checking transaction : commd >> 129 == 0.
2018-03-04 00:39:41.940 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 112: Ignoring transaction since not waiting for data.

@chris

Hopefully these two issues are now resolved.

[chris (Chris Jackson)]

@5iver

Found a lot of these though, from all types of battery powered devices…

This is “fine” - fine in that the binding is handling these corrupted messages ok. All of these messages are too short to be handled, the binding is catching the exception that gets thrown, and then printing the message that was received. The null on the end is the message from the exception - I might remove this as it looks not so useful

@5iver

And some of these…

Again, this is fine (this time fine, not “fine” ). This possibly means the device didn’t report these command classes in its NIF, but the binding then received a message from them so added it. It can also happen if messages are received before the device is initialised (for basically the same reason - except we’ve not received the NIF yet).

[5iver (Scott Rushworth)]

@chris

This possibly means the device didn’t report these command classes in its NIF, but the binding then received a message from them so added it

That part makes sense, but these are not command classes reported by these devices. The log looks like they are, but that can’t be accurate. And it would explain the oddity with the VRMX1. I’m still searching the logs for it’s initialization, which I’m guessing will look like a motion sensor.

[chris (Chris Jackson)]

@5iver

these are not command classes reported by these devices

Ok, then I guess it’s as you suggested - the messages got scrambled somewhere. The error detection on the ZWave packets is not very strong - both between the controller and the PC, but also between the controller and the remote device. This means that the ability to detect errors on the RF link is not great. This is why ZWave introduced the CRC encapsulation command class a while ago, but not too many devices use it still.

[hl_at (Herbert)]

Hi @chris!

Just updated - the notifications mentioned by @5iver are still the same in Habmin.

Regards,
Herbert

[chris (Chris Jackson)]

Hmm - strange. Maybe I didn’t export the right version then as it is ok here . I’ll take another look later on.

[5iver (Scott Rushworth)]

@hl_at

Just updated - the notifications mentioned by @5iver are still the same in Habmin.

Ditto