dogtagpki

#2551 CA: Logging Improvement
Closed: migrated by dmoluguw. Opened by gkapoor.

Closed: migrated
Reopen Issue

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/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: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(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

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

Metadata Update from @gkapoor:
- Issue set to the milestone: UNTRIAGED

Metadata Update from @mharmsen:
- Custom field feature adjusted to ''
- Custom field proposedmilestone adjusted to ''
- Custom field proposedpriority adjusted to ''
- Custom field reviewer adjusted to ''
- Custom field version adjusted to ''
- Issue close_status updated to: None
- Issue set to the milestone: 10.4 (was: UNTRIAGED)

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

Metadata Update from @mharmsen:
- Issue set to the milestone: FUTURE (was: 10.4)

Metadata Update from @mharmsen:
- Custom field lowhangingfruit adjusted to vakwetu: X

This issue is no longer happening in PKI 10.8.

Metadata Update from @edewata:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)

Metadata Update from @edewata:
- Issue status updated to: Open (was: Closed)

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).

Dogtag PKI is moving from Pagure issues to GitHub issues. This means that existing or new
issues will be reported and tracked through Dogtag PKI's GitHub Issue tracker.

This issue has been cloned to GitHub and is available here:
https://github.com/dogtagpki/pki/issues/2671

If you want to receive further updates on the issue, please navigate to the
GitHub issue and click on Subscribe button.

Thank you for understanding, and we apologize for any inconvenience.

Metadata Update from @dmoluguw:
- Issue close_status updated to: migrated
- Issue status updated to: Closed (was: Open)
Metadata
None
None
None
None
High
''
''
''
''
''
defect
Logging
QE
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.