Log Spam StartNotification and stopNotification

I original was running many of my notifications per this thread…

Since then I have added Dimmers and a Few other switches and I have attempted to now use the Startnotification and/or stopnotification commands added to the driver some months back. But I now get a lot if rapid chatter in the log that seems to slow down the RM as each notification triggers commands to about 10 switches it takes a bit of time to run… It takes about 15 seconds to set the parameter 8 values across these 10 switches…


@EricM_Inovelli should I be seeing so many logs or expecting a faster response time?

Something doesn’t seem right there. It looks like multiple commands are getting sent to each device. Do you have possible overlapping rules? Also, you can disable the logs in the device preferences. First we should probably figure out how multiple commands are being sent though.

Example of my rule that changes LED bars to solid red or solid green:

When you say turn off logging I would assume just the debug logging… These screenshots are two different notification triggeded by the same rule/command in RM4

The rule is a rather simple rule with a door open equals one notification vs door closed second notification… It sets the LED on 3 Dimmers, and 7 Switches…

My command is StartNotification, but yours seems to be Set Indicator…

Yeah, setIndicator just calls startNotification so it is essentially the same.

Man, that is crazy that you are getting so many reports from what seems to be a single command. What firmware version do you have? Also, it looks like it is happening on the dimmer and the switch right?

Lastly, a couple things to try. If you reboot the switch by pulling the air gap and pushing it back in does it still do the same? Does it do the same when you send the command through the device page?

image

I noticed the same thing a couple of days ago but thought it was just an anomaly. I was on Firmware 1.44 but updated (both components) to 1.47 yesterday. I was using the latest version of the driver though.

Looked in the logs but those entries have dropped off now :slightly_frowning_face:

Just tested from the device page on one of the three dimmers and if saw double messaging in some cases as I toggled between startNotification and stopnotification

These Dimmers are on 1.45. This also was after a reboot of the Hub with Platform update
2.2.2.145 this morning…

Triggered from the Device panel. Quickly sending the notification command seems to trigger the issue…
The s switches are 1.17 or 1.19

I seeing similar behavior with 1.47 (both components). It doesn’t happen all the time as shown below.

Multiple startNotifications:


Note: There is no “stopNotification” entry but the LED did change back.
Correct startNotification:

The startNotification/stopNotification are based on lock/unlock triggers for a lock. One thing that I noticed was that when there were multiple entries, it takes a lot longer for the LED to change back after the door is locked. In the above examples, when the entries were “correct”, the LED turned back to normal almost as soon as the door was locked. In the second case, it took about 30 seconds or so (enough for me to notice).

Is this a new development since a possible Hubitat firmware update? I’m not pointing fingers I’m just curious why this seems to be popping up all of the sudden.

I don’t believe its new, but its only that I switched my rules from using the built in Notification “Child” devices to the enabled set notification/ stop notification. I had then noticed a bit of a slowdown when the rule triggers and started to investigate and the logs show a single command and multiple log entries…

I can post on Hubitat if you think its might be on the Hub side, but wanted to start here…

I’m trying to recall if I saw it before the Hubitat upgrade, but frankly, I can’t be sure. I was looking at the logs closely only since the 1.47 firmware update because of the “flickering” issue I was having. The one thing I am certain of is that the intermittent lags between the locking and the LED responding to the stopNotification have been going on for a while (I started using this feature about 3 weeks ago)

So I wanted to validated that my Rule was not triggering this problem so I created a simple rule driven from a virtual switch…Switch on = StartNotification, Switch Off = StopNotification

Runs perfectly

Copied the Rule 7 Switches to the same notification value = Log Spam…

image

I’ve been going back and forth with our main z-wave engineer about this. His belief is that the Z-Wave sdk is sending multiple reports because the hub is not responding with an “ack” packet. You can see this in my quick zniffer log. The hub sent a “Configuration Get” and the switch responds with an “Ack”. The switch then sends a Configuration Report and the hub does not respond. So it sends it again . . . and then a third time (in which the hub finally responds with an “Ack”).

This really makes me wonder if something has changed on the Z-wave side of the hub. Can you try doing a z-wave repair? Maybe if your network is optimized it will behave better.

I will run a repair and report back…Have avoided the zniffer so far, but your comments/screen shot makes me want to inspect from my side…Is it worth the expense for the average consumer?

Hmmm, that is a good question. I would say based on the price it is worth it. I use it a lot but I have to do a lot of testing and troubleshooting. If it cost $50+ plus I would say that the average user shouldn’t worry about it. At the ~$30 price point it is a useful tool to have for a tinkerer.

The repair completed, but no obvious effect to the message in the log…

FWIW - my rule only sends the start/stop notification to one device. I don’t always get the multiple log entries, but I sometimes do. :man_shrugging:t4:

I also noticed that sometimes the status of my lock will not change (it will show unlocked but it’s been physically locked). The “unlock” status update seems to happen always (and that’s what triggers the startNotification). I have added a rule that refreshes the lock every 30 seconds but I don’t think that’s what is causing the multiple entries.

Very strange, if you do ask Hubitat about it I’d be interested in knowing if they have any idea what is going on. As I mentioned it is the z-wave protocol that seems to be re-sending the reports because it isn’t getting an ‘awk’. Maybe too many z-wave messages coming in at the same time causing the radio to get over burdened? We can try to disable the “configurationGet” that is part of the startNotification call. In the “startNotification” method comment out or delete this line:

cmds << zwave.configurationV1.configurationGet(parameterNumber: parameterNumbers[(ep == null)? 0:ep?.toInteger()-1])

Edit: this will definitely correct the multiple reports because it isn’t asking for the report anymore. I just figure that they aren’t really needed and if it makes your z-wave perform better we might as well.

I will give this a try and watch for and interesting side effects…

1 Like

I have continued to run with lines in the drivers Scene enable switches removed, but now that I am watching the logs digging into the investigation further I see some duplication in the Black Switch that when I change the LED color at night when HSM arms…

Also a bit of spam around Basic reports for one of the black switch.

If it helps the Stick I need for the Zniffer will arrive on Monday, but till then I should I am glad with that the extra logging doesn’t seem to influence the network too much, but want to get down to any potential latency impact on the z-wave network…

I got a surprise today package in the mail today early from Digikey and the Zniffer is up an running, don’t know exactly what I am looking at, but am seeing a significant number of routing errors at times, also I see a little bit of my network traffic at the slower 9.6Kbit/s speed. Need to determine what device is causing that…

Also reverted the Drivers to the default state so I could possibly monitor the effect in the zniffer

2 Likes