MT2652 shows as 'unknown device'

Tomas_Tichy · December 2, 2018, 1:38pm

Platform information:
- Hardware: raspberry PI 3B+
- OS: openhabian 1.4.1
- Java Runtime Environment: which java platform is used and what version
- openHAB version: 2, tried stable, testinng, unstable
Issue of the topic: MT2652 (devolo scene switch with battery) - keeps showing as ‘unknown device’
Please post configurations (if applicable):
If logs where generated please post these here using code fences:

tried to replace battery
tried reinstall openhabian many times
tried to wake up many times
read many discussions on the internet.

no result - always the device keep showing ONLINE but UNKNOWN DEVICE.

(I use other devices from FIBARO and TP-LINK without any problems)

However I am getting desperate. Any idea how to solve or troubleshoot the problem?

Thanks,

logs:
2018-12-02 12:30:12.566 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 3: Node found
2018-12-02 12:30:29.908 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
2018-12-02 12:32:32.378 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
2018-12-02 12:33:49.141 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
2018-12-02 12:44:53.696 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery could not resolve to a thingType! Manufacturer data not known.

sihui · December 2, 2018, 3:30pm

Battery devices need to be woken up after inclusion sometimes many times, keep going.
It’s in the database:
https://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-list/devicesummary/3

Make sure you are using the right wakeup procedure:

Click button 2 in management mode.

Tomas_Tichy · December 2, 2018, 4:23pm

yep, I tried more than 10 times… maybe I am doing something wrong?
I tried various things… anyway - now it is added as thing with ‘unknown device’ and
i am trying to wake it up using button 2 - switch to management by all 4 buttons for 5 seconds and then clicking button 2, (right upper)

Tomas_Tichy · December 2, 2018, 4:31pm

i tried now again 10x to wake it up… and nothing has changed.

sihui · December 2, 2018, 4:32pm

grafik

sihui · December 2, 2018, 4:33pm

Switch Zwave to DEBUG, wake it up and post the log, please

Tomas_Tichy · December 2, 2018, 4:33pm

yep, all 4,then it goes to management - green is flashing.
then clicking button 2 - and green is quickly flashing for something like 1 second.

sihui · December 2, 2018, 4:35pm

Check your manual for correct indication …

Tomas_Tichy · December 2, 2018, 4:54pm

