display_status wrappers go cyclic

[tiran]

What went wrong?

GSSAPI failed with RuntimeError: maximum recursion depth exceeded in cmp while reporting an error from gssapi.raw.ext_cred_store.acquire_cred_from

[Wed Feb 15 12:35:46.414055 2017] mod_wsgi (pid=2647): Exception occurred processing WSGI script '/usr/share/ipa/wsgi.py'.
[Wed Feb 15 12:35:46.414087 2017] Traceback (most recent call last):
[Wed Feb 15 12:35:46.414099 2017]   File "/usr/share/ipa/wsgi.py", line 51, in application
[Wed Feb 15 12:35:46.414144 2017]     return api.Backend.wsgi_dispatch(environ, start_response)
[Wed Feb 15 12:35:46.414150 2017]   File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 263, in __call__
[Wed Feb 15 12:35:46.414317 2017]     return self.route(environ, start_response)
[Wed Feb 15 12:35:46.414326 2017]   File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 275, in route
[Wed Feb 15 12:35:46.414337 2017]     return app(environ, start_response)
[Wed Feb 15 12:35:46.414340 2017]   File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 465, in __call__
[Wed Feb 15 12:35:46.414346 2017]     response = super(jsonserver, self).__call__(environ, start_response)
[Wed Feb 15 12:35:46.414349 2017]   File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 647, in __call__
[Wed Feb 15 12:35:46.414354 2017]     self.create_context(ccache=user_ccache)
[Wed Feb 15 12:35:46.414358 2017]   File "/usr/lib/python2.7/site-packages/ipalib/backend.py", line 125, in create_context
[Wed Feb 15 12:35:46.414400 2017]     time_limit=None)
[Wed Feb 15 12:35:46.414405 2017]   File "/usr/lib/python2.7/site-packages/ipalib/backend.py", line 66, in connect
[Wed Feb 15 12:35:46.414413 2017]     conn = self.create_connection(*args, **kw)
[Wed Feb 15 12:35:46.414418 2017]   File "/usr/lib/python2.7/site-packages/ipaserver/plugins/ldap2.py", line 205, in create_connection
[Wed Feb 15 12:35:46.414502 2017]     principal = krb_utils.get_principal(ccache_name=ccache)
[Wed Feb 15 12:35:46.414507 2017]   File "/usr/lib/python2.7/site-packages/ipalib/krb_utils.py", line 182, in get_principal
[Wed Feb 15 12:35:46.414544 2017]     creds = get_credentials(ccache_name=ccache_name)
[Wed Feb 15 12:35:46.414548 2017]   File "/usr/lib/python2.7/site-packages/ipalib/krb_utils.py", line 161, in get_credentials
[Wed Feb 15 12:35:46.414555 2017]     return gssapi.Credentials(usage='initiate', name=name, store=store)
[Wed Feb 15 12:35:46.414558 2017]   File "/usr/lib64/python2.7/site-packages/gssapi/creds.py", line 64, in __new__
[Wed Feb 15 12:35:46.414625 2017]     store=store)
[Wed Feb 15 12:35:46.414630 2017]   File "/usr/lib64/python2.7/site-packages/gssapi/creds.py", line 148, in acquire
[Wed Feb 15 12:35:46.414637 2017]     usage)
[Wed Feb 15 12:35:46.414640 2017]   File "gssapi/raw/ext_cred_store.pyx", line 182, in gssapi.raw.ext_cred_store.acquire_cred_from (gssapi/raw/ext_cred_store.c:1886)
[Wed Feb 15 12:35:46.414686 2017]   File "gssapi/raw/misc.pyx", line 216, in gssapi.raw.misc.GSSErrorRegistry.__call__ (gssapi/raw/misc.c:3057)
[Wed Feb 15 12:35:46.414716 2017]   File "gssapi/raw/misc.pyx", line 272, in gssapi.raw.misc.GSSError.__init__ (gssapi/raw/misc.c:3531)
[Wed Feb 15 12:35:46.414744 2017]   File "gssapi/raw/misc.pyx", line 325, in gssapi.raw.misc.GSSError.gen_message (gssapi/raw/misc.c:4484)
[Wed Feb 15 12:35:46.414772 2017]   File "gssapi/raw/misc.pyx", line 295, in gssapi.raw.misc.GSSError.get_all_statuses (gssapi/raw/misc.c:3819)
[Wed Feb 15 12:35:46.414799 2017]   File "gssapi/raw/misc.pyx", line 174, in gssapi.raw.misc._display_status (gssapi/raw/misc.c:1960)
[Wed Feb 15 12:35:46.414826 2017]   File "gssapi/raw/misc.pyx", line 216, in gssapi.raw.misc.GSSErrorRegistry.__call__ (gssapi/raw/misc.c:3057)
[Wed Feb 15 12:35:46.414853 2017]   File "gssapi/raw/misc.pyx", line 272, in gssapi.raw.misc.GSSError.__init__ (gssapi/raw/misc.c:3531)
[Wed Feb 15 12:35:46.414879 2017]   File "gssapi/raw/misc.pyx", line 325, in gssapi.raw.misc.GSSError.gen_message (gssapi/raw/misc.c:4484)
[Wed Feb 15 12:35:46.414906 2017]   File "gssapi/raw/misc.pyx", line 295, in gssapi.raw.misc.GSSError.get_all_statuses (gssapi/raw/misc.c:3819)
[Wed Feb 15 12:35:46.414933 2017]   File "gssapi/raw/misc.pyx", line 174, in gssapi.raw.misc._display_status (gssapi/raw/misc.c:1960)
[Wed Feb 15 12:35:46.414960 2017]   File "gssapi/raw/misc.pyx", line 216, in gssapi.raw.misc.GSSErrorRegistry.__call__ (gssapi/raw/misc.c:3057)
[Wed Feb 15 12:35:46.414987 2017]   File "gssapi/raw/misc.pyx", line 272, in gssapi.raw.misc.GSSError.__init__ (gssapi/raw/misc.c:3531)
[Wed Feb 15 12:35:46.415013 2017]   File "gssapi/raw/misc.pyx", line 325, in gssapi.raw.misc.GSSError.gen_message (gssapi/raw/misc.c:4484)
[Wed Feb 15 12:35:46.415047 2017]   File "gssapi/raw/misc.pyx", line 295, in gssapi.raw.misc.GSSError.get_all_statuses (gssapi/raw/misc.c:3819)
[Wed Feb 15 12:35:46.415075 2017]   File "gssapi/raw/misc.pyx", line 174, in gssapi.raw.misc._display_status (gssapi/raw/misc.c:1960)
...
[Wed Feb 15 12:35:46.429463 2017] RuntimeError: maximum recursion depth exceeded in cmp

