LZW31 Duplicate messages flooding zwave network

fluid324 · July 4, 2021, 5:37am

Having some trouble with my black series dimmers. They seem to be flooding the zwave network with duplicate messages causing massive delays or simply failed actions.

Zooz 700 series S2 zwave stick
running zwavejs2mqtt hooked into homeassistant with the zwavejs integration.

I have 3 black series dimmers. 2 of them are connected to 2 separate loads (nodes 4 & 8), one of them is not (node 12). I created a zwave association group so the one that is NOT connected to any sort of load will control the other 2. This works fairly well, however i am not sure it is 100% the correct way.

Next problem comes in with trying to control these lights from homeassistant. since it seems like association groups only work when using local control and not through the network i created a “light group” in home assistant and aded nodes 4 & 8 to it. However, anytime that gets turned on/off in homeassistant the zwave logs get flooded with duplicate messages. the number of duplicates vary and it doesn’t happen every single time, but i would say about 80% of the time it simply does not work. Toggling the lights seems more reliable that trying to dim them but both ways run in to issues. Log below

2021-07-04 00:17:33.519 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 67
2021-07-04 00:17:36.672 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 67 => 67
2021-07-04 00:17:53.185 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 67 => 54
2021-07-04 00:17:56.334 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 54 => 54
2021-07-04 00:18:06.873 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 54 => 99
2021-07-04 00:18:09.408 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 00:18:23.407 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 0
2021-07-04 00:18:26.496 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:18:36.359 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 0 => 99
2021-07-04 00:18:48.549 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 99 => 50
2021-07-04 00:18:51.595 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 50 => 50
2021-07-04 00:18:56.028 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 50 => 99
2021-07-04 00:18:59.005 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 99 => 99
2021-07-04 00:19:09.565 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 52
2021-07-04 00:19:09.987 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 99 => 52
2021-07-04 00:19:12.689 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 52 => 52
2021-07-04 00:19:12.946 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 52 => 52
2021-07-04 00:19:19.795 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 52 => 99
2021-07-04 00:19:20.012 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 52 => 99
2021-07-04 00:19:22.879 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 00:19:23.139 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 99 => 99
2021-07-04 00:19:30.792 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 0
2021-07-04 00:19:33.942 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:34.031 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:34.115 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:35.085 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:35.728 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:36.057 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:36.569 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:36.757 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:36.788 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:36.873 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:36.957 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:36.987 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:37.021 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:37.089 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:37.331 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:37.355 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:37.514 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:37.817 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:37.859 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:37.960 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:38.040 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:39.084 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:19:59.272 INFO ZWAVE: Node 5: value updated: 32-0-currentValue 0 => 255
2021-07-04 00:19:59.288 INFO ZWAVE: Node 5: value updated: 113-0-Home Security-Motion sensor status 0 => 8
2021-07-04 00:20:11.706 INFO ZWAVE: Node 5: value updated: 32-0-currentValue 255 => 0
2021-07-04 00:20:11.720 INFO ZWAVE: Node 5: value updated: 113-0-Home Security-Motion sensor status 8 => 0
2021-07-04 00:20:11.937 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 99 => 0
2021-07-04 00:20:12.202 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:20:15.298 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 0 => 0
2021-07-04 00:20:28.567 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 0 => 99
2021-07-04 00:20:32.484 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 99 => 0
2021-07-04 00:20:35.511 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 0 => 0

First part is me controlling them from home assistant one at a time, not so bad. Then i turned on the light group, which worked. Then i turned the light group OFF at 00:19:30.792. One light did manage to turn off pretty quickly, but then 40 seconds later at 00:20:11.937 you can see the other one finally turned off. Kind of at a loss here, first venture into the zwave world but if i can’t get this performance ironed out. Node 4 is two hops from controller (node 4 - multiple neighbors - hub). The other 2 nodes here are direct to the hub. I am posting here as i am not noticing the same problem with other zwave switches i have that are controlled from homeassistant. Only these black series dimmers are giving me problems.

