GD00Z-4 Fails to Securely Pair with Aeon Gen5, 1.9.0-snapshot bindings

Lou_Allegra · September 20, 2016, 1:02am

I cannot get a GD00Z-4 to pair securely. I was very careful to factory reset the GD00Z-4, to have it within inches of the zstick when pairing, keep the stick plugged in, and put it into include mode from habmin. The log file shows the pairing and then the node pinging. Can anyone help me with this?

I’m using the following:

GD00Z-4 Linear Garage Door Opener
Aeon Gen5 z-stick
org.openhab.binding.zwave-1.9.0-SNAPSHOT
habmin 1.5.0-SNAPSHOT
openhab 1.8.3

I followed these instructions: https://github.com/openhab/openhab/wiki/ZWave-Security-Testing

This is what the node.xml file looks like:

<node>
  <deviceClass>
    <basicDeviceClass>ROUTING_SLAVE</basicDeviceClass>
    <genericDeviceClass>ENTRY_CONTROL</genericDeviceClass>
    <specificDeviceClass>SECURE_BARRIER</specificDeviceClass>
  </deviceClass>
  <homeId>0xda3241c9</homeId>
  <nodeId>9</nodeId>
  <version>4</version>
  <manufacturer>0x14f</manufacturer>
  <deviceId>0x3030</deviceId>
  <deviceType>0x4744</deviceType>
  <listening>true</listening>
  <frequentlyListening>false</frequentlyListening>
  <routing>true</routing>
  <healState>DONE @ 2016-09-19T23:28:53+0000</healState>
  <security>false</security>
  <beaming>true</beaming>
  <maxBaudRate>40000</maxBaudRate>
  <nodeInformationFrame/>
  <supportedCommandClasses>
    <entry>
      <commandClass>BASIC</commandClass>
      <basicCommandClass>
        <version>1</version>
        <instances>1</instances>
        <isGetSupported>true</isGetSupported>
      </basicCommandClass>
    </entry>
    <entry>
      <commandClass>LOCK</commandClass>
      <lockCommandClass>
        <version>1</version>
        <instances>1</instances>
      </lockCommandClass>
    </entry>
    <entry>
      <commandClass>MANUFACTURER_SPECIFIC</commandClass>
      <manufacturerSpecificCommandClass>
        <version>1</version>
        <instances>1</instances>
      </manufacturerSpecificCommandClass>
    </entry>
    <entry>
      <commandClass>SECURITY</commandClass>
      <securityCommandClassWithInit>
        <version>1</version>
        <instances>1</instances>
        <disableEncapNonceGet>false</disableEncapNonceGet>
        <securePairingComplete>false</securePairingComplete>
      </securityCommandClassWithInit>
    </entry>
    <entry>
      <commandClass>NO_OPERATION</commandClass>
      <noOperationCommandClass>
        <version>1</version>
        <instances>1</instances>
      </noOperationCommandClass>
    </entry>
  </supportedCommandClasses>
  <securedCommandClasses/>
  <nodeNeighbors>

I was not allowed to upload a file and the size was too big to post here, so here are parts of the log file that I thought were relevant from the pairing:

