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

Sun Jun 19 03:02:23 UTC 2016

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

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.

rob

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