Why does the log show status change every few minutes?

[ryuvann]

Was debating on buying this plugin but the log shows status updates constantly when nothing has changed, anyone know why it does this? Here's just one small section of it:

Aug-06 10:10:20 AM EnvisaLink INFO Partition 1 status change: Ready
Aug-06 10:06:10 AM EnvisaLink INFO Partition 1 status change: Ready
Aug-06 10:02:00 AM EnvisaLink INFO Partition 1 status change: Ready
Aug-06 9:57:50 AM EnvisaLink INFO Partition 1 status change: Ready
Aug-06 9:53:40 AM EnvisaLink INFO Partition 1 status change: Ready
Aug-06 9:49:30 AM EnvisaLink INFO Partition 1 status change: Ready
Aug-06 9:45:20 AM EnvisaLink INFO Partition 1 status change: Ready
Aug-06 9:41:10 AM EnvisaLink INFO Partition 1 status change: Ready
Aug-06 9:37:00 AM EnvisaLink INFO Partition 1 status change: Ready
Aug-06 9:32:50 AM EnvisaLink INFO Partition 1 status change: Ready
Aug-06 9:28:40 AM EnvisaLink INFO Partition 1 status change: Ready
Aug-06 9:24:30 AM EnvisaLink INFO Partition 1 status change: Ready

[randy]

If you change the log level from "Info" you won't get as many log entries. If you have it set to info, it will log every time the system changes status which is fairly constant. Mine will generate an entry with every PIR, door/window or other device when it is in the info logging mode. I normally leave mine at "Warning". This is as a result of the panel reporting it not a problem with the plug-in. Here is just a few minutes of mine with the log level set to info:

Aug-06 8:23:12 AM EnvisaLink INFO LR Motion status change: Closed
Aug-06 8:23:10 AM EnvisaLink INFO LR Motion status change: Opened
Aug-06 8:22:35 AM EnvisaLink INFO Partition 1 status change: Not Ready
Aug-06 8:22:35 AM EnvisaLink INFO Dining Room Door status change: Opened
Aug-06 8:22:16 AM EnvisaLink INFO Partition 1 status change: Ready - Force Arming Enabled
Aug-06 8:22:16 AM EnvisaLink INFO LR Motion status change: Opened
Aug-06 8:21:36 AM EnvisaLink INFO Partition 1 status change: Ready
Aug-06 8:21:36 AM EnvisaLink INFO LR Motion status change: Closed
Aug-06 8:21:35 AM EnvisaLink INFO Partition 1 status change: Ready - Force Arming Enabled
Aug-06 8:21:35 AM EnvisaLink INFO LR Motion status change: Opened
Aug-06 8:21:29 AM EnvisaLink INFO Partition 1 status change: Ready
Aug-06 8:21:29 AM EnvisaLink INFO LR Motion status change: Closed
Aug-06 8:21:28 AM EnvisaLink INFO Partition 1 status change: Ready - Force Arming Enabled
Aug-06 8:21:27 AM EnvisaLink INFO LR Motion status change: Opened
Aug-06 8:21:27 AM EnvisaLink INFO Partition 1 status change: Ready
Aug-06 8:21:27 AM EnvisaLink INFO LR Motion status change: Closed
Aug-06 8:21:27 AM EnvisaLink INFO Partition 1 status change: Ready - Force Arming Enabled
Aug-06 8:21:27 AM EnvisaLink INFO LR Motion status change: Opened
Aug-06 8:21:27 AM EnvisaLink INFO Partition 1 status change: Ready
Aug-06 8:21:27 AM EnvisaLink INFO LR Motion status change: Closed
Aug-06 8:21:27 AM EnvisaLink INFO Partition 1 status change: Ready - Force Arming Enabled
Aug-06 8:21:27 AM EnvisaLink INFO LR Motion status change: Opened

[claude]

For each device defined with EnvisaLink on the home page, on the EnvisaLink tab of the Edit page, you can set 'Do not log status change' On or Off. Very useful with motion detectors. You can also enable/disable logging through an EnvisaLink event action.

[ryuvann]

