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: End
    
    

    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.log.0.

    Looks like we have a race condition.

    Steve



  • @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 -s
    
    

    Screenshot 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

    ![Screen Shot 2014-01-25 at 21.23.48.png](/public/imported_attachments/1/Screen Shot 2014-01-25 at 21.23.48.png)
    ![Screen Shot 2014-01-25 at 21.23.48.png_thumb](/public/imported_attachments/1/Screen Shot 2014-01-25 at 21.23.48.png_thumb)



  • 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.0
    

    The 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: End
    
    

    However, "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_unsort
    

    etc. 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

    ![Screen Shot 2014-01-26 at 00.12.34.png](/public/imported_attachments/1/Screen Shot 2014-01-26 at 00.12.34.png)
    ![Screen Shot 2014-01-26 at 00.12.34.png_thumb](/public/imported_attachments/1/Screen Shot 2014-01-26 at 00.12.34.png_thumb)
    ![Screen Shot 2014-01-26 at 00.14.03.png](/public/imported_attachments/1/Screen Shot 2014-01-26 at 00.14.03.png)
    ![Screen Shot 2014-01-26 at 00.14.03.png_thumb](/public/imported_attachments/1/Screen Shot 2014-01-26 at 00.14.03.png_thumb)
    ![Screen Shot 2014-01-26 at 00.18.57.png](/public/imported_attachments/1/Screen Shot 2014-01-26 at 00.18.57.png)
    ![Screen Shot 2014-01-26 at 00.18.57.png_thumb](/public/imported_attachments/1/Screen Shot 2014-01-26 at 00.18.57.png_thumb)



  • 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

    ![Screen Shot 2014-01-26 at 00.28.49.png](/public/imported_attachments/1/Screen Shot 2014-01-26 at 00.28.49.png)
    ![Screen Shot 2014-01-26 at 00.28.49.png_thumb](/public/imported_attachments/1/Screen Shot 2014-01-26 at 00.28.49.png_thumb)


Log in to reply