HS3 hung / log zero'd and lost

[denisl]

Last night my wife came home and the house lights were all randomly on and the wall switches were not responding. She disabled the z-wave plugin to take back control of the house.

I went to look at things this morning and my HS3 log was gone. No information since 2:35AM which is when she disabled the z-wave plugin. Apparently disabling the z-wave plugin wiped out the log and started over.

I have no log to check to see what happened. In VMware I see that I had cpu spikes starting at around 10pm last night that went away around the time when the z-wave plugin was disabled. That's all I can see.

[Rupp]

Is the log empty or corrupt? How big is your HomeSeerLog.hsd file? Does the Windows event viewer offer any clues?

[denisl]

It seems like the log was emptied completely. My first message in the log is when the z-wave plugin was disabled. I have my HS log retention set to 100MB or 30 days.

My current log is ~735KB.
My backup from 1AM which was an about an hour and a half before the zwave plugin was disabled was ~3.9MB (in the middle of the issue I would guess) and then the log size the day before on 3/18 was ~33MB which is when it was normal.

Is there a way to read my back log files to see what is in them? Would you be interested in a copy to review?

root@p-vubuhs301:/home/bkup/hs3/p-vubuhs301/Daily# unzip -l hs3_DAILY_2016-03-19_01-00-00_FULL.zip | grep HomeSeerLog.hsd
3991552 2016-03-19 01:01 HomeSeer/Logs/HomeSeerLog.hsd

root@p-vubuhs301:/home/bkup/hs3/p-vubuhs301/Daily# unzip -l hs3_DAILY_2016-03-18_01-00-00_FULL.zip | grep HomeSeerLog.hsd
33183744 2016-03-18 01:00 HomeSeer/Logs/HomeSeerLog.hsd

root@p-vubuhs301:/home/bkup/hs3/p-vubuhs301/Daily# ls -l /home/hs3/HomeSeer/Logs/HomeSeerLog.hsd
-rw-r--r-- 1 root root 735232 Mar 19 23:18 /home/hs3/HomeSeer/Logs/HomeSeerLog.hsd

Beginning of current log:

Mar-19 2:44:37 AM Blue-Iris Successfully logged in to BlueIris server: Unnamed (ver 4.2.9.3) as denisl.
Mar-19 2:39:37 AM Blue-Iris Refreshing data from Blue Iris server
Mar-19 2:39:37 AM Blue-Iris Successfully logged in to BlueIris server: Unnamed (ver 4.2.9.3) as denisl.
Mar-19 2:35:23 AM Error Calling SetIOMulti in plugin Z-Wave:Object reference not set to an instance of an object
Mar-19 2:35:04 AM Log Maintenance 146673 additional records were removed from the log database to reduce its size to 105.72MB.
Mar-19 2:35:04 AM Log Warning Log database maintenance may be needed. (106 >= 100)
Mar-19 2:35:00 AM Log Info The log database is currently 105.72MB in size.

[sparkman]

Is there a way to read my back log files to see what is in them?

Download sqlitebrowser and you can open up your old files with it (as long as they are not corrupt).

Cheers
Al

[denisl]

Thanks Al - I'll do that now.

Here are all my backups for 30 days. I guess the log file size is a pre-allocated size and doesn't change? Same size every day except for last night and now.

33183744 2016-02-19 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-02-20 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-02-21 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-02-22 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-02-23 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-02-24 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-02-25 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-02-26 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-02-27 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-02-28 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-02-29 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-03-01 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-03-02 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-03-03 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-03-04 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-03-05 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-03-06 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-03-07 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-03-08 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-03-09 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-03-10 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-03-11 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-03-12 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-03-13 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-03-14 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-03-15 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-03-16 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-03-17 01:00 HomeSeer/Logs/HomeSeerLog.hsd
33183744 2016-03-18 01:00 HomeSeer/Logs/HomeSeerLog.hsd
3991552 2016-03-19 01:01 HomeSeer/Logs/HomeSeerLog.hsd

