Hi Guys,
I have a 2 host basic IPA setup both IPA servers are running dns & ca.
I'm running on Centos 7.6 using freeipa version 4.6.4 & dogtag version 10.5.9
I've made a subCA called vpnca and a certificate policy and all this is working fine
with the exception of OCSP on the 2nd IPA box.
The original master works fine and issues OCSP responses for certifcates issued by the
vpnca (subCA) however the replica IPA box fails to respond.
I've had a look through the logs and found in the /var/log/pki/pki-tomcat/ca/debug log
an error on the 2nd box when doing an OCSP request against it for a certificate issued by
the subCA.
I should note here that OCSP requests for certificates issued by the main IPA CA work fine
it's only for ones issued by the subCA on the replica that seem to be broken.
I have also spotted the 2nd IPA server complaining that is can't get caSigningCert
[04/Sep/2019:13:24:01][KeyRetrieverRunner-dd4ea812-c044-41c0-93bf-ec376c732c93]: Running
ExternalProcessKeyRetriever
[04/Sep/2019:13:24:01][KeyRetrieverRunner-dd4ea812-c044-41c0-93bf-ec376c732c93]: About to
execute command: [/usr/libexec/ipa/ipa-pki-retrieve-key, caSigningCert cert-pki-ca
dd4ea812-c044-41c0-93bf-ec376c732c93,
man-fb-ipa-01.testhost.com]
[04/Sep/2019:13:24:02][KeyRetrieverRunner-dd4ea812-c044-41c0-93bf-ec376c732c93]: Failed to
retrieve key from any host.
[04/Sep/2019:13:24:02][KeyRetrieverRunner-dd4ea812-c044-41c0-93bf-ec376c732c93]:
KeyRetriever did not return a result.
[04/Sep/2019:13:24:02][KeyRetrieverRunner-dd4ea812-c044-41c0-93bf-ec376c732c93]: Retrying
in 1946 seconds
I'm presuming this is the reason OCSP is failing as it can't sign the response for
the subCA?
Does anyone know if this is a known issue or if there is something I need to modify to get
the OCSP working on the replica host?
Any help would be greatly appreciated
Thanks
Dave
See logs below.
2nd IPA Replica (Broken) /var/log/pki/pki-tomcat/ca/debug
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet:service() uri =
/ca/ocsp
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet: caOCSP start to
service.
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: IP: 10.128.164.2
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet: no authMgrName
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet.authorize(DirAclAuthz)
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet: in auditSubjectID
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet: auditSubjectID
auditContext {locale=en_GB, ipAddress=10.128.164.2}
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet auditSubjectID:
subjectID: null
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet: in auditGroupID
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet: auditGroupID
auditContext {locale=en_GB, ipAddress=10.128.164.2}
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet auditGroupID: groupID:
null
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: In LdapBoundConnFactory::getConn()
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: masterConn is connected: true
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: getConn: conn is connected true
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: getConn: mNumConns now 2
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: returnConn: mNumConns now 3
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]:
AAclAuthz.checkPermission(certServer.ee.request.ocsp, submit)
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: checkAllowEntries(): expressions:
ipaddress=".*"
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: evaluating expressions:
ipaddress=".*"
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: evaluated expression:
ipaddress=".*" to be true
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: DirAclAuthz: authorization passed
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: SignedAuditLogger: event AUTHZ
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: OCSPServlet: Servlet Path: /ocsp
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: OCSPServlet: RequestURI: /ca/ocsp
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: OCSPServlet: PathInfo: null
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: OCSPServlet: HTTP method: POST
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: OCSPServlet: processing POST
request
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: OCSPServlet: decoding request
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: OCSPServlet: validating request
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: In LdapBoundConnFactory::getConn()
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: masterConn is connected: true
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: getConn: conn is connected true
[04/Sep/2019:12:25:13][ajp-bio-127.0.0.1-8009-exec-1]: getConn: mNumConns now 2
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: returnConn: mNumConns now 3
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: In LdapBoundConnFactory::getConn()
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: masterConn is connected: true
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: getConn: conn is connected true
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: getConn: mNumConns now 2
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: returnConn: mNumConns now 3
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: CertificateAuthority: validating
OCSP request
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: CertificateAuthority: processing
request for cert 0x1b
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: In LdapBoundConnFactory::getConn()
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: masterConn is connected: true
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: getConn: conn is connected true
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: getConn: mNumConns now 2
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: returnConn: mNumConns now 3
java.lang.NullPointerException
at
com.netscape.ca.CertificateAuthority.getResponderIDByName(CertificateAuthority.java:2340)
at com.netscape.ca.CertificateAuthority.validate(CertificateAuthority.java:2473)
at com.netscape.ca.CertificateAuthority.validate(CertificateAuthority.java:2428)
at com.netscape.cms.servlet.ocsp.OCSPServlet.process(OCSPServlet.java:222)
at com.netscape.cms.servlet.base.CMSServlet.service(CMSServlet.java:493)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:288)
at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:285)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAsPrivileged(Subject.java:549)
at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:320)
at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:175)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:297)
at
org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:55)
at
org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:191)
at
org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:187)
at java.security.AccessController.doPrivileged(Native Method)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:186)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:288)
at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:285)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAsPrivileged(Subject.java:549)
at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:320)
at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:260)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:237)
at
org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:55)
at
org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:191)
at
org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:187)
at java.security.AccessController.doPrivileged(Native Method)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:186)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:218)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:110)
at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:506)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:169)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:962)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:445)
at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:190)
at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:637)
at
org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet: in auditSubjectID
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet: auditSubjectID
auditContext {locale=en_GB, ipAddress=10.128.164.2}
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet auditSubjectID:
subjectID: null
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: SignedAuditLogger: event
OCSP_GENERATION
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: OCSPServlet: response is null
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet.java: renderTemplate
[04/Sep/2019:12:25:14][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet: curDate=Wed Sep 04
12:25:14 BST 2019 id=caOCSP time=213
If I look at 1st IPA server which is working I see
1st IPA Master (Working) /var/log/pki/pki-tomcat/ca/debug
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: CMSServlet:service() uri =
/ca/ocsp
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: CMSServlet: caOCSP start to
service.
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: IP: 10.128.167.2
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: CMSServlet: no authMgrName
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: CMSServlet.authorize(DirAclAuthz)
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: CMSServlet: in auditSubjectID
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: CMSServlet: auditSubjectID
auditContext {locale=en_GB, ipAddress=10.128.167.2}
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: CMSServlet auditSubjectID:
subjectID: null
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: CMSServlet: in auditGroupID
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: CMSServlet: auditGroupID
auditContext {locale=en_GB, ipAddress=10.128.167.2}
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: CMSServlet auditGroupID: groupID:
null
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: In
LdapBoundConnFactory::getConn()
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: masterConn is connected: true
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: getConn: conn is connected true
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: getConn: mNumConns now 2
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: returnConn: mNumConns now 3
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]:
AAclAuthz.checkPermission(certServer.ee.request.ocsp, submit)
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: checkAllowEntries(): expressions:
ipaddress=".*"
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: evaluating expressions:
ipaddress=".*"
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: evaluated expression:
ipaddress=".*" to be true
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: DirAclAuthz: authorization passed
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: SignedAuditLogger: event AUTHZ
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: OCSPServlet: Servlet Path: /ocsp
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: OCSPServlet: RequestURI: /ca/ocsp
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: OCSPServlet: PathInfo: null
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: OCSPServlet: HTTP method: POST
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: OCSPServlet: processing POST
request
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: OCSPServlet: decoding request
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: OCSPServlet: validating request
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: In
LdapBoundConnFactory::getConn()
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: masterConn is connected: true
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: getConn: conn is connected true
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: getConn: mNumConns now 4
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: returnConn: mNumConns now 5
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: In
LdapBoundConnFactory::getConn()
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: masterConn is connected: true
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: getConn: conn is connected true
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: getConn: mNumConns now 4
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: returnConn: mNumConns now 5
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: CertificateAuthority: validating
OCSP request
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: CertificateAuthority: processing
request for cert 0x1b
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: In
LdapBoundConnFactory::getConn()
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: masterConn is connected: true
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: getConn: conn is connected true
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: getConn: mNumConns now 4
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: returnConn: mNumConns now 5
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: adding signature
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: Getting algorithm context for
SHA256withRSA RSASignatureWithSHA256Digest
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: Signing Certificate
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: CMSServlet: in auditSubjectID
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: CMSServlet: auditSubjectID
auditContext {locale=en_GB, ipAddress=10.128.167.2}
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: CMSServlet auditSubjectID:
subjectID: null
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: SignedAuditLogger: event
OCSP_GENERATION
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: OCSPServlet: OCSP Request:
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: OCSPServlet:
MGwwaqADAgEAMD4wPDA6MAkGBSsOAwIaBQAEFK377uGJz9Owh8lyIT07pU1YHAEs^M
BBTDA9mf27XJPVL0EOy+SaFKAxCZhAIBG6IjMCEwHwYJKwYBBQUHMAECBBIEEJMj^M
ZAn0Vjd91e0eZdmHXyo=^M
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: Serial Number: 27
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: OCSPServlet: OCSP Response Size:
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: OCSPServlet: 2364
[04/Sep/2019:13:22:06][ajp-bio-127.0.0.1-8009-exec-15]: OCSPServlet: OCSP Response Data:
**SNIP**