Thanks guys, if I disable logging or make it warning though does that mean I'll lose things in the log that show when it was armed, or the door opening etc? I kind of like being able to see in the log things like that. My neighbour went into my place the other day to get butter when I was out of town, didn't even know but saw in the log that the alarm was turned off at 1am and front door which is zone 2 was changed to open, so that was handy.

[waynehead99]

Logging is good for debugging. I only turn it on when needed. Otherwise it causes overhead. Enough to cause issues? I don't know, but it's a practice I got into because I have seen logging crash other applications.

Turning logging off won't affect the function of the status change.

[ryuvann]

I feel like something is still wrong though, it's not devices but alarm status every 4 minutes. So if I disarm it, I get EnvisaLink INFO DSC Alarm status change: Ready, every minute.

This causes problems as I have it set to change Blue Iris's profile when home vs away, as well as turning on lights etc. So when I view my log you see it doing that over and over:


Aug-08 6:09:07 PM Blue-Iris Setting profile to 1
Aug-08 6:09:07 PM Device Control Device: House House Status to Away (2)
Aug-08 6:09:07 PM Event Event Trigger "House Status Set to Away when Alarm is Armed"
Aug-08 6:09:07 PM Event Event Trigger "Security Cameras Set Blue Iris to Away Schedule when Away"
Aug-08 6:09:07 PM EnvisaLink INFO DSC Alarm status change: Armed Away
Aug-08 6:08:23 PM Blue-Iris Setting profile to 1
Aug-08 6:08:23 PM Device Control Device: House House Status to Away (2)
Aug-08 6:08:23 PM Event Event Trigger "House Status Set to Away when Alarm is Armed"
Aug-08 6:08:23 PM Event Event Trigger "Security Cameras Set Blue Iris to Away Schedule when Away"
Aug-08 6:08:23 PM EnvisaLink INFO DSC Alarm status change: Armed Away
Aug-08 6:07:13 PM Blue-Iris Setting profile to 1
Aug-08 6:07:13 PM Device Control Device: House House Status to Away (2)
Aug-08 6:07:13 PM Event Event Trigger "House Status Set to Away when Alarm is Armed"
Aug-08 6:07:13 PM Event Event Trigger "Security Cameras Set Blue Iris to Away Schedule when Away"
Aug-08 6:07:13 PM EnvisaLink INFO DSC Alarm status change: Armed Away

So it just keeps triggering the events over and over. It's very strange.

[spud]

you're right the panel should only send a "status change" message for the partition if the status has actually changed, but I have seen this behavior when for example there is a problem with the battery, in this case some other messages are logged at debug level. So set the log level to debug and you may be able to figure out the problem.

A workaround to avoid multiple event triggers is to use the trigger "This device changes and becomes" with the partition device, instead of using the specific "EnvisaLink Receive Message" trigger.

Regarding logging, as claude said you can turn it on/off at device level.

[ryuvann]

Thanks, I've actually tried both ways, first I did "A device changes and becomes" but that still triggers events non stop, and then using Envisalink Message Received does the same. A few days ago I thought sure I found a forum on here talking about something similar that it was a low battery. I know the panel keeps flashing yellow caution saying low battery, but when I press < > to view them it never shows me any information so no idea what battery is low. I only have 2 wireless sensors plus a wireless keypad, and the keypad was dead recently but I changed the battery on it but the caution low battery warning still comes up. So I'll try to replace it on the door sensors that are wireless as well.

What I don't understand is why the event still triggers even if I do pick "A device changes and becomes..." as being in Armed Away and then a minute later saying "Armed Away" again is a device "becoming", but not "changing". I would assume a device changes and becomes means it would only trigger the first time it changes to that state but maybe not.

[spud]

The battery in question may be the one connected to your panel in case of power loss.

"A device changes and becomes.." is supposed to work as you expect, please set the log level to debug from the EnvisaLink config page, and capture the problem showing the event triggering twice without a real change of the partition status.

[ryuvann]

Thanks I'll check, the battery on the panel is about a year old, I installed all of this April 2015, do they die that fast?

This is for my other home so won't be there until Thursday but definitely will test more, as well as replace all batteries as I only have that battery back up, the one wireless keypad which I replaced, and then 2 door sensors.

[norcalhkr]

Thanks I'll check, the battery on the panel is about a year old, I installed all of this April 2015, do they die that fast?

