#2226 KRA installation: NullPointerException in ProxyRealm.findSecurityConstraints
Closed: Fixed None Opened 8 years ago by cheimes.

KRA setup over LDAPS fails with a NullPointerException in ProxyRealm.findSecurityConstraints.

https://fedorahosted.org/freeipa/ticket/5570
https://www.redhat.com/archives/pki-devel/2016-February/msg00100.html

curl

# curl http://master1.ipa.test:8080/ca/admin/ca/getStatus
<!DOCTYPE html><html><head><title>Apache Tomcat/8.0.26 - Error report</title><style type="text/css">H1 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:22px;} H2 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:16px;} H3 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:14px;} BODY {font-family:Tahoma,Arial,sans-serif;color:black;background-color:white;} B {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;} P {font-family:Tahoma,Arial,sans-serif;background:white;color:black;font-size:12px;}A {color : black;}A.name {color : black;}.line {height: 1px; background-color: #525D76; border: none;}</style> </head><body><h1>HTTP Status 500 - </h1><div class="line"></div><p><b>type</b> Exception report</p><p><b>message</b> <u></u></p><p><b>description</b> <u>The server encountered an internal error that prevented it from fulfilling this request.</u></p><p><b>exception</b></p><pre>java.lang.NullPointerException
        com.netscape.cms.tomcat.ProxyRealm.findSecurityConstraints(ProxyRealm.java:114)
        org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:496)
        org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
        org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:616)
        org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:518)
        org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1091)
        org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:673)
        org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1526)
        org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1482)
        java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        java.lang.Thread.run(Thread.java:745)
</pre><p><b>note</b> <u>The full stack trace of the root cause is available in the Apache Tomcat/8.0.26 logs.</u></p><hr class="line"><h3>Apache Tomcat/8.0.26</h3></body></html>

journalctl

# journalctl -f -u pki-tomcatd@pki-tomcat.service
...
Mar 01 12:10:31 master1.ipa.test server[8061]: Mar 01, 2016 12:10:31 PM org.apache.catalina.core.ContainerBase backgroundProcess
Mar 01 12:10:31 master1.ipa.test server[8061]: WARNING: Exception processing realm com.netscape.cms.tomcat.ProxyRealm@65ac2207 background process
Mar 01 12:10:31 master1.ipa.test server[8061]: java.lang.NullPointerException
Mar 01 12:10:31 master1.ipa.test server[8061]: at com.netscape.cms.tomcat.ProxyRealm.backgroundProcess(ProxyRealm.java:109)
Mar 01 12:10:31 master1.ipa.test server[8061]: at org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1127)
Mar 01 12:10:31 master1.ipa.test server[8061]: at org.apache.catalina.core.StandardContext.backgroundProcess(StandardContext.java:5554)
Mar 01 12:10:31 master1.ipa.test server[8061]: at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1377)
Mar 01 12:10:31 master1.ipa.test server[8061]: at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1381)
Mar 01 12:10:31 master1.ipa.test server[8061]: at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1381)
Mar 01 12:10:31 master1.ipa.test server[8061]: at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1349)
Mar 01 12:10:31 master1.ipa.test server[8061]: at java.lang.Thread.run(Thread.java:745)
# rpm -qa tomcat pki-ca freeipa-server
pki-ca-10.2.6-15.fc23.noarch
freeipa-server-4.3.90-0.fc23.x86_64
tomcat-8.0.26-2.fc23.noarch

I think the NULL ptr exception is caused by an error during CMSEngine initialization. CMSStartServlet.init() sets up the proxy realm with ProxyRealm.registerRealm(subsystem, new PKIRealm());.

Mar 01 12:07:23 master1.ipa.test server[8061]: CMSEngine.initializePasswordStore() begins
Mar 01 12:07:23 master1.ipa.test server[8061]: CMSEngine.initializePasswordStore(): tag=internaldb
Mar 01 12:07:23 master1.ipa.test server[8061]: testLDAPConnection connecting to master1.ipa.test:636
Mar 01 12:07:23 master1.ipa.test server[8061]: CMSEngine.initializePasswordStore(): tag=replicationdb
Mar 01 12:07:23 master1.ipa.test server[8061]: testLDAPConnection connecting to master1.ipa.test:636
Mar 01 12:07:23 master1.ipa.test server[8061]: testLDAPConnection: The specified user cn=Replication Manager masterAgreement1-master1.ipa.test-pki-tomcat,cn=config do
Mar 01 12:07:24 master1.ipa.test server[8061]: CMSEngine: init(): password test execution failed for replicationdbwith NO_SUCH_USER.  This may not be a latest instanc
Mar 01 12:07:27 master1.ipa.test server[8061]: KRA is started.

