Problem with Fibaro Double Switch in OpenHab3

Jjordan · June 12, 2022, 11:31pm

Problems with Fibaro Double Switch in OH3

Platform information:
- Hardware: PC
- OS: Windows11
- Java Runtime Environment: openjdk version “11.0.12”
- openHAB version: 3.2.0

Hello. I’m having a strange issue with my FIbaro Double Switch 223.
The switch is connected directly to a light switch. When I toggle the light switch manually, I can turn on and off the light and I can also receive state updates in OH3 UI.
However, when I send the command from OH3 to change the state, the command is ignored. The OH3 toggle switches ON and then back OFF in a couple of seconds.
If I launch the OH2 on the same PC with same hardware then everything works fine.
I captured ZWAve logs and hope somebody can shed some light of what is going on. Note the Node35 below

2022-06-12 19:04:05.133 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Command received zwave:device:466d9b93a7:node35:switch_binary1 --> ON [OnOffType]
2022-06-12 19:04:05.133 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 35: Creating new message for application command SWITCH_BINARY_SET
2022-06-12 19:04:05.133 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Encapsulating message, instance / endpoint 1
2022-06-12 19:04:05.133 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 35: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2022-06-12 19:04:05.134 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
2022-06-12 19:04:05.134 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2022-06-12 19:04:05.134 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Adding to device queue
2022-06-12 19:04:05.134 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Added 272 to queue - size 1
2022-06-12 19:04:05.134 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-06-12 19:04:05.134 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 13 23 07 60 0D 01 01 25 01 FF 25 DD 88 
2022-06-12 19:04:05.134 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 35: Sending REQUEST Message = 01 0E 00 13 23 07 60 0D 01 01 25 01 FF 25 DD 88 
2022-06-12 19:04:05.136 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2022-06-12 19:04:05.136 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 272: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 221
2022-06-12 19:04:05.136 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Polling initialised at 1800 seconds - start in 15000 milliseconds.
2022-06-12 19:04:07.137 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 35: TID 272: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2022-06-12 19:04:07.137 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2022-06-12 19:04:07.137 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 272: Transaction ABORTED
2022-06-12 19:04:07.137 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2022-06-12 19:04:07.137 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2022-06-12 19:04:07.139 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2022-06-12 19:04:07.139 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-06-12 19:04:07.139 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-06-12 19:04:07.139 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 272: [ABORTED] priority=Set, requiresResponse=true, callback: 221
2022-06-12 19:04:07.139 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2022-06-12 19:04:07.139 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-12 19:04:07.139 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2022-06-12 19:04:07.139 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-12 19:04:07.139 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-12 19:04:18.037 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 1A 0E 32 02 21 44 00 00 04 82 01 2D 00 00 04 82 82 
2022-06-12 19:04:18.038 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=26, callback=0, payload=00 1A 0E 32 02 21 44 00 00 04 82 01 2D 00 00 04 82 
2022-06-12 19:04:18.038 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=26, callback=0, payload=00 1A 0E 32 02 21 44 00 00 04 82 01 2D 00 00 04 82 
2022-06-12 19:04:18.038 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 272: [ABORTED] priority=Set, requiresResponse=true, callback: 221
2022-06-12 19:04:18.038 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Application Command Request (ALIVE:DONE)
2022-06-12 19:04:18.038 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: resetResendCount initComplete=true isDead=false
2022-06-12 19:04:18.038 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: Incoming command class COMMAND_CLASS_METER, endpoint 0
2022-06-12 19:04:18.038 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: SECURITY not supported
2022-06-12 19:04:18.038 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 26: Received COMMAND_CLASS_METER V3 METER_REPORT
2022-06-12 19:04:18.039 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 26: Meter: Type=Electric(1), Scale=kWh(0), Value=11.54
2022-06-12 19:04:18.039 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Got an event from Z-Wave network: ZWaveMeterValueEvent
2022-06-12 19:04:18.039 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=11.54
2022-06-12 19:04:18.039 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Updating channel state zwave:device:466d9b93a7:node26:meter_kwh to 11.54 [DecimalType]
2022-06-12 19:04:18.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Commands processed 1.
2022-06-12 19:04:18.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@2de25cec.
2022-06-12 19:04:18.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2022-06-12 19:04:18.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2022-06-12 19:04:18.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-12 19:04:18.039 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-12 19:04:19.027 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 1A 0E 32 02 21 54 00 00 00 00 01 2D 00 00 00 00 92 
2022-06-12 19:04:19.028 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=26, callback=0, payload=00 1A 0E 32 02 21 54 00 00 00 00 01 2D 00 00 00 00 
2022-06-12 19:04:19.028 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=26, callback=0, payload=00 1A 0E 32 02 21 54 00 00 00 00 01 2D 00 00 00 00 
2022-06-12 19:04:19.028 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 272: [ABORTED] priority=Set, requiresResponse=true, callback: 221
2022-06-12 19:04:19.028 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Application Command Request (ALIVE:DONE)
2022-06-12 19:04:19.028 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: resetResendCount initComplete=true isDead=false
2022-06-12 19:04:19.028 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: Incoming command class COMMAND_CLASS_METER, endpoint 0
2022-06-12 19:04:19.028 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: SECURITY not supported
2022-06-12 19:04:19.028 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 26: Received COMMAND_CLASS_METER V3 METER_REPORT
2022-06-12 19:04:19.028 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 26: Meter: Type=Electric(1), Scale=W(2), Value=0E+1
2022-06-12 19:04:19.028 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Got an event from Z-Wave network: ZWaveMeterValueEvent
2022-06-12 19:04:19.028 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=0E+1
2022-06-12 19:04:19.028 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Updating channel state zwave:device:466d9b93a7:node26:meter_watts to 0 [DecimalType]
2022-06-12 19:04:19.029 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Commands processed 1.
2022-06-12 19:04:19.029 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@337efe46.
2022-06-12 19:04:19.029 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2022-06-12 19:04:19.029 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2022-06-12 19:04:19.029 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-12 19:04:19.029 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-12 19:04:19.138 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 35: TID 272: Timeout at state ABORTED. 3 retries remaining.
2022-06-12 19:04:19.138 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 272: Transaction is current transaction, so clearing!!!!!
2022-06-12 19:04:19.138 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 272: Transaction CANCELLED
2022-06-12 19:04:19.138 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2022-06-12 19:04:19.138 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: notifyTransactionResponse TID:272 CANCELLED
2022-06-12 19:04:19.138 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-06-12 19:04:20.024 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 1A 0A 32 02 A1 42 2F 65 01 2D 2F 49 28 
2022-06-12 19:04:20.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=26, callback=0, payload=00 1A 0A 32 02 A1 42 2F 65 01 2D 2F 49 
2022-06-12 19:04:20.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=26, callback=0, payload=00 1A 0A 32 02 A1 42 2F 65 01 2D 2F 49 
2022-06-12 19:04:20.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2022-06-12 19:04:20.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Application Command Request (ALIVE:DONE)
2022-06-12 19:04:20.025 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: resetResendCount initComplete=true isDead=false
2022-06-12 19:04:20.025 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: Incoming command class COMMAND_CLASS_METER, endpoint 0
2022-06-12 19:04:20.025 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: SECURITY not supported
2022-06-12 19:04:20.025 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 26: Received COMMAND_CLASS_METER V3 METER_REPORT
2022-06-12 19:04:20.025 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 26: Meter: Type=Electric(1), Scale=V(4), Value=121.33
2022-06-12 19:04:20.025 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Got an event from Z-Wave network: ZWaveMeterValueEvent
2022-06-12 19:04:20.025 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=121.33
2022-06-12 19:04:20.025 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Updating channel state zwave:device:466d9b93a7:node26:meter_voltage to 121.33 [DecimalType]
2022-06-12 19:04:20.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Commands processed 1.
2022-06-12 19:04:20.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@702f609e.
2022-06-12 19:04:20.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2022-06-12 19:04:20.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2022-06-12 19:04:20.026 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-12 19:04:20.026 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-06-12 19:04:20.138 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Polling...
2022-06-12 19:04:20.173 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Polling zwave:device:466d9b93a7:node35:switch_binary1
2022-06-12 19:04:20.173 [DEBUG] [converter.ZWaveBinarySwitchConverter] - NODE 35: Generating poll message for COMMAND_CLASS_SWITCH_BINARY, endpoint 1
2022-06-12 19:04:20.173 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 35: Creating new message for application command SWITCH_BINARY_GET
2022-06-12 19:04:20.173 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Encapsulating message, instance / endpoint 1
2022-06-12 19:04:20.173 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 35: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2022-06-12 19:04:20.173 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
2022-06-12 19:04:20.174 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2022-06-12 19:04:20.174 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Polling skipped for zwave:device:466d9b93a7:node35:switch_binary1 on COMMAND_CLASS_BASIC
2022-06-12 19:04:20.174 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Polling zwave:device:466d9b93a7:node35:switch_binary2
2022-06-12 19:04:20.174 [DEBUG] [converter.ZWaveBinarySwitchConverter] - NODE 35: Generating poll message for COMMAND_CLASS_SWITCH_BINARY, endpoint 2
2022-06-12 19:04:20.174 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 35: Creating new message for application command SWITCH_BINARY_GET
2022-06-12 19:04:20.174 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Encapsulating message, instance / endpoint 2
2022-06-12 19:04:20.174 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 35: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 2
2022-06-12 19:04:20.174 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
2022-06-12 19:04:20.174 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2022-06-12 19:04:20.174 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Polling skipped for zwave:device:466d9b93a7:node35:switch_binary2 on COMMAND_CLASS_BASIC
2022-06-12 19:04:20.174 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Adding to device queue
2022-06-12 19:04:20.174 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Added 273 to queue - size 1
2022-06-12 19:04:20.174 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-06-12 19:04:20.174 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 23 06 60 0D 01 01 25 02 25 DE 75 
2022-06-12 19:04:20.174 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 35: Sending REQUEST Message = 01 0D 00 13 23 06 60 0D 01 01 25 02 25 DE 75 
2022-06-12 19:04:20.176 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2022-06-12 19:04:20.176 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 273: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 222
2022-06-12 19:04:20.176 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Adding to device queue
2022-06-12 19:04:20.176 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Added 274 to queue - size 1
2022-06-12 19:04:20.177 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2022-06-12 19:04:20.177 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-06-12 19:04:20.177 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-06-12 19:04:20.177 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 273: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 222
2022-06-12 19:04:20.177 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2022-06-12 19:04:20.177 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-12 19:04:20.178 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-12 19:04:20.178 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-12 19:04:20.182 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2022-06-12 19:04:20.183 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2022-06-12 19:04:20.183 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2022-06-12 19:04:20.183 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 273: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 222
2022-06-12 19:04:20.183 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2022-06-12 19:04:20.183 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 273: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 222
2022-06-12 19:04:20.183 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2022-06-12 19:04:20.186 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 35: sentData successfully placed on stack.
2022-06-12 19:04:20.186 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 273: Advanced to WAIT_REQUEST
2022-06-12 19:04:20.186 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: TID 273: Transaction not completed
2022-06-12 19:04:20.186 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-12 19:04:20.186 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-12 19:04:20.263 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 DE 00 00 08 3D 
2022-06-12 19:04:20.264 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=222, payload=DE 00 00 08 
2022-06-12 19:04:20.264 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=222, payload=DE 00 00 08 
2022-06-12 19:04:20.264 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 273: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 222
2022-06-12 19:04:20.264 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2022-06-12 19:04:20.264 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 273: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 222
2022-06-12 19:04:20.264 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 273: (Callback 222)
2022-06-12 19:04:20.265 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2022-06-12 19:04:20.265 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 273: callback 222
2022-06-12 19:04:20.265 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=222, payload=DE 00 00 08 
2022-06-12 19:04:20.265 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 35: SendData Request. CallBack ID = 222, Status = Transmission complete and ACK received(0)
2022-06-12 19:04:20.265 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: resetResendCount initComplete=true isDead=false
2022-06-12 19:04:20.265 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 273: Advanced to WAIT_DATA
2022-06-12 19:04:20.265 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: TID 273: Transaction not completed
2022-06-12 19:04:20.265 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-12 19:04:20.266 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-12 19:04:20.347 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 23 07 60 0D 01 01 25 03 00 99 
2022-06-12 19:04:20.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=35, callback=0, payload=00 23 07 60 0D 01 01 25 03 00 
2022-06-12 19:04:20.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=35, callback=0, payload=00 23 07 60 0D 01 01 25 03 00 
2022-06-12 19:04:20.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2022-06-12 19:04:20.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Application Command Request (ALIVE:DONE)
2022-06-12 19:04:20.348 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: resetResendCount initComplete=true isDead=false
2022-06-12 19:04:20.348 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2022-06-12 19:04:20.348 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Incoming command class COMMAND_CLASS_SWITCH_BINARY, endpoint 1
2022-06-12 19:04:20.348 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: SECURITY NOT required on COMMAND_CLASS_SWITCH_BINARY
2022-06-12 19:04:20.348 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 35: Received COMMAND_CLASS_SWITCH_BINARY V1 SWITCH_BINARY_REPORT
2022-06-12 19:04:20.348 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 35: Switch Binary report, value = 0
2022-06-12 19:04:20.348 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2022-06-12 19:04:20.348 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_SWITCH_BINARY, value=0
2022-06-12 19:04:20.348 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Updating channel state zwave:device:466d9b93a7:node35:switch_binary1 to OFF [OnOffType]
2022-06-12 19:04:20.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Commands processed 1.
2022-06-12 19:04:20.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@7ba30153.
2022-06-12 19:04:20.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@7ba30153.
2022-06-12 19:04:20.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: notifyTransactionResponse TID:273 DONE
2022-06-12 19:04:20.349 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2022-06-12 19:04:20.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2022-06-12 19:04:20.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2022-06-12 19:04:20.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-12 19:04:20.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-06-12 19:04:20.349 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 23 06 60 0D 01 02 25 02 25 DF 77 
2022-06-12 19:04:20.349 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 35: Sending REQUEST Message = 01 0D 00 13 23 06 60 0D 01 02 25 02 25 DF 77 
2022-06-12 19:04:20.350 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2022-06-12 19:04:20.350 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 274: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 223
2022-06-12 19:04:20.351 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2022-06-12 19:04:20.351 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-06-12 19:04:20.359 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2022-06-12 19:04:20.360 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2022-06-12 19:04:20.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-06-12 19:04:20.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 274: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 223
2022-06-12 19:04:20.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2022-06-12 19:04:20.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2022-06-12 19:04:20.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 274: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 223
2022-06-12 19:04:20.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2022-06-12 19:04:20.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 274: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 223
2022-06-12 19:04:20.364 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2022-06-12 19:04:20.364 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 35: sentData successfully placed on stack.
2022-06-12 19:04:20.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 274: Advanced to WAIT_REQUEST
2022-06-12 19:04:20.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: TID 274: Transaction not completed
2022-06-12 19:04:20.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-12 19:04:20.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-12 19:04:20.498 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 DF 00 00 0E 3A 
2022-06-12 19:04:20.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=223, payload=DF 00 00 0E 
2022-06-12 19:04:20.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=223, payload=DF 00 00 0E 
2022-06-12 19:04:20.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 274: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 223
2022-06-12 19:04:20.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2022-06-12 19:04:20.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 274: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 223
2022-06-12 19:04:20.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 274: (Callback 223)
2022-06-12 19:04:20.499 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2022-06-12 19:04:20.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 274: callback 223
2022-06-12 19:04:20.499 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=223, payload=DF 00 00 0E 
2022-06-12 19:04:20.499 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 35: SendData Request. CallBack ID = 223, Status = Transmission complete and ACK received(0)
2022-06-12 19:04:20.499 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: resetResendCount initComplete=true isDead=false
2022-06-12 19:04:20.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 274: Advanced to WAIT_DATA
2022-06-12 19:04:20.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: TID 274: Transaction not completed
2022-06-12 19:04:20.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-12 19:04:20.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-12 19:04:20.581 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 23 07 60 0D 02 01 25 03 00 9A 
2022-06-12 19:04:20.581 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=35, callback=0, payload=00 23 07 60 0D 02 01 25 03 00 
2022-06-12 19:04:20.581 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=35, callback=0, payload=00 23 07 60 0D 02 01 25 03 00 
2022-06-12 19:04:20.581 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2022-06-12 19:04:20.586 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Application Command Request (ALIVE:DONE)
2022-06-12 19:04:20.586 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: resetResendCount initComplete=true isDead=false
2022-06-12 19:04:20.586 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2022-06-12 19:04:20.586 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Incoming command class COMMAND_CLASS_SWITCH_BINARY, endpoint 2
2022-06-12 19:04:20.587 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: SECURITY NOT required on COMMAND_CLASS_SWITCH_BINARY
2022-06-12 19:04:20.587 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 35: Received COMMAND_CLASS_SWITCH_BINARY V1 SWITCH_BINARY_REPORT
2022-06-12 19:04:20.587 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 35: Switch Binary report, value = 0
2022-06-12 19:04:20.587 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2022-06-12 19:04:20.587 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Got a value event from Z-Wave network, endpoint=2, command class=COMMAND_CLASS_SWITCH_BINARY, value=0
2022-06-12 19:04:20.587 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Updating channel state zwave:device:466d9b93a7:node35:switch_binary2 to OFF [OnOffType]
2022-06-12 19:04:20.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Commands processed 1.
2022-06-12 19:04:20.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@441937f7.
2022-06-12 19:04:20.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@441937f7.
2022-06-12 19:04:20.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: notifyTransactionResponse TID:274 DONE
2022-06-12 19:04:20.587 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2022-06-12 19:04:20.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2022-06-12 19:04:20.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2022-06-12 19:04:20.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-12 19:04:20.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-06-12 19:04:21.024 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 1A 0A 32 02 A1 4A 00 00 01 2D 00 00 0C 
2022-06-12 19:04:21.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=26, callback=0, payload=00 1A 0A 32 02 A1 4A 00 00 01 2D 00 00 
2022-06-12 19:04:21.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=26, callback=0, payload=00 1A 0A 32 02 A1 4A 00 00 01 2D 00 00 
2022-06-12 19:04:21.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2022-06-12 19:04:21.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Application Command Request (ALIVE:DONE)
2022-06-12 19:04:21.025 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: resetResendCount initComplete=true isDead=false
2022-06-12 19:04:21.025 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: Incoming command class COMMAND_CLASS_METER, endpoint 0
2022-06-12 19:04:21.025 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: SECURITY not supported
2022-06-12 19:04:21.026 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 26: Received COMMAND_CLASS_METER V3 METER_REPORT
2022-06-12 19:04:21.026 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 26: Meter: Type=Electric(1), Scale=A(5), Value=0E+1
2022-06-12 19:04:21.026 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Got an event from Z-Wave network: ZWaveMeterValueEvent
2022-06-12 19:04:21.026 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=0E+1
2022-06-12 19:04:21.026 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Updating channel state zwave:device:466d9b93a7:node26:meter_current to 0 [DecimalType]
2022-06-12 19:04:21.026 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Commands processed 1.
2022-06-12 19:04:21.026 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@516dfc.
2022-06-12 19:04:21.026 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2022-06-12 19:04:21.026 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2022-06-12 19:04:21.026 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-12 19:04:21.026 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

