Sarg reports broken in 2014
-
I've had sarg reports working reliably for some time. I noticed on New Year's Day that they were no longer working. Running from the command line I get the following. The "-d day-1" arguments appear to be getting correctly interpreted, but there is no output. It appears that it's failing to match the requested date range against the access log. If I just pass "-x" then a report is generated. Has anybody else seen this?
[2.1-RELEASE][admin@pfsense]/root(2): sargs -x -d day-1 SARG: Init SARG: Loading configuration from /usr/pbi/sarg-i386/etc/sarg/sarg.conf SARG: Chaining IP resolving module "dns" SARG: Loading exclude host file from: /usr/pbi/sarg-i386/etc/sarg/exclude_hosts.conf SARG: Loading exclude file from: /usr/pbi/sarg-i386/etc/sarg/exclude_users.conf SARG: Reading host alias file "/usr/pbi/sarg-i386/etc/sarg/hostalias" SARG: List of host names to alias: SARG: Parameters: SARG: Hostname or IP address (-a) = SARG: Useragent log (-b) = SARG: Exclude file (-c) = /usr/pbi/sarg-i386/etc/sarg/exclude_hosts.conf SARG: Date from-until (-d) = 04/01/2014-04/01/2014 SARG: Email address to send reports (-e) = SARG: Config file (-f) = /usr/pbi/sarg-i386/etc/sarg/sarg.conf SARG: Date format (-g) = Europe (dd/mm/yyyy) SARG: IP report (-i) = No SARG: Keep temporary files (-k) = No SARG: Input log (-l) = /var/squid/logs/access.log SARG: Resolve IP Address (-n) = Yes SARG: Output dir (-o) = /usr/local/sarg-reports/ SARG: Use Ip Address instead of userid (-p) = No SARG: Accessed site (-s) = SARG: Time (-t) = SARG: User (-u) = SARG: Temporary dir (-w) = /tmp/sarg SARG: Debug messages (-x) = Yes SARG: Process messages (-z) = No SARG: Previous reports to keep (--lastlog) = 0 SARG: SARG: sarg version: 2.3.6 Arp-21-2013 SARG: Reading access log file: /var/squid/logs/access.log SARG: Records in file: 12273, reading: 0.00%SARG: Records in file: 5000, reading: 40.74%SARG: Records in file: 10000, reading: 81.48%SARG: Records in file: 12273, reading: 100.00% SARG: Records read: 12273, written: 0, excluded: 0 SARG: Squid log format SARG: No records found SARG: EndSteve
-
Having fixed this with a re-install, it died again after a week last night. I checked the logs and found that the logs had rotated at exactly mid-night. It would appear that sarg ran a few seconds later and found nothing of interest in /var/log/squid/access.log to match the preceding day as all that information was in access.log.0.
Looks like we have a race condition.
Steve
-
Having fixed this with a re-install, it died again after a week last night. I checked the logs and found that the logs had rotated at exactly mid-night. It would appear that sarg ran a few seconds later and found nothing of interest in /var/log/squid/access.log to match the preceding day as all that information was in access.0.log.
Looks like we have a race condition.
Steve
Well what are the cronjobs setup as? Is it just moving it before it should be? Do the times look right inside the file?
Any chance you have an early october version of crontab running and you have multiple cron processes being spawned?
ps -aux | grep cron -
Dropping the -u, just the one cron.
[2.1-RELEASE][admin@pfsense]/root(8): ps -ax | grep cron 16592 ?? INs 0:00.66 /usr/sbin/cron -sScreenshot of the pfsense cron entries attached. I've set the logs back to rotate once per day, so hopefully again tonight I'll see the logs rotate at exactly midnight, and the sarg logs generated a couple of minutes later.
What I think is happening is that the logs get rotated and then sarg looks at /var/log/squid/access.log to find nothing of interest for the previous day.
I'll post what I see later.
Steve
 -
