Cannot parse Squid and SquidGuard log files (HISTORY OFFSET)

[ddsm28]

Hello: Could you please help me in finding why the Time difference between the SquidAnalyzer.current file and log files from Squid an SquidGuard to be able to fix it. The reports only worked the first time I ran squid-analyzer.

Here the latest output of -> sudo squid-analyzer -d -c /etc/squidanalyzer/squidanalyzer.conf SquidAnalyzer version 6.6 SQUID LOG HISTORY TIME: Fri May 24 22:00:00 2019 - HISTORY OFFSET: 123318 SQUIDGUARD LOG HISTORY TIME: Fri May 24 22:00:00 2019 - HISTORY OFFSET: 123318 Starting to parse logfile /var/log/squid/access.log. DEBUG: this file will not be parsed: /var/log/squid/access.log, line after offset is older than expected: 1558731605.186 < 1558756800.727. Starting to parse logfile /var/log/squidguard/pornbl.log. DEBUG: this file will not be parsed: /var/log/squidguard/pornbl.log, size is lower than expected. DEBUG: exploring /var/log/squidguard/pornbl.log, timestamp found at startup, 1558660503, is lower than history time 1558808233. Starting to parse logfile /var/log/squidguard/socialbl.log. DEBUG: this file will not be parsed: /var/log/squidguard/socialbl.log, line after offset is older than expected: 1558732847 < 1558808233. Starting to parse logfile /var/log/squidguard/pelisbl.log. DEBUG: this file will not be parsed: /var/log/squidguard/pelisbl.log, size is lower than expected. DEBUG: exploring /var/log/squidguard/pelisbl.log, timestamp found at startup, 1558655426, is lower than history time 1558808233. Starting to parse logfile /var/log/squidguard/musicabl.log. DEBUG: this file will not be parsed: /var/log/squidguard/musicabl.log, size is lower than expected. DEBUG: exploring /var/log/squidguard/musicabl.log, timestamp found at startup, 1558655416, is lower than history time 1558808233. Starting to parse logfile /var/log/squidguard/proxiesbl.log. DEBUG: this file will not be parsed: /var/log/squidguard/proxiesbl.log, size is lower than expected. DEBUG: exploring /var/log/squidguard/proxiesbl.log, timestamp found at startup, 1558659605, is lower than history time 1558808233. No new log registered... DEBUG: the log statistics gathering took: 0 wallclock secs ( 0.01 usr + 0.00 sys = 0.01 CPU) Skipping HTML build. DEBUG: generating HTML output took: 0 wallclock secs ( 0.00 usr + 0.00 sys = 0.00 CPU) DEBUG: total execution time: 0 wallclock secs ( 0.01 usr + 0.00 sys = 0.01 CPU)

I'm also including the time entries of: SquidAnalyzer.current 1558756800.727 123318

SquidGuard.current 1558808233 6835

Squid access.log file 1558805639.311

SquidGuard log INFO: squidGuard ready for requests (1558738669.378)

BlackList Logs 2019-05-25 11:10:43 [20269] Request(default/musica/-) 2019-05-25 11:17:13 [20269] Request(default/pelis/-) 2019-05-23 18:18:24 [1253] Request(default/porn/-) 2019-05-23 18:00:05 [1253] Request(default/proxies/-) 2019-05-25 11:17:14 [20269] Request(default/social/-)

Also why troubleshooting I deleted SquidAnalyzer.current and SquidGuard.current. Ran squid-analyzer --rebuild, and just the first report works. After that I get the parse error again.

If there is any additional information you need please let me know.

[darold]

Are you using latest development code? Recent commit 1bfd73c fix auto detection and handling of timezone. This is the reason of the time differences.

[ddsm28]

Good Day Darold: I upgraded to the latest code has you mention. I also deleted both SquidAnalyzer and SquidGuard current files and ran squid-analyzer --rebuild, but still having the same problem. For some reason squid-analyzer is moving 5 hours ahead that the server's time.

