[SOLVED] Z-Wave, qubino dimmer and wrong states

rliffredo · November 2, 2018, 9:51am

Hello,

Since I moved to the new version of the binding (with 2.4 M4), I noticed a weird behavior with my Qubino dimmers.
Essentially, whenever I send a command (e.g. OFF) the end state is almost never 0, but something like 50.
From the logs, it seems that the dimmer sends two updates, but the second is discarded.

This is from the logs:

2018-11-02 10:02:39.763 [ome.event.ItemCommandEvent] - Item 'LightCorridor' received command OFF
2018-11-02 10:02:39.771 [nt.ItemStatePredictedEvent] - LightCorridor predicted to become OFF
==> /var/log/openhab2/openhab.log <==
2018-11-02 10:02:39.775 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Command received zwave:device:512:node3:switch_dimmer --> OFF [OnOffType]
2018-11-02 10:02:39.778 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 3: Creating new message for command SWITCH_MULTILEVEL_SET
2018-11-02 10:02:39.780 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
==> /var/log/openhab2/events.log <==
2018-11-02 10:02:39.782 [vent.ItemStateChangedEvent] - LightCorridor changed from 100 to 0
==> /var/log/openhab2/openhab.log <==
2018-11-02 10:02:39.784 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2018-11-02 10:02:39.785 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue
2018-11-02 10:02:39.788 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Added 3373 to queue - size 5
2018-11-02 10:02:39.790 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-02 10:02:39.792 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 03 03 26 01 00 25 F7 13 
2018-11-02 10:02:39.794 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 0A 00 13 03 03 26 01 00 25 F7 13 
2018-11-02 10:02:39.796 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-11-02 10:02:39.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 3373: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 247
2018-11-02 10:02:39.799 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-11-02 10:02:39.801 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling intialised at 86400 seconds - start in 1500 milliseconds.
2018-11-02 10:02:39.801 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-11-02 10:02:39.807 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-11-02 10:02:39.809 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3373: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 247
2018-11-02 10:02:39.810 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-11-02 10:02:39.811 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-02 10:02:39.812 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-11-02 10:02:39.816 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2018-11-02 10:02:39.818 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2018-11-02 10:02:39.821 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2018-11-02 10:02:39.822 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3373: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 247
2018-11-02 10:02:39.824 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-11-02 10:02:39.825 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 3373: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 247
2018-11-02 10:02:39.828 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 F7 00 00 03 1F 
2018-11-02 10:02:39.831 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2018-11-02 10:02:39.832 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack.
2018-11-02 10:02:39.834 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=247, payload=F7 00 00 03 
2018-11-02 10:02:39.836 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 3373: Advanced to WAIT_REQUEST
2018-11-02 10:02:39.838 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 3373: Transaction not completed
2018-11-02 10:02:39.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=247, payload=F7 00 00 03 
2018-11-02 10:02:39.842 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3373: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 247
2018-11-02 10:02:39.844 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-11-02 10:02:39.845 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 3373: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 247
2018-11-02 10:02:39.848 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 3373: (Callback 247)
2018-11-02 10:02:39.849 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-11-02 10:02:39.851 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 3373: callback 247
2018-11-02 10:02:39.853 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=247, payload=F7 00 00 03 
2018-11-02 10:02:39.855 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 247, Status = Transmission complete and ACK received(0)
2018-11-02 10:02:39.856 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
2018-11-02 10:02:39.858 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 3373: Transaction COMPLETED
2018-11-02 10:02:39.859 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Response processed after 61ms
2018-11-02 10:02:39.861 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 3373: Transaction completed
2018-11-02 10:02:39.862 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:3373 DONE
2018-11-02 10:02:39.941 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-11-02 10:02:39.943 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-02 10:02:39.944 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-02 10:02:40.445 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 03 03 26 03 00 D7 
2018-11-02 10:02:40.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 03 26 03 00 
2018-11-02 10:02:40.450 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 03 26 03 00 
2018-11-02 10:02:40.452 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-11-02 10:02:40.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DONE)
2018-11-02 10:02:40.454 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
2018-11-02 10:02:40.456 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2018-11-02 10:02:40.457 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
2018-11-02 10:02:40.458 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT
2018-11-02 10:02:40.460 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 3: Switch Multi Level report, value = 0
2018-11-02 10:02:40.461 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-11-02 10:02:40.463 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SWITCH_MULTILEVEL, value = 0
2018-11-02 10:02:40.464 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:512:node3:switch_dimmer to 0 [PercentType]
2018-11-02 10:02:40.467 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
2018-11-02 10:02:40.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@3f8b50.
2018-11-02 10:02:40.469 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-11-02 10:02:40.470 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-11-02 10:02:40.471 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-02 10:02:40.472 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-02 10:02:41.301 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling...
2018-11-02 10:02:41.303 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling zwave:device:512:node3:switch_dimmer
2018-11-02 10:02:41.304 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 3: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2018-11-02 10:02:41.305 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 3: Creating new message for command SWITCH_MULTILEVEL_GET
2018-11-02 10:02:41.307 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
2018-11-02 10:02:41.308 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2018-11-02 10:02:41.310 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling skipped for zwave:device:512:node3:switch_dimmer on COMMAND_CLASS_BASIC
2018-11-02 10:02:41.312 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue
2018-11-02 10:02:41.313 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Added 3374 to queue - size 5
2018-11-02 10:02:41.314 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-02 10:02:41.316 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 03 02 26 02 25 F8 1D 
2018-11-02 10:02:41.318 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 09 00 13 03 02 26 02 25 F8 1D 
2018-11-02 10:02:41.320 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-11-02 10:02:41.321 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 3374: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 248
2018-11-02 10:02:41.323 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-11-02 10:02:41.324 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-11-02 10:02:41.326 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-11-02 10:02:41.327 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3374: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 248
2018-11-02 10:02:41.328 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-11-02 10:02:41.329 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2018-11-02 10:02:41.329 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-02 10:02:41.330 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-11-02 10:02:41.333 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2018-11-02 10:02:41.334 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2018-11-02 10:02:41.336 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3374: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 248
2018-11-02 10:02:41.337 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-11-02 10:02:41.339 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 3374: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 248
2018-11-02 10:02:41.340 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2018-11-02 10:02:41.342 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack.
2018-11-02 10:02:41.343 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 3374: Advanced to WAIT_REQUEST
2018-11-02 10:02:41.345 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 3374: Transaction not completed
2018-11-02 10:02:41.345 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 F8 00 00 02 11 
2018-11-02 10:02:41.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-02 10:02:41.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=248, payload=F8 00 00 02 
2018-11-02 10:02:41.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-11-02 10:02:41.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=248, payload=F8 00 00 02 
2018-11-02 10:02:41.350 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3374: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 248
2018-11-02 10:02:41.352 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-11-02 10:02:41.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 3374: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 248
2018-11-02 10:02:41.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 3374: (Callback 248)
2018-11-02 10:02:41.357 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-11-02 10:02:41.358 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 3374: callback 248
2018-11-02 10:02:41.360 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=248, payload=F8 00 00 02 
2018-11-02 10:02:41.361 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 248, Status = Transmission complete and ACK received(0)
2018-11-02 10:02:41.363 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
2018-11-02 10:02:41.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 3374: Advanced to WAIT_DATA
2018-11-02 10:02:41.366 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 3374: Transaction not completed
2018-11-02 10:02:41.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-02 10:02:41.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-11-02 10:02:41.378 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 03 03 26 03 31 E6 
2018-11-02 10:02:41.380 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 03 26 03 31 
2018-11-02 10:02:41.382 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 03 26 03 31 
2018-11-02 10:02:41.384 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-11-02 10:02:41.386 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DONE)
2018-11-02 10:02:41.388 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
2018-11-02 10:02:41.390 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2018-11-02 10:02:41.392 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
2018-11-02 10:02:41.394 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT
2018-11-02 10:02:41.396 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 3: Switch Multi Level report, value = 49
2018-11-02 10:02:41.398 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-11-02 10:02:41.399 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SWITCH_MULTILEVEL, value = 49
2018-11-02 10:02:41.402 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:512:node3:switch_dimmer to 49 [PercentType]
2018-11-02 10:02:41.405 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
==> /var/log/openhab2/events.log <==
2018-11-02 10:02:41.409 [vent.ItemStateChangedEvent] - LightCorridor changed from 0 to 49
==> /var/log/openhab2/openhab.log <==
2018-11-02 10:02:41.410 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@70ce43.
2018-11-02 10:02:41.411 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@70ce43.
2018-11-02 10:02:41.413 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:3374 DONE
2018-11-02 10:02:41.415 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-11-02 10:02:41.416 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2018-11-02 10:02:41.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-11-02 10:02:41.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-02 10:02:41.420 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-02 10:02:42.456 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 03 0E 32 02 21 34 00 00 00 3F 00 00 00 00 00 00 F8 
2018-11-02 10:02:42.463 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 0E 32 02 21 34 00 00 00 3F 00 00 00 00 00 00 
2018-11-02 10:02:42.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 0E 32 02 21 34 00 00 00 3F 00 00 00 00 00 00 
2018-11-02 10:02:42.470 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-11-02 10:02:42.472 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DONE)
2018-11-02 10:02:42.475 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
2018-11-02 10:02:42.478 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_METER, endpoint 0
2018-11-02 10:02:42.481 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
2018-11-02 10:02:42.483 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_METER V3 METER_REPORT
2018-11-02 10:02:42.486 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 3: Meter: Type=Electric(1), Scale=W(2), Value=6.3
2018-11-02 10:02:42.488 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveMeterValueEvent
2018-11-02 10:02:42.491 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_METER, value = 6.3
2018-11-02 10:02:42.494 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:512:node3:meter_watts to 6.3 [DecimalType]
2018-11-02 10:02:42.497 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
2018-11-02 10:02:42.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@2a872a.
2018-11-02 10:02:42.502 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-11-02 10:02:42.504 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-11-02 10:02:42.506 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-02 10:02:42.508 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-02 10:02:43.453 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 03 0E 32 02 21 34 00 00 00 03 00 00 00 00 00 00 C4 
2018-11-02 10:02:43.459 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 0E 32 02 21 34 00 00 00 03 00 00 00 00 00 00 
2018-11-02 10:02:43.462 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 0E 32 02 21 34 00 00 00 03 00 00 00 00 00 00 
2018-11-02 10:02:43.464 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-11-02 10:02:43.466 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DONE)
2018-11-02 10:02:43.469 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
2018-11-02 10:02:43.472 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_METER, endpoint 0
2018-11-02 10:02:43.474 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
2018-11-02 10:02:43.476 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_METER V3 METER_REPORT
2018-11-02 10:02:43.479 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 3: Meter: Type=Electric(1), Scale=W(2), Value=0.3
2018-11-02 10:02:43.482 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveMeterValueEvent
2018-11-02 10:02:43.484 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_METER, value = 0.3
2018-11-02 10:02:43.487 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:512:node3:meter_watts to 0.3 [DecimalType]
2018-11-02 10:02:43.490 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
2018-11-02 10:02:43.492 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1ab2f0f.
2018-11-02 10:02:43.494 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-11-02 10:02:43.496 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-11-02 10:02:43.498 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-02 10:02:43.500 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-11-02 10:02:44.451 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 03 0E 32 02 21 34 00 00 00 00 00 00 00 00 00 00 C7 
2018-11-02 10:02:44.457 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 0E 32 02 21 34 00 00 00 00 00 00 00 00 00 00 
2018-11-02 10:02:44.461 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=3, callback=0, payload=00 03 0E 32 02 21 34 00 00 00 00 00 00 00 00 00 00 
2018-11-02 10:02:44.462 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-11-02 10:02:44.464 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Application Command Request (ALIVE:DONE)
2018-11-02 10:02:44.465 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: resetResendCount initComplete=true isDead=false
2018-11-02 10:02:44.467 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Incoming command class COMMAND_CLASS_METER, endpoint 0
2018-11-02 10:02:44.468 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported
2018-11-02 10:02:44.471 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Received COMMAND_CLASS_METER V3 METER_REPORT
2018-11-02 10:02:44.472 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 3: Meter: Type=Electric(1), Scale=W(2), Value=0E+1
2018-11-02 10:02:44.474 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveMeterValueEvent
2018-11-02 10:02:44.475 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_METER, value = 0E+1
2018-11-02 10:02:44.478 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating channel state zwave:device:512:node3:meter_watts to 0 [DecimalType]
2018-11-02 10:02:44.480 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Commands processed 1.
2018-11-02 10:02:44.481 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1724ce1.
2018-11-02 10:02:44.483 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-11-02 10:02:44.484 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-11-02 10:02:44.485 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-11-02 10:02:44.487 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

