26933 Smart Motion Dimmer on OZW Daemon + Beta Integration

dev0 · July 28, 2020, 12:56am

I am trying to get the GE/Jasco Motion Dimmer to work with OZWD and the HA Beta Integration.

I was able to successfully add the dimmer. It ends up showing as two devices, with a total of 8 entities (4 on each). 4 of those 8 entities are disabled. The active entities are the motion sensor (binary_sensor.multilevel_power_switch_home_security_motion_detected) and the dimmer level (light.multilevel_power_switch_level). Note that there are two of each.
The disabled entities are sensor.multilevel_power_switch_previous_event_cleared and sensor.multilevel_power_switch_home_security.

The switch seems to be reporting motion correctly and when I ues the device controls to turn the light on / off it seems to be showing correctly in HA too – at least for the second device that was added.
So far so good. However, the Z-Wave controls are not working as expected.

After a lot of testing and trying I believe that the config parameter of the switch are not working correctly. When looking at the lights during the dim up / dim down it appears like the switch is simply dimming up/down very slowly. I tried manually adjusting the parameters responsible for the Z-Wave dim rate (parameter 7 and 8), but even at 99 step size and 1 dim rate (every 10ms) the lights respond very slowly. I als tried adjusting the other dim rate and step size setting but they also didn’t have an effect on the Z-Wave dim rate.

Note that the switch works as expected when physically interacting with it and everything works as expected when paired with the SmartThings hub and the custom device handler:
https://raw.githubusercontent.com/MichaelStruck/SmartThingsPublic/master/devicetypes/michaelstruck/ge-motion-dimmer-switch-26933.src/ge-motion-dimmer-switch-26933.groovy

I verified using that ST device handler that the OZW device XML settings match and they seem to do so. However, dim rate and step size config settings seem to get ignored by the dimmer. Note that I tried changing other config parameters successfully (e.g. the timeout duration).

Any help or pointers in the right direction would be greatly appreciated.

firstof9 · July 28, 2020, 2:12am

Known issue, hold tight should be resolved shortly.

dev0 · July 28, 2020, 2:30am

This is it! Explicitly setting the transition value no light.turn_on does indeed fix it.

While debugging this at appears like I did find another bug though. Setting config parameter 8 (Z-Wave Dim Rate) on the Dimmer Switch seems to be failing. I filed it against qt-openzwave, but I’m frankly not sure where exactly the bug sits:

github.com/OpenZWave/qt-openzwave

GE Z-Wave Motion Dimmer 26933 config parameter 8 setvalue resulting in 'Incorrect Field Type (Short) for "setvalue"'

opened 02:24AM - 28 Jul 20 UTC

closed 04:08AM - 28 Jul 20 UTC

DanielBaulig

Setting configuration parameter 8 on GE Z-Wave Motion Dimmer 26933 fails with th…e following message: ``` 2020-07-28 02:15:20.329278214 [20200728 2:15:20.328 UTC] [ozw.mqtt.commands] [debug]: Got "OpenZWave/1/command/setvalue/" Message: "{\"ValueIDKey\": 2251799941349398, \"Value\": null}" 2020-07-28 02:15:20.330266679 [20200728 2:15:20.329 UTC] [ozw.mqtt.commands.setValue] [warning]: Incorrect Field Type (Short) for "setvalue" : Value: 0 2020-07-28 02:15:20.339244437 [20200728 2:15:20.330 UTC] [ozw.mqtt.commands] [warning]: Message Processing for "setvalue" failed: "{\"ValueIDKey\": 2251799941349398, \"Value\": null}" ``` The config value has a type of "short" in 26933-motion-dimmer-xml for config parameter 8. It seemed to have been changed from byte in https://github.com/OpenZWave/open-zwave/pull/1968 Note that at least the value range indicate that short is the correct type (assuming we are only talking about signed types). I tried changing the value back to byte to see if that would get rid of the error, but changing the value in the xml file didn't actually change the error. I then learned that there is some kind of cache that needs updating too. I assumed it to be the ozwcache* file in the mounted docker volume and manually updated that to also use byte for the type of the config parameter 8. But that also didn't change anything. So now I'm not sure if I'm down a completely wrong path here. Any help greatly appreciated.

firstof9 · July 28, 2020, 2:31am

Apparently you sent a null value for Parameter 8. How did you send the parameter?

