Issue with GE Zwave dimmer switches (14294) not switching light state

Hey guys,

I recently replaced all the switches in my house with the GE Smart Dimmer switches. Most of them have been working fine except for some are randomly having issues. I will describe them below.

I have the switches set so that the little blue light on the switch is on when the controlled light is off (so you can find the switch in the dark). This obviously means that when the controlled light is on, the little blue light is off. Randomly, a switch will not turn the controlled light on or off (depending on the command) but the little blue light will change state and the OpenHab logs will report that the switch received the command and report that the controlled light changed state (when it actually didn’t as stated above). See the below logs:

Item 'ZWave051ShowerAndTubLightDimmerSwitchSwitchDimmer' received command OFF
ZWave051ShowerAndTubLightDimmerSwitchSwitchDimmer changed from 100 to 0

This happens randomly, maybe 1 out of 10 times and can happen whether the switch is triggered by a rule, by Basic UI, or by manually pressing the button on the switch.

I am interested to get the communities thoughts on this and see whether yall have had a similar experience.

Are these switch items in a group or used in a rule?

Yes, pretty much all of my switches are in a group and used in rules. The main one thats acting up is only in one group and used in 1 rule though. I look it out of all other groups/rules.

To be clear though, this happen whether its activated via rule, group, or manually. doesn’t seem to matter.

Without seeing the rule and item/group config I would remove the items from the group and see if the issue continues. If the group is not the cause then remove the rule and test.

This doesn’t mean that the switch received the command - it means that the software received the command. From here it should send it to the ZWave binding, and then the binding should send it to the switch.

You really should enable debug logging if not already done to see where in this chain things are going amiss.

I will do that and post the logs here. i am not sure what im looking for in the logs.

Okay so i managed to get the switch to act up by activating it via a rule.

I have the below rule which turns all the lights in my master bathroom on when a particular switch is turned on. The only members of MasterBathAuto are the other 2 lights in the bathroom. One of those lights is the switch that keeps acting up. i have a second identical rule for turning the master bath lights off.

Node 25: ZWave025VanityLightsDimmerSwitchSwitchDimmer
Node 51: Switch in master bathroom. This switch is in MasterBathAuto group.
Node 30: other switch in master bathroom. This switch is in MasterBathAuto group.

rule "Master Bathroom Lights ON"
when
   Item ZWave025VanityLightsDimmerSwitchSwitchDimmer changed from 0
then
    MasterBathAuto.sendCommand(ON)
end

Admittedly i was activating the rule about every 10 seconds (On wait 10 seconds, Off, Repeat) to get it to mess up and it did (I was not spamming it though). In the end, when the switch messed up, i activated the rule to turn all master bath lights off and the light attached to node 51 stayed on but the little blue light on node 51 turned on.

Logs:

2020-01-18 11:44:07.318 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Application Command Request (ALIVE:SUC_ROUTE)

2020-01-18 11:44:07.319 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: Incoming command class COMMAND_CLASS_BASIC, endpoint 0

2020-01-18 11:44:07.319 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: SECURITY not supported

2020-01-18 11:44:07.319 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 25: Received COMMAND_CLASS_BASIC V1 BASIC_SET

2020-01-18 11:44:07.319 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 25: Basic report, value = 0

2020-01-18 11:44:07.319 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2020-01-18 11:44:07.319 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_BASIC, value=0

2020-01-18 11:44:07.319 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Updating channel state zwave:device:28e4dafb:node25:switch_dimmer to 0 [PercentType]

2020-01-18 11:44:07.320 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Commands processed 1.

2020-01-18 11:44:07.320 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@143695e.

2020-01-18 11:44:07.320 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1

2020-01-18 11:44:07.320 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1

2020-01-18 11:44:07.320 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 11:44:07.320 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2020-01-18 11:44:07.327 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 51: Command received zwave:device:28e4dafb:node51:switch_dimmer --> OFF [OnOffType]

2020-01-18 11:44:07.328 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 51: Creating new message for command SWITCH_MULTILEVEL_SET

2020-01-18 11:44:07.328 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 51: SECURITY not supported

2020-01-18 11:44:07.328 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 51: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured

2020-01-18 11:44:07.328 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: Adding to device queue

2020-01-18 11:44:07.328 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: Added 13716 to queue - size 8

2020-01-18 11:44:07.328 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2020-01-18 11:44:07.328 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 51: Polling initialised at 86400 seconds - start in 1500 milliseconds.

2020-01-18 11:44:07.330 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 30: Command received zwave:device:28e4dafb:node30:switch_dimmer --> OFF [OnOffType]

2020-01-18 11:44:07.330 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 30: Creating new message for command SWITCH_MULTILEVEL_SET

2020-01-18 11:44:07.330 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: SECURITY not supported

2020-01-18 11:44:07.330 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured

2020-01-18 11:44:07.330 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: Adding to device queue

2020-01-18 11:44:07.331 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: Added 13717 to queue - size 9

2020-01-18 11:44:07.331 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2020-01-18 11:44:07.331 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling initialised at 86400 seconds - start in 1500 milliseconds.

2020-01-18 11:44:07.490 [INFO ] [e.smarthome.model.script.Temperature] - InsideTemp received update: 23.000000000000004 in Celsius = 73.4000000000000072 in Fahrenheit.