How do we reproduce?

The error occurred with latest FreeIPA master with privilege separation patch merged freeipa/freeipa#314.

Component versions (python-gssapi, Kerberos, OS / distro, etc.)

python-gssapi-1.2.0-2.fc25.x86_64
freeipa-server-4.4.90.dev201702151002+git88f8c15-0.fc25.x86_64
krb5-libs-1.14.4-4.fc25.x86_64

[tiran]

krb5kdc.log:

Feb 15 12:35:46 master.ipa.example krb5kdc[2611](info): TGS_REQ (6 etypes {18 17 16 23 25 26}) 192.168.121.1: ISSUE: authtime 1487162132, etypes {rep=18 tkt=18 ses=18}, admin@IPA.EXAMPLE for HTTP/master.ipa.example@IPA.EXAMPLE
Feb 15 12:35:46 master.ipa.example krb5kdc[2611](info): closing down fd 11
Feb 15 12:35:46 master.ipa.example krb5kdc[2611](info): AS_REQ (6 etypes {18 17 16 23 25 26}) 192.168.121.252: NEEDED_PREAUTH: HTTP/master.ipa.example@IPA.EXAMPLE for krbtgt/IPA.EXAMPLE@IPA.EXAMPLE, Additional pre-authentication required
Feb 15 12:35:46 master.ipa.example krb5kdc[2611](info): closing down fd 11
Feb 15 12:35:46 master.ipa.example krb5kdc[2611](info): AS_REQ (6 etypes {18 17 16 23 25 26}) 192.168.121.252: ISSUE: authtime 1487162146, etypes {rep=18 tkt=18 ses=18}, HTTP/master.ipa.example@IPA.EXAMPLE for krbtgt/IPA.EXAMPLE@IPA.EXAMPLE
Feb 15 12:35:46 master.ipa.example krb5kdc[2611](info): closing down fd 11
Feb 15 12:35:46 master.ipa.example krb5kdc[2611](info): AS_REQ (6 etypes {18 17 16 23 25 26}) 192.168.121.252: NEEDED_PREAUTH: HTTP/master.ipa.example@IPA.EXAMPLE for krbtgt/IPA.EXAMPLE@IPA.EXAMPLE, Additional pre-authentication required
Feb 15 12:35:46 master.ipa.example krb5kdc[2611](info): closing down fd 11
Feb 15 12:35:46 master.ipa.example krb5kdc[2611](info): AS_REQ (6 etypes {18 17 16 23 25 26}) 192.168.121.252: ISSUE: authtime 1487162146, etypes {rep=18 tkt=18 ses=18}, HTTP/master.ipa.example@IPA.EXAMPLE for krbtgt/IPA.EXAMPLE@IPA.EXAMPLE
Feb 15 12:35:46 master.ipa.example krb5kdc[2611](info): closing down fd 11

[frozencemetery]

Hah! Well, RFC permits this, even if we thought it'd never happen in practice.

If you can easily check this, what's the value of maj_stat returned by gss_display_status() (in _display_status())?

[DirectXMan12]

I'd love to see what the major and minor statuses are that are causing this to go cyclic -- maybe BAD_MECH or INACCESIBLE_WRITE (although I wouldn't expect us to have the later).

[frozencemetery]

Well, I wouldn't expect us to have the former, either, since we pass in GSS_C_NO_OID...

[tiran]

The issues occurred again, https://pagure.io/freeipa/issue/6796

It could have been BAD_MECH. The most recent version enable SPNEGO and I saw gss_acquire_cred[_from]() failed to get server creds: [Unspecified GSS failure. Minor code may provide more information ( SPNEGO cannot find mechanisms to negotiate)] in Apache error log a couple of times.

[tiran]

By the way I love the fact that _display_status even has ac comment that points out a potential recursion issue: # NB(directxman12): this is highly unlikely to cause a recursive loop :)