apella12 · June 13, 2022, 11:55am

Jjordan:

2022-06-12 19:04:07.137 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 35: TID 272: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2022-06-12 19:04:07.137 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2022-06-12 19:04:07.137 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 272: Transaction ABORTED

This is where the message fails, although I’m not sure why. It appears the controller did not respond to the SET command after 2 seconds and then the command was cancelled 12 seconds later. Since OH items use autoupdate by default, you see a movement in the switch (thinking the command will go through), but that is reversed when the polling confirms the device is still off. FYI there is a debug log viewer here that helps make Debug files more readable.

Since this appears to work in OH2, I’d suggest doing the same test in Debug and compare for differences.

Bob

Jjordan · June 13, 2022, 10:39pm

Thank you, Bob, for your help.
Here is the full RAW log from the OH2 Where the FIbaro Double switch worked with no issue on same PC with same controller. I don’t see anything out of the ordinary. Do you? Can this be an issue with the ZWave library in OH3?


2022-06-13 18:35:15.768 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-13 18:35:15.768 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-06-13 18:35:16.340 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Command received zwave:device:2ac50d9a:node35:switch_binary1 --> ON [OnOffType]
2022-06-13 18:35:16.340 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 35: Creating new message for application command SWITCH_BINARY_SET
2022-06-13 18:35:16.340 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Encapsulating message, instance / endpoint 1
2022-06-13 18:35:16.340 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 35: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2022-06-13 18:35:16.340 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
2022-06-13 18:35:16.340 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2022-06-13 18:35:16.340 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Adding to device queue
2022-06-13 18:35:16.340 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Added 285 to queue - size 1
2022-06-13 18:35:16.340 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-06-13 18:35:16.341 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 13 23 07 60 0D 01 01 25 01 FF 25 0F 5A 
2022-06-13 18:35:16.341 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 35: Sending REQUEST Message = 01 0E 00 13 23 07 60 0D 01 01 25 01 FF 25 0F 5A 
2022-06-13 18:35:16.344 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2022-06-13 18:35:16.344 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-06-13 18:35:16.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-06-13 18:35:16.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2022-06-13 18:35:16.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2022-06-13 18:35:16.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-13 18:35:16.347 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2022-06-13 18:35:16.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 285: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 15
2022-06-13 18:35:16.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-13 18:35:16.348 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Polling initialised at 1800 seconds - start in 1500 milliseconds.
2022-06-13 18:35:16.352 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2022-06-13 18:35:16.353 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2022-06-13 18:35:16.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2022-06-13 18:35:16.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 285: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 15
2022-06-13 18:35:16.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2022-06-13 18:35:16.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 285: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 15
2022-06-13 18:35:16.354 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2022-06-13 18:35:16.354 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 35: sentData successfully placed on stack.
2022-06-13 18:35:16.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 285: Advanced to WAIT_REQUEST
2022-06-13 18:35:16.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: TID 285: Transaction not completed
2022-06-13 18:35:16.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-13 18:35:16.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-13 18:35:16.417 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 0F 00 00 07 E3 
2022-06-13 18:35:16.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=15, payload=0F 00 00 07 
2022-06-13 18:35:16.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=15, payload=0F 00 00 07 
2022-06-13 18:35:16.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 285: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 15
2022-06-13 18:35:16.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2022-06-13 18:35:16.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 285: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 15
2022-06-13 18:35:16.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 285: (Callback 15)
2022-06-13 18:35:16.419 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2022-06-13 18:35:16.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 285: callback 15
2022-06-13 18:35:16.419 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=15, payload=0F 00 00 07 
2022-06-13 18:35:16.419 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 35: SendData Request. CallBack ID = 15, Status = Transmission complete and ACK received(0)
2022-06-13 18:35:16.419 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: resetResendCount initComplete=true isDead=false
2022-06-13 18:35:16.419 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 285: Transaction COMPLETED
2022-06-13 18:35:16.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Response processed after 72ms
2022-06-13 18:35:16.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: TID 285: Transaction completed
2022-06-13 18:35:16.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: notifyTransactionResponse TID:285 DONE
2022-06-13 18:35:16.419 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2022-06-13 18:35:16.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-13 18:35:16.420 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-06-13 18:35:16.503 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 23 07 60 0D 01 01 25 03 FF 66 
2022-06-13 18:35:16.507 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=35, callback=0, payload=00 23 07 60 0D 01 01 25 03 FF 
2022-06-13 18:35:16.507 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=35, callback=0, payload=00 23 07 60 0D 01 01 25 03 FF 
2022-06-13 18:35:16.507 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2022-06-13 18:35:16.507 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Application Command Request (ALIVE:DONE)
2022-06-13 18:35:16.507 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: resetResendCount initComplete=true isDead=false
2022-06-13 18:35:16.508 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2022-06-13 18:35:16.508 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Incoming command class COMMAND_CLASS_SWITCH_BINARY, endpoint 1
2022-06-13 18:35:16.508 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: SECURITY NOT required on COMMAND_CLASS_SWITCH_BINARY
2022-06-13 18:35:16.508 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 35: Received COMMAND_CLASS_SWITCH_BINARY V1 SWITCH_BINARY_REPORT
2022-06-13 18:35:16.508 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 35: Switch Binary report, value = 255
2022-06-13 18:35:16.508 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2022-06-13 18:35:16.508 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_SWITCH_BINARY, value=255
2022-06-13 18:35:16.508 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Updating channel state zwave:device:2ac50d9a:node35:switch_binary1 to ON [OnOffType]
2022-06-13 18:35:16.508 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Commands processed 1.
2022-06-13 18:35:16.508 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@66894639.
2022-06-13 18:35:16.509 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2022-06-13 18:35:16.509 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2022-06-13 18:35:16.509 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-13 18:35:16.509 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-06-13 18:35:17.857 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Polling...
2022-06-13 18:35:17.857 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Polling zwave:device:2ac50d9a:node35:switch_binary1
2022-06-13 18:35:17.857 [DEBUG] [converter.ZWaveBinarySwitchConverter] - NODE 35: Generating poll message for COMMAND_CLASS_SWITCH_BINARY, endpoint 1
2022-06-13 18:35:17.857 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 35: Creating new message for application command SWITCH_BINARY_GET
2022-06-13 18:35:17.857 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Encapsulating message, instance / endpoint 1
2022-06-13 18:35:17.857 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 35: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2022-06-13 18:35:17.857 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
2022-06-13 18:35:17.857 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2022-06-13 18:35:17.857 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Polling skipped for zwave:device:2ac50d9a:node35:switch_binary1 on COMMAND_CLASS_BASIC
2022-06-13 18:35:17.857 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Polling zwave:device:2ac50d9a:node35:switch_binary2
2022-06-13 18:35:17.857 [DEBUG] [converter.ZWaveBinarySwitchConverter] - NODE 35: Generating poll message for COMMAND_CLASS_SWITCH_BINARY, endpoint 2
2022-06-13 18:35:17.857 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 35: Creating new message for application command SWITCH_BINARY_GET
2022-06-13 18:35:17.857 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Encapsulating message, instance / endpoint 2
2022-06-13 18:35:17.857 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 35: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 2
2022-06-13 18:35:17.857 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
2022-06-13 18:35:17.857 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2022-06-13 18:35:17.857 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Polling skipped for zwave:device:2ac50d9a:node35:switch_binary2 on COMMAND_CLASS_BASIC
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Adding to device queue
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Added 286 to queue - size 1
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-06-13 18:35:17.857 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 23 06 60 0D 01 01 25 02 25 10 BB 
2022-06-13 18:35:17.857 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 35: Sending REQUEST Message = 01 0D 00 13 23 06 60 0D 01 01 25 02 25 10 BB 
2022-06-13 18:35:17.857 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 286: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 16
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Adding to device queue
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Added 287 to queue - size 1
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-13 18:35:17.857 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 286: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 16
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-13 18:35:17.857 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 286: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 16
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 286: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 16
2022-06-13 18:35:17.857 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2022-06-13 18:35:17.857 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 35: sentData successfully placed on stack.
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 286: Advanced to WAIT_REQUEST
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: TID 286: Transaction not completed
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-13 18:35:17.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-13 18:35:17.904 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 10 00 00 05 FE 
2022-06-13 18:35:17.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=16, payload=10 00 00 05 
2022-06-13 18:35:17.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=16, payload=10 00 00 05 
2022-06-13 18:35:17.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 286: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 16
2022-06-13 18:35:17.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2022-06-13 18:35:17.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 286: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 16
2022-06-13 18:35:17.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 286: (Callback 16)
2022-06-13 18:35:17.904 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2022-06-13 18:35:17.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 286: callback 16
2022-06-13 18:35:17.904 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=16, payload=10 00 00 05 
2022-06-13 18:35:17.904 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 35: SendData Request. CallBack ID = 16, Status = Transmission complete and ACK received(0)
2022-06-13 18:35:17.904 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: resetResendCount initComplete=true isDead=false
2022-06-13 18:35:17.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 286: Advanced to WAIT_DATA
2022-06-13 18:35:17.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: TID 286: Transaction not completed
2022-06-13 18:35:17.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-13 18:35:17.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-13 18:35:17.982 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 23 07 60 0D 01 01 25 03 FF 66 
2022-06-13 18:35:17.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=35, callback=0, payload=00 23 07 60 0D 01 01 25 03 FF 
2022-06-13 18:35:17.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=35, callback=0, payload=00 23 07 60 0D 01 01 25 03 FF 
2022-06-13 18:35:17.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2022-06-13 18:35:17.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Application Command Request (ALIVE:DONE)
2022-06-13 18:35:17.982 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: resetResendCount initComplete=true isDead=false
2022-06-13 18:35:17.982 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2022-06-13 18:35:17.982 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Incoming command class COMMAND_CLASS_SWITCH_BINARY, endpoint 1
2022-06-13 18:35:17.982 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: SECURITY NOT required on COMMAND_CLASS_SWITCH_BINARY
2022-06-13 18:35:17.982 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 35: Received COMMAND_CLASS_SWITCH_BINARY V1 SWITCH_BINARY_REPORT
2022-06-13 18:35:17.982 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 35: Switch Binary report, value = 255
2022-06-13 18:35:17.982 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2022-06-13 18:35:17.982 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_SWITCH_BINARY, value=255
2022-06-13 18:35:17.982 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Updating channel state zwave:device:2ac50d9a:node35:switch_binary1 to ON [OnOffType]
2022-06-13 18:35:17.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Commands processed 1.
2022-06-13 18:35:17.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@2131f1a2.
2022-06-13 18:35:17.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@2131f1a2.
2022-06-13 18:35:17.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: notifyTransactionResponse TID:286 DONE
2022-06-13 18:35:17.982 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2022-06-13 18:35:17.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2022-06-13 18:35:17.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2022-06-13 18:35:17.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-13 18:35:17.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-06-13 18:35:17.982 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 23 06 60 0D 01 02 25 02 25 11 B9 
2022-06-13 18:35:17.982 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 35: Sending REQUEST Message = 01 0D 00 13 23 06 60 0D 01 02 25 02 25 11 B9 
2022-06-13 18:35:17.982 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2022-06-13 18:35:17.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 287: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 17
2022-06-13 18:35:17.982 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2022-06-13 18:35:17.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-06-13 18:35:17.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2022-06-13 18:35:17.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 287: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 17
2022-06-13 18:35:17.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2022-06-13 18:35:17.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-13 18:35:17.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-13 18:35:17.998 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2022-06-13 18:35:17.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2022-06-13 18:35:17.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2022-06-13 18:35:17.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 287: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 17
2022-06-13 18:35:17.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2022-06-13 18:35:17.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 287: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 17
2022-06-13 18:35:17.998 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2022-06-13 18:35:17.998 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 35: sentData successfully placed on stack.
2022-06-13 18:35:17.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 287: Advanced to WAIT_REQUEST
2022-06-13 18:35:17.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: TID 287: Transaction not completed
2022-06-13 18:35:17.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-13 18:35:17.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-13 18:35:18.146 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 11 00 00 10 EA 
2022-06-13 18:35:18.146 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=17, payload=11 00 00 10 
2022-06-13 18:35:18.146 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=17, payload=11 00 00 10 
2022-06-13 18:35:18.146 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 287: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 17
2022-06-13 18:35:18.146 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2022-06-13 18:35:18.146 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 287: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 17
2022-06-13 18:35:18.146 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 287: (Callback 17)
2022-06-13 18:35:18.146 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2022-06-13 18:35:18.146 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 287: callback 17
2022-06-13 18:35:18.146 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=17, payload=11 00 00 10 
2022-06-13 18:35:18.146 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 35: SendData Request. CallBack ID = 17, Status = Transmission complete and ACK received(0)
2022-06-13 18:35:18.146 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: resetResendCount initComplete=true isDead=false
2022-06-13 18:35:18.146 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 287: Advanced to WAIT_DATA
2022-06-13 18:35:18.146 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: TID 287: Transaction not completed
2022-06-13 18:35:18.146 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-13 18:35:18.146 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2022-06-13 18:35:18.372 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 23 07 60 0D 02 01 25 03 00 9A 
2022-06-13 18:35:18.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=35, callback=0, payload=00 23 07 60 0D 02 01 25 03 00 
2022-06-13 18:35:18.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=35, callback=0, payload=00 23 07 60 0D 02 01 25 03 00 
2022-06-13 18:35:18.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2022-06-13 18:35:18.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Application Command Request (ALIVE:DONE)
2022-06-13 18:35:18.372 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: resetResendCount initComplete=true isDead=false
2022-06-13 18:35:18.372 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2022-06-13 18:35:18.372 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Incoming command class COMMAND_CLASS_SWITCH_BINARY, endpoint 2
2022-06-13 18:35:18.372 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: SECURITY NOT required on COMMAND_CLASS_SWITCH_BINARY
2022-06-13 18:35:18.372 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 35: Received COMMAND_CLASS_SWITCH_BINARY V1 SWITCH_BINARY_REPORT
2022-06-13 18:35:18.372 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 35: Switch Binary report, value = 0
2022-06-13 18:35:18.372 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2022-06-13 18:35:18.372 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Got a value event from Z-Wave network, endpoint=2, command class=COMMAND_CLASS_SWITCH_BINARY, value=0
2022-06-13 18:35:18.372 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Updating channel state zwave:device:2ac50d9a:node35:switch_binary2 to OFF [OnOffType]
2022-06-13 18:35:18.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Commands processed 1.
2022-06-13 18:35:18.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@401c8901.
2022-06-13 18:35:18.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@401c8901.
2022-06-13 18:35:18.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: notifyTransactionResponse TID:287 DONE
2022-06-13 18:35:18.372 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2022-06-13 18:35:18.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2022-06-13 18:35:18.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2022-06-13 18:35:18.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-13 18:35:18.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2022-06-13 18:35:18.951 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 12 00 04 00 23 0C 60 0D 01 01 32 02 21 32 01 AE 00 00 27 
2022-06-13 18:35:18.966 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=35, callback=0, payload=00 23 0C 60 0D 01 01 32 02 21 32 01 AE 00 00 
2022-06-13 18:35:18.966 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=35, callback=0, payload=00 23 0C 60 0D 01 01 32 02 21 32 01 AE 00 00 
2022-06-13 18:35:18.966 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2022-06-13 18:35:18.966 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Application Command Request (ALIVE:DONE)
2022-06-13 18:35:18.966 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: resetResendCount initComplete=true isDead=false
2022-06-13 18:35:18.966 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2022-06-13 18:35:18.966 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: Incoming command class COMMAND_CLASS_METER, endpoint 1
2022-06-13 18:35:18.966 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: SECURITY NOT required on COMMAND_CLASS_METER
2022-06-13 18:35:18.966 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 35: Received COMMAND_CLASS_METER V3 METER_REPORT
2022-06-13 18:35:18.966 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 35: Meter: Type=Electric(1), Scale=W(2), Value=43
2022-06-13 18:35:18.966 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Got an event from Z-Wave network: ZWaveMeterValueEvent
2022-06-13 18:35:18.966 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_METER, value=43
2022-06-13 18:35:18.966 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Updating channel state zwave:device:2ac50d9a:node35:meter_watts1 to 43 [DecimalType]
2022-06-13 18:35:18.966 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Commands processed 1.
2022-06-13 18:35:18.966 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@722f2062.
2022-06-13 18:35:18.966 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2022-06-13 18:35:18.966 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2022-06-13 18:35:18.966 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2022-06-13 18:35:18.966 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

