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

Add-ons Bindings
,
1443

I set DEBUG on zwave (log:set DEBUG org.openhab.binding.zwave) and have a 1.7MB dump of the trace during the enumeration. Given the size I don’t want to just C&P it here… so guidance on what specifically would be interesting to look at would help.

Here’s the very top, filtering the log for the node number (77):

2017-08-05 18:02:21.984 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 77: Device discovered
2017-08-05 18:02:21.984 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:controller:node77' to inbox.
2017-08-05 18:02:21.984 [InboxAddedEvent           ] - Discovery Result with UID 'zwave:device:controller:node77' has been added.
2017-08-05 18:02:21.984 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: Starting initialisation from INCLUSION_START
2017-08-05 18:02:21.984 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: Node advancer: Node just included (73885459)
2017-08-05 18:02:21.985 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: Node advancer - advancing to IDENTIFY_NODE
2017-08-05 18:02:21.985 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: Node advancer: Initialisation starting from inclusion
2017-08-05 18:02:21.988 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 77: ProtocolInfo
2017-08-05 18:02:21.988 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 77: Listening = false
2017-08-05 18:02:21.988 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 77: Routing   = true
2017-08-05 18:02:21.988 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 77: Beaming   = true
2017-08-05 18:02:21.988 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 77: Version   = 4
2017-08-05 18:02:21.988 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 77: FLIRS     = true
2017-08-05 18:02:21.988 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 77: Security  = false
2017-08-05 18:02:21.988 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 77: Max Baud  = 40000
2017-08-05 18:02:21.988 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 77: Basic    = BASIC_TYPE_ROUTING_SLAVE
2017-08-05 18:02:21.988 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 77: Generic  = GENERIC_TYPE_ENTRY_CONTROL
2017-08-05 18:02:21.988 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 77: Specific = SPECIFIC_TYPE_SECURE_KEYPAD_DOOR_LOCK
2017-08-05 18:02:21.988 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 77: Creating new instance of command class COMMAND_CLASS_NO_OPERATION
2017-08-05 18:02:21.989 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 77: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created
2017-08-05 18:02:21.989 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 77: Version = 1, version set. Enabling extra functionality.
2017-08-05 18:02:21.989 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes.
2017-08-05 18:02:21.989 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 77: Creating new instance of command class COMMAND_CLASS_BASIC
2017-08-05 18:02:21.989 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 77: Command class COMMAND_CLASS_BASIC, endpoint 0 created
2017-08-05 18:02:21.989 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes.
2017-08-05 18:02:21.989 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: Node Init response (0) COMPLETE
2017-08-05 18:02:21.989 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: Node Init transaction completed with response COMPLETE
2017-08-05 18:02:22.989 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: Node is listening - ignore wakeup
2017-08-05 18:02:22.989 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: Node advancer - advancing to SECURITY_REPORT
2017-08-05 18:02:22.990 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 77: Updated networkKey
2017-08-05 18:02:22.990 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 77: setupNetworkKey useSchemeZero=false
2017-08-05 18:02:22.990 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: Performing secure inclusion.
2017-08-05 18:02:22.990 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: SECURITY_INC State=GET_SCHEME
2017-08-05 18:02:22.991 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: ZWaveCommandClassTransactionPayload - send to node
2017-08-05 18:02:22.992 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: Encapsulating message, endpoint 0
2017-08-05 18:02:22.992 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: SECURITY check internal
2017-08-05 18:02:22.992 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: Command Class COMMAND_CLASS_SECURITY is NOT required to be secured
2017-08-05 18:02:22.993 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@3c989c8c
2017-08-05 18:02:22.993 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: Adding to device queue
2017-08-05 18:02:22.993 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: Added to queue - size 0
2017-08-05 18:02:22.994 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: listening == false, frequentlyListening == true, awake == false
2017-08-05 18:02:22.995 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 77: Sending REQUEST Message = 01 0A 00 13 4D 03 98 04 00 25 3A 2B 
2017-08-05 18:02:23.004 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 77: Sent Data successfully placed on stack.
2017-08-05 18:02:23.004 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: TID 1750: Transaction not completed
2017-08-05 18:02:23.119 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 77: SendData Request. CallBack ID = 58, Status = Transmission complete, no ACK received(1)
2017-08-05 18:02:23.120 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: TID 1750: Transaction completed
2017-08-05 18:02:23.120 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: notifyTransactionResponse TID:1750 CANCELLED
2017-08-05 18:02:23.120 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: -- To notify -- TIMEOUT_WAITING_FOR_RESPONSE
2017-08-05 18:02:23.120 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: Node Init response (0) TIMEOUT_WAITING_FOR_RESPONSE
2017-08-05 18:02:23.120 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: ZWaveCommandClassTransactionPayload - send to node
2017-08-05 18:02:23.120 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: Encapsulating message, endpoint 0
2017-08-05 18:02:23.120 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: SECURITY check internal
2017-08-05 18:02:23.120 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: Command Class COMMAND_CLASS_SECURITY is NOT required to be secured
2017-08-05 18:02:23.120 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@3c989c8c
2017-08-05 18:02:23.120 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: Adding to device queue
2017-08-05 18:02:23.120 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: Added to queue - size 0
2017-08-05 18:02:23.120 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: listening == false, frequentlyListening == true, awake == false
2017-08-05 18:02:23.120 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 77: Sending REQUEST Message = 01 0A 00 13 4D 03 98 04 00 25 3B 2A 
2017-08-05 18:02:23.132 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 77: Sent Data successfully placed on stack.
2017-08-05 18:02:23.132 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: TID 1751: Transaction not completed
2017-08-05 18:02:23.266 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 77: SendData Request. CallBack ID = 59, Status = Transmission complete, no ACK received(1)
2017-08-05 18:02:23.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: TID 1751: Transaction completed
2017-08-05 18:02:23.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: notifyTransactionResponse TID:1751 CANCELLED
2017-08-05 18:02:23.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: -- To notify -- TIMEOUT_WAITING_FOR_RESPONSE
2017-08-05 18:02:23.267 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: Node Init response (0) TIMEOUT_WAITING_FOR_RESPONSE
2017-08-05 18:02:23.267 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: ZWaveCommandClassTransactionPayload - send to node
2017-08-05 18:02:23.267 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: Encapsulating message, endpoint 0
2017-08-05 18:02:23.267 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: SECURITY check internal
2017-08-05 18:02:23.267 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: Command Class COMMAND_CLASS_SECURITY is NOT required to be secured

