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] ad...@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



--
Manage your subscription for the Freeipa-users mailing list:
https://www.redhat.com/mailman/listinfo/freeipa-users
Go to http://freeipa.org for more info on the project

Reply via email to