dev0 · July 28, 2020, 2:55am

I’m not sure if this is the case. ~~Notice the timetamps on the first and second log row are out of order~~. They’re actually not in the example I posted. I have another example in which they are though.

I suspect that the second log row is indicating that the type of the value is incorrect and that results in a null value in the first log row.

Regardless, I’m using a HA Developer Tools service call to ozw.set_config_parameter with following service data:

node_id: 7
parameter: 8
value: 1

Note that setting other parameters (e.g. parameter 7 that has a type of byte) seems to be working.

firstof9 · July 28, 2020, 3:02am

That sounds like the XML isn’t right. I’d check openzwave/openzwave repo not the qt-openzwave repo, make sure the config is correct there.

dev0 · July 28, 2020, 3:03am

Note that the bug report states that I checked the config and that I changed it from short to byte but that resulted in the same error. I also tried manually changing the cache file but that also didn’t result in a different result.

firstof9 · July 28, 2020, 3:10am

In order to adjust the cache you have to stop the container, make your edit, then start it up again.
Did you follow those steps?

dev0 · July 28, 2020, 3:41am

I did not. Doing it in the correct order made it pick up the change. I am no longer getting the error, but it’s still not working. It appears like the value isn’t actually changing. Here’s the excerpt from my logs:

2020-07-28 03:40:15.113928013  [20200728 3:40:15.113 UTC] [ozw.mqtt.commands] [debug]: Got  "OpenZWave/1/command/setvalue/"  Message:  "{\"ValueIDKey\": 2251799941349393, \"Value\": 1}"
2020-07-28 03:40:15.114215917  [20200728 3:40:15.114 UTC] [ozw.mqtt.commands.setValue] [info]: Setting  2251799941349393  to Value  QVariant(uint, 1)
2020-07-28 03:40:15.114381229  [20200728 3:40:15.114 UTC] [ozw.values] [debug]: setData Called for Row 36  With Value QVariant(uint, 1)
2020-07-28 03:40:15.114522708  [20200728 3:40:15.114 UTC] [ozw.values] [debug]: valueModel Changed! QTOZW_ValueIds::Value - 36 :  QVariant(uint, 1)
2020-07-28 03:40:15.114652281  [20200728 3:40:15.114 UTC] [ozw.values] [debug]: valueModel Changed! vidKey: 2251799941349393 QVariant(uint, 1)
2020-07-28 03:40:15.114850963  [20200728 3:40:15.114 UTC] [ozw.library] [info]: Info - Node: 7 Value::Set - COMMAND_CLASS_CONFIGURATION - Z-Wave Command Dim Rate - 8 - 1 - 1
2020-07-28 03:40:15.115037886  [20200728 3:40:15.114 UTC] [ozw.library] [info]: Info - Node: 7 Configuration::Set - Parameter=8, Value=1 Size=1
2020-07-28 03:40:15.115233939  [20200728 3:40:15.115 UTC] [ozw.library] [debug]: Detail - Node: 7 Queuing (Send) ConfigurationCmd_Set (Node=7): 0x01, 0x0c, 0x00, 0x13, 0x07, 0x05, 0x70, 0x04, 0x08, 0x01, 0x01, 0x25, 0x28, 0x93
2020-07-28 03:40:15.115440547  [20200728 3:40:15.115 UTC] [ozw.library] [debug]: Detail - Node: 7 Queuing (Send) ConfigurationCmd_Get (Node=7): 0x01, 0x0a, 0x00, 0x13, 0x07, 0x03, 0x70, 0x05, 0x08, 0x25, 0x29, 0x93
2020-07-28 03:40:15.115801672  [20200728 3:40:15.115 UTC] [ozw.mqtt.commands] [info]: Processed Message for  "setvalue" :  "{\"ValueIDKey\": 2251799941349393, \"Value\": 1}"
2020-07-28 03:40:15.115915726  [20200728 3:40:15.115 UTC] [ozw.library] [info]: Info - Node: 7 Sending (Send) message (Callback ID=0x28, Expected Reply=0x13) - ConfigurationCmd_Set (Node=7): 0x01, 0x0c, 0x00, 0x13, 0x07, 0x05, 0x70, 0x04, 0x08, 0x01, 0x01, 0x25, 0x28, 0x93
2020-07-28 03:40:15.116156167  [20200728 3:40:15.116 UTC] [ozw.library] [info]: Info - Node: 7 Encrypted Flag is 0
2020-07-28 03:40:15.124030184  [20200728 3:40:15.123 UTC] [ozw.library] [debug]: Detail - Node: 7   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-07-28 03:40:15.124264681  [20200728 3:40:15.124 UTC] [ozw.library] [debug]: Detail - Node: 7   ZW_SEND_DATA delivered to Z-Wave stack
2020-07-28 03:40:15.143834717  [20200728 3:40:15.143 UTC] [ozw.library] [debug]: Detail - Node: 7   Received: 0x01, 0x18, 0x00, 0x13, 0x28, 0x00, 0x00, 0x02, 0x00, 0xcf, 0x7f, 0x7f, 0x7f, 0x7f, 0x00, 0x00, 0x03, 0x00, 0x00, 0x00, 0x00, 0x03, 0x01, 0x00, 0x00, 0x10
2020-07-28 03:40:15.144040251  [20200728 3:40:15.143 UTC] [ozw.library] [debug]: Detail - Node: 7   ZW_SEND_DATA Request with callback ID 0x28 received (expected 0x28)
2020-07-28 03:40:15.144215748  [20200728 3:40:15.144 UTC] [ozw.library] [info]: Info - Node: 7 Request RTT 27 Average Request RTT 27
2020-07-28 03:40:15.144427060  [20200728 3:40:15.144 UTC] [ozw.library] [debug]: Detail - Node: 7 Extended TxStatus: Time: 20, Hops: 0, Rssi:  -49 --- --- --- ---, AckChannel: 0, TxChannel: 0, RouteScheme: Last Working Route, Route: 0 0 0 0, RouteSpeed: 100K, RouteTries: 1, FailedLinkFrom: 0, FailedLinkTo: 0
2020-07-28 03:40:15.144603520  [20200728 3:40:15.144 UTC] [ozw.library] [debug]: Detail - Node: 7   Expected callbackId was received
2020-07-28 03:40:15.144770259  [20200728 3:40:15.144 UTC] [ozw.library] [debug]: Detail - Node: 7   Expected reply was received
2020-07-28 03:40:15.144937423  [20200728 3:40:15.144 UTC] [ozw.library] [debug]: Detail - Node: 7   Message transaction complete
2020-07-28 03:40:15.145102273  [20200728 3:40:15.144 UTC] [ozw.library] [debug]: Detail - Node: 7 Removing current message
2020-07-28 03:40:15.145305751  [20200728 3:40:15.145 UTC] [ozw.library] [info]: Info - Node: 7 Sending (Send) message (Callback ID=0x29, Expected Reply=0x04) - ConfigurationCmd_Get (Node=7): 0x01, 0x0a, 0x00, 0x13, 0x07, 0x03, 0x70, 0x05, 0x08, 0x25, 0x29, 0x93
2020-07-28 03:40:15.145475360  [20200728 3:40:15.145 UTC] [ozw.library] [info]: Info - Node: 7 Encrypted Flag is 0
2020-07-28 03:40:15.153084714  [20200728 3:40:15.152 UTC] [ozw.library] [debug]: Detail - Node: 7   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-07-28 03:40:15.153275193  [20200728 3:40:15.153 UTC] [ozw.library] [debug]: Detail - Node: 7   ZW_SEND_DATA delivered to Z-Wave stack
2020-07-28 03:40:15.172884284  [20200728 3:40:15.172 UTC] [ozw.library] [debug]: Detail - Node: 7   Received: 0x01, 0x18, 0x00, 0x13, 0x29, 0x00, 0x00, 0x03, 0x00, 0xcf, 0x7f, 0x7f, 0x7f, 0x7f, 0x00, 0x00, 0x03, 0x00, 0x00, 0x00, 0x00, 0x03, 0x01, 0x00, 0x00, 0x10
2020-07-28 03:40:15.173090707  [20200728 3:40:15.172 UTC] [ozw.library] [debug]: Detail - Node: 7   ZW_SEND_DATA Request with callback ID 0x29 received (expected 0x29)
2020-07-28 03:40:15.173264112  [20200728 3:40:15.173 UTC] [ozw.library] [info]: Info - Node: 7 Request RTT 27 Average Request RTT 27
2020-07-28 03:40:15.173468905  [20200728 3:40:15.173 UTC] [ozw.library] [debug]: Detail - Node: 7 Extended TxStatus: Time: 30, Hops: 0, Rssi:  -49 --- --- --- ---, AckChannel: 0, TxChannel: 0, RouteScheme: Last Working Route, Route: 0 0 0 0, RouteSpeed: 100K, RouteTries: 1, FailedLinkFrom: 0, FailedLinkTo: 0
2020-07-28 03:40:15.173644829  [20200728 3:40:15.173 UTC] [ozw.library] [debug]: Detail - Node: 7   Expected callbackId was received
2020-07-28 03:40:15.185296125  [20200728 3:40:15.185 UTC] [ozw.library] [debug]: Detail - Node: 7   Received: 0x01, 0x0e, 0x00, 0x04, 0x00, 0x07, 0x06, 0x70, 0x06, 0x08, 0x02, 0x00, 0x03, 0xcf, 0x00, 0x44
2020-07-28 03:40:15.185496363  [20200728 3:40:15.185 UTC] [ozw.library] [info]: Info - Node: 7 Response RTT 39 Average Response RTT 39
2020-07-28 03:40:15.185675972  [20200728 3:40:15.185 UTC] [ozw.library] [debug]: Detail - Node: 7 Value Updated: old value=3, new value=3, type=byte
2020-07-28 03:40:15.185862136  [20200728 3:40:15.185 UTC] [ozw.library] [debug]: Detail - Node: 7 Changes to this value are not verified
2020-07-28 03:40:15.186039541  [20200728 3:40:15.185 UTC] [ozw.library] [info]: Info - Node: 7 Received Configuration report: Parameter=8, Value=3
2020-07-28 03:40:15.186208038  [20200728 3:40:15.186 UTC] [ozw.library] [debug]: Detail - Node: 7   Expected reply and command class was received
2020-07-28 03:40:15.186375684  [20200728 3:40:15.186 UTC] [ozw.library] [debug]: Detail - Node: 7   Message transaction complete
2020-07-28 03:40:15.186539811  [20200728 3:40:15.186 UTC] [ozw.library] [debug]: Detail - Node: 7 Removing current message
2020-07-28 03:40:15.186749068  [20200728 3:40:15.186 UTC] [ozw.library] [debug]: Detail - Node: 7 Notification: ValueRefreshed CC: COMMAND_CLASS_CONFIGURATION Instance: 1 Index: 8
2020-07-28 03:40:15.186974879  [20200728 3:40:15.186 UTC] [ozw.notifications] [debug]: Notification pvt_valueRefreshed:  2251799941349393 Thread:  0xb3cf1010
2020-07-28 03:40:15.187419669  [20200728 3:40:15.187 UTC] [ozw.mqtt.publisher] [debug]: Publishing Event valueRefreshed: 2251799941349393