jtronicus · July 4, 2021, 5:43pm

When you set up Node 12 to control Nodes 4 and 8, did you also set up either Node 4 or 8 to control Node 12? If so, and you did not properly set parameter 12, you may have created an infinite loop (which would flood the zwave network).

Is your goal to have 3 switches grouped together as part of a virtual 4-way setup (so any of the 3 dimmers controls all 3), or are you trying to do something else?

fluid324 · July 4, 2021, 6:12pm

It’s a pseudo 4 way. As in if I operate either node 4 or node 8 independently I do not want them controlling the other switches. Only node 12 has associations to 4 and 8. I did not configure any associations on the others. Local control seems to be working. The real struggle is toggling/dimming the light group from home assistant. Where home assistant has a group that essentially creates a new single light containing nodes 4 and 8.

I feel like I could have a workaround but associations don’t work when controlled from home assistant/remotely. I see the config parameter for it but it stays set to [-1] Custom. If I disable it, [0] disabled, that sticks, but if I choose enable it just goes back to [-1] Custom. Then if I toggle node12 remotely it doesn’t trigger the associations. I feel like it should though as they function is present in other brand switches. Does that feature require the red series or something?

jtronicus · July 4, 2021, 7:15pm

If you havent already, I recommend both power-cycling the dimmers by pulling the air-gap, and then reinterviewing the nodes in zwavejs2mqtt (you dont need to exclude/include, just a reinterview).

Paramater 12 should look like this in zwavejs2mqtt (I dont have any black series dimmers, so my screenshot is from a red series. It should look similar though)

If everything works fine locally , I wouldnt think the config parameters are the issue though. Have you double-checked to make sure you dont have any automations that could be causing issues?

kelchm · July 4, 2021, 7:20pm

This is a bug in the display of partial parameters on the LZW31/LZW31-SN in recent releases that you can safely ignore – anytime you see -1 for one of these you can just read it as 1. I’ve been meaning to file a bug, but haven’t gotten to it yet.

fluid324 · July 4, 2021, 8:10pm

This is what mine look like. but it is the same for ALL (6) of my black series dimmers. The value will not change.

fluid324 · July 4, 2021, 8:11pm

From my experience it is not just a display bug as the associations only work locally and not through zwave hub. If it was just a display bug i should still be able to toggle node12 remotely and have it also toggle its associated nodes, 4 and 8.

fluid324 · July 4, 2021, 8:26pm

reinterviewed the 3 nodes after power cycling. Called light.turn_on from home assistant to the light group, then light.turn_off. This is what happens

