Multiple Logged Events for Single Action

[raidflex]

So I was doing some testing with the latest update 2.2.3.132 and after turning on descriptive text logging for a couple Leviton DZ6HD dimmers I am receiving a bunch of events in the logs for a single action. Normally I leave this logging off to cut down on log entries, but something is very wrong here.

For example below is two different Leviton DZ6HD dimmers and all I did was turn each one on 1 time from the switch. This is the first time experiencing this issue and the result is the same either from the physical switch or if I use HE to control the light.

I am using the Generic Z-Wave Smart Dimmer driver.

I do not experience the issue with the Zigbee bulbs that I have.

[jvm33]

I'm seeing this too and its particularly problematic for a homebridge plugin I"m writing which monitors the Hubitat eventstream via a websocket.

[raidflex]

I am still experiencing this issue on 2.2.3.135.

[raidflex]

I am just looping in @mike.maxwell and @gopher.ny for further feedback into this issue, not sure if this is a known issue. Thanks.

[raidflex]

Would be nice to get some feedback on if this issue is being looked into, Thanks.

[gopher.ny]

Can't reproduce it yet, but I've created a GitHub issue and will be on lookout for similar occurrences.

[raidflex]

Thanks. Yeah not sure whats causing it, but I can easily reproduce it with any of my Leviton DZ6HD or GE dimmers. And I never noticed it until the first 2.2.3 update.

I also noticed that even with motion lighting I see 4 events in the log for 1 action.

[jvm33]

@raidflex is not alone in this. I also get massive repeating of log events. E.g., See image below:

[Hasty1]

How many concurrent zwave events are happening with this and which hub do you have?

[jvm33]

C7 hub. Latest firmware (2.2.3.145). It also happend on the last few 2.2.3.x versions. This is an unpredictable occurrence - sometimes everything is fine. Other times, there is a burst of these log messages for one physical or control action.

As a further investigation, I wrote a simple JavaScript program to monitor the eventStream port and these messages are repeated on the eventStream - so its not just a logging issue, these are events that propagate through the system. That can't be good for performance!

[Hasty1]

I wonder if it’s related to this

Z-Wave storms - looks like HE Hub's fault?

Ok Zniffer trace and hub log output below. It's the hub that is spamming with loads of Basic Get commands and the log just shows the responses to the Get. I've been chasing phantom nodes and buying $100 of debugging equipment by now. Doesn't this look like HE is the culprit? What am I missing? I have turned off scenes and groups. This is just a RuleMachine 4.0 turning on a fan, triggered by a doubleclick of a switch. [hubitat] [zniff]

[raidflex]

@Hasty1

How many concurrent zwave events are happening with this and which hub do you have?

I have a C5 hub, if I turn on a single switch I will see 4 events for that single action. It doesn't matter if it is from the physical switch, HE or motion lighting, all will exhibit the same issue.

[raidflex]

@jvm33

As a further investigation, I wrote a simple JavaScript program to monitor the eventStream port and these messages are repeated on the eventStream - so its not just a logging issue, these are events that propagate through the system. That can't be good for performance!

This would also prob explain the increased latency I have seen also.

[tony.fleisher]

I just saw something like this on my C7 with the 145 firmware while I was running a zwave repair.
Just as the Zooz Double Plug was starting repair, it reported power, and the logs showed the reports duplicated a dozen or so times

[mark.amber]

Throwing my hat into the ring too. I am seeing these multiple logged events for single actions very much the same as the others are reporting. Its a very common occurrence and can't be good for overall performance both to the mesh and the hub itself.

For reference, I have a C7 Hub running version 2.2.3.145.

[cj_rezz]

I am also noticing this in my logs, especially when I activate a scene:

[jvm33]

@cj_rezz

I am also noticing this in my logs, especially when I activate a scene:

Did you find a solution - I'm still having this problem. I'm hoping this is to be fixed in the next firmware (2.2.4), but I haven't seen much to indicate one way or another if that's the case.

[raidflex]

The drivers need to be fixed, not much else we can do unfortunately.

[JasonJoel]

I'm not so sure it is universally a driver problem based on sniffer logs...

It is hard for me to tell for sure though, because it rarely happens on my c7 hubs.

A couple times I've caught it though the hub was sending a command, and getting responses from the end device in the expected time frame, but then sent the same command out a bunch more times.

And in those cases I've verified it was not the driver asking it to send the commands multiple times.

So it is still a bit of a mystery to me. I'm just happy it is very rare on my hubs.

My guess is this is one of those things that will magically stop happening at some point after an update, and no one will know exactly why.

[raidflex]

@JasonJoel

I'm not so sure it is universally a driver problem based on sniffer logs...

It is hard for me to tell for sure though, because it rarely happens on my c7 hubs.

A couple times I've caught it though the hub was sending a command, and getting responses from the end device in the expected time frame, but then sent the same command out a bunch more times.

And in those cases I've verified it was not the driver asking it to send the commands multiple times.

So it is still a bit of a mystery to me. I'm just happy it is very rare on my hubs.

Well something changed in the 2.2.3 versions, because when I reverted back to 2.2.2 the issue was not present.

There may be differences between hub versions as well because I am on a C4, so not sure.