Aeotec Z-Wave Controller gen7 working with Openhab?

Hubbabubba · January 1, 2025, 2:01pm

Hello everyone,

I’m currently trying to get an Aeotec Z-Wave Stick gen7 to work on a Raspberry Pi with Openhabian RaspiOS.

I tried this with my productive system Raspi4 (Bullseye / 100 Nodes) as well as with a newly and freshly set up Raspi5 (Bookworm / 0 Nodes). In both cases, the Openhab version was the current 4.3.1.

Results are identical in both cases:
After the stick is plugged in, it is assigned to /dev/ttyUSB0; you can read and write to the device as “openhabian”. It is also recognized and initialized by the Z-Wave binding of Openhab.

However, the following message appears in the log for both systems (Raspi4 and fresh Raspi5):

2024-12-31 12:56:42.619 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2024-12-31 12:56:42.620 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2024-12-31 12:56:45.763 [WARN ] [.core.thing.binding.BaseThingHandler] - Attempt to apply invalid configuration 'Configuration[{key=controller_softreset; type=Boolean; value=false}, {key=security_networkkey; type=String; value=99 C9 89 DF F6 DB 77 57 77 D2 2F 77 62 E2 36 BF}, {key=security_inclusionmode; type=BigDecimal; value=2}, {key=controller_sisnode; type=BigDecimal; value=0}, {key=controller_maxawakeperiod; type=BigDecimal; value=10}, {key=controller_sync; type=Boolean; value=false}, {key=controller_master; type=Boolean; value=true}, {key=inclusion_mode; type=BigDecimal; value=2}, {key=port; type=String; value=/dev/ttyUSB0}, {key=controller_wakeupperiod; type=BigDecimal; value=3600}, {key=controller_exclude; type=Boolean; value=false}, {key=heal_time; type=BigDecimal; value=-1}, {key=controller_inclusiontimeout; type=BigDecimal; value=30}, {key=controller_hardreset; type=Boolean; value=false}]' on thing 'zwave:serial_zstick:0a79edb193' blocked. This is most likely a bug: {controller_sisnode=The value must not be less than 1.}

The nodes (things) cannot be controlled (in the productive system), although all nodes and the Z-Wave controller are in the “Online” status.
Regarding the error message in the Log …the SIS-Node parameter in the UI when I open the controller thing is set to 1 - so should be ok.

Despite the sentence in the official documentation on Z-Wave binding “Note: As of OpenHAB 4.1 700 chip controllers are fully supported”, is this stick not supported?
Or does something need to be additionally configured?

Thank you for the hints/help and wish you a happy New Year,
Hubba

rlkoshak · January 1, 2025, 4:40pm

What about user “openhab”? openHABian is the user you log in as but OH runs as user openhab and it’s that user that needs to be a member of dialout and have permission to read/write to the tty file.

I don’t think that warning is necessarily related to this issue you are having with the controller. There was a bug that has been fixed but I didn’t think it made it into the 4.3.1 release. There was a place where an Internet was being returned as a float.

I can’t remember if there is a good mitigation. I’m on my phone and having difficulty finding the issue/PR. But if you are on a bigger screen you might have better luck finding it.

This stick is fully supported.

apella12 · January 2, 2025, 1:00am

This is a little concerning since it is the second time. You could review this post starting about here and try the suggestions.

Hubbabubba · January 2, 2025, 11:57am

Hi together and welcome in 2025

Thanks for the hints. Did some of the mentioned ideas/questions on the new/fresh Raspi5 setup.
Here are the results:

User “openhab” is member of dialout and is also able to write and get information from ttyUSB0.

openhabian@openhabian:~ $ groups openhab
openhab : openhab tty dialout audio bluetooth gpio

Openhab user can also create lock files in /var/lock. Added also JAVA command line option for the port as supposed under “Serial Port Configuration | openHAB”.

Unfortunately could not find the mentioned PR/Issue referred by Rich, could just find one similar one related to Homatic, but not related to Z-Wave binding?

Regarding the hint of Bob and the referred post:

There is also no XML file entry for the controller under /var/lib/openhab/zwave after the controller thing has been created in Openhab and is Online.

openhabian@openhabian:/var/lib/openhab/zwave $ ls -l
total 0
openhabian@openhabian:/var/lib/openhab/zwave $

Also resetted the Controller and defined the SIS node as supposed using the Simplicity Studio5 program “Z-Wave PC Controller” and was adding the bridge in Openhab manually making sure the SIS node is set to 1.

All that with no success.

Here is the appropriate log (Debug mode) of the manual add of the bridge (controller) thing in Openhab.
It looks like the binding is able to access the stick since I saw in the log, the binding is able to extract the right firmware version number. So this at least seems to work.

