In regards to the logging stopping. Support gave the answer you saw because they get more reports of the log stopping when PHLocation is running. It sounds like there can be other apps or log entries that can stop the log. I can tell you that logging will stop for a few reasons, one being when there is an error writing to the log. It sets a flag to stop the logging. Of course we cannot log that error! What I can look at doing is writing the error message to the startup log since that is just a simple text file. Knowing the last log entry can help figure out the source.
-
-
To follow up on the logging issue, if you are seeing the log stopping you can enable debug mode and it will write all log entries to the file "debug logs\debug_other.log". To enable debug mode edit your settings.ini file in your Config folder and in the Settings section add:
gDebug=32
Setting it to 32 will cause all normal log entries to go to debug_other.log and not log other debug types.
Restart HS after editing the settings.ini file so the logging will start. If you have any files in the "debug logs" folder delete them before you start HS.
If you see the logging stop, note the time and then look in the debug_other.log and see which log entry might have caused the logging to stop, might be an error message there.
I would not enable this on a system with a small system drive, like a HomeTroller Zee, as the log can very large.Comment
-
I followed instructions above, Where is the "debug logs" directory? I don't see it anywhere in the HS3 Directory????Originally posted by rjh View Post
BobSpen
EDIT: Upon further inspection after a restart the "gDebug=32" entry seems to be erased from the settings.ini file!! I've tried it 3 times with the same result---am I missing something?Last edited by BobSpen; November 14, 2018, 09:55 PM.Comment
-
Back in 2016 or 2017, Rich told me to start it by entering a command in the control panel. I cannot find email now, but my notes say that debug logging is automatically disabled on startup.
Here is the page Rich referred me to. I was never told to edit the settings.ini file. The setting you quoted in the post from Rich may be a different setting. You will need to see if Rich can clear this up.
I also had a link to the thread where this was discussed on the old forum, but the link now points to a different thread it seems.HS4 Pro, 4.2.19.16 Windows 10 pro, Supermicro LP XeonComment
-
Not sure why the gDebug is getting removed, I don't see that anywhere in the code. But you can enable it like Randy said. Open the control panel from the tools menu and in the run box enter:
&hs.DebugMode=32
This should log everything to the Debug Logs folder in your HS folder.
After enabling this turn something on/off to generate some log entries, it will create the folder if it does not exist.
Originally posted by BobSpen View PostComment
-
I also have the log stopping problem. I do not and never have had PHLocation installed, so my problem is not related to that. I do however have errors writing to the database (see example below). One of my scripts saves the name of the current song playing on the FM radio in a virtual device. On occasion it picks up something like "It's my life". My suspicion was that the single quote is in conflict with the database delimiters or something. I added code to my script to strip out any single quotes but at the moment some are still getting by until I have time to troubleshoot further. Usually these are logged just fine as below, but is it possible that in some circumstances it locks up the database logging?
I have two HS systems, and both have the logging lockup problem. My other system also gets these "single quote mark" errors caused by a completely different script.
I will do some more work to see if I can eliminate the single quotes and see if the logging lockup goes away with the errors. I have also enabled the gDebug=32 as noted in a previous post.
We really need to get this fixed, because it really gets in the way of fixing other flaws when there is no logging to refer back to...
Nov-15 23:18:01 Error SQL Exception updating device record in the database: SQL logic error or missing database unrecognized token: "'", Code=1, Link= Nov-15 23:18:01 Error SQL Exception : UPDATE [Devices] SET [ref]=572,[name]='Denon Display - Line 0',[location]='House',[location2]='Audio/Video',[Last_Change]='2018-11-15 23:17:45',[devValue]=0,[devString]='ow Playing',[object_version]=101,[object_data]=@ByteArray WHERE [ref]=572; Nov-15 23:18:01 Error SQL Exception updating device record in the database: SQL logic error or missing database unrecognized token: "'Server Error", Code=1, Link= Nov-15 23:18:01 Error SQL Exception : UPDATE [Devices] SET [ref]=573,[name]='Denon Display - Line 1',[location]='House',[location2]='Audio/Video',[Last_Change]='2018-11-15 23:17:45',[devValue]=0,[devString]='Server Error',[object_version]=101,[object_data]=@ByteArray WHERE [ref]=573; Nov-15 23:18:01 Error SQL Exception updating device record in the database: SQL logic error or missing database unrecognized token: "'", Code=1, Link= Nov-15 23:18:01 Error SQL Exception : UPDATE [Devices] SET [ref]=574,[name]='Denon Display - Line 2',[location]='House',[location2]='Audio/Video',[Last_Change]='2018-11-15 23:17:45',[devValue]=0,[devString]='',[object_version]=101,[object_data]=@ByteArray WHERE [ref]=574; Nov-15 23:18:01 Error SQL Exception updating device record in the database: SQL logic error or missing database unrecognized token: "'", Code=1, Link= Nov-15 23:18:01 Error SQL Exception : UPDATE [Devices] SET [ref]=575,[name]='Denon Display - Line 3',[location]='House',[location2]='Audio/Video',[Last_Change]='2018-11-15 23:17:45',[devValue]=0,[devString]='',[object_version]=101,[object_data]=@ByteArray WHERE [ref]=575; Nov-15 23:18:01 Error SQL Exception updating device record in the database: SQL logic error or missing database unrecognized token: "'", Code=1, Link= Nov-15 23:18:01 Error SQL Exception : UPDATE [Devices] SET [ref]=576,[name]='Denon Display - Line 4',[location]='House',[location2]='Audio/Video',[Last_Change]='2018-11-15 23:17:45',[devValue]=0,[devString]=' 00:00 0%',[object_version]=101,[object_data]=@ByteArray WHERE [ref]=576; Nov-15 23:18:01 Error SQL Exception updating device record in the database: SQL logic error or missing database unrecognized token: "'", Code=1, Link= Nov-15 23:18:01 Error SQL Exception : UPDATE [Devices] SET [ref]=577,[name]='Denon Display - Line 5',[location]='House',[location2]='Audio/Video',[Last_Change]='2018-11-15 23:17:46',[devValue]=0,[devString]='ecently Played',[object_version]=101,[object_data]=@ByteArray WHERE [ref]=577; Nov-15 23:18:01 Error SQL Exception updating device record in the database: SQL logic error or missing database unrecognized token: "'", Code=1, Link= Nov-15 23:18:01 Error SQL Exception : UPDATE [Devices] SET [ref]=578,[name]='Denon Display - Line 6',[location]='House',[location2]='Audio/Video',[Last_Change]='2018-11-15 23:17:46',[devValue]=0,[devString]='',[object_version]=101,[object_data]=@ByteArray WHERE [ref]=578; Nov-15 23:18:01 Error SQL Exception updating device record in the database: SQL logic error or missing database unrecognized token: "' [ 1/5 ]", Code=1, Link= Nov-15 23:18:01 Error SQL Exception : UPDATE [Devices] SET [ref]=580,[name]='Denon Display - Line 8',[location]='House',[location2]='Audio/Video',[Last_Change]='2018-11-15 23:17:46',[devValue]=0,[devString]=' [ 1/5 ]',[object_version]=101,[object_data]=@ByteArray WHERE [ref]=580; Comment
-
Not sure what the next step is?
Date/Time Pri Type/Error Message/Source nov-24 13:14:53 P1 DeviceUpdateFrequency (60 sec) greater than last update (10 sec), skipping... nov-24 13:14:45 Arduino Plugin New UDP Text Recieved = Alive 2 nov-24 13:14:45 Arduino Plugin Data Received:Alive 2 nov-24 13:14:44 Arduino Plugin Keeping Board: 2 Alive. nov-24 13:14:44 Arduino Plugin Sent to IP:192.168.178.101 Port No:86 = 2 K ,Keep Alive Command nov-24 13:14:44 PHLocation (UpdateAppLvTimers) Loop started. nov-24 13:14:44 P1 ! nov-24 13:14:44 P1 0-1:24.4.0(1) nov-24 13:14:44 P1 (08455.581) nov-24 13:14:44 P1 0-1:24.3.0(181124130000)(00)(60)(1)(0-1:24.2.1)(m3) nov-24 13:14:44 P1 0-1:96.1.0(3238303039303031313036323133303131) nov-24 13:14:44 P1 0-1:24.1.0(3) nov-24 13:14:44 P1 0-0:96.13.0() nov-24 13:14:44 P1 0-0:96.13.1() nov-24 13:14:44 P1 0-0:96.3.10(1) nov-24 13:14:44 P1 0-0:17.0.0(0999.00*kW) nov-24 13:14:44 P1 1-0:2.7.0(0000.00*kW) nov-24 13:14:44 P1 1-0:1.7.0(0000.09*kW) nov-24 13:14:44 P1 0-0:96.14.0(0001) nov-24 13:14:44 P1 Energy logging is disabled in setup for 199 nov-24 13:14:44 P1 1-0:2.8.2(01510.115*kWh) nov-24 13:14:44 P1 Energy logging is disabled in setup for 121
Debug_Composite.log
2018-11-24_01:14:43:9695: P1~/ISk5\2MT382-1003
2018-11-24_01:14:43:9755: P1~0-0:96.1.1(5A424244303035313239313132343132)
2018-11-24_01:14:43:9875: P1~1-0:1.8.1(17146.159*kWh)
2018-11-24_01:14:44:0115: P1~Energy logging is disabled in setup for 195
2018-11-24_01:14:44:0195: P1~1-0:1.8.2(12598.930*kWh)
2018-11-24_01:14:44:0515: P1~Energy logging is disabled in setup for 197
2018-11-24_01:14:44:0565: P1~1-0:2.8.1(00635.668*kWh)
2018-11-24_01:14:44:0695: P1~Energy logging is disabled in setup for 121
2018-11-24_01:14:44:0725: P1~1-0:2.8.2(01510.115*kWh)
2018-11-24_01:14:44:0915: P1~Energy logging is disabled in setup for 199
2018-11-24_01:14:44:0945: P1~0-0:96.14.0(0001)
2018-11-24_01:14:44:1005: P1~1-0:1.7.0(0000.09*kW)
2018-11-24_01:14:44:1145: P1~1-0:2.7.0(0000.00*kW)
2018-11-24_01:14:44:1345: P1~0-0:17.0.0(0999.00*kW)
2018-11-24_01:14:44:1375: P1~0-0:96.3.10(1)
2018-11-24_01:14:44:1415: P1~0-0:96.13.1()
2018-11-24_01:14:44:1445: P1~0-0:96.13.0()
2018-11-24_01:14:44:1475: P1~0-1:24.1.0(3)
2018-11-24_01:14:44:1515: P1~0-1:96.1.0(3238303039303031313036323133303131)
2018-11-24_01:14:44:1565: P1~0-1:24.3.0(181124130000)(00)(60)(1)(0-1:24.2.1)(m3)
2018-11-24_01:14:44:1595: P1~(08455.581)
2018-11-24_01:14:44:1725: P1~0-1:24.4.0(1)
2018-11-24_01:14:44:1755: P1~!
2018-11-24_01:14:44:2605: PHLocation~(UpdateAppLvTimers) Loop started.
2018-11-24_01:14:44:8595: Arduino Plugin~Sent to IP:192.168.178.101 Port No:86 = 2 K ,Keep Alive Command
2018-11-24_01:14:44:8745: Arduino Plugin~Keeping Board: 2 Alive.
2018-11-24_01:14:45:1585: Arduino Plugin~Data Received:Alive 2
2018-11-24_01:14:45:1785: Arduino Plugin~New UDP Text Recieved = Alive 2
In between here
2018-11-24_01:14:53:7000: P1~DeviceUpdateFrequency (60 sec) greater than last update (10 sec), skipping...
and here somewhere the log stops with logging
2018-11-24_01:15:00:8594: weatherXML~Check for timer items to run
2018-11-24_01:15:03:7156: P1~DeviceUpdateFrequency (60 sec) greater than last update (20 sec), skipping...
2018-11-24_01:15:05:2937: Log Maintenance~30384 records, selected by date/time, were removed from the log database.
2018-11-24_01:15:13:7402: P1~DeviceUpdateFrequency (60 sec) greater than last update (30 sec), skipping...
2018-11-24_01:15:15:2793: Arduino Plugin~Sent to IP:192.168.178.101 Port No:86 = 2 K ,Keep Alive Command
2018-11-24_01:15:15:2973: Arduino Plugin~Keeping Board: 2 Alive.
2018-11-24_01:15:15:5293: Arduino Plugin~Data Received:Alive 2
2018-11-24_01:15:15:5533: Arduino Plugin~New UDP Text Recieved = Alive 2
2018-11-24_01:15:22:9507: PHLocation~Loc Timer elapsed
2018-11-24_01:15:22:9547: PHLocation~(UpdateTimers) Loop started.
2018-11-24_01:15:22:9597: PHLocation~(UpdateTimers) Last update time for device: 313 found : 24-11-2018 12:28:23
2018-11-24_01:15:22:9627: PHLocation~(UpdateTimers) Elapsed Loc Time for device: 313 is 46 minutes.
2018-11-24_01:15:22:9677: PHLocation~(UpdateTimers) Updated timer for device: 313 to 46 minutes.
2018-11-24_01:15:22:9727: PHLocation~(UpdateTimers) Last update time for device: 325 found : 21-12-2017 22:19:20
2018-11-24_01:15:22:9777: PHLocation~(UpdateTimers) Elapsed Loc Time for device: 325 is 486176 minutes.
2018-11-24_01:15:22:9877: PHLocation~(UpdateTimers) Updated timer for device: 325 to 486176 minutes.
2018-11-24_01:15:22:9937: PHLocation~(UpdateTimers) Last update time for device: 478 found : 9-6-2018 0:18:55
2018-11-24_01:15:22:9977: PHLocation~(UpdateTimers) Elapsed Loc Time for device: 478 is 242696 minutes.
2018-11-24_01:15:23:0017: PHLocation~(UpdateTimers) Updated timer for device: 478 to 242696 minutes.
Debug_Other.log
2018-11-24_01:14:38:7194: P1~1-0:2.8.2(01510.115*kWh)
2018-11-24_01:14:38:7334: P1~Energy logging is disabled in setup for 199
2018-11-24_01:14:38:7374: P1~0-0:96.14.0(0001)
2018-11-24_01:14:38:7464: P1~1-0:1.7.0(0000.39*kW)
2018-11-24_01:14:38:7584: P1~1-0:2.7.0(0000.00*kW)
2018-11-24_01:14:38:7714: P1~0-0:17.0.0(0999.00*kW)
2018-11-24_01:14:38:7764: P1~0-0:96.3.10(1)
2018-11-24_01:14:38:7804: P1~0-0:96.13.1()
2018-11-24_01:14:38:7874: P1~0-0:96.13.0()
2018-11-24_01:14:38:7924: P1~0-1:24.1.0(3)
2018-11-24_01:14:38:7984: P1~0-1:96.1.0(3238303039303031313036323133303131)
2018-11-24_01:14:38:8034: P1~0-1:24.3.0(181124010000)(00)(60)(1)(0-1:24.2.1)(m3)
2018-11-24_01:14:38:8084: P1~(08451.480)
2018-11-24_01:14:38:8264: P1~0-1:24.4.0(1)
2018-11-24_01:14:38:8304: P1~!
2018-11-24_01:14:48:8520: P1~DeviceUpdateFrequency (60 sec) greater than last update (10 sec), skipping...
Somewhere here the log stops with logging
2018-11-24_01:14:58:8715: P1~DeviceUpdateFrequency (60 sec) greater than last update (20 sec), skipping...
2018-11-24_01:15:00:1496: Log Info~The log database is currently 883,83MB in size.
2018-11-24_01:15:00:6906: weatherXML~Check for timer items to run
2018-11-24_01:15:07:8401: Arduino Plugin~Sent to IP:192.168.178.101 Port No:86 = 2 K ,Keep Alive Command
2018-11-24_01:15:07:8501: Arduino Plugin~Keeping Board: 2 Alive.
2018-11-24_01:15:08:1501: Arduino Plugin~Data Received:Alive 2
2018-11-24_01:15:08:1871: Arduino Plugin~New UDP Text Recieved = Alive 2
2018-11-24_01:15:08:3971: P1~DeviceUpdateFrequency (60 sec) greater than last update (30 sec), skipping...
2018-11-24_01:15:13:7784: PHLocation~Loc Timer elapsed
2018-11-24_01:15:13:7834: PHLocation~(UpdateTimers) Loop started.
2018-11-24_01:15:13:7894: PHLocation~(UpdateTimers) Last update time for device: 313 found : 23-11-2018 20:29:17
2018-11-24_01:15:13:7954: PHLocation~(UpdateTimers) Elapsed Loc Time for device: 313 is 285 minutes.
Comment
-
Same issue over here. Running .478 Only reboot will temporary resolve the issueComment
-
In this case it looks the log maintenance might be the issue. Can you check your log settings in setup and change the max log size to a much larger #? This should stop the log maintenance from running. Lets see if that keeps the log running. If so, we know what we have to fix.
Originally posted by Broes View PostComment
-
It is also surprising to me that it is pruning 30384 records. Mine prunes every 3 hours. If he is pruning that many records, either his log is busier to I have ever seen, or it is not doing it frequently enough. If it is every 3 hours, thatβs 10,000 per hour or about 169 minute. His log is also fairly large at 883gb. I keep 21 days and mine is 43mb.Originally posted by rjh View Post
I wonder if this problem has anything to do with the overall log size.
Here is the last two days of mine. Granted, I have minimized my logging and maybe his number is normal, but it seems like a lot.Nov-28 7:15:00 PM Log Maintenance 500 records, selected by date/time, were removed from the log database. Nov-28 4:15:00 PM Log Maintenance 455 records, selected by date/time, were removed from the log database. Nov-28 1:15:00 PM Log Maintenance 3051 records, selected by date/time, were removed from the log database. Nov-28 10:15:00 AM Log Maintenance 350 records, selected by date/time, were removed from the log database. Nov-28 7:15:00 AM Log Maintenance 235 records, selected by date/time, were removed from the log database. Nov-28 4:15:00 AM Log Maintenance 85 records, selected by date/time, were removed from the log database. Nov-28 1:15:00 AM Log Maintenance 212 records, selected by date/time, were removed from the log database. Nov-27 10:15:00 PM Log Maintenance 176 records, selected by date/time, were removed from the log database. Nov-27 7:15:00 PM Log Maintenance 380 records, selected by date/time, were removed from the log database. Nov-27 4:15:00 PM Log Maintenance 447 records, selected by date/time, were removed from the log database. Nov-27 1:15:00 PM Log Maintenance 1696 records, selected by date/time, were removed from the log database. Nov-27 10:15:00 AM Log Maintenance 347 records, selected by date/time, were removed from the log database. Nov-27 7:15:00 AM Log Maintenance 263 records, selected by date/time, were removed from the log database. Nov-27 4:15:00 AM Log Maintenance 108 records, selected by date/time, were removed from the log database. Nov-27 1:15:00 AM Log Maintenance 195 records, selected by date/time, were removed from the log database. HS4 Pro, 4.2.19.16 Windows 10 pro, Supermicro LP XeonComment
-
I had stopping log issues too, until 6 weeks ago or so. Since then I have not had this issue anymore. Until then the log was pruned due to size (had it set to 100 Mb). I have logs pruning set to 90 days. But due to a race condition somewhere in June the size of the log was high, that is why pruning due to size took place.
After the loglines of this racecondition were removed by pruning, pruning due to date/time came back and I think the log never stopped logging anymore from here. So you might be on a clue here rjh
Wim-- Wim
Plugins: JowiHue, RFXCOM, Sonos4, Jon00's Perfmon and Network monitor, EasyTrigger, Pushover 3P, rnbWeather, BLBackup, AK SmartDevice, Pushover, PHLocation, Zwave, GCalseer, SDJ-Health, Device History, BLGData
1210 devices/features ---- 392 events ----- 40 scriptsComment
-
More Data: My Log size is set at 100MB and/or 6 months. Like Randy's it trims the 6 months old entries every 3 hours(must be the program design interval).
My actual log size hovers around 40MB( I log a lot less than Randy does)
Here is recent example:Nov-28 10:15:00 PM Log Maintenance 47 records, selected by date/time, were removed from the log database. Nov-28 7:15:00 PM Log Maintenance 16 records, selected by date/time, were removed from the log database. Nov-28 4:15:00 PM Log Maintenance 28 records, selected by date/time, were removed from the log database. Nov-28 1:15:00 PM Log Maintenance 28 records, selected by date/time, were removed from the log database. Nov-28 10:15:00 AM Log Maintenance 17 records, selected by date/time, were removed from the log database. Nov-28 7:15:00 AM Log Maintenance 23 records, selected by date/time, were removed from the log database. Nov-28 4:15:00 AM Log Maintenance 19 records, selected by date/time, were removed from the log database. Nov-28 1:15:00 AM Log Maintenance 25 records, selected by date/time, were removed from the log database. Nov-27 10:15:00 PM Log Maintenance 43 records, selected by date/time, were removed from the log database. Comment
-
Wow 883 GB is a huge log file, the prune process might take forever. It would be ideal if you have a large log file to shut down HS, rename the log file, then start HS so it creates a new log file. Set the max log file size to a high number, then see if the log stops. If for sure its the pruning process, we can look into that. There was an error with that long ago where it would get stuck in a loop since it could never prune to the desired size. I know that was fixed, but there could be a different issue. I could also do a build with the pruning totally disabled to see if that keeps the log working.Comment
-
Gee... personally, I don't see the need to keep such a large log file. My log file is set to 50mb and I keep only 14 days of log. What are the reasons people keep such large files? I figured that since I pretty much look at my logs every day as part of my routine, I generally have no need to go back too far. In fact I have never gone back beyond a day and a half. If something goes weird, I pretty much know the day of. My current logs is just over 7MB.
...that's just me.
RobertHS3PRO 3.0.0.500 as a Fire Daemon service, Windows 2016 Server Std Intel Core i5 PC HTPC Slim SFF 4GB, 120GB SSD drive, WLG800, RFXCom, TI103,NetCam, UltraNetcam3, BLBackup, CurrentCost 3P Rain8Net, MCsSprinker, HSTouch, Ademco Security plugin/AD2USB, JowiHue, various Oregon Scientific temp/humidity sensors, Z-Net, Zsmoke, Aeron Labs micro switches, Amazon Echo Dots, WS+, WD+ ... on and on.Comment
Comment