I think it is in align with manual…
here are DEBUG logs from now:
2018-12-02 17:43:34.869 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling…
2018-12-02 17:45:22.066 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Handler disposed. Unregistering listener.
2018-12-02 17:45:22.185 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 3: Serialise aborted as static stages not complete
2018-12-02 17:45:22.198 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=360, service.bundleid=201, service.scope=singleton} - org.openhab.binding.zwave
2018-12-02 17:45:36.698 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:6f2c0bd3
2018-12-02 17:45:36.709 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
2018-12-02 17:45:36.720 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:6f2c0bd3
2018-12-02 17:45:36.729 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
2018-12-02 17:45:36.740 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2018-12-02 17:45:36.749 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion
2018-12-02 17:45:36.759 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.
2018-12-02 17:45:36.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 59 to queue - size 1
2018-12-02 17:45:36.778 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:45:36.786 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 55 24
2018-12-02 17:45:36.792 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 55 24
2018-12-02 17:45:36.800 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-12-02 17:45:36.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:45:36.810 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:45:36.815 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-12-02 17:45:36.816 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 55 01 00 00 E6
2018-12-02 17:45:36.820 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-12-02 17:45:36.826 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:45:36.828 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-12-02 17:45:36.835 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 59: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 85
2018-12-02 17:45:36.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:45:36.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=85, payload=55 01 00 00
2018-12-02 17:45:36.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=85, payload=55 01 00 00
2018-12-02 17:45:36.868 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 59: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 85
2018-12-02 17:45:36.873 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-12-02 17:45:36.877 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 59: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 85
2018-12-02 17:45:36.882 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 59: (Callback 85)
2018-12-02 17:45:36.886 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-12-02 17:45:36.892 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 59: callback 85
2018-12-02 17:45:36.897 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=85, payload=55 01 00 00
2018-12-02 17:45:36.901 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
2018-12-02 17:45:36.906 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart
2018-12-02 17:45:36.911 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 59: Transaction COMPLETED
2018-12-02 17:45:36.917 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 81ms
2018-12-02 17:45:36.920 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 59: Transaction completed
2018-12-02 17:45:36.925 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:59 DONE
2018-12-02 17:45:36.933 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:45:36.937 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:45:38.843 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery completed
2018-12-02 17:45:38.858 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery resolved to thingType zwave:fibaro_fgwp102_03_002
2018-12-02 17:45:38.874 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery completed
2018-12-02 17:45:38.949 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery could not resolve to a thingType! Manufacturer data not known.
2018-12-02 17:45:38.962 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing ‘zwave:device:6f2c0bd3:node3’ to inbox.
2018-12-02 17:45:38.968 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 4: Device discovery completed
2018-12-02 17:45:38.984 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 4: Device discovery could not resolve to a thingType! Manufacturer data not known.
2018-12-02 17:45:49.129 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 55 02 00 00 E5
2018-12-02 17:45:49.159 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=85, payload=55 02 00 00
2018-12-02 17:45:49.166 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=85, payload=55 02 00 00
2018-12-02 17:45:49.175 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-12-02 17:45:49.182 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2018-12-02 17:45:49.191 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2018-12-02 17:45:49.206 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=85, payload=55 02 00 00
2018-12-02 17:45:49.218 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: New node found.
2018-12-02 17:45:49.225 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:45:49.231 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:45:51.793 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 55 07 03 00 E3
2018-12-02 17:45:51.829 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=85, payload=55 07 03 00
2018-12-02 17:45:51.836 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=85, payload=55 07 03 00
2018-12-02 17:45:51.842 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-12-02 17:45:51.851 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2018-12-02 17:45:51.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2018-12-02 17:45:51.866 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=85, payload=55 07 03 00
2018-12-02 17:45:51.874 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Failed.
2018-12-02 17:45:51.883 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeStart, new event IncludeFail
2018-12-02 17:45:51.889 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2018-12-02 17:45:51.900 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 60 to queue - size 1
2018-12-02 17:45:51.909 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:45:51.915 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 56 E3
2018-12-02 17:45:51.921 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 56 E3
2018-12-02 17:45:51.928 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-12-02 17:45:51.932 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:45:51.948 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-12-02 17:45:51.952 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 60: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 86
2018-12-02 17:45:51.961 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:45:51.964 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 60: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 86
2018-12-02 17:45:51.969 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-12-02 17:45:51.973 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:45:51.980 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 56 06 03 00 E1
2018-12-02 17:45:51.976 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:45:52.008 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=86, payload=56 06 03 00
2018-12-02 17:45:52.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=86, payload=56 06 03 00
2018-12-02 17:45:52.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 60: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 86
2018-12-02 17:45:52.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-12-02 17:45:52.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 60: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 86
2018-12-02 17:45:52.027 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 60: (Callback 86)
2018-12-02 17:45:52.033 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-12-02 17:45:52.037 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 60: callback 86
2018-12-02 17:45:52.042 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=86, payload=56 06 03 00
2018-12-02 17:45:52.046 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
2018-12-02 17:45:52.050 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovered
2018-12-02 17:45:52.058 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeFail, new event IncludeDone
2018-12-02 17:45:52.065 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2018-12-02 17:45:52.071 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 61 to queue - size 1
2018-12-02 17:45:52.075 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:45:52.081 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion
2018-12-02 17:45:52.085 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done
2018-12-02 17:45:52.089 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 60: Advanced to DONE
2018-12-02 17:45:52.094 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 142ms
2018-12-02 17:45:52.099 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 60: Transaction completed
2018-12-02 17:45:52.104 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:60 DONE
2018-12-02 17:45:52.118 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:45:52.124 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:45:52.129 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 00 B5
2018-12-02 17:45:52.135 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 00 B5
2018-12-02 17:45:52.142 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-12-02 17:45:52.146 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:45:52.168 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-12-02 17:45:52.173 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 61: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2018-12-02 17:45:52.178 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:45:52.181 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 61: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2018-12-02 17:45:52.186 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-12-02 17:45:52.189 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:45:52.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:45:55.216 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=368, service.bundleid=201, service.scope=singleton} - org.openhab.binding.zwave
2018-12-02 17:45:55.259 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:6f2c0bd3:node3.
2018-12-02 17:45:55.279 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: MANUFACTURER not set
2018-12-02 17:45:55.283 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Controller status changed to ONLINE.
2018-12-02 17:45:55.292 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Controller is ONLINE. Starting device initialisation.
2018-12-02 17:45:55.314 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties.
2018-12-02 17:45:55.321 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties. MAN=2147483647
2018-12-02 17:45:55.326 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Properties synchronised
2018-12-02 17:45:55.341 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2018-12-02 17:45:55.346 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising Thing Node…
2018-12-02 17:45:55.352 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling intialised at 1800 seconds - start in 1024200 milliseconds.
2018-12-02 17:45:55.356 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Device initialisation complete.
2018-12-02 17:45:57.178 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 61: Timeout at state WAIT_REQUEST. 3 retries remaining.
2018-12-02 17:45:57.186 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 61: Transaction is current transaction, so clearing!!!
2018-12-02 17:45:57.194 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 61: Transaction CANCELLED
2018-12-02 17:45:57.200 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:61 CANCELLED
2018-12-02 17:45:57.214 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:46:06.723 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:6f2c0bd3
2018-12-02 17:46:06.731 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
2018-12-02 17:47:22.697 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:6f2c0bd3
2018-12-02 17:47:22.705 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
2018-12-02 17:47:22.715 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:6f2c0bd3
2018-12-02 17:47:22.722 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
2018-12-02 17:47:22.730 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2018-12-02 17:47:22.739 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion
2018-12-02 17:47:22.746 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.
2018-12-02 17:47:22.751 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 62 to queue - size 1
2018-12-02 17:47:22.757 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:47:22.763 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 58 29
2018-12-02 17:47:22.768 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 58 29
2018-12-02 17:47:22.775 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-12-02 17:47:22.779 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:47:22.783 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:47:22.786 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-12-02 17:47:22.790 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-12-02 17:47:22.791 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 58 01 00 00 EB
2018-12-02 17:47:22.800 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:47:22.798 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-12-02 17:47:22.809 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 62: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 88
2018-12-02 17:47:22.815 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:47:22.838 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=88, payload=58 01 00 00
2018-12-02 17:47:22.845 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=88, payload=58 01 00 00
2018-12-02 17:47:22.849 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 62: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 88
2018-12-02 17:47:22.853 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-12-02 17:47:22.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 62: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 88
2018-12-02 17:47:22.862 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 62: (Callback 88)
2018-12-02 17:47:22.867 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-12-02 17:47:22.872 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 62: callback 88
2018-12-02 17:47:22.875 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=88, payload=58 01 00 00
2018-12-02 17:47:22.881 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
2018-12-02 17:47:22.887 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart
2018-12-02 17:47:22.892 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 62: Transaction COMPLETED
2018-12-02 17:47:22.897 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 88ms
2018-12-02 17:47:22.901 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 62: Transaction completed
2018-12-02 17:47:22.905 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:62 DONE
2018-12-02 17:47:22.911 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:47:22.914 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:47:24.817 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery completed
2018-12-02 17:47:24.824 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery resolved to thingType zwave:fibaro_fgwp102_03_002
2018-12-02 17:47:24.840 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery completed
2018-12-02 17:47:24.854 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery could not resolve to a thingType! Manufacturer data not known.
2018-12-02 17:47:24.869 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 4: Device discovery completed
2018-12-02 17:47:24.885 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 4: Device discovery could not resolve to a thingType! Manufacturer data not known.
2018-12-02 17:47:26.326 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 58 02 00 00 E8
2018-12-02 17:47:26.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=88, payload=58 02 00 00
2018-12-02 17:47:26.376 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=88, payload=58 02 00 00
2018-12-02 17:47:26.382 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-12-02 17:47:26.388 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2018-12-02 17:47:26.393 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2018-12-02 17:47:26.401 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=88, payload=58 02 00 00
2018-12-02 17:47:26.407 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: New node found.
2018-12-02 17:47:26.414 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:47:26.420 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:47:29.574 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 58 07 03 00 EE
2018-12-02 17:47:29.609 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=88, payload=58 07 03 00
2018-12-02 17:47:29.618 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=88, payload=58 07 03 00
2018-12-02 17:47:29.624 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-12-02 17:47:29.629 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2018-12-02 17:47:29.634 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2018-12-02 17:47:29.641 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=88, payload=58 07 03 00
2018-12-02 17:47:29.646 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Failed.
2018-12-02 17:47:29.659 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeStart, new event IncludeFail
2018-12-02 17:47:29.666 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2018-12-02 17:47:29.672 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 63 to queue - size 1
2018-12-02 17:47:29.678 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:47:29.688 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 59 EC
2018-12-02 17:47:29.695 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 59 EC
2018-12-02 17:47:29.705 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-12-02 17:47:29.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:47:29.728 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-12-02 17:47:29.731 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 63: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 89
2018-12-02 17:47:29.741 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:47:29.744 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 63: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 89
2018-12-02 17:47:29.748 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-12-02 17:47:29.755 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 59 06 03 00 EE
2018-12-02 17:47:29.752 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:47:29.765 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:47:29.788 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=89, payload=59 06 03 00
2018-12-02 17:47:29.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=89, payload=59 06 03 00
2018-12-02 17:47:29.802 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 63: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 89
2018-12-02 17:47:29.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-12-02 17:47:29.810 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 63: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 89
2018-12-02 17:47:29.814 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 63: (Callback 89)
2018-12-02 17:47:29.818 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-12-02 17:47:29.821 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 63: callback 89
2018-12-02 17:47:29.825 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=89, payload=59 06 03 00
2018-12-02 17:47:29.830 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
2018-12-02 17:47:29.834 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovered
2018-12-02 17:47:29.843 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveInclusionEvent
2018-12-02 17:47:29.847 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeFail, new event IncludeDone
2018-12-02 17:47:29.853 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2018-12-02 17:47:29.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 64 to queue - size 1
2018-12-02 17:47:29.861 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:47:29.865 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion
2018-12-02 17:47:29.869 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done
2018-12-02 17:47:29.873 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 63: Advanced to DONE
2018-12-02 17:47:29.878 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 147ms
2018-12-02 17:47:29.883 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 63: Transaction completed
2018-12-02 17:47:29.888 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:63 DONE
2018-12-02 17:47:29.895 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:47:29.900 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:47:29.905 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 00 B5
2018-12-02 17:47:29.910 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 00 B5
2018-12-02 17:47:29.917 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-12-02 17:47:29.920 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:47:29.938 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-12-02 17:47:29.942 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 64: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2018-12-02 17:47:29.947 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:47:29.951 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 64: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2018-12-02 17:47:29.955 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-12-02 17:47:29.959 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:47:29.963 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:47:34.947 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 64: Timeout at state WAIT_REQUEST. 3 retries remaining.
2018-12-02 17:47:34.957 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 64: Transaction is current transaction, so clearing!!!
2018-12-02 17:47:34.964 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 64: Transaction CANCELLED