2021-07-04 15:25:01.110 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 99
2021-07-04 15:25:01.192 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 15:25:01.241 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 15:25:01.352 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 15:25:01.386 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 15:25:01.439 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 15:25:01.497 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 0 => 99
2021-07-04 15:25:02.186 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 15:25:02.217 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 15:25:02.248 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 15:25:02.355 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 15:25:02.443 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 15:25:02.512 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 15:25:02.620 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 15:25:02.702 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 15:25:02.751 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 15:25:02.856 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 15:25:02.924 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 15:25:02.974 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 15:25:03.067 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 99
2021-07-04 15:25:10.728 ERROR ZWAVE-SERVER: Z-Wave error Failed to send the command after 3 attempts (Status Fail)
ZWaveError: Failed to send the command after 3 attempts (Status Fail)
at Driver.sendMessage (/usr/src/app/node_modules/zwave-js/src/lib/driver/Driver.ts:2271:23)
at Driver.sendCommand (/usr/src/app/node_modules/zwave-js/src/lib/driver/Driver.ts:2405:28)
at Driver.sendSupervisedCommand (/usr/src/app/node_modules/zwave-js/src/lib/driver/Driver.ts:2460:27)
at Driver.trySendCommandSupervised (/usr/src/app/node_modules/zwave-js/src/lib/driver/Driver.ts:2492:16)
at MultilevelSwitchCCAPI.set (/usr/src/app/node_modules/zwave-js/src/lib/commandclass/MultilevelSwitchCC.ts:172:47)
at Proxy.MultilevelSwitchCCAPI.<computed> (/usr/src/app/node_modules/zwave-js/src/lib/commandclass/MultilevelSwitchCC.ts:311:33)
at ZWaveNode.setValue (/usr/src/app/node_modules/zwave-js/src/lib/node/Node.ts:752:14)
at Function.handle (/usr/src/app/node_modules/@zwave-js/server/dist/lib/node/message_handler.js:19:44)
at Object.node (/usr/src/app/node_modules/@zwave-js/server/dist/lib/server.js:37:91)
at Client.receiveMessage (/usr/src/app/node_modules/@zwave-js/server/dist/lib/server.js:91:99)
2021-07-04 15:25:15.365 ERROR ZWAVE-SERVER: Z-Wave error Failed to send the command after 3 attempts (Status Fail)
ZWaveError: Failed to send the command after 3 attempts (Status Fail)
at Driver.sendMessage (/usr/src/app/node_modules/zwave-js/src/lib/driver/Driver.ts:2271:23)
at Driver.sendCommand (/usr/src/app/node_modules/zwave-js/src/lib/driver/Driver.ts:2405:28)
at Driver.sendSupervisedCommand (/usr/src/app/node_modules/zwave-js/src/lib/driver/Driver.ts:2460:27)
at Driver.trySendCommandSupervised (/usr/src/app/node_modules/zwave-js/src/lib/driver/Driver.ts:2492:16)
at MultilevelSwitchCCAPI.set (/usr/src/app/node_modules/zwave-js/src/lib/commandclass/MultilevelSwitchCC.ts:172:47)
at Proxy.MultilevelSwitchCCAPI.<computed> (/usr/src/app/node_modules/zwave-js/src/lib/commandclass/MultilevelSwitchCC.ts:311:33)
at ZWaveNode.setValue (/usr/src/app/node_modules/zwave-js/src/lib/node/Node.ts:752:14)
at Function.handle (/usr/src/app/node_modules/@zwave-js/server/dist/lib/node/message_handler.js:19:44)
at Object.node (/usr/src/app/node_modules/@zwave-js/server/dist/lib/server.js:37:91)
at Client.receiveMessage (/usr/src/app/node_modules/@zwave-js/server/dist/lib/server.js:91:99)
2021-07-04 15:25:21.656 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 99 => 0
2021-07-04 15:25:21.958 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 99 => 0
2021-07-04 15:25:24.866 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:24.931 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:24.977 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:25.092 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:25.194 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:25.207 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:25.255 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:26.058 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:26.089 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:26.137 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:26.281 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:26.350 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:26.418 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:26.624 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:26.683 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:26.729 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:26.757 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:26.829 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:26.891 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:26.924 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:26.935 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:26.967 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:27.049 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:27.101 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:27.116 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:27.164 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:27.249 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:27.390 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:27.515 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0
2021-07-04 15:25:27.810 INFO ZWAVE: Node 4: value updated: 38-0-currentValue 0 => 0

It seems something with homeassistant light groups and these dimmers do not play nicely together.

jtronicus · July 4, 2021, 8:47pm

Have you tried restarting zwavejsmqtt or the computer it is running on?

fluid324 · July 4, 2021, 9:23pm

everything has been restarted/rebooted multiple times. home assistant and zwavejs2mqtt are both current/up-to-date versions. Firmware on dimmers is latest stable. Healed the network to make sure things were correctly routing.

jtronicus · July 4, 2021, 9:35pm

and if you call light.turn_on for any individual dimmer, it works fine? Its only when you control the group that is floods the network?

fluid324 · July 4, 2021, 10:32pm

it does happen with turning them on individually from homeassistant, however not nearly as frequently nor does it send quite as many messages. Whereas turning on the group either the on or the off is almost guaranteed to send the flood of duplicate messages

kelchm · July 5, 2021, 1:02am