I'm able to reproduce it regularly with IPA CI tests, attaching snippet from debug log

[09/Mar/2016:09:47:10][localhost-startStop-1]: init: before makeConnection errorIfDown is true
[09/Mar/2016:09:47:10][localhost-startStop-1]: makeConnection: errorIfDown true
[09/Mar/2016:09:47:10][localhost-startStop-1]: LdapJssSSLSocket set client auth cert nicknamesubsystemCert cert-pki-ca
[09/Mar/2016:09:47:10][localhost-startStop-1]: SSL handshake happened
Internal Database Error encountered: Could not connect to LDAP server host replica2.ipa.test port 636 Error netscape.ldap.LDAPException: Authentication failed (48)
        at com.netscape.cmscore.dbs.DBSubsystem.init(DBSubsystem.java:673)
        at com.netscape.cmscore.apps.CMSEngine.initSubsystem(CMSEngine.java:1167)
        at com.netscape.cmscore.apps.CMSEngine.initSubsystems(CMSEngine.java:1073)
        at com.netscape.cmscore.apps.CMSEngine.init(CMSEngine.java:570)
        at com.netscape.certsrv.apps.CMS.init(CMS.java:187)
        at com.netscape.certsrv.apps.CMS.start(CMS.java:1594)
        at com.netscape.cms.servlet.base.CMSStartServlet.init(CMSStartServlet.java:114)
        at javax.servlet.GenericServlet.init(GenericServlet.java:158)
        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:286)
        at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:283)
        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:318)
        at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:173)
        at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:122)
        at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1219)
        at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1144)
        at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:1031)
        at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:4914)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5201)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:725)
        at org.apache.catalina.core.ContainerBase.access$000(ContainerBase.java:131)
        at org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:153)
        at org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:143)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:699)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:717)
        at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:586)
        at org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1750)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        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)

The following error message indicates that the replicationdb password in /var/lib/pki/pki-tomcat/conf/password.conf is incorrect:

CMSEngine: init(): password test execution failed for replicationdbwith NO_SUCH_USER.  This may not be a latest instance. Ignoring ..

The following error also indicates authentication issue:

Internal Database Error encountered: Could not connect to LDAP server host replica2.ipa.test port 636 Error netscape.ldap.LDAPException: Authentication failed (48)

According to mbasti the problem was reproduced with vagrant. I have not had a chance to try it successfully with vagrant, and I was not able to reproduce the problem with normal KRA installation.

Could you describe the test scenario (with detailed steps) without vagrant? If that scenario works without vagrant, I'd say that this is a vagrant-specific problem and not PKI.

Vagrant is just provisioning system for creating VMs. VMs are running under libvirt provider so I don't think this is related to vagrant. This can be related to speed because VMs are faster on our laptops than in LAB.

FreeIPA team can provide SSH tunel to local VMs if needed.

Steps to reproduce is just to run ipa-kra-install on master.

Just an update, it appears that in that particular situation PKI does not actually send a client certificate (i.e. subsystemCert cert-pki-ca) to the DS even though the log says so, that's why the authentication failed. It's still unclear why it doesn't send the certificate since the same code works in other situations. Does IPA do anything specific to "subsystemCert cert-pki-ca" during installation?

Per CS Bug/Ticket Triage held 04/19/2016: 10.3.1

I'm seeing this exception in a FreeIPA server as well. KRA installation worked fine but this seems to be preventing the CMS from starting properly resulting in all CA operations to fail. Using the CA/KRA master for CA operations works without a problem.

If the LDAP connection error happens during KRA cloning it might be fixed in ticket #2374.

This may be fixed by upgrading to NSS 3.27. See this ticket:
https://bugzilla.redhat.com/show_bug.cgi?id=1393393

Per discussion with mharmsen, this will be fixed on the current Fedora only. The current RHEL/CentOS does not have NSS 3.27. It's also unknown if the problem happens on other platforms.

Patch posted in bug #1393393.

Updated NSS dependency as mentioned in bug #1393393.

Changes in master:

  • f7b69b0804ddb1c80250616fff601e3573602eae

Changes in 10.3 branch:

  • 12921f2270d66beb6f2cbaf5ed12127ae2ac65bd

Feel free to reopen the ticket if the problem still persists.

Metadata Update from @cheimes:
- Issue assigned to edewata
- Issue set to the milestone: 10.3.9

7 years ago

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/2346

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.

Login to comment on this ticket.

Metadata