Bug 1055080 - Giant /var/log/pki-ca/debug
Summary: Giant /var/log/pki-ca/debug
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 6
Classification: Red Hat
Component: pki-core
Version: 6.5
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: rc
: 6.6
Assignee: Matthew Harmsen
QA Contact: Asha Akkiangady
URL:
Whiteboard:
Depends On:
Blocks: 1061410 1112887
TreeView+ depends on / blocked
 
Reported: 2014-01-18 16:43 UTC by Ian Pilcher
Modified: 2014-10-14 07:36 UTC (History)
4 users (show)

Fixed In Version: pki-core-9.0.3-34.el6
Doc Type: Bug Fix
Doc Text:
Clone Of:
: 1112887 (view as bug list)
Environment:
Last Closed: 2014-10-14 07:36:45 UTC


Attachments (Terms of Use)
/var/log/pki-ca/debug from last 24 hours (1.16 MB, text/plain)
2014-01-19 16:18 UTC, Ian Pilcher
no flags Details
Patch to limit 'debug' logging from OBNOXIOUS down to INFO (3.04 KB, patch)
2014-06-18 02:57 UTC, Matthew Harmsen
no flags Details | Diff
Patch to limit 'debug' logging from OBNOXIOUS down to INFO (spec file) (47.75 KB, text/plain)
2014-06-18 02:57 UTC, Matthew Harmsen
no flags Details
SRPM containing all patches and spec file (for testing) (2.32 MB, application/x-rpm)
2014-06-19 00:52 UTC, Matthew Harmsen
no flags Details
Patch to limit 'debug' logging from OBNOXIOUS down to INFO (3.04 KB, patch)
2014-06-20 04:57 UTC, Matthew Harmsen
no flags Details | Diff
SRPM containing all patches and spec file (for testing) (2.32 MB, application/x-rpm)
2014-06-20 04:59 UTC, Matthew Harmsen
no flags Details


Links
System ID Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2014:1549 normal SHIPPED_LIVE pki-core bug fix and enhancement update 2014-10-14 01:21:26 UTC

Description Ian Pilcher 2014-01-18 16:43:13 UTC
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

Comment 1 Ian Pilcher 2014-01-18 16:43:39 UTC
pki-ca-9.0.3-32.el6.noarch, BTW.

Comment 3 Nathan Kinder 2014-01-19 03:33:21 UTC
(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.

Comment 4 Ian Pilcher 2014-01-19 16:17:38 UTC
(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.)

Comment 5 Ian Pilcher 2014-01-19 16:18:41 UTC
Created attachment 852428 [details]
/var/log/pki-ca/debug from last 24 hours

Comment 6 Nathan Kinder 2014-01-19 16:53:24 UTC
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.

Comment 7 Ade Lee 2014-01-31 14:22:06 UTC
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,

Comment 8 Matthew Harmsen 2014-03-10 21:57:25 UTC
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.

Comment 9 Matthew Harmsen 2014-03-10 21:59:18 UTC
Upstream ticket:
https://fedorahosted.org/pki/ticket/898

Comment 10 Matthew Harmsen 2014-06-18 02:57:00 UTC
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.

Comment 11 Matthew Harmsen 2014-06-18 02:57:50 UTC
Created attachment 909827 [details]
Patch to limit 'debug' logging from OBNOXIOUS down to INFO (spec file)

Comment 12 Matthew Harmsen 2014-06-19 00:44:07 UTC
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.

Comment 13 Matthew Harmsen 2014-06-19 00:52:21 UTC
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.

Comment 14 Matthew Harmsen 2014-06-20 04:57:43 UTC
Created attachment 910629 [details]
Patch to limit 'debug' logging from OBNOXIOUS down to INFO

Comment 15 Matthew Harmsen 2014-06-20 04:59:35 UTC
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.

Comment 17 Roshni 2014-07-15 17:01:54 UTC
Verified on RHEL 6.6 with pki-core-9.0.3-36.el6

Comment 18 Roshni 2014-07-18 14:47:40 UTC
Verified as explained in comment 12. The debug log file was much more heavier with the build that had this bug.

Comment 19 errata-xmlrpc 2014-10-14 07:36:45 UTC
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


Note You need to log in before you can comment on or make changes to this bug.