Is there anything that can be done about this, or it’s just a qubino quirk, and I should manage around at rule level (e.g. by sending again the command after 1 second, to ensure the state is coherent)?

BTW, a bit off-topic, but the new version is really good. It’s much smoother, and I get now all state notifications correct. It really is a big big step forward!

chris · November 2, 2018, 9:56am

Try setting the repoll period to something a little longer - maybe 4 seconds or something as it’s 1.5 seconds I think by default, and that doesn’t appear to be enough. This will give the light time to change value - I guess you might have the lights set to dim slowly?

rliffredo · November 2, 2018, 10:25am

The soft-dim for that switch is set to 0.5 seconds (default is 1s), while the polling is 1.5 seconds (default).

Once I put to 4 seconds, it started to behave OK.
However, I tried to use also “disabled”: if the dimmer is sending back the state as an event, why is polling required? This seems to work OK as well.

Am I correct in my understanding, that for this device I can disable polling after setting the state, because it will send the state anyways?

chris · November 2, 2018, 10:29am

Devices are not meant to send back such events. Qubino did this for a while, but ZWave forced them to remove this feature. By polling after the event, we check that the state was changed. If you don’t want it, then please feel free to disable this.

rliffredo · November 2, 2018, 10:31am

OK, thanks for the explanation!

