Added log messages for OCSP service.

Some log messages have been added into OCSP-related classes for
clarity.

https://pagure.io/dogtagpki/issue/2652

Change-Id: I7eda806a3103ac235a5d3e073db8c60a9b3d482d

4 files changed, 128 insertions, 58 deletions

diff --git a/base/ca/src/com/netscape/ca/CertificateAuthority.java b/base/ca/src/com/netscape/ca/CertificateAuthority.java
index d8f3cfc4f..d4b8d7ecd 100644
--- a/base/ca/src/com/netscape/ca/CertificateAuthority.java
+++ b/base/ca/src/com/netscape/ca/CertificateAuthority.java
@@ -150,6 +150,7 @@ import com.netscape.cmsutil.ocsp.NameID;
 import com.netscape.cmsutil.ocsp.OCSPRequest;
 import com.netscape.cmsutil.ocsp.OCSPResponse;
 import com.netscape.cmsutil.ocsp.OCSPResponseStatus;
+import com.netscape.cmsutil.ocsp.Request;
 import com.netscape.cmsutil.ocsp.ResponderID;
 import com.netscape.cmsutil.ocsp.ResponseBytes;
 import com.netscape.cmsutil.ocsp.ResponseData;
@@ -2306,7 +2307,7 @@ public class CertificateAuthority
             throws EBaseException {
 
         if (!mEnableOCSP) {
-            CMS.debug("Local ocsp service is disable.");
+            CMS.debug("CertificateAuthority: OCSP service disabled");
             return null;
         }
 
@@ -2341,53 +2342,60 @@ public class CertificateAuthority
          */
         ICertificateAuthority ocspCA = this;
         if (caMap.size() > 0 && tbsReq.getRequestCount() > 0) {
-            com.netscape.cmsutil.ocsp.Request req = tbsReq.getRequestAt(0);
+            Request req = tbsReq.getRequestAt(0);
             BigInteger serialNo = req.getCertID().getSerialNumber();
             X509CertImpl cert = mCertRepot.getX509Certificate(serialNo);
             X500Name certIssuerDN = (X500Name) cert.getIssuerDN();
             ocspCA = getCA(certIssuerDN);
         }
+
         if (ocspCA == null)
             throw new CANotFoundException("Could not locate issuing CA");
+
         if (ocspCA != this)
             return ((IOCSPService) ocspCA).validate(request);
 
+        CMS.debug("CertificateAuthority: validating OCSP request");
+
         mNumOCSPRequest++;
         IStatsSubsystem statsSub = (IStatsSubsystem) CMS.getSubsystem("stats");
         long startTime = CMS.getCurrentDate().getTime();
+
         try {
             //log(ILogger.LL_INFO, "start OCSP request");
 
             // (3) look into database to check the
             //     certificate's status
             Vector<SingleResponse> singleResponses = new Vector<SingleResponse>();
+
             if (statsSub != null) {
                 statsSub.startTiming("lookup");
             }
 
             long lookupStartTime = CMS.getCurrentDate().getTime();
-            for (int i = 0; i < tbsReq.getRequestCount(); i++) {
-                com.netscape.cmsutil.ocsp.Request req =
-                        tbsReq.getRequestAt(i);
-                CertID cid = req.getCertID();
-                SingleResponse sr = processRequest(cid);
 
+            for (int i = 0; i < tbsReq.getRequestCount(); i++) {
+                Request req = tbsReq.getRequestAt(i);
+                SingleResponse sr = processRequest(req);
                 singleResponses.addElement(sr);
             }
+
             long lookupEndTime = CMS.getCurrentDate().getTime();
+            mLookupTime += lookupEndTime - lookupStartTime;
+
             if (statsSub != null) {
                 statsSub.endTiming("lookup");
             }
-            mLookupTime += lookupEndTime - lookupStartTime;
 
             if (statsSub != null) {
                 statsSub.startTiming("build_response");
             }
-            SingleResponse res[] = new SingleResponse[singleResponses.size()];
 
+            SingleResponse res[] = new SingleResponse[singleResponses.size()];
             singleResponses.copyInto(res);
 
             ResponderID rid = null;
+
             if (mByName) {
                 if (mResponderIDByName == null) {
                     mResponderIDByName = getResponderIDByName();
@@ -2410,8 +2418,10 @@ public class CertificateAuthority
                     nonce[0] = thisExt;
                 }
             }
+
             ResponseData rd = new ResponseData(rid,
                     new GeneralizedTime(CMS.getCurrentDate()), res, nonce);
+
             if (statsSub != null) {
                 statsSub.endTiming("build_response");
             }
@@ -2419,10 +2429,14 @@ public class CertificateAuthority
             if (statsSub != null) {
                 statsSub.startTiming("signing");
             }
+
             long signStartTime = CMS.getCurrentDate().getTime();
+
             BasicOCSPResponse basicRes = sign(rd);
+
             long signEndTime = CMS.getCurrentDate().getTime();
             mSignTime += signEndTime - signStartTime;
+
             if (statsSub != null) {
                 statsSub.endTiming("signing");
             }
@@ -2435,8 +2449,10 @@ public class CertificateAuthority
             //log(ILogger.LL_INFO, "done OCSP request");
             long endTime = CMS.getCurrentDate().getTime();
             mTotalTime += endTime - startTime;
+
             return response;
         } catch (Exception e) {
+
             log(ILogger.LL_FAILURE, CMS.getLogMessage("CMSCORE_CA_CA_OCSP_REQUEST", e.toString()));
             throw new EBaseException(e.toString(), e);
         }
@@ -2486,10 +2502,12 @@ public class CertificateAuthority
         }
     }
 