2020-01-18 11:44:07.494 [INFO ] [clipse.smarthome.model.script.Length] - RainRate received update: 0.0 in milimeters = 0.0000000000 in inches.

2020-01-18 11:44:07.492 [INFO ] [e.smarthome.model.script.Temperature] - OutsideTemp received update: 22.38888888888889 in Celsius = 72.300000000000002 in Fahrenheit.

2020-01-18 11:44:08.829 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 51: Polling...

2020-01-18 11:44:08.829 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 51: Polling deferred until initialisation complete

2020-01-18 11:44:08.831 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling...

2020-01-18 11:44:08.831 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling deferred until initialisation complete

2020-01-18 11:44:09.607 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 51: TID 13715: Timeout at state WAIT_REQUEST. 3 retries remaining.

2020-01-18 11:44:09.607 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 13715: Transaction is current transaction, so clearing!!!!!

2020-01-18 11:44:09.608 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 13715: Transaction CANCELLED

2020-01-18 11:44:09.608 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 51: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2020-01-18 11:44:09.608 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: notifyTransactionResponse TID:13715 CANCELLED

2020-01-18 11:44:09.608 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2020-01-18 11:44:09.608 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 33 03 26 01 00 25 02 D6

2020-01-18 11:44:09.609 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 51: Sending REQUEST Message = 01 0A 00 13 33 03 26 01 00 25 02 D6

2020-01-18 11:44:09.609 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 13715: Transaction event listener: DONE: CANCELLED ->

2020-01-18 11:44:09.609 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 51: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@4478b9

2020-01-18 11:44:09.610 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2020-01-18 11:44:09.610 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 13716: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 2

2020-01-18 11:44:11.584 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2020-01-18 11:44:11.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2020-01-18 11:44:11.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2020-01-18 11:44:11.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 13716: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 2

2020-01-18 11:44:11.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2020-01-18 11:44:11.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 11:44:11.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2020-01-18 11:44:11.586 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 00 E9

2020-01-18 11:44:11.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=00

2020-01-18 11:44:11.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=00

2020-01-18 11:44:11.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 13716: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 2

2020-01-18 11:44:11.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2020-01-18 11:44:11.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 13716: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 2

2020-01-18 11:44:11.589 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=00

2020-01-18 11:44:11.589 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 51: sentData was not placed on stack.

2020-01-18 11:44:11.589 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 13716: Transaction CANCELLED

2020-01-18 11:44:11.589 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started...

2020-01-18 11:44:11.589 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 51: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2020-01-18 11:44:11.589 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: CANCEL while sending message. Requeueing - 2 attempts left!

2020-01-18 11:44:11.589 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 13716: Transaction RESET with 2 retries remaining.

2020-01-18 11:44:11.589 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: Adding to device queue

2020-01-18 11:44:11.589 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: Added 13716 to queue - size 9

2020-01-18 11:44:11.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.

2020-01-18 11:44:11.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: TID 13716: Transaction not completed

2020-01-18 11:44:11.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 11:44:11.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.

2020-01-18 11:44:11.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2020-01-18 11:44:11.839 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 33 03 26 01 00 25 03 D7

2020-01-18 11:44:11.839 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 51: Sending REQUEST Message = 01 0A 00 13 33 03 26 01 00 25 03 D7

2020-01-18 11:44:11.841 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2020-01-18 11:44:11.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 13716: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 3

2020-01-18 11:44:13.841 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 51: TID 13716: Timeout at state WAIT_RESPONSE. 2 retries remaining.

2020-01-18 11:44:13.841 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!

2020-01-18 11:44:13.842 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 13716: Transaction ABORTED

2020-01-18 11:44:13.842 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA

2020-01-18 11:44:13.842 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA

2020-01-18 11:44:13.844 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2020-01-18 11:44:13.844 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2020-01-18 11:44:15.696 [INFO ] [clipse.smarthome.model.script.Length] - Rainlast1h received update: 0.0 in milimeters = 0.0000000000 in inches.

2020-01-18 11:44:15.698 [INFO ] [clipse.smarthome.model.script.Length] - Rain15min received update: 0.0 in milimeters = 0.0000000000 in inches.

2020-01-18 11:44:15.696 [INFO ] [clipse.smarthome.model.script.Length] - Rainlast24h received update: 0.0 in milimeters = 0.0000000000 in inches.

2020-01-18 11:44:15.721 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2020-01-18 11:44:15.721 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2020-01-18 11:44:15.721 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2020-01-18 11:44:15.721 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 13716: [ABORTED] priority=Set, requiresResponse=true, callback: 3

2020-01-18 11:44:15.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2020-01-18 11:44:15.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 11:44:15.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2020-01-18 11:44:15.723 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 00 E9

2020-01-18 11:44:15.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=00

2020-01-18 11:44:15.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=00

2020-01-18 11:44:15.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 13716: [ABORTED] priority=Set, requiresResponse=true, callback: 3

2020-01-18 11:44:15.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2020-01-18 11:44:15.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 13716: [ABORTED] priority=Set, requiresResponse=true, callback: 3

2020-01-18 11:44:15.726 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=00