2016-09-19 18:05:22.424 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1240]- NODE 9: Initialisation retry timer started 5000
2016-09-19 18:05:22.426 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 9: Node advancer: loop - PING try 1: stageAdvanced(false)
2016-09-19 18:05:22.431 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 9: Node advancer - advancing to SECURITY_REPORT
2016-09-19 18:05:22.431 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 9: Node advancer: loop - SECURITY_REPORT try 0: stageAdvanced(true)
2016-09-19 18:05:22.438 [INFO ] [z.i.p.i.ZWaveNodeStageAdvancer:509 ]- NODE 9: does not support SECURITY_REPORT, proceeding to next stage.
2016-09-19 18:05:22.445 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 9: Node advancer - advancing to DETAILS
2016-09-19 18:05:22.445 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 9: Node advancer: loop - DETAILS try 0: stageAdvanced(true)
2016-09-19 18:05:22.447 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:529 ]- NODE 9: Node advancer: DETAILS - send RequestNodeInfo
2016-09-19 18:05:22.453 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 255: Creating empty message of class = RequestNodeInfo (0x60), type = Request (0x00)
2016-09-19 18:05:22.455 [DEBUG] [b.z.i.protocol.ZWaveController:649 ]- Enqueueing message. Queue length = 1, Queue = [Message: class = RequestNodeInfo (0x60), type = Request (0x00), payload = 09 , callbackid = 0]
2016-09-19 18:05:22.461 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 9: Node advancer - queued packet. Queue length is 1
2016-09-19 18:05:22.462 [DEBUG] [WaveController$ZWaveSendThread:1430]- NODE 9: Response processed for callback id 2 after 164ms/610ms.
2016-09-19 18:05:22.462 [TRACE] [WaveController$ZWaveSendThread:1433]- Acquired. Transaction completed permit count -> 0
2016-09-19 18:05:22.463 [TRACE] [b.z.i.protocol.ZWaveController:235 ]- Released. Transaction completed permit count -> 0
2016-09-19 18:05:22.463 [DEBUG] [WaveController$ZWaveSendThread:1295]- Took message from queue for sending. Queue length = 0
2016-09-19 18:05:22.463 [TRACE] [o.b.z.i.protocol.SerialMessage:200 ]- Calculated checksum = 0x92
2016-09-19 18:05:22.464 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ]- Assembled message buffer = 01 04 00 60 09 92 
...
2016-09-19 18:05:22.585 [TRACE] [.ApplicationUpdateMessageClass:92  ]- NODE 9: Command class 0x98 is supported.
2016-09-19 18:05:22.587 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 9: Creating new instance of command class SECURITY
2016-09-19 18:05:22.588 [TRACE] [.o.b.z.i.p.c.ZWaveCommandClass:71  ]- Command class SECURITY created
2016-09-19 18:05:22.588 [TRACE] [veController$WatchDogTimerTask:1672]- Watchdog: Checking Serial threads
2016-09-19 18:05:22.611 [INFO ] [.p.c.ZWaveSecurityCommandClass:796 ]- NODE 9: setupNetworkKey useSchemeZero=false
2016-09-19 18:05:22.619 [TRACE] [.p.c.ZWaveSecurityCommandClass:807 ]- NODE 9: Using Real Network Key.
2016-09-19 18:05:22.627 [TRACE] [.ApplicationUpdateMessageClass:99  ]- NODE 9: Application update request. Adding Command class SECURITY.
2016-09-19 18:05:22.627 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 9: Adding command class SECURITY to the list of supported command classes.
2016-09-19 18:05:22.628 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 9: Notifying event listeners: ZWaveNodeInfoEvent
2016-09-19 18:05:22.633 [DEBUG] [.z.internal.ZWaveActiveBinding:455 ]- ZwaveIncomingEvent
2016-09-19 18:05:22.633 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164]- NODE 9: 9 NIF event during initialisation stage DETAILS
2016-09-19 18:05:22.634 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1174]- NODE 9: NIF event during initialisation stage DETAILS
2016-09-19 18:05:22.634 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 9: Node advancer - DETAILS: queue length(1), free to send(false)
2016-09-19 18:05:22.634 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1240]- NODE 9: Initialisation retry timer started 5000
2016-09-19 18:05:22.635 [DEBUG] [b.z.i.protocol.ZWaveController:649 ]- Enqueueing message. Queue length = 1, Queue = [Message: class = RequestNodeInfo (0x60), type = Request (0x00), payload = 09 , callbackid = 0]
2016-09-19 18:05:22.636 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 9: Node advancer - queued packet. Queue length is 1
2016-09-19 18:05:22.641 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:83  ]- Sent message Message: class = RequestNodeInfo (0x60), type = Request (0x00), payload = 09 , callbackid = 0
2016-09-19 18:05:22.642 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:84  ]- Recv message Message: class = ApplicationUpdate (0x49), type = Request (0x00), payload = 84 09 05 04 40 07 72 98 , callbackid = 0
2016-09-19 18:05:22.643 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85  ]- Checking transaction complete: Sent message Message: class = RequestNodeInfo (0x60), type = Request (0x00), payload = 09 , callbackid = 0
2016-09-19 18:05:22.643 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:96  ]- Checking transaction complete: Recv message Message: class = ApplicationUpdate (0x49), type = Request (0x00), payload = 84 09 05 04 40 07 72 98 , callbackid = 0
2016-09-19 18:05:22.644 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:99  ]- Checking transaction complete: class=ApplicationUpdate, callback id=0, expected=ApplicationUpdate, cancelled=false        transaction complete!
2016-09-19 18:05:22.648 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 255: Notifying event listeners: ZWaveTransactionCompletedEvent
2016-09-19 18:05:22.649 [DEBUG] [.z.internal.ZWaveActiveBinding:455 ]- ZwaveIncomingEvent
2016-09-19 18:05:22.650 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1116]- NODE 9: Node advancer - DETAILS: Transaction complete (RequestNodeInfo:Request) success(true)
2016-09-19 18:05:22.659 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 9: Node advancer - checking initialisation queue. Queue size 1.
...
2016-09-19 18:05:29.844 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 9: Node advancer - advancing to STATIC_END
2016-09-19 18:05:29.853 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 9: Node advancer: loop - STATIC_END try 0: stageAdvanced(true)
2016-09-19 18:05:29.855 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:100 ]- NODE 9: Serialise aborted as static stages not complete
2016-09-19 18:05:29.855 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 9: Node advancer - advancing to SESSION_START
2016-09-19 18:05:29.856 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 9: Node advancer: loop - SESSION_START try 0: stageAdvanced(true)
2016-09-19 18:05:29.857 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 9: Node advancer - advancing to DYNAMIC_VALUES
2016-09-19 18:05:29.858 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 9: Node advancer: loop - DYNAMIC_VALUES try 0: stageAdvanced(true)
2016-09-19 18:05:29.865 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:885 ]- NODE 9: Node advancer: DYNAMIC_VALUES - checking BASIC
2016-09-19 18:05:29.865 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:885 ]- NODE 9: Node advancer: DYNAMIC_VALUES - checking LOCK
2016-09-19 18:05:29.867 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:885 ]- NODE 9: Node advancer: DYNAMIC_VALUES - checking MANUFACTURER_SPECIFIC
2016-09-19 18:05:29.867 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:885 ]- NODE 9: Node advancer: DYNAMIC_VALUES - checking SECURITY
2016-09-19 18:05:29.867 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:885 ]- NODE 9: Node advancer: DYNAMIC_VALUES - checking NO_OPERATION
2016-09-19 18:05:29.872 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:919 ]- NODE 9: Node advancer: DYNAMIC_VALUES - queued 0 frames
2016-09-19 18:05:29.873 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 9: Node advancer - advancing to DONE
2016-09-19 18:05:29.880 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 9: Node advancer: loop - DONE try 0: stageAdvanced(true)
2016-09-19 18:05:29.881 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:107 ]- NODE 9: Serializing to file /var/lib/openhab/zwave/node9.xml
2016-09-19 18:05:29.953 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:931 ]- NODE 9: Node advancer: Initialisation complete!
2016-09-19 18:05:29.955 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 9: Notifying event listeners: ZWaveInitializationCompletedEvent
2016-09-19 18:05:29.955 [DEBUG] [.z.internal.ZWaveActiveBinding:446 ]- NODE 9: ZWaveIncomingEvent Called, Network Event, Init Done. Setting device ready.