I haven’t experienced any change in behavior beyond the UI incorrectly showing the wrong sign for these values, but if you want to know for sure what is actually getting set for the parameter, turn on debug logging and check the logs.

2021-07-05T00:58:17.003Z DRIVER « [Node 018] [REQ] [BridgeApplicationCommand]
└─[ConfigurationCCReport]
parameter #: 12
value size: 1
value: 15

You can also use the ‘Custom Configuration’ option at the bottom of the config tab to get/set the raw value and bypass the partial parameters entirely if you want.

kelchm · July 5, 2021, 1:46am

I actually have experienced this quite a lot recently, among other performance issues on my Z-Wave network and have spent literally weeks trying to understand the root cause. I actually shared some very similar logs in an issue on the Z-Wave JS GitHub here.

I’ve since rebuilt my network multiple times over, moved from a 500 series to 700 series stick and also gotten a ‘zniffer’ stick setup. Unfortunately, none of these have been a complete fix, though I have managed to make incremental improvements in the overall performance.

IMO, what you are experiencing is not directly related the associations or the use of groups within Home Assistant, but is something you can likely reproduce anytime there is a significant amount of traffic being routed on your Z-Wave network.

Here’s an example from my own network of toggling 4 nodes (no associations) via the HA UI:

Z-Wave JS Log (Debug only for Node 15)