[… repeats in a similar vein for a while…]

2017-08-05 18:02:32.916 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: ZWaveCommandClassTransactionPayload - send to node
2017-08-05 18:02:32.916 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: Encapsulating message, endpoint 0
2017-08-05 18:02:32.916 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: SECURITY check internal
2017-08-05 18:02:32.916 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: Command Class COMMAND_CLASS_SECURITY is NOT required to be secured
2017-08-05 18:02:32.916 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@3c989c8c
2017-08-05 18:02:32.916 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: Adding to device queue
2017-08-05 18:02:32.916 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: Added to queue - size 0
2017-08-05 18:02:32.916 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: listening == false, frequentlyListening == true, awake == false
2017-08-05 18:02:32.916 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 77: Sending REQUEST Message = 01 0A 00 13 4D 03 98 04 00 25 84 95 
2017-08-05 18:02:32.927 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 77: Sent Data successfully placed on stack.
2017-08-05 18:02:32.927 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: TID 1824: Transaction not completed
2017-08-05 18:02:33.047 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 77: SendData Request. CallBack ID = 132, Status = Transmission complete, no ACK received(1)
2017-08-05 18:02:33.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: TID 1824: Transaction completed
2017-08-05 18:02:33.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: notifyTransactionResponse TID:1824 CANCELLED
2017-08-05 18:02:33.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: -- To notify -- TIMEOUT_WAITING_FOR_RESPONSE
2017-08-05 18:02:33.048 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: Node Init response (0) TIMEOUT_WAITING_FOR_RESPONSE
2017-08-05 18:02:33.048 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: timed out after 10056307193 / 10000000000
2017-08-05 18:02:33.048 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: SECURITY_INC State=FAILED
2017-08-05 18:02:33.048 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: Node advancer - advancing to MANUFACTURER
2017-08-05 18:02:33.048 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: Node advancer: MANUFACTURER - send ManufacturerSpecific
2017-08-05 18:02:33.048 [DEBUG] [WaveManufacturerSpecificCommandClass] - NODE 77: Creating new message for command MANUFACTURER_SPECIFIC_GET
2017-08-05 18:02:33.048 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: ZWaveCommandClassTransactionPayload - send to node
2017-08-05 18:02:33.048 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: Encapsulating message, endpoint 0
2017-08-05 18:02:33.048 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: SECURITY NOT required on COMMAND_CLASS_MANUFACTURER_SPECIFIC
2017-08-05 18:02:33.048 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: Command Class COMMAND_CLASS_MANUFACTURER_SPECIFIC is NOT required to be secured
2017-08-05 18:02:33.048 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@4874d2a3
2017-08-05 18:02:33.048 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: Adding to device queue
2017-08-05 18:02:33.048 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: Added to queue - size 0
2017-08-05 18:02:33.048 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: listening == false, frequentlyListening == true, awake == false
2017-08-05 18:02:33.049 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 77: Sending REQUEST Message = 01 09 00 13 4D 02 72 04 25 85 7C 
2017-08-05 18:02:33.060 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 77: Sent Data successfully placed on stack.
2017-08-05 18:02:33.060 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: TID 1825: Transaction not completed
2017-08-05 18:02:33.077 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 77: SendData Request. CallBack ID = 133, Status = Transmission complete and ACK received(0)
2017-08-05 18:02:33.077 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: TID 1825: Transaction not completed
2017-08-05 18:02:37.035 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: Application Command Request (ALIVE:MANUFACTURER)
2017-08-05 18:02:37.035 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: Incoming command class COMMAND_CLASS_MANUFACTURER_SPECIFIC, endpoint 0
2017-08-05 18:02:37.035 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 77: SECURITY NOT required on COMMAND_CLASS_MANUFACTURER_SPECIFIC
2017-08-05 18:02:37.035 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 77: Received COMMAND_CLASS_MANUFACTURER_SPECIFIC V0 MANUFACTURER_SPECIFIC_REPORT
2017-08-05 18:02:37.035 [DEBUG] [WaveManufacturerSpecificCommandClass] - NODE 77: Manufacturer ID = 0x0090
2017-08-05 18:02:37.035 [DEBUG] [WaveManufacturerSpecificCommandClass] - NODE 77: Device Type     = 0x0001
2017-08-05 18:02:37.035 [DEBUG] [WaveManufacturerSpecificCommandClass] - NODE 77: Device ID       = 0x0001

