Z-wave item value set to value received during dimming operation, instead of value when operation is complete

  • Platform information:
    • Hardware: Pine64
    • OS: Ubuntu 16.04
    • Java Runtime Environment: Oracle build 1.8.0_152-b16
    • openHAB version: 2.4
  • Issue of the topic: z-wave dimmers not functioning well with 2.4 – they never reach the desired state when turning off or on.

In the paper ui, setting the value to on or off functions, but the node receives an update while it is dimming and sets the current state to the value seen as the node is dimming, rather than the value when the dimming operation is complete.

  • If logs where generated please post these here using code fences:
12:41:47.742 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'KitchenTable' received command OFF
12:41:47.751 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Command received zwave:device:bb68da29:node10:switch_dimmer --> OFF [OnOffType]
12:41:47.755 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 10: Creating new message for command SWITCH_MULTILEVEL_SET
12:41:47.753 [INFO ] [arthome.event.ItemStatePredictedEvent] - KitchenTable predicted to become OFF
12:41:47.767 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
12:41:47.768 [INFO ] [smarthome.event.ItemStateChangedEvent] - KitchenTable changed from 100 to 0
12:41:47.772 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
12:41:47.779 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
12:41:47.784 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Added 82 to queue - size 3
12:41:47.791 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
12:41:47.797 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0A 03 26 01 00 25 39 D4 
12:41:47.803 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 10: Sending REQUEST Message = 01 0A 00 13 0A 03 26 01 00 25 39 D4 
12:41:47.808 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
12:41:47.811 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
12:41:47.815 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
12:41:47.816 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
12:41:47.819 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
12:41:47.820 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
12:41:47.825 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
12:41:47.830 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 82: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 57
12:41:47.832 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
12:41:47.831 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
12:41:47.835 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Polling intialised at 1800 seconds - start in 1500 milliseconds.
12:41:47.841 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
12:41:47.847 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
12:41:47.851 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 82: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 57
12:41:47.855 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
12:41:47.859 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 13 39 00 00 04 01 B6 7F 7F 7F 7F 01 01 03 06 00 00 00 02 01 00 00 78 
12:41:47.860 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 82: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 57
12:41:47.865 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=57, payload=39 00 00 04 01 B6 7F 7F 7F 7F 01 01 03 06 00 00 00 02 01 00 00 
12:41:47.870 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
12:41:47.874 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 10: sentData successfully placed on stack.
12:41:47.877 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 82: Advanced to WAIT_REQUEST
12:41:47.880 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: TID 82: Transaction not completed
12:41:47.884 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=57, payload=39 00 00 04 01 B6 7F 7F 7F 7F 01 01 03 06 00 00 00 02 01 00 00 
12:41:47.888 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 82: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 57
12:41:47.891 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
12:41:47.896 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 82: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 57
12:41:47.899 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 82: (Callback 57)
12:41:47.903 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
12:41:47.907 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 82: callback 57
12:41:47.912 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=57, payload=39 00 00 04 01 B6 7F 7F 7F 7F 01 01 03 06 00 00 00 02 01 00 00 
12:41:47.915 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 10: SendData Request. CallBack ID = 57, Status = Transmission complete and ACK received(0)
12:41:47.920 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: resetResendCount initComplete=true isDead=false
12:41:47.923 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 82: Transaction COMPLETED
12:41:47.927 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Response processed after 97ms
12:41:47.930 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: TID 82: Transaction completed
12:41:47.934 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: notifyTransactionResponse TID:82 DONE
12:41:47.939 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
12:41:47.944 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
12:41:47.948 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
12:41:49.335 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Polling...
12:41:49.342 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Polling zwave:device:bb68da29:node10:switch_dimmer
12:41:49.351 [DEBUG] [verter.ZWaveMultiLevelSwitchConverter] - NODE 10: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
12:41:49.360 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 10: Creating new message for command SWITCH_MULTILEVEL_GET
12:41:49.369 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
12:41:49.376 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
12:41:49.382 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Polling skipped for zwave:device:bb68da29:node10:switch_dimmer on COMMAND_CLASS_BASIC
12:41:49.392 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Adding to device queue
12:41:49.396 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Added 83 to queue - size 3
12:41:49.401 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
12:41:49.406 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 0A 02 26 02 25 3A D6 
12:41:49.410 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 10: Sending REQUEST Message = 01 09 00 13 0A 02 26 02 25 3A D6 
12:41:49.417 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
12:41:49.420 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
12:41:49.425 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
12:41:49.428 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
12:41:49.429 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
12:41:49.429 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
12:41:49.432 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
12:41:49.435 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 83: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 58
12:41:49.438 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
12:41:49.440 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
12:41:49.442 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
12:41:49.449 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
12:41:49.452 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 83: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 58
12:41:49.457 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
12:41:49.460 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 83: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 58
12:41:49.464 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
12:41:49.467 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 13 3A 00 00 04 01 B6 7F 7F 7F 7F 01 01 03 06 00 00 00 02 01 00 00 7B 
12:41:49.468 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 10: sentData successfully placed on stack.
12:41:49.472 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=58, payload=3A 00 00 04 01 B6 7F 7F 7F 7F 01 01 03 06 00 00 00 02 01 00 00 
12:41:49.474 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 83: Advanced to WAIT_REQUEST
12:41:49.479 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: TID 83: Transaction not completed
12:41:49.483 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=58, payload=3A 00 00 04 01 B6 7F 7F 7F 7F 01 01 03 06 00 00 00 02 01 00 00 
12:41:49.487 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 83: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 58
12:41:49.492 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
12:41:49.496 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 83: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 58
12:41:49.500 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 83: (Callback 58)
12:41:49.504 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
12:41:49.511 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 83: callback 58
12:41:49.513 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 0A 03 26 03 2E B6 45 
12:41:49.515 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=58, payload=3A 00 00 04 01 B6 7F 7F 7F 7F 01 01 03 06 00 00 00 02 01 00 00 
12:41:49.520 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=0, payload=00 0A 03 26 03 2E B6 
12:41:49.524 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 10: SendData Request. CallBack ID = 58, Status = Transmission complete and ACK received(0)
12:41:49.528 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: resetResendCount initComplete=true isDead=false
12:41:49.533 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 83: Advanced to WAIT_DATA
12:41:49.538 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: TID 83: Transaction not completed
12:41:49.542 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=10, callback=0, payload=00 0A 03 26 03 2E B6 
12:41:49.547 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
12:41:49.551 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Application Command Request (ALIVE:DONE)
12:41:49.555 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: resetResendCount initComplete=true isDead=false
12:41:49.559 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
12:41:49.564 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 10: SECURITY not supported
12:41:49.568 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 10: Received COMMAND_CLASS_SWITCH_MULTILEVEL V1 SWITCH_MULTILEVEL_REPORT
12:41:49.572 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 10: Switch Multi Level report, value = 46
12:41:49.576 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
12:41:49.581 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SWITCH_MULTILEVEL, value = 46
12:41:49.586 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Updating channel state zwave:device:bb68da29:node10:switch_dimmer to 46 [PercentType]
12:41:49.596 [INFO ] [smarthome.event.ItemStateChangedEvent] - KitchenTable changed from 0 to 46
12:41:49.602 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Commands processed 1.
12:41:49.606 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1d36dae.
12:41:49.611 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1d36dae.
12:41:49.616 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 10: notifyTransactionResponse TID:83 DONE
12:41:49.621 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
12:41:49.626 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
12:41:49.631 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
12:41:49.635 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
12:41:49.639 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.```


I could, perhaps, double the rate at which it dims to work around this, but this behavior was not present in 2.3.. so maybe it's a bug?

I wanted to mention that by adjusting the rate at which the light dims when being set to on or off, I have avoided this issue. However, I was using the default parameter set for the GE / Jasco device and others will likely run into the same issue as me.

Try changing the command poll delay in the thing. It defaults to 1500ms - if you use a larger value, it should resolve this.

That also works. Oddly enough, I think that I actually prefer the faster dimming transition, but this is all good to know. I suppose that one could calculate the time required to complete all dimming steps and see if it is greater than the command polling delay.

Any idea why this happened when going from 2.3 -> 2.4? Obviously you’ve overhauled the z-wave stuff quite a bit, and I can’t thank you enough for all of the hard work you’ve put in so that people like me can control their lights!

1 Like

You could do this, but also keep in mind there are often other delays in the ZWave system, so you should add some margin.

Previously the GET was sent immediately after the SET - in 2.4 I added this delay which was designed to solve this sort of issue in a few devices - unfortunately, it has caused issues with others, but at least now it is configurable…