Log Stops showing events

[olof]

Not even one day and logging stopped again. This time I haven't debug on. It stopped at 01.15

jan-21 01:15:30

SDJ-Health

Entered value 82 for battery device ref #2056 in database C:\Program Files (x86)\HomeSeer HS3/Data/SDJ-Health/BatteryLog.db3.

jan-21 01:15:28

SDJ-Health

1 queued messages processed

jan-21 01:15:05

Log Info

The log database is currently 999,18MB in size.

jan-21 01:14:38

SDJ-Health

Activity Device #3303 added to message queue for processing.

jan-21 01:14:37

Z-Wave

Setting device Watts to value 0 Network: D081E7CA Node: 6 Device Ref: 2120

jan-21 01:14:37

Z-Wave

Find, Looking for 0:1:-1:2 Compare -1:1:0:2 for Basement Washing Watts

Seems log is maybe full and clean up will not work properly

[olof]

Logging stopped again... same day at 23.45..
Going to reboot and let it run in debug mode again and will send that to support again.

As it is always at exactly 15 minute interval it seems to be related to a timed process

jan-21 23:44:58

Z-Wave

Payload1 zd is nothing

jan-21 23:44:58

Z-Wave

Find, Looking for 0:1:-1:2 Compare 1:1:0:2 for Basement Washing Watts 1

jan-21 23:44:58

Z-Wave

Find, Looking for 0:1:-1:2 Compare 2:1:0:0 for Basement Washing kW Hours 2

jan-21 23:44:58

Z-Wave

Find, Looking for 0:1:-1:2 Compare 1:1:0:0 for Basement Washing kW Hours 1

jan-21 23:44:58

Z-Wave

Find, Looking for 0:1:-1:2 Compare 2:1:0:2 for Basement Washing Watts 2

jan-21 23:44:58

Z-Wave

Handle_Meter_Report OK

jan-21 23:44:58

Z-Wave

Meter type:Electric_meter Scale:2

jan-21 23:44:58

Z-Wave

Payload1: 32-02-21-34-00-00-00-00-00-00-B9-00-7D

jan-21 23:44:58

Z-Wave

Frame: 32-02-21-34-00-00-00-00-00-00-B9-00-7D

jan-21 23:44:58

Z-Wave

ApplicationCommandHandler from Network: D081E7CA Node: 2 HANDLING: COMMAND_CLASS_METER_V2 Frame(7)=2

[olof]

Again stopped... errors:

jan-24 15:53:24

Error

Log Database failed to open. File: C:\Program Files (x86)\HomeSeer HS3\Logs\HomeSeerLog.hsd, Exception=database is locked database is locked

jan-24 15:53:24

Error

716 Log records failed to be written to the log database, resetting database.

jan-24 14:34:16

Error

Log Database failed to open. File: C:\Program Files (x86)\HomeSeer HS3\Logs\HomeSeerLog.hsd, Exception=database is locked database is locked

jan-24 14:34:16

Error

574 Log records failed to be written to the log database, resetting database.

jan-24 14:07:56

Error

HSLogQueue count exceeded threshold! Clearing queue to prevent memory issues.

jan-24 13:40:44

Error

HSLogQueue count exceeded threshold! Clearing queue to prevent memory issues.

jan-24 13:06:39

Error

Log Database failed to open. File: C:\Program Files (x86)\HomeSeer HS3\Logs\HomeSeerLog.hsd, Exception=database is locked database is locked

jan-24 13:06:39

Error

405 Log records failed to be written to the log database, resetting database.

jan-24 12:57:00

Error

Log Database failed to open. File: C:\Program Files (x86)\HomeSeer HS3\Logs\HomeSeerLog.hsd, Exception=database is locked database is locked

jan-24 12:57:00

Error

891 Log records failed to be written to the log database, resetting database.

jan-24 12:53:37

Error

HSLogQueue count exceeded threshold! Clearing queue to prevent memory issues.

jan-24 11:51:54

Error

Log Database failed to open. File: C:\Program Files (x86)\HomeSeer HS3\Logs\HomeSeerLog.hsd, Exception=database is locked database is locked

jan-24 11:51:54

Error

1328 Log records failed to be written to the log database, resetting database.

jan-24 11:18:29

Error

