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

Here’s a log file showing the initialization of the Minimote, node 96.
https://drive.google.com/open?id=17xgAD0-e1W8FAhSHrm9fnQrR0kpFA65p

The device is discovered and identified correctly as a Minimote.

However, after a few wake-ups, while it does receive the NIF, it doesn’t seem to be going beyond that? It’s not even clear to me whether its doing anything with the NIF. Seems odd (at least to me) that the receipt of the NIF is appearing in the log file before the WAKEUP notification is logged. But maybe that’s normal. I also see that the NIF contains an unsupported command class (COMMAND_CLASS_ASSOCIATION_COMMAND_CONFIGURATION). Could this be causing a problem?

I’ve just updated the binding (link still at the top of this thread). Two points to note -:

  1. This version now has the “new” DEAD node code merged.
  2. The filename has changed to version 2.4-SNAPSHOT

There are still a couple of issues I will try to merge in the coming days, but if there are no major complaints with this version in the next week or two, then I will merge this into master.

Hi Chris, I have been frequently updating my zwave binding from this thread without any major issues. I just tried out the new version of the binding you posted and now see issues with node availability. About 1/3 of my nodes show as offline, I have approximately 60 mains devices and 1 battery device (Yale deadbolt). I can post a log file, I just need to first update my logging config for zwave to write to its own file as I have other noise in the main log.

Right now, I have only two dead nodes. So, it appears to sort itself out with time. These nodes will eventually wakeup and raise from the dead. I’ve seen no loss in functionality due to this. After a restart, devices of all types can show up dead. After a day or so, the mains piowered devices are alive and some battery devices are dead. Give it a few more days, and they seem to all get sorted, for the most part. I have not been able to identify anything in the logs, but it seem to be related to battery devices going to sleep and being marked as dead. Right after a restart, it looks like mains devices are being marked dead due to the amount of traffic.

I think one of the most important things to do in preparation for the merge is to find a prominent place in the zwave docs to educate people on the need for deleting Things. Not just for the upgrade, but for updating Thing definitions that have been changed. Maybe this would fit in the Device Database section, but it’s kind of buried.

Yes please - please email it over or raise a ticket on my site. It would be interesting to see if there’s any similarity to @5iver logs.

Good idea - I’ll add something for this.

1 Like

@chris

I see in this commit that the Minimote was changed.

It was changed from

<property name="commandClass:COMMAND_CLASS_WAKE_UP">getSupported=false</property>

to

<property name="commandClass:COMMAND_CLASS_WAKE_UP">ccAdd</property>

I also see in the logs that the WAKE_UP_INTERVAL_GET is not working. I suspect this may be the reason why it’s not progressing through initialization?

WDYT?

@5iver I see you made the change to the Minimote database entry. This is what appears to be causing the WAKE_UP_INTERVAL_GET to fail during initialization (i.e. I don’t think the Minimote supports this transaction).

Thanks.
will this version still work with the OH2.3 release ?

I made that change, but WAKE_UP_INTERVAL_GET was failing before this was done. I thought there was more progress made with this, but it looks to have just stalled out. This PR did not resolve the issue, and appears to have made it worse, so maybe it should be rolled back? What’s odd is that there must be another change involved, because I was able to initialize minimotes after this PR was put in.

Ah, yes, I do remember this issue.

If you’re ok, I’d like to change it back to NOGET, then see what happens. I don’t know if this is the reason why the devices aren’t initializing, but it will remove one variable.

Interesting. Have you been able to initialize it (after deleting thing AND node.xml) with the latest dead node handling code?

I have three Minimotes. Two of them are white ones with the numbered buttons. Those will not initialize. One is a black one with the unnumbered buttons. That one initialized successfully. All three report the same firmware number. Which device(s) do you have?

I have the first gen (numbered buttons). I just deleted the Thing, deleted the XML rediscovered, and it came right back up. Maybe I need to restart after deleting the XML? How close is the minimote to the controller when you are waking it up, and have you tried it closer?

Hang on… something’s fishy here. The device works and Habmin shows it as initialized, but no XML was created. Hmmm…

It’s within about 15 feet of the controller. It seems to be communicating fine.

  • Looking at the HABmin UI, everything looks correct
  • When I wake it up, I can see the binding receive the NIF
  • During initialization, I see the binding send the WAKE_UP_INTERVAL_GET, but it gets no response
  • When I press a numbered button, I see the binding receive the SCENE_ACTIVATION command, but the binding complains about SCENE_ACTIVATION command class not found

What do you see when you press a scene button?

Yes.

Restarted the binding and it came up fine… and XML was there. SCENE_ACTIVATION is properly reported and item linked to the channel is updated. Not seeing the same issue. Charge it up?

I’ll try this proper… delete the Thing and XML, and then restart OH before discovering.