Aha, as suspected! No sarg report generated for the 25th.
The log rotated first.Note the time at which access.log.0 was created.
[2.1-RELEASE][admin@pfsense]/var/log/squid(11): ls -l total 53544 -rw-r----- 1 proxy proxy 43161 Jan 26 00:10 access.log -rw-r----- 1 proxy proxy 2569913 Jan 25 23:59 access.log.0 -rw-r----- 1 proxy proxy 27398 Jan 26 00:00 cache.log -rw-r--r-- 1 proxy proxy 52104175 Jan 25 22:19 cache.log.0The output from the system log shows sarg reported back a little later, but only just. See below.
Now with the log rotated, there is nothing to report for yesterday.
[2.1-RELEASE][admin@pfsense]/var/log/squid(14): sarg -x -d day-1 SARG: Init SARG: Loading configuration from /usr/pbi/sarg-i386/etc/sarg/sarg.conf SARG: Chaining IP resolving module "dns" SARG: Loading exclude host file from: /usr/pbi/sarg-i386/etc/sarg/exclude_hosts.conf SARG: Loading exclude file from: /usr/pbi/sarg-i386/etc/sarg/exclude_users.conf SARG: Reading host alias file "/usr/pbi/sarg-i386/etc/sarg/hostalias" SARG: List of host names to alias: SARG: Deleting temporary directory "/tmp/sarg" SARG: Parameters: SARG: Hostname or IP address (-a) = SARG: Useragent log (-b) = SARG: Exclude file (-c) = /usr/pbi/sarg-i386/etc/sarg/exclude_hosts.conf SARG: Date from-until (-d) = 25/01/2014-25/01/2014 SARG: Email address to send reports (-e) = SARG: Config file (-f) = /usr/pbi/sarg-i386/etc/sarg/sarg.conf SARG: Date format (-g) = Europe (dd/mm/yyyy) SARG: IP report (-i) = No SARG: Keep temporary files (-k) = No SARG: Input log (-l) = /var/log/squid/access.log SARG: Resolve IP Address (-n) = Yes SARG: Output dir (-o) = /usr/local/sarg-reports/ SARG: Use Ip Address instead of userid (-p) = No SARG: Accessed site (-s) = SARG: Time (-t) = SARG: User (-u) = SARG: Temporary dir (-w) = /tmp/sarg SARG: Debug messages (-x) = Yes SARG: Process messages (-z) = No SARG: Previous reports to keep (--lastlog) = 0 SARG: SARG: sarg version: 2.3.6 Arp-21-2013 SARG: Reading access log file: /var/log/squid/access.log SARG: Records in file: 285, reading: 100.00% SARG: Records read: 285, written: 0, excluded: 0 SARG: Squid log format SARG: No records found SARG: EndHowever, "unrotate" the logs, and…
[2.1-RELEASE][admin@pfsense]/var/log/squid(15): mv access.log.0 access.log [2.1-RELEASE][admin@pfsense]/var/log/squid(16): sarg -x -d day-1 SARG: Init SARG: Loading configuration from /usr/pbi/sarg-i386/etc/sarg/sarg.conf SARG: Chaining IP resolving module "dns" SARG: Loading exclude host file from: /usr/pbi/sarg-i386/etc/sarg/exclude_hosts.conf SARG: Loading exclude file from: /usr/pbi/sarg-i386/etc/sarg/exclude_users.conf SARG: Reading host alias file "/usr/pbi/sarg-i386/etc/sarg/hostalias" SARG: List of host names to alias: SARG: Deleting temporary directory "/tmp/sarg" SARG: Parameters: SARG: Hostname or IP address (-a) = SARG: Useragent log (-b) = SARG: Exclude file (-c) = /usr/pbi/sarg-i386/etc/sarg/exclude_hosts.conf SARG: Date from-until (-d) = 25/01/2014-25/01/2014 SARG: Email address to send reports (-e) = SARG: Config file (-f) = /usr/pbi/sarg-i386/etc/sarg/sarg.conf SARG: Date format (-g) = Europe (dd/mm/yyyy) SARG: IP report (-i) = No SARG: Keep temporary files (-k) = No SARG: Input log (-l) = /var/log/squid/access.log SARG: Resolve IP Address (-n) = Yes SARG: Output dir (-o) = /usr/local/sarg-reports/ SARG: Use Ip Address instead of userid (-p) = No SARG: Accessed site (-s) = SARG: Time (-t) = SARG: User (-u) = SARG: Temporary dir (-w) = /tmp/sarg SARG: Debug messages (-x) = Yes SARG: Process messages (-z) = No SARG: Previous reports to keep (--lastlog) = 0 SARG: SARG: sarg version: 2.3.6 Arp-21-2013 SARG: Reading access log file: /var/log/squid/access.log SARG: Records in file: 15904, reading: 100.00% SARG: Records read: 15904, written: 15903, excluded: 0 SARG: Squid log format SARG: Period covered by log files: 25/01/2014-25/01/2014 SARG: Period: 25 Jan 2014 SARG: Sorting log /tmp/sarg/10_5_1_145.user_unsort SARG: Making file: /tmp/sarg/10_5_1_145 SARG: Sorting log /tmp/sarg/10_5_1_106.user_unsortetc. And then, we have a log for the 25th.
So, there we have it, a race condition.
I'll turn off rotation until I've had time to think about it further.
Steve
 -
I have a fix!
sarg can examine more than one log file, so regardless of order of execution of the rotate and log generation, just ensure all the logs, rotated or not, are used thus:
Steve
