Z-wave Devices Spamming the log

Jonopo · July 10, 2019, 7:33am

So I've been trying to figure out why z-wave has issues with hubitat.

Here is a log of just 2 devices being turned off via the alexa skill. They are Honeywell Z-wave Plus Switches. Is this verbosity expected? The Craft Room Light reports itself on 40 time. is this why the z-wave stops working on hubitat? And its not just the craft room light.

dev:972019-07-10 01:20:06.764 am infoCraft Room Alcove is on [physical]

dev:972019-07-10 01:20:06.758 am infoBasicReport value: 255

dev:972019-07-10 01:20:06.755 am debugparse description: zw device: 16, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:06.446 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:06.440 am infoBasicReport value: 255

dev:962019-07-10 01:20:06.436 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:06.311 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:06.305 am infoBasicReport value: 255

dev:962019-07-10 01:20:06.301 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:06.234 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:06.226 am infoBasicReport value: 255

dev:962019-07-10 01:20:06.223 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:06.162 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:06.159 am infoBasicReport value: 255

dev:962019-07-10 01:20:06.143 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:06.072 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:06.068 am infoBasicReport value: 255

dev:962019-07-10 01:20:06.053 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:06.033 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:06.026 am infoBasicReport value: 255

dev:962019-07-10 01:20:06.023 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:05.997 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:05.990 am infoBasicReport value: 255

dev:962019-07-10 01:20:05.987 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:05.857 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:05.850 am infoBasicReport value: 255

dev:962019-07-10 01:20:05.846 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:05.811 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:05.804 am infoBasicReport value: 255

dev:962019-07-10 01:20:05.801 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:05.731 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:05.725 am infoBasicReport value: 255

dev:962019-07-10 01:20:05.721 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:05.403 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:05.392 am infoBasicReport value: 255

dev:962019-07-10 01:20:05.385 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:972019-07-10 01:20:05.337 am infoCraft Room Alcove is on [physical]

dev:972019-07-10 01:20:05.329 am infoBasicReport value: 255

dev:972019-07-10 01:20:05.325 am infoCraft Room Alcove is on [physical]

dev:972019-07-10 01:20:05.316 am debugparse description: zw device: 16, command: 2003, payload: FF , isMulticast: false

dev:972019-07-10 01:20:05.300 am infoBasicReport value: 255

dev:972019-07-10 01:20:05.293 am debugparse description: zw device: 16, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:05.289 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:05.273 am infoBasicReport value: 255

dev:972019-07-10 01:20:05.263 am infoCraft Room Alcove is on [physical]

dev:962019-07-10 01:20:05.259 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:972019-07-10 01:20:05.254 am infoBasicReport value: 255

dev:972019-07-10 01:20:05.245 am debugparse description: zw device: 16, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:05.239 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:05.232 am infoBasicReport value: 255

dev:962019-07-10 01:20:05.228 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:972019-07-10 01:20:05.177 am infoCraft Room Alcove is on [physical]

dev:972019-07-10 01:20:05.171 am infoBasicReport value: 255

dev:972019-07-10 01:20:05.168 am debugparse description: zw device: 16, command: 2003, payload: FF , isMulticast: false

dev:972019-07-10 01:20:04.850 am infoCraft Room Alcove is on [physical]

dev:972019-07-10 01:20:04.844 am infoBasicReport value: 255

dev:972019-07-10 01:20:04.840 am debugparse description: zw device: 16, command: 2003, payload: FF , isMulticast: false

dev:972019-07-10 01:20:04.820 am infoCraft Room Alcove is on [physical]

dev:972019-07-10 01:20:04.814 am infoBasicReport value: 255

dev:972019-07-10 01:20:04.811 am debugparse description: zw device: 16, command: 2003, payload: FF , isMulticast: false

dev:972019-07-10 01:20:04.788 am infoCraft Room Alcove is on [physical]

dev:972019-07-10 01:20:04.781 am infoBasicReport value: 255

dev:972019-07-10 01:20:04.776 am debugparse description: zw device: 16, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:04.345 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:04.338 am infoBasicReport value: 255

dev:962019-07-10 01:20:04.333 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:03.980 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:03.974 am infoBasicReport value: 255

dev:962019-07-10 01:20:03.970 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:03.600 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:03.594 am infoBasicReport value: 255

dev:962019-07-10 01:20:03.590 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:03.309 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:03.303 am infoBasicReport value: 255

dev:962019-07-10 01:20:03.297 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:03.212 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:03.206 am infoBasicReport value: 255

dev:962019-07-10 01:20:03.203 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:03.114 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:03.108 am infoBasicReport value: 255

dev:962019-07-10 01:20:03.104 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:972019-07-10 01:20:02.995 am infoCraft Room Alcove is on [physical]

dev:972019-07-10 01:20:02.988 am infoBasicReport value: 255

dev:972019-07-10 01:20:02.981 am debugparse description: zw device: 16, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:02.877 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:02.872 am infoBasicReport value: 255

dev:962019-07-10 01:20:02.868 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:972019-07-10 01:20:02.815 am infoCraft Room Alcove is on [physical]

