freeipa

Clone
Source Code
GIT

#6775 [ipalib/rpc.py] - "maximum recursion depth exceeded" with ipa vault commands
Closed: fixed 7 years ago Opened 7 years ago by mreznik.

Closed: fixed
Reopen Issue

When trying to troubleshoot failing "test_vault_plugin.py" tests, which are passing fine with fresh ipa-server installation but failing after uninstall and install again I am getting random issue with "maximum recursion depth exceeded" with ipa vault commands. Please see:

    [root@system01 ~]# ipa vault-add another_try --type standard
    ipa: ERROR: non-public: RuntimeError: maximum recursion depth exceeded
    Traceback (most recent call last):
      File "/usr/lib/python2.7/site-packages/ipalib/backend.py", line 139, in execute
        result = self.Command[_name](*args, **options)
      File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 447, in __call__
        return self.__do_call(*args, **options)
      File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 475, in __do_call
        ret = self.run(*args, **options)
      File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 1199, in run
        return self.forward(*args, **options)
      File "/usr/lib/python2.7/site-packages/ipaclient/plugins/vault.py", line 350, in forward
        response = self.api.Command.vault_add_internal(*args, **options)
      File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 447, in __call__
        return self.__do_call(*args, **options)
      File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 475, in __do_call
        ret = self.run(*args, **options)
      File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 798, in run
        return self.forward(*args, **options)
      File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 821, in forward
        *args, **kw)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
        return self.forward(name, *args, **kw)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
        return self.forward(name, *args, **kw)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
        return self.forward(name, *args, **kw)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
        return self.forward(name, *args, **kw)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
        return self.forward(name, *args, **kw)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
        return self.forward(name, *args, **kw)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
        return self.forward(name, *args, **kw)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
        return self.forward(name, *args, **kw)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
        return self.forward(name, *args, **kw)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
        return self.forward(name, *args, **kw)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
        return self.forward(name, *args, **kw)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
        return self.forward(name, *args, **kw)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
        return self.forward(name, *args, **kw)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
        return self.forward(name, *args, **kw)
    ...
    ...
    ...
    ...
    ...
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
        return self.forward(name, *args, **kw)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
        return self.forward(name, *args, **kw)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
        return self.forward(name, *args, **kw)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1047, in forward
        return self._call_command(command, params)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1028, in _call_command
        return command(*params)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1169, in _call
        return self.__request(name, args)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1136, in __request
        verbose=self.__verbose >= 3,
      File "/usr/lib64/python2.7/xmlrpclib.py", line 1283, in request
        return self.single_request(host, handler, request_body, verbose)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 652, in single_request
        h = SSLTransport.make_connection(self, host)
      File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 542, in make_connection
        conn.connect()
      File "/usr/lib64/python2.7/httplib.py", line 1263, in connect
        server_hostname=server_hostname)
      File "/usr/lib64/python2.7/ssl.py", line 363, in wrap_socket
        _context=self)
      File "/usr/lib64/python2.7/ssl.py", line 605, in __init__
        server_hostname, ssl_sock=self)
      File "/usr/lib64/python2.7/encodings/idna.py", line 164, in encode
        result.append(ToASCII(label))
      File "/usr/lib64/python2.7/encodings/idna.py", line 65, in ToASCII
        label = label.encode("ascii")
    RuntimeError: maximum recursion depth exceeded
    ipa: ERROR: an internal error has occurred

When trying to retrieve the vault:

[root@system01 ~]# ipa vault-add http_password --type standard
---------------------------
Added vault "http_password"
---------------------------
  Vault name: http_password
  Type: standard
  Owner users: admin
  Vault user: admin
[root@system01 ~]# ipa vault-archive http_password --in password.txt
----------------------------------------
Archived data into vault "http_password"
----------------------------------------
[root@system01 ~]# rm password.txt
rm: remove regular file 'password.txt'? y
[root@system01 ~]# ipa vault-retrieve http_password
ipa: ERROR: No archived data.
[root@system01 ~]#

