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?


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: zdzich...@chrome.pl         "God is more forgiving."

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