dev:972019-07-10 01:20:02.808 am infoBasicReport value: 255

dev:972019-07-10 01:20:02.805 am debugparse description: zw device: 16, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:02.784 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:02.778 am infoBasicReport value: 255

dev:962019-07-10 01:20:02.774 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:02.740 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:02.734 am infoBasicReport value: 255

dev:962019-07-10 01:20:02.730 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:972019-07-10 01:20:02.635 am infoCraft Room Alcove is on [physical]

dev:972019-07-10 01:20:02.627 am infoBasicReport value: 255

dev:972019-07-10 01:20:02.623 am debugparse description: zw device: 16, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:02.097 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:02.091 am infoBasicReport value: 255

dev:962019-07-10 01:20:02.087 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:01.845 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:01.839 am infoBasicReport value: 255

dev:962019-07-10 01:20:01.835 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:01.805 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:01.798 am infoBasicReport value: 255

dev:962019-07-10 01:20:01.792 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:01.769 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:01.763 am infoBasicReport value: 255

dev:962019-07-10 01:20:01.759 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:01.563 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:01.557 am infoBasicReport value: 255

dev:962019-07-10 01:20:01.553 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:01.235 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:01.229 am infoBasicReport value: 255

dev:962019-07-10 01:20:01.225 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:972019-07-10 01:20:00.683 am infoCraft Room Alcove is on [physical]

dev:972019-07-10 01:20:00.675 am infoBasicReport value: 255

dev:972019-07-10 01:20:00.671 am debugparse description: zw device: 16, command: 2003, payload: FF , isMulticast: false

dev:972019-07-10 01:20:00.530 am infoCraft Room Alcove was turned on[digital]

dev:972019-07-10 01:20:00.522 am infoBasicReport value: 255

dev:972019-07-10 01:20:00.518 am debugparse description: zw device: 16, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:00.214 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:00.208 am infoBasicReport value: 255

dev:962019-07-10 01:20:00.204 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:00.140 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:00.131 am infoBasicReport value: 255

dev:962019-07-10 01:20:00.126 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:20:00.075 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:20:00.066 am infoBasicReport value: 255

dev:962019-07-10 01:20:00.061 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:992019-07-10 01:19:59.782 am infoIron is off [physical]

dev:962019-07-10 01:19:59.141 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:19:59.136 am infoBasicReport value: 255

dev:962019-07-10 01:19:59.131 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:19:59.072 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:19:59.064 am infoBasicReport value: 255

dev:962019-07-10 01:19:59.060 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:19:58.706 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:19:58.699 am infoBasicReport value: 255

dev:962019-07-10 01:19:58.696 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:19:58.528 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:19:58.521 am infoBasicReport value: 255

dev:962019-07-10 01:19:58.518 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:19:58.190 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:19:58.181 am infoBasicReport value: 255

dev:962019-07-10 01:19:58.176 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

dev:962019-07-10 01:19:57.678 am infoCraft Room Light is on [physical]

dev:962019-07-10 01:19:57.670 am infoBasicReport value: 255

dev:962019-07-10 01:19:57.667 am debugparse description: zw device: 15, command: 2003, payload: FF , isMulticast: false

JasonJoel · July 10, 2019, 7:35am

What does it do when turning on/off from the device detail page? Would be helpful to narrow down if this is a device issue, a driver issue, or an Alexa integration issue. If it acts normally when on/off from the device detail page, but not when controlling from Alexa, that would be very good information to include in an official support email to Hubitat...
What driver are you using for the devices - the in-box or a user driver? If a user driver, try it with the in-box driver and see if behavior changes.

craigspree · July 10, 2019, 11:42am

I just noticed this too after my z-wave devices have become sluggish with the latest updates last week.

My devices are using stock drivers.

I haven’t changed anything or added new drivers/apps other than update the HE firmware.

I have performed several z-wave mesh repairs. I have also shut down, unplugged the hub for 30 seconds and plugged it back in several times over the past few days.

Last night I looked in the logs and see my z-wave devices doing the same thing you posted here. Bulbs, switches, etc. I was actually going to post a similar thread today.

@mike.maxwell I’m curious if this is a known issue or if you could please tell us what additional steps you’d like us to take to help debug what might be happening (logs, list of all devices, etc). I know you are super busy and I want to be extremely respectful of your time.

craigspree · July 10, 2019, 11:48am

my devices mostly work fine from both the device page and apps like Alexa and Dashboards. I’ve noticed a few times in the past few days where motion sensors would trigger but lights associated with a rule would not turn on. I suspected a mesh issue and thus repaired my mesh and rebooted the hub (full shut down, unplug 30 seconds, plug back in). The shut down makes things run faster but after a day or two I noticed my z-wave devices getting sluggish again. I checked the logs last night and see the same behavior posted above. Lots of z-wave devices repeating their state 5-10 times in a row when triggered via RM 2.5 and RM 3 rules. This wasn’t happening before the recent updates. No other user code was added between updating the HE software and today.
these devices are all using built in drivers (generic z-wave...)

automation · July 10, 2019, 5:00pm