2021-07-05T01:39:51.366Z SERIAL » 0x011300a9010f076c01b103260100250000000037a6 (21 bytes)
2021-07-05T01:39:51.371Z DRIVER » [Node 015] [REQ] [SendDataBridge]
│ source node id: 1
│ transmit options: 0x25
│ route: 0, 0, 0, 0
│ callback id: 55
└─[SupervisionCCGet]
│ session id: 49
│ request updates: true
└─[MultilevelSwitchCCSet]
target value: 0
2021-07-05T01:39:51.380Z SERIAL « [ACK] (0x06)
2021-07-05T01:39:51.382Z SERIAL « 0x010401a90152 (6 bytes)
2021-07-05T01:39:51.384Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:51.386Z DRIVER « [RES] [SendDataBridge]
was sent: true
2021-07-05T01:39:51.399Z SERIAL « 0x011d00a93700000100ab7f7f7f7f00000300000000030100007f7f7f7f7fa8 (31 bytes)
2021-07-05T01:39:51.401Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:51.404Z DRIVER « [REQ] [SendDataBridge]
callback id: 55
transmit status: OK
2021-07-05T01:39:51.414Z SERIAL « 0x010e00a800010f056c0231ff0000ab59 (16 bytes)
2021-07-05T01:39:51.415Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:51.417Z DRIVER « [Node 015] [REQ] [BridgeApplicationCommand]
└─[SupervisionCCReport]
session id: 49
more updates follow: false
status: Success
duration: 0s
2021-07-05T01:39:51.420Z CNTRLR [Node 015] [~] [Multilevel Switch] currentValue: 1 => 0 [Endpoint 0]
2021-07-04 21:39:51.421 INFO ZWAVE: Node 15: value updated: 38-0-currentValue 1 => 0
2021-07-05T01:39:51.441Z SERIAL » 0x011300a90110076c01b203260100250000000038b5 (21 bytes)
2021-07-05T01:39:51.449Z SERIAL « [ACK] (0x06)
2021-07-05T01:39:51.452Z SERIAL « 0x010401a90152 (6 bytes)
2021-07-05T01:39:51.454Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:51.456Z DRIVER « [RES] [SendDataBridge]
was sent: true
2021-07-05T01:39:51.468Z SERIAL « 0x011d00a93800000100a57f7f7f7f00000300000000030100007f7f7f7f7fa9 (31 bytes)
2021-07-05T01:39:51.469Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:51.473Z DRIVER « [REQ] [SendDataBridge]
callback id: 56
transmit status: OK
2021-07-05T01:39:51.485Z SERIAL « 0x010e00a8000110056c0232ff0000a54b (16 bytes)
2021-07-05T01:39:51.487Z SERIAL » [ACK] (0x06)
2021-07-04 21:39:51.492 INFO ZWAVE: Node 16: value updated: 38-0-currentValue 1 => 0
2021-07-05T01:39:51.500Z SERIAL « 0x010e00a800010f056c0231ff0000ab59 (16 bytes)
2021-07-05T01:39:51.501Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:51.503Z DRIVER « [Node 015] [REQ] [BridgeApplicationCommand]
└─[SupervisionCCReport]
session id: 49
more updates follow: false
status: Success
duration: 0s
2021-07-05T01:39:51.520Z SERIAL » 0x011300a90111076c01b303260100250000000039b4 (21 bytes)
2021-07-05T01:39:51.528Z SERIAL « [ACK] (0x06)
2021-07-05T01:39:51.534Z SERIAL « 0x010401a90152 (6 bytes)
2021-07-05T01:39:51.535Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:51.537Z DRIVER « [RES] [SendDataBridge]
was sent: true
2021-07-05T01:39:51.546Z SERIAL « 0x011d00a93900000100ae7f7f7f7f00000300000000030100007f7f7f7f7fa3 (31 bytes)
2021-07-05T01:39:51.548Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:51.551Z DRIVER « [REQ] [SendDataBridge]
callback id: 57
transmit status: OK
2021-07-05T01:39:51.562Z SERIAL « 0x010e00a8000111056c0233ff0000ae40 (16 bytes)
2021-07-05T01:39:51.563Z SERIAL » [ACK] (0x06)
2021-07-04 21:39:51.569 INFO ZWAVE: Node 17: value updated: 38-0-currentValue 1 => 0
2021-07-05T01:39:51.577Z SERIAL « 0x010e00a800010f056c0231ff0000aa58 (16 bytes)
2021-07-05T01:39:51.578Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:51.581Z DRIVER « [Node 015] [REQ] [BridgeApplicationCommand]
└─[SupervisionCCReport]
session id: 49
more updates follow: false
status: Success
duration: 0s
2021-07-05T01:39:51.601Z SERIAL » 0x011300a9012d076c01b40326010025000000003a8c (21 bytes)
2021-07-05T01:39:51.609Z SERIAL « [ACK] (0x06)
2021-07-05T01:39:51.611Z SERIAL « 0x010401a90152 (6 bytes)
2021-07-05T01:39:51.613Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:51.615Z DRIVER « [RES] [SendDataBridge]
was sent: true
2021-07-05T01:39:51.625Z SERIAL « 0x010e00a8000110056c0232ff0000ca24 (16 bytes)
2021-07-05T01:39:51.626Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:51.633Z SERIAL « 0x011d00a93a00000100a07f7f7f7f00000300000000030100007f7f7f7f7fae (31 bytes)
2021-07-05T01:39:51.635Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:51.637Z DRIVER « [REQ] [SendDataBridge]
callback id: 58
transmit status: OK
2021-07-05T01:39:51.698Z SERIAL « 0x010e00a8000111056c0233ff0000b25c (16 bytes)
2021-07-05T01:39:51.700Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:51.744Z SERIAL « 0x010e00a800010f056c0231ff0000b143 (16 bytes)
2021-07-05T01:39:51.745Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:51.747Z DRIVER « [Node 015] [REQ] [BridgeApplicationCommand]
└─[SupervisionCCReport]
session id: 49
more updates follow: false
status: Success
duration: 0s
2021-07-05T01:39:51.787Z SERIAL « 0x010e00a800010f056c0231ff0000c032 (16 bytes)
2021-07-05T01:39:51.789Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:51.791Z DRIVER « [Node 015] [REQ] [BridgeApplicationCommand]
└─[SupervisionCCReport]
session id: 49
more updates follow: false
status: Success
duration: 0s
2021-07-05T01:39:51.837Z SERIAL « 0x010e00a800010f056c0231ff0000c032 (16 bytes)
2021-07-05T01:39:51.839Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:51.841Z DRIVER « [Node 015] [REQ] [BridgeApplicationCommand]
└─[SupervisionCCReport]
session id: 49
more updates follow: false
status: Success
duration: 0s
2021-07-05T01:39:51.952Z SERIAL « 0x010e00a800012d056c0234ff0000ca1f (16 bytes)
2021-07-05T01:39:51.956Z SERIAL » [ACK] (0x06)
2021-07-04 21:39:51.966 INFO ZWAVE: Node 45: value updated: 38-0-currentValue 1 => 0
2021-07-05T01:39:52.588Z SERIAL « 0x010c00a800010f0326030000c0b3 (14 bytes)
2021-07-05T01:39:52.592Z CNTRLR [Node 015] [~] [Multilevel Switch] currentValue: 0 => 0 [Endpoint 0]
2021-07-04 21:39:52.594 INFO ZWAVE: Node 15: value updated: 38-0-currentValue 0 => 0
2021-07-05T01:39:52.597Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:52.601Z DRIVER « [Node 015] [REQ] [BridgeApplicationCommand]
└─[MultilevelSwitchCCReport]
current value: 0
2021-07-05T01:39:52.645Z SERIAL « 0x010c00a80001100326030000caa6 (14 bytes)
2021-07-04 21:39:52.647 INFO ZWAVE: Node 16: value updated: 38-0-currentValue 0 => 0
2021-07-05T01:39:52.649Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:52.660Z SERIAL « 0x010c00a80001110326030000b2df (14 bytes)
2021-07-04 21:39:52.662 INFO ZWAVE: Node 17: value updated: 38-0-currentValue 0 => 0
2021-07-05T01:39:52.664Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:52.781Z SERIAL « 0x010c00a800012d0326030000ca9b (14 bytes)
2021-07-04 21:39:52.785 INFO ZWAVE: Node 45: value updated: 38-0-currentValue 0 => 0
2021-07-05T01:39:52.789Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:54.924Z SERIAL « 0x011300a800010f0a3202213400000000000000c0a5 (21 bytes)
2021-07-05T01:39:54.929Z CNTRLR [Node 015] [~] [Meter] value[66049]: 1.6 => 0 [Endpoint 0]
2021-07-04 21:39:54.931 INFO ZWAVE: Node 15: value updated: 50-0-value-66049 1.6 => 0
2021-07-05T01:39:54.934Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:54.939Z DRIVER « [Node 015] [REQ] [BridgeApplicationCommand]
└─[MeterCCReport]
type: Electric
scale: W
rate type: Consumed
value: 0
time delta: 0 seconds
2021-07-05T01:39:54.979Z SERIAL « 0x011300a80001100a3202213400000000000000cab0 (21 bytes)
2021-07-04 21:39:54.981 INFO ZWAVE: Node 16: value updated: 50-0-value-66049 1.6 => 0
2021-07-05T01:39:54.983Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:54.990Z SERIAL « 0x011300a80001110a3202213400000000000000b1ca (21 bytes)
2021-07-04 21:39:54.992 INFO ZWAVE: Node 17: value updated: 50-0-value-66049 1.6 => 0
2021-07-05T01:39:54.994Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:55.104Z SERIAL « 0x011300a800012d0a3202213400000000000000ca8d (21 bytes)
2021-07-04 21:39:55.109 INFO ZWAVE: Node 45: value updated: 50-0-value-66049 1.6 => 0
2021-07-05T01:39:55.112Z SERIAL » [ACK] (0x06)
2021-07-05T01:39:56.536Z SERIAL « 0x011300a80001130a3202213400000010000000a4cd (21 bytes)
2021-07-04 21:39:56.541 INFO ZWAVE: Node 19: value updated: 50-0-value-66049 1.6 => 1.6
2021-07-05T01:39:56.544Z SERIAL » [ACK] (0x06)

