Z-wave packets for 1 action: seems like a lot of them?

jbeale1 · January 15, 2020, 6:07pm

AKA, How many messages does it take to turn on a light bulb?

I’m a newcomer to Z-wave. I’m using HA 0.103.6 to control a EVA Logik ZW39 dimmer, with Zooz ZST10 S2 stick in RPi4. My automation sets the dimmer to 10/255 (which, in hex becomes 0x03 out of 0x63). Here is my code in /config/automations.yaml

- id: '1579109759606'
  alias: turn dimmer to 10/255
  description: turn dimmer to very low setting 10/255 or 4%
  trigger:
  - at: '10:00'
    platform: time
  condition: []
  action:
  - data:
      brightness: 10
    entity_id: light.inovelli_unknown_type_c000_id_c002_level
    service: light.turn_on

And below is the resulting OZW log from http://hassio:8123/config/zwave showing what happens when this one automation is manually triggered once. I’m counting 3 packets sent and 10 packets received. The controller and device are two feet apart, and I have only one Z-wave device in the entire house. Is this message count typical or necessary? Can I do something to reduce the chatter? It’s still plenty fast with only one device, but if I end up with a lot of devices, having 13 packets result from every simple action may cause the system to become slower than it might otherwise be. I was expecting just one set command and one readback command, with response to each that would be 4 packets total not 13.

2020-01-15 09:36:23.993 Info, Node005, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Level - 0 - 1 - 3
2020-01-15 09:36:23.994 Info, Node005, SwitchMultilevel::Set - Setting to level 3
2020-01-15 09:36:23.994 Detail, Node005, Queuing (Send) SwitchMultilevelCmd_Set (Node=5): 0x01, 0x0a, 0x00, 0x13, 0x05, 0x03, 0x26, 0x01, 0x03, 0x25, 0x4a, 0xab
2020-01-15 09:36:23.994 Detail, Node005, Queuing (Send) SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x4b, 0xa8
2020-01-15 09:36:23.994 Detail,
2020-01-15 09:36:23.994 Info, Node005, Sending (Send) message (Callback ID=0x4a, Expected Reply=0x13) - SwitchMultilevelCmd_Set (Node=5): 0x01, 0x0a, 0x00, 0x13, 0x05, 0x03, 0x26, 0x01, 0x03, 0x25, 0x4a, 0xab

2020-01-15 09:36:24.002 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-01-15 09:36:24.002 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack

2020-01-15 09:36:24.022 Detail, Node005,   Received: 0x01, 0x18, 0x00, 0x13, 0x4a, 0x00, 0x00, 0x02, 0x00, 0xda, 0x7f, 0x7f, 0x7f, 0x7f, 0x00, 0x00, 0x03, 0x00, 0x00, 0x00, 0x00, 0x03, 0x01, 0x00, 0x00, 0x67
2020-01-15 09:36:24.022 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0x4a received (expected 0x4a)
2020-01-15 09:36:24.022 Info, Node005, Request RTT 28 Average Request RTT 29
2020-01-15 09:36:24.022 Detail,   Expected callbackId was received
2020-01-15 09:36:24.022 Detail,   Expected reply was received
2020-01-15 09:36:24.022 Detail,   Message transaction complete
2020-01-15 09:36:24.022 Detail,
2020-01-15 09:36:24.022 Detail, Node005, Removing current message
2020-01-15 09:36:24.022 Detail,
2020-01-15 09:36:24.022 Info, Node005, Sending (Send) message (Callback ID=0x4b, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x4b, 0xa8

2020-01-15 09:36:24.030 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-01-15 09:36:24.031 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack

2020-01-15 09:36:24.054 Detail, Node005,   Received: 0x01, 0x18, 0x00, 0x13, 0x4b, 0x00, 0x00, 0x03, 0x00, 0xda, 0x7f, 0x7f, 0x7f, 0x7f, 0x00, 0x00, 0x03, 0x00, 0x00, 0x00, 0x00, 0x03, 0x01, 0x00, 0x00, 0x67
2020-01-15 09:36:24.055 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0x4b received (expected 0x4b)
2020-01-15 09:36:24.055 Info, Node005, Request RTT 32 Average Request RTT 30
2020-01-15 09:36:24.055 Detail,   Expected callbackId was received

2020-01-15 09:36:24.069 Detail, Node005,   Received: 0x01, 0x0d, 0x00, 0x04, 0x00, 0x05, 0x05, 0x26, 0x03, 0x03, 0x03, 0x00, 0xda, 0x00, 0x09
2020-01-15 09:36:24.069 Detail,
2020-01-15 09:36:24.069 Info, Node005, Response RTT 46 Average Response RTT 46
2020-01-15 09:36:24.069 Info, Node005, Received SwitchMultiLevel report: level=3
2020-01-15 09:36:24.069 Detail, Node005, Refreshed Value: old value=0, new value=3, type=byte
2020-01-15 09:36:24.069 Detail, Node005, Changes to this value are not verified
2020-01-15 09:36:24.069 Detail, Node005,   Expected reply and command class was received
2020-01-15 09:36:24.069 Detail, Node005,   Message transaction complete
2020-01-15 09:36:24.069 Detail,
2020-01-15 09:36:24.069 Detail, Node005, Removing current message
2020-01-15 09:36:24.069 Detail, Node005, Notification: ValueChanged

2020-01-15 09:36:25.075 Detail, Node005,   Received: 0x01, 0x0b, 0x00, 0x04, 0x00, 0x05, 0x03, 0x20, 0x03, 0x03, 0xd8, 0x00, 0x0e
2020-01-15 09:36:25.075 Detail,
2020-01-15 09:36:25.075 Info, Node005, Received Basic report from node 5: level=3
2020-01-15 09:36:25.075 Detail, Node005, Queuing (Send) SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x4c, 0xaf
2020-01-15 09:36:25.075 Detail,
2020-01-15 09:36:25.075 Info, Node005, Sending (Send) message (Callback ID=0x4c, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x4c, 0xaf

2020-01-15 09:36:25.083 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-01-15 09:36:25.083 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack

2020-01-15 09:36:25.102 Detail, Node005,   Received: 0x01, 0x0d, 0x00, 0x04, 0x00, 0x05, 0x05, 0x26, 0x03, 0x03, 0x03, 0x00, 0xd7, 0x00, 0x04
2020-01-15 09:36:25.102 Detail,
2020-01-15 09:36:25.102 Info, Node005, Response RTT 26 Average Response RTT 36
2020-01-15 09:36:25.102 Info, Node005, Received SwitchMultiLevel report: level=3
2020-01-15 09:36:25.102 Detail, Node005, Refreshed Value: old value=3, new value=3, type=byte
2020-01-15 09:36:25.102 Detail, Node005, Changes to this value are not verified
2020-01-15 09:36:25.102 Detail, Node005, Notification: ValueChanged

2020-01-15 09:36:25.122 Detail, Node005,   Received: 0x01, 0x18, 0x00, 0x13, 0x4c, 0x00, 0x00, 0x04, 0x00, 0xd8, 0x7f, 0x7f, 0x7f, 0x7f, 0x00, 0x00, 0x03, 0x00, 0x00, 0x00, 0x00, 0x03, 0x01, 0x00, 0x00, 0x65
2020-01-15 09:36:25.122 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0x4c received (expected 0x4c)
2020-01-15 09:36:25.123 Info, Node005, Request RTT 47 Average Request RTT 38
2020-01-15 09:36:25.123 Detail,   Expected callbackId was received

2020-01-15 09:36:25.140 Detail, Node005,   Received: 0x01, 0x0d, 0x00, 0x04, 0x00, 0x05, 0x05, 0x26, 0x03, 0x03, 0x03, 0x00, 0xd8, 0x00, 0x0b
2020-01-15 09:36:25.140 Detail,
2020-01-15 09:36:25.140 Info, Node005, Response RTT 65 Average Response RTT 50
2020-01-15 09:36:25.140 Info, Node005, Received SwitchMultiLevel report: level=3
2020-01-15 09:36:25.141 Detail, Node005, Refreshed Value: old value=3, new value=3, type=byte
2020-01-15 09:36:25.141 Detail, Node005, Changes to this value are not verified
2020-01-15 09:36:25.141 Detail, Node005,   Expected reply and command class was received
2020-01-15 09:36:25.141 Detail, Node005,   Message transaction complete
2020-01-15 09:36:25.141 Detail,
2020-01-15 09:36:25.141 Detail, Node005, Removing current message
2020-01-15 09:36:25.141 Detail, Node005, Notification: ValueChanged

jbeale1 · January 15, 2020, 6:26pm

turning the device off was even more chatty: 5 packets sent and 16 received, for a total of 21 messages. Here is the automation:

- id: '1579057907142'
  alias: LightOffAt8pm
  description: ''
  trigger:
  - at: '20:00'
    platform: time
  condition: []
  action:
  - device_id: 5c628ec259a24837b99b74aa5d1e1213
    domain: light
    entity_id: light.inovelli_unknown_type_c000_id_c002_level
    type: turn_off

And a summary of what happens when that is triggered:

cat Zwave-turnoff2.txt | grep "Sending" 
2020-01-15 10:14:14.812 Info, Node005, Sending (Send) message (Callback ID=0x55, Expected Reply=0x13) - SwitchMultilevelCmd_Set (Node=5): 0x01, 0x0a, 0x00, 0x13, 0x05, 0x03, 0x26, 0x01, 0x00, 0x25, 0x55, 0xb7
2020-01-15 10:14:14.841 Info, Node005, Sending (Send) message (Callback ID=0x56, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x56, 0xb5
2020-01-15 10:14:15.813 Info, Node005, Sending (Send) message (Callback ID=0x57, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x57, 0xb4
2020-01-15 10:14:15.883 Info, Node005, Sending (Send) message (Callback ID=0x58, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x58, 0xbb
2020-01-15 10:14:16.814 Info, Node005, Sending (Send) message (Callback ID=0x59, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x59, 0xba

cat Zwave-turnoff2.txt | grep "Received:" 
2020-01-15 10:14:14.819 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-01-15 10:14:14.840 Detail, Node005,   Received: 0x01, 0x18, 0x00, 0x13, 0x55, 0x00, 0x00, 0x03, 0x00, 0xda, 0x7f, 0x7f, 0x7f, 0x7f, 0x00, 0x00, 0x03, 0x00, 0x00, 0x00, 0x00, 0x03, 0x01, 0x00, 0x00, 0x79
2020-01-15 10:14:14.849 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-01-15 10:14:14.868 Detail, Node005,   Received: 0x01, 0x18, 0x00, 0x13, 0x56, 0x00, 0x00, 0x02, 0x00, 0xdb, 0x7f, 0x7f, 0x7f, 0x7f, 0x00, 0x00, 0x03, 0x00, 0x00, 0x00, 0x00, 0x03, 0x01, 0x00, 0x00, 0x7a
2020-01-15 10:14:14.886 Detail, Node005,   Received: 0x01, 0x0d, 0x00, 0x04, 0x00, 0x05, 0x05, 0x26, 0x03, 0x00, 0x00, 0x00, 0xdb, 0x00, 0x08
2020-01-15 10:14:15.821 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-01-15 10:14:15.843 Detail, Node005,   Received: 0x01, 0x18, 0x00, 0x13, 0x57, 0x00, 0x00, 0x02, 0x00, 0xda, 0x7f, 0x7f, 0x7f, 0x7f, 0x00, 0x00, 0x03, 0x00, 0x00, 0x00, 0x00, 0x03, 0x01, 0x00, 0x00, 0x7a
2020-01-15 10:14:15.860 Detail, Node005,   Received: 0x01, 0x0b, 0x00, 0x04, 0x00, 0x05, 0x03, 0x20, 0x03, 0x00, 0xda, 0x00, 0x0f
2020-01-15 10:14:15.879 Detail, Node005,   Received: 0x01, 0x0d, 0x00, 0x04, 0x00, 0x05, 0x05, 0x26, 0x03, 0x00, 0x00, 0x00, 0xda, 0x00, 0x09
2020-01-15 10:14:15.891 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-01-15 10:14:15.902 Detail, Node005,   Received: 0x01, 0x0d, 0x00, 0x04, 0x00, 0x05, 0x05, 0x26, 0x03, 0x00, 0x00, 0x00, 0xda, 0x00, 0x09
2020-01-15 10:14:15.923 Detail, Node005,   Received: 0x01, 0x18, 0x00, 0x13, 0x58, 0x00, 0x00, 0x04, 0x00, 0xda, 0x7f, 0x7f, 0x7f, 0x7f, 0x00, 0x00, 0x03, 0x00, 0x00, 0x00, 0x00, 0x03, 0x01, 0x00, 0x00, 0x73
2020-01-15 10:14:15.941 Detail, Node005,   Received: 0x01, 0x0d, 0x00, 0x04, 0x00, 0x05, 0x05, 0x26, 0x03, 0x00, 0x00, 0x00, 0xdb, 0x00, 0x08
2020-01-15 10:14:16.822 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-01-15 10:14:16.842 Detail, Node005,   Received: 0x01, 0x18, 0x00, 0x13, 0x59, 0x00, 0x00, 0x02, 0x00, 0xda, 0x7f, 0x7f, 0x7f, 0x7f, 0x00, 0x00, 0x03, 0x00, 0x00, 0x00, 0x00, 0x03, 0x01, 0x00, 0x00, 0x74
2020-01-15 10:14:16.928 Detail, Node005,   Received: 0x01, 0x0d, 0x00, 0x04, 0x00, 0x05, 0x05, 0x26, 0x03, 0x00, 0x00, 0x00, 0xda, 0x00, 0x09

freshcoast · January 15, 2020, 6:28pm

Normal behavior for OpenZWave (OZW) is to always follow up a Set with a Get (and Get until the value matches the expected). In addition, it looks like your device is sending a Basic Set after the level is reached, which is causing the extra chatter. When OZW receives a Basic Set, it triggers another Get because it translates the Basic Set into the Multilevel Command class, and does the Multilevel Get to obtain all the values associated with it.

There are various ways to change the behavior in the XML config file. There is a listing of all the compatibility flags for OZW 1.6 in the Wiki. I don’t know how well they are all supported in OZW 1.4 and they have different names. For example, whatever the equivalent of the BasicCommandClass IgnoreMapping flag in OZW 1.4 is should stop the Get after the Basic Set is received.

jbeale1 · January 15, 2020, 6:34pm

Thank you, this suggests what maybe is going on because the light does not snap on or off, but it seems to ramp up and down over 1-2 seconds so it makes sense that the Get polling continues until the final setpoint is reached. At some point maybe I’ll figure out how to change the dimmer speed. Presumably a simple on/off switch would turn off immediately and not trigger the extra Get statements. I guess I’ll find out when I get one of those.
Obviously I have much to learn about the Z-Wave system and OZW, I was not aware of a “Basic Set” function or of Z-wave devices controlling each other directly without going through a host controller; interesting.

michael.olson · August 9, 2020, 9:52pm

Did you ever figure out how to have HA turn this on/off instantly or just generally make this device behave more sensibly? Oddest Z-Wave device I have in my network, lots of chatter and managed to crash my qt-openzwave install just trying to communicate with it.