Sorry - I’ve not had the chance to look at this yet as I had to go out last night. I’ll try and take a look tonight.

I think this is normal. The NIF is also used as a wakeup - so the NIF is processed, then the binding sets the device awake.

No - this class isn’t supported, but it isn’t needed (unless you think otherwise?). It’s a strange command class and certainly the fact that it isn’t supported will have no impact on the use of the device.

It has a full charge. :slightly_frowning_face:

I see this when I press a scene button. What do you see?

2018-07-03 08:22:07.272 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 5F 04 2B 01 01 00 81 
2018-07-03 08:22:07.273 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=95, callback=0, payload=00 5F 04 2B 01 01 00 
2018-07-03 08:22:07.273 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=95, callback=0, payload=00 5F 04 2B 01 01 00 
2018-07-03 08:22:07.273 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=95, callback=0, payload=00 5F 04 2B 01 01 00 
2018-07-03 08:22:07.273 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-03 08:22:07.273 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 95: Application Command Request (ALIVE:SET_WAKEUP)
2018-07-03 08:22:07.273 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 95: Incoming command class COMMAND_CLASS_SCENE_ACTIVATION, endpoint 0
2018-07-03 08:22:07.273 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 95: Command class COMMAND_CLASS_SCENE_ACTIVATION not found.
2018-07-03 08:22:07.274 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 95: Commands processed 1.

No worries.

Ok. I realized this after looking at the code.

Ok, that makes sense to me.

2018-07-03 08:15:09.982 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: Incoming command class COMMAND_CLASS_SCENE_ACTIVATION, endpoint 0
2018-07-03 08:15:09.982 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: SECURITY not supported
2018-07-03 08:15:09.982 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 212: Received COMMAND_CLASS_SCENE_ACTIVATION V0 SCENEACTIVATION_SET
2018-07-03 08:15:09.982 [DEBUG] [ocol.commandclass.ZWaveSceneActivationCommandClass] - NODE 212: Scene activation: Scene 1, Time 0
2018-07-03 08:15:09.982 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-07-03 08:15:09.982 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SCENE_ACTIVATION, value = 1
2018-07-03 08:15:09.983 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Updating channel state zwave:device:07cb40a2:node212:scene_number to 1 [DecimalType]
2018-07-03 08:15:09.985 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Commands processed 1.

BTW, I’m on zwave 2.4.0.201807021829 and snapshot 1304.

I’m on zwave 2.3.0.201807011259, snapshot 1302

What do you see before this line?

2018-07-03 08:15:09.982 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: Incoming command class COMMAND_CLASS_SCENE_ACTIVATION, endpoint 0

Edit: I’m going to install the same zwave version you’re running.

I’m grepping NODE 212, so let me know if yu want the raw data…

2018-07-03 08:12:46.198 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Device initialisation complete.
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: ProtocolInfo
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: Listening = false
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: Routing   = false
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: Beaming   = true
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: Version   = 3
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: FLIRS     = false
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: Security  = false
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: Max Baud  = 40000
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: Basic    = BASIC_TYPE_CONTROLLER
2018-07-03 08:12:46.286 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: Generic  = GENERIC_TYPE_GENERIC_CONTROLLER
2018-07-03 08:12:46.287 [DEBUG] [al.protocol.serialmessage.IdentifyNodeMessageClass] - NODE 212: Specific = SPECIFIC_TYPE_PORTABLE_REMOTE_CONTROLLER
2018-07-03 08:12:46.287 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 212: Creating new instance of command class COMMAND_CLASS_NO_OPERATION
2018-07-03 08:12:46.287 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 212: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created
2018-07-03 08:12:46.287 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 212: Version = 1, version set. Enabling extra functionality.
2018-07-03 08:12:46.287 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes.
2018-07-03 08:12:46.287 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 212: Creating new instance of command class COMMAND_CLASS_BASIC
2018-07-03 08:12:46.287 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 212: Command class COMMAND_CLASS_BASIC, endpoint 0 created
2018-07-03 08:12:46.287 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes.
2018-07-03 08:12:46.288 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 212: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@5e8387de
2018-07-03 08:12:46.288 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 212: Node Init transaction completed with response COMPLETE
2018-07-03 08:12:46.288 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 212: Node advancer - advancing to INIT_NEIGHBORS
2018-07-03 08:12:46.288 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2018-07-03 08:12:46.288 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 212: Node advancer: INIT_NEIGHBORS - send RoutingInfo
2018-07-03 08:12:46.288 [DEBUG] [.protocol.serialmessage.GetRoutingInfoMessageClass] - NODE 212: Request routing info
2018-07-03 08:15:09.982 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 212: Application Command Request (ALIVE:INIT_NEIGHBORS)
2018-07-03 08:15:09.982 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 212: Incoming command class COMMAND_CLASS_SCENE_ACTIVATION, endpoint 0