apella12 · June 14, 2022, 12:35am

It is not obvious to me why this is not working. Everything seems the same except the controller does not send back an ACK in OH3 and the message times out at 2 seconds. With OH2 the controller sends this

2022-06-13 18:35:16.344 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

There is only one database but the OH2 version is older, so there could have been a change. However, it appears the issue is the controller does not respond in OH3. This device has a lot of parameters are they identical between versions?

Bob

chris4789 · June 14, 2022, 8:09am

I remember there were troubles with this device due to wrong entries in database.
I can’t remember when this was exactly but possibly this is your problem with OH 3.2.
I also can’t remember in which version this was solved (I am getting old ).
If you have no problem with upgrading I would try latest 3.3 where the 223 working for sure.

Duke_Jones · June 14, 2022, 12:11pm

Hi, I also use this module in my 3.2 installation (openhabian) and have no troubles (of this kind).
Although… 2 days ago I had exactly the same problems (but also with other modules). But the prehistory to this was also a repositioning of the Z-Wave controller to another floor. Directly from this I had also updated my installation, so there were two possible causes. Since yesterday evening, however, everything has been working again.

Jjordan · June 18, 2022, 6:14pm

Update: Today I installed OpenHab 3.3.0 (M6) and confirmed that my Fibaro Double Switch indeed is working correctly. Considering that it works in OpenHab2.5 and OpenHab 3.3 but NOT in OpenHab 3.2.5, This looks like an issue specific to that OpenHab version. Thank you All for your help.