Bug 1055080

pki-ca-9.0.3-32.el6.noarch, BTW.

(In reply to Ian Pilcher from comment #0)
> I just received a warning that my /var/log filesystem was almost full.  It
> turns out that /var/log/pki-ca/debug had grown to 190MB.
> 
> It looks like this has been fixed upstream:
> 
>   https://fedorahosted.org/pki/ticket/363

Does your log repeatedly contain the following lines?

---------------------------------------------------------------
[11/Oct/2012:09:50:24][RetrieveModificationsTask]: Done with run method of RetrieveModificationsThread
[11/Oct/2012:09:50:24][RetrieveModificationsTask]: Inside run method of RetrieveModificationsThread
---------------------------------------------------------------

Upstream ticket 363 was an issue specific to the above lines being logged repeatedly.  You might just be experiencing growth of the debug log over a long period of time.  There is no log rotation functionality built in, though I believe that logrotate can be used.

(In reply to Nathan Kinder from comment #3)
> Does your log repeatedly contain the following lines?

I'm embarrassed to admit that I deleted it.  :-(

> ---------------------------------------------------------------
> [11/Oct/2012:09:50:24][RetrieveModificationsTask]: Done with run method of
> RetrieveModificationsThread
> [11/Oct/2012:09:50:24][RetrieveModificationsTask]: Inside run method of
> RetrieveModificationsThread
> ---------------------------------------------------------------
> 
> Upstream ticket 363 was an issue specific to the above lines being logged
> repeatedly.  You might just be experiencing growth of the debug log over a
> long period of time.  There is no log rotation functionality built in,
> though I believe that logrotate can be used.

The IdM server has been running for about 24 hours since I deleted the debug log.  The new debug log does not contain "RetrieveModificationsTask", but it has already grown to 1.2MB.

After deleting what appear to be startup messages (based on timestamp) it looks like it's writing about 1MB per day.  Am I crazy to think that this is an excessively verbose default setting?  (This IdM server is *very* lightly used.  It's used for DNS on my home network plus directory/Kerberos services when I spin up my RHEV test environment, which doesn't happen very often.)

Created attachment 852428 [details]
/var/log/pki-ca/debug from last 24 hours

Ok, it looks like there is a bunch of logging around the CertStatusUpdateThread.

------------------------------------------------------------------------
[18/Jan/2014:20:16:33][CertStatusUpdateThread]: getConn: mNumConns now 1
...
------------------------------------------------------------------------

These was some debug logging added in this area a while back, but I did not think it was at the default log level.  It is not something that we should log by default.

I'm adding Ade Lee to the CC list, as he worked on logging in this area.

The main problem here is that we 
1) Log by default at the debug level.  It is suggested that users change the debug level on a production server.
2) Log too much of the regularly scheduled status threads at debug level.
3) Do not implement log rotation for the debug log.

We need to review how we do our logging and decide how to move forward,

Per consensus reached in RHCS/RHDS meeting held 3/10/2014, Red Hat Enterprise Linux 6 (6.6) will, at least, change the default log level to NOT log at the debug level.

Upstream ticket:
https://fedorahosted.org/pki/ticket/898

Created attachment 909826 [details]
Patch to limit 'debug' logging from OBNOXIOUS down to INFO

After reviewing the code, I discovered the following:

    * The following 'debug' log file parameters are available from 'CS.cfg':

          debug.append=false
          debug.enabled=true
          debug.filename=/var/lib/pki-ca/logs/debug
          debug.hashkeytypes=
          debug.level=0
          debug.showcaller=false
    
    * From 'pki/base/common/src/com/netscape/certsrv/logging/ILogger.java':
      
      PKI utilizes its own logging system which defines the following
      log levels:
      
          LL_DEBUG = 0;  // depreciated
          LL_INFO = 1;
          LL_WARN = 2;
          LL_FAILURE = 3;
          LL_MISCONF = 4;
          LL_CATASTRPHE = 5;
          LL_SECURITY = 6;
     
      While this system is utilized for the 'system', 'transaction',
      'selftests', and 'signed-audit' systems for their logging
      functionality, the file also includes the following comment:
      
         /**
          * Debug level is depreciated since CMS6.1. Please use
          * CMS.debug() to output messages to debugging file.
          */
      
    * From 'pki/base/common/src/com/netscape/certsrv/apps/CMS.java':
          
          public static final int DEBUG_OBNOXIOUS = 10;
          public static final int DEBUG_VERBOSE = 5;
          public static final int DEBUG_INFORM = 1;
          
          public void debug(int level, String msg) {
              if (!debugOn()) {
                  // this helps to not saving stuff to file when debug
                  // is disable
                  return;
              }
              Debug.trace(level, msg);
          }
      
          public void debug(String msg) {
              if (!debugOn()) {
                  // this helps to not saving stuff to file when debug
                  // is disable
                  return;
              }
              Debug.trace(msg);
          }
          
      Throughout the source code, the most commonly used debug
      function is the non-level specified CMS.debug(String msg).      
    
    * From 'pki/base/common/src/com/netscape/cmscore/util/Debug.java':
      
          public static final int OBNOXIOUS = 10;
          public static final int VERBOSE = 5;
          public static final int INFORM = 1;
      
          public static void trace(String t) {
              trace(VERBOSE, t);
          }
          