sudo tail /var/www/squidanalyzer/SquidAnalyzer.current | perl -p -e 's/^([0-9]*)/"[".localtime($1)."]"/e' [Mon May 27 17:26:04 2019].142 3304486 /var/www/squidanalyzer$ date Mon May 27 10:27:14 MDT 2019

[darold]

This is because you are using localtime, you should use gmtime() instead.

[ddsm28]

Good Day Darold: Where should I used gmtime()??. I should have told you before that this is my second implementation of SquidAnalyzer and on the other server I don't have this issue, its reporting perfectly. Basically I just copied all of the conf files to have consistency across my offices. Coming back to the issue at hand, how to I do correct this?. Appreciate your time on this.

[darold]

Does TimeZone configuration directive is commented out in your configuration file?

#TimeZone +00

[ddsm28]

Yes it is.

[darold]

Last commit 89b53f1 fixes start/end/history debug display time to include the timezone used.

For example:

SQUIGUARD LOG END TIME  : Mon Sep  8 09:40:41 2014
cat /var/www/squidanalyzer/SquidGuard.current
1410165641      334
$ perl -e 'print scalar(localtime(1410165641)), "\n";'
Mon Sep  8 10:40:41 2014
$ perl -e 'print scalar(gmtime(1410165641)), "\n";'
Mon Sep  8 08:40:41 2014
$ perl -e 'print scalar(gmtime(1410165641-(-3600))), "\n";'09
Mon Sep  8 09:40:41 2014

Before this patch we had SQUIGUARD LOG END TIME : Mon Sep 8 10:40:41 2014

To obtain the timezone auto-detected by SquidAnalyzer you can execute the following command:

perl -e '
my @lt = localtime(); my @gt = gmtime(); my $hour_diff = $gt[2] - $lt[2];
my $min_diff  = $gt[1] - $lt[1]; $hour_diff += $lt[8];
print "Auto-detected timezone: ", ($hour_diff * 3600) + ($min_diff * 60), "\n";
'

For me it returns: Auto-detected timezone: -3600

[ddsm28]

Hello Darold: I installed the latest version, and still having the same problem.

[ddsm28]

Good Day Darold: I previously mention that I have another Squid Proxy server with SquidAnalyzer to get the reports I need. Well I installed that version (more than 1 year old) on this new Proxy server and it works perfectly. Don't have any issues with the Time difference. Still I would like to have the latest and greatest version.

[darold]

My code to auto-detect timezone was totally wrong, commit 29dc026 fix this problem. Can you test with latest development code?

[ddsm28]

Hi Darold: I tested the latest code and unfortunately it got worst. Please check the image I'm attaching.

Installed the old version again and got the reports correctly. Lost all of the previous days statistics. Is there a way to get them back?. I doing a big no, no and testing on a production server.

[darold]

Sorry Dan, commit 6b9ae05 fixes previous lazy patch that miss replacement of all call to timegm_nocheck() by timelocal_nocheck(). Please upgrade to latest development code.

About recovering statistics, you have to remove wrong stats+history file and rerun squid-analyzer on the last squid access.log files. For example:

sudo rm -rf /var/www/squidanalyer/1969
sudo rm -f /var/www/squidanalyer/SquidAnalyzer.current
sudo rm -f /var/www/squidanalyer/index.html
sudo squid-analyzer -d /var/log/squid/access.log*

you may want to set exactly the list of access.log file to parse instead of using the wildcard like here.

For previous statistics I guess that you have used the -p | --preserve option? If so they are lost, you must restore them from a backup. If by chance you have a backup, just restore the full content of the /var/www/squidanalyer/ before using command above.

Sorry for the inconveniences.

[ddsm28]

Hi Darold: Thanks for the advise, got my stats back from my backup. But still having problems with the Dates. Installed the latest code and I'm still off. Here is the debug info:

/var/www/squidanalyzer$ sudo squid-analyzer -d -c /etc/squidanalyzer/squidanalyzer.conf SquidAnalyzer version 6.6 SQUID LOG HISTORY TIME: Fri Jul 12 23:34:41 2019 - HISTORY OFFSET: 7655113 SQUIDGUARD LOG HISTORY TIME: Fri Jul 12 23:18:47 2019 - HISTORY OFFSET: 7655113 Starting to parse logfile /var/log/squid/access.log. DEBUG: this file will not be parsed: /var/log/squid/access.log, size is lower than expected. DEBUG: exploring /var/log/squid/access.log, timestamp found at startup, 1562960031.504, is lower than history time 1562974481.183. Starting to parse logfile /var/log/squidguard/pornbl.log. DEBUG: bad or empty log file /var/log/squidguard/pornbl.log. Starting to parse logfile /var/log/squidguard/socialbl.log. DEBUG: this file will not be parsed: /var/log/squidguard/socialbl.log, size is lower than expected. DEBUG: exploring /var/log/squidguard/socialbl.log, timestamp found at startup, 1562614810, is lower than history time 1562973527. Starting to parse logfile /var/log/squidguard/pelisbl.log. DEBUG: this file will not be parsed: /var/log/squidguard/pelisbl.log, size is lower than expected. DEBUG: exploring /var/log/squidguard/pelisbl.log, timestamp found at startup, 1562616928, is lower than history time 1562973527. Starting to parse logfile /var/log/squidguard/musicabl.log. DEBUG: this file will not be parsed: /var/log/squidguard/musicabl.log, size is lower than expected. DEBUG: exploring /var/log/squidguard/musicabl.log, timestamp found at startup, 1562614806, is lower than history time 1562973527. Starting to parse logfile /var/log/squidguard/proxiesbl.log. DEBUG: bad or empty log file /var/log/squidguard/proxiesbl.log. No new log registered... DEBUG: the log statistics gathering took: 0 wallclock secs ( 0.01 usr + 0.00 sys = 0.01 CPU) Skipping HTML build. DEBUG: generating HTML output took: 0 wallclock secs ( 0.00 usr + 0.00 sys = 0.00 CPU) DEBUG: total execution time: 0 wallclock secs ( 0.01 usr + 0.00 sys = 0.01 CPU)

/var/www/squidanalyzer$ date Fri Jul 12 11:43:56 MDT 2019

/var/www/squidanalyzer$ sudo cat SquidAnalyzer.current 1562974481.183 7655113 /var/www/squidanalyzer$ sudo cat SquidGuard.current 1562973527 814966

[darold]

You should remove SquidAnalyzer.current and SquidGuard.current as they have wrong timestamp. But take care to only give logs entries that haven't been parsed, squid-analyzer will parse the log from the beginning. Once it is done we will see at next run if the problem is really fixed.

[ddsm28]

Sorry Darold no luck, I still having problems:

/var/www/squidanalyzer$ sudo tail /var/www/squidanalyzer/SquidAnalyzer.current | perl -p -e 's/^([0-9]*)/"[".localtime($1)."]"/e' [Fri Jul 12 19:25:10 2019].558 2517246

/var/www/squidanalyzer$ sudo tail /var/www/squidanalyzer/SquidGuard.current | perl -p -e 's/^([0-9]*)/"[".localtime($1)."]"/e' [Fri Jul 12 19:00:38 2019] 815118 /var/www/squidanalyzer$ date Fri Jul 12 13:26:27 MDT 2019

Ok, I'm going to erase everything and start allover again, just to make sure I'm not doing some wrong. As soon as I can I will let you know the outcome. Again I appreciate your help, thanks.

[darold]

Ok I've taken the problem from the start and add commit 1cdee5f that will help to find the right direction to solve this issue. Please update to latest development code

First the commit print the timezone used in debug mode so next so that we will now exactly what it use. Second I have set the default value to the TImeZone configuration to +00 in squidanalyzer.conf. Please do the same on your server before running again squid-analyzer.

The commit says: "Set TimeZone configuration directive to +00 by default to force SquidAnalyzer to use localtime. If this directive is commented then SquidAnalyzer will autodetect the timezone and apply it to all timestamp found. If the directive is set to an other timezone value, this is this value that will be applied."

and this is the behavior where we should end :-)

[ddsm28]

Good Day Darold, just to let you know with the last commit I'm getting the correct time on the reports. I appreciate your time and effort, thanks.

[darold]

Good news, thanks for the feedback.