Node security state is failed at 18:02:33.048.

Without the ‘Node 77’ filter, the complete log just before that is:

2017-08-05 18:02:33.047 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=132, payload=84 01 00 0D 
2017-08-05 18:02:33.047 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 77: SendData Request. CallBack ID = 132, Status = Transmission complete, no ACK received(1)
2017-08-05 18:02:33.047 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1824: Transaction CANCELLED
2017-08-05 18:02:33.047 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1824: TransactionAdvance ST: CANCELLED
2017-08-05 18:02:33.047 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1824: TransactionAdvance WT: ApplicationCommandHandler {}
2017-08-05 18:02:33.047 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1824: TransactionAdvance RX: Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=132, payload=84 01 00 0D 
2017-08-05 18:02:33.047 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1824: TransactionAdvance TO: CANCELLED
2017-08-05 18:02:33.047 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-08-05 18:02:33.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: TID 1824: Transaction completed
2017-08-05 18:02:33.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: notifyTransactionResponse TID:1824 CANCELLED
2017-08-05 18:02:33.047 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-08-05 18:02:33.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-08-05 18:02:33.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 1824: Transaction event listener: DONE: CANCELLED -> 
2017-08-05 18:02:33.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-08-05 18:02:33.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: -- To notify -- TIMEOUT_WAITING_FOR_RESPONSE
2017-08-05 18:02:33.047 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 38: listening == false, frequentlyListening == false, awake == false
2017-08-05 18:02:33.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 38: Node not awake!
2017-08-05 18:02:33.047 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: listening == false, frequentlyListening == false, awake == false
2017-08-05 18:02:33.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Node not awake!
2017-08-05 18:02:33.047 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 47: listening == false, frequentlyListening == false, awake == false
2017-08-05 18:02:33.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 47: Node not awake!
2017-08-05 18:02:33.047 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 38: listening == false, frequentlyListening == false, awake == false
2017-08-05 18:02:33.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 38: Node not awake!
2017-08-05 18:02:33.048 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete 1824 -- 
2017-08-05 18:02:33.048 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 38: listening == false, frequentlyListening == false, awake == false
2017-08-05 18:02:33.048 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 38: Node not awake!
2017-08-05 18:02:33.048 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: Node Init response (0) TIMEOUT_WAITING_FOR_RESPONSE
2017-08-05 18:02:33.048 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-08-05 18:02:33.048 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: timed out after 10056307193 / 10000000000
2017-08-05 18:02:33.048 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2017-08-05 18:02:33.048 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
2017-08-05 18:02:33.048 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-08-05 18:02:33.048 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: SECURITY_INC State=FAILED
2017-08-05 18:02:33.048 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 77: Node advancer - advancing to MANUFACTURER