-    private SingleResponse processRequest(CertID cid) {
+    private SingleResponse processRequest(Request req) {
+
+        CertID cid = req.getCertID();
         INTEGER serialNo = cid.getSerialNumber();
+        CMS.debug("CertificateAuthority: processing request for cert 0x" + serialNo.toString(16));
 
-        CMS.debug("process request " + serialNo);
         CertStatus certStatus = null;
         GeneralizedTime thisUpdate = new GeneralizedTime(CMS.getCurrentDate());
         GeneralizedTime nextUpdate = null;
diff --git a/base/server/cms/src/com/netscape/cms/ocsp/DefStore.java b/base/server/cms/src/com/netscape/cms/ocsp/DefStore.java
index ea095ba3f..a009cbb91 100644
--- a/base/server/cms/src/com/netscape/cms/ocsp/DefStore.java
+++ b/base/server/cms/src/com/netscape/cms/ocsp/DefStore.java
@@ -60,6 +60,7 @@ import com.netscape.cmsutil.ocsp.GoodInfo;
 import com.netscape.cmsutil.ocsp.OCSPRequest;
 import com.netscape.cmsutil.ocsp.OCSPResponse;
 import com.netscape.cmsutil.ocsp.OCSPResponseStatus;
+import com.netscape.cmsutil.ocsp.Request;
 import com.netscape.cmsutil.ocsp.ResponderID;
 import com.netscape.cmsutil.ocsp.ResponseBytes;
 import com.netscape.cmsutil.ocsp.ResponseData;
@@ -322,35 +323,40 @@ public class DefStore implements IDefStore, IExtendedPluginInfo {
     public OCSPResponse validate(OCSPRequest request)
             throws EBaseException {
 
+        CMS.debug("DefStore: validating OCSP request");
+
+        TBSRequest tbsReq = request.getTBSRequest();
+
         IStatsSubsystem statsSub = (IStatsSubsystem) CMS.getSubsystem("stats");
 
         mOCSPAuthority.incNumOCSPRequest(1);
         long startTime = CMS.getCurrentDate().getTime();
+
         try {
             mOCSPAuthority.log(ILogger.LL_INFO, "start OCSP request");
-            TBSRequest tbsReq = request.getTBSRequest();
 
             // (3) look into database to check the
             //     certificate's status
             Vector<SingleResponse> singleResponses = new Vector<SingleResponse>();
+
             if (statsSub != null) {
                 statsSub.startTiming("lookup");
             }
 
             long lookupStartTime = CMS.getCurrentDate().getTime();
-            for (int i = 0; i < tbsReq.getRequestCount(); i++) {
-                com.netscape.cmsutil.ocsp.Request req =
-                        tbsReq.getRequestAt(i);
-                CertID cid = req.getCertID();
-                SingleResponse sr = processRequest(cid);
 
+            for (int i = 0; i < tbsReq.getRequestCount(); i++) {
+                Request req = tbsReq.getRequestAt(i);
+                SingleResponse sr = processRequest(req);
                 singleResponses.addElement(sr);
             }
+
             long lookupEndTime = CMS.getCurrentDate().getTime();
+            mOCSPAuthority.incLookupTime(lookupEndTime - lookupStartTime);
+
             if (statsSub != null) {
                 statsSub.endTiming("lookup");
             }
-            mOCSPAuthority.incLookupTime(lookupEndTime - lookupStartTime);
 
             if (singleResponses.size() <= 0) {
                 CMS.debug("DefStore: No Request Found");
@@ -360,8 +366,8 @@ public class DefStore implements IDefStore, IExtendedPluginInfo {
             if (statsSub != null) {
                 statsSub.startTiming("build_response");
             }
-            SingleResponse res[] = new SingleResponse[singleResponses.size()];
 
+            SingleResponse res[] = new SingleResponse[singleResponses.size()];
             singleResponses.copyInto(res);
 
             ResponderID rid = null;
@@ -385,6 +391,7 @@ public class DefStore implements IDefStore, IExtendedPluginInfo {
 
             ResponseData rd = new ResponseData(rid,
                     new GeneralizedTime(CMS.getCurrentDate()), res, nonce);
+
             if (statsSub != null) {
                 statsSub.endTiming("build_response");
             }
@@ -392,13 +399,17 @@ public class DefStore implements IDefStore, IExtendedPluginInfo {
             if (statsSub != null) {
                 statsSub.startTiming("signing");
             }
+
             long signStartTime = CMS.getCurrentDate().getTime();
+
             BasicOCSPResponse basicRes = mOCSPAuthority.sign(rd);
+
             long signEndTime = CMS.getCurrentDate().getTime();
+            mOCSPAuthority.incSignTime(signEndTime - signStartTime);
+
             if (statsSub != null) {
                 statsSub.endTiming("signing");
             }
-            mOCSPAuthority.incSignTime(signEndTime - signStartTime);
 
             OCSPResponse response = new OCSPResponse(
                     OCSPResponseStatus.SUCCESSFUL,
@@ -406,8 +417,10 @@ public class DefStore implements IDefStore, IExtendedPluginInfo {
                             new OCTET_STRING(ASN1Util.encode(basicRes))));
 
             log(ILogger.LL_INFO, "done OCSP request");
+
             long endTime = CMS.getCurrentDate().getTime();
             mOCSPAuthority.incTotalTime(endTime - startTime);
+
             return response;
 
         } catch (Exception e) {
@@ -420,10 +433,13 @@ public class DefStore implements IDefStore, IExtendedPluginInfo {
     /**
      * Check against the database for status.
      */
-    private SingleResponse processRequest(CertID cid) {
+    private SingleResponse processRequest(Request req) {
         // need to find the right CA
 
-        CMS.debug("DefStore: process request");
+        CertID cid = req.getCertID();
+        INTEGER serialNo = cid.getSerialNumber();
+        CMS.debug("DefStore: processing request for cert 0x" + serialNo.toString(16));
+
         try {
             // cache result to speed up the performance
             X509CertImpl theCert = null;
@@ -489,10 +505,7 @@ public class DefStore implements IDefStore, IExtendedPluginInfo {
             }
 
             // check the serial number
-            INTEGER serialNo = cid.getSerialNumber();
-
             log(ILogger.EV_AUDIT, AuditFormat.LEVEL, "Checked Status of certificate 0x" + serialNo.toString(16));
-            CMS.debug("DefStore: process request 0x" + serialNo.toString(16));
 
             GeneralizedTime thisUpdate;
 
diff --git a/base/server/cms/src/com/netscape/cms/ocsp/LDAPStore.java b/base/server/cms/src/com/netscape/cms/ocsp/LDAPStore.java
index 0d2d608bf..4cc9269cd 100644
--- a/base/server/cms/src/com/netscape/cms/ocsp/LDAPStore.java
+++ b/base/server/cms/src/com/netscape/cms/ocsp/LDAPStore.java
@@ -27,19 +27,9 @@ import java.util.Hashtable;
 import java.util.Locale;
 import java.util.Vector;
 
-import netscape.ldap.LDAPAttribute;
-import netscape.ldap.LDAPConnection;
-import netscape.ldap.LDAPEntry;
-import netscape.ldap.LDAPException;
-import netscape.ldap.LDAPSearchResults;
-import netscape.ldap.LDAPv2;
-import netscape.security.x509.RevokedCertificate;
-import netscape.security.x509.X509CRLImpl;
-import netscape.security.x509.X509CertImpl;
-import netscape.security.x509.X509Key;
-
 import org.mozilla.jss.asn1.ASN1Util;
 import org.mozilla.jss.asn1.GeneralizedTime;
+import org.mozilla.jss.asn1.INTEGER;
 import org.mozilla.jss.asn1.OCTET_STRING;
 import org.mozilla.jss.pkix.cert.Extension;
 
@@ -63,6 +53,7 @@ import com.netscape.cmsutil.ocsp.GoodInfo;
 import com.netscape.cmsutil.ocsp.OCSPRequest;
 import com.netscape.cmsutil.ocsp.OCSPResponse;
 import com.netscape.cmsutil.ocsp.OCSPResponseStatus;
+import com.netscape.cmsutil.ocsp.Request;
 import com.netscape.cmsutil.ocsp.ResponderID;
 import com.netscape.cmsutil.ocsp.ResponseBytes;
 import com.netscape.cmsutil.ocsp.ResponseData;
@@ -71,6 +62,17 @@ import com.netscape.cmsutil.ocsp.SingleResponse;
 import com.netscape.cmsutil.ocsp.TBSRequest;
 import com.netscape.cmsutil.ocsp.UnknownInfo;
 
+import netscape.ldap.LDAPAttribute;
+import netscape.ldap.LDAPConnection;
+import netscape.ldap.LDAPEntry;
+import netscape.ldap.LDAPException;
+import netscape.ldap.LDAPSearchResults;
+import netscape.ldap.LDAPv2;
+import netscape.security.x509.RevokedCertificate;
+import netscape.security.x509.X509CRLImpl;
+import netscape.security.x509.X509CertImpl;
+import netscape.security.x509.X509Key;
+
 /**
  * This is the LDAP OCSP store. It reads CA certificate and
  * revocation list attributes from the CA entry.
@@ -270,13 +272,17 @@ public class LDAPStore implements IDefStore, IExtendedPluginInfo {
     public OCSPResponse validate(OCSPRequest request)
             throws EBaseException {
 
+        CMS.debug("LDAPStore: validating OCSP request");
+
+        TBSRequest tbsReq = request.getTBSRequest();
+
         IStatsSubsystem statsSub = (IStatsSubsystem) CMS.getSubsystem("stats");
 
         mOCSPAuthority.incNumOCSPRequest(1);
         long startTime = CMS.getCurrentDate().getTime();
+
         try {
             mOCSPAuthority.log(ILogger.LL_INFO, "start OCSP request");
-            TBSRequest tbsReq = request.getTBSRequest();
 
             Vector<SingleResponse> singleResponses = new Vector<SingleResponse>();
 
@@ -285,25 +291,25 @@ public class LDAPStore implements IDefStore, IExtendedPluginInfo {
             }
 
             long lookupStartTime = CMS.getCurrentDate().getTime();
-            for (int i = 0; i < tbsReq.getRequestCount(); i++) {
-                com.netscape.cmsutil.ocsp.Request req =
-                        tbsReq.getRequestAt(i);
-                CertID cid = req.getCertID();
-                SingleResponse sr = processRequest(cid);
 
+            for (int i = 0; i < tbsReq.getRequestCount(); i++) {
+                Request req = tbsReq.getRequestAt(i);
+                SingleResponse sr = processRequest(req);
                 singleResponses.addElement(sr);
             }
+
             long lookupEndTime = CMS.getCurrentDate().getTime();
+            mOCSPAuthority.incLookupTime(lookupEndTime - lookupStartTime);
+
             if (statsSub != null) {
                 statsSub.endTiming("lookup");
             }
-            mOCSPAuthority.incLookupTime(lookupEndTime - lookupStartTime);
 
             if (statsSub != null) {
                 statsSub.startTiming("build_response");
             }
-            SingleResponse res[] = new SingleResponse[singleResponses.size()];
 
+            SingleResponse res[] = new SingleResponse[singleResponses.size()];
             singleResponses.copyInto(res);
 
             ResponderID rid = null;
@@ -327,6 +333,7 @@ public class LDAPStore implements IDefStore, IExtendedPluginInfo {
 
             ResponseData rd = new ResponseData(rid,
                     new GeneralizedTime(CMS.getCurrentDate()), res, nonce);
+
             if (statsSub != null) {
                 statsSub.endTiming("build_response");
             }
@@ -336,9 +343,12 @@ public class LDAPStore implements IDefStore, IExtendedPluginInfo {
             }
 
             long signStartTime = CMS.getCurrentDate().getTime();
+
             BasicOCSPResponse basicRes = mOCSPAuthority.sign(rd);
+
             long signEndTime = CMS.getCurrentDate().getTime();
             mOCSPAuthority.incSignTime(signEndTime - signStartTime);
+
             if (statsSub != null) {
                 statsSub.endTiming("signing");
             }
@@ -349,8 +359,10 @@ public class LDAPStore implements IDefStore, IExtendedPluginInfo {
                             new OCTET_STRING(ASN1Util.encode(basicRes))));
 
             log(ILogger.LL_INFO, "done OCSP request");
+
             long endTime = CMS.getCurrentDate().getTime();
             mOCSPAuthority.incTotalTime(endTime - startTime);
+
             return response;
         } catch (Exception e) {
             CMS.debug("LDAPStore: validation " + e.toString());
@@ -454,7 +466,12 @@ public class LDAPStore implements IDefStore, IExtendedPluginInfo {
     /**
      * Check against the database for status.
      */
-    private SingleResponse processRequest(CertID cid) throws EBaseException {
+    private SingleResponse processRequest(Request req) throws EBaseException {
+
+        CertID cid = req.getCertID();
+        INTEGER serialNo = cid.getSerialNumber();
+        CMS.debug("LDAPStore: processing request for cert 0x" + serialNo.toString(16));
+
         // locate the right CRL
         X509CertImpl theCert = null;
         X509CRLImpl theCRL = null;
diff --git a/base/server/cms/src/com/netscape/cms/servlet/ocsp/OCSPServlet.java b/base/server/cms/src/com/netscape/cms/servlet/ocsp/OCSPServlet.java
index 5fde89dfe..2d7d35cf5 100644
--- a/base/server/cms/src/com/netscape/cms/servlet/ocsp/OCSPServlet.java
+++ b/base/server/cms/src/com/netscape/cms/servlet/ocsp/OCSPServlet.java
@@ -122,27 +122,33 @@ public class OCSPServlet extends CMSServlet {
             return;
         }
 
-        CMS.debug("Servlet Path=" + httpReq.getServletPath());
-        CMS.debug("RequestURI=" + httpReq.getRequestURI());
+        CMS.debug("OCSPServlet: Servlet Path: " + httpReq.getServletPath());
+        CMS.debug("OCSPServlet: RequestURI: " + httpReq.getRequestURI());
+
         String pathInfo = httpReq.getPathInfo();
         if (pathInfo != null && pathInfo.indexOf('%') != -1) {
             try {
                 pathInfo = URLDecoder.decode(pathInfo, "UTF-8");
             } catch (UnsupportedEncodingException e) {
-                e.printStackTrace();
-                throw new EBaseException("OCSPServlet: Unsupported encoding" + e);
+                CMS.debug(e);
+                throw new EBaseException("OCSPServlet: Unsupported encoding: " + e, e);
             }
         }
-        CMS.debug("PathInfo=" + pathInfo);
+        CMS.debug("OCSPServlet: PathInfo: " + pathInfo);
 
         OCSPRequest ocspReq = null;
 
         try {
             InputStream is = httpReq.getInputStream();
             byte reqbuf[] = null;
+
             String method = httpReq.getMethod();
-            CMS.debug("Method=" + method);
+            CMS.debug("OCSPServlet: HTTP method: " + method);
+
             if (method != null && method.equals("POST")) {
+
+                CMS.debug("OCSPServlet: processing POST request");
+
                 int reqlen = httpReq.getContentLength();
 
                 if (reqlen == -1) {
@@ -173,8 +179,11 @@ public class OCSPServlet extends CMSServlet {
                     }
                 }
                 is = new ByteArrayInputStream(reqbuf);
+
             } else {
-                // GET method
+
+                CMS.debug("OCSPServlet: processing GET request");
+
                 if ((pathInfo == null) ||
                         (pathInfo.equals("")) ||
                         (pathInfo.substring(1) == null) ||
@@ -199,6 +208,7 @@ public class OCSPServlet extends CMSServlet {
                                        + "empty or malformed");
                 }
 
+                CMS.debug("OCSPServlet: decoding request");
                 ocspReq = (OCSPRequest) reqTemplate.decode(is);
 
                 if ((ocspReq == null) ||
@@ -207,6 +217,7 @@ public class OCSPServlet extends CMSServlet {
                                        + "is empty or malformed");
                 }
 
+                CMS.debug("OCSPServlet: validating request");
                 response = ((IOCSPService) mAuthority).validate(ocspReq);
 
             } catch (Exception e) {
@@ -228,32 +239,39 @@ public class OCSPServlet extends CMSServlet {
                 if (CMS.debugOn()) {
                     CMS.debug("OCSPServlet: OCSP Request:");
                     CMS.debug("OCSPServlet: " + CMS.BtoA(ASN1Util.encode(ocspReq)));
+
                     TBSRequest tbsReq = ocspReq.getTBSRequest();
                     for (int i = 0; i < tbsReq.getRequestCount(); i++) {
                         com.netscape.cmsutil.ocsp.Request req = tbsReq.getRequestAt(i);
                         CMS.debug("Serial Number: " + req.getCertID().getSerialNumber());
                     }
+
                     CMS.debug("OCSPServlet: OCSP Response Size:");
                     CMS.debug("OCSPServlet: " + Integer.toString(respbytes.length));
                     CMS.debug("OCSPServlet: OCSP Response Data:");
                     CMS.debug("OCSPServlet: " + CMS.BtoA(respbytes));
+
                     ResponseBytes rbytes = response.getResponseBytes();
                     if (rbytes == null) {
-                        CMS.debug("Response bytes is null");
+                        CMS.debug("OCSPServlet: Response bytes is null");
+
                     } else if (rbytes.getObjectIdentifier().equals(
                                ResponseBytes.OCSP_BASIC)) {
+
                         BasicOCSPResponse basicRes = (BasicOCSPResponse)
                                 BasicOCSPResponse.getTemplate().decode(
                                         new ByteArrayInputStream(rbytes.getResponse().toByteArray()));
+
                         if (basicRes == null) {
-                            CMS.debug("Basic Res is null");
+                            CMS.debug("OCSPServlet: Basic Res is null");
+
                         } else {
                             ResponseData data = basicRes.getResponseData();
                             for (int i = 0; i < data.getResponseCount(); i++) {
                                 SingleResponse res = data.getResponseAt(i);
-                                CMS.debug("Serial Number: " +
-                                          res.getCertID().getSerialNumber() +
-                                          " Status: " +
+                                CMS.debug("OCSPServlet: Serial Number: " +
+                                          res.getCertID().getSerialNumber());
+                                CMS.debug("OCSPServlet: Status: " +
                                           res.getCertStatus().getClass().getName());
                             }
                         }
@@ -272,9 +290,13 @@ public class OCSPServlet extends CMSServlet {
                 }
 
                 mRenderResult = false;
+
+            } else {
+                CMS.debug("OCSPServlet: response is null");
             }
+
         } catch (Exception e) {
-            CMS.debug("OCSPServlet: " + e.toString());
+            CMS.debug(e);
         }
     }
 }