2020-01-18 11:44:15.725 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18

2020-01-18 11:44:15.727 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=

2020-01-18 11:44:15.727 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 51: sentData was not placed on stack.

2020-01-18 11:44:15.727 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 13716: Transaction CANCELLED

2020-01-18 11:44:15.728 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 51: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2020-01-18 11:44:15.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: CANCEL while sending message. Requeueing - 1 attempts left!

2020-01-18 11:44:15.728 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 13716: Transaction RESET with 1 retries remaining.

2020-01-18 11:44:15.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: Adding to device queue

2020-01-18 11:44:15.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: Added 13716 to queue - size 9

2020-01-18 11:44:15.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2020-01-18 11:44:15.728 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 33 03 26 01 00 25 04 D0

2020-01-18 11:44:15.729 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 51: Sending REQUEST Message = 01 0A 00 13 33 03 26 01 00 25 04 D0

2020-01-18 11:44:15.730 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2020-01-18 11:44:15.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2020-01-18 11:44:15.732 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2020-01-18 11:44:15.732 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 13716: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 4

2020-01-18 11:44:15.732 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: TID 13716: Transaction not completed

2020-01-18 11:44:15.732 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=

2020-01-18 11:44:15.732 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 13716: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 4

2020-01-18 11:44:15.732 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started...

2020-01-18 11:44:15.733 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 00 E9

2020-01-18 11:44:15.734 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 13716: Resetting transaction

2020-01-18 11:44:15.734 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: notifyTransactionResponse TID:13716 WAIT_RESPONSE

2020-01-18 11:44:15.734 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: Adding to device queue

2020-01-18 11:44:15.734 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: Added 13716 to queue - size 9

2020-01-18 11:44:15.734 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=00

2020-01-18 11:44:15.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.

2020-01-18 11:44:15.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2020-01-18 11:44:15.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2020-01-18 11:44:15.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2020-01-18 11:44:15.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=00

2020-01-18 11:44:15.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2020-01-18 11:44:15.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0

2020-01-18 11:44:15.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null

2020-01-18 11:44:15.736 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 11:44:15.736 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.

2020-01-18 11:44:15.826 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 19 03 20 01 00 D9

2020-01-18 11:44:15.828 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=25, callback=16, payload=10 19 03 20 01 00

2020-01-18 11:44:15.828 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=25, callback=16, payload=10 19 03 20 01 00

2020-01-18 11:44:15.828 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2020-01-18 11:44:15.828 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Application Command Request (ALIVE:SUC_ROUTE)

2020-01-18 11:44:15.828 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: Incoming command class COMMAND_CLASS_BASIC, endpoint 0

2020-01-18 11:44:15.829 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: SECURITY not supported

2020-01-18 11:44:15.829 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 25: Received COMMAND_CLASS_BASIC V1 BASIC_SET

2020-01-18 11:44:15.829 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 25: Basic report, value = 0

2020-01-18 11:44:15.829 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2020-01-18 11:44:15.829 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_BASIC, value=0

2020-01-18 11:44:15.829 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Updating channel state zwave:device:28e4dafb:node25:switch_dimmer to 0 [PercentType]

2020-01-18 11:44:15.829 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Commands processed 1.

2020-01-18 11:44:15.829 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@149e843.

2020-01-18 11:44:15.830 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2020-01-18 11:44:15.830 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2020-01-18 11:44:15.830 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 11:44:15.830 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.

2020-01-18 11:44:15.892 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 51 01 00 AA

2020-01-18 11:44:15.894 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AssignSucReturnRoute[81], type=Request[0], dest=0, callback=1, payload=01 00

2020-01-18 11:44:15.894 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AssignSucReturnRoute[81], type=Request[0], dest=0, callback=1, payload=01 00

2020-01-18 11:44:15.894 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2020-01-18 11:44:15.894 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0

2020-01-18 11:44:15.894 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null

2020-01-18 11:44:15.895 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AssignSucReturnRoute[81], type=Request[0], dest=0, callback=1, payload=01 00

2020-01-18 11:44:15.895 [DEBUG] [age.AssignSucReturnRouteMessageClass] - NODE {}: transaction not correlated for AssignSucReturnRouteMessageClass

2020-01-18 11:44:15.895 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 11:44:15.895 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.

2020-01-18 11:44:15.906 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 10 2A 12 56 01 32 02 21 74 00 17 B0 9E 00 05 00 18 8C 2E 81 3C C2

2020-01-18 11:44:15.908 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=42, callback=16, payload=10 2A 12 56 01 32 02 21 74 00 17 B0 9E 00 05 00 18 8C 2E 81 3C

2020-01-18 11:44:15.908 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=42, callback=16, payload=10 2A 12 56 01 32 02 21 74 00 17 B0 9E 00 05 00 18 8C 2E 81 3C

2020-01-18 11:44:15.908 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2020-01-18 11:44:15.908 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Application Command Request (ALIVE:SUC_ROUTE)

2020-01-18 11:44:15.908 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Decapsulating COMMAND_CLASS_CRC_16_ENCAP

2020-01-18 11:44:15.909 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Incoming command class COMMAND_CLASS_METER, endpoint 0

