Feedback on latest zwave build

mhilbush · August 11, 2016, 3:53pm

@chris I installed a new OH2 build (#445) for the first time in a couple weeks. I wanted to give some feedback on a few things I’m seeing.

Let me know if I should open issues for any of these. As always, your work on this binding is outstanding, and very much appreciated!

The full debug log is large, and is located here:
https://drive.google.com/file/d/0Bwmcwu6ccTd_aUxEOXBKMzVtaGM/view?usp=sharing

I recall seeing that there was a format change to the node xml files, so I removed the old ones prior to startup.

###HABmin
Loving that I can install HABmin from the Paper UI or using addons.cfg! Nice!

Also l like the initialization status for each node in the thing list. Very helpful indeed!

###Binding
1:
I’m seeing many (about 100 for my 27 node network) of these “Controller handler not found” warnings at startup. – possibly because the thing handler is initialized before the bridge handler? Seem to be associated with REFRESH? I suppose these will go away when the thing lifecycle gets reworked…

2016-08-11 08:32:54.237 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-08-11 08:32:54.242 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Command received zwave:device:154acc671d8:node11:switch_binary --> REFRESH
2016-08-11 08:32:54.243 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2016-08-11 08:32:54.243 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Controller initialised.
2016-08-11 08:32:54.243 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Command received zwave:device:154acc671d8:node11:scene_number --> REFRESH
2016-08-11 08:32:54.244 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2016-08-11 08:32:54.244 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Controller status changed to UNINITIALIZED.
2016-08-11 08:32:54.245 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Controller is not online.
2016-08-11 08:32:54.287 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-08-11 08:32:54.298 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Controller initialised.
2016-08-11 08:32:54.301 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Controller status changed to UNINITIALIZED.
2016-08-11 08:32:54.302 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Controller is not online.
2016-08-11 08:32:54.309 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-08-11 08:32:54.311 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Command received zwave:device:154acc671d8:node12:sensor_door --> REFRESH

2:
I’ve seen this NPE a few times. This happens on nodes 11, 15, and 22, which all are Leviton VRS05 devices. Could be due to #3 below…

2016-08-11 08:34:02.327 [ERROR] [ve.internal.protocol.ZWaveController] - Exception during ZWave thread: Input 2. {}
java.lang.NullPointerException
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.advanceNodeStage(ZWaveNodeInitStageAdvancer.java:885)[174:org.openhab.binding.zwave:2.0.0.201608110102]
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.handleNodeQueue(ZWaveNodeInitStageAdvancer.java:230)[174:org.openhab.binding.zwave:2.0.0.201608110102]
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.ZWaveIncomingEvent(ZWaveNodeInitStageAdvancer.java:1276)[174:org.openhab.binding.zwave:2.0.0.201608110102]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.notifyEventListeners(ZWaveController.java:541)[174:org.openhab.binding.zwave:2.0.0.201608110102]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:244)[174:org.openhab.binding.zwave:2.0.0.201608110102]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:208)[174:org.openhab.binding.zwave:2.0.0.201608110102]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$7(ZWaveController.java:202)[174:org.openhab.binding.zwave:2.0.0.201608110102]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1288)[174:org.openhab.binding.zwave:2.0.0.201608110102]

3:
The Leviton VRS05 switch has 2 association groups in the zwave database. I believe I did that a while ago when I made some edits to that device. Might be causing NPE in #2 above. Could you please delete association group “GroupID 2”?

4:
I’ve not noticed this before. There appears to be a mismatch between the database and what the device reports for the BASIC command class version for the Leviton VRPD3. Should the database be updated to reflect version 0?

2016-08-11 08:34:04.916 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 17: Application Command Request (ALIVE:VERSION)
2016-08-11 08:34:04.916 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 17: Incoming command class VERSION
2016-08-11 08:34:04.916 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 17: Received VERSION command V0
2016-08-11 08:34:04.916 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 17: Process Version Command Class Report
2016-08-11 08:34:04.916 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 17: Requested Command Class = BASIC, Version = 0
2016-08-11 08:34:04.916 [INFO ] [ommandclass.ZWaveVersionCommandClass] - NODE 17: Command Class BASIC has version 0!
2016-08-11 08:34:04.916 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 17: Version = 1, version set. Enabling extra functionality.

5:
I can now set the Polling Period for a node. Yay! What’s the maximum value? It looks like it might be 7200 seconds. I have a node (14) that’s behaving a bit flaky. Until I replace it, I was hoping to set a longer polling period.

6:
For node 14, VERSION_COMMAND_CLASS_GET is being sent with a parameter “UNKNOWN(83)”. The command is never successful. What does that mean?

Edit: Is 83 hex or decimal? There is no 0x83 command class, but there is a 0x53 (83 decimal) command class (SCHEDULE). I suppose I should do the “FORCEVERSION” thing on the SCHEDULE command class for this device?

This list got a bit longer than I had expected.

I appreciate your time looking into these questions.