Log Database failed to open. File: C:\Program Files (x86)\HomeSeer HS3\Logs\HomeSeerLog.hsd, Exception=database is locked database is locked

jan-24 11:18:29

Error

13 Log records failed to be written to the log database, resetting database.

jan-24 10:33:31

Error

Log Database failed to open. File: C:\Program Files (x86)\HomeSeer HS3\Logs\HomeSeerLog.hsd, Exception=database is locked database is locked

jan-24 10:33:31

Error

58 Log records failed to be written to the log database, resetting database.

jan-24 09:53:26

Error

Log Database failed to open. File: C:\Program Files (x86)\HomeSeer HS3\Logs\HomeSeerLog.hsd, Exception=database is locked database is locked

jan-24 09:53:26

Error

15 Log records failed to be written to the log database, resetting database.

jan-24 07:18:30

Error

Log Database failed to open. File: C:\Program Files (x86)\HomeSeer HS3\Logs\HomeSeerLog.hsd, Exception=database is locked database is locked

jan-24 06:33:33

Error

Log Database failed to open. File: C:\Program Files (x86)\HomeSeer HS3\Logs\HomeSeerLog.hsd, Exception=database is locked database is locked

jan-24 06:33:33

Error

1 Log records failed to be written to the log database, resetting database.

jan-24 01:48:26

Error

Log Database failed to open. File: C:\Program Files (x86)\HomeSeer HS3\Logs\HomeSeerLog.hsd, Exception=database is locked database is locked

jan-24 01:48:26

Error

43 Log records failed to be written to the log database, resetting database.

jan-24 00:57:37

Error

HSLogQueue count exceeded threshold! Clearing queue to prevent memory issues.

jan-24 00:18:25

Error

Log Database failed to open. File: C:\Program Files (x86)\HomeSeer HS3\Logs\HomeSeerLog.hsd, Exception=database is locked database is locked

jan-24 00:18:25

Error

13 Log records failed to be written to the log database, resetting database.

No response from support yet

[chrisgo]

I am also having this issue. What's seems odd is that the homeseer log is being opened RO, then an attempt is made to write to it. I upgraded to the latest (3.0.0.500) and I am still having this issue. I emailed support, waiting for a response.

Feb-09 4:00:47 AM

Database

There were errors generated during the save of the database item. Please consult this log for more details and report any data loss to HomeSeer Technologies.

Feb-09 4:00:42 AM

Database

ERROR, Exception in SaveDevices: attempt to write a readonly database attempt to write a readonly database

Feb-09 4:00:42 AM

Database

Error - Exception during Save of the devices to the database: Object reference not set to an instance of an object.

Feb-07 11:02:06 PM

Database

Opening (Mode=Read/Write) up HomeSeer Energy database C:\Program Files (x86)\HomeSeer HS3\Data\Energy\Energy.hsd

Feb-07 11:01:43 PM

Database

Loading Devices...

Feb-07 11:01:42 PM

Database

Opening (Mode=Read Only) up HomeSeer database C:\Program Files (x86)\HomeSeer HS3\Data\HomeSeerData.hsd

[chuckk9032]

Did anything sort out on this yet? I also have the issue on one system stopping log entries at 11PM often. UltraLog shows log entries after this, but not HS3. These were the last entries several days ago as an example. There have been no entries since. Restarting HS3 will reactivate logging. Changing the log file size makes no difference.

Feb-06 11:00:21 PM

Error

Energy Data Processing Thread encountered an exception: Object reference not set to an instance of an object.

Feb-06 11:00:21 PM

Error

SQL Exception adding record(s) to the ENERGY database(0): attempt to write a readonly database attempt to write a readonly database, Code=8 SQL=

Feb-06 11:00:19 PM

Error

Energy Data Processing Thread encountered an exception: Object reference not set to an instance of an object.

Feb-06 11:00:19 PM

Error

SQL Exception adding record(s) to the ENERGY database(0): attempt to write a readonly database attempt to write a readonly database, Code=8 SQL=

[jhaney143]

I am also wondering if anyone can shed some light on this. I cannot point to a single event that may have made HS start doing this. Seems to be totally random when it does happen and I see no errors logged anywhere.

[jhaney143]

Found some errors. Same as others reported. Locked database. Argh.

