Zwave - Cannot discover new things anymore

andreas1919 · March 2, 2022, 8:55pm

I’m running the following setup:

openhab 3.1.1
zwave controller UZB1
approx. 30 devices
OS Debian

For one year my setup has been running fine with openhab and zwave. One week ago, I have done the update to openhab 3.2.0 after this I was not able to discover new things anymore. (Nothing shows up in the inbox, when I’ve done a “Scan”)

Then I’ve started a “synchronize network” action on my controller thing. But still I haven’t been able to discover anything.

After this synchronize network my entry control devices stopped working with zwave (strange!! But not my biggest issue for now) and the network became quite unstable since then. (And a few devices could not receive any messages anymore, few other has been still working)

And still, I could not discover new devices.

Then I’ve used zensys-tool to delete dead devices, but this improved nothing so far.

Now I decided to give another controller a try and I bought a brand new Aeotec Gen5+.

Pluged off the old UZB1, disabled the old controller thing (bridge) in OH3… Pluged in the new Gen5+, created a new controller thing (bridge), started Scan for new devices … still nothing Shows up No device displayed/discovered… very strange!!

Now I’ve tried to do a downgrade again to 3.1.1 and trying again with UZB1 and Gen5+ but nothing discovered.

What is wrong? openhab.log shows nothing.
Would be nice, if someone could give me some tips.

Comments:

- I’ve tried discovery more than 1000 times with different NEW things like fibaro double switch 2, Popp switch or qubino DIN dimmer.
*- I’ve reseted the NEW things multiple times to ensure, they aren’t synched already. *

Thank you,
Andreas

jswim788 · March 2, 2022, 9:21pm

You turned on debug logging as mentioned here? ZWave - Bindings | openHAB Maybe that would give a clue? Or have you already tried that?

andreas1919 · March 2, 2022, 9:42pm

Yes, I’ve tried already to find out details/issues using debug mode. Nothing in there.

When I start the s, inlusion mode starts, but nothing received an placed in the Inbox.

apella12 · March 2, 2022, 11:08pm

Don’t know why it stopped working. Synchronize network was probably not a good idea, but with factory reset devices and new controller it should be working (or at least getting a Debug log of why it is not).

Are you getting these lines at least? (Showing the controller is working)

2022-03-01 09:29:43.453 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2022-03-01 09:29:48.642 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2022-03-01 09:29:48.649 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.

Also does dmesg show anything suspect regarding the serial connection?

Bob

andreas1919 · March 3, 2022, 9:01am

yes, this lines are there:

2022-03-02 21:07:54.896 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2022-03-02 21:07:54.907 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
…
2022-03-02 21:09:15.519 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2022-03-02 21:09:15.519 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.

andreas1919 · March 3, 2022, 11:41am

Here is the extract of the openhab.log of plugging in new Gen5+ and start “Scan”