chris · August 11, 2016, 4:49pm

Yes - it’s something like this. I don’t think it’s an issue, and as you say once the lifecycle issues are sorted this can be reworked.

I always need to see the previous lines as they will show the data that is received and it’s likely that this caused the exception.

Done. However I don’t know why this would cause the NPE, so don’t expect it to go away…

No - it’s normal. The version is set to 0 on initialisation, and in this code it’s requested the version (since it was not set - ie 0) and now it knows it’s version 1. All good I think.

It’s 2 hours (7200 seconds).

This is just shown as unknown in the log viewer - it is really known - it’s the schedule command as you worked out (I’ve just updated the log viewer). I think you already answered what the fix is Can you update the database with the FORCEVERSION command?

No probs - nothing too difficult

mhilbush · August 11, 2016, 5:31pm

Thanks for the quick feedback.

Here are the lines preceding the NPE. It had finished doing the association for group 1. I suspected it had moved on to group 2 when the NPE occurred. That’s why I speculated that it was linked to the extra association group in the DB… Wouldn’t that be guilt by association. (pun intended)

 2016-08-11 08:34:02.322 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
 2016-08-11 08:34:02.322 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
 2016-08-11 08:34:02.322 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Node advancer - ASSOCIATIONS: Transaction complete (SendData:Request) success(true)
 2016-08-11 08:34:02.322 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Node advancer - checking initialisation queue. Queue size 1.
 2016-08-11 08:34:02.323 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Node advancer - message removed from queue. Queue size 0.
 2016-08-11 08:34:02.323 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Node advancer - ASSOCIATIONS: queue length(0), free to send(true)
 2016-08-11 08:34:02.323 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Initialisation retry timer started 5000
 2016-08-11 08:34:02.323 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 D6 00 00 03 3E 
 2016-08-11 08:34:02.323 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Node advancer: loop - ASSOCIATIONS try 1: stageAdvanced(false)
 2016-08-11 08:34:02.323 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Node advancer - advancing to SET_WAKEUP
 2016-08-11 08:34:02.324 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
 2016-08-11 08:34:02.324 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Got an event from Z-Wave network: ZWaveInitializationStateEvent
 2016-08-11 08:34:02.324 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Node advancer: loop - SET_WAKEUP try 0: stageAdvanced(true)
 2016-08-11 08:34:02.324 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Node advancer: SET_WAKEUP - Wakeup command class not supported
 2016-08-11 08:34:02.325 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Node advancer - advancing to SET_ASSOCIATION
 2016-08-11 08:34:02.325 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
 2016-08-11 08:34:02.325 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Got an event from Z-Wave network: ZWaveInitializationStateEvent
 2016-08-11 08:34:02.325 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Node advancer: loop - SET_ASSOCIATION try 0: stageAdvanced(true)
 2016-08-11 08:34:02.326 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 22: Node advancer: SET_ASSOCIATION - ASSOCIATION set for group 1
 2016-08-11 08:34:02.327 [ERROR] [ve.internal.protocol.ZWaveController] - Exception during ZWave thread: Input 2. {}
 java.lang.NullPointerException
         at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.advanceNodeStage(ZWaveNodeInitStageAdvancer.java:885)[174:org.openhab.binding.zwave:2.0.0.201608110102]
         at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.handleNodeQueue(ZWaveNodeInitStageAdvancer.java:230)[174:org.openhab.binding.zwave:2.0.0.201608110102]
         at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.ZWaveIncomingEvent(ZWaveNodeInitStageAdvancer.java:1276)[174:org.openhab.binding.zwave:2.0.0.201608110102]
         at org.openhab.binding.zwave.internal.protocol.ZWaveController.notifyEventListeners(ZWaveController.java:541)[174:org.openhab.binding.zwave:2.0.0.201608110102]
         at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:244)[174:org.openhab.binding.zwave:2.0.0.201608110102]
         at or.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:208)[174:org.openhab.binding.zwave:2.0.0.201608110102]
         at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$7(ZWaveController.java:202)[174:org.openhab.binding.zwave:2.0.0.201608110102]
         at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1288)[174:org.openhab.binding.zwave:2.0.0.201608110102]

I tried, but the SCHEDULE command class is not listed in the drop down box in the database editor.

mhilbush · August 14, 2016, 12:16pm

@chris

One other thought about the NPE during association… That incorrect association group for the VRS05 has been in the database for a while, yet I’ve never seen any errors in the logs. Could the new association code be handling that differently than before? Since the NPE occurs only on the three VRS05 nodes, I’m sticking with my theory that the NPE somehow was related to the incorrect DB entry.

And, when you get a moment, could you add the SCHEDULE command class to the command class drop down in the DB editor?

Thanks!

chris · August 14, 2016, 12:21pm

I’ve added SCHEDULE to the database - can you create an issue for the NPE in the OH2 repo and post the log there so I can track it?

Thanks

mhilbush · August 14, 2016, 12:23pm

Certainly. Thanks.