[SOLVED] Z-Wave dimmer commands being sent an OFF command then randomly resetting to something near 50

will_stewart1a · February 1, 2020, 2:16am

RPi 4
OH2 2.5.0
Z-Wave Binding version: Latest as of 2 weeks ago

I have multiple dimmer devices that are being sent commands to turn them off (upon a rule sendCommand), then immediately a message comes out to set them to some value near 50 out of the clear blue. And the switch indicator in HabMIN bounces from Off to On.

As an example, I have a GoControl bulb triggered by a rule that sends a command to the light. Please let me know why this is happening.

(p.s., I don’t know the right way to post log information, pls let me know if I’m doing it wrong. I’m also uploading the file in case that is the right thing to do)

2020-01-31 05:54:38.865 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Command received zwave:device:b6e7c13d:node26:switch_dimmer --> OFF [OnOffType]

2020-01-31 05:54:38.879 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 26: Creating new message for command SWITCH_MULTILEVEL_SET

2020-01-31 05:54:38.887 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: SECURITY not supported

2020-01-31 05:54:38.889 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured

2020-01-31 05:54:38.891 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Adding to device queue

2020-01-31 05:54:38.894 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Added 1593 to queue - size 11

2020-01-31 05:54:38.902 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 26: Sending REQUEST Message = 01 0A 00 13 1A 03 26 01 00 25 41 BC 

2020-01-31 05:54:38.910 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Polling initialised at 86400 seconds - start in 1500 milliseconds.

2020-01-31 05:54:38.962 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 26: sentData successfully placed on stack.

2020-01-31 05:54:38.967 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: TID 1593: Transaction not completed

2020-01-31 05:54:38.985 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 26: SendData Request. CallBack ID = 65, Status = Transmission complete and ACK received(0)

2020-01-31 05:54:38.988 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: resetResendCount initComplete=true isDead=false

2020-01-31 05:54:38.992 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Response processed after 84ms

2020-01-31 05:54:38.993 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: TID 1593: Transaction completed

2020-01-31 05:54:38.995 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: notifyTransactionResponse TID:1593 DONE

2020-01-31 05:54:38.997 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2020-01-31 05:54:40.410 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Polling...

2020-01-31 05:54:40.413 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Polling zwave:device:b6e7c13d:node26:switch_dimmer

2020-01-31 05:54:40.416 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 26: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0

2020-01-31 05:54:40.419 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 26: Creating new message for command SWITCH_MULTILEVEL_GET

2020-01-31 05:54:40.423 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: SECURITY not supported

2020-01-31 05:54:40.427 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured

2020-01-31 05:54:40.430 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Polling skipped for zwave:device:b6e7c13d:node26:switch_dimmer on COMMAND_CLASS_BASIC

2020-01-31 05:54:40.435 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Adding to device queue

2020-01-31 05:54:40.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Added 1594 to queue - size 11

2020-01-31 05:54:40.453 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 26: Sending REQUEST Message = 01 09 00 13 1A 02 26 02 25 42 BE 

2020-01-31 05:54:40.495 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 26: sentData successfully placed on stack.

2020-01-31 05:54:40.500 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: TID 1594: Transaction not completed

2020-01-31 05:54:40.520 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 26: SendData Request. CallBack ID = 66, Status = Transmission complete and ACK received(0)

2020-01-31 05:54:40.523 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: resetResendCount initComplete=true isDead=false

2020-01-31 05:54:40.527 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: TID 1594: Transaction not completed

2020-01-31 05:54:40.535 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Application Command Request (ALIVE:DONE)

2020-01-31 05:54:40.537 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: resetResendCount initComplete=true isDead=false

2020-01-31 05:54:40.540 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0

2020-01-31 05:54:40.543 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: SECURITY not supported

2020-01-31 05:54:40.545 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 26: Received COMMAND_CLASS_SWITCH_MULTILEVEL V1 SWITCH_MULTILEVEL_REPORT

2020-01-31 05:54:40.548 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 26: Switch Multi Level report, value = 48

2020-01-31 05:54:40.550 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2020-01-31 05:54:40.553 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=48

2020-01-31 05:54:40.556 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Updating channel state zwave:device:b6e7c13d:node26:switch_dimmer to 48 [PercentType]

2020-01-31 05:54:40.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Commands processed 1.

2020-01-31 05:54:40.578 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@7adee5.

2020-01-31 05:54:40.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@7adee5.

2020-01-31 05:54:40.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: notifyTransactionResponse TID:1594 DONE

2020-01-31 05:54:40.591 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent[DimmerOffToOnPercentage.txt|attachment](upload://iCTi8SKztTP1ZwQC9pTw2f0nQ4Q.txt) (6.0 KB)

5iver · February 1, 2020, 3:45am

This looks good… thank you!

Look here, specifically the last paragraph. Command Polling was implemented to go get the state of a device after a command has been sent, but this is only really needed if your device does not report the state on its own. This setting is adjustable in case the poll is occurring too soon after the command is sent, which it appears is what is causing your issue. Most devices do report their own states and IMO the default setting should be Disabled.

Your device reports its state, so there is no need for Command Polling and it should be disabled. Try this and see if it resolves your issue.

will_stewart1a · February 1, 2020, 1:36pm

Thanks Scott @5iver , that appears to remove the confusing state reset. Much appreciated!

chris · February 1, 2020, 2:30pm

Just to note that no devices should report the state on their own after a command has been sent to it. The only way to be sure that the command was implemented is with the polling.

How? If you think this is done through associations, then it should not be the case. I know Qubino did this for a while (ie sent state updates after a command was received) but the Alliance made them remove this feature as it is not permitted in the standards (although I tried to find this in the thousands of pages of docs, and failed). Qubino made this optional via a config parameter, but as far as I know, most devices will not do this.

Are you really sure that you see this happening in the logs? ie you see a REPORT command received immediately after the binding sends a SET command? Maybe in the ever changing world of ZWave, this requirement has been removed.

chris · February 1, 2020, 2:43pm

I found it in the spec -:

So, as a general rule devices should NOT send reports after the binding sends a command, and if the application (ie the binding) wants to know the state it needs to poll.

There may be some exceptions of course…

5iver · February 1, 2020, 3:21pm

My understanding was that after the Lutron status update patent expired, manufacturers would be free to implement this. It’s been a few years now, so I’ve been assuming this is the case, hence my rationale that this setting is not useful for most devices. The Linear bulbs came out relatively recently. My Leviton paid the license fees for my dimmers and switches, and my plugs use Hail, so I have this disabled on all of my devices.

@will_stewart1a, Chris knows best… you may want to enable the command polling again and increase the interval until things work properly. If you don’t and the bulb doesn’t report its state, then the Item could potentially get of sync with reality.

will_stewart1a · February 1, 2020, 3:24pm

Ok, thanks @chris and @5iver, I’ll set it to something at or over 5 seconds.

chris · February 1, 2020, 3:26pm

It’s nothing to to with the patent - it’s the standards that define how the system is meant to work and as per the post above (directly cut from the ZWave docs) it’s not allowed to do this.

mhilbush · February 1, 2020, 3:37pm

IIRC, the patent covered the case where the device would report it’s status after a change was made manually on the actual device.

But, my memory may be a bit foggy, as I haven’t read the patent in quite a while.

will_stewart1a · February 1, 2020, 4:06pm

Setting the command polling to 3 seconds eliminates any return status other than 0 for a sendCommand to set a dimmer to 0 for both an Evoke LRM-AS dimmer and a GoControl LB60Z-1 dimmer bulb. Thanks again!