Hello!
I’ve recently upgraded to 2.4 and my existing z-wave devices all communicate ok with OH.
When I try to add a new device using Habmin I get the error “z-wave network inclusion failed”.
I’ve also tried to add a new device using Paper UI but it doesn’t give any errors; it just doesn’t find any z-wave device to add.
Has anyone else encountered this error?
Br
Freddy Söderlund
It would be worth enabling debug logging to see what is happening. Probably the error is coming back from the controller itself, but the log would confirm (or not!) that this is the case.
So I did log:set debug org.openhab and then tried to search for a z-wave device again and this is what I ended up with in the openHab.log.
2019-01-01 16:51:50.271 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:2c01b3df
2019-01-01 16:51:50.275 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
2019-01-01 16:51:50.281 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:2c01b3df
2019-01-01 16:51:50.284 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
2019-01-01 16:51:50.290 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2019-01-01 16:51:50.293 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion
2019-01-01 16:51:50.300 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.
2019-01-01 16:51:50.303 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 50 to queue - size 1
2019-01-01 16:51:50.306 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-01 16:51:52.314 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery completed
2019-01-01 16:51:52.327 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery resolved to thingType zwave:fibaro_fgsd002_03_002
2019-01-01 16:51:52.339 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery completed
2019-01-01 16:51:52.351 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery resolved to thingType zwave:fibaro_fgsd002_03_002
2019-01-01 16:51:52.362 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 4: Device discovery completed
2019-01-01 16:51:52.374 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 4: Device discovery resolved to thingType zwave:fibaro_fgsd002_03_002
2019-01-01 16:51:52.386 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 5: Device discovery completed
2019-01-01 16:51:52.397 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 5: Device discovery resolved to thingType zwave:fibaro_fgsd002_03_002
2019-01-01 16:51:52.409 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 6: Device discovery completed
2019-01-01 16:51:52.424 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 6: Device discovery could not resolve to a thingType! Manufacturer data not known.
2019-01-01 16:51:52.433 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 7: Device discovery completed
2019-01-01 16:51:52.445 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 7: Device discovery resolved to thingType zwave:telldus_tzwp100_00_000
2019-01-01 16:51:52.455 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 8: Device discovery completed
2019-01-01 16:51:52.460 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 8: Device discovery resolved to thingType zwave:telldus_tzwp100_00_000
2019-01-01 16:51:52.469 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 9: Device discovery completed
2019-01-01 16:51:52.474 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 9: Device discovery resolved to thingType zwave:telldus_tzwp100_00_000
2019-01-01 16:51:52.483 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 10: Device discovery completed
2019-01-01 16:51:52.489 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 10: Device discovery resolved to thingType zwave:telldus_tzwp100_00_000
2019-01-01 16:51:52.497 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 11: Device discovery completed
2019-01-01 16:51:52.503 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 11: Device discovery resolved to thingType zwave:telldus_tzwp100_00_000
2019-01-01 16:51:52.511 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 12: Device discovery completed
2019-01-01 16:51:52.517 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 12: Device discovery resolved to thingType zwave:telldus_tzwp100_00_000
2019-01-01 16:51:52.526 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 13: Device discovery completed
2019-01-01 16:51:52.529 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 13: Device discovery resolved to thingType zwave:fibaro_fgdw002_00_000
2019-01-01 16:51:52.535 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 14: Device discovery completed
2019-01-01 16:51:52.541 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 14: Device discovery resolved to thingType zwave:telldus_tzwp100_00_000
2019-01-01 16:51:52.550 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 15: Device discovery completed
2019-01-01 16:51:52.555 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 15: Device discovery resolved to thingType zwave:telldus_tzwp100_00_000
2019-01-01 16:51:52.564 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 16: Device discovery completed
2019-01-01 16:51:52.565 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 16: Device discovery resolved to thingType zwave:aeon_zw100_01_010
2019-01-01 16:51:52.570 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 17: Device discovery completed
2019-01-01 16:51:52.575 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 17: Device discovery resolved to thingType zwave:telldus_tzwp100_00_000
2019-01-01 16:51:52.584 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 18: Device discovery completed
2019-01-01 16:51:52.589 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 18: Device discovery resolved to thingType zwave:telldus_tzwp100_00_000
2019-01-01 16:51:52.598 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 22: Device discovery completed
2019-01-01 16:51:52.603 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 22: Device discovery resolved to thingType zwave:telldus_tzwp100_00_000
2019-01-01 16:51:52.612 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 23: Device discovery completed
2019-01-01 16:51:52.618 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 23: Device discovery resolved to thingType zwave:telldus_tzwp100_00_000
2019-01-01 16:51:58.326 [DEBUG] [ternal.core.TelldusCoreBridgeHandler] - Sensor Event for TellstickSensor [sensorId=135, protocol=fineoffset, model=temperature, timeStamp=Tue Jan 01 16:51:10 CET 2019, data={TEMPERATURE=1.9}] event TellstickSensorEvent [sensorId=135, model=temperature, protocol=fineoffset, data=1.9, timestamp=1546357918000]
2019-01-01 16:51:58.329 [DEBUG] [ternal.core.TelldusCoreBridgeHandler] - Update curr 1.9 new 1.9
2019-01-01 16:52:01.528 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL: Stored item 'Hall_Pi_Temp' as '49'[49] in SQL database at 2019-01-01 16:52:01.515.
2019-01-01 16:52:01.530 [DEBUG] [sql.internal.MysqlPersistenceService] - mySQL: query: INSERT INTO Item25 (TIME, VALUE) VALUES(?,?) ON DUPLICATE KEY UPDATE VALUE=?;
2019-01-01 16:52:03.607 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 14: TID 48: Timeout at state WAIT_DATA. 3 retries remaining.
2019-01-01 16:52:03.609 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 48: Transaction is current transaction, so clearing!!!!!
2019-01-01 16:52:03.611 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 48: Transaction CANCELLED
2019-01-01 16:52:03.612 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-01-01 16:52:03.614 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: notifyTransactionResponse TID:48 CANCELLED
2019-01-01 16:52:03.616 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-01 16:52:03.616 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 48: Transaction event listener: DONE: CANCELLED ->
2019-01-01 16:52:03.619 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 03 72
2019-01-01 16:52:03.624 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: Node Init response (1) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@a5ee5c
2019-01-01 16:52:03.626 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 03 72
2019-01-01 16:52:03.628 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-01-01 16:52:03.627 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 14: No data from device, but it was ACK'd. Possibly not supported? (Try 1)
2019-01-01 16:52:03.630 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 50: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 3
2019-01-01 16:52:03.631 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-01-01 16:52:03.635 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-01 16:52:03.638 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-01 16:52:03.639 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 03 07 00 00 B6
2019-01-01 16:52:03.640 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 50: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 3
2019-01-01 16:52:03.642 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-01-01 16:52:03.643 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-01 16:52:03.644 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=3, payload=03 07 00 00
2019-01-01 16:52:03.645 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-01 16:52:03.648 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=3, payload=03 07 00 00
2019-01-01 16:52:03.649 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 50: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 3
2019-01-01 16:52:03.651 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-01-01 16:52:03.653 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 50: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 3
2019-01-01 16:52:03.654 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 50: (Callback 3)
2019-01-01 16:52:03.656 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-01-01 16:52:03.658 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 50: callback 3
2019-01-01 16:52:03.659 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=3, payload=03 07 00 00
2019-01-01 16:52:03.662 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Failed.
2019-01-01 16:52:03.672 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeFail
2019-01-01 16:52:03.677 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2019-01-01 16:52:03.679 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 51 to queue - size 1
2019-01-01 16:52:03.681 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-01 16:52:03.686 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 50: Transaction CANCELLED
2019-01-01 16:52:03.688 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: CANCEL while sending message. Requeueing - 2 attempts left!
2019-01-01 16:52:03.690 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 50: Transaction RESET with 2 retries remaining.
2019-01-01 16:52:03.692 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 50 to queue - size 2
2019-01-01 16:52:03.693 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-01 16:52:03.696 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 04 75
2019-01-01 16:52:03.698 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 04 75
2019-01-01 16:52:03.700 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-01-01 16:52:03.702 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 50: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 4
2019-01-01 16:52:03.702 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-01-01 16:52:03.704 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 50: Transaction not completed
2019-01-01 16:52:03.705 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-01 16:52:03.706 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-01 16:52:03.707 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-01 16:52:03.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-01 16:52:03.710 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 50: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 4
2019-01-01 16:52:03.711 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 04 07 00 00 B1
2019-01-01 16:52:03.712 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-01-01 16:52:03.713 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-01 16:52:03.715 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-01 16:52:03.716 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=4, payload=04 07 00 00
2019-01-01 16:52:03.729 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=4, payload=04 07 00 00
2019-01-01 16:52:03.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 50: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 4
2019-01-01 16:52:03.732 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-01-01 16:52:03.734 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 50: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 4
2019-01-01 16:52:03.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 50: (Callback 4)
2019-01-01 16:52:03.737 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-01-01 16:52:03.738 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 50: callback 4
2019-01-01 16:52:03.739 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=4, payload=04 07 00 00
2019-01-01 16:52:03.740 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Failed.
2019-01-01 16:52:03.742 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeFail, new event IncludeFail
2019-01-01 16:52:03.744 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2019-01-01 16:52:03.745 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Transaction already in queue - removed original
2019-01-01 16:52:03.746 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 52 to queue - size 1
2019-01-01 16:52:03.747 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-01 16:52:03.749 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 50: Transaction CANCELLED
2019-01-01 16:52:03.750 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: CANCEL while sending message. Requeueing - 1 attempts left!
2019-01-01 16:52:03.751 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 50: Transaction RESET with 1 retries remaining.
2019-01-01 16:52:03.752 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 50 to queue - size 2
2019-01-01 16:52:03.753 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-01 16:52:03.754 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 05 74
2019-01-01 16:52:03.756 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 05 74
2019-01-01 16:52:03.757 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-01-01 16:52:03.758 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 50: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 5
2019-01-01 16:52:03.758 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-01-01 16:52:03.759 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 50: Transaction not completed
2019-01-01 16:52:03.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-01 16:52:03.761 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-01 16:52:03.762 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 05 07 00 00 B0
2019-01-01 16:52:03.762 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 50: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 5
2019-01-01 16:52:03.763 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-01-01 16:52:03.764 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=5, payload=05 07 00 00
2019-01-01 16:52:03.765 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=5, payload=05 07 00 00
2019-01-01 16:52:03.767 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 50: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 5
2019-01-01 16:52:03.768 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-01-01 16:52:03.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 50: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 5
2019-01-01 16:52:03.771 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 50: (Callback 5)
2019-01-01 16:52:03.772 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-01-01 16:52:03.773 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 50: callback 5
2019-01-01 16:52:03.775 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=5, payload=05 07 00 00
2019-01-01 16:52:03.776 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Failed.
2019-01-01 16:52:03.778 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeFail, new event IncludeFail
2019-01-01 16:52:03.781 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2019-01-01 16:52:03.782 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Transaction already in queue - removed original
2019-01-01 16:52:03.783 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 53 to queue - size 1
2019-01-01 16:52:03.785 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-01 16:52:03.786 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 50: Transaction CANCELLED
2019-01-01 16:52:03.788 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Retry count exceeded. Discarding message: TID 50: [CANCELLED] priority=Controller, requiresResponse=true, callback: 5
2019-01-01 16:52:03.789 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 50: Transaction completed
2019-01-01 16:52:03.790 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:50 CANCELLED
2019-01-01 16:52:03.791 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-01 16:52:03.794 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-01 16:52:03.795 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 06 B3
2019-01-01 16:52:03.797 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 06 B3
2019-01-01 16:52:03.799 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-01-01 16:52:03.800 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-01-01 16:52:03.800 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 53: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 6
2019-01-01 16:52:03.801 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-01 16:52:03.802 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-01 16:52:03.803 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 53: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 6
2019-01-01 16:52:03.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-01-01 16:52:03.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-01 16:52:03.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-01 16:52:04.506 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2019-01-01 16:52:05.599 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@14629c
2019-01-01 16:52:05.601 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: Adding to device queue
2019-01-01 16:52:05.603 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: Added 54 to queue - size 19
2019-01-01 16:52:05.605 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-01 16:52:08.801 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 53: Timeout at state WAIT_REQUEST. 3 retries remaining.
2019-01-01 16:52:08.803 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 53: Transaction is current transaction, so clearing!!!!!
2019-01-01 16:52:08.804 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 53: Transaction CANCELLED
2019-01-01 16:52:08.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:53 CANCELLED
2019-01-01 16:52:08.808 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-01 16:52:08.816 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 10 8B
2019-01-01 16:52:08.818 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 10 8B
2019-01-01 16:52:08.820 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-01-01 16:52:08.822 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-01-01 16:52:08.822 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 49: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-01-01 16:52:08.824 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-01 16:52:08.826 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-01 16:52:08.827 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 49: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-01-01 16:52:08.829 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-01-01 16:52:08.829 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 01 9B
2019-01-01 16:52:08.830 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-01 16:52:08.832 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-01 16:52:08.833 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01
2019-01-01 16:52:08.836 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01
2019-01-01 16:52:08.838 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 49: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-01-01 16:52:08.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-01-01 16:52:08.842 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 49: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-01-01 16:52:08.844 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01
2019-01-01 16:52:08.845 [DEBUG] [lmessage.RequestNodeInfoMessageClass] - Request node info successfully placed on stack.
2019-01-01 16:52:08.847 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 49: Advanced to WAIT_DATA
2019-01-01 16:52:08.849 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: TID 49: Transaction not completed
2019-01-01 16:52:08.851 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-01 16:52:08.852 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-01 16:52:18.787 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion timer at IncludeFail
2019-01-01 16:52:18.790 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2019-01-01 16:52:18.793 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 55 to queue - size 1
2019-01-01 16:52:18.794 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-01 16:52:18.797 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion
2019-01-01 16:52:18.799 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done
2019-01-01 16:52:20.281 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:2c01b3df
2019-01-01 16:52:20.283 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to doAs I thought - the error is reported from the controller. Unfortunately, there is no reason provided - just the failure, and the ZWave documentation doesn’t describe what would cause this.
Would it be a fair guess to assume the problem is with the latest OH or z-wave binding?
Before upgrading to 2.4 and the latest z-wave binding I did not have this issue.
No - I don’t see why this would be the case. From your log, nothing is sent prior to this command, and the controller is reporting that it is unable to start inclusion. I don’t really see how this can be a binding problem.
Have you tried to reset the controller for starters?
I don’t see how you can draw the conclusion that it is related to the latest binding from this?
My assumption to the problem being OH or the binding was based on the fact that I previously only had to search for things in the Paper UI and then I could find the new device.
This time I had to stop OH, remove the z-wave controller, hold the button on the controller until it started blinking, reset the z-wave device, press the button on the controller, press the button on the new device, plug the controller back in, start OH and go to the Paper UI to add the device.
In any case, despite my faulty assumptions, the device I wanted to add has now been successfully added.
Thank you for your assistance!
I guess my point is it’s easy to jump to conclusions like this - and I can appreciate why. But if you upgrade to a newer OS on your computer, and the hard disk crashes at the same time, it doesn’t mean it’s was due to the newer version of the OS 
.
Cool - as a matter of interest do you know what made it work again? Did you just try again until it worked, or did you reset the controller? Or something else?
I know.
But jumping to conclusions is pretty much the only jumping I do these days. 
I’m not sure I did a controller reset but I actually stopped OH and removed the controller and then I went back to reading the manual for the controller (Aeotec Z-Stick Gen 5) and put the controller in removal mode before resetting the device. Then I put the controller in Inclusion mode and pressed the button on the device I wanted to add and it was added to the controller. Then I plugged the controller back into my Raspberry Pi3 and started OH again.
In the openhab.log file I then saw the following line:
2019-01-01 18:07:01.440 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:2c01b3df:node27' to inbox.
In the Paper UI I saw the device being found so I added it.
Now it seems to work but I am confused why I need to do it like this when previously it was just by searching for the device and see it appear in the Inbox?
Yep - this is what I would call a controller reset - you removed the power (ie removed it from the USB).
My guess is the controller got itself into a confused state and needed a reset. Occasionally, computers crash. The controller is after-all, a micro-controller running software - it’s not going to be perfect.