Multiple log entries for a single device event

I thought I had seen some discussion about this but I didn't find any with a "solved" status. I have several devices some z-wave some zigbee that seem to flood my logs with multiple entries for what I believe should be a single event.

Usually, this just results in the logging entries if it's a motion event, but I've noticed that it sometimes results in multiple executions of rules that are contact sensor triggered. All drivers for the devices are "system" not "user", so this may be some kind of logging or device firmware glitch but since it sometimes results in multiple triggers it seems like it may be an issue with the overall performance of HE?

This an example of the output from a dome dmms1 z-wave sensor logging:

dev:24852018-11-28 12:58:24.954 am infoBoys Room - Motion is active

dev:24852018-11-28 12:58:24.893 am infoBoys Room - Motion is active

dev:24852018-11-28 12:58:24.817 am infoBoys Room - Motion is active

dev:24852018-11-28 12:58:24.782 am infoBoys Room - Motion is active

dev:24852018-11-28 12:58:24.739 am infoBoys Room - Motion is active

dev:24852018-11-28 12:58:24.693 am infoBoys Room - Motion is active

dev:24852018-11-28 12:58:24.241 am infoBoys Room - Motion is active

dev:24852018-11-28 12:58:24.187 am infoBoys Room - Motion is active

Most of the time when I see this it's low batteries.

I think it's a Dome thing. Both of mine do that. My kids run back and forth chasing the dog under one of the Dome Motion sensors and it goes nuts.

100% battery

I have one Sensative strip device that does this - so far found no explanation. I have excluded, factory reset and reinstalled - still behaves the same.

Other Sensative strips behave flawlessly.

Still seems to function but the logs get crowded!

Bringing this back up...this device doesn't have batteries. Also I've seen this a lot in the logs. Sometimes 1 entry sometimes multiple. This one was a lot. There is 1 rule that turns this light on in the evening then off at night.