[Richel]

I am also wondering if anyone can shed some light on this. I cannot point to a single event that may have made HS start doing this. Seems to be totally random when it does happen and I see no errors logged anywhere.

This is really an annoying problem! I would hope HomeSeer would look into it and fix it.

[chuckk9032]

I looked at this again and hope I've found a fix. I figured something was happening at 11PM on a regular basis (since that's when the log stops) that was locking up the HS3 database. I found that I was backing up the whole HS3 tree with a third party program every night at 11PM. I suspect that this occasionally locked the database just like I saw it previously do to a VoIP MySQL database. I figure the fix is for the backup program to use the VSS file copy or, in my case, I was already running backups with BLBackup so I just used those compressed backup files. I'll monitor this and post a subsequent message as to whether this solved it for me.

[mwaite]

HS3 version 3.0.0.500

I have had log stopping issues for quite some time. I've been following these threads. Yes I used PHLocation but then I migrated over to PHLocation2 and still have log lock-ups. And quite frankly from reading all of these comments it makes no sense to point the issue to PHLocation(2) because there are others that do not use this/these plugins.

Having read how to enable debug logging, I did that and voila, I see something interesting. At the time it appears my Internet connection was momentarily lost - I'm not suggesting that as a cause of log logging failures, other than there were more 'events' logging at that time. When the last log item appeared in the log, the debug log stated Error~SQL Exception adding record(s) to the LOG database(0): attempt to write a readonly database attempt to write a readonly database, Code=8 SQL=.

So the logging stopping issue, in this case, seems a result of the log database being in readonly mode. But what causes this? Somehow HS3 needs to manage this better. What about an option to restart logging, or try to change to read/write. Seems like the logging function is running over itself.

This really needs to be fixed. My system is way too involved to want to reboot HS3 on a daily basis, what I am having to do right now. Please HS3 rjh, let's find a solution!

