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

Rob Crittenden rcritten at redhat.com
Tue Jun 21 17:38:19 UTC 2016 

Tomasz Torcz wrote:
> 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?

Not that I know of. The debug log is sure a firehose but you've 
identified the problem.

> $ 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

Run getcert list and look at the expiration dates. What you want to do 
is kill ntpd, set the date back to say a week before the oldest date, 
restart the dirsrv, restart the pki-tomcat/pki-cad service then restart 
certmonger. This should force a renewal attempt.

Use getcert and syslog to watch progress. It may require a few restarts 
of certmonger to get all the certs renewed.

Ideally that all happens fairly gracefully so then you move forward in 
time again, run ipactl restart and things work as usual.

rob

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

More information about the Freeipa-users mailing list