Zniffer Log (Filtered to Node 15)

1	04.07.21	21:39:51.914	100K	67	0	0	1	15	CFDCE908	Singlecast	Supervision Get	CFDCE908014109120F6C01B1032601000459
2	04.07.21	21:39:51.923	100K	59	0	0	15	1	CFDCE908	Ack		CFDCE9080F03090B011960
3	04.07.21	21:39:51.941	100K	59	0	0	15	1	CFDCE908	Singlecast	Supervision Report	CFDCE9080F410910016C0231FF009EEB
4	04.07.21	21:39:51.946	100K	66	0	0	1	15	CFDCE908	Ack		CFDCE9080103090B0F3706
9	04.07.21	21:39:52.025	100K	59	0	0	15	1	CFDCE908	Singlecast	Supervision Report	CFDCE9080F410910016C0231FF009EEB
10	04.07.21	21:39:52.030	100K	67	0	0	1	15	CFDCE908	Ack		CFDCE9080103090B0F3706
11	04.07.21	21:39:52.058	40K	60	1	0	15	1	CFDCE908	Singlecast	Supervision Report	CFDCE9080F51090F016C0231FF00F4
23	04.07.21	21:39:52.271	40K	61	1	0	15	1	CFDCE908	Singlecast	Supervision Report	CFDCE9080F510A0F016C0231FF00F7
24	04.07.21	21:39:52.275	40K	73	1	0	1	15	CFDCE908	Ack		CFDCE90801138A0A0F90
25	04.07.21	21:39:52.306	40K	61	1	0	15	2(1)	CFDCE908	Routed:(15)->2 - (1)	Supervision Report	CFDCE9080F810712010010026C0231FF0025
26	04.07.21	21:39:52.313	40K	71	1	0	2(15)	1	CFDCE908	Routed:(15) - 2->(1)	Supervision Report	CFDCE9080F810712010011026C0231FF0024
27	04.07.21	21:39:52.322	40K	73	1	0	1	2(15)	CFDCE908	Routed:(15) - 2<-(1)	Routed Ack	CFDCE908018107120F0B1002417F7F7F7FCF
28	04.07.21	21:39:52.329	40K	71	1	0	2(1)	15	CFDCE908	Routed:(15)<-2 - (1)	Routed Ack	CFDCE90801C107120F0B1F0241D47F7F7F2B
29	04.07.21	21:39:52.340	40K	61	1	0	15	2	CFDCE908	Ack		CFDCE9080F03070A020E
30	04.07.21	21:39:52.355	40K	61	1	0	15	2(1)	CFDCE908	Routed:(15)->2 - (1)	Supervision Report	CFDCE9080F810712010010026C0231FF0025
31	04.07.21	21:39:52.364	40K	71	1	0	2(15)	1	CFDCE908	Routed:(15) - 2->(1)	Supervision Report	CFDCE9080F810712010011026C0231FF0024
32	04.07.21	21:39:52.399	40K	66	1	0	1	2(15)	CFDCE908	Routed:(15) - 2<-(1)	Routed Ack	CFDCE908018107120F0B1002417F7F7F7FCF
33	04.07.21	21:39:52.408	40K	70	1	0	2(1)	15	CFDCE908	Routed:(15)<-2 - (1)	Routed Ack	CFDCE90801C107120F0B1F0241D47F7F7F2B
34	04.07.21	21:39:52.418	40K	60	1	0	15	2	CFDCE908	Ack		CFDCE9080F03070A020E
40	04.07.21	21:39:53.106	40K	60	1	0	15	2(1)	CFDCE908	Routed:(15)->2 - (1)	Switch Multilevel Report	CFDCE9080F81081001001002260300AD
41	04.07.21	21:39:53.114	40K	71	1	0	2(15)	1	CFDCE908	Routed:(15) - 2->(1)	Switch Multilevel Report	CFDCE9080F81081001001102260300AC
42	04.07.21	21:39:53.121	40K	73	1	0	1	2(15)	CFDCE908	Routed:(15) - 2<-(1)	Routed Ack	CFDCE908018108120F0B1002417F7F7F7FC0
43	04.07.21	21:39:53.131	40K	71	1	0	2(1)	15	CFDCE908	Routed:(15)<-2 - (1)	Routed Ack	CFDCE90801C108120F0B1F0241D47F7F7F24
44	04.07.21	21:39:53.144	40K	60	1	0	15	2	CFDCE908	Ack		CFDCE9080F03080A0201
57	04.07.21	21:39:55.442	40K	60	1	0	15	2(1)	CFDCE908	Routed:(15)->2 - (1)	Meter Report	CFDCE9080F8109170100100232022134000000000000AB
58	04.07.21	21:39:55.452	40K	71	1	0	2(15)	1	CFDCE908	Routed:(15) - 2->(1)	Meter Report	CFDCE9080F8109170100110232022134000000000000AA
59	04.07.21	21:39:55.459	40K	73	1	0	1	2(15)	CFDCE908	Routed:(15) - 2<-(1)	Routed Ack	CFDCE908018109120F0B1002417F7F7F7FC1
60	04.07.21	21:39:55.467	40K	70	1	0	2(1)	15	CFDCE908	Routed:(15)<-2 - (1)	Routed Ack	CFDCE90801C109120F0B1F0241D37F7F7F22
61	04.07.21	21:39:55.477	40K	60	1	0	15	2	CFDCE908	Ack		CFDCE9080F03090A0200