2020-01-18 11:44:15.909 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: SECURITY NOT required on COMMAND_CLASS_METER

2020-01-18 11:44:15.909 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Received COMMAND_CLASS_METER V3 METER_REPORT

2020-01-18 11:44:15.909 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 42: Meter: Type=Electric(1), Scale=W(2), Value=1552.542

2020-01-18 11:44:15.909 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Got an event from Z-Wave network: ZWaveMeterValueEvent

2020-01-18 11:44:15.909 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=1552.542

2020-01-18 11:44:15.909 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Updating channel state zwave:device:28e4dafb:node42:meter_watts to 1552.542 [DecimalType]

2020-01-18 11:44:15.910 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Commands processed 1.

2020-01-18 11:44:15.910 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@620df3.

2020-01-18 11:44:15.910 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2020-01-18 11:44:15.910 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2020-01-18 11:44:15.910 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 11:44:15.910 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.

2020-01-18 11:44:15.966 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 10 2A 12 56 01 32 02 21 74 00 17 B0 9E 00 05 00 18 8C 2E 81 3C C2

2020-01-18 11:44:15.968 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=42, callback=16, payload=10 2A 12 56 01 32 02 21 74 00 17 B0 9E 00 05 00 18 8C 2E 81 3C

2020-01-18 11:44:15.968 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=42, callback=16, payload=10 2A 12 56 01 32 02 21 74 00 17 B0 9E 00 05 00 18 8C 2E 81 3C

2020-01-18 11:44:15.968 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2020-01-18 11:44:15.969 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Application Command Request (ALIVE:SUC_ROUTE)

2020-01-18 11:44:15.969 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 42: Meter: Type=Electric(1), Scale=W(2), Value=1552.542

2020-01-18 11:44:15.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Got an event from Z-Wave network: ZWaveMeterValueEvent

2020-01-18 11:44:15.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=1552.542

2020-01-18 11:44:15.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Updating channel state zwave:device:28e4dafb:node42:meter_watts to 1552.542 [DecimalType]

2020-01-18 11:44:15.970 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Commands processed 1.

2020-01-18 11:44:15.970 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1d6bf5c.

2020-01-18 11:44:15.970 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2020-01-18 11:44:15.970 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2020-01-18 11:44:15.971 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 11:44:15.971 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.

2020-01-18 11:44:15.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2020-01-18 11:44:15.982 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 33 03 26 01 00 25 04 D0

2020-01-18 11:44:15.982 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 51: Sending REQUEST Message = 01 0A 00 13 33 03 26 01 00 25 04 D0

2020-01-18 11:44:15.985 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2020-01-18 11:44:15.985 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2020-01-18 11:44:15.985 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2020-01-18 11:44:15.985 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 13716: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 4

2020-01-18 11:44:15.985 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2020-01-18 11:44:15.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 13716: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 4

2020-01-18 11:44:15.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2020-01-18 11:44:15.987 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 11:44:15.987 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2020-01-18 11:44:15.994 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8

2020-01-18 11:44:15.996 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01

2020-01-18 11:44:15.996 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01

2020-01-18 11:44:15.996 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 13716: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 4

2020-01-18 11:44:15.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2020-01-18 11:44:15.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 13716: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 4

2020-01-18 11:44:15.997 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01

2020-01-18 11:44:15.997 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 51: sentData successfully placed on stack.

2020-01-18 11:44:15.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 13716: Advanced to WAIT_REQUEST

2020-01-18 11:44:15.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: TID 13716: Transaction not completed

2020-01-18 11:44:15.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 11:44:15.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2020-01-18 11:44:16.052 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 10 2A 12 56 01 32 02 21 74 00 17 B0 9E 00 05 00 18 8C 2E 81 3C C2

2020-01-18 11:44:16.054 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=42, callback=16, payload=10 2A 12 56 01 32 02 21 74 00 17 B0 9E 00 05 00 18 8C 2E 81 3C

2020-01-18 11:44:16.054 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=42, callback=16, payload=10 2A 12 56 01 32 02 21 74 00 17 B0 9E 00 05 00 18 8C 2E 81 3C

2020-01-18 11:44:16.054 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 13716: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 4

2020-01-18 11:44:16.056 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1

2020-01-18 11:44:16.056 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1

2020-01-18 11:44:16.056 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 11:44:16.057 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2020-01-18 11:44:16.330 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 10 19 03 20 01 00 D9

2020-01-18 11:44:16.332 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=25, callback=16, payload=10 19 03 20 01 00

2020-01-18 11:44:16.332 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=25, callback=16, payload=10 19 03 20 01 00

2020-01-18 11:44:16.332 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 13716: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 4

2020-01-18 11:44:16.333 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Application Command Request (ALIVE:SUC_ROUTE)

2020-01-18 11:44:16.333 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: Incoming command class COMMAND_CLASS_BASIC, endpoint 0

2020-01-18 11:44:16.333 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: SECURITY not supported

2020-01-18 11:44:16.333 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 25: Received COMMAND_CLASS_BASIC V1 BASIC_SET

2020-01-18 11:44:16.333 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 25: Basic report, value = 0

2020-01-18 11:44:16.334 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2020-01-18 11:44:16.334 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_BASIC, value=0

