10000 CA: Logging Improvement · Issue #2671 · dogtagpki/pki · GitHub
[go: up one dir, main page]
More Web Proxy on the site http://driver.im/
Skip to content

CA: Logging Improvement #2671

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
pki-bot opened this issue Oct 3, 2020 · 12 comments
Closed

CA: Logging Improvement #2671

pki-bot opened this issue Oct 3, 2020 · 12 comments
Labels
Stale
Milestone
FUTURE

Comments

@pki-bot
Copy link
pki-bot commented Oct 3, 2020

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.ResourceMethodI
8000
nvoker.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 pki-bot added this to the FUTURE milestone Oct 3, 2020
@pki-bot
Copy link
Author
pki-bot commented Oct 3, 2020

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

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

@pki-bot
Copy link
Author
pki-bot commented Oct 3, 2020

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

Metadata Update from @geetikakay:

  • Issue set to the milestone: UNTRIAGED

@pki-bot
Copy link
Author
pki-bot commented Oct 3, 2020

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

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)

@pki-bot
Copy link
Author
pki-bot commented Oct 3, 2020

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
Copy link
Author
pki-bot commented Oct 3, 2020

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

Metadata Update from @mharmsen:

  • Issue set to the milestone: FUTURE (was: 10.4)

@pki-bot
Copy link
Author
pki-bot commented Oct 3, 2020

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

Metadata Update from @mharmsen:

  • Custom field lowhangingfruit adjusted to vakwetu: X

@pki-bot
Copy link
Author
pki-bot commented Oct 3, 2020

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

This issue is no longer happening in PKI 10.8.

@pki-bot
Copy link
Author
pki-bot commented Oct 3, 2020

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

Metadata Update from @edewata:

  • Issue close_status updated to: fixed
  • Issue status updated to: Closed (was: Open)

@pki-bot
Copy link
Author
pki-bot commented Oct 3, 2020

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

Metadata Update from @edewata:

  • Issue status updated to: Open (was: Closed)

@pki-bot
Copy link
Author
pki-bot commented Oct 3, 2020

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

@github-actions GitHub Actions
Copy link

This issue is stale because it has been open 365 days with no activity. Remove stale label or comment or this will be closed in 30 days.

@github-actions github-actions bot added the Stale label Mar 11, 2025
@github-actions GitHub Actions
Copy link

This issue will be closed for inactivity. If the problem is still present reopen this or create a new issue.

@github-actions github-actions bot closed this as not planned Won't fix, can't repro, duplicate, stale Apr 11, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Stale
Projects
None yet
Milestone
FUTURE
Development

No branches or pull requests
1 participant
@pki-bot
0