Sorry about the very long post. If there are more friendly ways to provide and discuss log files please let me know…

1444

A lot of times I just upload it to my Google Drive and share it with @chris He’s going to have to look at the above and let you know if he has any ideas or needs more info. It’s above my pay grade at this point. Just wanted to help you get enough info to him to troubleshoot.

I did notice the timeouts. The one thing I do is keep hitting the inclusion button on my lock every time the light goes out to make sure it stays awake to complete the inclusion (I don’t know if that actually helps or not ;-).

1445

@chris I think found a bug with my DSC06 Smart Energy Switch (Node 43 for me). I’m pulling the Energy_kWh channel and getting the following error in my logs. Let me know if you want a full debug log.

2017-08-08 15:09:18.266 [ERROR] [.commandclass.ZWaveMeterCommandClass] - NODE 43: Meter Report: Buffer too short: length=3, required=4
1446

Grab the received message associated with this and I’ll take a look, but I think that this probably means there’s not enough data to process correctly…

1447

I’ll try to catch them. Looks about every 1/2 hour though not as many this afternoon.

1448

Still haven’t gotten secure inclusion of the lock working. My next step would seem to be including it in a clean (no other devices) network. But, I don’t want to reset my current stick and go through the effort of re-including all my existing devices. I did that for a clean OH1->OH2 transfer, and it sucked.

[Edit: Ignore below. I tried a multi-stick install it and it seems to be working… but lock inclusion still doesn’t. So, continuing to play around with that.]

Does the binding support a multi-instance installation? My thinking is to get another USB Zwave stick, and try including only the secure device on that stick, with all other devices on the existing stick. But, I’m not sure how to include a binding twice, or have a single binding use two sticks.

Chris, you mentioned in a year-old thread that OH2 “should (in theory)” support this… but I didn’t see any evidence that theory and reality ever converged, or how to make it work…

_https://community.openhab.org/t/multiple-z-wave-bindings/10716/27_

In general, would having the secure and not-secure devices on different zwave networks/sticks offer any benefits in terms of either reliability or security?

1449

No - there isn’t a way to run the binding twice, but this isn’t what you really want is it? You just want to have two sticks - right?

Sure - this is perfectly possible in OH2 - just add two interfaces.

Probably not any advantages. You might have issues with interference, but hopefully it won’t cause too many issues.

1450

Thanks for the quick reply… after writing the post I tried it and it worked. You responded while I was editing. Too quick! :slight_smile: Lock inclusion still doesn’t work, but the log files are much cleaner so it’s easier to see what’s happening. I’ll play with that for a while.

1451

Just an update… it works now. What I ended up doing was getting a second USB zwave stick, and adding it as another interface. Just trying to add the new device after adding the usb stick didn’t work… (I’m not sure how to specifically enable zwave inclusion on one interface of the binding?) So, I pulled the ‘main’ zwave stick out, and just ran inclusion on the second stick. This worked the third time I tried.

At this point, I can send commands (door lock/unlock works) but the updates from the device don’t seem to be reflected in the items… if I manually lock/unlock I don’t see events, and the alarm, battery, etc., are not updated. Stlll debugging that.

Thanks for all your hard work on zwave and openhab, Chris!

1452

