Red Hat Bugzilla – Bug 1438390
python-gssapi display_status can exceed recursion depth
Last modified: 2017-08-01 08:50:53 EDT
+++ This bug was initially created as a clone of Bug #1438016 +++ Description of problem: After upgrading the IPA server from IPA version 4.4 (rhel7.3) to 4.5 (rhel7.4), I'm seeing gssapi errors and internal server error's when running commands. After upgrade: [root@auto-hv-02-guest10 /]# ipa user-find ipa: ERROR: cannot connect to 'https://auto-hv-02-guest10.isc03081.test/ipa/json': Internal Server Error In /var/log/httpd/error_log I see a backtrace and a lot of these: File "misc.pyx", line 174, in gssapi.raw.misc._display_status (gssapi/raw/misc.c:1797) File "misc.pyx", line 216, in gssapi.raw.misc.GSSErrorRegistry.__call__ (gssapi/raw/misc.c:2719) File "misc.pyx", line 272, in gssapi.raw.misc.GSSError.__init__ (gssapi/raw/misc.c:3143) File "misc.pyx", line 324, in gssapi.raw.misc.GSSError.gen_message (gssapi/raw/misc.c:3862) File "misc.pyx", line 291, in gssapi.raw.misc.GSSError.get_all_statuses (gssapi/raw/misc.c:3298) RuntimeError: maximum recursion depth exceeded while calling a Python object Version-Release number of selected component (if applicable): ipa-server-4.5.0-4.el7.x86_64 gssproxy-0.7.0-3.el7.x86_64 mod_wsgi-3.4-12.el7_0.x86_64 How reproducible: Unknown. Steps to Reproduce: 1. on rhel7.3 install 4.4 ipa server 2. upgrade to 4.5 version 3. ipa user-find Actual results: internal server error Expected results: find users and not errors. Additional info: /var/log/httpd/error_log entries: [Fri Mar 31 11:41:18.567914 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 274, in route [Fri Mar 31 11:41:18.567933 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] return app(environ, start_response) [Fri Mar 31 11:41:18.567941 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 468, in __call__ [Fri Mar 31 11:41:18.567965 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] response = super(jsonserver, self).__call__(environ, start_response) [Fri Mar 31 11:41:18.567974 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 648, in __call__ [Fri Mar 31 11:41:18.567988 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] self.create_context(ccache=user_ccache) [Fri Mar 31 11:41:18.568007 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] File "/usr/lib/python2.7/site-packages/ipalib/backend.py", line 125, in create_context [Fri Mar 31 11:41:18.568076 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] time_limit=None) [Fri Mar 31 11:41:18.568088 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] File "/usr/lib/python2.7/site-packages/ipalib/backend.py", line 66, in connect [Fri Mar 31 11:41:18.568104 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] conn = self.create_connection(*args, **kw) [Fri Mar 31 11:41:18.568113 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] File "/usr/lib/python2.7/site-packages/ipaserver/plugins/ldap2.py", line 205, in create_connection [Fri Mar 31 11:41:18.568248 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] principal = krb_utils.get_principal(ccache_name=ccache) [Fri Mar 31 11:41:18.568266 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] File "/usr/lib/python2.7/site-packages/ipalib/krb_utils.py", line 168, in get_principal [Fri Mar 31 11:41:18.568334 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] creds = get_credentials(ccache_name=ccache_name) [Fri Mar 31 11:41:18.568361 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] File "/usr/lib/python2.7/site-packages/ipalib/krb_utils.py", line 147, in get_credentials [Fri Mar 31 11:41:18.568379 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] return gssapi.Credentials(usage='initiate', name=name, store=store) [Fri Mar 31 11:41:18.568395 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] File "/usr/lib64/python2.7/site-packages/gssapi/creds.py", line 64, in __new__ [Fri Mar 31 11:41:18.568519 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] store=store) [Fri Mar 31 11:41:18.568530 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] File "/usr/lib64/python2.7/site-packages/gssapi/creds.py", line 148, in acquire [Fri Mar 31 11:41:18.568547 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] usage) [Fri Mar 31 11:41:18.568554 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] File "ext_cred_store.pyx", line 182, in gssapi.raw.ext_cred_store.acquire_cred_from (gssapi/raw/ext_cred_store.c:1726) [Fri Mar 31 11:41:18.568657 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] File "misc.pyx", line 216, in gssapi.raw.misc.GSSErrorRegistry.__call__ (gssapi/raw/misc.c:2719) [Fri Mar 31 11:41:18.568737 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] File "misc.pyx", line 272, in gssapi.raw.misc.GSSError.__init__ (gssapi/raw/misc.c:3143) [Fri Mar 31 11:41:18.568814 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] File "misc.pyx", line 325, in gssapi.raw.misc.GSSError.gen_message (gssapi/raw/misc.c:3890) [Fri Mar 31 11:41:18.568891 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] File "misc.pyx", line 295, in gssapi.raw.misc.GSSError.get_all_statuses (gssapi/raw/misc.c:3360) [Fri Mar 31 11:41:18.568979 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] File "misc.pyx", line 174, in gssapi.raw.misc._display_status (gssapi/raw/misc.c:1797) [Fri Mar 31 11:41:18.603558 2017] [:error] [pid 25246] [remote ipa_master_ip_address:84] RuntimeError: maximum recursion depth exceeded while calling a Python object --- Additional comment from Martin Babinsky on 2017-04-03 09:45:34 CEST --- Looks like https://pagure.io/freeipa/issue/6796 to me.
According to triage of IPA bug 6796, the issue is in python-gssapi. Should be PR https://github.com/pythongssapi/python-gssapi/pull/112 This needs to be fixed in RHEL 7.4.
Created attachment 1270552 [details] var log from fresh install with bug when 3g memory FYI, I think I'm seeing this bug also on a fresh install when the host has only 3g of memory. It should be noted that I did the initial install with the VM having 4g of memory. When I did that, I didn't see the error. When I lowered memory down to 3g, I see the error. Attached is /var/log from the test host.
A little more info on what I think I might have seen in comment #5 above. I think I might have been doing something slightly different between my 3g and 4g setup. And considering that Nikhil saw no issues when he ran some upgrade tests on 2g machines, I think that helps indicate the problem was a difference in my tests. I am able to reproduce the problem still and memory is not involved. I think it's an selinux issue. The reproducer is: 1. setenforce 0 2. ipa-server-install [NOTE: steps 3 thru 7 emulate the reboot I was doing] 3. ipactl stop 4. systemctl stop gssproxy 5 setenforce 1 6. systemctl start gssproxy 7. ipactl start [END REBOOT EMULATION] 8. kinit admin 9. ipa user-find 10. setenforce 0 11. ipactl stop; ipactl start 12. ipa user-find [WORKAROUND] 13. systemctl stop gssproxy 14. ipactl stop 15. systemctl start gssproxy 16. ipactl start 17. ipa user-find Results: The user-finds at 9 and 12 fail. The user-find at 17 passes. And I can see 2 AVC messages when gssproxy starts when selinux is in enforcing: [root@rhel7-2 ~]# ausearch -m avc -ts 13:45 ---- time->Tue Apr 11 13:45:04 2017 type=SYSCALL msg=audit(1491936304.374:189): arch=c000003e syscall=2 success=no exit=-13 a0=555b3fc38640 a1=0 a2=1b6 a3=24 items=0 ppid=1 pid=2636 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="gssproxy" exe="/usr/sbin/gssproxy" subj=system_u:system_r:gssproxy_t:s0 key=(null) type=AVC msg=audit(1491936304.374:189): avc: denied { dac_read_search } for pid=2636 comm="gssproxy" capability=2 scontext=system_u:system_r:gssproxy_t:s0 tcontext=system_u:system_r:gssproxy_t:s0 tclass=capability type=AVC msg=audit(1491936304.374:189): avc: denied { dac_override } for pid=2636 comm="gssproxy" capability=1 scontext=system_u:system_r:gssproxy_t:s0 tcontext=system_u:system_r:gssproxy_t:s0 tclass=capability ---- time->Tue Apr 11 13:45:04 2017 type=SYSCALL msg=audit(1491936304.375:190): arch=c000003e syscall=2 success=no exit=-13 a0=555b3fc48a10 a1=0 a2=1b6 a3=24 items=0 ppid=1 pid=2636 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="gssproxy" exe="/usr/sbin/gssproxy" subj=system_u:system_r:gssproxy_t:s0 key=(null) type=AVC msg=audit(1491936304.375:190): avc: denied { dac_read_search } for pid=2636 comm="gssproxy" capability=2 scontext=system_u:system_r:gssproxy_t:s0 tcontext=system_u:system_r:gssproxy_t:s0 tclass=capability type=AVC msg=audit(1491936304.375:190): avc: denied { dac_override } for pid=2636 comm="gssproxy" capability=1 scontext=system_u:system_r:gssproxy_t:s0 tcontext=system_u:system_r:gssproxy_t:s0 tclass=capability But, I can only see one AVC when selinux is in permissive: [root@rhel7-2 ~]# ausearch -m avc -ts 13:47:45 ---- time->Tue Apr 11 13:47:48 2017 type=SYSCALL msg=audit(1491936468.506:238): arch=c000003e syscall=2 success=yes exit=3 a0=55786efcb640 a1=0 a2=1b6 a3=24 items=0 ppid=1 pid=3950 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="gssproxy" exe="/usr/sbin/gssproxy" subj=system_u:system_r:gssproxy_t:s0 key=(null) type=AVC msg=audit(1491936468.506:238): avc: denied { dac_override } for pid=3950 comm="gssproxy" capability=1 scontext=system_u:system_r:gssproxy_t:s0 tcontext=system_u:system_r:gssproxy_t:s0 tclass=capability
FYI, my last issue was determined to be a different bug and moved to bug #1441376
Based on the steps Description and Comment#7, Tested the bug with following observations: (Are these sufficient to verify the bug) The following is console output from upgrade task rhel 7.3.z > 7.4: [root@dhcp213-39 ~]# rpm -q ipa-server ipa-server-4.5.0-11.el7.x86_64 [root@dhcp213-39 ~]# tail -1 /var/log/ipaupgrade.log 2017-05-17T11:44:49Z INFO The ipa-server-upgrade command was successful [root@dhcp213-39 ~]# ipa user-find ipa: ERROR: did not receive Kerberos credentials [root@dhcp213-39 ~]# kinit admin Password for admin@TESTRELM.TEST: [root@dhcp213-39 ~]# ipa user-find -------------- 1 user matched -------------- User login: admin Last name: Administrator Home directory: /home/admin Login shell: /bin/bash Principal alias: admin@TESTRELM.TEST UID: 207800000 GID: 207800000 Account disabled: False ---------------------------- Number of entries returned 1 ---------------------------- [root@dhcp213-39 ~]# cat /var/log/httpd/error_log | grep -i "maximum recursion depth" [root@dhcp213-39 ~]# [root@dhcp213-39 ~]# cat /var/log/httpd/error_log | grep -i "recursion" [root@dhcp213-39 ~]# [root@dhcp213-39 ~]# free -h total used free shared buff/cache available Mem: 2.8G 1.1G 1.0G 8.5M 712M 1.5G Swap: 3.9G 0B 3.9G [root@dhcp213-39 ~]# ipactl stop Stopping ipa-dnskeysyncd Service Stopping ipa-otpd Service Stopping pki-tomcatd Service Stopping ntpd Service Stopping ipa-custodia Service Stopping httpd Service Stopping named Service Stopping kadmin Service Stopping krb5kdc Service Stopping Directory Service ipa: INFO: The ipactl command was successful [root@dhcp213-39 ~]# systemctl stop gssproxy [root@dhcp213-39 ~]# setenforce 1 [root@dhcp213-39 ~]# systemctl start gssproxy [root@dhcp213-39 ~]# ipactl start Starting Directory Service Starting krb5kdc Service Starting kadmin Service Starting named Service Starting httpd Service Starting ipa-custodia Service Starting ntpd Service Starting pki-tomcatd Service Starting ipa-otpd Service Starting ipa-dnskeysyncd Service ipa: INFO: The ipactl command was successful [root@dhcp213-39 ~]# kinit admin Password for admin@TESTRELM.TEST: [root@dhcp213-39 ~]# ipa user-find -------------- 1 user matched -------------- User login: admin Last name: Administrator Home directory: /home/admin Login shell: /bin/bash Principal alias: admin@TESTRELM.TEST UID: 207800000 GID: 207800000 Account disabled: False ---------------------------- Number of entries returned 1 ---------------------------- [root@dhcp213-39 ~]# setenforce 0 [root@dhcp213-39 ~]# ipactl stop; ipactl start Stopping ipa-dnskeysyncd Service Stopping ipa-otpd Service Stopping pki-tomcatd Service Stopping ntpd Service Stopping ipa-custodia Service Stopping httpd Service Stopping named Service Stopping kadmin Service Stopping krb5kdc Service Stopping Directory Service ipa: INFO: The ipactl command was successful Starting Directory Service Starting krb5kdc Service Starting kadmin Service Starting named Service Starting httpd Service Starting ipa-custodia Service Starting ntpd Service Starting pki-tomcatd Service Starting ipa-otpd Service Starting ipa-dnskeysyncd Service ipa: INFO: The ipactl command was successful [root@dhcp213-39 ~]# ipa user-find -------------- 1 user matched -------------- User login: admin Last name: Administrator Home directory: /home/admin Login shell: /bin/bash Principal alias: admin@TESTRELM.TEST UID: 207800000 GID: 207800000 Account disabled: False ---------------------------- Number of entries returned 1 ---------------------------- [root@dhcp213-39 ~]# kinit -n [root@dhcp213-39 ~]# -n -bash: -n: command not found [root@dhcp213-39 ~]# klist Ticket cache: KEYRING:persistent:0:krb_ccache_jjdGhJm Default principal: WELLKNOWN/ANONYMOUS@WELLKNOWN:ANONYMOUS Valid starting Expires Service principal 05/17/2017 17:23:29 05/18/2017 17:23:29 krbtgt/TESTRELM.TEST@TESTRELM.TEST [root@dhcp213-39 ~]# kinit admin Password for admin@TESTRELM.TEST: [root@dhcp213-39 ~]# klist Ticket cache: KEYRING:persistent:0:0 Default principal: admin@TESTRELM.TEST Valid starting Expires Service principal 05/17/2017 17:24:00 05/18/2017 17:23:53 krbtgt/TESTRELM.TEST@TESTRELM.TEST [root@dhcp213-39 ~]# kinit -n [root@dhcp213-39 ~]# [root@dhcp213-39 ~]# cat /var/log/httpd/error_log | grep -i "maximum recursion depth" [root@dhcp213-39 ~]# cat /var/log/httpd/error_log | grep -i "recursion" [root@dhcp213-39 ~]# 2) Similar behavior noticed on systems with 2GB and 4GB memory.
Addition observations for above comment#10: [root@dhcp213-39 ~]# ausearch -m AVC <no matches> [root@dhcp213-39 ~]# rpm -qa gss* gssproxy-0.7.0-3.el7.x86_64 [root@dhcp213-39 ~]# ausearch -m avc <no matches> [root@dhcp213-39 ~]# ausearch -m avc -ts today <no matches> [root@dhcp213-39 ~]# rpm -qa python-gssapi python-gssapi-1.2.0-3.el7.x86_64 [root@dhcp213-39 ~]# Thus based on observations in above Comment#10, marking the status of this bug to "VERIFIED".
(In reply to Nikhil Dehadrai from comment #10) > Based on the steps Description and Comment#7, Tested the bug with following > observations: (Are these sufficient to verify the bug) These should be sufficient. Thanks Nikhil!
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHBA-2017:2269