2019-3-6_07:02:21:0196: 3/6/2019 7:02:21 AM~PHLocation2 Error~(GetReverseGeoO) Error: Empty Response.
2019-3-6_07:02:21:1526: 3/6/2019 7:02:21 AM~PHLocation2 Warning~(UpdateUserDevice) Primary reverse geocode lookup failed, trying alternative provider!
2019-3-6_07:02:30:4846: 3/6/2019 7:02:30 AM~Event~Running script in background: C:/program files (x86)/homeseer hs3/scripts/WOL.vb
2019-3-6_07:02:35:4956: 3/6/2019 7:02:35 AM~Event~Running script in background: C:/program files (x86)/homeseer hs3/scripts/WOL.vb
2019-3-6_07:03:16:3516: 3/6/2019 7:03:16 AM~Z-Wave~Device: <font color='#000080'>Z-Wave Attic Temperature-x</font> Set to <font color='#008000'>67.2 (F)</font>
2019-3-6_07:03:55:5366: 3/6/2019 7:03:55 AM~Web Server~Web Server authorized login successful from:
2019-3-6_07:04:02:5916: 3/6/2019 7:04:02 AM~HSTouch Server~Opening connection from:
2019-3-6_07:04:03:6276: 3/6/2019 7:04:03 AM~HSTouch Server~Client Office () named Office has CONNECTED.
2019-3-6_07:04:03:6296: 3/6/2019 7:04:03 AM~HSTouch Server~Connecting speaker client to HomeSeer IP 192.168.0.35
2019-3-6_07:04:03:9386: 3/6/2019 7:04:03 AM~Speaker~Speaker host added, Name: hal Instance: Office IP address:
2019-3-6_07:08:03:8306: 3/6/2019 7:08:03 AM~Warning~Not running script since its already running: C:/program files (x86)/homeseer hs3/scripts/Jon00HTML2ImageHS3.vben Single instance option enabled in event properties
2019-3-6_07:08:06:5596: 3/6/2019 7:08:06 AM~Device Control~Device: Virtual House Mike Home Wifi to Away (0) by/from: CAPI Control Handler
2019-3-6_07:08:09:9656: 3/6/2019 7:08:09 AM~Warning~Not running script since its already running: C:/program files (x86)/homeseer hs3/scripts/Jon00HTML2ImageHS3.vben Single instance option enabled in event properties
2019-3-6_07:08:16:1916: 3/6/2019 7:08:16 AM~Device Control~Device: Virtual House Mike Home Wifi to Home (100) by/from: CAPI Control Handler
2019-3-6_07:08:16:4486: 3/6/2019 7:08:16 AM~Z-Wave~Device: <font color='#000080'>Z-Wave Attic Temperature-x</font> Set to <font color='#008000'>67.1 (F)</font>
2019-3-6_07:09:31:2036: 3/6/2019 7:09:31 AM~PHLocation2 Error~(idmsaAuthenticate) webException for Ref: 3344 Ex:The remote name could not be resolved: 'idmsa.apple.com'
2019-3-6_07:10:11:4526: 3/6/2019 7:10:11 AM~Warning~Webserver accept callback: An existing connection was forcibly closed by the remote host
2019-3-6_07:10:11:4566: 3/6/2019 7:10:11 AM~Warning~Webserver accept callback: An existing connection was forcibly closed by the remote host
2019-3-6_07:13:16:2986: 3/6/2019 7:13:16 AM~Z-Wave~Device: <font color='#000080'>Z-Wave Attic Temperature-x</font> Set to <font color='#008000'>66.7 (F)</font>
2019-3-6_07:15:00:1246: 3/6/2019 7:15:00 AM~Log Info~The log database is currently 8.51MB in size.
2019-3-6_07:16:03:6276: 3/6/2019 7:16:03 AM~Warning~Not running script since its already running: C:/program files (x86)/homeseer hs3/scripts/Jon00HTML2ImageHS3.vben Single instance option enabled in event properties
2019-3-6_07:16:07:2676: 3/6/2019 7:16:07 AM~Warning~Not running script since its already running: C:/program files (x86)/homeseer hs3/scripts/Jon00HTML2ImageHS3.vben Single instance option enabled in event properties
2019-3-6_07:18:40:3856: 3/6/2019 7:18:40 AM~Jon00_Seneye~Error at Main Block 5 The remote name could not be resolved: 'api.seneye.com'
2019-3-6_07:18:40:3876: 3/6/2019 7:18:40 AM~Jon00_Seneye~Error - cannot download data from Seneye cloud!
2019-3-6_07:18:55:6726: 3/6/2019 7:18:55 AM~Web Server~Web Server authorized login successful from:
2019-3-6_07:19:02:5696: 3/6/2019 7:19:02 AM~Neato~Upstairs Neato went offline (not announced).
2019-3-6_07:19:15:2496: 3/6/2019 7:19:15 AM~Neato~Upstairs Neato now Idle (not announced).
2019-3-6_07:21:29:7676: 3/6/2019 7:21:29 AM~Neato~Upstairs Neato went offline (not announced).
2019-3-6_07:21:42:4236: 3/6/2019 7:21:42 AM~Neato~Upstairs Neato now Idle (not announced).
2019-3-6_07:21:45:0676: 3/6/2019 7:21:45 AM~Error~SQL Exception adding record(s) to the LOG database(0): attempt to write a readonly database
attempt to write a readonly database, Code=8 SQL=
2019-3-6_07:23:16:3846: 3/6/2019 7:23:16 AM~Z-Wave~Device: <font color='#000080'>Z-Wave Attic Temperature-x</font> Set to <font color='#008000'>66.3 (F)</font>
2019-3-6_07:25:06:2766: 3/6/2019 7:25:06 AM~Z-Wave~Device: <font color='#000080'>Z-Wave Living Room Stairs Central Scene</font> Set to <font color='#008000'>2000</font>

I'd also like to point out I've tried all combinations of Max Logsize and Max # of days, from large to small - seems to make no difference.

[rjh]

In build 500 I changed it so when this error occurred it would just retry on the next write. I guess its getting into a bad state where it can no longer write to the DB. The code allowed multiple threads to read the db but only one to write. I made a change so only one thread can access the db at a time. Lets see if that helps, please try build 518 for Windows here:

http://homeseer.com/updates3/SetupHS3_3_0_0_518.msi

HS3 version 3.0.0.500

I have had log stopping issues for quite some time. I've been following these threads. Yes I used PHLocation but then I migrated over to PHLocation2 and still have log lock-ups. And quite frankly from reading all of these comments it makes no sense to point the issue to PHLocation(2) because there are others that do not use this/these plugins.

