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

Sat Jun 18 17:13:54 UTC 2016

On Fri, Jun 17, 2016 at 11:32:22AM +0200, Petr Vobornik wrote:
> On 27.5.2016 14:28, Tomasz Torcz wrote:
> > Hi,
> > 
> >   In my home environment I'm using two-server FreeIPA configuration on Fedora.
> > Initially installed on fedora 19 in November 2013, it have been upgraded every
> > Fedora release. It generally works OK, but somewhat degrades during operation.
> > Recently I've jumped to F24 in hope my problems will be resolved, but they weren't.
> > Thus this email and plea for assistance.
> > 
> >   I'm using freeipa-server-4.3.1-1.fc24.x86_64. One of the servers is called
> > kaitain.pipebreaker.pl, the other okda.pipebreaker.pl.
> > 
> >   Currently I encounter following main problems:
> > 1) named is not servicing all the records from LDAP
> > 2) can't login to WebUI on kaitain.pipebreaker.pl
> > 3) can't login to WebUI on okda.pipebreaker.pl
> > 4) pycparser.lextab/lextab.py/yacctab.py permission errors
> 
> 
> Switch IPA framework to debug mode as described below. It should show
> more information.
> 
> 
> Httpd error_log should at least show which operation encountered the
> Gateway timeout. If not, then put IPA framework into debug mode:
> 
> http://www.freeipa.org/page/Troubleshooting#Administration_Framework

  Thanks Petr! While editing /etc/ipa/defualt.conf to enable debug
I've noticed my previous errors.  Few weeks ago I was having problems
with certmonger not re-requesting certificates. In order to point 
certmonger to the other IPA server, I've edited host= line
in default.conf.
  After all I must have mixed things up, and _both_ mine IPA servers
had the other host entered in host= line. After entering correct
names, I can log into both web uis.

  Most of the functions work, but 5) I cannot get Authentication→Certificates
list:

on kaitain, after going into Authentication -> Certificates list I got
ethernal spinning in browser, and error_log contains:
[Sat Jun 18 18:46:07.665264 2016] [wsgi:error] [pid 12629] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
[Sat Jun 18 18:46:07.665458 2016] [wsgi:error] [pid 12629] ipa: DEBUG: WSGI jsonserver_session.__call__:
[Sat Jun 18 18:46:07.665637 2016] [wsgi:error] [pid 12629] ipa: DEBUG: found session cookie_id = 47c42943141700c4968c2c2f3f050848
[Sat Jun 18 18:46:07.666035 2016] [wsgi:error] [pid 12629] ipa: DEBUG: found session data in cache with id=47c42943141700c4968c2c2f3f050848
[Sat Jun 18 18:46:07.666169 2016] [wsgi:error] [pid 12629] ipa: DEBUG: jsonserver_session.__call__: session_id=47c42943141700c4968c2c2f3f050848 start_timestamp=2016-06-18T18:42:34 access_timestamp=2016-06-18T18:46:07 expiration_timestamp=2016-06-18T19:06:01
[Sat Jun 18 18:46:07.666268 2016] [wsgi:error] [pid 12629] ipa: DEBUG: storing ccache data into file "/var/run/ipa_memcached/krbcc_12629"
[Sat Jun 18 18:46:07.667531 2016] [wsgi:error] [pid 12629] ipa: DEBUG: set_session_expiration_time: duration_type=inactivity_timeout duration=1200 max_age=1466354363.67 expiration=1466269567.67 (2016-06-18T19:06:07)
[Sat Jun 18 18:46:07.938034 2016] [wsgi:error] [pid 12629] ipa: DEBUG: Created connection context.ldap2_139873368474448
[Sat Jun 18 18:46:07.938202 2016] [wsgi:error] [pid 12629] ipa: DEBUG: WSGI jsonserver.__call__:
[Sat Jun 18 18:46:07.938293 2016] [wsgi:error] [pid 12629] ipa: DEBUG: WSGI WSGIExecutioner.__call__:
[Sat Jun 18 18:46:07.938652 2016] [wsgi:error] [pid 12629] ipa: DEBUG: raw: cert_find(version=u'2.164')
[Sat Jun 18 18:46:07.938900 2016] [wsgi:error] [pid 12629] ipa: DEBUG: cert_find(exactly=False, all=False, raw=False, version=u'2.164')
[Sat Jun 18 18:46:07.939225 2016] [wsgi:error] [pid 12629] ipa: DEBUG: raw: ca_is_enabled(version=u'2.164')
[Sat Jun 18 18:46:07.939574 2016] [wsgi:error] [pid 12629] ipa: DEBUG: ca_is_enabled(version=u'2.164')
[Sat Jun 18 18:46:08.079826 2016] [wsgi:error] [pid 12629] ipa: DEBUG: ipaserver.plugins.dogtag.ra.find()
[Sat Jun 18 18:46:08.080263 2016] [wsgi:error] [pid 12629] ipa: DEBUG: ipaserver.plugins.dogtag.ra.find(): request: <?xml version='1.0' encoding='UTF-8'?>
[Sat Jun 18 18:46:08.080339 2016] [wsgi:error] [pid 12629] <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>

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.100983 2016] [wsgi:error] [pid 748083] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
[Sat Jun 18 18:59:10.101728 2016] [wsgi:error] [pid 748083] ipa: DEBUG: WSGI jsonserver_session.__call__:
[Sat Jun 18 18:59:10.102146 2016] [wsgi:error] [pid 748083] ipa: DEBUG: found session cookie_id = b5e06452ed9aa125f497913ce7703e2d
[Sat Jun 18 18:59:10.103128 2016] [wsgi:error] [pid 748083] ipa: DEBUG: found session data in cache with id=b5e06452ed9aa125f497913ce7703e2d
[Sat Jun 18 18:59:10.103506 2016] [wsgi:error] [pid 748083] ipa: DEBUG: jsonserver_session.__call__: session_id=b5e06452ed9aa125f497913ce7703e2d start_timestamp=2016-06-18T18:53:51 access_timestamp=2016-06-18T18:59:10 expiration_timestamp=2016-06-18T19:18:05
[Sat Jun 18 18:59:10.103740 2016] [wsgi:error] [pid 748083] ipa: DEBUG: storing ccache data into file "/var/run/ipa_memcached/krbcc_748083"
[Sat Jun 18 18:59:10.106447 2016] [wsgi:error] [pid 748083] ipa: DEBUG: set_session_expiration_time: duration_type=inactivity_timeout duration=1200 max_age=1466355156.11 expiration=1466270350.11 (2016-06-18T19:19:10)
[Sat Jun 18 18:59:10.146746 2016] [wsgi:error] [pid 748083] ipa: DEBUG: Created connection context.ldap2_139926010708624
[Sat Jun 18 18:59:10.146927 2016] [wsgi:error] [pid 748083] ipa: DEBUG: WSGI jsonserver.__call__:
[Sat Jun 18 18:59:10.147058 2016] [wsgi:error] [pid 748083] ipa: DEBUG: WSGI WSGIExecutioner.__call__:
[Sat Jun 18 18:59:10.204085 2016] [wsgi:error] [pid 748083] ipa: DEBUG: raw: cert_find(version=u'2.164')
[Sat Jun 18 18:59:10.207402 2016] [wsgi:error] [pid 748083] ipa: DEBUG: cert_find(exactly=False, all=False, raw=False, version=u'2.164')
[Sat Jun 18 18:59:10.227056 2016] [wsgi:error] [pid 748083] ipa: DEBUG: raw: ca_is_enabled(version=u'2.164')
[Sat Jun 18 18:59:10.229373 2016] [wsgi:error] [pid 748083] ipa: DEBUG: ca_is_enabled(version=u'2.164')
[Sat Jun 18 18:59:10.414288 2016] [wsgi:error] [pid 748083] ipa: DEBUG: ipaserver.plugins.dogtag.ra.find()
[Sat Jun 18 18:59:10.523459 2016] [wsgi:error] [pid 748083] ipa: DEBUG: ipaserver.plugins.dogtag.ra.find(): request: <?xml version='1.0' encoding='UTF-8'?>
[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
[Sat Jun 18 18:59:11.339764 2016] [wsgi:error] [pid 748083] ipa: DEBUG: reading ccache data from file "/var/run/ipa_memcached/krbcc_748083"
[Sat Jun 18 18:59:11.340133 2016] [wsgi:error] [pid 748083] ipa: DEBUG: store session: session_id=b5e06452ed9aa125f497913ce7703e2d start_timestamp=2016-06-18T18:53:51 access_timestamp=2016-06-18T18:59:11 expiration_timestamp=2016-06-18T19:19:10
[Sat Jun 18 18:59:11.342056 2016] [wsgi:error] [pid 748083] ipa: DEBUG: Destroyed connection context.ldap2_139926010708624

  How to fix those?

BTW, I've increased socket-timeout in /etc/httpd/conf.d/ipa.conf

> Gateway timeout - some operation takes more than 30s, will be removed in
> 4.4 - https://fedorahosted.org/freeipa/ticket/5833. But still it won't
> make the operation quicker.
> 
> >   Also (related?) error during 'ipactl' invocations:
> > $ ipactl status
> > WARNING: yacc table file version is out of date
> 
> These were seen before, it is not known if it affect IPA functionality.
> 
> https://bugzilla.redhat.com/show_bug.cgi?id=1336913
> 

-- 
Tomasz Torcz                 "God, root, what's the difference?"
xmpp: zdzichubg at chrome.pl         "God is more forgiving."