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

Add-ons Bindings
,
2492

Hi All,

I have successfully joined a lock to OH using Habmin, but I had to put the server temporarily a few feet from the lock.
Now that I have moved server back to its normal position (about 20 meters on a different floor), it can’t find the device anymore. The network topology shows Node9 off on its own with no links.
Few questions:

  • What was the option to get it to resync neighbors? I thought it was going to do it at night automatically. (Heal Time)
  • Before the secure inclusion, it did use its neighbors to connect to the device. Is this still possible with secure inclusion? Ie. can security pass through other devices?
  • Should I enable secure inclusion for all devices?

Thanks

2493

I’m having problems trying to securely associate Kwikset 914.

2018-02-21 20:26:27.805 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - NODE 35: setupNetworkKey useSchemeZero=true
2018-02-21 20:26:27.808 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - NODE 35: Using Scheme0 Network Key for Key Exchange since we are in inclusion mode.
2018-02-21 20:26:27.938 [INFO ] [curityCommandClassWithInitialization] - NODE 35: Setting Network Key to real key after SECURITY_NETWORK_KEY_SET
2018-02-21 20:26:27.940 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - NODE 35: setupNetworkKey useSchemeZero=false
2018-02-21 20:26:28.038 [ERROR] [col.security.ZWaveSecureNonceTracker] - NODE 35: SECURITY_ERROR Device message contained nonce that is unknown to us, id=84.
2018-02-21 20:26:28.109 [WARN ] [mmandclass.ZWaveSecurityCommandClass] - NODE 35: payloadQueue was empty, returning!

I’ve been digging through this thread trying to figure out what I could be doing wrong but I don’t have enough understanding to figure it out. Any help is greatly appreciated.

Using binding 2.3.0.201802202333.

2494

This is not the development binding linked to in the first post (or in the marketplace). Or did you build it yourself?

2495

Now I just feel dumb. I assumed that the code had been merged into the main branch by now. I’ll switch over.

2496

You’d only be dumb if you didn’t ask for help!

2497

Hi there,

I have a new minor issue :wink: I added some motorized shades from Bali that come with a z wave capable motor from Somfy and a remote. The Somfy motor gets recognized with no issues but the remotes are not. Its a simple two button remote (node 10 & 11) it gets added to the network during inclusion but seems to not be in the database also no XML is created and the node shows offline:

12:18:52.340 [DEBUG] [ave.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
12:18:52.343 [DEBUG] [ave.internal.protocol.ZWaveController] - Event listener added.
12:18:52.346 [DEBUG] [nal.protocol.ZWaveInclusionController] - ZWave controller start inclusion
12:18:52.349 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.
12:18:52.352 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Adding to priority controller queue
12:18:52.356 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
12:18:52.358 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
12:18:52.362 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
12:18:52.365 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 06 00 4A C1 01 8C FF 
12:18:52.369 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 06 00 4A C1 01 8C FF 
12:18:52.372 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
12:18:52.374 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
12:18:52.377 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
12:18:52.376 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 169: Transaction Start type AddNodeToNetwork 
12:18:52.378 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
12:18:52.381 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
12:18:52.380 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 169: [WAIT_REQUEST] requiresResponse=true callback: 140
12:18:52.382 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 01 01 00 00 B2 
12:18:52.383 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
12:18:52.384 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
12:18:52.387 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
12:18:52.387 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=1, payload=01 01 00 00 
12:18:52.390 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
12:18:52.388 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
12:18:52.392 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
12:18:52.391 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=1, payload=01 01 00 00 
12:18:52.394 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
12:18:52.399 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Feb 22 12:18:57 CST 2018 - 4999ms
12:18:52.402 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 169: [WAIT_REQUEST] requiresResponse=true callback: 140
12:18:52.405 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
12:18:52.408 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Feb 22 12:18:57 CST 2018 - 4990ms
12:18:52.411 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
12:18:52.414 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
12:18:52.417 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Feb 22 12:18:57 CST 2018 - 4982ms
12:18:52.420 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=1, payload=01 01 00 00 
12:18:52.422 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 169: [WAIT_REQUEST] requiresResponse=true callback: 140
12:18:52.425 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
12:18:52.427 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 169: [WAIT_REQUEST] requiresResponse=true callback: 140
12:18:52.430 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 169: (Callback 140)
12:18:52.432 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - NO callback match! (140 <> 1)
12:18:52.435 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ****************** Transaction not correlated
12:18:52.437 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=1, payload=01 01 00 00 
12:18:52.442 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
12:18:52.444 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
12:18:52.448 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart
12:18:52.450 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
12:18:52.449 [INFO ] [smarthome.event.BindingEvent         ] - org.openhab.binding.zwave.event.BindingEvent@1336705
12:18:52.453 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
12:18:52.456 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
12:18:52.458 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
12:18:52.461 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Feb 22 12:18:57 CST 2018 - 4937ms
12:18:53.025 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 01 02 00 00 B1 
12:18:53.030 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=1, payload=01 02 00 00 
12:18:53.034 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=1, payload=01 02 00 00 
12:18:53.037 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=1, payload=01 02 00 00 
12:18:53.041 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 169: [WAIT_REQUEST] requiresResponse=true callback: 140
12:18:53.045 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
12:18:53.050 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 169: [WAIT_REQUEST] requiresResponse=true callback: 140
12:18:53.054 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 169: (Callback 140)
12:18:53.058 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - NO callback match! (140 <> 1)
12:18:53.062 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ****************** Transaction not correlated
12:18:53.067 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=1, payload=01 02 00 00 
12:18:53.072 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Add Node: New node found.
12:18:53.077 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
12:18:53.082 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
12:18:53.086 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
12:18:53.091 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
12:18:53.096 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Feb 22 12:18:57 CST 2018 - 4303ms
12:18:53.192 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 19 00 4A 01 04 0B 12 01 01 01 5E 86 72 5A 73 85 59 80 5B 84 EF 20 84 5B 26 87 
12:18:53.197 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=4, callback=1, payload=01 04 0B 12 01 01 01 5E 86 72 5A 73 85 59 80 5B 84 EF 20 84 5B 26 
12:18:53.201 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=AddNodeToNetwork[74], type=Request[0], dest=4, callback=1, payload=01 04 0B 12 01 01 01 5E 86 72 5A 73 85 59 80 5B 84 EF 20 84 5B 26 
12:18:53.204 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=4, callback=1, payload=01 04 0B 12 01 01 01 5E 86 72 5A 73 85 59 80 5B 84 EF 20 84 5B 26 
12:18:53.206 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 169: [WAIT_REQUEST] requiresResponse=true callback: 140
12:18:53.209 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
12:18:53.211 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 169: [WAIT_REQUEST] requiresResponse=true callback: 140
12:18:53.214 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 169: (Callback 140)
12:18:53.217 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - NO callback match! (140 <> 1)
12:18:53.220 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ****************** Transaction not correlated
12:18:53.223 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=4, callback=1, payload=01 04 0B 12 01 01 01 5E 86 72 5A 73 85 59 80 5B 84 EF 20 84 5B 26 
12:18:53.226 [DEBUG] [col.serialmessage.AddNodeMessageClass] - NODE 11: Adding controller.
12:18:53.228 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
12:18:53.231 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeStart, new event IncludeControllerFound
12:18:53.234 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
12:18:53.236 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
12:18:53.238 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
12:18:53.241 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
12:18:53.243 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Feb 22 12:18:57 CST 2018 - 4155ms
12:18:53.841 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 01 05 0B 00 BD 
12:18:53.850 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=5, callback=1, payload=01 05 0B 00 
12:18:53.857 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=AddNodeToNetwork[74], type=Request[0], dest=5, callback=1, payload=01 05 0B 00 
12:18:53.862 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=5, callback=1, payload=01 05 0B 00 
12:18:53.867 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 169: [WAIT_REQUEST] requiresResponse=true callback: 140
12:18:53.871 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
12:18:53.875 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 169: [WAIT_REQUEST] requiresResponse=true callback: 140
12:18:53.880 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 169: (Callback 140)
12:18:53.884 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - NO callback match! (140 <> 1)
12:18:53.889 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ****************** Transaction not correlated
12:18:53.894 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=5, callback=1, payload=01 05 0B 00 
12:18:53.898 [DEBUG] [col.serialmessage.AddNodeMessageClass] - NODE 11: Add Node: Protocol done.
12:18:53.903 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
12:18:53.907 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeControllerFound, new event IncludeProtocolDone
12:18:53.912 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
12:18:53.916 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Adding to priority controller queue
12:18:53.922 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
12:18:53.924 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
12:18:53.927 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
12:18:53.931 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
12:18:53.934 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Feb 22 12:18:57 CST 2018 - 3464ms
12:18:53.938 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion protocol completed with nodeId == 0! Nothing to do!
12:18:53.941 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
12:18:53.944 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
12:18:53.946 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
12:18:53.948 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
12:18:53.951 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Feb 22 12:18:57 CST 2018 - 3447ms
12:18:57.398 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
12:18:57.403 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 255: TID 169: Timeout at state WAIT_REQUEST. 3 retries remaining.
12:18:57.407 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - TID 169: Transaction is current transaction, so clearing!!!!!
12:18:57.411 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 169: Transaction CANCELLED
12:18:57.415 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
12:18:57.420 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:169 CANCELLED
12:18:57.424 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
12:18:57.428 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
12:18:57.434 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 06 00 4A 05 01 8D 3A 
12:18:57.440 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 06 00 4A 05 01 8D 3A 
12:18:57.444 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
12:18:57.447 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
12:18:57.448 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 170: Transaction Start type AddNodeToNetwork 
12:18:57.452 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 170: [WAIT_REQUEST] requiresResponse=true callback: 141
12:18:57.453 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
12:18:57.455 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
12:18:57.461 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
12:18:57.460 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
12:18:57.464 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
12:18:57.467 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
12:18:57.467 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
12:18:57.469 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
12:18:57.470 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Feb 22 12:19:02 CST 2018 - 4997ms
12:18:57.472 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
12:18:57.474 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 170: [WAIT_REQUEST] requiresResponse=true callback: 141
12:18:57.475 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
12:18:57.476 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
12:18:57.478 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
12:18:57.480 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Feb 22 12:19:02 CST 2018 - 4988ms
12:18:57.482 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
12:18:57.484 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
12:18:57.487 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Feb 22 12:19:02 CST 2018 - 4980ms
12:18:57.538 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 01 06 0B 00 BE 
12:18:57.543 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=1, payload=01 06 0B 00 
12:18:57.546 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=1, payload=01 06 0B 00 
12:18:57.549 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=1, payload=01 06 0B 00 
12:18:57.551 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 170: [WAIT_REQUEST] requiresResponse=true callback: 141
12:18:57.555 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
12:18:57.557 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 170: [WAIT_REQUEST] requiresResponse=true callback: 141
12:18:57.560 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 170: (Callback 141)
12:18:57.562 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - NO callback match! (141 <> 1)
12:18:57.565 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ****************** Transaction not correlated
12:18:57.568 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=1, payload=01 06 0B 00 
12:18:57.570 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Add Node: Done.
12:18:57.573 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
12:18:57.588 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - NODE 11: Device discovered
12:18:57.596 [INFO ] [smarthome.event.InboxAddedEvent      ] - Discovery Result with UID 'zwave:device:7a3013b6:node11' has been added.
12:18:57.596 [INFO ] [ig.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:7a3013b6:node11' to inbox.
12:18:57.601 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeProtocolDone, new event IncludeDone
12:18:57.602 [INFO ] [smarthome.event.BindingEvent         ] - org.openhab.binding.zwave.event.BindingEvent@162a502
12:18:57.606 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
12:18:57.608 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Adding to priority controller queue
12:18:57.611 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
12:18:57.613 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
12:18:57.615 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
12:18:57.617 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
12:18:57.619 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Feb 22 12:19:02 CST 2018 - 4848ms
12:18:57.621 [DEBUG] [nal.protocol.ZWaveInclusionController] - ZWave controller end exclusion
12:18:57.623 [DEBUG] [ave.internal.protocol.ZWaveController] - ZWaveController include done
12:18:57.624 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
12:18:57.626 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
12:18:57.628 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
12:18:57.630 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
12:18:57.632 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Feb 22 12:19:02 CST 2018 - 4835ms
12:19:02.468 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
12:19:02.472 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 255: TID 170: Timeout at state WAIT_REQUEST. 3 retries remaining.
12:19:02.477 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - TID 170: Transaction is current transaction, so clearing!!!!!
12:19:02.481 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 170: Transaction CANCELLED
12:19:02.486 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
12:19:02.490 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:170 CANCELLED
12:19:02.495 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
12:19:02.500 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
12:19:02.506 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 06 00 4A 05 00 8E 38 
12:19:02.512 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 06 00 4A 05 00 8E 38 
12:19:02.517 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
12:19:02.520 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
12:19:02.522 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 171: Transaction Start type AddNodeToNetwork 
12:19:02.524 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 171: [WAIT_REQUEST] requiresResponse=true callback: 142
12:19:02.524 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
12:19:02.526 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
12:19:02.529 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
12:19:02.528 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
12:19:02.531 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
12:19:02.533 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
12:19:02.536 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
12:19:02.536 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
12:19:02.537 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
12:19:02.539 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Feb 22 12:19:07 CST 2018 - 4997ms
12:19:02.540 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
12:19:02.542 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 171: [WAIT_REQUEST] requiresResponse=true callback: 142
12:19:02.543 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
12:19:02.545 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
12:19:02.547 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Feb 22 12:19:07 CST 2018 - 4989ms
12:19:02.550 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
12:19:02.551 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
12:19:02.553 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Feb 22 12:19:07 CST 2018 - 4983ms
12:19:07.536 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
12:19:07.539 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 255: TID 171: Timeout at state WAIT_REQUEST. 3 retries remaining.
12:19:07.544 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - TID 171: Transaction is current transaction, so clearing!!!!!
12:19:07.549 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 171: Transaction CANCELLED
12:19:07.556 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
12:19:07.561 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:171 CANCELLED
12:19:07.566 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
12:19:07.570 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
12:19:07.575 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
12:19:07.579 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
12:19:13.602 [DEBUG] [ave.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do

12:19:14.597 [DEBUG] [nal.protocol.ZWaveInclusionController] - ZWave inclusion controller finalised

12:20:00.032 [INFO ] [smarthome.event.InboxRemovedEvent    ] - Discovery Result with UID 'zwave:device:7a3013b6:node10' has been removed.
12:20:00.054 [DEBUG] [org.openhab.binding.zwave            ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=395, service.bundleid=195, service.scope=singleton} - org.openhab.binding.zwave
12:20:00.068 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:7a3013b6:node10.
12:20:00.068 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:7a3013b6:node10' changed from UNINITIALIZED to INITIALIZING
12:20:00.078 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: MANUFACTURER not set
12:20:00.082 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Controller status changed to ONLINE.
12:20:00.085 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:7a3013b6:node10' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
12:20:00.086 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Controller is ONLINE. Starting device initialisation.
12:20:00.093 [DEBUG] [ave.internal.protocol.ZWaveController] - Event listener added.
12:20:00.096 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Initialising Thing Node...
12:20:00.097 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:7a3013b6:node10' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to OFFLINE: Node not found in Z-Wave network
12:20:00.101 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Polling intialised at 1800 seconds - start in 1494000 milliseconds.
12:20:00.103 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Device initialisation complete.

12:20:06.293 [INFO ] [smarthome.event.InboxRemovedEvent    ] - Discovery Result with UID 'zwave:device:7a3013b6:node11' has been removed.
12:20:06.307 [DEBUG] [org.openhab.binding.zwave            ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=396, service.bundleid=195, service.scope=singleton} - org.openhab.binding.zwave
12:20:06.324 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:7a3013b6:node11.
12:20:06.326 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:7a3013b6:node11' changed from UNINITIALIZED to INITIALIZING
12:20:06.346 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 11: MANUFACTURER not set
12:20:06.350 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 11: Controller status changed to ONLINE.
12:20:06.355 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 11: Controller is ONLINE. Starting device initialisation.
12:20:06.355 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:7a3013b6:node11' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
12:20:06.359 [DEBUG] [ave.internal.protocol.ZWaveController] - Event listener added.
12:20:06.362 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:7a3013b6:node11' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to OFFLINE: Node not found in Z-Wave network
12:20:06.364 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 11: Initialising Thing Node...
12:20:06.368 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling intialised at 1800 seconds - start in 226800 milliseconds.
12:20:06.371 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 11: Device initialisation complete.
12:20:21.074 [INFO ] [smarthome.event.ItemStateChangedEvent] - LocalTime_Date changed from 2018-02-22T12:19:21.053-0600 to 2018-02-22T12:20:21.056-0600
12:20:41.283 [DEBUG] [ng.zwave.internal.ZWaveConfigProvider] - NODE 10: Node not found in getConfigDescription

12:23:53.169 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling...
12:23:53.182 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling deferred until initialisation complete

Thx for the effort

Christian

2498

From a quick look I don’t see any wakeup messages - try waking the device up a few times to get it initialised.

If the device isn’t in the database once the initialisation is complete, then refer to the database documentation on how to add it.

2499

I am having a wierd issue with one of my rules that involves my zwave thermostat. I have a thread here

Does this look like a binding issue? If i set the command with the iOS app or the default sitemap the temperature change sticks but when it is set by the rule it looks like the command is sent and then something changes it back.

2500

Please disregard this post i solved my own problem…

2501

Hello,

First of all, thank you for openhab and the zwave bindings !

I’m using 2.3.0-SNAPSHOT Build #1211 with the latest zwave bindings (8th feb 2018).

My zwave network is :

  • one controller (aeotec gen5)
  • one switch (AN179 In-Wall Switch Module) in unsecured mode
  • one Aeotec ZW130 WallMote Quad, included in secure mode, with the latest firmware (1.08). Other topics show that it is not an unknown device.

Everything’s working fine excepting the Wallmote, The discovery shows in particular this message :

NODE 28: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0

I’ve uploaded here the Detailed Trace logs I’m trying to understand…

Openhab seems to dial correctly in secure mode… in fact, I wonder if you could help me to decode what’s wrong in the log !
NB : the first part of the log file contains non-readable characters, and I don’t know why. Could it be related ?

Thanks for your attention,

Regards,

Romain

2502

It’s empty.

Could be a sign for a bad sd card. Those are cheap so just take a (working) backup to a new one and try it out.

2503

sihui,

Thank you for your help !

The log file I uploaded is not empty, it just begins by a long suite of non-readable characters. The logs are at the end of the file.
As a convenience, I removed those characters from the initial file to get this more readable.

I’m working on a classical hard drive (not SSD, not SD card) and have not noticed any failure sign of whatever else (other applications, system updates, documents… are correctly read and written).
Just this repeatable behaviour of openhab when beginning logging about zwave. But it seems to be caused by emptying the log file with “echo “” > openhab.log” before beginning my zwave test scenario.

So the problem I found in the log file is : Node 2 (AN179 in unsecured mode) is OK, node 28 (ZW130 wallmote quad in secured mode) fails with

2018-02-23 19:38:13.059 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 28: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0

2504

Although I’m using the security version of the binding I don’t use any secure devices, so am not of any help.
Feeding your log through the log viewer shows:

1
11199×509 73.9 KB

Are you sure your device has finished initialization? Sometimes battery operated devices need several manual wakeups.

2505

I’ve tried to wake-up the Wallmote four times in 20 minutes. The logs always look like the one I uploaded (I see dialog between the controller and the Wallmote, but nothing more).

The wallmote, when woken-up, blinks yellow until the controller sends something telling “OK, I finished what I wanted to do with you”. For instance, when I changed the node configuration in Jeedom (my previous software for driving the zwave network), I woken-up the Wallmote, and it blinked for less than 5 seconds and then lighted-off.
With openhab, when I wake-up the Wallmote device, it blinks for 10 minutes. It matches with the default timeout of the wallmote, so I think it is an hint that openhab did not send the “OK, I finished what I wanted to do with you” message.

But I’ve no idea about what to do know :frowning:

2506

I am using this build 2.3.0.201802081624 and thought it had all the code for including security devices. Is that not the case?

2507

Here are my logs:

http://www.faure.ca/~paul/openhab_feb24.log

I thought it included security, but I cant see it in the logs.

2508

Unfortunately your log is a bit large for me to open (10MB is normally a good size). However, you won’t necessarily see security stuff in the log unless you have secure devices included in the first place.

2509

Here is a new log file showing the same problem for Aeotec Wallmote Quad with the current Snapshot builds of openhab and the zwave bindings (2.3.0-SNAPSHOT Build #1219).

The problem still seems to be

2018-02-24 19:54:59.877 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 28: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0

And I’ve also noticed that :

NODE 28: Unknown command class 0xffffff84

Hope it helps ? @chris

2510

Try this one, its a fresh restart of OH. Filesize is under 3MB.

http://www.faure.ca/~paul/openhab_feb24_b.log

Appreciate your help.

2511

Hello Paul,

I don’t know if I’m telling you something obvious, but did you try what your logs suggest ?

2018-02-24 14:29:59.093 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 9: Node advancer: loop - SECURITY_REPORT try 0: stageAdvanced(true)
2018-02-24 14:29:59.094 [DEBUG] [curityCommandClassWithInitialization] - NODE 9: SECURITY_INITIALIZE Initialising=true, Inclusion=false, Paired=false, lastRxMsg=1519500599094ms, lastTxMsg=4692ms
2018-02-24 14:29:59.094 [ERROR] [curityCommandClassWithInitialization] - NODE 9: SECURITY_ERROR Invalid state! Secure inclusion has not completed and we are not in inclusion mode. Aborting
2018-02-24 14:29:59.095 [DEBUG] [curityCommandClassWithInitialization] - NODE 9: Security.initialize, from xml, handing back message=null
2018-02-24 14:29:59.095 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 9: Since secure inclusion failed, the node must be manually excluded via habmin