[Freeipa-users] Multiple issues (weblogin, DNS) with 4.3.1

Tomasz Torcz tomek at pipebreaker.pl
Mon Jun 20 08:07:15 UTC 2016 

On Sat, Jun 18, 2016 at 11:02:23PM -0400, Rob Crittenden wrote:
> > 
> >    Most of the functions work, but 5) I cannot get Authentication→Certificates
> > list:
> > 
> > On okda, going to Certificates list yields ”Certificate operation cannot be completed: Unable to communicate with CMS (Internal Server Error)”
> > and error_log contains:
> > [Sat Jun 18 18:59:10.523796 2016] [wsgi:error] [pid 748083] <CertSearchRequest><revokedByInUse>false</revokedByInUse><certTypeInUse>false</certTypeInUse><revokedOnInUse>false</revokedOnInUse><validNotAfterInUse>false</validNotAfterInUse><revocationReasonInUse>false</revocationReasonInUse><serialNumberRangeInUse>true</serialNumberRangeInUse><validityLengthInUse>false</validityLengthInUse><subjectInUse>false</subjectInUse><validNotBeforeInUse>false</validNotBeforeInUse><issuedByInUse>false</issuedByInUse><issuedOnInUse>false</issuedOnInUse><matchExactly>false</matchExactly></CertSearchRequest>
> > [Sat Jun 18 18:59:11.244206 2016] [wsgi:error] [pid 748083] ipa: DEBUG: HTTP Response code: 500
> > [Sat Jun 18 18:59:11.248305 2016] [wsgi:error] [pid 748083] ipa: ERROR: ipaserver.plugins.dogtag.ra.find(): Unable to communicate with CMS (Internal Server Error)
> > [Sat Jun 18 18:59:11.336576 2016] [wsgi:error] [pid 748083] ipa: DEBUG: WSGI wsgi_execute PublicError: Traceback (most recent call last):
> > [Sat Jun 18 18:59:11.336895 2016] [wsgi:error] [pid 748083]   File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 350, in wsgi_execute
> > [Sat Jun 18 18:59:11.337011 2016] [wsgi:error] [pid 748083]     result = self.Command[name](*args, **options)
> > [Sat Jun 18 18:59:11.337086 2016] [wsgi:error] [pid 748083]   File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 446, in __call__
> > [Sat Jun 18 18:59:11.337156 2016] [wsgi:error] [pid 748083]     ret = self.run(*args, **options)
> > [Sat Jun 18 18:59:11.337241 2016] [wsgi:error] [pid 748083]   File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 763, in run
> > [Sat Jun 18 18:59:11.337311 2016] [wsgi:error] [pid 748083]     return self.execute(*args, **options)
> > [Sat Jun 18 18:59:11.337373 2016] [wsgi:error] [pid 748083]   File "/usr/lib/python2.7/site-packages/ipalib/plugins/cert.py", line 819, in execute
> > [Sat Jun 18 18:59:11.337417 2016] [wsgi:error] [pid 748083]     result=self.Backend.ra.find(options)
> > [Sat Jun 18 18:59:11.337455 2016] [wsgi:error] [pid 748083]   File "/usr/lib/python2.7/site-packages/ipaserver/plugins/dogtag.py", line 1861, in find
> > [Sat Jun 18 18:59:11.337493 2016] [wsgi:error] [pid 748083]     detail=e.msg)
> > [Sat Jun 18 18:59:11.337566 2016] [wsgi:error] [pid 748083]   File "/usr/lib/python2.7/site-packages/ipaserver/plugins/dogtag.py", line 1331, in raise_certificate_operation_error
> > [Sat Jun 18 18:59:11.337653 2016] [wsgi:error] [pid 748083]     raise errors.CertificateOperationError(error=err_msg)
> > [Sat Jun 18 18:59:11.337717 2016] [wsgi:error] [pid 748083] CertificateOperationError: Certificate operation cannot be completed: Unable to communicate with CMS (Internal Server Error)
> > [Sat Jun 18 18:59:11.337770 2016] [wsgi:error] [pid 748083]
> > [Sat Jun 18 18:59:11.338805 2016] [wsgi:error] [pid 748083] ipa: INFO: [jsonserver_session] admin at PIPEBREAKER.PL: cert_find(version=u'2.164'): CertificateOperationError
> > 
> >    How to fix those?
> 
> You'll need to look at the dogtag debug log for the reason it threw a 500,
> it's in /var/log/pki-tomcat/ca or something close to that.


  I've looked into the logs but I'm not wiser.  Is there a setting to get