Yes, that is one of the shortcomings in the current dev version when using 2 sticks. Would be nice to have that more controllable.

1453

This is a limitation of the system - not the binding. I opened an issue about this some time back…

1454

Interesting. What about extending the mechanism used to ‘Exclude Devices’ in the Advanced Settings part of each instance; putting a ‘Include Devices’ mechanism there, and some way of having the binding discovery just query the interfaces for newly included devices would be hacky and less convenient for users with only one interface (ie. almost everyone…). Maybe an additional port configuration, “Interface enters Include Mode on Discovery”,or such, that defaults to true, but multi-interface users could disable and trigger inclusion manually for each interface?

Sorry, getting off the ‘Security’ topic of the thread (which works! Yay!), but given my experience the reliability of secure inclusion will drive more people to try multiple sticks, and the multiple-interface use case might become more common…

1455

This is really a hack. The system should support this and I’d prefer not to try and hack something into the binding.

I’d prefer to put time into solving the issue to avoid this - it’s likely to cause other problems, and isn’t nice. I’ll likely look to invest more into getting the info needed to resolve this.

1 Like
1456

I have the inclusion issue on a second lock I bought. Anything I can do to help you find the issue?

1457

Probably not - I’m happy to look at a log, but I suspect that it will just show the device not responding which is what I’ve seen in other logs.

I’m considering investing in the full developers kit to try and get this resolved - let’s see…

1458

So I’ve been working through a lot of my problems so far without resorting to asking a dumb question, and I’ve been entirely successful so far thanks to a lot of the forum posts I’ve searched around. Have my garage door controller included securely and working great, my door lock actually works (Yale Real Living). OpenHab is kicking butt, especially since I created an XML for my Alarm.com thermostat (put in my created xml via a ticket on the database site, same as the building 36 one actually).

Now that being said, I’m stumped. As I said, I have my door lock added, and it works. But, I’m missing a few things when I view the item in Habmin. I have no configuration options nor user codes. The only sections I see are “Description,” “Properties,” “Channels,” and “Attributes.” I know there are supposed to be other sections, I’ve tried enabling view advanced settings and it helps nothing. My Zipato keypad (same product as the wintop rfid keypad, different ID) also does the same thing. No user codes options or configuration area.

Anyone have an idea what the heck I’ve done wrong? Door lock says it’s added securely in attributes… Keypad for some ungodly reason doesn’t support security, but should still work regardless. Looking forward to fixing this last problem in my system!!! Any help is appreciated. And the work put in to helping the community by many here, especially Chris, is astounding. I downloaded the dev binding from here, the 2.1, probably 1-2 weeks ago if that helps at all. Thanks!

1459

how much is the developers’ kit?

1460

Well, it’s north of $1000, but it also has requirements that would mean a small part of the binding could not be open source. This is limited to the very low level communications with the stick so is a very small part of the binding which could be split out so that there was an OS version that worked like the current binding (ie using the current source), and a closed source part that hopefully solved issues that people have (like deleting nodes from the stick, and improving healing). All the command class stuff would remain OS in any case… Most people wouldn’t notice the difference - it’s just this part of the source that would have to be a JAR instead of Java…

(sorry - that was a long answer to a short question :wink: ).

1461

Is it possible that would be something that the OH Foundation can invest into? Not sure what stores of any $ they may have raised or put together at this point. But for something so wide-spread to the ZWave functionality - seems like a worthwhile direction of investment.

$1k seems like a pretty penny of a hit to an individual. I guess the alternative could be some type of a “bug bounty” type situation where once enough people pledge the $ to raise to the $1k mark, then you could initiate the purchase? I mean at scale, the OH community of ZWave users is fairly large. It shouldn’t be hard to find 1k users to donate $1, or in some instances many would likely donate or pledge $10 and we’re down to just 100 users.

Just some food for thought.

1462

Sooo, I wanted to suggest the bug bounty. As a developer though I think it’s a bad idea because it contributes to short sighted bug fixes rather than longer term goals.

Since I’ve just about gotten my OH2 working (just trying to figure out why user codes aren’t showing as well) I want to get Z-Wave over the finish line. I’m happy to contribute to a campaign where we could raise money for a dev kit AND maybe pay for some of @chris’ time (or however he chooses to use the extra $).