Bug 1319353

Summary: access log file is huge, logs way too much
Product: [Fedora] Fedora Reporter: Adam Williamson <awilliam>
Component: 389-ds-baseAssignee: Rich Megginson <rmeggins>
Status: CLOSED WORKSFORME QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 23CC: awilliam, edewata, mreynolds, nhosoi, nkinder, rmeggins
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-07-15 19:39:51 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Adam Williamson 2016-03-18 23:22:50 UTC
I just noticed the disk on my FreeIPA server had become completely full, breaking all sorts of stuff. On investigation I noticed that /var/log/dirsrv/slapd-HAPPYASSASSIN-NET was huge, nearly 2GB in size. It seems /var/log/dirsrv/slapd-HAPPYASSASSIN-NET/access is logging way too verbosely by default - I had seven logrotated copies of the log, one for each day of the last week, each several hundred MB in size.

I dunno where to go to turn down the logging verbosity, OpenLDAP is way too complex for me.

This is an F23 FreeIPA server box which was originally F19 and has been upgraded through (IIRC) F21 then F23.

Comment 1 Noriko Hosoi 2016-03-18 23:34:08 UTC
They are programmable.  Please set a smaller value to 
nsslapd-accesslog-maxlogsperdir and nsslapd-accesslog-maxlogsperdir.

Please see also this guide:
https://access.redhat.com/documentation/en-US/Red_Hat_Directory_Server/10/html/Configuration_Command_and_File_Reference/Core_Server_Configuration_Reference.html#cnconfig-nsslapd_accesslog_Access_Log

nsslapd-accesslog-maxlogsperdir: 10
  ## This attribute sets the total number of access logs that can be contained in the directory where the access log is stored.
nsslapd-accesslog-maxlogsize: 100 
  ## This attribute sets the maximum access log size in megabytes

Comment 2 Rich Megginson 2016-03-18 23:36:59 UTC
(In reply to Adam Williamson from comment #0)
> I just noticed the disk on my FreeIPA server had become completely full,
> breaking all sorts of stuff. On investigation I noticed that
> /var/log/dirsrv/slapd-HAPPYASSASSIN-NET was huge, nearly 2GB in size. It
> seems /var/log/dirsrv/slapd-HAPPYASSASSIN-NET/access is logging way too
> verbosely by default - I had seven logrotated copies of the log, one for
> each day of the last week, each several hundred MB in size.
> 
> I dunno where to go to turn down the logging verbosity, OpenLDAP is way too
> complex for me.

It doesn't use OpenLDAP, it uses 389.

And no, there isn't a way to turn down the access log verbosity.  The amount of access logs should be directly proportional to the actual access by clients, so perhaps there is some sort of rogue client?

> 
> This is an F23 FreeIPA server box which was originally F19 and has been
> upgraded through (IIRC) F21 then F23.

It will be helpful to figure out what is causing so much logging.

You can use the logconv.pl tool to analyze, and we can use that report as a good start.

Comment 3 Adam Williamson 2016-03-18 23:41:51 UTC
Well, I only have the 'access' file remaining now and it doesn't seem to be growing crazy fast...maybe I should've kept the old log files around somewhere else, sorry :/ Here's what I get with logconv.pl on the current 'access':

[root@id slapd-HAPPYASSASSIN-NET]# logconv.pl access
Access Log Analyzer 8.1
Command: logconv.pl access
Processing 1 Access Log(s)...

[001] access                        	size (bytes):     28930390
     25000 Lines Processed          9296675 of     28930390 bytes (32.135%)
     50000 Lines Processed         18517085 of     28930390 bytes (64.006%)
     75000 Lines Processed         27714328 of     28930390 bytes (95.797%)


Total Log Lines Analysed:  80327


----------- Access Log Output ------------

Start of Logs:    18/Mar/2016:10:36:44
End of Logs:      18/Mar/2016:16:39:41

Processed Log Time:  6 Hours, 2 Minutes, 57 Seconds

Restarts:                     2
Total Connections:            234
 - LDAP Connections:          115
 - LDAPI Connections:         16
 - LDAPS Connections:         103
 - StartTLS Extended Ops:     0
 Secure Protocol Versions:
  - TLS1.2 client bound as uid=pkidbuser,ou=people,o=ipaca - 18
  - TLS1.2 128-bit AES-GCM; client CN=CA Subsystem,O=HAPPYASSASSIN.NET; issuer CN=Certificate Authority,O=HAPPYASSASSIN.NET - 18
  - TLS1.2 128-bit AES - 85

Peak Concurrent Connections:  42
Total Operations:             39778
Total Results:                39692
Overall Performance:          99.8%

Searches:                     38812         (1.78/sec)  (106.93/min)
Modifications:                210           (0.01/sec)  (0.58/min)
Adds:                         0             (0.00/sec)  (0.00/min)
Deletes:                      0             (0.00/sec)  (0.00/min)
Mod RDNs:                     0             (0.00/sec)  (0.00/min)
Compares:                     0             (0.00/sec)  (0.00/min)
Binds:                        685           (0.03/sec)  (1.89/min)

Proxied Auth Operations:      0
Persistent Searches:          4
Internal Operations:          0
Entry Operations:             0
Extended Operations:          0
Abandoned Requests:           0
Smart Referrals Received:     0

VLV Operations:               71
VLV Unindexed Searches:       0
VLV Unindexed Components:     0
SORT Operations:              71

Entire Search Base Queries:   0
Paged Searches:               323
Unindexed Searches:           0
Unindexed Components:         4

FDs Taken:                    250
FDs Returned:                 210
Highest FD Taken:             127

Broken Pipes:                 0
Connections Reset By Peer:    0
Resource Unavailable:         0
Max BER Size Exceeded:        0

Binds:                        685
Unbinds:                      204
 - LDAP v2 Binds:             0
 - LDAP v3 Binds:             675
 - AUTOBINDs:                 10
 - SSL Client Binds:          0
 - Failed SSL Client Binds:   0
 - SASL Binds:                670
    GSSAPI - 648
    EXTERNAL - 22
 - Directory Manager Binds:   0
 - Anonymous Binds:           660
 - Other Binds:               25

I can keep an eye out and see if it grows again and re-do the numbers...

Comment 4 Rich Megginson 2016-03-18 23:57:32 UTC
That is a lot of search requests.  You can use logconv.pl -V to get very detailed, verbose output.  This will break down the searches so we can see which clients are doing the most searches, which search requests are happening the most, which IP addresses are accessing the most, etc. etc.  Then we can track down who is doing all of these searches, and why.

Comment 5 Noriko Hosoi 2016-07-15 19:15:04 UTC
Hello, Adam.

May we close this bug now?  Or are there anything else we could do?

Thanks!
--noriko

Comment 6 Adam Williamson 2016-07-15 19:39:51 UTC
I think we may as well close it, the file seems to have been well-behaved lately (it's 1.5M at present).

Comment 7 Noriko Hosoi 2016-07-15 19:43:00 UTC
Good to hear that.  Thanks, Adam!