| Summary: | CA: Logging Improvement | ||
|---|---|---|---|
| Product: | Red Hat Enterprise Linux 8 | Reporter: | Geetika Kapoor <gkapoor> |
| Component: | pki-core | Assignee: | RHCS Maintainers <rhcs-maint> |
| Status: | CLOSED UPSTREAM | QA Contact: | Asha Akkiangady <aakkiang> |
| Severity: | unspecified | Docs Contact: | |
| Priority: | unspecified | ||
| Version: | 8.3 | CC: | ascheel, edewata, mharmsen |
| Target Milestone: | rc | ||
| Target Release: | --- | ||
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2020-02-10 04:54:30 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
Upstream ticket: https://fedorahosted.org/pki/ticket/2551 Moved to RHEL 7.7. This issue will be addressed upstream. |
Description of problem: There are couple of places which needs logging improvement.Because logs might mislead and are not user friendly. Scenario 1 : ----------- ExternalCA installation debug logs throws below mentioned exception.When we check nssdb all certs exist but still it shows issues. <debug logs snip> SigningUnit: Certificate object not found Certificate object not found </debug logs snip> nssdb: certutil -L -d /root/testLuna -h lunasaQE | grep Test_ExternalCA3 Enter Password or Pin for "lunasaQE": lunasaQE:gkapoor/Test_ExternalCA3/subsystem u,u,u lunasaQE:gkapoor/Test_ExternalCA3/sslserver/nocp30.idm.lab.eng.rdu2.redhat.com u,u,u lunasaQE:gkapoor/Test_ExternalCA3/ca_ocsp_signing u,u,u lunasaQE:gkapoor/Test_ExternalCA3/ca_audit_signing u,u,u lunasaQE:gkapoor/Test_ExternalCA3/ca_signing u,u,u lunasaQE:gkapoor/Test_ExternalCA3/External CA1 ,, Scenario 2: ----------- Whenever CA failed to restart maybe ports/address in use or because of any other exception we always see a NPE .Can we have better logging for this. Installation logs: ================== pkispawn : DEBUG ........... No connection - server may still be down pkispawn : DEBUG ........... No connection - exception thrown: ('Connection aborted.', error(111, 'Connection refused')) pkispawn : ERROR ....... server failed to restart pkispawn : DEBUG ....... Error Type: Exception pkispawn : DEBUG ....... Error Message: server failed to restart pkispawn : DEBUG ....... File "/usr/sbin/pkispawn", line 528, in main scriptlet.spawn(deployer) File "/usr/lib/python2.7/site-packages/pki/server/deployment/scriptlets/configuration.py", line 375, in spawn raise Exception("server failed to restart") Installation failed: server failed to restart localhost/catlina logs: ======================== Nov 07, 2016 6:20:49 AM org.apache.catalina.core.ApplicationContext log SEVERE: Servlet castart threw unload() exception javax.servlet.ServletException: Servlet.destroy() for servlet castart threw exception at org.apache.catalina.core.StandardWrapper.unload(StandardWrapper.java:1505) at org.apache.catalina.core.StandardWrapper.stopInternal(StandardWrapper.java:1846) at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:224) at org.apache.catalina.core.StandardContext.stopInternal(StandardContext.java:5767) at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:224) at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1588) at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1577) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) Caused by: java.lang.NullPointerException at com.netscape.cmscore.profile.ProfileSubsystem.shutdown(ProfileSubsystem.java:225) at com.netscape.cmscore.apps.CMSEngine.shutdownSubsystems(CMSEngine.java:2115) at com.netscape.cmscore.apps.CMSEngine.shutdown(CMSEngine.java:2010) at com.netscape.certsrv.apps.CMS.shutdown(CMS.java:233) at com.netscape.cms.servlet.base.CMSStartServlet.destroy(CMSStartServlet.java:144) 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.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:102) at org.apache.catalina.core.StandardWrapper.unload(StandardWrapper.java:1478) ... 10 more 10.3.3.13 How reproducible: always Steps to Reproduce: 1. Scenario 1 can be seen in externalCA with hsm 2. Scenario 2 can be recreated when CA installation failed during CA server restart. 3. Actual results: Expected results: Additional info: additional logs for scenario 1: [15/Nov/2016:01:49:25][http-bio-31142-exec-3]: Established LDAP connection using basic authentication to host nocp30.idm.lab.eng.rdu2.redhat.com port 3389 as cn=Directory Manager [15/Nov/2016:01:49:25][http-bio-31142-exec-3]: initializing with mininum 3 and maximum 15 connections to host nocp30.idm.lab.eng.rdu2.redhat.com port 3389, secure connection, false, authentication type 1 [15/Nov/2016:01:49:25][http-bio-31142-exec-3]: increasing minimum connections by 3 [15/Nov/2016:01:49:25][http-bio-31142-exec-3]: new total available connections 3 [15/Nov/2016:01:49:25][http-bio-31142-exec-3]: new number of connections 3 [15/Nov/2016:01:49:25][http-bio-31142-exec-3]: Cert Repot inited [15/Nov/2016:01:49:25][http-bio-31142-exec-3]: CRL Repot inited [15/Nov/2016:01:49:25][http-bio-31142-exec-3]: Replica Repot inited [15/Nov/2016:01:49:25][http-bio-31142-exec-3]: CertificateAuthority:initSigUnit: ca cert found [15/Nov/2016:01:49:25][http-bio-31142-exec-3]: CertificateAuthority: initSigUnit 1- setting mIssuerObj and mSubjectObj [15/Nov/2016:01:49:25][http-bio-31142-exec-3]: ca.signing Signing Unit nickname lunasaQE:gkapoor/Test_ExternalCA3/ca_signing [15/Nov/2016:01:49:25][http-bio-31142-exec-3]: Got token lunasaQE by name [15/Nov/2016:01:49:25][http-bio-31142-exec-3]: Found cert by nickname: 'lunasaQE:gkapoor/Test_ExternalCA3/ca_signing' with serial number: 15938 [15/Nov/2016:01:49:25][http-bio-31142-exec-3]: converted to x509CertImpl [15/Nov/2016:01:49:25][http-bio-31142-exec-3]: Got private key from cert [15/Nov/2016:01:49:25][http-bio-31142-exec-3]: Got public key from cert [15/Nov/2016:01:49:25][http-bio-31142-exec-3]: got signing algorithm RSASignatureWithSHA512Digest [15/Nov/2016:01:49:25][http-bio-31142-exec-3]: CA signing unit inited [15/Nov/2016:01:49:25][http-bio-31142-exec-3]: cachainNum= 0 [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: in init - got CA chain from JSS. [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: ca.ocsp_signing Signing Unit nickname ocspSigningCert cert-Test_ExternalCA3 [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: Got token internal by name [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: SigningUnit: Certificate object not found Certificate object not found at com.netscape.ca.SigningUnit.init(SigningUnit.java:174) at com.netscape.ca.SigningUnit.init(SigningUnit.java:131) at com.netscape.ca.CertificateAuthority.initSigUnit(CertificateAuthority.java:1667) at com.netscape.ca.CertificateAuthority.init(CertificateAuthority.java:525) at com.netscape.cmscore.apps.CMSEngine.reinit(CMSEngine.java:1344) at com.netscape.certsrv.apps.CMS.reinit(CMS.java:191) at com.netscape.cms.servlet.csadmin.ConfigurationUtils.reInitSubsystem(ConfigurationUtils.java:2300) at org.dogtagpki.server.rest.SystemConfigService.configure(SystemConfigService.java:181) at org.dogtagpki.server.rest.SystemConfigService.configure(SystemConfigService.java:121) 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.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:137) at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:280) at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:234) at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:221) at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:356) at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:179) at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:220) at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56) at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51) 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:220) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505) 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:956) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:436) at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1078) at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625) at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Thread.java:745) Caused by: org.mozilla.jss.crypto.ObjectNotFoundException at org.mozilla.jss.CryptoManager.findCertByNicknameNative(Native Method) at org.mozilla.jss.CryptoManager.findCertByNickname(CryptoManager.java:1235) at com.netscape.ca.SigningUnit.init(SigningUnit.java:171) ... 70 more [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: CertificateAuthority.init(): Swallow exception in pre-op mode [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: CertificateAuthority init: initRequestQueue [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: selected policy processor = classic [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: GenericPolicyProcessor::init begins [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: GenericPolicyProcessor::init Certificate Policy Framework (deprecated) is DISABLED [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: CA policy inited [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: CA service inited [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: CA notifier inited [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: CA pending notifier inited [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: RequestRepository: constructor2. [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: CertificateAuthority.init(): Abort in pre-op mode [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: Creating LdapAnonConnFactory(PasswdUserDBAuthentication) [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: increasing minimum number of connections by 3 [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: new total number of connections 3 [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: new total available connections 3 [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: AuthSubsystem: initializing authentication manager AgentCertAuth [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: AuthSubsystem: initializing authentication manager SSLclientCertAuth [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: AuthSubsystem: initializing authentication manager TokenAuth [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: AuthSubsystem: initializing authentication manager flatFileAuth [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: FlatFileAuth: Splitting String: UID on commas [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: FlatFileAuth: countTokens:1 [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: FlatFileAuth: token 0 = UID [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: FlatFileAuth: Splitting String: PWD on commas [15/Nov/2016:01:49:26][http-bio-31142-exec-3]: FlatFileAuth: countTokens:1