diff options
author | Endi S. Dewata <edewata@redhat.com> | 2017-06-20 00:06:58 +0200 |
---|---|---|
committer | Endi S. Dewata <edewata@redhat.com> | 2017-06-20 20:04:58 +0200 |
commit | 53d695a365b8a104b507970381a6a88df8624cd9 (patch) | |
tree | cbbe63b26671bded57fa69d38f478dfe125b8a2d /base/server/cms | |
parent | a91b457abfd61c39e1e4318c2443e38b2dd93c5c (diff) | |
download | pki-53d695a365b8a104b507970381a6a88df8624cd9.tar.gz pki-53d695a365b8a104b507970381a6a88df8624cd9.tar.xz pki-53d695a365b8a104b507970381a6a88df8624cd9.zip |
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
Diffstat (limited to 'base/server/cms')
3 files changed, 99 insertions, 47 deletions
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); } } } |