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

[rgerrans]

@Brent_Chartrand

I have a Kwiset 916 lock that I’m trying to get securely added. I’ve pulled it from the door, and it’s sitting about a foot from the USB ZWave controller, so range isn’t an issue.

I have the same lock and was able to get it included securely. I have a Aeon zstick and I think I did the inclusion directly with the stick vs. using Openhab. I had to drop it off my network yesterday so will be (hopefully) adding it back today so will try from Openhab and if that doesn’t work directly with the stick and will report back

[andrewoke]

I’ve had terrible problems with my locks and secure inclusion. If you happen to have a mains powered device that you can include securely try that. I’ve included 4 securely (first 4 nodes are aeotec multisensors) and this made secure inclusion MUCH more reliable.

I’ve found that if you in-securely include devices, include secure battery powered devices before including a secure mains powered device then dealing with secure inclusion is just a pain.

There’s a document by honeywell which explained how to fill out a z-wave network and once I followed that almost all my problems went away.

[geekshrek (shrek)]

would you mind posting a sample config of NGD00Z-4.
I just got it secure included. There are many channels listed. Which one is to open/close the door? Barrier State ?

[rgerrans]

@rgerrans

I had to drop it off my network yesterday so will be (hopefully) adding it back today so will try from Openhab and if that doesn’t work directly with the stick and will report back

@Brent_Chartrand Just to report back, I was able to add it back through normal inclusion from Habmin with no issues. Do you have your Network Security Key entered in your Zwave Controller?

[Branden_Smale]

OpenHab2 and Linear NGD00Z-4 Garage Door Controller

I am trying to use Linear NGD00Z-4 Garage Door Controller with OH2. It needs the Security Classes to be included. I am able to successfully include it in the network with OpenHab2. However, it only shows 1 channel: “BARRIER_POSITION” with type Number. There is no channel to Open/Close the Garage Door. As per this post, it should work with OH1: Unknown device with Linear NGD00Z-4 As per this post, OH2 binding now has security. OH2 Z-Wave refactoring and testing... and SECURITY What am I missi…

Post 19. Hes got the solution!

[5iver (Scott Rushworth)]

@geekshrek

would you mind posting a sample of the config of NGD00Z-4.

I posted some setup info in the following thread. The only channel that I could get values for was BARRIER_STATE. I believe the other channels should not have been included for the device because it does not support the ALARM CC. I was waiting for the OP for that thread before asking Chris about them. But I think they should be removed.

OpenHab2 and Linear NGD00Z-4 Garage Door Controller

I just looked at the XML in the binding and see BARRIER_STATE and all the other channels you are seeing. I didnt realize the device database was updated back in April. I haven’t deleted (or reinitialized) the Things for my garage openers, which would have picked up these changes! So, I reinitialized them and am in the same state as you (I’m also on 2.2.0 snapshot). I swapped my items from barrier_operator to barrier_state and everything is behaving as before. I tried the other channels and noth…

[5iver (Scott Rushworth)]

@rgerrans

I have a Aeon zstick and I think I did the inclusion directly with the stick vs. using Openhab.

To avoid confusion, this would not have been possible. The zstick needs to be plugged into USB to perform a secure inclusion, managed by the binding.

[rgerrans]

@5iver

To avoid confusion, this would not have been possible. The zstick needs to be plugged into USB to perform a secure inclusion, managed by the binding.

I reported on my follow-up posting that I did it from the openhad controller.

Thanks

[5iver (Scott Rushworth)]

My concern was that people would be trying to do secure inclusions with their sticks, so wanted to make it clear that it is not a possibility.

[p0lar]

How long in general does it take to get an recently approved device in the online web db into the jar file in snapshots?

[chris (Chris Jackson)]

@p0lar

How long in general does it take to get an recently approved device in the online web db into the jar file in snapshots?

Updates from the database are flowed into the master every few days, but for the development version, the process is more manual and I normally only do updates every week or two. However, there was an update done only a couple of days ago - what are you waiting for?

[p0lar]

The ca600 light switch I added to the db a few ago

[chris (Chris Jackson)]

Are you sure it’s not in the latest version? It looks like this was exported last on the 3rd and the last update of was the 4th. Maybe it just missed the cut, but it simply based on that it should be in there…

[p0lar]

I will double check

[Brent_Chartrand]

Yes, I have a key in the controller network settings. I counted a few times and it is indeed 16 bytes. I’ve tried a few more times, no dice.

I have ~60 zwave devices in the network, and they seem pretty active; there are lots of messages from other sensors and devices interleaved with the enumeration of the lock. Could that be messing with the timing or something? I saw someplace that it seemed secure inclusion worked better with an empty network?

What can I look for in the logs to indicate where the problem might be?

[rgerrans]

@Brent_Chartrand

What can I look for in the logs to indicate where the problem might be?

If you haven’t turned on debug while doing the inclusion yet, I’d suggest starting there.

[Brent_Chartrand]

@rgerrans

If you haven’t turned on debug while doing the inclusion yet, I’d suggest starting there.

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…

[rgerrans]

@Brent_Chartrand

If there are more friendly ways to provide and discuss log files please let me know…

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 ;-).

[rgerrans]

@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

[chris (Chris Jackson)]

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…