2020-01-18 11:44:16.334 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Updating channel state zwave:device:28e4dafb:node25:switch_dimmer to 0 [PercentType]

2020-01-18 11:44:16.334 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Commands processed 1.

2020-01-18 11:44:16.334 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1b4caf7.

2020-01-18 11:44:16.334 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1

2020-01-18 11:44:16.334 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1

2020-01-18 11:44:16.335 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 11:44:16.335 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2020-01-18 11:44:17.100 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 04 00 00 6F 80

2020-01-18 11:44:17.102 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=4, payload=04 00 00 6F

2020-01-18 11:44:17.102 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=4, payload=04 00 00 6F

2020-01-18 11:44:17.102 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 13716: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 4

2020-01-18 11:44:17.102 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2020-01-18 11:44:17.102 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 13716: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 4

2020-01-18 11:44:17.102 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 13716: (Callback 4)

2020-01-18 11:44:17.102 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2020-01-18 11:44:17.102 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 13716: callback 4

2020-01-18 11:44:17.103 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=4, payload=04 00 00 6F

2020-01-18 11:44:17.103 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 51: SendData Request. CallBack ID = 4, Status = Transmission complete and ACK received(0)

2020-01-18 11:44:17.103 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 13716: Transaction COMPLETED

2020-01-18 11:44:17.103 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: Response processed after 1118ms

2020-01-18 11:44:17.103 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: TID 13716: Transaction completed

2020-01-18 11:44:17.103 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: notifyTransactionResponse TID:13716 DONE

2020-01-18 11:44:17.103 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 51: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2020-01-18 11:44:17.104 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 11:44:17.104 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2020-01-18 11:44:17.104 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 1E 03 26 01 00 25 05 FC

2020-01-18 11:44:17.104 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 30: Sending REQUEST Message = 01 0A 00 13 1E 03 26 01 00 25 05 FC

2020-01-18 11:44:17.107 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2020-01-18 11:44:17.107 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2020-01-18 11:44:17.108 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2020-01-18 11:44:17.108 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 13717: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 5

2020-01-18 11:44:17.108 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2020-01-18 11:44:17.108 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 13717: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 5

2020-01-18 11:44:17.108 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2020-01-18 11:44:17.109 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 11:44:17.109 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2020-01-18 11:44:17.116 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8

2020-01-18 11:44:17.118 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01

2020-01-18 11:44:17.118 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01

2020-01-18 11:44:17.118 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 13717: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 5

2020-01-18 11:44:17.119 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2020-01-18 11:44:17.119 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 13717: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 5

2020-01-18 11:44:17.119 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01

2020-01-18 11:44:17.119 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 30: sentData successfully placed on stack.

2020-01-18 11:44:17.119 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 13717: Advanced to WAIT_REQUEST

2020-01-18 11:44:17.119 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: TID 13717: Transaction not completed

2020-01-18 11:44:17.119 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 11:44:17.119 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2020-01-18 11:44:17.245 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 05 00 00 0D E3

2020-01-18 11:44:17.247 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=5, payload=05 00 00 0D

2020-01-18 11:44:17.247 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=5, payload=05 00 00 0D

2020-01-18 11:44:17.248 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 13717: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 5

2020-01-18 11:44:17.248 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2020-01-18 11:44:17.248 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 13717: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 5

2020-01-18 11:44:17.248 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 13717: (Callback 5)

2020-01-18 11:44:17.248 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2020-01-18 11:44:17.249 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 13717: callback 5

2020-01-18 11:44:17.249 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=5, payload=05 00 00 0D

2020-01-18 11:44:17.249 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 30: SendData Request. CallBack ID = 5, Status = Transmission complete and ACK received(0)

2020-01-18 11:44:17.249 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 13717: Transaction COMPLETED

2020-01-18 11:44:17.250 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: Response processed after 142ms

2020-01-18 11:44:17.250 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: TID 13717: Transaction completed

2020-01-18 11:44:17.250 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: notifyTransactionResponse TID:13717 DONE

2020-01-18 11:44:17.250 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 30: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2020-01-18 11:44:17.250 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 11:44:17.251 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2020-01-18 11:44:17.632 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 19 03 26 03 00 CD

2020-01-18 11:44:17.634 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=25, callback=0, payload=00 19 03 26 03 00

2020-01-18 11:44:17.634 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=25, callback=0, payload=00 19 03 26 03 00

2020-01-18 11:44:17.634 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2020-01-18 11:44:17.634 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Application Command Request (ALIVE:SUC_ROUTE)

2020-01-18 11:44:17.635 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0

2020-01-18 11:44:17.635 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: SECURITY not supported

2020-01-18 11:44:17.635 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 25: Received COMMAND_CLASS_SWITCH_MULTILEVEL V2 SWITCH_MULTILEVEL_REPORT

2020-01-18 11:44:17.635 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 25: Switch Multi Level report, value = 0

2020-01-18 11:44:17.635 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2020-01-18 11:44:17.635 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=0

2020-01-18 11:44:17.635 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Updating channel state zwave:device:28e4dafb:node25:switch_dimmer to 0 [PercentType]

2020-01-18 11:44:17.635 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Commands processed 1.

2020-01-18 11:44:17.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1f54ca7.