However, closer examination of the source code basically revealed that
similar to the other PKI logging systems, a "larger" number actually
yields less logging.  Therefore, it was determined that the numeric
values for OBNOXIOUS and INFORM had been reversed.  Similarly, the
numeric values for DEBUG_OBNOXIOUS, and DEBUG_INFORM as specified in
'pki/base/common/src/com/netscape/certsrv/apps/CMS.java' had also been
reversed.  Although I could locate only one use of these parameters in
'pki/base/common/src/com/netscape/cms/servlet/base/CMSServlet.java', I
have attached this patch to address the issue raised by this bug.

IMPORTANT:

The repercussions caused by this change means that the default
behaviour will be to severely limit output to the 'debug' log file,
and changes the traditional focus away from development/support to
customer deployments.

If the proposed patch above is implemented, developers and support
will need to be highly aware of this change, as changing
"debug.level=10" back to "debug.level=0" followed by restarting the
PKI instance, will need to become among the first things that they
do in order to develop/debug PKI and IPA deployments.

Created attachment 909827 [details]
Patch to limit 'debug' logging from OBNOXIOUS down to INFO (spec file)

TESTING:

After installing and configuring a new PKI instance (e. g. - 'pki-ca'), merely review the '/var/log/pki-ca/debug' log. Rather than the mountains of data that used to be present, something similar to the following will be inside the file:

    # cat /var/log/pki-ca/debug 
    [18/Jun/2014:15:07:30][main]: ============================================
    [18/Jun/2014:15:07:30][main]: =====  DEBUG SUBSYSTEM INITIALIZED   =======
    [18/Jun/2014:15:07:30][main]: ============================================

Exercising the PKI server now only basically appears to store the date, id, and time of any CMSServlet being accessed.  For example:

    # cat /var/log/pki-ca/debug 
    [18/Jun/2014:15:07:30][main]: ============================================
    [18/Jun/2014:15:07:30][main]: =====  DEBUG SUBSYSTEM INITIALIZED   =======
    [18/Jun/2014:15:07:30][main]: ============================================
    [18/Jun/2014:15:08:51][http-9445-7]: CMSServlet: curDate=Wed Jun 18 
    15:08:51 GMT-08:00 2014 id=caGetStatus time=62
    [18/Jun/2014:15:08:53][http-9445-7]: CMSServlet: curDate=Wed Jun 18 
    15:08:53 GMT-08:00 2014 id=caGetDomainXML time=12
    [18/Jun/2014:15:09:25][http-9445-7]: CMSServlet: curDate=Wed Jun 18 
    15:09:25 GMT-08:00 2014 id=caGetDomainXML time=10
    [18/Jun/2014:15:09:54][http-9180-1]: CMSServlet: curDate=Wed Jun 18 
    15:09:54 GMT-08:00 2014 id=caGetCAChain time=24
    [18/Jun/2014:15:10:11][http-9445-5]: CMSServlet: curDate=Wed Jun 18 
    15:10:11 GMT-08:00 2014 id=caGetAdminBySerial time=37
    [18/Jun/2014:15:10:16][http-9445-6]: CMSServlet: curDate=Wed Jun 18 
    15:10:16 GMT-08:00 2014 id=caGetDomainXML time=11

As documented in comment #10 above, this is controlled by setting the value of the 'debug.level' in the PKI instances 'CS.cfg' file (set to '10' by this patch from its previous value of '0') where debug levels equate to the following numeric values:

    DEBUG_OBNOXIOUS = 1;
    DEBUG_VERBOSE = 5;
    DEBUG_INFORM = 10;

A number need not be any of these specific values, but basically, the rule of thumb is 'less is more' (i. e. - when the value was '0' the debug logging was 'OBNOXIOUS' whereas with a value of '10', only messages at a level of 'INFORM' and higher are generated).

As stated previously in comment #10 above, the internal server generally logs its messages at the 'VERBOSE' level of '5', so theoretically, a setting of '6' would probably be equivalent to '10'; however, a setting of '0', '1', '2', '3', '4', or '5' would all pretty much equate to the old value of '0', which displays everything.

Created attachment 910200 [details]
SRPM containing all patches and spec file (for testing)

Sample SRPM that contains all patches and an appropriate spec file for use in testing this patch.

Created attachment 910629 [details]
Patch to limit 'debug' logging from OBNOXIOUS down to INFO

Created attachment 910630 [details]
SRPM containing all patches and spec file (for testing)

Sample SRPM that contains all patches and an appropriate spec file for use in testing this patch.

Verified on RHEL 6.6 with pki-core-9.0.3-36.el6

Verified as explained in comment 12. The debug log file was much more heavier with the build that had this bug.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHBA-2014-1549.html