Tomas_Tichy · December 2, 2018, 4:54pm

2018-12-02 17:47:34.970 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:64 CANCELLED
2018-12-02 17:47:34.983 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:47:39.657 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Handler disposed. Unregistering listener.
2018-12-02 17:47:39.726 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 3: Serialise aborted as static stages not complete
2018-12-02 17:47:39.738 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=368, service.bundleid=201, service.scope=singleton} - org.openhab.binding.zwave
2018-12-02 17:47:43.952 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:6f2c0bd3
2018-12-02 17:47:43.961 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
2018-12-02 17:47:43.978 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:6f2c0bd3
2018-12-02 17:47:43.987 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
2018-12-02 17:47:43.996 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2018-12-02 17:47:44.006 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion
2018-12-02 17:47:44.013 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.
2018-12-02 17:47:44.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 65 to queue - size 1
2018-12-02 17:47:44.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:47:44.030 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 5B 2A
2018-12-02 17:47:44.036 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 5B 2A
2018-12-02 17:47:44.044 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-12-02 17:47:44.049 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:47:44.054 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:47:44.055 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 5B 01 00 00 E8
2018-12-02 17:47:44.058 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-12-02 17:47:44.065 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-12-02 17:47:44.068 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:47:44.068 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-12-02 17:47:44.074 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 65: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 91
2018-12-02 17:47:44.081 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:47:44.098 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=91, payload=5B 01 00 00
2018-12-02 17:47:44.102 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=91, payload=5B 01 00 00
2018-12-02 17:47:44.106 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 65: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 91
2018-12-02 17:47:44.112 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-12-02 17:47:44.116 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 65: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 91
2018-12-02 17:47:44.121 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 65: (Callback 91)
2018-12-02 17:47:44.125 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-12-02 17:47:44.129 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 65: callback 91
2018-12-02 17:47:44.134 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=91, payload=5B 01 00 00
2018-12-02 17:47:44.138 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
2018-12-02 17:47:44.145 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart
2018-12-02 17:47:44.150 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 65: Transaction COMPLETED
2018-12-02 17:47:44.156 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 82ms
2018-12-02 17:47:44.160 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 65: Transaction completed
2018-12-02 17:47:44.163 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:65 DONE
2018-12-02 17:47:44.174 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:47:44.179 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:47:46.085 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery completed
2018-12-02 17:47:46.093 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery resolved to thingType zwave:fibaro_fgwp102_03_002
2018-12-02 17:47:46.106 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery completed
2018-12-02 17:47:46.122 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery could not resolve to a thingType! Manufacturer data not known.
2018-12-02 17:47:46.144 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 5B 02 00 00 EB
2018-12-02 17:47:46.138 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing ‘zwave:device:6f2c0bd3:node3’ to inbox.
2018-12-02 17:47:46.157 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 4: Device discovery completed
2018-12-02 17:47:46.174 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 4: Device discovery could not resolve to a thingType! Manufacturer data not known.
2018-12-02 17:47:46.189 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=91, payload=5B 02 00 00
2018-12-02 17:47:46.197 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=91, payload=5B 02 00 00
2018-12-02 17:47:46.205 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-12-02 17:47:46.213 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2018-12-02 17:47:46.219 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2018-12-02 17:47:46.228 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=91, payload=5B 02 00 00
2018-12-02 17:47:46.233 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: New node found.
2018-12-02 17:47:46.238 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:47:46.242 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:47:49.451 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 5B 07 03 00 ED
2018-12-02 17:47:49.489 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=91, payload=5B 07 03 00
2018-12-02 17:47:49.496 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=91, payload=5B 07 03 00
2018-12-02 17:47:49.505 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-12-02 17:47:49.513 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2018-12-02 17:47:49.521 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2018-12-02 17:47:49.529 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=91, payload=5B 07 03 00
2018-12-02 17:47:49.536 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Failed.
2018-12-02 17:47:49.545 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeStart, new event IncludeFail
2018-12-02 17:47:49.553 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2018-12-02 17:47:49.558 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 66 to queue - size 1
2018-12-02 17:47:49.564 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:47:49.570 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 5C E9
2018-12-02 17:47:49.575 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 5C E9
2018-12-02 17:47:49.580 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-12-02 17:47:49.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:47:49.608 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-12-02 17:47:49.611 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 66: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 92
2018-12-02 17:47:49.619 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:47:49.622 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 66: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 92
2018-12-02 17:47:49.628 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-12-02 17:47:49.631 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:47:49.632 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 5C 06 03 00 EB
2018-12-02 17:47:49.637 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:47:49.668 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=92, payload=5C 06 03 00
2018-12-02 17:47:49.674 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=92, payload=5C 06 03 00
2018-12-02 17:47:49.679 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 66: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 92
2018-12-02 17:47:49.683 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-12-02 17:47:49.686 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 66: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 92
2018-12-02 17:47:49.691 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 66: (Callback 92)
2018-12-02 17:47:49.696 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-12-02 17:47:49.699 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 66: callback 92
2018-12-02 17:47:49.715 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=92, payload=5C 06 03 00
2018-12-02 17:47:49.719 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
2018-12-02 17:47:49.723 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovered
2018-12-02 17:47:49.732 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeFail, new event IncludeDone
2018-12-02 17:47:49.736 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2018-12-02 17:47:49.743 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 67 to queue - size 1
2018-12-02 17:47:49.750 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:47:49.754 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion
2018-12-02 17:47:49.760 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done
2018-12-02 17:47:49.765 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 66: Advanced to DONE
2018-12-02 17:47:49.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 158ms
2018-12-02 17:47:49.772 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 66: Transaction completed
2018-12-02 17:47:49.777 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:66 DONE
2018-12-02 17:47:49.783 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:47:49.786 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:47:49.791 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 00 B5
2018-12-02 17:47:49.795 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 00 B5
2018-12-02 17:47:49.800 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-12-02 17:47:49.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:47:49.828 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-12-02 17:47:49.831 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 67: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2018-12-02 17:47:49.834 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:47:49.838 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 67: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2018-12-02 17:47:49.843 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-12-02 17:47:49.847 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:47:49.851 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:47:54.834 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 67: Timeout at state WAIT_REQUEST. 3 retries remaining.
2018-12-02 17:47:54.840 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 67: Transaction is current transaction, so clearing!!!
2018-12-02 17:47:54.847 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 67: Transaction CANCELLED
2018-12-02 17:47:54.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:67 CANCELLED
2018-12-02 17:47:54.866 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:47:59.117 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=369, service.bundleid=201, service.scope=singleton} - org.openhab.binding.zwave
2018-12-02 17:47:59.159 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:6f2c0bd3:node3.
2018-12-02 17:47:59.192 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: MANUFACTURER not set
2018-12-02 17:47:59.199 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Controller status changed to ONLINE.
2018-12-02 17:47:59.206 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Controller is ONLINE. Starting device initialisation.
2018-12-02 17:47:59.230 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties.
2018-12-02 17:47:59.235 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties. MAN=2147483647
2018-12-02 17:47:59.239 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Properties synchronised
2018-12-02 17:47:59.257 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2018-12-02 17:47:59.266 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising Thing Node…
2018-12-02 17:47:59.271 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling intialised at 1800 seconds - start in 952200 milliseconds.
2018-12-02 17:47:59.277 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Device initialisation complete.
2018-12-02 17:48:12.638 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Handler disposed. Unregistering listener.
2018-12-02 17:48:12.707 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 3: Serialise aborted as static stages not complete
2018-12-02 17:48:12.717 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=369, service.bundleid=201, service.scope=singleton} - org.openhab.binding.zwave
2018-12-02 17:48:13.981 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:6f2c0bd3
2018-12-02 17:48:13.987 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
2018-12-02 17:48:23.315 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave inclusion controller finalised
2018-12-02 17:48:23.321 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave inclusion controller finalised
2018-12-02 17:48:23.326 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave inclusion controller finalised
2018-12-02 17:48:42.361 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:6f2c0bd3
2018-12-02 17:48:42.369 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
2018-12-02 17:48:42.377 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:6f2c0bd3
2018-12-02 17:48:42.388 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
2018-12-02 17:48:42.397 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2018-12-02 17:48:42.404 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion
2018-12-02 17:48:42.412 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.
2018-12-02 17:48:42.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 68 to queue - size 1
2018-12-02 17:48:42.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:48:42.437 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 5E 2F
2018-12-02 17:48:42.443 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 5E 2F
2018-12-02 17:48:42.450 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-12-02 17:48:42.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:48:42.460 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:48:42.464 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-12-02 17:48:42.466 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 5E 01 00 00 ED
2018-12-02 17:48:42.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-12-02 17:48:42.475 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:48:42.479 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-12-02 17:48:42.484 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 68: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 94
2018-12-02 17:48:42.490 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:48:42.508 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=94, payload=5E 01 00 00
2018-12-02 17:48:42.513 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=94, payload=5E 01 00 00
2018-12-02 17:48:42.518 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 68: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 94
2018-12-02 17:48:42.522 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-12-02 17:48:42.525 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 68: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 94
2018-12-02 17:48:42.530 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 68: (Callback 94)
2018-12-02 17:48:42.534 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-12-02 17:48:42.537 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 68: callback 94
2018-12-02 17:48:42.541 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=94, payload=5E 01 00 00
2018-12-02 17:48:42.544 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
2018-12-02 17:48:42.549 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart
2018-12-02 17:48:42.555 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 68: Transaction COMPLETED
2018-12-02 17:48:42.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 75ms
2018-12-02 17:48:42.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 68: Transaction completed
2018-12-02 17:48:42.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:68 DONE
2018-12-02 17:48:42.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:48:42.574 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:48:44.495 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery completed
2018-12-02 17:48:44.504 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery resolved to thingType zwave:fibaro_fgwp102_03_002
2018-12-02 17:48:44.518 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery completed
2018-12-02 17:48:44.534 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery could not resolve to a thingType! Manufacturer data not known.
2018-12-02 17:48:44.544 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing ‘zwave:device:6f2c0bd3:node3’ to inbox.
2018-12-02 17:48:44.552 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 4: Device discovery completed
2018-12-02 17:48:44.569 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 4: Device discovery could not resolve to a thingType! Manufacturer data not known.
2018-12-02 17:48:51.268 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 5E 02 00 00 EE
2018-12-02 17:48:51.309 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=94, payload=5E 02 00 00
2018-12-02 17:48:51.317 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=94, payload=5E 02 00 00
2018-12-02 17:48:51.325 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-12-02 17:48:51.330 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2018-12-02 17:48:51.335 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2018-12-02 17:48:51.342 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=2, callback=94, payload=5E 02 00 00
2018-12-02 17:48:51.347 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: New node found.
2018-12-02 17:48:51.353 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:48:51.361 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:48:54.113 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 5E 07 03 00 E8
2018-12-02 17:48:54.148 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=94, payload=5E 07 03 00
2018-12-02 17:48:54.158 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=94, payload=5E 07 03 00
2018-12-02 17:48:54.163 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-12-02 17:48:54.171 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2018-12-02 17:48:54.180 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2018-12-02 17:48:54.187 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=7, callback=94, payload=5E 07 03 00
2018-12-02 17:48:54.196 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Failed.
2018-12-02 17:48:54.204 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeStart, new event IncludeFail
2018-12-02 17:48:54.214 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2018-12-02 17:48:54.220 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 69 to queue - size 1
2018-12-02 17:48:54.226 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:48:54.233 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 5F EA
2018-12-02 17:48:54.242 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 5F EA
2018-12-02 17:48:54.251 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-12-02 17:48:54.256 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:48:54.278 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-12-02 17:48:54.282 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 69: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 95
2018-12-02 17:48:54.290 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:48:54.293 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 69: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 95
2018-12-02 17:48:54.299 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-12-02 17:48:54.303 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:48:54.306 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 5F 06 03 00 E8
2018-12-02 17:48:54.308 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:48:54.339 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=95, payload=5F 06 03 00
2018-12-02 17:48:54.343 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=95, payload=5F 06 03 00
2018-12-02 17:48:54.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 69: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 95
2018-12-02 17:48:54.353 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-12-02 17:48:54.360 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 69: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 95
2018-12-02 17:48:54.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 69: (Callback 95)
2018-12-02 17:48:54.376 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-12-02 17:48:54.382 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 69: callback 95