2020-01-18 11:44:17.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2020-01-18 11:44:17.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2020-01-18 11:44:17.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 11:44:17.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

I would try adding a short timer and conditional statement in the rule to check the light level before sending the command.

You also did not post the rule for turning all master bedroom lights off (the rule you mentioned running when the issue occurred).

I will add a short timer. Maybe that will help.

Here is the rule you are referencing. In the last few minutes I added the delay shown:

rule "Master Bathroom Lights OFF"
when
   Item ZWave025VanityLightsDimmerSwitchSwitchDimmer changed to 0
then
    createTimer(now.plusSeconds(1), [ |
        MasterBathAuto.sendCommand(OFF)
        ])
end

I caught another example of the one switch not turning off with the above rule. This time it was not forced, i was leaving the room, hit the switch attached to this item: ZWave025VanityLightsDimmerSwitchSwitchDimmer and node 30 turned off but node 51 did not. See the below logs. If someone can help me interpret them, I would really appreciate it.

Rule File:

rule "Master Bathroom Lights OFF"
when
   Item ZWave025VanityLightsDimmerSwitchSwitchDimmer changed to 0
then
    createTimer(now.plusSeconds(1), [ |
        MasterBathAuto.sendCommand(OFF)
        ])
end

Event.log

2020-01-18 21:47:50.620 [vent.ItemStateChangedEvent] - ZWave025VanityLightsDimmerSwitchSwitchDimmer changed from 100 to 0
2020-01-18 21:47:50.620 [GroupItemStateChangedEvent] - MasterBathLights changed from ON to OFF through ZWave025VanityLightsDimmerSwitchSwitchDimmer
2020-01-18 21:47:50.621 [GroupItemStateChangedEvent] - MasterBathMainLights changed from 100.00000000 to 0.00000000 through ZWave025VanityLightsDimmerSwitchSwitchDimmer
2020-01-18 21:47:50.676 [vent.ItemStateChangedEvent] - ZWaveSerialController_SerialSof changed from 187104 to 187105
2020-01-18 21:47:50.676 [vent.ItemStateChangedEvent] - zwave_serial_zstick_28e4dafb_serial_sof changed from 187104 to 187105
2020-01-18 21:47:51.619 [ome.event.ItemCommandEvent] - Item 'MasterBathAuto' received command OFF
2020-01-18 21:47:51.623 [ome.event.ItemCommandEvent] - Item 'ZWave051ShowerAndTubLightDimmerSwitchSwitchDimmer' received command OFF
2020-01-18 21:47:51.627 [ome.event.ItemCommandEvent] - Item 'ZWave030MasterBathroomStandaloneLightDimmerSwitchSwitchDimmer' received command OFF
2020-01-18 21:47:51.629 [nt.ItemStatePredictedEvent] - ZWave051ShowerAndTubLightDimmerSwitchSwitchDimmer predicted to become OFF
2020-01-18 21:47:51.631 [nt.ItemStatePredictedEvent] - ZWave030MasterBathroomStandaloneLightDimmerSwitchSwitchDimmer predicted to become OFF
2020-01-18 21:47:51.633 [vent.ItemStateChangedEvent] - ZWave051ShowerAndTubLightDimmerSwitchSwitchDimmer changed from 100 to 0
2020-01-18 21:47:51.634 [vent.ItemStateChangedEvent] - ZWave030MasterBathroomStandaloneLightDimmerSwitchSwitchDimmer changed from 100 to 0

OpenHab.log

2020-01-18 21:47:50.613 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 19 03 20 01 00 C9

2020-01-18 21:47:50.615 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=25, callback=0, payload=00 19 03 20 01 00

2020-01-18 21:47:50.616 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=25, callback=0, payload=00 19 03 20 01 00

2020-01-18 21:47:50.616 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2020-01-18 21:47:50.616 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Application Command Request (ALIVE:SUC_ROUTE)

2020-01-18 21:47:50.616 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: Incoming command class COMMAND_CLASS_BASIC, endpoint 0

2020-01-18 21:47:50.616 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: SECURITY not supported

2020-01-18 21:47:50.616 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 25: Received COMMAND_CLASS_BASIC V1 BASIC_SET

2020-01-18 21:47:50.617 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 25: Basic report, value = 0

2020-01-18 21:47:50.617 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2020-01-18 21:47:50.617 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_BASIC, value=0

2020-01-18 21:47:50.617 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Updating channel state zwave:device:28e4dafb:node25:switch_dimmer to 0 [PercentType]

2020-01-18 21:47:50.617 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Commands processed 1.

2020-01-18 21:47:50.618 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@9bfc77.

2020-01-18 21:47:50.618 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2020-01-18 21:47:50.619 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2020-01-18 21:47:50.619 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 21:47:50.619 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2020-01-18 21:47:50.676 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 19 03 26 03 00 CD

2020-01-18 21:47:50.678 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=25, callback=0, payload=00 19 03 26 03 00

2020-01-18 21:47:50.679 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=25, callback=0, payload=00 19 03 26 03 00

2020-01-18 21:47:50.679 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2020-01-18 21:47:50.679 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Application Command Request (ALIVE:SUC_ROUTE)

2020-01-18 21:47:50.679 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0