Thanks for taking a look!

freeipa-server-4.5.90.dev201703161100+git9ac62be-0.fc25.x86_64
gssproxy-0.7.0-2simo3.fc25.x86_64

Attaching also http error_log. Let me know if any other details are needed.

httpd-error_log

Got another occurrence while testing downstream:

[root@server02 ~]# ipa service-show
Principal name: vpn    <= I am aware that the principal name is wrong but still...
ipa: ERROR: non-public: RuntimeError: maximum recursion depth exceeded
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/ipalib/backend.py", line 139, in execute
    result = self.Command[_name](*args, **options)
  File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 447, in __call__
    return self.__do_call(*args, **options)
  File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 475, in __do_call
    ret = self.run(*args, **options)
  File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 798, in run
    return self.forward(*args, **options)
  File "/usr/lib/python2.7/site-packages/ipaclient/plugins/service.py", line 51, in forward
    return super(service_show, self).forward(*keys, **options)
  File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 821, in forward
    *args, **kw)
  File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
    return self.forward(name, *args, **kw)
  File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
    return self.forward(name, *args, **kw)
  File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
    return self.forward(name, *args, **kw)
...
...
...
  File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1080, in forward
    return self.forward(name, *args, **kw)
  File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1047, in forward
    return self._call_command(command, params)
  File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1028, in _call_command
    return command(*params)
  File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1169, in _call
    return self.__request(name, args)
  File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 1136, in __request
    verbose=self.__verbose >= 3,
  File "/usr/lib64/python2.7/xmlrpclib.py", line 1273, in request
    return self.single_request(host, handler, request_body, verbose)
  File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 652, in single_request
    h = SSLTransport.make_connection(self, host)
  File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 542, in make_connection
    conn.connect()
  File "/usr/lib64/python2.7/httplib.py", line 1227, in connect
    HTTPConnection.connect(self)
  File "/usr/lib64/python2.7/httplib.py", line 807, in connect
    self.timeout, self.source_address)
  File "/usr/lib64/python2.7/socket.py", line 553, in create_connection
    for res in getaddrinfo(host, port, 0, SOCK_STREAM):
  File "/usr/lib64/python2.7/encodings/idna.py", line 164, in encode
    result.append(ToASCII(label))
  File "/usr/lib64/python2.7/encodings/idna.py", line 65, in ToASCII
    label = label.encode("ascii")
RuntimeError: maximum recursion depth exceeded
ipa: ERROR: an internal error has occurred
[root@server02 ~]#

ipa-server-4.5.90-201703162305.el7.x86_64
gssproxy-0.7.0-2.el7.x86_64
Edited 7 years ago by mreznik

I'm not able to reproduce this issue with current master (freeipa-server-4.5.90.dev201703211425+git4ee7e4e-0.fc25.x86_64).

Could you provide some steps to reproduce or perhaps a machine that is affected by this issue?

The issue is quite random, now I got it when running "xmlrpc" test suite:

