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

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!

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?

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.

Interesting (but good I guess :wink: ).

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
:frowning:

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

image

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)

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

Hopefully these two issues are now resolved.

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…

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.

:no_mouth:

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 :wink:

Again, this is fine (this time fine, not “fine” :wink: ). 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).

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.

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.

1 Like

Hi @chris!

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

Regards,
Herbert

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

Ditto

Ok, I must have messed something up with the export as I only tested it in the IDE… I’ll do an update a bit later.

Thanks.

Hi Chris,

I configured my zwave devices in config files. If I change configuration parameters in Habmin, an INFO appears in the log file and the parameter is not set.

Received HTTP PUT request for update configuration at ‘things/zwave:fibaro_fgwp102_03_002:controller:node12/config’ for an unmanaged thing ‘zwave:fibaro_fgwp102_03_002:controller:node12’.

If I added the zwave thing as thing in paperui or habmin, the configuration works fine.

I used the latest February snapshot version.

Regards,
Holly

Unfortunately it’s not possible to configure parameters within openHAB if you configure things in a file. ESH blocks configuration calls from the UI from getting to the binding if the thing is configured in a file.

Hi @5iver what version of OH do you use?

Bad news :-/