Bug 1438390

Summary: python-gssapi display_status can exceed recursion depth
Product: Red Hat Enterprise Linux 7 Reporter: Petr Vobornik <pvoborni>
Component: python-gssapiAssignee: Robbie Harwood <rharwood>
Status: CLOSED ERRATA QA Contact: Nikhil Dehadrai <ndehadra>
Severity: high Docs Contact:
Priority: high    
Version: 7.4CC: ipa-maint, ipa-qe, ksiddiqu, mbabinsk, mkosek, nsoman, pvoborni, rcritten, spoore, tscherf
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: python-gssapi-1.2.0-3.el7 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: 1438016 Environment:
Last Closed: 2017-08-01 12:50:53 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1438016    

Description Petr Vobornik 2017-04-03 10:29:25 UTC
+++ 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.

Comment 1 Petr Vobornik 2017-04-03 10:31:23 UTC
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.

Comment 5 Scott Poore 2017-04-10 18:36:58 UTC
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.

Comment 7 Scott Poore 2017-04-11 18:54:51 UTC
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

Comment 8 Scott Poore 2017-04-11 20:24:59 UTC
FYI, my last issue was determined to be a different bug and moved to bug #1441376

Comment 10 Nikhil Dehadrai 2017-05-17 11:58:49 UTC
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: 
[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
  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: 
[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
  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
  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
[root@dhcp213-39 ~]# kinit admin
Password for admin: 
[root@dhcp213-39 ~]# klist
Ticket cache: KEYRING:persistent:0:0
Default principal: admin

Valid starting       Expires              Service principal
05/17/2017 17:24:00  05/18/2017 17:23:53  krbtgt/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.

Comment 11 Nikhil Dehadrai 2017-05-17 14:49:12 UTC
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".

Comment 12 Robbie Harwood 2017-05-17 15:46:56 UTC
(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!

Comment 13 errata-xmlrpc 2017-08-01 12:50:53 UTC
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