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

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

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

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.

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.

Please disregard this post i solved my own problem…

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

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.

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

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:

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

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:

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?

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.

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.

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

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.

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

Well - this is a good clue - but for a slightly different reason. :wink:

The log is not from the right version of the binding - it’s an old version that doesn’t support security. It has security messages, but it doesn’t work.

The 7FFFFFFF business normally means the binding hasn’t received the manufacturer information from the device.

The log seems to confirm this, but I don’t really know why it’s not working - I could guess that there’s a communication issue - ie it’s too far away from the controller? Is that likely?

It does look like it’s securely included ok, but there are a number of retries. It could also be caused by something else with security, but it’s hard to diagnose unfortunately.

Thanks chris for your help.

Very unlikely. I stick the device to the controller when I give it a try.

What do you think about the “Unknown command class 0xffffff84” ?

2018-02-24 19:59:24.086 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 28: Unknown command class 0xffffff84

I think it’s probably a small bug, but unlikely it’s the actual problem.

Another thought - try deleting the XML for this node and restarting the binding - let’s see if that helps. Provide the log if it doesn’t.