[dev:108](http://192.168.13.46/logs#dev108)2018-12-05 04:14:24.551 pm [info](http://192.168.13.46/device/edit/108)Entryway Zooz Power Switch Switch is on

[dev:108](http://192.168.13.46/logs#dev108)2018-12-05 04:14:23.673 pm [info](http://192.168.13.46/device/edit/108)Entryway Zooz Power Switch Switch is on

[dev:108](http://192.168.13.46/logs#dev108)2018-12-05 04:14:23.143 pm [info](http://192.168.13.46/device/edit/108)Entryway Zooz Power Switch Switch is on

[dev:108](http://192.168.13.46/logs#dev108)2018-12-05 04:14:22.779 pm [info](http://192.168.13.46/device/edit/108)Entryway Zooz Power Switch Switch is on

[dev:108](http://192.168.13.46/logs#dev108)2018-12-05 04:14:22.675 pm [info](http://192.168.13.46/device/edit/108)Entryway Zooz Power Switch Switch is on

[dev:108](http://192.168.13.46/logs#dev108)2018-12-05 04:14:22.508 pm [info](http://192.168.13.46/device/edit/108)Entryway Zooz Power Switch Switch is on

[dev:108](http://192.168.13.46/logs#dev108)2018-12-05 04:14:22.503 pm [info](http://192.168.13.46/device/edit/108)Entryway Zooz Power Switch Switch is on

[dev:108](http://192.168.13.46/logs#dev108)2018-12-05 04:14:22.339 pm [info](http://192.168.13.46/device/edit/108)Entryway Zooz Power Switch Switch is on

[dev:108](http://192.168.13.46/logs#dev108)2018-12-05 04:14:22.183 pm [info](http://192.168.13.46/device/edit/108)Entryway Zooz Power Switch Switch is on

[dev:108](http://192.168.13.46/logs#dev108)2018-12-05 04:14:22.104 pm [info](http://192.168.13.46/device/edit/108)Entryway Zooz Power Switch Switch is on

[dev:108](http://192.168.13.46/logs#dev108)2018-12-05 04:14:18.348 pm [info](http://192.168.13.46/device/edit/108)Entryway Zooz Power Switch Switch is on

I have this with my Zooz 4 in 1 sensor, it originally would give 2 entries with every event, now it is 3 entries with every event. Kinda weird.

Just bumping this thread as it came up when I searched for a problem I'm having also. This sensor is an Aeotec Multisensor 6s running the built in driver and on USB power so it's not battery related. The multiple entries also cause a delay in motion activated lights coming on. Whether that is because they are overloading the Zwave network with repeat events or something else I don't know, but surely you shouldn't get repeat events for motion active at all never mind that many spread over 3 seconds? Any thoughts @patrick ?

I have a rule that I run at night that turns off about 35 Leviton/GE dimmers and switches and I see multiple log entries for all the devices when it runs. So it actually takes almost 1 minute for everything to turn off. I upgraded the firmware on all the Leviton switches and it didn't change anything (other than fixing the status reporting issue).

Could this be an issue of overloading the Z-Wave network? I actually moved all my Hue lights to my secondary HE hub thinking that it was slowing the primary hub down, but no change in rule execution.

Any thoughts?

I swapped out the above switch with a different brand thinking the switch was bad...still seeing them same results. For me I'm pretty sure I've only seen it on zwave devices. I've been slowly swapping them out. Just assuming I'm having a zwave issue in the house...that I don't care to track anymore. I'm going Lutron caseta route as it doesn't have the zwave issues. I don't see this on any zigbee stuff....

sometimes it's twice. just grabbed this from the logs. or sometimes it's 10-15 times.

I'm not sure what's going on.

I only see the multiple log entries when I run a rule that is changing the status on lots (50+ ZWave+), 40 Zigbee devices at the same time. My next step will be to move all my zigbee to another HE and separate things this way to see if that helps speed up large rules.

Not to beat a dead horse, but did anyone ever find out why this multiple entry thing happens?
I'm experiencing a similar condition that arose recently on multiple z-wave devices (mostly GE wall switches/outlets & Fibaro motion sensors). Not only is there extra log traffic, but some controlled devices (mostly lights) are responding erratically. Sometimes they come on or go off, sometimes they don't. Sometimes repeat manual commands will get them in line, sometimes not. Often their current state does not reflect their actual state. I noticed that the occurrence of multiple log entries cropped up at about the same time.

Welcome to the community. I have not been able to resolve this issue. I am able to minimize it. Some devices seem to be worse than others. Most of my Zwave devices are either GE/Jasco or Leviton. Separating ZWave and Zigbee to different hubs had no real improvement. I ended up adding delays to my large rules turning off lots of devices. I turned the devices that don't send multiple log entries off first with a 15 second delay and then turn the bad ones off last. This seems to minimize the time the hub is bogged down with all the responses. It feels like this is really just a limitation of zwave protocols and too much traffic at the same time.

Thanks for feeding back!
Do you think it is an issue of connectivity? Do the Z-Wave devices report multiple times because they are not getting some confirmation back from the hub? I'm not sure why they would autonomously issue multiple reports like that.
I gotta admit, I don't really understand the inner workings of z-wave.
When you say 'minimize the time the hub is bogged down', do you believe that this multiple reporting causes issues where the hub might miss something because it is 'bogged down'? I still wonder if my inconsistent lighting issues are related to this multiple report issue or not.

Bumping this again (and tagging @bobbyD & @mike.maxwell):

I'm seeing issues with USB-powered Multisensor 6's (with the built in driver) reporting multiples of motion, humidity, etc. Note that these are all set to Z-wave selective reporting for the events other than motion. In this particular case, it appears (but I'm not sure) that it caused a 30 second delay in my closet light going on - note the two reports of Illuminence from a different sensor than the one that triggered for my closet:

[dev:168] 2020-05-02 02:13:50.925 pm [info] Guy's Closet Light switch is on
[dev:173] 2020-05-02 02:13:23.258 pm [info] Nic's Closet illuminance is 29 Lux
[dev:173] 2020-05-02 02:13:22.764 pm [info] Nic's Closet illuminance is 29 Lux
[dev:169] 2020-05-02 02:13:20.160 pm [info] Guy's Closet motion is active

Has anyone at Hubitat staff looked at these or attempted to track down whether these are actual issues or just log artifacts?

Thanks.

This is isually the device not getting a response from the hub, or getting a slow response, so it sends the report again.

So, I'm presuming this may be the cause of the delays I occasionally see, and, also, I know you folks are working on memory issues and other things that are most likely related to these issues, correct?

If so, I guess this means in the meantime before a fix, the only real course of action is a reboot to clear things up? I'm automatically rebooting every morning at around 3:30 am, but have occasionally found that I sometimes need to reboot in the middle of the day.

I've not heard nor seen any corelation between a slow hub situation and repeate device reports.

If that's the case, are you saying it's still likely a Z-wave network optimization issue?

That would be the first thing to look into

1 Like