I had the same issue last night. I thought that it was just an anomaly with the switch. My Zwave devices froze during the process. I had issued a command to lock a zwave Schlage lock and was waiting on the lock to lock. It was delayed about 5 minutes before it finally locked. The lock normally locks immediately. I looked in the log and I saw where one of my Dome On/Off Zwave switches was continuously reporting an attribute over and over. The switch and the lock use stock drivers. Until I read this post, I thought it was just my switch. Im running the latest .119 firmware.

craigspree · July 10, 2019, 5:47pm

@bobbyD with 3 users here reporting the same symptoms, could you please let us know if is there an existing open ticket or knowledge of this among support? Thank you!

codahq · July 12, 2019, 8:25pm

I've been experiencing this for ages. I too would like to know what's going on. It is especially bad when a group of devices is turned off at the same time. I can reproduce this any time I want if anybody needs to see logs.

mike.maxwell · July 12, 2019, 11:31pm

What actual devices are being used here?, stock driver or not, the device is just spitting out endless basic reports...
I have seen the zwave q stall out if there's a secure command in the middle of a pile of other device commands, and the radio is having a tough time getting an ack from the lock...
But the first post just shows a switch basically gone spastic...
Unless there's an app command loop, or some refresh polling gone wild, which I'm not seeing in the logs...
@Jonopo, @JasonJoel asked the correct questions, but I've not seen your answers to them...

spalexander68 · July 12, 2019, 11:39pm

I have noticed some log weirdness as well.

I am getting double and sometimes triple log events for a lot of my devices, both Zigbee and Z-Wave.

Here is a snippet of what I am talking about. One is the Zooz 4 & 1 motion detector using built-in drivers and a Zigbee lock using in-house generic lock driver.

All devices work as intended from the device page and automations, its just putting extraneous entries into the logs.

Jonopo · July 13, 2019, 1:28am

What does it do when turning on/off from the device detail page?

I can get it and other switches to do this by quickly turning on and off a group a few times. I can actually be worse with this as I can turn it on and off quicker then with alexa.

What driver are you using for the devices - the in-box or a user driver?

Honeywell Jasco Z-Wave Plus Switch, Generic Z-Wave Smart Switch.

Jonopo · July 13, 2019, 1:29am

I have seen the zwave q stall out if there's a secure command in the middle of a pile of other device commands,

This might be it. as I have 2 Schlage BE469 Locks. This sounds like a bug and its sounds like its on the hub itself. Do you know if they are working on fixing that? That would be great news.

mike.maxwell · July 13, 2019, 1:34am

There is nothing that escapes us.

If you're running a massive good night routine that locks doors and turns everything off you might insert a delay of 5 seconds after your main devices and before the lock commands as a workaround.

craigspree · July 13, 2019, 2:26am

I’m guessing this is my issue too. I have 3 BE469 locks and the z-wave log spam seems to happen most frequently around the time the locks are used.

I know these locks have been causing a lot of headaches for the Hubitat staff and users. If the BE469s are still buggy I know it is not for lack of effort from Hubitat staff. I am confident the issues will get resolved.

Jonopo · July 13, 2019, 2:41am

If you're running a massive good night routine that locks doors and turns everything off you might insert a delay of 5 seconds after your main devices and before the lock commands as a workaround.

This specific example was just turning off a basement group no locks involved. Could a lock on the network cause the freezing just by virtue of being on the network?

mike.maxwell · July 13, 2019, 2:56am

Not that I've ever seen.
What actual devices are you using in your original post, and do they exhibit this behaviour when operated from the driver page?

brianwilson · July 13, 2019, 3:04am

Not seeing spamming but, me too on sluggishness and oddities. Back Door lock (BE469) showing as unlocked manually today at 4:50 pm, but it’s been locked and unlocked many times since. Lockdown ran tonight and it couldn’t lock it. Rebooted hub and still door lock is unresponsive to a refresh, configure or lock/unlock. But zwave details show its there.

mike.maxwell · July 13, 2019, 3:08am

Virtually ever unresponsive lock issue had been repeater mesh/related.
When communication is iffy, commands back up, then eventually timeout.
I have three zwave locks and two garage door controllers in addition to two or three locks running in the lab, I've not had any issues with them.

brianwilson · July 13, 2019, 3:10am

Ok. Things have been fine until recent update. Any way to see load on the device? If it’s showing in zwave details, shouldn’t the device show last updated with that time?

craigspree · July 13, 2019, 3:27am

Here is an example of the 'Spam' in my logs. I did not interact with the locks at the time of these log entries.

DEVICE info:
Inovelli 1 Channel Smart Plug NZW36

DRIVER:
Generic Z-Wave Outlet

LOG:

EVENTS:

I did not turn on or off the device at the time of the log spam. However, a few minutes later a rule was triggered that turned on the device (humidity in the basement was greater than 10% higher than the humidity in my living room), triggered via an Aeotec multi-sensor.

Device behaves normally when turning on/off from device page, dashboard, and Alexa.

cuboy29 · July 13, 2019, 4:20am

I get these repeating logs all the time too.