This is for my other home so won't be there until Thursday but definitely will test more, as well as replace all batteries as I only have that battery back up, the one wireless keypad which I replaced, and then 2 door sensors.

Mine is exhibiting the same issue and only for away mode where it constantly keeps trigger that the mode has changed to away and triggers events as if it was armed. Doesn;t seem to happen in stay mode. Has been happening since I started getting the low battery warning as well

[Kirby]

Hey Spud,
I just bought a DSC unit and I'm trying out your plugin. Everything seems to be fine except for the redundant partition change messages. Otherwise I really like the INFO level logging.

Could you change your plugin so that when it receives a change notification it checks the status of the device that received the notification and if it is already set to the status of the change notification, it ignores the change notification?

Maybe you could still log it at the DEBUG level.

This would really clean up my log without missing any "real" changes.

Thanks,
Kirby

[scorp508]

I have my PC1864 set...

Log Level: Info
Log to File: Yes
File Log Level: Error


...and the output is identical to rprade. My only wired motion sensor reports Closed every 4 to 5 seconds (never open), followed by the partition being Ready even though if you stare at the panel itself it is always in a Ready state.

I think I'll drop down to warning as I don't need thousands of these log entries if I'm not debugging something.
I do not see the panel status changes others are. The only odd, if you want to call it that, message I get is from the only wired motion detectors I have. When the original installer installed two motion detectors he put them on the same zone. So to adjoining rooms each have a single motion detector and they're wired back to the same zone. I only mention it if it matters.


Mar-07 10:54:59 PM
*
EnvisaLink
INFO Partition 1 status change: Ready - Force Arming Enabled
Mar-07 10:54:59 PM
*
EnvisaLink
INFO Z06: Kitchen/Family Motion status change: Opened
Mar-07 10:54:40 PM
*
EnvisaLink
INFO Partition 1 status change: Ready
Mar-07 10:54:40 PM
*
EnvisaLink
INFO Z06: Kitchen/Family Motion status change: Closed
Mar-07 10:54:36 PM
*
EnvisaLink
INFO Partition 1 status change: Ready - Force Arming Enabled
Mar-07 10:54:36 PM
*
EnvisaLink
INFO Z06: Kitchen/Family Motion status change: Opened
Mar-07 10:53:58 PM
*
EnvisaLink
INFO Partition 1 status change: Ready
Mar-07 10:53:58 PM
*
EnvisaLink
INFO Z06: Kitchen/Family Motion status change: Closed
Mar-07 10:53:54 PM
*
EnvisaLink
INFO Partition 1 status change: Ready - Force Arming Enabled
Mar-07 10:53:54 PM
*
EnvisaLink
INFO Z06: Kitchen/Family Motion status change: Opened
Mar-07 10:53:53 PM
*
EnvisaLink
INFO Partition 1 status change: Ready
Mar-07 10:53:53 PM
*
EnvisaLink
INFO Z06: Kitchen/Family Motion status change: Closed
Mar-07 10:53:49 PM
*
EnvisaLink
INFO Partition 1 status change: Ready - Force Arming Enabled

[scorp508]

I have my PC1864 set...

Log Level: Info
Log to File: Yes
File Log Level: Error


...and the output is identical to rprade. My only wired motion sensor reports Closed every 4 to 5 seconds (never open), followed by the partition being Ready even though if you stare at the panel itself it is always in a Ready state.

I think I'll drop down to warning as I don't need thousands of these log entries if I'm not debugging something.

[spud]

...and the output is identical to rprade. My only wired motion sensor reports Closed every 4 to 5 seconds (never open)

well, the logs you posted show that the motion sensor does report open:

EnvisaLink 
INFO Z06: Kitchen/Family Motion status change: Closed 
Mar-07 10:54:36 PM 
* 
EnvisaLink 
INFO Partition 1 status change: Ready - Force Arming Enabled 
Mar-07 10:54:36 PM 
* 
EnvisaLink 
INFO Z06: Kitchen/Family Motion status change: [COLOR="red"]Opened[/COLOR] 
Mar-07 10:53:58 PM 
* 
EnvisaLink 
INFO Partition 1 status change: Ready 
Mar-07 10:53:58 PM

Anyway, you can configure at device level if you want to see the status change in the logs for each device. See the very end of this post from the user guide