2025-01-02 12:02:39.795 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No thing found in getConfigDescription thing:zwave:serial_zstick:c108306243
2025-01-02 12:02:40.004 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:c108306243 with scan time of 60
2025-01-02 12:02:40.005 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:c108306243
2025-01-02 12:02:40.006 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2025-01-02 12:02:40.146 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2025-01-02 12:02:40.147 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:c108306243.
2025-01-02 12:02:40.148 [DEBUG] [zwave.handler.ZWaveControllerHandler] - No network key set by user - using random value.
2025-01-02 12:02:45.388 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyUSB0'
2025-01-02 12:02:45.413 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
2025-01-02 12:02:45.414 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2025-01-02 12:02:45.414 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
2025-01-02 12:02:45.415 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
2025-01-02 12:02:45.416 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2025-01-02 12:02:45.416 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-02 12:02:45.416 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2025-01-02 12:02:45.416 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-02 12:02:45.417 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2025-01-02 12:02:45.418 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2025-01-02 12:02:48.417 [DEBUG] [.ZWaveController$InitializeDelayTask] - Initialising network
2025-01-02 12:02:48.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 20 to queue - size 1
2025-01-02 12:02:48.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-02 12:02:48.420 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 15 E9 
2025-01-02 12:02:48.421 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2025-01-02 12:02:48.422 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-02 12:02:48.426 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-02 12:02:48.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-02 12:02:48.428 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 01 15 5A 2D 57 61 76 65 20 37 2E 32 31 00 07 94 
2025-01-02 12:02:48.429 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-02 12:02:48.430 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2025-01-02 12:02:48.431 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-02 12:02:48.431 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-02 12:02:48.431 [DEBUG] [nal.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 37 2E 32 31 00 07 
2025-01-02 12:02:48.432 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 20: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.433 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 21 to queue - size 1
2025-01-02 12:02:48.434 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-02 12:02:48.434 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-02 12:02:48.435 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 22 to queue - size 2
2025-01-02 12:02:48.435 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetVersion[21], type=Response[1], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 37 2E 32 31 00 07 
2025-01-02 12:02:48.435 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-02 12:02:48.435 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 20: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.436 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 23 to queue - size 3
2025-01-02 12:02:48.436 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-02 12:02:48.437 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - Get SUC NodeID
2025-01-02 12:02:48.437 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-02 12:02:48.437 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 20: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 24 to queue - size 4
2025-01-02 12:02:48.438 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetVersion[21], type=Response[1], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 37 2E 32 31 00 07 
2025-01-02 12:02:48.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-02 12:02:48.438 [DEBUG] [serialmessage.GetVersionMessageClass] - Got MessageGetVersion response. Version=Z-Wave 7.21, Library Type=7
2025-01-02 12:02:48.439 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 20: Transaction COMPLETED
2025-01-02 12:02:48.440 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 16ms
2025-01-02 12:02:48.440 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 20: Transaction completed
2025-01-02 12:02:48.440 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:20 DONE
2025-01-02 12:02:48.441 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-02 12:02:48.441 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-02 12:02:48.442 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 20 DC 
2025-01-02 12:02:48.442 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2025-01-02 12:02:48.447 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-02 12:02:48.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-02 12:02:48.449 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 20 FD 20 DE 03 00 01 D6 
2025-01-02 12:02:48.455 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-02 12:02:48.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 21: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.457 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-02 12:02:48.457 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=FD 20 DE 03 00 01 
2025-01-02 12:02:48.457 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 21: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.458 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-02 12:02:48.458 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=FD 20 DE 03 00 01 
2025-01-02 12:02:48.459 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 21: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.459 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-02 12:02:48.460 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 21: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.460 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=FD 20 DE 03 00 01 
2025-01-02 12:02:48.461 [DEBUG] [erialmessage.MemoryGetIdMessageClass] - Got MessageMemoryGetId response. Home id = 0xfd20de03, Controller Node id = 0
2025-01-02 12:02:48.461 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 21: Transaction COMPLETED
2025-01-02 12:02:48.462 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 6ms
2025-01-02 12:02:48.462 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 21: Transaction completed
2025-01-02 12:02:48.463 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:21 DONE
2025-01-02 12:02:48.464 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-02 12:02:48.465 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-02 12:02:48.465 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 07 FB 
2025-01-02 12:02:48.466 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2025-01-02 12:02:48.474 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-02 12:02:48.475 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-02 12:02:48.477 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 2B 01 07 07 15 00 00 00 04 00 04 F6 87 3E 88 CF 2B C0 4F FB D7 FD E0 97 00 00 80 00 80 86 80 BA 05 00 70 00 00 EE 7F C0 00 00 00 52 
2025-01-02 12:02:48.479 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-02 12:02:48.480 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 22: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.481 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-02 12:02:48.482 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 22: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.483 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-02 12:02:48.484 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-02 12:02:48.484 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=07 15 00 00 00 04 00 04 F6 87 3E 88 CF 2B C0 4F FB D7 FD E0 97 00 00 80 00 80 86 80 BA 05 00 70 00 00 EE 7F C0 00 00 00 
2025-01-02 12:02:48.484 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-02 12:02:48.485 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=07 15 00 00 00 04 00 04 F6 87 3E 88 CF 2B C0 4F FB D7 FD E0 97 00 00 80 00 80 86 80 BA 05 00 70 00 00 EE 7F C0 00 00 00 
2025-01-02 12:02:48.486 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 22: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.487 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-02 12:02:48.488 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 22: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.489 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=07 15 00 00 00 04 00 04 F6 87 3E 88 CF 2B C0 4F FB D7 FD E0 97 00 00 80 00 80 86 80 BA 05 00 70 00 00 EE 7F C0 00 00 00 
2025-01-02 12:02:48.489 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - API Version    = 7.21
2025-01-02 12:02:48.490 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Manufacture ID = 0x0
2025-01-02 12:02:48.491 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Device Type    = 0x4
2025-01-02 12:02:48.492 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Device ID      = 0x4
2025-01-02 12:02:48.493 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 22: Transaction COMPLETED
2025-01-02 12:02:48.493 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 25 to queue - size 3
2025-01-02 12:02:48.494 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-02 12:02:48.495 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 15ms
2025-01-02 12:02:48.496 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 22: Transaction completed
2025-01-02 12:02:48.497 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:22 DONE
2025-01-02 12:02:48.498 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-02 12:02:48.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-02 12:02:48.500 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 06 96 0F 65 
2025-01-02 12:02:48.501 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2025-01-02 12:02:48.507 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-02 12:02:48.509 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-02 12:02:48.510 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 01 06 96 0F 64 
2025-01-02 12:02:48.515 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-02 12:02:48.516 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 23: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.517 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-02 12:02:48.517 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 
2025-01-02 12:02:48.517 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 23: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.518 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-02 12:02:48.518 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 
2025-01-02 12:02:48.519 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 23: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.519 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-02 12:02:48.520 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 23: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.520 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 
2025-01-02 12:02:48.521 [DEBUG] [age.SerialApiSetTimeoutsMessageClass] - Got SerialApiSetTimeouts response. ACK=150, BYTE=15
2025-01-02 12:02:48.521 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 23: Transaction COMPLETED
2025-01-02 12:02:48.522 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 6ms
2025-01-02 12:02:48.522 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 23: Transaction completed
2025-01-02 12:02:48.524 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:23 DONE
2025-01-02 12:02:48.524 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-02 12:02:48.525 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-02 12:02:48.525 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 56 AA 
2025-01-02 12:02:48.525 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2025-01-02 12:02:48.530 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-02 12:02:48.531 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-02 12:02:48.532 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 01 56 00 00 AD 
2025-01-02 12:02:48.535 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-02 12:02:48.536 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 24: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.536 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-02 12:02:48.536 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 24: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.537 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-02 12:02:48.537 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=00 00 
2025-01-02 12:02:48.537 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-02 12:02:48.537 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-02 12:02:48.538 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=00 00 
2025-01-02 12:02:48.538 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 24: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.538 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-02 12:02:48.538 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 24: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.539 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=00 00 
2025-01-02 12:02:48.539 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - Got SUC NodeID response.
2025-01-02 12:02:48.539 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - No SUC Node is set
2025-01-02 12:02:48.539 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 24: Transaction COMPLETED
2025-01-02 12:02:48.540 [DEBUG] [ve.internal.protocol.ZWaveController] - SUC was not set as required - currently 0, requires 1
2025-01-02 12:02:48.540 [DEBUG] [serialmessage.SetSucNodeMessageClass] - NODE 1: SetSucNodeID node true
2025-01-02 12:02:48.540 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 26 to queue - size 2
2025-01-02 12:02:48.540 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-02 12:02:48.541 [DEBUG] [etControllerCapabilitiesMessageClass] - Creating GET_CONTROLLER_CAPABILITIES message
2025-01-02 12:02:48.541 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 27 to queue - size 3
2025-01-02 12:02:48.541 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-02 12:02:48.542 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 6ms
2025-01-02 12:02:48.542 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 24: Transaction completed
2025-01-02 12:02:48.542 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:24 DONE
2025-01-02 12:02:48.543 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-02 12:02:48.544 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-02 12:02:48.544 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 02 FE 
2025-01-02 12:02:48.545 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 02 FE 
2025-01-02 12:02:48.547 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-02 12:02:48.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 25: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.553 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-02 12:02:48.553 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-02 12:02:48.554 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-02 12:02:48.554 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 25: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.554 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 25 01 02 0A 00 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 07 00 C8 
2025-01-02 12:02:48.554 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-02 12:02:48.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-02 12:02:48.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-02 12:02:48.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=0A 00 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 07 00 
2025-01-02 12:02:48.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=0A 00 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 07 00 
2025-01-02 12:02:48.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 25: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.558 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-02 12:02:48.558 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 25: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:48.559 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=0A 00 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 07 00 
2025-01-02 12:02:48.560 [DEBUG] [age.SerialApiGetInitDataMessageClass] - Got MessageSerialApiGetInitData response.
2025-01-02 12:02:48.560 [DEBUG] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2025-01-02 12:02:48.560 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2025-01-02 12:02:48.560 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2025-01-02 12:02:48.560 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2025-01-02 12:02:48.561 [DEBUG] [age.SerialApiGetInitDataMessageClass] - # Nodes = 1
2025-01-02 12:02:48.561 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2025-01-02 12:02:48.561 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 25: Transaction COMPLETED
2025-01-02 12:02:48.562 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 1: Init node thread start
2025-01-02 12:02:48.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 20ms
2025-01-02 12:02:48.568 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 25: Transaction completed
2025-01-02 12:02:48.569 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:25 DONE
2025-01-02 12:02:48.570 [DEBUG] [ve.internal.protocol.ZWaveController] - Starting waiting for init threads
2025-01-02 12:02:48.571 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 1: Serializing from file /var/lib/openhab/zwave/network_fd20de03__node_1.xml
2025-01-02 12:02:48.571 [DEBUG] [ve.internal.protocol.ZWaveController] - Waiting for init thread Node_1_init
2025-01-02 12:02:48.571 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 1: Error serializing from file: file does not exist.
2025-01-02 12:02:48.572 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Starting initialisation from EMPTYNODE
2025-01-02 12:02:48.574 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 1: Init node thread finished
2025-01-02 12:02:48.574 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-02 12:02:48.574 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to IDENTIFY_NODE
2025-01-02 12:02:48.574 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-02 12:02:48.575 [DEBUG] [ve.internal.protocol.ZWaveController] - Init thread Node_1_init complete
2025-01-02 12:02:48.575 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer: Initialisation starting
2025-01-02 12:02:48.575 [DEBUG] [ve.internal.protocol.ZWaveController] - All init threads complete
2025-01-02 12:02:48.575 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@66cf2e8b
2025-01-02 12:02:48.575 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller: Incoming Network State Event true
2025-01-02 12:02:48.575 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 54 01 01 00 01 03 A1 
2025-01-02 12:02:48.576 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 08 00 54 01 01 00 01 03 A1 
2025-01-02 12:02:48.579 [WARN ] [.core.thing.binding.BaseThingHandler] - Attempt to apply invalid configuration 'Configuration[{key=controller_softreset; type=Boolean; value=false}, {key=security_networkkey; type=String; value=C1 9A 7E DE 37 F2 A2 2C 80 F3 DE A8 24 60 A1 C2}, {key=security_inclusionmode; type=BigDecimal; value=2}, {key=controller_sisnode; type=BigDecimal; value=0}, {key=controller_maxawakeperiod; type=BigDecimal; value=10}, {key=controller_sync; type=Boolean; value=false}, {key=port; type=String; value=/dev/ttyUSB0}, {key=controller_master; type=Boolean; value=true}, {key=inclusion_mode; type=BigDecimal; value=2}, {key=controller_wakeupperiod; type=BigDecimal; value=3600}, {key=heal_time; type=BigDecimal; value=-1}, {key=controller_exclude; type=Boolean; value=false}, {key=controller_inclusiontimeout; type=BigDecimal; value=30}, {key=controller_hardreset; type=Boolean; value=false}]' on thing 'zwave:serial_zstick:c108306243' blocked. This is most likely a bug: {controller_sisnode=The value must not be less than 1.}
2025-01-02 12:02:48.582 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-02 12:02:48.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-02 12:02:48.583 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 54 01 AF 
2025-01-02 12:02:48.583 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-02 12:02:48.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 26: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 3
2025-01-02 12:02:48.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 28 to queue - size 1
2025-01-02 12:02:48.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-02 12:02:48.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-02 12:02:48.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 26: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 3
2025-01-02 12:02:48.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SetSucNodeID[84], type=Response[1], dest=255, callback=0, payload=01 
2025-01-02 12:02:48.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-02 12:02:48.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-02 12:02:48.586 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-02 12:02:48.586 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SetSucNodeID[84], type=Response[1], dest=255, callback=0, payload=01 
2025-01-02 12:02:48.586 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 26: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 3
2025-01-02 12:02:48.586 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-02 12:02:48.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 26: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 3
2025-01-02 12:02:48.587 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SetSucNodeID[84], type=Response[1], dest=255, callback=0, payload=01 
2025-01-02 12:02:48.587 [DEBUG] [serialmessage.SetSucNodeMessageClass] - NODE 1: SetSucNodeID node response.
2025-01-02 12:02:48.587 [DEBUG] [serialmessage.SetSucNodeMessageClass] - NODE 1: SetSucNodeID command OK.
2025-01-02 12:02:48.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 26: Advanced to WAIT_REQUEST
2025-01-02 12:02:48.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 26: Transaction not completed
2025-01-02 12:02:48.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-02 12:02:48.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-02 12:02:53.589 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 26: Timeout at state WAIT_REQUEST. 3 retries remaining.
2025-01-02 12:02:53.589 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 26: Transaction is current transaction, so clearing!!!!!
2025-01-02 12:02:53.590 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 26: Transaction CANCELLED
2025-01-02 12:02:53.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:26 CANCELLED
2025-01-02 12:02:53.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-02 12:02:53.591 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 01 BB 
2025-01-02 12:02:53.591 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 01 BB 
2025-01-02 12:02:53.596 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-02 12:02:53.596 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-02 12:02:53.597 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-02 12:02:53.597 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 01 41 00 00 00 03 00 00 00 B6 
2025-01-02 12:02:53.597 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2025-01-02 12:02:53.597 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-02 12:02:53.598 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-02 12:02:53.603 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-02 12:02:53.604 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 28: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:53.604 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-02 12:02:53.604 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=00 00 00 03 00 00 00 
2025-01-02 12:02:53.605 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=00 00 00 03 00 00 00 
2025-01-02 12:02:53.605 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 28: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:53.605 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-02 12:02:53.606 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 28: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:53.606 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=00 00 00 03 00 00 00 
2025-01-02 12:02:53.606 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: ProtocolInfo
2025-01-02 12:02:53.607 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Listening = false
2025-01-02 12:02:53.607 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Routing   = false
2025-01-02 12:02:53.607 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Beaming   = false
2025-01-02 12:02:53.607 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Version   = 1
2025-01-02 12:02:53.608 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: FLIRS     = false
2025-01-02 12:02:53.608 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Security  = false
2025-01-02 12:02:53.608 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Max Baud  = 9600
2025-01-02 12:02:53.608 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Basic    = BASIC_TYPE_SLAVE
2025-01-02 12:02:53.609 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Generic  = GENERIC_TYPE_NOT_USED
2025-01-02 12:02:53.609 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Specific = SPECIFIC_TYPE_NOT_USED
2025-01-02 12:02:53.609 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Creating new instance of command class COMMAND_CLASS_NO_OPERATION
2025-01-02 12:02:53.609 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created
2025-01-02 12:02:53.610 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Version = 1, version set. Enabling extra functionality.
2025-01-02 12:02:53.610 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 1: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes.
2025-01-02 12:02:53.610 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Creating new instance of command class COMMAND_CLASS_BASIC
2025-01-02 12:02:53.611 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_BASIC, endpoint 0 created
2025-01-02 12:02:53.611 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 1: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes.
2025-01-02 12:02:53.611 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 28: Transaction COMPLETED
2025-01-02 12:02:53.611 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 8ms
2025-01-02 12:02:53.612 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 28: Transaction completed
2025-01-02 12:02:53.612 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:28 DONE
2025-01-02 12:02:53.612 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-02 12:02:53.612 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 28: Transaction event listener: DONE: DONE -> UNINTIALIZED
2025-01-02 12:02:53.613 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-02 12:02:53.613 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@6c3745fb
2025-01-02 12:02:53.613 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 05 F9 
2025-01-02 12:02:53.613 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init transaction completed with response COMPLETE
2025-01-02 12:02:53.613 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 05 F9 
2025-01-02 12:02:53.614 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to REQUEST_NIF
2025-01-02 12:02:53.614 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@2935d619
2025-01-02 12:02:53.614 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: Bump transaction 29 priority from Controller to Immediate
2025-01-02 12:02:53.618 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-02 12:02:53.618 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-02 12:02:53.619 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 05 2C D3 
2025-01-02 12:02:53.623 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-02 12:02:53.623 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 27: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:53.624 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-02 12:02:53.624 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: Adding to device queue
2025-01-02 12:02:53.624 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=2C 
2025-01-02 12:02:53.624 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 27: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:53.624 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: Added 29 to queue - size 1
2025-01-02 12:02:53.624 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-02 12:02:53.625 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-02 12:02:53.625 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=2C 
2025-01-02 12:02:53.625 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 27: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:53.625 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-02 12:02:53.626 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 27: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-02 12:02:53.626 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=2C 
2025-01-02 12:02:53.626 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is secondary = false
2025-01-02 12:02:53.626 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is on other network = false
2025-01-02 12:02:53.627 [DEBUG] [etControllerCapabilitiesMessageClass] - Node ID Server is present = false
2025-01-02 12:02:53.627 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is real primary = true
2025-01-02 12:02:53.627 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is SUC = false
2025-01-02 12:02:53.627 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 27: Transaction COMPLETED
2025-01-02 12:02:53.628 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 5ms
2025-01-02 12:02:53.628 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 27: Transaction completed
2025-01-02 12:02:53.628 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:27 DONE
2025-01-02 12:02:53.628 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-02 12:02:53.629 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

BTW: Did the same procedure on the new/fresh Raspi5 setup with an Aeotec gen5 stick - this was working without problems. So seems to be related to the gen7 stick and the handling of the stick by the Z-Wave binding.

Thx for further ideas/hints/help,
Hubba

apella12 · January 2, 2025, 2:24pm

TBH I do not know why this is happening. It seems the controllers with SDK 7.21 and 7.22 seem to start with node 0 and the BaseThingHandler “checker” throws a warning that messes thing up. I have Zsticks that work fine with the earlier SDK 7.18 and 7.19. The binding resets the controller to node 1, but it is too late.

My theory with this suggestion is to hopefully bypass the BaseThingHandler warning and see if the binding can recover. Use this procedure (modified to put into the thing folder, not a subfolder) to overwrite this file.
controller_serial.xml (13.0 KB)
All I did was lower the minimum on the sis_node

            <parameter name="controller_sisnode" type="integer" groupName="network" min="0" max="232"> //changed min from 1 to 0
                <label>SIS Node</label>
                <description>Set node for SIS that will receive updates from other controllers in the network. If there is no SIS in the network, the controller will be set as SIS.</description>
                <default>1</default>
                <advanced>true</advanced>
            </parameter>

Will need to reset the zstick for a clean test. Let me know if this works.

EDIT: Think I found the problem and this isn’t it. I’m going to need to test, but currently it is an OH5 snapshot requiring Java21 and I’ll need a new controller, so could be a bit.

rlkoshak · January 2, 2025, 4:06pm

The issue I was referring to is in core and not specific to any individual binding. But it’s looking like that might not be relevant.

Hubbabubba · January 3, 2025, 10:31am

Did the adaption if the binding … without success.

The only thing which has been changed, the SIS node now is “0” in the UI thing parameter page once it got created manually and specified as “1” during creation of the controller thing.

The warning in the log doesn’t appear anymore, but still no XML file entry for the controller under /var/lib/openhab/zwave after the controller thing has been created in Openhab and is Online.

Thx,
Hubba

lsiepel · January 7, 2025, 9:34pm

I have similar issue:
in the log: controller_sisnode=The value must not be less than 1.
And it is actually set as 1.

The warnings comes from core.thing.binding.BaseThingHandler so @rlkoshak is probably right. I think you are referring to Fix config normalization in addon configuration by J-N-K · Pull Request #4528 · openhab/openhab-core · GitHub

apella12 · January 7, 2025, 10:57pm

I have been investigating and uncovered a problem with controllers that use the newest SDK 7.21 (700 chips) and SDK 7.22 (800 chips). They ship with 16-bit Node Ids enabled and the OH Zwave only supports 8 bits. I just finished some testing of a PR to revert back to 8 bits during initialization, but it hasn’t been reviewed and only tested by me. On one controller I used the Silabs PC controller to change the NodeId back to 8 bits after posting an issue with Silabs. I was going to do a write-up of that procedure, but wanted to get the PR out for review first.

EDIT @lsiepel don’t know if the above is your issue, but from @Hubbabubba log I can see that it is his.

apella12 · January 9, 2025, 2:08pm

I did create a guide here for the fix Zwave Z-stick SDK issue with OH Z-wave binding - Tutorials & Examples / Solutions - openHAB Community

Hubbabubba · January 9, 2025, 8:16pm

Thanks for that documented way - unfortunately doesnt work for me. (just to verify I sent “00 0B 80 01”)

After it doesnt work when I itried it I was reading the “Serial API Host Appl. Prg. Guid” from here - page 44 indicates that:

"Notice: The command is not persistent. Must be re-issued after a reset or power-cycle of the Serial API Controller. "

Since I have a Rasberry Pi running and only using the PC to do some maintenance of the Controller Sticks it probably gets set back once I unplug from PC and plug in the stick back in the raspberry to try it.

BUT, some lines above it is stated: “The 8 bits setting is the default (legacy) setting where the Node ID field is 1 byte wide…” so I am wondering.

The documentation is a bit outdated (2021) - could not find a newer one so far, maybe the default has been changed in future releases?

apella12 · January 9, 2025, 9:08pm

Thanks for trying, but I’m confused. Initially I believe I set in the PC and replugged into the Rpis, but I also did some testing in a WSL environment, so the stick may not have been unplugged. I definitely see the reversion to 16-bit with a reset. At this point I’ll have to go back and try that scenario.

The default 8-bit NodeIdType seems to have changed to 16-bit with SDK 7.21 and 7.22. 7.22 is the first 800 only SDK, so that makes some sense. The change to 16-bit for a 700 controller makes less sense because I didn’t think it had the dual frequency/power

Lately most of my testing lately was a modified OH5 snapshot binding that sets the 8-bit during startup. Could I see a debug ZWave snippet of a startup in a rpi? At this point I’ll have to go back and try that scenario explicitly. Thanks for the heads-up.

Edit: I did a first test on WSL, but the Zstick had been unplugged most of the day and the 8-bit was still active, so I’m not sure what is meant by power cycle. One other difference besides the WSL environment was after I reset to 8-bit, I copied the Rpi4 production network onto the stick (thinking I was done and was for backup), so it wasn’t completely blank. The difficulty of the Rpi test is that all my Rpis (3b, 4 and 5) have a production Zstick. Let me think about how to do a test.

Hubbabubba · January 9, 2025, 9:46pm

How this can be verified in the PC Controller Software itself? So I can verify that this is set and if it got resetted once I unplug and replug?

apella12 · January 9, 2025, 10:03pm

If the question is how to verify that 8-bit has been set use the zniffer output that you set up from the guidance document. Not an expert on the PC controller, but it appears once you hit OK there is a scan of the device. Then once the command is sent it appears later.

In the upper section (before setting the parameter) shows a 16-bit SUC node.

You could try to set, unplug the stick and get a new interview and (check the SUC node)
EDIT:. That might not be a good test. I ran through all the initial screens (14) and it was always 16-bit SUC, even the one that just worked in OH.

Hubbabubba · January 10, 2025, 7:07am

Here is the Debug Log.

What I did:

started Openhab (clean installation) without things and without node.xml file in /var/lib/openhab/zwave (7:34:xx)
changed Stick in Windows (Silabs PC-Controller-Software) as described to set NodeIDType to 8 bit
plugged in Stick in Raspberry
created controller thing manually in Openhab (7:38:xx)

2025-01-10 07:34:39.719 [INFO ] [org.openhab.core.Activator          ] - Starting openHAB 4.3.1 (Release Build)
2025-01-10 07:34:41.835 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Berlin'.
2025-01-10 07:34:41.842 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'de_DE'.
2025-01-10 07:34:43.688 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://192.168.100.106:8080/rest/events's Observer 
2025-01-10 07:34:45.823 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://192.168.100.106:8080/rest/events's Observer 
2025-01-10 07:34:49.846 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://192.168.100.106:8080/rest/events's Observer 
2025-01-10 07:35:10.784 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2025-01-10 07:35:18.288 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.
2025-01-10 07:35:22.198 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : BundleComponentActivator : ComponentHolder created.
2025-01-10 07:35:22.204 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : BundleComponentActivator : ComponentHolder created.
2025-01-10 07:35:22.217 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Dependency Manager created ConfigDescriptionRegistryinterface=org.openhab.core.config.core.ConfigDescriptionRegistry, filter=null, policy=static, cardinality=1..1, bind=setConfigDescriptionRegistry, unbind=unsetConfigDescriptionRegistry, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2025-01-10 07:35:22.225 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Dependency Manager created ThingRegistryinterface=org.openhab.core.thing.ThingRegistry, filter=null, policy=static, cardinality=1..1, bind=setThingRegistry, unbind=unsetThingRegistry, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2025-01-10 07:35:22.227 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Dependency Manager created ThingTypeRegistryinterface=org.openhab.core.thing.type.ThingTypeRegistry, filter=null, policy=static, cardinality=1..1, bind=setThingTypeRegistry, unbind=unsetThingTypeRegistry, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2025-01-10 07:35:22.234 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Dependency Manager created osgi.ds.satisfying.conditioninterface=org.osgi.service.condition.Condition, filter=(osgi.condition.id=true), policy=dynamic, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2025-01-10 07:35:22.241 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component created: DS=DS13, implementation=org.openhab.binding.zwave.internal.ZWaveConfigProvider, immediate=true, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[org.openhab.binding.zwave.internal.ZWaveConfigProvider]
2025-01-10 07:35:22.243 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component Services: scope=singleton, services=[org.openhab.core.config.core.ConfigDescriptionProvider, org.openhab.core.config.core.ConfigOptionProvider]
2025-01-10 07:35:22.252 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component Properties: {osgi.ds.satisfying.condition.target=(osgi.condition.id=true)}
2025-01-10 07:35:22.258 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Querying state disabled
2025-01-10 07:35:22.264 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Querying state disabled
2025-01-10 07:35:22.267 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Component can not be activated since it is in state disabled
2025-01-10 07:35:22.278 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider] : Querying state disabled
2025-01-10 07:35:22.285 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Updating target filters
2025-01-10 07:35:22.287 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : No change in target property for dependency ConfigDescriptionRegistry: currently registered: false
2025-01-10 07:35:22.295 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] :  No existing service listener to unregister for dependency ConfigDescriptionRegistry
2025-01-10 07:35:22.305 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Setting target property for dependency ConfigDescriptionRegistry to null
2025-01-10 07:35:22.311 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : New service tracker for ConfigDescriptionRegistry, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.config.core.ConfigDescriptionRegistry), initialReferenceFilter (objectClass=org.openhab.core.config.core.ConfigDescriptionRegistry)
2025-01-10 07:35:22.323 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : dm ConfigDescriptionRegistry tracker reset (closed)
2025-01-10 07:35:22.332 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : dm ConfigDescriptionRegistry tracking 1 SingleStatic added {org.openhab.core.config.core.ConfigDescriptionRegistry}={service.id=249, service.bundleid=168, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.config.core.ConfigDescriptionRegistry, component.id=116} (enter)
2025-01-10 07:35:22.344 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : dm ConfigDescriptionRegistry tracking 1 SingleStatic active: false trackerOpened: false optional: false
2025-01-10 07:35:22.351 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : dm ConfigDescriptionRegistry tracking 1 SingleStatic added {org.openhab.core.config.core.ConfigDescriptionRegistry}={service.id=249, service.bundleid=168, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.config.core.ConfigDescriptionRegistry, component.id=116} (exit)
2025-01-10 07:35:22.358 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : dm ConfigDescriptionRegistry tracker opened
2025-01-10 07:35:22.365 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : registering service listener for dependency ConfigDescriptionRegistry
2025-01-10 07:35:22.368 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : No change in target property for dependency ThingRegistry: currently registered: false
2025-01-10 07:35:22.378 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] :  No existing service listener to unregister for dependency ThingRegistry
2025-01-10 07:35:22.387 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Setting target property for dependency ThingRegistry to null
2025-01-10 07:35:22.389 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : New service tracker for ThingRegistry, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.thing.ThingRegistry), initialReferenceFilter (objectClass=org.openhab.core.thing.ThingRegistry)
2025-01-10 07:35:22.392 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : dm ThingRegistry tracker reset (closed)
2025-01-10 07:35:22.408 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : dm ThingRegistry tracking 2 SingleStatic added {org.openhab.core.thing.ThingRegistry}={service.id=395, service.bundleid=221, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.thing.internal.ThingRegistryImpl, component.id=269} (enter)
2025-01-10 07:35:22.419 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : dm ThingRegistry tracking 2 SingleStatic active: false trackerOpened: false optional: false
2025-01-10 07:35:22.429 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : dm ThingRegistry tracking 2 SingleStatic added {org.openhab.core.thing.ThingRegistry}={service.id=395, service.bundleid=221, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.thing.internal.ThingRegistryImpl, component.id=269} (exit)
2025-01-10 07:35:22.435 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : dm ThingRegistry tracker opened
2025-01-10 07:35:22.445 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : registering service listener for dependency ThingRegistry
2025-01-10 07:35:22.447 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : No change in target property for dependency ThingTypeRegistry: currently registered: false
2025-01-10 07:35:22.464 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] :  No existing service listener to unregister for dependency ThingTypeRegistry
2025-01-10 07:35:22.473 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Setting target property for dependency ThingTypeRegistry to null
2025-01-10 07:35:22.475 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : New service tracker for ThingTypeRegistry, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.thing.type.ThingTypeRegistry), initialReferenceFilter (objectClass=org.openhab.core.thing.type.ThingTypeRegistry)
2025-01-10 07:35:22.482 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : dm ThingTypeRegistry tracker reset (closed)
2025-01-10 07:35:22.491 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : dm ThingTypeRegistry tracking 3 SingleStatic added {org.openhab.core.thing.type.ThingTypeRegistry}={service.id=428, service.bundleid=221, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.thing.type.ThingTypeRegistry, component.id=285} (enter)
2025-01-10 07:35:22.499 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : dm ThingTypeRegistry tracking 3 SingleStatic active: false trackerOpened: false optional: false
2025-01-10 07:35:22.507 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : dm ThingTypeRegistry tracking 3 SingleStatic added {org.openhab.core.thing.type.ThingTypeRegistry}={service.id=428, service.bundleid=221, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.thing.type.ThingTypeRegistry, component.id=285} (exit)
2025-01-10 07:35:22.514 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : dm ThingTypeRegistry tracker opened
2025-01-10 07:35:22.520 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : registering service listener for dependency ThingTypeRegistry
2025-01-10 07:35:22.529 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] :  No existing service listener to unregister for dependency osgi.ds.satisfying.condition
2025-01-10 07:35:22.542 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Setting target property for dependency osgi.ds.satisfying.condition to (osgi.condition.id=true)
2025-01-10 07:35:22.547 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : New service tracker for osgi.ds.satisfying.condition, initial active: false, previous references: {}, classFilter: (objectClass=org.osgi.service.condition.Condition), initialReferenceFilter (&(objectClass=org.osgi.service.condition.Condition)(osgi.condition.id=true))
2025-01-10 07:35:22.555 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : dm osgi.ds.satisfying.condition tracker reset (closed)
2025-01-10 07:35:22.568 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : dm osgi.ds.satisfying.condition tracking 4 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (enter)
2025-01-10 07:35:22.576 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : dm osgi.ds.satisfying.condition tracking 4 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (exit)
2025-01-10 07:35:22.583 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : dm osgi.ds.satisfying.condition tracker opened
2025-01-10 07:35:22.587 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : registering service listener for dependency osgi.ds.satisfying.condition
2025-01-10 07:35:22.597 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Changed state from disabled to unsatisfiedReference
2025-01-10 07:35:22.599 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Component enabled
2025-01-10 07:35:22.606 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : ActivateInternal
2025-01-10 07:35:22.608 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Querying state unsatisfiedReference
2025-01-10 07:35:22.621 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Querying state unsatisfiedReference
2025-01-10 07:35:22.625 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Activating component from state unsatisfiedReference
2025-01-10 07:35:22.633 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Querying state unsatisfiedReference
2025-01-10 07:35:22.635 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Querying state unsatisfiedReference
2025-01-10 07:35:22.641 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Changed state from unsatisfiedReference to satisfied
2025-01-10 07:35:22.651 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : registration change queue [registered]
2025-01-10 07:35:22.715 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Checking constructor public org.openhab.binding.zwave.internal.ZWaveConfigProvider()
2025-01-10 07:35:22.729 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Found constructor with 0 arguments : public org.openhab.binding.zwave.internal.ZWaveConfigProvider()
2025-01-10 07:35:22.734 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : getting bind: setConfigDescriptionRegistry
2025-01-10 07:35:22.744 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Locating method setConfigDescriptionRegistry in class org.openhab.binding.zwave.internal.ZWaveConfigProvider
2025-01-10 07:35:22.753 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry
2025-01-10 07:35:22.786 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry([interface org.osgi.framework.ServiceReference]) not found
2025-01-10 07:35:22.800 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry([interface org.osgi.service.component.ComponentServiceObjects]) not found
2025-01-10 07:35:22.813 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : getClassFromComponentClassLoader: Looking for interface class org.openhab.core.config.core.ConfigDescriptionRegistry through loader of org.openhab.binding.zwave.internal.ZWaveConfigProvider
2025-01-10 07:35:22.815 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : getClassFromComponentClassLoader: Found class org.openhab.core.config.core.ConfigDescriptionRegistry
2025-01-10 07:35:22.844 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.config.core.ConfigDescriptionRegistry
2025-01-10 07:35:22.847 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry(org.openhab.core.config.core.ConfigDescriptionRegistry)
2025-01-10 07:35:22.862 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setConfigDescriptionRegistry(org.openhab.core.config.core.ConfigDescriptionRegistry)
2025-01-10 07:35:22.872 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : getting bind: setThingRegistry
2025-01-10 07:35:22.885 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Locating method setThingRegistry in class org.openhab.binding.zwave.internal.ZWaveConfigProvider
2025-01-10 07:35:22.887 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry
2025-01-10 07:35:22.902 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry([interface org.osgi.framework.ServiceReference]) not found
2025-01-10 07:35:22.910 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry([interface org.osgi.service.component.ComponentServiceObjects]) not found
2025-01-10 07:35:22.912 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : getClassFromComponentClassLoader: Looking for interface class org.openhab.core.thing.ThingRegistry through loader of org.openhab.binding.zwave.internal.ZWaveConfigProvider
2025-01-10 07:35:22.926 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : getClassFromComponentClassLoader: Found class org.openhab.core.thing.ThingRegistry
2025-01-10 07:35:22.928 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.thing.ThingRegistry
2025-01-10 07:35:22.949 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry(org.openhab.core.thing.ThingRegistry)
2025-01-10 07:35:22.952 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingRegistry(org.openhab.core.thing.ThingRegistry)
2025-01-10 07:35:22.970 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : getting bind: setThingTypeRegistry
2025-01-10 07:35:22.981 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Locating method setThingTypeRegistry in class org.openhab.binding.zwave.internal.ZWaveConfigProvider
2025-01-10 07:35:22.983 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry
2025-01-10 07:35:22.996 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry([interface org.osgi.framework.ServiceReference]) not found
2025-01-10 07:35:23.002 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry([interface org.osgi.service.component.ComponentServiceObjects]) not found
2025-01-10 07:35:23.012 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : getClassFromComponentClassLoader: Looking for interface class org.openhab.core.thing.type.ThingTypeRegistry through loader of org.openhab.binding.zwave.internal.ZWaveConfigProvider
2025-01-10 07:35:23.015 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : getClassFromComponentClassLoader: Found class org.openhab.core.thing.type.ThingTypeRegistry
2025-01-10 07:35:23.025 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.thing.type.ThingTypeRegistry
2025-01-10 07:35:23.028 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry(org.openhab.core.thing.type.ThingTypeRegistry)
2025-01-10 07:35:23.041 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveConfigProvider.setThingTypeRegistry(org.openhab.core.thing.type.ThingTypeRegistry)
2025-01-10 07:35:23.044 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : This thread collected dependencies
2025-01-10 07:35:23.059 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : getService (single component manager) dependencies collected.
2025-01-10 07:35:23.065 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Querying state satisfied
2025-01-10 07:35:23.067 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Querying state satisfied
2025-01-10 07:35:23.074 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : For dependency ConfigDescriptionRegistry, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.config.core.ConfigDescriptionRegistry}={service.id=249, service.bundleid=168, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.config.core.ConfigDescriptionRegistry, component.id=116}] service: [org.openhab.core.config.core.ConfigDescriptionRegistry@1a16a3e8]]]
2025-01-10 07:35:23.081 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : For dependency ThingRegistry, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.thing.ThingRegistry}={service.id=395, service.bundleid=221, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.thing.internal.ThingRegistryImpl, component.id=269}] service: [org.openhab.core.thing.internal.ThingRegistryImpl@2fce2cc2]]]
2025-01-10 07:35:23.083 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : For dependency ThingTypeRegistry, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.thing.type.ThingTypeRegistry}={service.id=428, service.bundleid=221, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.thing.type.ThingTypeRegistry, component.id=285}] service: [org.openhab.core.thing.type.ThingTypeRegistry@10cc6300]]]
2025-01-10 07:35:23.090 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : For dependency osgi.ds.satisfying.condition, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
2025-01-10 07:35:23.297 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : invoking bind: setConfigDescriptionRegistry: parameters [org.openhab.core.config.core.ConfigDescriptionRegistry]
2025-01-10 07:35:23.299 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : invoked bind: setConfigDescriptionRegistry
2025-01-10 07:35:23.303 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : invoking bind: setThingRegistry: parameters [org.openhab.core.thing.internal.ThingRegistryImpl]
2025-01-10 07:35:23.307 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : invoked bind: setThingRegistry
2025-01-10 07:35:23.309 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : invoking bind: setThingTypeRegistry: parameters [org.openhab.core.thing.type.ThingTypeRegistry]
2025-01-10 07:35:23.311 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : invoked bind: setThingTypeRegistry
2025-01-10 07:35:23.337 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : getting activate: activate
2025-01-10 07:35:23.339 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Locating method activate in class org.openhab.binding.zwave.internal.ZWaveConfigProvider
2025-01-10 07:35:23.341 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Declared Method org.openhab.binding.zwave.internal.ZWaveConfigProvider.activate([interface org.osgi.service.component.ComponentContext]) not found
2025-01-10 07:35:23.344 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Locating method activate in class java.lang.Object
2025-01-10 07:35:23.347 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
2025-01-10 07:35:23.352 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : activate method [activate] not found, ignoring
2025-01-10 07:35:23.354 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Set implementation object for component
2025-01-10 07:35:23.360 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveConfigProvider(339)] : Changed state from satisfied to active
2025-01-10 07:35:23.364 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Dependency Manager created SerialPortManagerinterface=org.openhab.core.io.transport.serial.SerialPortManager, filter=null, policy=static, cardinality=1..1, bind=setSerialPortManager, unbind=unsetSerialPortManager, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2025-01-10 07:35:23.370 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Dependency Manager created osgi.ds.satisfying.conditioninterface=org.osgi.service.condition.Condition, filter=(osgi.condition.id=true), policy=dynamic, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2025-01-10 07:35:23.372 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component created: DS=DS13, implementation=org.openhab.binding.zwave.internal.ZWaveHandlerFactory, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[org.openhab.binding.zwave.internal.ZWaveHandlerFactory]
2025-01-10 07:35:23.379 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component Services: scope=singleton, services=[org.openhab.core.thing.binding.ThingHandlerFactory]
2025-01-10 07:35:23.386 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component Properties: {osgi.ds.satisfying.condition.target=(osgi.condition.id=true)}
2025-01-10 07:35:23.392 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Querying state disabled
2025-01-10 07:35:23.395 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Querying state disabled
2025-01-10 07:35:23.401 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Component can not be activated since it is in state disabled
2025-01-10 07:35:23.403 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory] : Querying state disabled
2025-01-10 07:35:23.410 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Updating target filters
2025-01-10 07:35:23.416 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : No change in target property for dependency SerialPortManager: currently registered: false
2025-01-10 07:35:23.419 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] :  No existing service listener to unregister for dependency SerialPortManager
2025-01-10 07:35:23.425 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Setting target property for dependency SerialPortManager to null
2025-01-10 07:35:23.428 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : New service tracker for SerialPortManager, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.io.transport.serial.SerialPortManager), initialReferenceFilter (objectClass=org.openhab.core.io.transport.serial.SerialPortManager)
2025-01-10 07:35:23.434 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : dm SerialPortManager tracker reset (closed)
2025-01-10 07:35:23.442 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : dm SerialPortManager tracking 1 SingleStatic added {org.openhab.core.io.transport.serial.SerialPortManager}={service.id=504, service.bundleid=262, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=333} (enter)
2025-01-10 07:35:23.450 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : dm SerialPortManager tracking 1 SingleStatic active: false trackerOpened: false optional: false
2025-01-10 07:35:23.457 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : dm SerialPortManager tracking 1 SingleStatic added {org.openhab.core.io.transport.serial.SerialPortManager}={service.id=504, service.bundleid=262, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=333} (exit)
2025-01-10 07:35:23.459 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : dm SerialPortManager tracker opened
2025-01-10 07:35:23.465 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : registering service listener for dependency SerialPortManager
2025-01-10 07:35:23.468 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] :  No existing service listener to unregister for dependency osgi.ds.satisfying.condition
2025-01-10 07:35:23.474 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Setting target property for dependency osgi.ds.satisfying.condition to (osgi.condition.id=true)
2025-01-10 07:35:23.475 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : New service tracker for osgi.ds.satisfying.condition, initial active: false, previous references: {}, classFilter: (objectClass=org.osgi.service.condition.Condition), initialReferenceFilter (&(objectClass=org.osgi.service.condition.Condition)(osgi.condition.id=true))
2025-01-10 07:35:23.481 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : dm osgi.ds.satisfying.condition tracker reset (closed)
2025-01-10 07:35:23.483 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : dm osgi.ds.satisfying.condition tracking 2 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (enter)
2025-01-10 07:35:23.490 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : dm osgi.ds.satisfying.condition tracking 2 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (exit)
2025-01-10 07:35:23.492 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : dm osgi.ds.satisfying.condition tracker opened
2025-01-10 07:35:23.497 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : registering service listener for dependency osgi.ds.satisfying.condition
2025-01-10 07:35:23.499 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Changed state from disabled to unsatisfiedReference
2025-01-10 07:35:23.505 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Component enabled
2025-01-10 07:35:23.507 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : ActivateInternal
2025-01-10 07:35:23.509 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Querying state unsatisfiedReference
2025-01-10 07:35:23.512 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Querying state unsatisfiedReference
2025-01-10 07:35:23.513 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Activating component from state unsatisfiedReference
2025-01-10 07:35:23.515 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Querying state unsatisfiedReference
2025-01-10 07:35:23.517 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Querying state unsatisfiedReference
2025-01-10 07:35:23.519 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Changed state from unsatisfiedReference to satisfied
2025-01-10 07:35:23.521 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : registration change queue [registered]
2025-01-10 07:35:23.543 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Checking constructor public org.openhab.binding.zwave.internal.ZWaveHandlerFactory()
2025-01-10 07:35:23.545 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Found constructor with 0 arguments : public org.openhab.binding.zwave.internal.ZWaveHandlerFactory()
2025-01-10 07:35:23.547 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : getting bind: setSerialPortManager
2025-01-10 07:35:23.549 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Locating method setSerialPortManager in class org.openhab.binding.zwave.internal.ZWaveHandlerFactory
2025-01-10 07:35:23.551 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : doFindMethod: Looking for method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager
2025-01-10 07:35:23.553 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Declared Method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager([interface org.osgi.framework.ServiceReference]) not found
2025-01-10 07:35:23.554 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Declared Method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager([interface org.osgi.service.component.ComponentServiceObjects]) not found
2025-01-10 07:35:23.556 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : getClassFromComponentClassLoader: Looking for interface class org.openhab.core.io.transport.serial.SerialPortManager through loader of org.openhab.binding.zwave.internal.ZWaveHandlerFactory
2025-01-10 07:35:23.558 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : getClassFromComponentClassLoader: Found class org.openhab.core.io.transport.serial.SerialPortManager
2025-01-10 07:35:23.559 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.core.io.transport.serial.SerialPortManager
2025-01-10 07:35:23.561 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : doFindMethod: Found Method protected void org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager(org.openhab.core.io.transport.serial.SerialPortManager)
2025-01-10 07:35:23.563 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Found bind method: protected void org.openhab.binding.zwave.internal.ZWaveHandlerFactory.setSerialPortManager(org.openhab.core.io.transport.serial.SerialPortManager)
2025-01-10 07:35:23.564 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : This thread collected dependencies
2025-01-10 07:35:23.566 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : getService (single component manager) dependencies collected.
2025-01-10 07:35:23.568 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Querying state satisfied
2025-01-10 07:35:23.570 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Querying state satisfied
2025-01-10 07:35:23.572 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : For dependency SerialPortManager, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.io.transport.serial.SerialPortManager}={service.id=504, service.bundleid=262, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=333}] service: [org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl@63c18e9e]]]
2025-01-10 07:35:23.575 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : For dependency osgi.ds.satisfying.condition, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
2025-01-10 07:35:23.578 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : invoking bind: setSerialPortManager: parameters [org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl]
2025-01-10 07:35:23.580 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : invoked bind: setSerialPortManager
2025-01-10 07:35:23.582 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : getting activate: activate
2025-01-10 07:35:23.584 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Locating method activate in class org.openhab.binding.zwave.internal.ZWaveHandlerFactory
2025-01-10 07:35:23.587 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Declared Method org.openhab.binding.zwave.internal.ZWaveHandlerFactory.activate([interface org.osgi.service.component.ComponentContext]) not found
2025-01-10 07:35:23.591 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Locating method activate in class org.openhab.core.thing.binding.BaseThingHandlerFactory
2025-01-10 07:35:23.594 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Found activate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.activate(org.osgi.service.component.ComponentContext)
2025-01-10 07:35:23.597 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl]
2025-01-10 07:35:23.601 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : invoked activate: activate
2025-01-10 07:35:23.603 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Set implementation object for component
2025-01-10 07:35:23.606 [DEBUG] [g.zwave.internal.ZWaveHandlerFactory] - bundle org.openhab.binding.zwave:4.3.1 (266)[org.openhab.binding.zwave.internal.ZWaveHandlerFactory(340)] : Changed state from satisfied to active
2025-01-10 07:38:33.744 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No thing found in getConfigDescription thing:zwave:serial_zstick:09110f9b8f
2025-01-10 07:38:33.975 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:09110f9b8f with scan time of 60
2025-01-10 07:38:33.978 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:09110f9b8f
2025-01-10 07:38:33.980 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2025-01-10 07:38:34.072 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2025-01-10 07:38:34.074 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:09110f9b8f.
2025-01-10 07:38:34.076 [DEBUG] [zwave.handler.ZWaveControllerHandler] - No network key set by user - using random value.
2025-01-10 07:38:39.205 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyUSB0'
2025-01-10 07:38:39.238 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
2025-01-10 07:38:39.245 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
2025-01-10 07:38:39.246 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2025-01-10 07:38:39.249 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
2025-01-10 07:38:39.285 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2025-01-10 07:38:39.285 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:38:39.288 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2025-01-10 07:38:39.288 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:38:39.292 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2025-01-10 07:38:39.294 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2025-01-10 07:38:39.298 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 19 hours time.
2025-01-10 07:38:42.292 [DEBUG] [.ZWaveController$InitializeDelayTask] - Initialising network
2025-01-10 07:38:42.300 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 0 to queue - size 1
2025-01-10 07:38:42.302 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:38:42.306 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 15 E9 
2025-01-10 07:38:42.308 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2025-01-10 07:38:42.311 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-10 07:38:42.315 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-10 07:38:42.317 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:38:42.318 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:38:42.320 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2025-01-10 07:38:42.320 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 01 15 5A 2D 57 61 76 65 20 37 2E 32 31 00 07 94 
2025-01-10 07:38:42.322 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-10 07:38:42.323 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:38:42.329 [DEBUG] [nal.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 37 2E 32 31 00 07 
2025-01-10 07:38:42.341 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.343 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:38:42.345 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 1 to queue - size 1
2025-01-10 07:38:42.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetVersion[21], type=Response[1], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 37 2E 32 31 00 07 
2025-01-10 07:38:42.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:38:42.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-10 07:38:42.351 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.353 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 2 to queue - size 2
2025-01-10 07:38:42.353 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetVersion[21], type=Response[1], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 37 2E 32 31 00 07 
2025-01-10 07:38:42.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:38:42.357 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 3 to queue - size 3
2025-01-10 07:38:42.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:38:42.362 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - Get SUC NodeID
2025-01-10 07:38:42.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 4 to queue - size 4
2025-01-10 07:38:42.366 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:38:42.372 [DEBUG] [serialmessage.GetVersionMessageClass] - Got MessageGetVersion response. Version=Z-Wave 7.21, Library Type=7
2025-01-10 07:38:42.374 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 0: Transaction COMPLETED
2025-01-10 07:38:42.375 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 63ms
2025-01-10 07:38:42.377 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 0: Transaction completed
2025-01-10 07:38:42.379 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:0 DONE
2025-01-10 07:38:42.384 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:38:42.385 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:38:42.387 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 20 DC 
2025-01-10 07:38:42.389 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2025-01-10 07:38:42.395 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-10 07:38:42.397 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:38:42.397 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-10 07:38:42.398 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.399 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 01 20 D0 DA 0B 3A 01 EC 
2025-01-10 07:38:42.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:38:42.401 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.402 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-10 07:38:42.404 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:38:42.405 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:38:42.407 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=D0 DA 0B 3A 01 
2025-01-10 07:38:42.409 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=D0 DA 0B 3A 01 
2025-01-10 07:38:42.410 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.411 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-10 07:38:42.413 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.414 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=D0 DA 0B 3A 01 
2025-01-10 07:38:42.416 [DEBUG] [erialmessage.MemoryGetIdMessageClass] - Got MessageMemoryGetId response. Home id = 0xd0da0b3a, Controller Node id = 1
2025-01-10 07:38:42.417 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1: Transaction COMPLETED
2025-01-10 07:38:42.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 20ms
2025-01-10 07:38:42.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 1: Transaction completed
2025-01-10 07:38:42.420 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:1 DONE
2025-01-10 07:38:42.422 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:38:42.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:38:42.424 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 07 FB 
2025-01-10 07:38:42.426 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2025-01-10 07:38:42.429 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-10 07:38:42.430 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.434 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-10 07:38:42.435 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:38:42.437 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:38:42.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.439 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-10 07:38:42.440 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 2B 01 07 07 15 00 00 00 04 00 04 F6 87 3E 88 CF 2B C0 4F FB D7 FD E0 97 00 00 80 00 80 86 80 BA 05 00 70 00 00 EE 7F C0 00 00 00 52 
2025-01-10 07:38:42.440 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:38:42.441 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:38:42.449 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=07 15 00 00 00 04 00 04 F6 87 3E 88 CF 2B C0 4F FB D7 FD E0 97 00 00 80 00 80 86 80 BA 05 00 70 00 00 EE 7F C0 00 00 00 
2025-01-10 07:38:42.452 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=07 15 00 00 00 04 00 04 F6 87 3E 88 CF 2B C0 4F FB D7 FD E0 97 00 00 80 00 80 86 80 BA 05 00 70 00 00 EE 7F C0 00 00 00 
2025-01-10 07:38:42.454 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-10 07:38:42.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.460 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=07 15 00 00 00 04 00 04 F6 87 3E 88 CF 2B C0 4F FB D7 FD E0 97 00 00 80 00 80 86 80 BA 05 00 70 00 00 EE 7F C0 00 00 00 
2025-01-10 07:38:42.462 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - API Version    = 7.21
2025-01-10 07:38:42.463 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Manufacture ID = 0x0
2025-01-10 07:38:42.464 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Device Type    = 0x4
2025-01-10 07:38:42.465 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Device ID      = 0x4
2025-01-10 07:38:42.467 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2: Transaction COMPLETED
2025-01-10 07:38:42.469 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 5 to queue - size 3
2025-01-10 07:38:42.470 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:38:42.471 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 41ms
2025-01-10 07:38:42.472 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 2: Transaction completed
2025-01-10 07:38:42.473 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2 DONE
2025-01-10 07:38:42.474 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:38:42.475 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:38:42.477 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 06 96 0F 65 
2025-01-10 07:38:42.478 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2025-01-10 07:38:42.481 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-10 07:38:42.482 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.484 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-10 07:38:42.485 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:38:42.486 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:38:42.487 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 01 06 96 0F 64 
2025-01-10 07:38:42.488 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.489 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-10 07:38:42.490 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:38:42.491 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 
2025-01-10 07:38:42.492 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:38:42.493 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 
2025-01-10 07:38:42.494 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.495 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-10 07:38:42.496 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.497 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 
2025-01-10 07:38:42.498 [DEBUG] [age.SerialApiSetTimeoutsMessageClass] - Got SerialApiSetTimeouts response. ACK=150, BYTE=15
2025-01-10 07:38:42.500 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 3: Transaction COMPLETED
2025-01-10 07:38:42.501 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 18ms
2025-01-10 07:38:42.502 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 3: Transaction completed
2025-01-10 07:38:42.503 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:3 DONE
2025-01-10 07:38:42.504 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:38:42.505 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:38:42.506 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 56 AA 
2025-01-10 07:38:42.508 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2025-01-10 07:38:42.512 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-10 07:38:42.513 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.513 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-10 07:38:42.515 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:38:42.516 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:38:42.517 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 56 00 AC 
2025-01-10 07:38:42.517 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.518 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-10 07:38:42.519 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:38:42.520 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:38:42.521 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=00 
2025-01-10 07:38:42.522 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=00 
2025-01-10 07:38:42.523 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.524 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-10 07:38:42.525 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.526 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=00 
2025-01-10 07:38:42.528 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - Got SUC NodeID response.
2025-01-10 07:38:42.529 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - No SUC Node is set
2025-01-10 07:38:42.530 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 4: Transaction COMPLETED
2025-01-10 07:38:42.531 [DEBUG] [ve.internal.protocol.ZWaveController] - SUC was not set as required - currently 0, requires 1
2025-01-10 07:38:42.532 [DEBUG] [serialmessage.SetSucNodeMessageClass] - NODE 1: SetSucNodeID node true
2025-01-10 07:38:42.534 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 6 to queue - size 2
2025-01-10 07:38:42.535 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:38:42.536 [DEBUG] [etControllerCapabilitiesMessageClass] - Creating GET_CONTROLLER_CAPABILITIES message
2025-01-10 07:38:42.538 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 7 to queue - size 3
2025-01-10 07:38:42.539 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:38:42.540 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 27ms
2025-01-10 07:38:42.541 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 4: Transaction completed
2025-01-10 07:38:42.542 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:4 DONE
2025-01-10 07:38:42.543 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:38:42.544 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:38:42.546 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 02 FE 
2025-01-10 07:38:42.547 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 02 FE 
2025-01-10 07:38:42.556 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-10 07:38:42.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:38:42.558 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-10 07:38:42.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:38:42.561 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 25 01 02 0A 00 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 07 00 C8 
2025-01-10 07:38:42.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-10 07:38:42.564 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:38:42.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:38:42.569 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=0A 00 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 07 00 
2025-01-10 07:38:42.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=0A 00 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 07 00 
2025-01-10 07:38:42.573 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.574 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-10 07:38:42.575 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:42.577 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=0A 00 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 07 00 
2025-01-10 07:38:42.579 [DEBUG] [age.SerialApiGetInitDataMessageClass] - Got MessageSerialApiGetInitData response.
2025-01-10 07:38:42.580 [DEBUG] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2025-01-10 07:38:42.581 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2025-01-10 07:38:42.582 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2025-01-10 07:38:42.583 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2025-01-10 07:38:42.584 [DEBUG] [age.SerialApiGetInitDataMessageClass] - # Nodes = 1
2025-01-10 07:38:42.585 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2025-01-10 07:38:42.586 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 5: Transaction COMPLETED
2025-01-10 07:38:42.591 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 1: Init node thread start
2025-01-10 07:38:42.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 33ms
2025-01-10 07:38:42.592 [DEBUG] [ve.internal.protocol.ZWaveController] - Starting waiting for init threads
2025-01-10 07:38:42.594 [DEBUG] [ve.internal.protocol.ZWaveController] - Waiting for init thread Node_1_init
2025-01-10 07:38:42.594 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 5: Transaction completed
2025-01-10 07:38:42.595 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:5 DONE
2025-01-10 07:38:42.597 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:38:42.599 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:38:42.601 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 54 01 01 00 01 01 A3 
2025-01-10 07:38:42.603 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 08 00 54 01 01 00 01 01 A3 
2025-01-10 07:38:42.606 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-10 07:38:42.608 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 1
2025-01-10 07:38:42.609 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-10 07:38:42.611 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:38:42.613 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:38:42.613 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 54 01 AF 
2025-01-10 07:38:42.615 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 1
2025-01-10 07:38:42.616 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-10 07:38:42.617 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SetSucNodeID[84], type=Response[1], dest=255, callback=0, payload=01 
2025-01-10 07:38:42.618 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:38:42.619 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:38:42.621 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SetSucNodeID[84], type=Response[1], dest=255, callback=0, payload=01 
2025-01-10 07:38:42.622 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 1
2025-01-10 07:38:42.624 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-10 07:38:42.625 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 1
2025-01-10 07:38:42.627 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SetSucNodeID[84], type=Response[1], dest=255, callback=0, payload=01 
2025-01-10 07:38:42.628 [DEBUG] [serialmessage.SetSucNodeMessageClass] - NODE 1: SetSucNodeID node response.
2025-01-10 07:38:42.629 [DEBUG] [serialmessage.SetSucNodeMessageClass] - NODE 1: SetSucNodeID command OK.
2025-01-10 07:38:42.631 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 6: Advanced to WAIT_REQUEST
2025-01-10 07:38:42.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 6: Transaction not completed
2025-01-10 07:38:42.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:38:42.634 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:38:42.750 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 1: Serializing from file /var/lib/openhab/zwave/network_d0da0b3a__node_1.xml
2025-01-10 07:38:42.751 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 1: Error serializing from file: file does not exist.
2025-01-10 07:38:42.778 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Starting initialisation from EMPTYNODE
2025-01-10 07:38:42.782 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 1: Init node thread finished
2025-01-10 07:38:42.782 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to IDENTIFY_NODE
2025-01-10 07:38:42.783 [DEBUG] [ve.internal.protocol.ZWaveController] - Init thread Node_1_init complete
2025-01-10 07:38:42.783 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer: Initialisation starting
2025-01-10 07:38:42.785 [DEBUG] [ve.internal.protocol.ZWaveController] - All init threads complete
2025-01-10 07:38:42.785 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@2a4bb021
2025-01-10 07:38:42.786 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller: Incoming Network State Event true
2025-01-10 07:38:42.790 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 8 to queue - size 1
2025-01-10 07:38:42.792 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:38:42.798 [WARN ] [.core.thing.binding.BaseThingHandler] - Attempt to apply invalid configuration 'Configuration[{key=controller_softreset; type=Boolean; value=false}, {key=security_networkkey; type=String; value=63 62 EF 8D 73 61 16 7A 84 6E 58 B7 64 2D DB 0E}, {key=security_inclusionmode; type=BigDecimal; value=2}, {key=controller_sisnode; type=BigDecimal; value=0}, {key=controller_maxawakeperiod; type=BigDecimal; value=10}, {key=controller_sync; type=Boolean; value=false}, {key=port; type=String; value=/dev/ttyUSB0}, {key=controller_master; type=Boolean; value=true}, {key=inclusion_mode; type=BigDecimal; value=2}, {key=controller_wakeupperiod; type=BigDecimal; value=3600}, {key=heal_time; type=BigDecimal; value=2}, {key=controller_exclude; type=Boolean; value=false}, {key=controller_inclusiontimeout; type=BigDecimal; value=30}, {key=controller_hardreset; type=Boolean; value=false}]' on thing 'zwave:serial_zstick:09110f9b8f' blocked. This is most likely a bug: {controller_sisnode=The value must not be less than 1.}
2025-01-10 07:38:47.633 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 6: Timeout at state WAIT_REQUEST. 3 retries remaining.
2025-01-10 07:38:47.636 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 6: Transaction is current transaction, so clearing!!!!!
2025-01-10 07:38:47.638 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 6: Transaction CANCELLED
2025-01-10 07:38:47.640 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:6 CANCELLED
2025-01-10 07:38:47.643 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:38:47.646 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 01 BB 
2025-01-10 07:38:47.649 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 01 BB 
2025-01-10 07:38:47.654 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-10 07:38:47.656 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 8: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:47.656 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-10 07:38:47.658 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:38:47.660 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:38:47.662 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 01 41 D3 96 01 02 02 01 00 F0 
2025-01-10 07:38:47.662 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 8: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:47.664 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-10 07:38:47.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:38:47.668 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:38:47.668 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 96 01 02 02 01 00 
2025-01-10 07:38:47.671 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 96 01 02 02 01 00 
2025-01-10 07:38:47.673 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 8: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:47.674 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-10 07:38:47.676 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 8: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:47.679 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=D3 96 01 02 02 01 00 
2025-01-10 07:38:47.681 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: ProtocolInfo
2025-01-10 07:38:47.683 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Listening = true
2025-01-10 07:38:47.685 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Routing   = true
2025-01-10 07:38:47.687 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Beaming   = true
2025-01-10 07:38:47.688 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Version   = 4
2025-01-10 07:38:47.690 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: FLIRS     = false
2025-01-10 07:38:47.692 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Security  = false
2025-01-10 07:38:47.694 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Max Baud  = 40000
2025-01-10 07:38:47.696 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Basic    = BASIC_TYPE_STATIC_CONTROLLER
2025-01-10 07:38:47.698 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Generic  = GENERIC_TYPE_STATIC_CONTROLLER
2025-01-10 07:38:47.700 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Specific = SPECIFIC_TYPE_PC_CONTROLLER
2025-01-10 07:38:47.703 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Creating new instance of command class COMMAND_CLASS_NO_OPERATION
2025-01-10 07:38:47.707 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created
2025-01-10 07:38:47.709 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Version = 1, version set. Enabling extra functionality.
2025-01-10 07:38:47.711 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 1: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes.
2025-01-10 07:38:47.713 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Creating new instance of command class COMMAND_CLASS_BASIC
2025-01-10 07:38:47.723 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_BASIC, endpoint 0 created
2025-01-10 07:38:47.725 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 1: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes.
2025-01-10 07:38:47.727 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 8: Transaction COMPLETED
2025-01-10 07:38:47.729 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 73ms
2025-01-10 07:38:47.731 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 8: Transaction completed
2025-01-10 07:38:47.733 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:8 DONE
2025-01-10 07:38:47.736 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:38:47.737 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 8: Transaction event listener: DONE: DONE -> UNINTIALIZED
2025-01-10 07:38:47.739 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:38:47.742 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 05 F9 
2025-01-10 07:38:47.743 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@55a18391
2025-01-10 07:38:47.745 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 05 F9 
2025-01-10 07:38:47.746 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init transaction completed with response COMPLETE
2025-01-10 07:38:47.748 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer: FAILED_CHECK - Controller - terminating initialisation
2025-01-10 07:38:47.750 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to DONE
2025-01-10 07:38:47.751 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-10 07:38:47.752 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 1: Serializing to file /var/lib/openhab/zwave/network_d0da0b3a__node_1.xml
2025-01-10 07:38:47.753 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:38:47.753 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-10 07:38:47.755 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:47.755 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 05 3C C3 
2025-01-10 07:38:47.757 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:38:47.758 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=3C 
2025-01-10 07:38:47.758 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:47.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-10 07:38:47.761 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=3C 
2025-01-10 07:38:47.763 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:47.764 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-10 07:38:47.765 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:38:47.767 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=3C 
2025-01-10 07:38:47.769 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is secondary = false
2025-01-10 07:38:47.770 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is on other network = false
2025-01-10 07:38:47.771 [DEBUG] [etControllerCapabilitiesMessageClass] - Node ID Server is present = false
2025-01-10 07:38:47.773 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is real primary = true
2025-01-10 07:38:47.774 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is SUC = true
2025-01-10 07:38:47.776 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 7: Transaction COMPLETED
2025-01-10 07:38:47.777 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 23ms
2025-01-10 07:38:47.779 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 7: Transaction completed
2025-01-10 07:38:47.780 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:7 DONE
2025-01-10 07:38:47.782 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:38:47.783 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

The warning is still there. But the node.xml file has been created this time. But it is not working … tried to add a new thing (inclusion) afterwards but this doesn’t work.

Hubbabubba · January 10, 2025, 7:08am

To verify I did the same steps again with a fresh resetted stick:

started Openhab (clean installation) without things and without node.xml file in /var/lib/openhab/zwave
resetted Stick in Windows (Silabs PC-Controller-Software)
plugged in Stick in Raspberry
created controller thing manually in Openhab

2025-01-10 07:56:22.350 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:a257a75725 with scan time of 60
2025-01-10 07:56:22.352 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:a257a75725
2025-01-10 07:56:22.359 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2025-01-10 07:56:22.450 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2025-01-10 07:56:22.452 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:a257a75725.
2025-01-10 07:56:22.455 [DEBUG] [zwave.handler.ZWaveControllerHandler] - No network key set by user - using random value.
2025-01-10 07:56:27.574 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyUSB0'
2025-01-10 07:56:27.613 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
2025-01-10 07:56:27.617 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
2025-01-10 07:56:27.619 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2025-01-10 07:56:27.620 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
2025-01-10 07:56:27.645 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2025-01-10 07:56:27.645 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:56:27.647 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:56:27.647 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2025-01-10 07:56:27.649 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2025-01-10 07:56:27.650 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2025-01-10 07:56:27.652 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 19 hours time.
2025-01-10 07:56:30.649 [DEBUG] [.ZWaveController$InitializeDelayTask] - Initialising network
2025-01-10 07:56:30.657 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 0 to queue - size 1
2025-01-10 07:56:30.659 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:56:30.663 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 15 E9 
2025-01-10 07:56:30.665 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2025-01-10 07:56:30.667 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-10 07:56:30.671 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-10 07:56:30.673 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:56:30.677 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 01 15 5A 2D 57 61 76 65 20 37 2E 32 31 00 07 94 
2025-01-10 07:56:30.678 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:56:30.679 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2025-01-10 07:56:30.681 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-10 07:56:30.683 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:56:30.688 [DEBUG] [nal.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 37 2E 32 31 00 07 
2025-01-10 07:56:30.701 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.704 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:56:30.706 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 1 to queue - size 1
2025-01-10 07:56:30.707 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetVersion[21], type=Response[1], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 37 2E 32 31 00 07 
2025-01-10 07:56:30.708 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:56:30.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.710 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-10 07:56:30.712 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.714 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 2 to queue - size 2
2025-01-10 07:56:30.714 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetVersion[21], type=Response[1], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 37 2E 32 31 00 07 
2025-01-10 07:56:30.715 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:56:30.718 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 3 to queue - size 3
2025-01-10 07:56:30.720 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:56:30.722 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - Get SUC NodeID
2025-01-10 07:56:30.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 4 to queue - size 4
2025-01-10 07:56:30.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:56:30.732 [DEBUG] [serialmessage.GetVersionMessageClass] - Got MessageGetVersion response. Version=Z-Wave 7.21, Library Type=7
2025-01-10 07:56:30.733 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 0: Transaction COMPLETED
2025-01-10 07:56:30.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 67ms
2025-01-10 07:56:30.737 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 0: Transaction completed
2025-01-10 07:56:30.739 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:0 DONE
2025-01-10 07:56:30.742 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:56:30.743 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:56:30.745 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 20 DC 
2025-01-10 07:56:30.746 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2025-01-10 07:56:30.750 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-10 07:56:30.751 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.752 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-10 07:56:30.753 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:56:30.755 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:56:30.756 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 20 C6 3F B9 4C 00 01 DA 
2025-01-10 07:56:30.756 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.757 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-10 07:56:30.759 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:56:30.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:56:30.762 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=C6 3F B9 4C 00 01 
2025-01-10 07:56:30.764 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=C6 3F B9 4C 00 01 
2025-01-10 07:56:30.766 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.767 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-10 07:56:30.768 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.769 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=C6 3F B9 4C 00 01 
2025-01-10 07:56:30.770 [DEBUG] [erialmessage.MemoryGetIdMessageClass] - Got MessageMemoryGetId response. Home id = 0xc63fb94c, Controller Node id = 0
2025-01-10 07:56:30.771 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1: Transaction COMPLETED
2025-01-10 07:56:30.772 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 21ms
2025-01-10 07:56:30.773 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 1: Transaction completed
2025-01-10 07:56:30.774 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:1 DONE
2025-01-10 07:56:30.775 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:56:30.777 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:56:30.778 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 07 FB 
2025-01-10 07:56:30.779 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2025-01-10 07:56:30.782 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-10 07:56:30.783 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.788 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-10 07:56:30.789 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:56:30.790 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:56:30.792 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.793 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-10 07:56:30.794 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 2B 01 07 07 15 00 00 00 04 00 04 F6 87 3E 88 CF 2B C0 4F FB D7 FD E0 97 00 00 80 00 80 86 80 BA 05 00 70 00 00 EE 7F C0 00 00 00 52 
2025-01-10 07:56:30.794 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:56:30.796 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:56:30.803 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=07 15 00 00 00 04 00 04 F6 87 3E 88 CF 2B C0 4F FB D7 FD E0 97 00 00 80 00 80 86 80 BA 05 00 70 00 00 EE 7F C0 00 00 00 
2025-01-10 07:56:30.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=07 15 00 00 00 04 00 04 F6 87 3E 88 CF 2B C0 4F FB D7 FD E0 97 00 00 80 00 80 86 80 BA 05 00 70 00 00 EE 7F C0 00 00 00 
2025-01-10 07:56:30.808 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.809 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-10 07:56:30.810 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.813 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=07 15 00 00 00 04 00 04 F6 87 3E 88 CF 2B C0 4F FB D7 FD E0 97 00 00 80 00 80 86 80 BA 05 00 70 00 00 EE 7F C0 00 00 00 
2025-01-10 07:56:30.814 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - API Version    = 7.21
2025-01-10 07:56:30.815 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Manufacture ID = 0x0
2025-01-10 07:56:30.816 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Device Type    = 0x4
2025-01-10 07:56:30.817 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Device ID      = 0x4
2025-01-10 07:56:30.818 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2: Transaction COMPLETED
2025-01-10 07:56:30.820 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 5 to queue - size 3
2025-01-10 07:56:30.822 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:56:30.823 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 40ms
2025-01-10 07:56:30.824 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 2: Transaction completed
2025-01-10 07:56:30.825 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2 DONE
2025-01-10 07:56:30.827 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:56:30.828 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:56:30.829 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 06 96 0F 65 
2025-01-10 07:56:30.830 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2025-01-10 07:56:30.833 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-10 07:56:30.834 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.836 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-10 07:56:30.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:56:30.838 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:56:30.839 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 01 06 96 0F 64 
2025-01-10 07:56:30.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-10 07:56:30.842 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:56:30.843 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:56:30.843 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 
2025-01-10 07:56:30.844 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 
2025-01-10 07:56:30.846 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.847 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-10 07:56:30.848 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.849 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 
2025-01-10 07:56:30.850 [DEBUG] [age.SerialApiSetTimeoutsMessageClass] - Got SerialApiSetTimeouts response. ACK=150, BYTE=15
2025-01-10 07:56:30.851 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 3: Transaction COMPLETED
2025-01-10 07:56:30.852 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 18ms
2025-01-10 07:56:30.853 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 3: Transaction completed
2025-01-10 07:56:30.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:3 DONE
2025-01-10 07:56:30.855 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:56:30.856 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:56:30.857 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 56 AA 
2025-01-10 07:56:30.859 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2025-01-10 07:56:30.862 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-10 07:56:30.863 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.864 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-10 07:56:30.865 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:56:30.866 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:56:30.867 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 01 56 00 00 AD 
2025-01-10 07:56:30.868 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.869 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-10 07:56:30.870 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:56:30.871 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=00 00 
2025-01-10 07:56:30.871 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:56:30.872 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=00 00 
2025-01-10 07:56:30.873 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.874 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-10 07:56:30.875 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.877 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=00 00 
2025-01-10 07:56:30.878 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - Got SUC NodeID response.
2025-01-10 07:56:30.879 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - No SUC Node is set
2025-01-10 07:56:30.880 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 4: Transaction COMPLETED
2025-01-10 07:56:30.881 [DEBUG] [ve.internal.protocol.ZWaveController] - SUC was not set as required - currently 0, requires 1
2025-01-10 07:56:30.882 [DEBUG] [serialmessage.SetSucNodeMessageClass] - NODE 1: SetSucNodeID node true
2025-01-10 07:56:30.883 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 6 to queue - size 2
2025-01-10 07:56:30.884 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:56:30.886 [DEBUG] [etControllerCapabilitiesMessageClass] - Creating GET_CONTROLLER_CAPABILITIES message
2025-01-10 07:56:30.887 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 7 to queue - size 3
2025-01-10 07:56:30.888 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:56:30.889 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 27ms
2025-01-10 07:56:30.890 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 4: Transaction completed
2025-01-10 07:56:30.891 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:4 DONE
2025-01-10 07:56:30.892 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:56:30.894 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:56:30.895 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 02 FE 
2025-01-10 07:56:30.896 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 02 FE 
2025-01-10 07:56:30.899 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-10 07:56:30.900 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.905 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-10 07:56:30.906 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:56:30.907 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:56:30.908 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.909 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-10 07:56:30.910 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 25 01 02 0A 00 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 07 00 C8 
2025-01-10 07:56:30.910 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:56:30.911 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:56:30.918 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=0A 00 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 07 00 
2025-01-10 07:56:30.921 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=0A 00 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 07 00 
2025-01-10 07:56:30.922 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.923 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-10 07:56:30.924 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 5: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:30.926 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiGetInitData[2], type=Response[1], dest=255, callback=0, payload=0A 00 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 07 00 
2025-01-10 07:56:30.927 [DEBUG] [age.SerialApiGetInitDataMessageClass] - Got MessageSerialApiGetInitData response.
2025-01-10 07:56:30.928 [DEBUG] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2025-01-10 07:56:30.930 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2025-01-10 07:56:30.931 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2025-01-10 07:56:30.932 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2025-01-10 07:56:30.933 [DEBUG] [age.SerialApiGetInitDataMessageClass] - # Nodes = 1
2025-01-10 07:56:30.934 [DEBUG] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2025-01-10 07:56:30.935 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 5: Transaction COMPLETED
2025-01-10 07:56:30.939 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 1: Init node thread start
2025-01-10 07:56:30.941 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 40ms
2025-01-10 07:56:30.941 [DEBUG] [ve.internal.protocol.ZWaveController] - Starting waiting for init threads
2025-01-10 07:56:30.942 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 5: Transaction completed
2025-01-10 07:56:30.942 [DEBUG] [ve.internal.protocol.ZWaveController] - Waiting for init thread Node_1_init
2025-01-10 07:56:30.943 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:5 DONE
2025-01-10 07:56:30.945 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:56:30.947 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:56:30.949 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 54 01 01 00 01 01 A3 
2025-01-10 07:56:30.951 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 08 00 54 01 01 00 01 01 A3 
2025-01-10 07:56:30.956 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-10 07:56:30.957 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 1
2025-01-10 07:56:30.958 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-10 07:56:30.960 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:56:30.962 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:56:30.962 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 54 01 AF 
2025-01-10 07:56:30.963 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 1
2025-01-10 07:56:30.965 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-10 07:56:30.966 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:56:30.968 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:56:30.969 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SetSucNodeID[84], type=Response[1], dest=255, callback=0, payload=01 
2025-01-10 07:56:30.971 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SetSucNodeID[84], type=Response[1], dest=255, callback=0, payload=01 
2025-01-10 07:56:30.972 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 1
2025-01-10 07:56:30.973 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-10 07:56:30.975 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 1
2025-01-10 07:56:30.976 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SetSucNodeID[84], type=Response[1], dest=255, callback=0, payload=01 
2025-01-10 07:56:30.978 [DEBUG] [serialmessage.SetSucNodeMessageClass] - NODE 1: SetSucNodeID node response.
2025-01-10 07:56:30.979 [DEBUG] [serialmessage.SetSucNodeMessageClass] - NODE 1: SetSucNodeID command OK.
2025-01-10 07:56:30.980 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 6: Advanced to WAIT_REQUEST
2025-01-10 07:56:30.981 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 6: Transaction not completed
2025-01-10 07:56:30.983 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:56:30.984 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:56:31.092 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 1: Serializing from file /var/lib/openhab/zwave/network_c63fb94c__node_1.xml
2025-01-10 07:56:31.093 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 1: Error serializing from file: file does not exist.
2025-01-10 07:56:31.118 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Starting initialisation from EMPTYNODE
2025-01-10 07:56:31.122 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 1: Init node thread finished
2025-01-10 07:56:31.122 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to IDENTIFY_NODE
2025-01-10 07:56:31.123 [DEBUG] [ve.internal.protocol.ZWaveController] - Init thread Node_1_init complete
2025-01-10 07:56:31.123 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer: Initialisation starting
2025-01-10 07:56:31.125 [DEBUG] [ve.internal.protocol.ZWaveController] - All init threads complete
2025-01-10 07:56:31.126 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@205d9927
2025-01-10 07:56:31.126 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller: Incoming Network State Event true
2025-01-10 07:56:31.138 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 8 to queue - size 1
2025-01-10 07:56:31.139 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:56:31.142 [WARN ] [.core.thing.binding.BaseThingHandler] - Attempt to apply invalid configuration 'Configuration[{key=controller_softreset; type=Boolean; value=false}, {key=security_networkkey; type=String; value=72 D2 82 38 E3 1B 25 ED E7 D0 14 5D B4 50 06 90}, {key=security_inclusionmode; type=BigDecimal; value=2}, {key=controller_sisnode; type=BigDecimal; value=0}, {key=controller_maxawakeperiod; type=BigDecimal; value=10}, {key=controller_sync; type=Boolean; value=false}, {key=port; type=String; value=/dev/ttyUSB0}, {key=controller_master; type=Boolean; value=true}, {key=inclusion_mode; type=BigDecimal; value=2}, {key=controller_wakeupperiod; type=BigDecimal; value=3600}, {key=heal_time; type=BigDecimal; value=2}, {key=controller_exclude; type=Boolean; value=false}, {key=controller_inclusiontimeout; type=BigDecimal; value=30}, {key=controller_hardreset; type=Boolean; value=false}]' on thing 'zwave:serial_zstick:a257a75725' blocked. This is most likely a bug: {controller_sisnode=The value must not be less than 1.}
2025-01-10 07:56:35.982 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 6: Timeout at state WAIT_REQUEST. 3 retries remaining.
2025-01-10 07:56:35.984 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 6: Transaction is current transaction, so clearing!!!!!
2025-01-10 07:56:35.986 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 6: Transaction CANCELLED
2025-01-10 07:56:35.988 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:6 CANCELLED
2025-01-10 07:56:35.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:56:35.995 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 01 BB 
2025-01-10 07:56:35.997 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 01 BB 
2025-01-10 07:56:36.005 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-10 07:56:36.006 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-10 07:56:36.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:56:36.008 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 8: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:36.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:56:36.012 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 01 41 00 00 00 03 00 00 00 B6 
2025-01-10 07:56:36.014 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 8: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:36.017 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-10 07:56:36.018 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=00 00 00 03 00 00 00 
2025-01-10 07:56:36.018 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:56:36.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:56:36.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=00 00 00 03 00 00 00 
2025-01-10 07:56:36.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 8: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:36.026 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-10 07:56:36.028 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 8: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:36.030 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IdentifyNode[65], type=Response[1], dest=255, callback=0, payload=00 00 00 03 00 00 00 
2025-01-10 07:56:36.032 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: ProtocolInfo
2025-01-10 07:56:36.034 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Listening = false
2025-01-10 07:56:36.035 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Routing   = false
2025-01-10 07:56:36.037 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Beaming   = false
2025-01-10 07:56:36.038 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Version   = 1
2025-01-10 07:56:36.040 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: FLIRS     = false
2025-01-10 07:56:36.041 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Security  = false
2025-01-10 07:56:36.043 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Max Baud  = 9600
2025-01-10 07:56:36.045 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Basic    = BASIC_TYPE_SLAVE
2025-01-10 07:56:36.047 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Generic  = GENERIC_TYPE_NOT_USED
2025-01-10 07:56:36.049 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 1: Specific = SPECIFIC_TYPE_NOT_USED
2025-01-10 07:56:36.051 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Creating new instance of command class COMMAND_CLASS_NO_OPERATION
2025-01-10 07:56:36.054 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created
2025-01-10 07:56:36.056 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Version = 1, version set. Enabling extra functionality.
2025-01-10 07:56:36.058 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 1: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes.
2025-01-10 07:56:36.060 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Creating new instance of command class COMMAND_CLASS_BASIC
2025-01-10 07:56:36.068 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 1: Command class COMMAND_CLASS_BASIC, endpoint 0 created
2025-01-10 07:56:36.069 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 1: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes.
2025-01-10 07:56:36.071 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 8: Transaction COMPLETED
2025-01-10 07:56:36.072 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 64ms
2025-01-10 07:56:36.074 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 8: Transaction completed
2025-01-10 07:56:36.075 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:8 DONE
2025-01-10 07:56:36.077 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:56:36.078 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 8: Transaction event listener: DONE: DONE -> UNINTIALIZED
2025-01-10 07:56:36.079 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2025-01-10 07:56:36.082 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@64d2fba6
2025-01-10 07:56:36.083 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init transaction completed with response COMPLETE
2025-01-10 07:56:36.084 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 05 F9 
2025-01-10 07:56:36.086 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 05 F9 
2025-01-10 07:56:36.086 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to REQUEST_NIF
2025-01-10 07:56:36.088 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@caa8210
2025-01-10 07:56:36.090 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: Bump transaction 9 priority from Controller to Immediate
2025-01-10 07:56:36.090 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2025-01-10 07:56:36.092 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:36.092 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2025-01-10 07:56:36.094 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:56:36.094 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: Adding to device queue
2025-01-10 07:56:36.096 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: Added 9 to queue - size 1
2025-01-10 07:56:36.096 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2025-01-10 07:56:36.097 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 05 2C D3 
2025-01-10 07:56:36.098 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:36.098 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:56:36.099 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2025-01-10 07:56:36.101 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:56:36.103 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2025-01-10 07:56:36.104 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=2C 
2025-01-10 07:56:36.106 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=2C 
2025-01-10 07:56:36.107 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:36.109 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2025-01-10 07:56:36.110 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 7: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2025-01-10 07:56:36.112 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetControllerCapabilities[5], type=Response[1], dest=255, callback=0, payload=2C 
2025-01-10 07:56:36.114 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is secondary = false
2025-01-10 07:56:36.115 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is on other network = false
2025-01-10 07:56:36.116 [DEBUG] [etControllerCapabilitiesMessageClass] - Node ID Server is present = false
2025-01-10 07:56:36.117 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is real primary = true
2025-01-10 07:56:36.118 [DEBUG] [etControllerCapabilitiesMessageClass] - Controller is SUC = false
2025-01-10 07:56:36.119 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 7: Transaction COMPLETED
2025-01-10 07:56:36.120 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 28ms
2025-01-10 07:56:36.121 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 7: Transaction completed
2025-01-10 07:56:36.122 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:7 DONE
2025-01-10 07:56:36.123 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2025-01-10 07:56:36.124 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

This time the node.xml files doesn’t got created so there seems to be a difference between the resetted stick (2nd try) and the adapted stick (nodeID Type to 8 Bit) (1st try).

apella12 · January 10, 2025, 12:15pm

Thanks for the info.
Ok try 1 has 8-bit NodeID, try 2 is back to 16-bit.
The good news is this shows the reset will hold, but a reset reverts to 16-bit

As to inclusion fail, did you exclude first? The device still might be paired with something.

It turns out the WARN message is not critical, but distracted me from finding the real problem. It appears that the SetSUC command with SDK 7.21 doesn’t return the callback OH expects (and the prior Specs require) if the node sending the command is the one being set as SUC. The best way to clear is after Zstick reset in the PC Controller, use set as SIS then change to 8-bit, then OH.

Based on your earlier post I developed a plan to test in my Rpi3b, but it was too late last night. From todays post i’ll also test inclusion.

EDIT: All worked; Outline: reset controller with SDK 7.21, set Node 1 as SIS, issue 8-bit message per guide, unplug from PC controller, plug into new OH docker container in Rpi3b running OH 4.3.1 (previously added Zwave binding to avoid extra logging), set Zwave logs to Debug, created bridge, xml created. Excluded device (Dome-Dmms1) battery sensor, Included ok xml created.

Only glitch for me was the battery sensor stopped short of full inclusion on the initial scan, but with two re-wakes was fully configured. That is not atypical for a battery device. In reviewing logs, the device failed to respond to a controller command and timed out.
2025-01-10 08:26:43.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Transaction failed waiting for REQUEST, assume sleeping device.
IMO not controller related.

Hubbabubba · January 10, 2025, 9:21pm

Hi,

now I setup a clean new Openhabian on the Raspi again. Did exactly your order of adapting the Z-Stick with Silabs PC-Controller-Software on the PC:

Reset the stick
Set as SIS Node
Switched to 8bit NodeID Type

Plugged the Stick from PC into Raspberry.

What should I say, this time it worked flawlessy, even without warning.

Also the inclusion of a new thing worked and this new thing (Switch) can be controlled via UI.
So all seems fine now.

Don’t know what I did wrong in the previous attempt, maybe something was still in cache or not excluded completely like you assumed.

On the weekend I will try to migrate my existing production system to Z-Stick gen7, lets see how this will work then. I will let you know.

Thanks for all your efforts and investigation on this,
Hubba.

Hubbabubba · January 11, 2025, 11:08am

That way also the migration of my “production” system worked from Aeotec gen5 to Aeotec gen7

With Silabs PC-Controller-Software on the PC:

1. Reset the Aeotec gen7 stick

With a HomeAssistant instance:

1. Perform a NVM Backup of the Aeotec gen5 stick
1. Perform a NVM Restore on the Aeotec gen7 stick

With Silabs PC-Controller-Software on the PC for Aeotec gen7 stick:

1. Set as SIS Node
1. Switched to 8bit NodeID Type

In Openhab on Raspberry:

1. After deletion of Aeotec gen5 Bridge-Thing created new Bridge with same UID than the Aeotec gen5 was

That was working fine, most of the things came back online. But not all and some things switched back and force between Online and Offline. Network was very unresponsiveness.

Need to investigate if this is still the known issue with 700er firmware or this migration path is just not working or I need to wait for some more time until network gets sorted again.
But at least the Aeotec gen7 stick works with Openhab in principal

apella12 · January 11, 2025, 1:03pm

I don’t know if the HA (Zwave-js) guys have resolved the issues of nvm compatibility between SDK 6.x and SDK7.x, but it used to be a problem. May need to ask on their forum. I wrote this for the OH community a year ago.
Transitioning a network from 500 chip.pdf (235.8 KB)