fluid324 · July 5, 2021, 2:07am

read your github issue and yes it does sound just like what i am experiencing. Thanks for that info, however all of this seems to be way over my head for debugging zwave network issues for the time being at least. Was trying to move away from my wifi switches but those have been extremely reliable and might just need to go back to them.

I did test this with both the Aoetec Zstick Gen5, as well as my current stick, the Zooz ZST10-700, neither made a difference. For the time being i will try and avoid using groups in homeassistant to change the lights but that is going to be a little prohibitive and might end up just putting my old switches back in.

kelchm · July 5, 2021, 2:37am

Here’s an even better example of this behavior which I was able to capture while simply toggling the state of one node on it’s own. This looks to me like evidence of a firmware bug.

@EricM_Inovelli could you please take a look at this thread and in particular the GitHub Gist I’ve linked above?

Some additional details:

Node 01: Silicon Labs UZB-7 (firmware v7.15.4)
Node 02: Aeotec Network ZW189-C15 (firmware v1.3)
Node 17: Inovelli LZW31-SN (firmware v1.56)

All three of these nodes are in the same room and within ~20ft of each other and have a direct line of sight between them.

EricM_Inovelli · July 9, 2021, 9:26pm

I have only seen this issue before on the Hubitat C7 running the 700 series chip. What we have had explained by our engineer is that the controller on the hub is not responding in time with ACK and the switch is sending duplicate messages (believing that the initial ones have been lost). This looks very similar but I am not sure if it is the same.

fluid324 · July 9, 2021, 9:43pm

I am running a 700 series hub, however, i tested with a 500 series hub and was getting the same results. Novice when it comes to zwave still but if there is anything more i can provide to assist let me know how to go about doing so.

kelchm · July 10, 2021, 1:16pm

I am using a 700 series stick (Silcon Lab’s reference design SLUSB001A with firmware included in the 7.15.4 SDK. I was able to reproduce this with a HUSBZB-1, which is a 500 series stick.

The delay until the first ACK was only 10ms and only 5ms for the second. What is the actual timeout before retrying?

jreed509 · August 31, 2021, 3:58am

I’m also seeing this issue using an Aeotec Z-Stick Gen5+. It definitely causes pretty significant slowdowns when controlling a large number of switches.

For me this is most noticeable when traffic is high on my zwave network. For example, when triggering my goodnight scene that turns off ~20 Inovelli Red switches and dimmers, my network is unresponsive for 30-45 seconds after triggering the scene due to repeated messages. In some cases I see as many as 15-20 repeat value reports per node!

I’ve managed to improve things a bit using multicast through zwave_js (at least now the lights turn off quickly), but the network congestion caused by this is still an issue.