Another question now: do you have any idea why polling 1.5 seconds after the command was returning the wrong values for something that should have lasted 0.5 seconds?

chris · November 2, 2018, 10:42am

No - clearly this is down to the device. The timings might end up being a little less than 1.5 seconds due to other delays, but it still should be > 1 second, and therefore > 0.5. Maybe there are some other delays somewhere, but your response is 50%, which presumably means that at the time of the polling, the light was at 50%, which means it was polled 250ms after the setting, and from the log, that does not seem to be the case.

Alternatively, it’s something completely different, but in any case, this value is being returned by the device, so it’s not a bug in the binding, but a feature of the device.

rliffredo · November 2, 2018, 11:07am

OK thanks again.

Let me sum up, for anyone coming back in the future (please correct anything that might be wrong!).

After command, the binding polls the device for the new state. This is according to z-wave standard, and the polling time can be configured for each device (Command poll period). The default is 1.5 seconds.
In case the state is not accurate, it means that the device for some reason is giving the wrong values, or it might be too early (e.g. long dimming time). In any case, increasing that period will solve the issue.
Qubino dimmers might send an event after the command. This is not according to z-wave standard, and qubino is not doing that any longer, but devices on the market might exhibit this behavior. In this case, it might be possible to disable to polling at all, but again, this is not according to the z-wave standard.

The general solution to the problem I stated in the beginning is to increase the value in Command poll period.

shorty707 · November 2, 2018, 12:06pm

I actually discussed that somewhere here on the Forum as I have a lot of Qubino din Dimmers.

When I increased polling to something like 4s It became worse … no clue why.

Addtionally when I changed other Config like Dim Timing the status Update by polling stopped working fully. That Could be Solved with a „re initalization“ …

Quite Tricky Those qubinos …

rliffredo · November 2, 2018, 12:42pm

Actually, I would say that most of my z-wave devices are “tricky” to say the least.

Did you try to completely disable the command update? In my case, all of my dimmers send an event after the command, so I don’t need the polling.
Did you try having a look at the debug z-wave log? That could help with some hint.