firstof9 · July 28, 2020, 4:01am

Try setting the value with ozw-admin see if that has the same issue.
Based on the log it processed the request, but the node didn’t accept the change for some reason.

dev0 · July 28, 2020, 4:21am

@firstof9
I assume that it didn’t accept the change because I changed the type from short (16 bit) to byte (8 bits), which the dimmer might not like.

The guys on the ozwdaemon bug report said that it appears like that Home Assistant OZW integration does not seem to support the short type. I filed a bug with HA here:

dev0 · July 28, 2020, 4:37am

To answer your question about using ozw-admin:

With type set to “short” (the production value shipped with OZW, that causes the Incorrect Field Type error from HA), changes to the config value through OZW are applied correctly.

With the type set to “byte” (my attempt at a workaround for the type error) OZW cannot apply changes to the config value and just like with HA, any attempts are ignored reset to the default value.

dev0 · August 13, 2020, 2:23am

The latest update 0.114 finally resolved the issue with the lights not dimming up and down correctly, yay!

I do run into a new problem now though. The entity state in HA updates as soon as I toggle the light on or off not considering the dim up/down duration. This results in HA showing a more or less random state of the light from while it is transitioning, instead of proper on or off state.

I’m pretty sure this happens due to HA doing a read after set without waiting for the dim up/down duration to pass. How can I fix this?

freshcoast · August 13, 2020, 4:20am

HA doesn’t control that behavior, it’s the zwave library that does it. You can watch this issue for updates.