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