Edit:
Looking at my log now with sqlitebrowser.
My Log from 3/19 has exactly 1 minute of time with 5571 lines most of which are my cooper light sync vb script running wild.
I'm guessing this vb script is the culprit. Here it is in CSV format.

[Rupp]

The script logging that much activity most likely caused a crash. What OS re you running HS3 on?

[sparkman]

Thanks Al - I'll do that now.

Here are all my backups for 30 days. I guess the log file size is a pre-allocated size and doesn't change? Same size every day except for last night and now.



Edit:
Looking at my log now with sqlitebrowser.
My Log from 3/19 has exactly 1 minute of time with 5571 lines most of which are my cooper light sync vb script running wild.
I'm guessing this vb script is the culprit. Here it is in CSV format.

The script only does one thing and then closes. Would need to figure out why the event(s) that called the script triggered so often. My guess is that it's related to the bug in the event engine that sometimes causes events to trigger over and over again.

Cheers
Al

[denisl]

Rupp - I'm running HS3 on Linux - see my sig.

Al - Ironically I ran into this bug earlier in the week and was recommended to add the not rerun option to prevent this. I never got around to adding the option. I just updated all my sync vb script events to "Cannot Re-Run For... 1 sec". Hopefully that prevents this from happening again until the event engine bug is fixed.

[Rupp]

You should always use the can not re-trigger option as the event engine is multi-threaded and can always trigger multiple times depending on the speed of your equipment. This has always been the case with HS3.

[sparkman]

You should always use the can not re-trigger option as the event engine is multi-threaded and can always trigger multiple times depending on the speed of your equipment. This has always been the case with HS3.

It should only trigger once when the event trigger and conditions are met. The bug makes it trigger multiple times. This setting is a workaround for this bug and should not be set for all events and in fact causes some events to not work properly if it needs to be triggered multiple times...

[Rupp]

in fact causes some events to not work properly if it needs to be triggered multiple times...

This is why it's adjustable for 1 second on. It's been this way since HS3 was released.

[Uncle Michael]

This setting . . . should not be set for all events and in fact causes some events to not work properly if it needs to be triggered multiple times...

Al,
I've been using this 'workaround' successfully for several months, since I first encountered the event trigger bug, but I've wondered if there were any circumstances when it would not be effective.

Can you be more specific about when it should not be used? Are you thinking of situations where an event needs to trigger more frequently than once a second, or is there something else?

[sparkman]

Can you be more specific about when it should not be used? Are you thinking of situations where an event needs to trigger more frequently than once a second, or is there something else?

Hi Mike,

Yes, in some cases I have events/scripts that trigger other events. These other events need to trigger whenever they are called and not be restricted to only once every x seconds as something could be missed.

Cheers
Al

[Uncle Michael]

. . . I have events/scripts that trigger other events. These other events need to trigger whenever they are called and not be restricted to only once every x seconds as something could be missed.

Thanks. I hadn't thought of that situation. Have you seen any of those come down with the 'runaway trigger' bug? In my limited experience it's been mostly events with recurring triggers, or events with a condition that is changed in the event, so the event can retrigger multiple times before the condition change takes effect.

I was actually wondering if the ability to impose a do not retrigger limit on all newly created events could be included in HS as a standard feature. I'm thinking of something similar to the one that allows new events to be disabled by default. If it were user selectable, along with the choice of the default retrigger time, it might save a new user from having to deal with the issue. And for the limited number of events where it was not appropriate, it could be set to zero.

I realize it's a bug that ought to be swatted, but I'm pretty sure Rich wants to swat it as badly as we do. Until he does, though, something more than letting each user unsuspectingly stumble on it seems in order.

[denisl]

I agree with you Mike. The fact that my wife knows how to go to the plug in manage page and disable the z-wave plugin is not a good thing. This isn't the first time that things went sideways and she had to disable HS. Always when I'm not around as usual.