2020-01-18 21:47:50.679 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 25: SECURITY not supported

2020-01-18 21:47:50.679 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 25: Received COMMAND_CLASS_SWITCH_MULTILEVEL V2 SWITCH_MULTILEVEL_REPORT

2020-01-18 21:47:50.679 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 25: Switch Multi Level report, value = 0

2020-01-18 21:47:50.680 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2020-01-18 21:47:50.680 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=0

2020-01-18 21:47:50.680 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Updating channel state zwave:device:28e4dafb:node25:switch_dimmer to 0 [PercentType]

2020-01-18 21:47:50.680 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Commands processed 1.

2020-01-18 21:47:50.680 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 25: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@a35db8.

2020-01-18 21:47:50.680 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2020-01-18 21:47:50.680 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2020-01-18 21:47:50.681 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 21:47:50.681 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2020-01-18 21:47:51.636 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 30: Command received zwave:device:28e4dafb:node30:switch_dimmer --> OFF [OnOffType]

2020-01-18 21:47:51.636 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 30: Creating new message for command SWITCH_MULTILEVEL_SET

2020-01-18 21:47:51.636 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: SECURITY not supported

2020-01-18 21:47:51.636 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured

2020-01-18 21:47:51.637 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: Adding to device queue

2020-01-18 21:47:51.637 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: Added 15274 to queue - size 7

2020-01-18 21:47:51.637 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2020-01-18 21:47:51.637 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 1E 03 26 01 00 25 99 60

2020-01-18 21:47:51.638 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 30: Sending REQUEST Message = 01 0A 00 13 1E 03 26 01 00 25 99 60

2020-01-18 21:47:51.640 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2020-01-18 21:47:51.641 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2020-01-18 21:47:51.641 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2020-01-18 21:47:51.641 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2020-01-18 21:47:51.641 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2020-01-18 21:47:51.641 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 21:47:51.642 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2020-01-18 21:47:51.642 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 15274: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 153

2020-01-18 21:47:51.642 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2020-01-18 21:47:51.642 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling initialised at 86400 seconds - start in 1500 milliseconds.

2020-01-18 21:47:51.644 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 51: Command received zwave:device:28e4dafb:node51:switch_dimmer --> OFF [OnOffType]

2020-01-18 21:47:51.646 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 51: Creating new message for command SWITCH_MULTILEVEL_SET

2020-01-18 21:47:51.648 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8

2020-01-18 21:47:51.650 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 51: SECURITY not supported

2020-01-18 21:47:51.650 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 51: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured

2020-01-18 21:47:51.650 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: Adding to device queue

2020-01-18 21:47:51.651 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01

2020-01-18 21:47:51.651 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: Added 15275 to queue - size 7

2020-01-18 21:47:51.651 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01

2020-01-18 21:47:51.651 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 15274: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 153

2020-01-18 21:47:51.651 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2020-01-18 21:47:51.652 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2020-01-18 21:47:51.652 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 15274: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 153

2020-01-18 21:47:51.652 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01

2020-01-18 21:47:51.652 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 30: sentData successfully placed on stack.

2020-01-18 21:47:51.652 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 15274: Advanced to WAIT_REQUEST

2020-01-18 21:47:51.653 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: TID 15274: Transaction not completed

2020-01-18 21:47:51.653 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 21:47:51.653 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2020-01-18 21:47:51.653 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 51: Polling initialised at 86400 seconds - start in 1500 milliseconds.

2020-01-18 21:47:51.706 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 99 00 00 06 74

2020-01-18 21:47:51.708 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=153, payload=99 00 00 06

2020-01-18 21:47:51.708 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=153, payload=99 00 00 06

2020-01-18 21:47:51.708 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 15274: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 153

2020-01-18 21:47:51.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2020-01-18 21:47:51.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 15274: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 153

2020-01-18 21:47:51.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 15274: (Callback 153)

2020-01-18 21:47:51.709 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2020-01-18 21:47:51.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 15274: callback 153

2020-01-18 21:47:51.709 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=153, payload=99 00 00 06

2020-01-18 21:47:51.710 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 30: SendData Request. CallBack ID = 153, Status = Transmission complete and ACK received(0)

2020-01-18 21:47:51.710 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 15274: Transaction COMPLETED

2020-01-18 21:47:51.710 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: Response processed after 68ms

2020-01-18 21:47:51.710 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: TID 15274: Transaction completed

2020-01-18 21:47:51.710 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: notifyTransactionResponse TID:15274 DONE

2020-01-18 21:47:51.710 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 30: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2020-01-18 21:47:51.710 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 21:47:51.711 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2020-01-18 21:47:51.711 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 33 03 26 01 00 25 9A 4E

2020-01-18 21:47:51.711 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 51: Sending REQUEST Message = 01 0A 00 13 33 03 26 01 00 25 9A 4E

2020-01-18 21:47:51.712 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2020-01-18 21:47:51.713 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2020-01-18 21:47:51.713 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2020-01-18 21:47:51.713 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 15275: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 154

2020-01-18 21:47:51.713 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2020-01-18 21:47:51.713 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 15275: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 154

2020-01-18 21:47:51.715 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2020-01-18 21:47:51.715 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 21:47:51.715 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2020-01-18 21:47:51.721 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8

