search

dogtagpki / pki

The Dogtag Certificate System is an enterprise-class Certificate Authority (CA) which supports all aspects of certificate lifecycle management, including key archival, OCSP and smartcard management.
https://www.dogtagpki.org
GNU General Public License v2.0
368 stars 136 forks source link

CA: Logging Improvement #2671

Open pki-bot opened 4 years ago

pki-bot commented 4 years ago

This issue was migrated from Pagure Issue #2551. Originally filed by gkapoor (@geetikakay) on 2016-11-16 20:15:08:

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:geetikakay/Test_ExternalCA3/subsystem                  u,u,u
lunasaQE:geetikakay/Test_ExternalCA3/sslserver/nocp30.idm.lab.eng.rdu2.redhat.com
u,u,u
lunasaQE:geetikakay/Test_ExternalCA3/ca_ocsp_signing            u,u,u
lunasaQE:geetikakay/Test_ExternalCA3/ca_audit_signing           u,u,u
lunasaQE:geetikakay/Test_ExternalCA3/ca_signing                 u,u,u
lunasaQE:geetikakay/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/confi
guration.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.ja
va:1846)
    at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:224)
    at org.apache.catalina.core.StandardContext.stopInternal(StandardContext.ja
va: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(DelegatingMethodAccessor
Impl.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

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.

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:geetikakay/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:geetikakay/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(CertificateAuthorit
y.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(SystemConfig
Service.java:181)
        at org.dogtagpki.server.rest.SystemConfigService.configure(SystemConfig
Service.java:121)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcce
ssorImpl.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(Resourc
eMethodInvoker.java:280)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodI
nvoker.java:234)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodI
nvoker.java:221)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDisp
atcher.java:356)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDisp
atcher.java:179)
        at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher
.service(ServletContainerDispatcher.java:220)
        at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.serv
ice(HttpServletDispatcher.java:56)
        at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.serv
ice(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(DelegatingMethodAcce
ssorImpl.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(App
licationFilterChain.java:297)
        at org.apache.catalina.core.ApplicationFilterChain.access$000(Applicati
onFilterChain.java:55)
        at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFil
terChain.java:191)
        at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFil
terChain.java:187)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(Application
FilterChain.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(DelegatingMethodAcce
ssorImpl.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(App
licationFilterChain.java:237)
        at org.apache.catalina.core.ApplicationFilterChain.access$000(Applicati
onFilterChain.java:55)
        at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFil
terChain.java:191)
        at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFil
terChain.java:187)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(Application
FilterChain.java:186)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapper
Valve.java:220)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContext
Valve.java:122)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(Authentic
atorBase.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(StandardEngineVa
lve.java:116)
        at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:436)
        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHtt
p11Processor.java:1078)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process
(AbstractProtocol.java:625)
        at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoi
nt.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(TaskT
hread.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
pki-bot commented 4 years ago

Comment from mharmsen (@mharmsen) at 2016-11-18 00:34:24

Per PKI Bug Council of 11/17/2016: 10.4 - minor

pki-bot commented 4 years ago

Comment from gkapoor (@geetikakay) at 2017-02-27 14:10:15

Metadata Update from @geetikakay:

pki-bot commented 4 years ago

Comment from mharmsen (@mharmsen) at 2017-03-03 14:34:20

Metadata Update from @mharmsen:

pki-bot commented 4 years ago

Comment from mharmsen (@mharmsen) at 2017-08-09 16:52:55

Per CS/DS Meeting of August 7, 2017, it was determined to move this issue from 10.4 ==> FUTURE.

pki-bot commented 4 years ago

Comment from mharmsen (@mharmsen) at 2017-08-09 16:52:55

Metadata Update from @mharmsen:

pki-bot commented 4 years ago

Comment from mharmsen (@mharmsen) at 2017-08-31 01:41:59

Metadata Update from @mharmsen:

pki-bot commented 4 years ago

Comment from edewata (@edewata) at 2020-02-09 23:13:47

This issue is no longer happening in PKI 10.8.

pki-bot commented 4 years ago

Comment from edewata (@edewata) at 2020-02-09 23:13:47

Metadata Update from @edewata:

pki-bot commented 4 years ago

Comment from edewata (@edewata) at 2020-02-09 23:41:22

Metadata Update from @edewata:

pki-bot commented 4 years ago

Comment from edewata (@edewata) at 2020-02-09 23:53:22

Actually, the first scenario is still generating exceptions, but in general there has been a lot of logging improvements in PKI 10.8 so some logging issues may no longer exist or have been handled differently.

The second scenario, however, is outside the scope of PKI. If the port is conflicting with another process, Tomcat will fail to start and it will log the reason in the systemd journal. pkispawn can only say that Tomcat fails to start. It's the admin's responsibility to check why Tomcat fails to start (by checking the systemd journal).