ProtocolError: <ProtocolError for server01.test/ipa/session/json: 401 Unauthorized>
[ipa.ipaclient.plugins.rpcclient.rpcclient] found session_cookie in persistent storage for principal 'admin@SERVER01.TEST', cookie: 'ipa_session=MagBearerToken=bGY8bCbDzTmX%2fiBoofVOF5l4YE9boJMIJXLdxa7GhdKakOnDBvoYwtYQDmWtgWqpCEqmU%2bPuVbg4CM6Bqz%2fS3xXFlu9qT6nb7aJSvxMA26y0oHDsGIcByk4S14KGVl%2bArp5ac9Gv9siI%2bYgR051lp5nFDRWD4OH58SakU%2b22hC6nWpVQ0igykok2QWFwWL5wo%2fb%2bJ4Skj3FEbGkHn3BwohRFCU4W7l0z3CZQ5r%2bXB7iQ%2fuQkeBbRz01TulBU0V%2b5dGMQvrks1tnDiM5tOxNXDOcXeL9ObIkr4SEE0TWsMPTliBGpk7FsT%2fcBtw3X5LBs&expiry=1490167931476949; Domain=server01.test; Path=/ipa; Expires=Wed, 22 Mar 2017 07:32:23 GMT; Secure; HttpOnly'
[ipa.ipaclient.plugins.rpcclient.rpcclient] setting session_cookie into context 'ipa_session=MagBearerToken=bGY8bCbDzTmX%2fiBoofVOF5l4YE9boJMIJXLdxa7GhdKakOnDBvoYwtYQDmWtgWqpCEqmU%2bPuVbg4CM6Bqz%2fS3xXFlu9qT6nb7aJSvxMA26y0oHDsGIcByk4S14KGVl%2bArp5ac9Gv9siI%2bYgR051lp5nFDRWD4OH58SakU%2b22hC6nWpVQ0igykok2QWFwWL5wo%2fb%2bJ4Skj3FEbGkHn3BwohRFCU4W7l0z3CZQ5r%2bXB7iQ%2fuQkeBbRz01TulBU0V%2b5dGMQvrks1tnDiM5tOxNXDOcXeL9ObIkr4SEE0TWsMPTliBGpk7FsT%2fcBtw3X5LBs&expiry=1490167931476949;'
[ipa.ipaclient.plugins.rpcclient.rpcclient] trying https://server01.test/ipa/session/json
[ipa.ipaclient.plugins.rpcclient.rpcclient] Forwarding 'dnszone_disable/1' to json server 'https://server01.test/ipa/session/json'
[ipa] New HTTP connection (server01.test)
[ipa] HTTP connection destroyed (server01.test)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 690, in single_request
    response.msg)