10:02:44.845 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:2458a4c94a with scan time of 60
10:02:44.847 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:2458a4c94a
10:02:44.848 [INFO ] [.zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
10:02:44.857 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:2458a4c94a' changed from UNINITIALIZED (DISABLED) to INITIALIZING
10:02:44.861 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
10:02:44.862 [DEBUG] [.zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:2458a4c94a.
10:03:01.642 [DEBUG] [ng.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:2458a4c94a
10:03:19.904 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
10:03:19.912 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Starting receive thread
10:03:19.914 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
10:03:19.914 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
10:03:19.915 [DEBUG] [.zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
10:03:19.917 [INFO ] [ave.internal.protocol.ZWaveController] - Starting ZWave controller
10:03:19.918 [INFO ] [ave.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
10:03:19.918 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:03:19.919 [DEBUG] [ave.internal.protocol.ZWaveController] - Event listener added.
10:03:19.919 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
10:03:19.920 [DEBUG] [ave.internal.protocol.ZWaveController] - Event listener added.
10:03:19.920 [DEBUG] [.zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 16 hours time.
10:03:22.919 [DEBUG] [l.ZWaveController$InitializeDelayTask] - Initialising network
10:03:22.922 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 2706 to queue - size 1
10:03:22.923 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
10:03:22.924 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 15 E9
10:03:22.925 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9
10:03:22.927 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
10:03:22.927 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2706: [WAIT_RESPONSE] priority=Controller, requiresResponse=true,                                                     callback: 0
10:03:22.927 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
10:03:22.928 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 2707 to queue - size 1
10:03:22.928 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
10:03:22.928 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:03:22.928 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 2708 to queue - size 2
10:03:22.929 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:03:22.929 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
10:03:22.929 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2706: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:22.929 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 01 15 5A 2D 57 61 76 65 20 36 2E 30 37 00 01 97
10:03:22.929 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 2709 to queue - size 3
10:03:22.930 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
10:03:22.930 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
10:03:22.930 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=GetVersion[21], type=Response[1], dest=255, callback=0                                                    , payload=5A 2D 57 61 76 65 20 36 2E 30 37 00 01
10:03:22.930 [DEBUG] [erialmessage.GetSucNodeIdMessageClass] - Get SUC NodeID
10:03:22.930 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:03:22.930 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 2710 to queue - size 4
10:03:22.931 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
10:03:22.931 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
10:03:22.932 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetVersion[21], type=Response[1], dest=255, callback=0, payload=5A 2D 57                                                     61 76 65 20 36 2E 30 37 00 01
10:03:22.932 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2706: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:22.933 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
10:03:22.933 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 2706: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:22.933 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetVersion[21], type=Response[1], dest=255, callback=0, payload=5A 2D 57                                                     61 76 65 20 36 2E 30 37 00 01
10:03:22.934 [DEBUG] [.serialmessage.GetVersionMessageClass] - Got MessageGetVersion response. Version=Z-Wave 6.07, Library Type=1
10:03:22.934 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 2706: Transaction COMPLETED
10:03:22.935 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 8ms
10:03:22.935 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 2706: Transaction completed
10:03:22.935 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2706 DONE
10:03:22.936 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:03:22.936 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
10:03:22.937 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 20 DC
10:03:22.937 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 20 DC
10:03:22.938 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
10:03:22.938 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2707: [WAIT_RESPONSE] priority=Controller, requiresResponse=true,                                                     callback: 0
10:03:22.938 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
10:03:22.939 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:03:22.939 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:03:22.940 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2707: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:22.940 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 01 20 D1 5F 22 EF 01 94
10:03:22.940 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
10:03:22.940 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:03:22.941 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
10:03:22.952 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=                                                    0, payload=D1 5F 22 EF 01
10:03:22.952 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=D1 5F 22                                                     EF 01
10:03:22.953 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2707: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:22.953 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
10:03:22.954 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 2707: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:22.954 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=D1 5F 22                                                     EF 01
10:03:22.954 [DEBUG] [serialmessage.MemoryGetIdMessageClass] - Got MessageMemoryGetId response. Home id = 0xd15f22ef, Controller Node id = 1
10:03:22.955 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 2707: Transaction COMPLETED
10:03:22.955 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 17ms
10:03:22.955 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 2707: Transaction completed
10:03:22.955 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2707 DONE
10:03:22.956 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:03:22.956 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
10:03:22.957 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 07 FB
10:03:22.957 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 07 FB
10:03:22.957 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
10:03:22.958 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2708: [WAIT_RESPONSE] priority=Controller, requiresResponse=true,                                                     callback: 0
10:03:22.958 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
10:03:22.958 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:03:22.959 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:03:22.959 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2708: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:22.959 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
10:03:22.960 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:03:22.960 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
10:03:22.961 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 2B 01 07 01 02 00 86 00 01 00 5A FE 87 7F 88 CF 7F C0 4F FB DF FD E0 67 00 80 80 00 8                                                    0 86 00 01 00 E8 73 00 80 0F 00 00 60 00 00 90
10:03:22.961 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=25                                                    5, callback=0, payload=01 02 00 86 00 01 00 5A FE 87 7F 88 CF 7F C0 4F FB DF FD E0 67 00 80 80 00 80 86 00 01 00 E8 73 00 80 0F 00 00 60 00 00
10:03:22.962 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payl                                                    oad=01 02 00 86 00 01 00 5A FE 87 7F 88 CF 7F C0 4F FB DF FD E0 67 00 80 80 00 80 86 00 01 00 E8 73 00 80 0F 00 00 60 00 00
10:03:22.962 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2708: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:22.962 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
10:03:22.963 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 2708: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:22.963 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payl                                                    oad=01 02 00 86 00 01 00 5A FE 87 7F 88 CF 7F C0 4F FB DF FD E0 67 00 80 80 00 80 86 00 01 00 E8 73 00 80 0F 00 00 60 00 00
10:03:22.964 [DEBUG] [.SerialApiGetCapabilitiesMessageClass] - API Version    = 1.2
10:03:22.964 [DEBUG] [.SerialApiGetCapabilitiesMessageClass] - Manufacture ID = 0x86
10:03:22.965 [DEBUG] [.SerialApiGetCapabilitiesMessageClass] - Device Type    = 0x1
10:03:22.965 [DEBUG] [.SerialApiGetCapabilitiesMessageClass] - Device ID      = 0x5a
10:03:22.965 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 2708: Transaction COMPLETED
10:03:22.966 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 2711 to queue - size 3
10:03:22.966 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
10:03:22.967 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 9ms
10:03:22.967 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 2708: Transaction completed
10:03:22.967 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2708 DONE
10:03:22.968 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:03:22.968 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
10:03:22.968 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 06 96 0F 65
10:03:22.968 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65
10:03:22.969 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
10:03:22.969 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2709: [WAIT_RESPONSE] priority=Controller, requiresResponse=true,                                                     callback: 0
10:03:22.970 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
10:03:22.970 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:03:22.970 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:03:22.970 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 01 06 96 0F 64
10:03:22.970 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2709: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:22.971 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
10:03:22.971 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, c                                                    allback=0, payload=96 0F
10:03:22.971 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:03:22.971 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
10:03:22.972 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=                                                    96 0F
10:03:22.972 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2709: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:22.972 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
10:03:22.973 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 2709: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:22.973 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=                                                    96 0F
10:03:22.973 [DEBUG] [sage.SerialApiSetTimeoutsMessageClass] - Got SerialApiSetTimeouts response. ACK=150, BYTE=15
10:03:22.974 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 2709: Transaction COMPLETED
10:03:22.974 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 5ms
10:03:22.975 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 2709: Transaction completed
10:03:22.975 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2709 DONE
10:03:22.976 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:03:22.976 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
10:03:22.976 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 56 AA
10:03:22.977 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 56 AA
10:03:22.977 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
10:03:22.977 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2710: [WAIT_RESPONSE] priority=Controller, requiresResponse=true,                                                     callback: 0
10:03:22.978 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
10:03:22.978 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:03:22.979 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 56 01 AD
10:03:22.979 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback                                                    =0, payload=01
10:03:22.980 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:03:22.980 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2710: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:22.981 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
10:03:22.981 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=01
10:03:22.981 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2710: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:22.982 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
10:03:22.982 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 2710: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:22.983 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=01
10:03:22.983 [DEBUG] [erialmessage.GetSucNodeIdMessageClass] - Got SUC NodeID response.
10:03:22.983 [DEBUG] [erialmessage.GetSucNodeIdMessageClass] - NODE 1: Node is SUC.
10:03:22.984 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 2710: Transaction COMPLETED
10:03:22.984 [DEBUG] [GetControllerCapabilitiesMessageClass] - Creating GET_CONTROLLER_CAPABILITIES message
10:03:22.984 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 2712 to queue - size 2
10:03:22.985 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
10:03:22.985 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 8ms
10:03:22.985 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 2710: Transaction completed
10:03:22.985 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2710 DONE
10:03:22.986 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:03:22.986 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
10:03:22.986 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 02 FE
10:03:22.987 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 02 FE
10:03:22.987 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
10:03:22.987 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2711: [WAIT_RESPONSE] priority=Controller, requiresResponse=true,                                                     callback: 0
10:03:22.988 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
10:03:22.988 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:03:22.989 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:03:22.989 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2711: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:22.989 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
10:03:22.990 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:03:22.990 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
10:03:23.088 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 25 01 02 08 08 1D 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0                                                    0 00 00 00 00 00 00 05 00 C0
10:03:23.090 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, c                                                    allback=0, payload=08 08 1D 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 05 00
10:03:23.091 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=                                                    08 08 1D 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 05 00
10:03:23.092 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2711: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:23.093 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
10:03:23.093 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 2711: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:23.094 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=                                                    08 08 1D 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 05 00
10:03:23.095 [DEBUG] [sage.SerialApiGetInitDataMessageClass] - Got MessageSerialApiGetInitData response.
10:03:23.096 [DEBUG] [sage.SerialApiGetInitDataMessageClass] - NODE 1: Node found
10:03:23.097 [DEBUG] [sage.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
10:03:23.098 [DEBUG] [sage.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
10:03:23.099 [DEBUG] [sage.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
10:03:23.099 [DEBUG] [sage.SerialApiGetInitDataMessageClass] - # Nodes = 1
10:03:23.100 [DEBUG] [sage.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
10:03:23.101 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 2711: Transaction COMPLETED
10:03:23.102 [DEBUG] [ave.internal.protocol.ZWaveController] - NODE 1: Init node thread start
10:03:23.102 [DEBUG] [ave.internal.protocol.ZWaveController] - Starting waiting for init threads
10:03:23.102 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 115ms
10:03:23.103 [DEBUG] [ave.internal.protocol.ZWaveController] - Waiting for init thread Node_1_init
10:03:23.104 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 2711: Transaction completed
10:03:23.104 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2711 DONE
10:03:23.105 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:03:23.109 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
10:03:23.109 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 05 F9
10:03:23.110 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 05 F9
10:03:23.110 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
10:03:23.111 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2712: [WAIT_RESPONSE] priority=Controller, requiresResponse=true,                                                     callback: 0
10:03:23.111 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
10:03:23.111 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:03:23.112 [DEBUG] [ol.initialization.ZWaveNodeSerializer] - NODE 1: Serializing from file /var/lib/openhab/zwave/network_d15f22ef__node_1.xml
10:03:23.112 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 05 3C C3
10:03:23.112 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:03:23.113 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=GetControllerCapabilities[5], type=Response[1], dest=2                                                    55, callback=0, payload=3C
10:03:23.113 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2712: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:23.113 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
10:03:23.114 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, pay                                                    load=3C
10:03:23.114 [DEBUG] [ave.internal.protocol.ZWaveController] - NODE 1: Restore from config: Ok.
10:03:23.114 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2712: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:23.115 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
10:03:23.115 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_BASIC, endpoint 0 created
10:03:23.115 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 2712: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:23.115 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created
10:03:23.115 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, pay                                                    load=3C
10:03:23.115 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Starting initialisation from EMPTYNODE
10:03:23.116 [DEBUG] [GetControllerCapabilitiesMessageClass] - Controller is secondary = false
10:03:23.116 [DEBUG] [GetControllerCapabilitiesMessageClass] - Controller is on other network = false
10:03:23.116 [DEBUG] [ave.internal.protocol.ZWaveController] - NODE 1: Init node thread finished
10:03:23.116 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to IDENTIFY_NODE
10:03:23.116 [DEBUG] [GetControllerCapabilitiesMessageClass] - Node ID Server is present = false
10:03:23.117 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer: Initialisation starting
10:03:23.117 [DEBUG] [ave.internal.protocol.ZWaveController] - Init thread Node_1_init complete
10:03:23.117 [DEBUG] [GetControllerCapabilitiesMessageClass] - Controller is real primary = true
10:03:23.117 [DEBUG] [ave.internal.protocol.ZWaveController] - All init threads complete
10:03:23.117 [DEBUG] [GetControllerCapabilitiesMessageClass] - Controller is SUC = true
10:03:23.118 [DEBUG] [.zwave.handler.ZWaveControllerHandler] - Controller: Incoming Network State Event true
10:03:23.118 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 2712: Transaction COMPLETED
10:03:23.118 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 7ms
10:03:23.118 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 2712: Transaction completed
10:03:23.118 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:serial_zstick:2458a4c94a' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONL                                                    INE
10:03:23.119 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2712 DONE
10:03:23.120 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:03:23.120 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@614d8b1f
10:03:23.120 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
10:03:23.121 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 2713 to queue - size 1
10:03:23.121 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
10:03:23.122 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 01 BB
10:03:23.122 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 01 BB
10:03:23.123 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
10:03:23.123 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2713: [WAIT_RESPONSE] priority=Controller, requiresResponse=true,                                                     callback: 0
10:03:23.123 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
10:03:23.124 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:03:23.124 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:03:23.124 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2713: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:23.124 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
10:03:23.125 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:03:23.125 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 D3 16 01 02 02 01 73
10:03:23.125 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
10:03:23.125 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback                                                    =0, payload=D3 16 01 02 02 01
10:03:23.126 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 16 0                                                    1 02 02 01
10:03:23.126 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2713: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:23.126 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
10:03:23.126 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 2713: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
10:03:23.127 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 16 0                                                    1 02 02 01
10:03:23.127 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: ProtocolInfo
10:03:23.127 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: Listening = true
10:03:23.128 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: Routing   = true
10:03:23.128 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: Beaming   = true
10:03:23.128 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: Version   = 4
10:03:23.128 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: FLIRS     = false
10:03:23.129 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: Security  = false
10:03:23.129 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: Max Baud  = 40000
10:03:23.129 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: Basic    = BASIC_TYPE_STATIC_CONTROLLER
10:03:23.129 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: Generic  = GENERIC_TYPE_STATIC_CONTROLLER
10:03:23.129 [DEBUG] [erialmessage.IdentifyNodeMessageClass] - NODE 1: Specific = SPECIFIC_TYPE_PC_CONTROLLER
10:03:23.130 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 1: Creating new instance of command class COMMAND_CLASS_NO_OPERATION
10:03:23.130 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created
10:03:23.130 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 1: Version = 1, version set. Enabling extra functionality.
10:03:23.130 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 1: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes.
10:03:23.131 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 1: Creating new instance of command class COMMAND_CLASS_BASIC
10:03:23.131 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_BASIC, endpoint 0 created
10:03:23.131 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 1: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes.
10:03:23.131 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 2713: Transaction COMPLETED
10:03:23.132 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 9ms
10:03:23.132 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 2713: Transaction completed
10:03:23.132 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2713 DONE
10:03:23.132 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:03:23.133 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 2713: Transaction event listener: DONE: DONE ->
10:03:23.133 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
10:03:23.133 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@15210d                                                    19
10:03:23.133 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init transaction completed with response COMPLETE
10:03:23.133 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer: FAILED_CHECK - Controller - terminating initialisation
10:03:23.134 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to DONE
10:03:23.134 [DEBUG] [ol.initialization.ZWaveNodeSerializer] - NODE 1: Serializing to file /var/lib/openhab/zwave/network_d15f22ef__node_1.xml
10:03:23.217 [DEBUG] [ng.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:2458a4c94a
10:10:59.809 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:2458a4c94a
10:10:59.810 [DEBUG] [ave.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
10:10:59.810 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:2458a4c94a
10:10:59.811 [DEBUG] [ave.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
10:10:59.811 [DEBUG] [ave.internal.protocol.ZWaveController] - Event listener added.
10:10:59.812 [DEBUG] [nal.protocol.ZWaveInclusionController] - ZWave controller start inclusion
10:10:59.812 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.
10:10:59.812 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 2717 to queue - size 1
10:10:59.813 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
10:10:59.813 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 6E 1F
10:10:59.813 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 6E 1F
10:10:59.814 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
10:10:59.814 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2717: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 110
10:10:59.815 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
10:10:59.815 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:10:59.815 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:10:59.816 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2717: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 110
10:10:59.816 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
10:10:59.817 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:10:59.817 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 6E 01 00 00 DD
10:10:59.817 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
10:10:59.818 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=110, payload=6E 01 00 00
10:10:59.818 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=110, payload=6E 01 00 00
10:10:59.818 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2717: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 110
10:10:59.818 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
10:10:59.819 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 2717: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 110
10:10:59.819 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 2717: (Callback 110)
10:10:59.819 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
10:10:59.819 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 2717: callback 110
10:10:59.820 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=110, payload=6E 01 00 00
10:10:59.820 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
10:10:59.820 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart
10:10:59.820 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 2717: Transaction COMPLETED
10:10:59.821 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 7ms
10:10:59.821 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 2717: Transaction completed
10:10:59.821 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2717 DONE
10:10:59.822 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:10:59.822 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
10:11:59.810 [DEBUG] [zwave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:2458a4c94a
10:11:59.812 [DEBUG] [nal.protocol.ZWaveInclusionController] - ZWave controller stopping inclusion at IncludeStart
10:11:59.813 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
10:11:59.814 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 2718 to queue - size 1
10:11:59.815 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
10:11:59.816 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 6F DA
10:11:59.817 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 6F DA
10:11:59.817 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
10:11:59.818 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2718: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 111
10:11:59.821 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
10:11:59.822 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:11:59.823 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:11:59.824 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2718: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 111
10:11:59.824 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
10:11:59.825 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:11:59.825 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
10:11:59.877 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 6F 06 00 00 DB
10:11:59.878 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=111, payload=6F 06 00 00
10:11:59.878 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=111, payload=6F 06 00 00
10:11:59.879 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2718: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 111
10:11:59.879 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
10:11:59.879 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 2718: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 111
10:11:59.879 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 2718: (Callback 111)
10:11:59.880 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
10:11:59.880 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 2718: callback 111
10:11:59.880 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=111, payload=6F 06 00 00
10:11:59.881 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Add Node: Done.
10:11:59.881 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeDone, new event IncludeDone
10:11:59.881 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
10:11:59.881 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added 2719 to queue - size 1
10:11:59.882 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
10:11:59.882 [DEBUG] [nal.protocol.ZWaveInclusionController] - ZWave controller end exclusion
10:11:59.882 [DEBUG] [ave.internal.protocol.ZWaveController] - ZWaveController include done
10:11:59.883 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 2718: Advanced to DONE
10:11:59.883 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 65ms
10:11:59.883 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 2718: Transaction completed
10:11:59.883 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2718 DONE
10:11:59.884 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:11:59.884 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
10:11:59.885 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 00 B5
10:11:59.885 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 00 B5
10:11:59.885 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
10:11:59.886 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2719: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
10:11:59.886 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
10:11:59.887 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:11:59.887 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
10:11:59.888 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 2719: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
10:11:59.888 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
10:11:59.888 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
10:11:59.889 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
10:12:04.886 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 255: TID 2719: Timeout at state WAIT_REQUEST. 3 retries remaining.
10:12:04.888 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - TID 2719: Transaction is current transaction, so clearing!!!!!
10:12:04.890 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 2719: Transaction CANCELLED
10:12:04.890 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2719 CANCELLED
10:12:04.890 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

apella12 · March 3, 2022, 2:13pm

To me your information rules out anything with the controller and serial connection … that leads to the device(s) and communication.

Does that gen5+ have a button with the color flashing? Could you try to add a device with the stick detached (OH stopped) and see if there is confirmation? This will not work with security devices, but should with some of the others you mentioned. Then put the stick back in OH and restart. They should appear automatically, but if not try a scan. If that doesn’t work, I’m not sure.

Alternately could you try to “add node” with stick in a PC using the Silabs PC controller? That should show the frame/message the device is sending when you press the inclusion button (per the inclusion protocol). At least then you know the device radio is working.

Bob

system · April 14, 2022, 6:13am

This topic was automatically closed 41 days after the last reply. New replies are no longer allowed.