rid of java traceback from logs and get more useful messages?  There seem
to be a problem with SSL connection to port 636, maybe because it seems to use
expired certificate?

$ echo | openssl s_client  -connect okda.pipebreaker.pl:636  | openssl x509 -noout
depth=1 O = PIPEBREAKER.PL, CN = Certificate Authority
verify return:1
depth=0 O = PIPEBREAKER.PL, CN = okda.pipebreaker.pl
verify error:num=10:certificate has expired
notAfter=Nov 17 12:19:28 2015 GMT
verify return:1
depth=0 O = PIPEBREAKER.PL, CN = okda.pipebreaker.pl
notAfter=Nov 17 12:19:28 2015 GMT
verify return:1
DONE



Log from /var/log/pki/pki-tomcat/ca/system:

0.localhost-startStop-1 - [18/Jun/2016:18:54:09 CEST] [8] [3] In Ldap (bound) connection pool to host okda.pipebreaker.pl port 636, Cannot connect to LDAP server. Error: netscape.ldap.LDAPException: IO Error creating JSS SSL Socket (-1)



Log from /var/log/pki/pki-tomcat/ca/debug:

[18/Jun/2016:18:54:03][localhost-startStop-1]: ============================================
[18/Jun/2016:18:54:03][localhost-startStop-1]: =====  DEBUG SUBSYSTEM INITIALIZED   =======
[18/Jun/2016:18:54:03][localhost-startStop-1]: ============================================
[18/Jun/2016:18:54:03][localhost-startStop-1]: CMSEngine: restart at autoShutdown? false
[18/Jun/2016:18:54:03][localhost-startStop-1]: CMSEngine: autoShutdown crumb file path? /var/lib/pki/pki-tomcat/logs/autoShutdown.crumb
[18/Jun/2016:18:54:03][localhost-startStop-1]: CMSEngine: about to look for cert for auto-shutdown support:auditSigningCert cert-pki-ca
[18/Jun/2016:18:54:03][localhost-startStop-1]: CMSEngine: found cert:auditSigningCert cert-pki-ca
[18/Jun/2016:18:54:03][localhost-startStop-1]: CMSEngine: done init id=debug
[18/Jun/2016:18:54:03][localhost-startStop-1]: CMSEngine: initialized debug
[18/Jun/2016:18:54:03][localhost-startStop-1]: CMSEngine: initSubsystem id=log
[18/Jun/2016:18:54:03][localhost-startStop-1]: CMSEngine: ready to init id=log
[18/Jun/2016:18:54:04][localhost-startStop-1]: Creating RollingLogFile(/var/lib/pki/pki-tomcat/logs/ca/signedAudit/ca_audit)
[18/Jun/2016:18:54:09][localhost-startStop-1]: Creating RollingLogFile(/var/lib/pki/pki-tomcat/logs/ca/system)
[18/Jun/2016:18:54:09][localhost-startStop-1]: Creating RollingLogFile(/var/lib/pki/pki-tomcat/logs/ca/transactions)
[18/Jun/2016:18:54:09][localhost-startStop-1]: CMSEngine: restart at autoShutdown? false
[18/Jun/2016:18:54:09][localhost-startStop-1]: CMSEngine: autoShutdown crumb file path? /var/lib/pki/pki-tomcat/logs/autoShutdown.crumb
[18/Jun/2016:18:54:09][localhost-startStop-1]: CMSEngine: about to look for cert for auto-shutdown support:auditSigningCert cert-pki-ca
[18/Jun/2016:18:54:09][localhost-startStop-1]: CMSEngine: found cert:auditSigningCert cert-pki-ca
[18/Jun/2016:18:54:09][localhost-startStop-1]: CMSEngine: done init id=log
[18/Jun/2016:18:54:09][localhost-startStop-1]: CMSEngine: initialized log
[18/Jun/2016:18:54:09][localhost-startStop-1]: CMSEngine: initSubsystem id=jss
[18/Jun/2016:18:54:09][localhost-startStop-1]: CMSEngine: ready to init id=jss
[18/Jun/2016:18:54:09][localhost-startStop-1]: CMSEngine: restart at autoShutdown? false
[18/Jun/2016:18:54:09][localhost-startStop-1]: CMSEngine: autoShutdown crumb file path? /var/lib/pki/pki-tomcat/logs/autoShutdown.crumb
[18/Jun/2016:18:54:09][localhost-startStop-1]: CMSEngine: about to look for cert for auto-shutdown support:auditSigningCert cert-pki-ca
[18/Jun/2016:18:54:09][localhost-startStop-1]: CMSEngine: found cert:auditSigningCert cert-pki-ca
[18/Jun/2016:18:54:09][localhost-startStop-1]: CMSEngine: done init id=jss
[18/Jun/2016:18:54:09][localhost-startStop-1]: CMSEngine: initialized jss
[18/Jun/2016:18:54:09][localhost-startStop-1]: CMSEngine: initSubsystem id=dbs
[18/Jun/2016:18:54:09][localhost-startStop-1]: CMSEngine: ready to init id=dbs
[18/Jun/2016:18:54:09][localhost-startStop-1]: DBSubsystem: init()  mEnableSerialMgmt=true
[18/Jun/2016:18:54:09][localhost-startStop-1]: Creating LdapBoundConnFactor(DBSubsystem)
[18/Jun/2016:18:54:09][localhost-startStop-1]: LdapBoundConnFactory: init 
[18/Jun/2016:18:54:09][localhost-startStop-1]: LdapBoundConnFactory:doCloning true
[18/Jun/2016:18:54:09][localhost-startStop-1]: LdapAuthInfo: init()
[18/Jun/2016:18:54:09][localhost-startStop-1]: LdapAuthInfo: init begins
[18/Jun/2016:18:54:09][localhost-startStop-1]: LdapAuthInfo: init ends
[18/Jun/2016:18:54:09][localhost-startStop-1]: init: before makeConnection errorIfDown is true
[18/Jun/2016:18:54:09][localhost-startStop-1]: makeConnection: errorIfDown true
[18/Jun/2016:18:54:09][localhost-startStop-1]: LdapJssSSLSocket set client auth cert nicknamesubsystemCert cert-pki-ca
Could not connect to LDAP server host okda.pipebreaker.pl port 636 Error netscape.ldap.LDAPException: IO Error creating JSS SSL Socket (-1)
        at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.makeConnection(LdapBoundConnFactory.java:205)
        at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.init(LdapBoundConnFactory.java:166)
        at com.netscape.cmscore.ldapconn.LdapBoundConnFactory.init(LdapBoundConnFactory.java:130)
        at com.netscape.cmscore.dbs.DBSubsystem.init(DBSubsystem.java:654)
        at com.netscape.cmscore.apps.CMSEngine.initSubsystem(CMSEngine.java:1166)
        at com.netscape.cmscore.apps.CMSEngine.initSubsystems(CMSEngine.java:1072)
        at com.netscape.cmscore.apps.CMSEngine.init(CMSEngine.java:568)
        at com.netscape.certsrv.apps.CMS.init(CMS.java:187)
        at com.netscape.certsrv.apps.CMS.start(CMS.java:1616)
        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:1226)
        at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1151)
        at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:1038)
        at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:4997)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5289)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:147)
        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:585)
        at org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1794)
        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)
Internal Database Error encountered: Could not connect to LDAP server host okda.pipebreaker.pl port 636 Error netscape.ldap.LDAPException: IO Error creating JSS SSL Socket (-1)
        at com.netscape.cmscore.dbs.DBSubsystem.init(DBSubsystem.java:676)
        at com.netscape.cmscore.apps.CMSEngine.initSubsystem(CMSEngine.java:1166)
        at com.netscape.cmscore.apps.CMSEngine.initSubsystems(CMSEngine.java:1072)
        at com.netscape.cmscore.apps.CMSEngine.init(CMSEngine.java:568)
        at com.netscape.certsrv.apps.CMS.init(CMS.java:187)
        at com.netscape.certsrv.apps.CMS.start(CMS.java:1616)
        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:1226)
        at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1151)
        at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:1038)
        at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:4997)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5289)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:147)
        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:585)
        at org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1794)
        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)
[18/Jun/2016:18:54:09][localhost-startStop-1]: CMSEngine.shutdown()


-- 
Tomasz Torcz               RIP is irrevelant. Spoofing is futile.
xmpp: zdzichubg at chrome.pl     Your routes will be aggreggated. -- Alex Yuriev

More information about the Freeipa-users mailing list