ProtocolError: <unprintable ProtocolError object>
[ipa.ipaclient.plugins.rpcclient.rpcclient] found session_cookie in persistent storage for principal 'admin@SERVER01.TEST', cookie: 'ipa_session=MagBearerToken=bGY8bCbDzTmX%2fiBoofVOF5l4YE9boJMIJXLdxa7GhdKakOnDBvoYwtYQDmWtgWqpCEqmU%2bPuVbg4CM6Bqz%2fS3xXFlu9qT6nb7aJSvxMA26y0oHDsGIcByk4S14KGVl%2bArp5ac9Gv9siI%2bYgR051lp5nFDRWD4OH58SakU%2b22hC6nWpVQ0igykok2QWFwWL5wo%2fb%2bJ4Skj3FEbGkHn3BwohRFCU4W7l0z3CZQ5r%2bXB7iQ%2fuQkeBbRz01TulBU0V%2b5dGMQvrks1tnDiM5tOxNXDOcXeL9ObIkr4SEE0TWsMPTliBGpk7FsT%2fcBtw3X5LBs&expiry=1490167931476949; Domain=server01.test; Path=/ipa; Expires=Wed, 22 Mar 2017 07:32:23 GMT; Secure; HttpOnly'
[ipa.ipaclient.plugins.rpcclient.rpcclient] setting session_cookie into context 'ipa_session=MagBearerToken=bGY8bCbDzTmX%2fiBoofVOF5l4YE9boJMIJXLdxa7GhdKakOnDBvoYwtYQDmWtgWqpCEqmU%2bPuVbg4CM6Bqz%2fS3xXFlu9qT6nb7aJSvxMA26y0oHDsGIcByk4S14KGVl%2bArp5ac9Gv9siI%2bYgR051lp5nFDRWD4OH58SakU%2b22hC6nWpVQ0igykok2QWFwWL5wo%2fb%2bJ4Skj3FEbGkHn3BwohRFCU4W7l0z3CZQ5r%2bXB7iQ%2fuQkeBbRz01TulBU0V%2b5dGMQvrks1tnDiM5tOxNXDOcXeL9ObIkr4SEE0TWsMPTliBGpk7FsT%2fcBtw3X5LBs&expiry=1490167931476949;'
[ipa.ipaclient.plugins.rpcclient.rpcclient] trying https://server01.test/ipa/session/json
[ipa.ipaclient.plugins.rpcclient.rpcclient] Forwarding 'dnszone_disable/1' to json server 'https://server01.test/ipa/session/json'
[ipa] HTTP connection destroyed (server01.test)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 661, in single_request
    h = SSLTransport.make_connection(self, host)
  File "/usr/lib/python2.7/site-packages/ipalib/rpc.py", line 551, in make_connection
    root_logger.debug("New HTTP connection (%s)", host)
  File "/usr/lib64/python2.7/logging/__init__.py", line 1155, in debug
    self._log(DEBUG, msg, args, **kwargs)
  File "/usr/lib64/python2.7/logging/__init__.py", line 1285, in _log
    record = self.makeRecord(self.name, level, fn, lno, msg, args, exc_info, func, extra)
  File "/usr/lib64/python2.7/logging/__init__.py", line 1259, in makeRecord
    rv = LogRecord(name, level, fn, lno, msg, args, exc_info, func)
  File "/usr/lib64/python2.7/logging/__init__.py", line 263, in __init__
    if (args and len(args) == 1 and isinstance(args[0], collections.Mapping)
  File "/usr/lib64/python2.7/abc.py", line 132, in __instancecheck__
    if subclass is not None and subclass in cls._abc_cache:
  File "/usr/lib64/python2.7/_weakrefset.py", line 72, in __contains__
    wr = ref(item)
RuntimeError: maximum recursion depth exceeded

freeipa-server-4.5.90.dev201703220536+git3de0970-0.fc25.x86_64

Like Christian mentioned in #6793 acquiring a new TGT solves the issue, at least in case of working with vaults.

We store session cookie now in the Kerberos ccache. When cookie is incorrect, we need to drop it and start authentication from scratch using existing Kerberos credentials from the ccache. It looks like some part of the code is improperly detecting this condition and does not break out of use of existing cookie.

The problem is obviously fixed when new TGT is acquired because you are clearing out all data in the ccache, including the cookie we stored there.

Please don't open new bugs for the same issue. Either #6793 or this bug should be used to track the issue, not two.

Besides the cookie / ccache handling issue, there are more problems related to the bug:

  • Recursion bug in python-gssapi's error reporting, #6796 and https://github.com/pythongssapi/python-gssapi/issues/111
  • The forward function of ipalib.rpc should have a max retry. At the moment it retries 401 over and over again until it hits a recursion limit (this ticket and #6793)
  • /var/run/ipa/ccache should be cleaned up, either when Apache restarts or at least during system reboot. As a user I expect that a reboot gives me a clean slate.
  • File handling in /var/run/ipa/ccache is subject to concurrency issues, #6794

This started happening to me after mod_lookup_identity was installed:
http://termbin.com/1yjk
Edited 7 years ago by stlaz

Noticed that while the issue is ongoing "gssproxy" is consuming lot of memory and there are huge leaks (valgrind output attached):

gssproxy-0.7.0-2.fc25.x86_64

==11860== LEAK SUMMARY:
==11860==    definitely lost: 656,695,678 bytes in 1,589,253 blocks
==11860==    indirectly lost: 55,608,591 bytes in 2,253,051 blocks
==11860==      possibly lost: 789,524 bytes in 12 blocks
==11860==    still reachable: 10,122 bytes in 33 blocks
==11860==         suppressed: 0 bytes in 0 blocks
==11860== 
==11860== For counts of detected and suppressed errors, rerun with: -v
==11860== ERROR SUMMARY: 27 errors from 27 contexts (suppressed: 0 from 0)

I understand that this is most probably a consequence rather then the cause but still would like to report it...
valgrind

Any chance re-do valgrind analysis with debuginfo installed?

Here you are:

gssproxy-debuginfo-0.7.0-2.fc25.x86_64
gssproxy-0.7.0-2.fc25.x86_64

==10030== 
==10030== 112,017,408 bytes in 355 blocks are definitely lost in loss record 748 of 748
==10030==    at 0x4C2FC47: realloc (vg_replace_malloc.c:785)
==10030==    by 0x6E12163: ??? (in /usr/lib64/libkrb5support.so.0.1)
==10030==    by 0x6E122D8: k5_buf_add_len (in /usr/lib64/libkrb5support.so.0.1)
==10030==    by 0x65EDD98: gss_export_cred (in /usr/lib64/libgssapi_krb5.so.2.2)
==10030==    by 0x11930E: gp_export_gssx_cred (gp_export.c:362)
==10030==    by 0x112ED3: gp_export_sync_creds (gp_creds.c:1136)
==10030==    by 0x11C8C5: gp_init_sec_context (gp_rpc_init_sec_context.c:173)
==10030==    by 0x1178A2: gp_rpc_execute (gp_rpc_process.c:321)
==10030==    by 0x1178A2: gp_rpc_process_call (gp_rpc_process.c:378)
==10030==    by 0x110A1A: gp_handle_query (gp_workers.c:424)
==10030==    by 0x110A1A: gp_worker_main (gp_workers.c:378)
==10030==    by 0x682F6C9: start_thread (in /usr/lib64/libpthread-2.24.so)
==10030==    by 0x6B4DF7E: clone (in /usr/lib64/libc-2.24.so)
==10030== 
==10030== LEAK SUMMARY:
==10030==    definitely lost: 235,809,111 bytes in 589,235 blocks
==10030==    indirectly lost: 20,632,139 bytes in 835,807 blocks
==10030==      possibly lost: 6,998,512 bytes in 340 blocks
==10030==    still reachable: 105,255 bytes in 2,933 blocks
==10030==         suppressed: 0 bytes in 0 blocks
==10030== 
==10030== For counts of detected and suppressed errors, rerun with: -v
==10030== ERROR SUMMARY: 44 errors from 44 contexts (suppressed: 0 from 0)

valgrind-debug

Thanks, I opened https://pagure.io/gssproxy/issue/176 using your comment.

Metadata Update from @pvoborni:
- Issue priority set to: 1
- Issue tagged with: regression
7 years ago

Metadata Update from @pvoborni:
- Issue set to the milestone: FreeIPA 4.5.1
7 years ago

Metadata Update from @tkrizek:
- Custom field rhbz adjusted to https://bugzilla.redhat.com/show_bug.cgi?id=1436642
7 years ago

Metadata Update from @tkrizek:
- Custom field rhbz adjusted to https://bugzilla.redhat.com/show_bug.cgi?id=1436642
7 years ago

Issue linked to Bugzilla: Bug 1436642

master:

  • 9a6ac74 Avoid growing FILE ccaches unnecessarily
  • fbbeb13 Handle failed authentication via cookie
  • e07aefb Work around issues fetching session data
  • d633266 Prevent churn on ccaches

ipa-4-5:

  • f1d731a Python 3: Fix session storage
  • ba828a5 Avoid growing FILE ccaches unnecessarily
  • f41c9f4 Handle failed authentication via cookie
  • 0912185 Work around issues fetching session data
  • e94575f Prevent churn on ccaches

Metadata Update from @tkrizek:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)
7 years ago

Log in to comment on this ticket.

Metadata
None

regression

None
None
critical
None
None
None
None
None
None
None
None
None
None
None
None
None
None
None
None
None
Attachments 3
httpd-error_log
Attached 7 years ago View Comment
valgrind
Attached 7 years ago View Comment
valgrind-debug
Attached 7 years ago View Comment
Powered by Pagure 5.14.1
Documentation • File an Issue • About • SSH Hostkey/Fingerprint
© Red Hat, Inc. and others.