Having read how to enable debug logging, I did that and voila, I see something interesting. At the time it appears my Internet connection was momentarily lost - I'm not suggesting that as a cause of log logging failures, other than there were more 'events' logging at that time. When the last log item appeared in the log, the debug log stated Error~SQL Exception adding record(s) to the LOG database(0): attempt to write a readonly database attempt to write a readonly database, Code=8 SQL=.

So the logging stopping issue, in this case, seems a result of the log database being in readonly mode. But what causes this? Somehow HS3 needs to manage this better. What about an option to restart logging, or try to change to read/write. Seems like the logging function is running over itself.

This really needs to be fixed. My system is way too involved to want to reboot HS3 on a daily basis, what I am having to do right now. Please HS3 rjh, let's find a solution!

2019-3-6_07:02:21:0196: 3/6/2019 7:02:21 AM~PHLocation2 Error~(GetReverseGeoO) Error: Empty Response.
2019-3-6_07:02:21:1526: 3/6/2019 7:02:21 AM~PHLocation2 Warning~(UpdateUserDevice) Primary reverse geocode lookup failed, trying alternative provider!
2019-3-6_07:02:30:4846: 3/6/2019 7:02:30 AM~Event~Running script in background: C:/program files (x86)/homeseer hs3/scripts/WOL.vb
2019-3-6_07:02:35:4956: 3/6/2019 7:02:35 AM~Event~Running script in background: C:/program files (x86)/homeseer hs3/scripts/WOL.vb
2019-3-6_07:03:16:3516: 3/6/2019 7:03:16 AM~Z-Wave~Device: <font color='#000080'>Z-Wave Attic Temperature-x</font> Set to <font color='#008000'>67.2 (F)</font>
2019-3-6_07:03:55:5366: 3/6/2019 7:03:55 AM~Web Server~Web Server authorized login successful from:
2019-3-6_07:04:02:5916: 3/6/2019 7:04:02 AM~HSTouch Server~Opening connection from:
2019-3-6_07:04:03:6276: 3/6/2019 7:04:03 AM~HSTouch Server~Client Office () named Office has CONNECTED.
2019-3-6_07:04:03:6296: 3/6/2019 7:04:03 AM~HSTouch Server~Connecting speaker client to HomeSeer IP 192.168.0.35
2019-3-6_07:04:03:9386: 3/6/2019 7:04:03 AM~Speaker~Speaker host added, Name: hal Instance: Office IP address:
2019-3-6_07:08:03:8306: 3/6/2019 7:08:03 AM~Warning~Not running script since its already running: C:/program files (x86)/homeseer hs3/scripts/Jon00HTML2ImageHS3.vben Single instance option enabled in event properties
2019-3-6_07:08:06:5596: 3/6/2019 7:08:06 AM~Device Control~Device: Virtual House Mike Home Wifi to Away (0) by/from: CAPI Control Handler
2019-3-6_07:08:09:9656: 3/6/2019 7:08:09 AM~Warning~Not running script since its already running: C:/program files (x86)/homeseer hs3/scripts/Jon00HTML2ImageHS3.vben Single instance option enabled in event properties
2019-3-6_07:08:16:1916: 3/6/2019 7:08:16 AM~Device Control~Device: Virtual House Mike Home Wifi to Home (100) by/from: CAPI Control Handler
2019-3-6_07:08:16:4486: 3/6/2019 7:08:16 AM~Z-Wave~Device: <font color='#000080'>Z-Wave Attic Temperature-x</font> Set to <font color='#008000'>67.1 (F)</font>
2019-3-6_07:09:31:2036: 3/6/2019 7:09:31 AM~PHLocation2 Error~(idmsaAuthenticate) webException for Ref: 3344 Ex:The remote name could not be resolved: 'idmsa.apple.com'
2019-3-6_07:10:11:4526: 3/6/2019 7:10:11 AM~Warning~Webserver accept callback: An existing connection was forcibly closed by the remote host
2019-3-6_07:10:11:4566: 3/6/2019 7:10:11 AM~Warning~Webserver accept callback: An existing connection was forcibly closed by the remote host
2019-3-6_07:13:16:2986: 3/6/2019 7:13:16 AM~Z-Wave~Device: <font color='#000080'>Z-Wave Attic Temperature-x</font> Set to <font color='#008000'>66.7 (F)</font>
2019-3-6_07:15:00:1246: 3/6/2019 7:15:00 AM~Log Info~The log database is currently 8.51MB in size.
2019-3-6_07:16:03:6276: 3/6/2019 7:16:03 AM~Warning~Not running script since its already running: C:/program files (x86)/homeseer hs3/scripts/Jon00HTML2ImageHS3.vben Single instance option enabled in event properties
2019-3-6_07:16:07:2676: 3/6/2019 7:16:07 AM~Warning~Not running script since its already running: C:/program files (x86)/homeseer hs3/scripts/Jon00HTML2ImageHS3.vben Single instance option enabled in event properties
2019-3-6_07:18:40:3856: 3/6/2019 7:18:40 AM~Jon00_Seneye~Error at Main Block 5 The remote name could not be resolved: 'api.seneye.com'
2019-3-6_07:18:40:3876: 3/6/2019 7:18:40 AM~Jon00_Seneye~Error - cannot download data from Seneye cloud!
2019-3-6_07:18:55:6726: 3/6/2019 7:18:55 AM~Web Server~Web Server authorized login successful from:
2019-3-6_07:19:02:5696: 3/6/2019 7:19:02 AM~Neato~Upstairs Neato went offline (not announced).
2019-3-6_07:19:15:2496: 3/6/2019 7:19:15 AM~Neato~Upstairs Neato now Idle (not announced).
2019-3-6_07:21:29:7676: 3/6/2019 7:21:29 AM~Neato~Upstairs Neato went offline (not announced).
2019-3-6_07:21:42:4236: 3/6/2019 7:21:42 AM~Neato~Upstairs Neato now Idle (not announced).
2019-3-6_07:21:45:0676: 3/6/2019 7:21:45 AM~Error~SQL Exception adding record(s) to the LOG database(0): attempt to write a readonly database
attempt to write a readonly database, Code=8 SQL=
2019-3-6_07:23:16:3846: 3/6/2019 7:23:16 AM~Z-Wave~Device: <font color='#000080'>Z-Wave Attic Temperature-x</font> Set to <font color='#008000'>66.3 (F)</font>
2019-3-6_07:25:06:2766: 3/6/2019 7:25:06 AM~Z-Wave~Device: <font color='#000080'>Z-Wave Living Room Stairs Central Scene</font> Set to <font color='#008000'>2000</font>