2020-01-18 21:47:51.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01

2020-01-18 21:47:51.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01

2020-01-18 21:47:51.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 15275: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 154

2020-01-18 21:47:51.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2020-01-18 21:47:51.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 15275: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 154

2020-01-18 21:47:51.724 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01

2020-01-18 21:47:51.724 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 51: sentData successfully placed on stack.

2020-01-18 21:47:51.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 15275: Advanced to WAIT_REQUEST

2020-01-18 21:47:51.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: TID 15275: Transaction not completed

2020-01-18 21:47:51.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 21:47:51.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2020-01-18 21:47:51.801 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 9A 00 00 09 78

2020-01-18 21:47:51.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=154, payload=9A 00 00 09

2020-01-18 21:47:51.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=154, payload=9A 00 00 09

2020-01-18 21:47:51.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 15275: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 154

2020-01-18 21:47:51.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2020-01-18 21:47:51.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 15275: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 154

2020-01-18 21:47:51.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 15275: (Callback 154)

2020-01-18 21:47:51.805 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2020-01-18 21:47:51.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 15275: callback 154

2020-01-18 21:47:51.805 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=154, payload=9A 00 00 09

2020-01-18 21:47:51.805 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 51: SendData Request. CallBack ID = 154, Status = Transmission complete and ACK received(0)

2020-01-18 21:47:51.805 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 15275: Transaction COMPLETED

2020-01-18 21:47:51.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: Response processed after 92ms

2020-01-18 21:47:51.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: TID 15275: Transaction completed

2020-01-18 21:47:51.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: notifyTransactionResponse TID:15275 DONE

2020-01-18 21:47:51.806 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 51: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2020-01-18 21:47:51.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2020-01-18 21:47:51.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2020-01-18 21:47:53.143 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling...

2020-01-18 21:47:53.143 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling deferred until initialisation complete

2020-01-18 21:47:53.153 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 51: Polling...

2020-01-18 21:47:53.153 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 51: Polling deferred until initialisation complete

In case its relevent, items files below:

Dimmer ZWave025VanityLightsDimmerSwitchSwitchDimmer "Master Bathroom Vanity Lights[%d%%]" (Lights, MasterBedBathLights, MasterBathLights, MasterBathMainLights) [ "Lighting" ]{channel="zwave:device:28e4dafb:node25:switch_dimmer"}

Dimmer   ZWave051ShowerAndTubLightDimmerSwitchSwitchDimmer   "Master Bathroom Shower and Tub Lights[%d %%]" (MasterBathAuto) [ "Lighting" ]   {channel="zwave:device:28e4dafb:node51:switch_dimmer"}

Dimmer   ZWave030MasterBathroomStandaloneLightDimmerSwitchSwitchDimmer   "Master Bathroom Standalone Lught[%d %%]" (MasterBathAuto) [ "Lighting" ] {channel="zwave:device:28e4dafb:node30:switch_dimmer"}

The log shows that the controller is rejecting the message - normally this happens when it’s busy. The binding retries and finally it gets through…

It’s unclear why this is happening. If I remember correctly, the docs say the controller will reject messages in this way if it has no buffers available - maybe it’s processing a lot of frames still (remember that what is in the log is not indicative of what’s happening on the network). I’m not really sure.

One strange thing is that these reject messages are returning very slowly - a couple of seconds after they are sent. Normally the controller will respond very quickly (ie milliseconds) so maybe there is something that is tying up the serial port - eg maybe the computer is quite busy / heavily loaded or something at this time.

I don’t see what hardware you’re using?

Chris, now that you mention it, you might be onto something. Most of my scenes that control multiple Z-wave switches take a few seconds to run. They are far from immediate.

Hardware is below:
Openhab 2.5.0-1 is running on a VM
CPU: 2 threads of 9900k
Ram: 4GB
Im using the Aeotech Z-stick as my Zwave controller

Thank you for your reponse. PLease let me know what other info i can provide you!

I noticed the rule has 1 second, try adding a few seconds in the rule and see if that helps.

Will do.

Chris, how can I go about troubleshooting the delay in the ZWave controller? I am new to ZWave and thought it must have been standard but it seems like it’s probably not.

Your advice is appreciated!

My guess is that this has something to do with the VM, but it’s hard to say for sure. The binding logs the messages when it processes them, so something is delaying this. It could be the controller, but I think that’s unlikely as it’s a microprocessor. It could be that there’s a large amount of traffic on the network that is not to the controller and that’s slowing down the controller, but again, this is probably unlikely unless you have a big network with a lot of communications outside of the controller.

I’m not really sure what you mean? What isn’t standard?

is there an easy way to swap out a controller without having to re-learn and re-name all the devices?

Sorry, i meant the delay in response to activating a scene.

No

Yes. VSC.

250ms max on my system, usually less.

1 Like

This info is very helpful. So is it fair to say that if you had a scene where all the lights in your house were set to turn off, all of them would do so in around 1/4 second rather than in a few seconds like i am experiencing?

Also, I think id like to try and eliminate the controller from the equation. Can i add a second controller to the network and then remove the first one? if someone could help me with the most painless way to do swap out controllers, id appreciate it!