Tomas_Tichy · December 2, 2018, 4:55pm

2018-12-02 17:48:54.389 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=95, payload=5F 06 03 00
2018-12-02 17:48:54.399 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
2018-12-02 17:48:54.405 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovered
2018-12-02 17:48:54.416 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeFail, new event IncludeDone
2018-12-02 17:48:54.424 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2018-12-02 17:48:54.434 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 70 to queue - size 1
2018-12-02 17:48:54.441 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:48:54.446 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion
2018-12-02 17:48:54.450 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done
2018-12-02 17:48:54.454 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 69: Advanced to DONE
2018-12-02 17:48:54.457 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 176ms
2018-12-02 17:48:54.462 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 69: Transaction completed
2018-12-02 17:48:54.467 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:69 DONE
2018-12-02 17:48:54.472 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:48:54.477 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:48:54.481 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 00 B5
2018-12-02 17:48:54.487 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 00 B5
2018-12-02 17:48:54.493 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-12-02 17:48:54.497 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:48:54.518 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-12-02 17:48:54.522 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 70: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2018-12-02 17:48:54.526 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:48:54.531 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 70: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2018-12-02 17:48:54.535 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-12-02 17:48:54.539 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:48:54.543 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:48:57.092 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=370, service.bundleid=201, service.scope=singleton} - org.openhab.binding.zwave
2018-12-02 17:48:57.120 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:6f2c0bd3:node3.
2018-12-02 17:48:57.135 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: MANUFACTURER not set
2018-12-02 17:48:57.139 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Controller status changed to ONLINE.
2018-12-02 17:48:57.146 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Controller is ONLINE. Starting device initialisation.
2018-12-02 17:48:57.161 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties.
2018-12-02 17:48:57.166 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties. MAN=2147483647
2018-12-02 17:48:57.171 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Properties synchronised
2018-12-02 17:48:57.184 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2018-12-02 17:48:57.189 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising Thing Node…
2018-12-02 17:48:57.194 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling intialised at 1800 seconds - start in 808200 milliseconds.
2018-12-02 17:48:57.198 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Device initialisation complete.
2018-12-02 17:48:59.527 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 70: Timeout at state WAIT_REQUEST. 3 retries remaining.
2018-12-02 17:48:59.542 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 70: Transaction is current transaction, so clearing!!!
2018-12-02 17:48:59.549 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 70: Transaction CANCELLED
2018-12-02 17:48:59.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:70 CANCELLED
2018-12-02 17:48:59.568 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:49:12.377 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:6f2c0bd3
2018-12-02 17:49:12.379 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
2018-12-02 17:51:28.723 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 4: ZWaveCommandClassTransactionPayload - send to node
2018-12-02 17:51:28.728 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: SECURITY not supported
2018-12-02 17:51:28.732 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Command Class COMMAND_CLASS_NO_OPERATION is NOT required to be secured
2018-12-02 17:51:28.736 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@19573a1
2018-12-02 17:51:28.745 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Adding to device queue
2018-12-02 17:51:28.749 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Added 71 to queue - size 2
2018-12-02 17:51:28.752 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:51:28.757 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 04 01 00 25 61 A5
2018-12-02 17:51:28.761 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 4: Sending REQUEST Message = 01 08 00 13 04 01 00 25 61 A5
2018-12-02 17:51:28.767 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-12-02 17:51:28.771 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:51:28.774 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:51:28.776 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2018-12-02 17:51:28.777 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-12-02 17:51:28.779 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-12-02 17:51:28.781 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:51:28.788 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-12-02 17:51:28.791 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 71: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 97
2018-12-02 17:51:28.795 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:51:28.818 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-12-02 17:51:28.821 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-12-02 17:51:28.824 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 71: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 97
2018-12-02 17:51:28.826 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-12-02 17:51:28.829 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 71: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 97
2018-12-02 17:51:28.832 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-12-02 17:51:28.834 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: sentData successfully placed on stack.
2018-12-02 17:51:28.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 71: Advanced to WAIT_REQUEST
2018-12-02 17:51:28.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 71: Transaction not completed
2018-12-02 17:51:28.842 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:51:28.844 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:51:33.653 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 13 61 01 01 E8 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 09 02 04 09
2018-12-02 17:51:33.691 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=97, payload=61 01 01 E8 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 09 02 04
2018-12-02 17:51:33.696 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=97, payload=61 01 01 E8 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 09 02 04
2018-12-02 17:51:33.699 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 71: [WAIT_REQUEST] priority=Poll, requiresResponse=true, callback: 97
2018-12-02 17:51:33.701 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-12-02 17:51:33.704 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 71: [WAIT_REQUEST] priority=Poll, requiresResponse=true, callback: 97
2018-12-02 17:51:33.706 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 71: (Callback 97)
2018-12-02 17:51:33.709 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-12-02 17:51:33.711 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 71: callback 97
2018-12-02 17:51:33.716 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=97, payload=61 01 01 E8 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 09 02 04
2018-12-02 17:51:33.719 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: SendData Request. CallBack ID = 97, Status = Transmission complete, no ACK received(1)
2018-12-02 17:51:33.722 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 71: Transaction CANCELLED
2018-12-02 17:51:33.724 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-12-02 17:51:33.727 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: CANCEL while sending message. Requeueing - 2 attempts left!
2018-12-02 17:51:33.729 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 71: Transaction RESET with 2 retries remaining.
2018-12-02 17:51:33.732 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Adding to device queue
2018-12-02 17:51:33.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Added 71 to queue - size 2
2018-12-02 17:51:33.737 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:51:33.741 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 04 01 00 25 62 A6
2018-12-02 17:51:33.745 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 4: Sending REQUEST Message = 01 08 00 13 04 01 00 25 62 A6
2018-12-02 17:51:33.754 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-12-02 17:51:33.757 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:51:33.763 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2018-12-02 17:51:33.768 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-12-02 17:51:33.770 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 71: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 98
2018-12-02 17:51:33.774 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 71: Transaction not completed
2018-12-02 17:51:33.776 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:51:33.779 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 71: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 98
2018-12-02 17:51:33.781 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-12-02 17:51:33.783 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:51:33.786 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:51:33.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-12-02 17:51:33.801 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-12-02 17:51:33.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 71: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 98
2018-12-02 17:51:33.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-12-02 17:51:33.809 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 71: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 98
2018-12-02 17:51:33.811 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-12-02 17:51:33.814 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: sentData successfully placed on stack.
2018-12-02 17:51:33.816 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 71: Advanced to WAIT_REQUEST
2018-12-02 17:51:33.817 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 71: Transaction not completed
2018-12-02 17:51:33.819 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:51:33.820 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:51:38.645 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 13 62 01 01 E8 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 09 02 04 0A
2018-12-02 17:51:38.681 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=98, payload=62 01 01 E8 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 09 02 04
2018-12-02 17:51:38.686 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=98, payload=62 01 01 E8 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 09 02 04
2018-12-02 17:51:38.691 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 71: [WAIT_REQUEST] priority=Poll, requiresResponse=true, callback: 98
2018-12-02 17:51:38.695 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-12-02 17:51:38.699 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 71: [WAIT_REQUEST] priority=Poll, requiresResponse=true, callback: 98
2018-12-02 17:51:38.702 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 71: (Callback 98)
2018-12-02 17:51:38.706 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-12-02 17:51:38.710 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 71: callback 98
2018-12-02 17:51:38.716 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=98, payload=62 01 01 E8 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 09 02 04
2018-12-02 17:51:38.721 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: SendData Request. CallBack ID = 98, Status = Transmission complete, no ACK received(1)
2018-12-02 17:51:38.724 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 71: Transaction CANCELLED
2018-12-02 17:51:38.728 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-12-02 17:51:38.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: CANCEL while sending message. Requeueing - 1 attempts left!
2018-12-02 17:51:38.733 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 71: Transaction RESET with 1 retries remaining.
2018-12-02 17:51:38.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Adding to device queue
2018-12-02 17:51:38.738 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Added 71 to queue - size 2
2018-12-02 17:51:38.740 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-12-02 17:51:38.744 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 04 01 00 25 63 A7
2018-12-02 17:51:38.748 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 4: Sending REQUEST Message = 01 08 00 13 04 01 00 25 63 A7
2018-12-02 17:51:38.754 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-12-02 17:51:38.757 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:51:38.766 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2018-12-02 17:51:38.778 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-12-02 17:51:38.779 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 71: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 99
2018-12-02 17:51:38.781 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 71: Transaction not completed
2018-12-02 17:51:38.783 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-12-02 17:51:38.784 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 71: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 99
2018-12-02 17:51:38.786 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-12-02 17:51:38.787 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:51:38.789 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:51:38.808 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-12-02 17:51:38.810 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-12-02 17:51:38.811 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 71: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 99
2018-12-02 17:51:38.813 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-12-02 17:51:38.815 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 71: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 99
2018-12-02 17:51:38.816 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
2018-12-02 17:51:38.818 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: sentData successfully placed on stack.
2018-12-02 17:51:38.820 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 71: Advanced to WAIT_REQUEST
2018-12-02 17:51:38.821 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 71: Transaction not completed
2018-12-02 17:51:38.823 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:51:38.824 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-12-02 17:51:43.623 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 13 63 01 01 E6 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 09 02 04 05
2018-12-02 17:51:43.660 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=99, payload=63 01 01 E6 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 09 02 04
2018-12-02 17:51:43.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=99, payload=63 01 01 E6 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 09 02 04
2018-12-02 17:51:43.669 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 71: [WAIT_REQUEST] priority=Poll, requiresResponse=true, callback: 99
2018-12-02 17:51:43.672 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-12-02 17:51:43.676 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 71: [WAIT_REQUEST] priority=Poll, requiresResponse=true, callback: 99
2018-12-02 17:51:43.679 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 71: (Callback 99)
2018-12-02 17:51:43.686 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-12-02 17:51:43.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 71: callback 99
2018-12-02 17:51:43.696 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=99, payload=63 01 01 E6 00 7F 7F 7F 7F 7F 00 01 07 00 00 00 00 02 09 02 04
2018-12-02 17:51:43.699 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: SendData Request. CallBack ID = 99, Status = Transmission complete, no ACK received(1)
2018-12-02 17:51:43.703 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 71: Transaction CANCELLED
2018-12-02 17:51:43.706 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-12-02 17:51:43.710 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Retry count exceeded. Discarding message: TID 71: [CANCELLED] priority=Poll, requiresResponse=true, callback: 99
2018-12-02 17:51:43.713 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 71: Transaction completed
2018-12-02 17:51:43.717 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: notifyTransactionResponse TID:71 CANCELLED
2018-12-02 17:51:43.727 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-12-02 17:51:43.727 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 71: Transaction event listener: DONE: CANCELLED ->
2018-12-02 17:51:43.734 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 4: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@13aafc9
2018-12-02 17:51:43.731 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-12-02 17:51:43.738 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

Tomas_Tichy · December 2, 2018, 4:56pm

MT2652 is NODE 3

sihui · December 2, 2018, 5:03pm

If it is Node 3: it seems to be added, but there is no communication with that node, probably because it is not properly woken up:

Tomas_Tichy · December 2, 2018, 5:49pm

Thank you.

I found out, that my device was not properly paired, it was NOT node 3, it just appeared accidentally
when I was it pairing. I’ve no idea what is it, maybe neighbor’s device? and made me confused.

Thanks a lot.

sihui · December 2, 2018, 6:03pm

It’s very unlikely that he/she pushed the inclusion button on that device within the 30 seconds your controller is put into inclusion mode …