Lou_Allegra · September 20, 2016, 1:24am

Here is the full log file:
zwave_pairing_node9.pdf (157.6 KB)

Lou_Allegra · September 20, 2016, 1:53am

The Z-Wave Binding section of openhab.cfg:

################################ Z-Wave  Binding ######################################
#
# The Z-Wave controller port. Valid values are e.g. COM1 for Windows and /dev/ttyS0 or
# /dev/ttyUSB0 for Linux
zwave:port = /dev/ttyACM0

# Z-Wave nightly heal time. This is the hour (eg 2AM) at which the automatic nightly
# network heal will be performed.
zwave:healtime = 2

# Z-Wave master contoller tells the binding that openHAB is the master controller
# of the Z-Wave netowrk and will initialise devices with more config data.
zwave:masterController = true

# Z-Wave network key is used to implement secure comms with deadbolts, garage doors,
# and other devices requiring the Security Command Class
zwave:networkKey=0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00

zwave:setSUC = true

(A real password was used, set to zeros for posting)

Lou_Allegra · September 20, 2016, 11:48pm

Upgraded zwave-1.9.0-SNAPSHOT from:

Bundle-Version: 1.9.0.201604020048
Build-Jdk: 1.7.0_45

to:

Bundle-Version: 1.9.0.201609200111
Build-Jdk: 1.7.0_79

Now there is no attempt to pair securely. I’m really confused.

sihui · September 21, 2016, 5:43am

It’s only implemented in the precompiled jar at your instructions link, you won’t find any security functions in the latest snapshot.

chris · September 21, 2016, 6:58am

I don’t think there’s any recent precompiled JAR. I provided a merged branch of the latest binding for people to test with a view to merging it soon, but there’s only been a couple of people try it. If the general consensus is that it’s ok, we can look to merge it.

Lou_Allegra · September 21, 2016, 11:54am

I would be happy to test any version and provide detailed feedback.

chris · September 21, 2016, 11:58am

I will see if I can compile a version in the coming day or two for testing…

Lou_Allegra · September 28, 2016, 1:14am

Hello Chris:

Have you had a chance to get a version together for me to test?

Thanks!

-Lou.

Lou_Allegra · October 1, 2016, 12:26pm

Chris:

Is there a site or thread I should watch to follow this? I know you’re
probably really busy and I don’t want to slow that down, but my project
has been at a full stop for two weeks. Any help you can provide is greatly
appreciated.

Thank you.

-Lou

chris · October 1, 2016, 2:03pm

Sorry - I’ve been travelling extensively over the past week or so and have just got off the plane after another long haul flight so I’ll take a look tomorrow.

Lou_Allegra · October 14, 2016, 7:58am

Have the security features been added to OH2 beta4 release? I’m getting a new machine ready so switching to OH2 is convenient. Should I start testing with the OH2 beta4 release or something else?

Thank you.

chris · October 14, 2016, 8:57am

No - secureity is not included in the V2 at the moment. I hope to get to work on this soon as the transaction rewrite which is needed for this is starting to looking like it’s working ok…

Lou_Allegra · November 11, 2016, 1:52am

Hello Chris:

Any word on the Secure Z-wave bindings? It’s been a while since I heard from you and I’m curious as to when I could get back to some testing.

Thanks man!

-Lou.

chris · November 11, 2016, 9:10am

Security is now included in the OH1 binding, but not the OH2 binding yet.