I'd also like to point out I've tried all combinations of Max Logsize and Max # of days, from large to small - seems to make no difference.

[mwaite]

In build 500 I changed it so when this error occurred it would just retry on the next write. I guess its getting into a bad state where it can no longer write to the DB. The code allowed multiple threads to read the db but only one to write. I made a change so only one thread can access the db at a time. Lets see if that helps, please try build 518 for Windows here:

http://homeseer.com/updates3/SetupHS3_3_0_0_518.msi

Fantastic. Thanks Rich! I'm installing now, I'll report back.

[chrisgo]

rjh thanks for v518, installing it now. Please note though this issue was prior to v500.

[socalsharky]

I looked at this again and hope I've found a fix. I figured something was happening at 11PM on a regular basis (since that's when the log stops) that was locking up the HS3 database. I found that I was backing up the whole HS3 tree with a third party program every night at 11PM. I suspect that this occasionally locked the database just like I saw it previously do to a VoIP MySQL database. I figure the fix is for the backup program to use the VSS file copy or, in my case, I was already running backups with BLBackup so I just used those compressed backup files. I'll monitor this and post a subsequent message as to whether this solved it for me.

I experience this problem every 7-10 days or so, with a log file size well below the maximum limit. When it stopped last night, it was about 30 seconds after BLBackup started to make a differential backup. Any thoughts on why BLBackup might be causing the logging to stop? Would it help to exclude the log file from the backup tree?

[jhirschhorn]

Been running .518 since you posted the link on 3/7. Just checked, Its now 3/9 @3:14PM and the Logfile stopped recording new events shortly after midnight. Looks like the issue still exists. Sorry to be the bearer of bad news, but I thought you'd like the feedback.