RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1505454 - IPA API returns TimeLimitExceeded without a reason
Summary: IPA API returns TimeLimitExceeded without a reason
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: ipa
Version: 7.4
Hardware: Unspecified
OS: Linux
unspecified
medium
Target Milestone: rc
: ---
Assignee: IPA Maintainers
QA Contact: ipa-qe
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-10-23 15:33 UTC by Lea Bradacova
Modified: 2023-09-14 04:10 UTC (History)
8 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-08-22 09:19:54 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)
CPU Utilization graph last week (65.98 KB, application/pdf)
2017-10-24 11:13 UTC, Lea Bradacova 		no flags Details
Memory utilization graph last week (72.22 KB, application/pdf)
2017-10-24 11:14 UTC, Lea Bradacova 		no flags Details
View All

Description Lea Bradacova 2017-10-23 15:33:18 UTC 
Description of problem:

Our client has a problem with IPA

An error TimeLimitExceeded sometimes reveals while calling IPA JSON API (/ipa/session/json). Api calls this error. User who calls JSON API is a user with login czechidm and it has in ds389 unlimited limits for these actions:

dn: uid=czechidm,cn=users,cn=accounts,dc=internal,dc=services
changetype: modify
add: nsIdleTimeout
nsIdleTimeout: -1
-
add: nsLookThroughLimit
nsLookThroughLimit: -1
-
add: nsSizeLimit
nsSizeLimit: -1
-
add: nsTimeLimit
nsTimeLimit: -1

Although it has unlimmited limits sometimes this error reveals in LDAP log. We are still not able to replicate this error but it reveals regularly with small changes as a lock of account. There is similar bug in this bugreport but not the same: https://bugzilla.redhat.com/show_bug.cgi?id=1183655#c37

API in error_log reports an error:

/var/log/httpd/error_log-20171001:[Fri Sep 29 11:13:47.875903 2017] [:error] [pid 5576] ipa: INFO: [jsonserver_session] czechidm: user_find(u'sb70854', uid=u'sb70854', timelimit=20, sizelimit=99999, all=True, version=u'2.156'): TimeLimitExceeded
/var/log/httpd/error_log-20171015:[Wed Oct 11 10:39:15.167196 2017] [:error] [pid 25658] ipa: INFO: [jsonserver_session] czechidm: user_find(None, uid=u'mcervinkova', timelimit=20, sizelimit=99999, all=True, version=u'2.156'): TimeLimitExceeded
/var/log/httpd/error_log-20171015:[Wed Oct 11 10:57:57.864386 2017] [:error] [pid 18378] ipa: INFO: [jsonserver_session] czechidm: user_find(u'mdlabacek', uid=u'mdlabacek', timelimit=20, sizelimit=99999, all=True, version=u'2.156'): TimeLimitExceeded
/var/log/httpd/error_log-20171015:[Wed Oct 11 11:01:00.321893 2017] [:error] [pid 18369] ipa: INFO: [jsonserver_session] czechidm: user_find(None, uid=u'jhyrsova', timelimit=20, sizelimit=99999, all=True, version=u'2.156'): TimeLimitExceeded
/var/log/httpd/error_log-20171015:[Wed Oct 11 11:01:05.830512 2017] [:error] [pid 18369] ipa: INFO: [jsonserver_session] czechidm: user_find(u'mmatys', uid=u'mmatys', timelimit=20, sizelimit=99999, all=True, version=u'2.156'): TimeLimitExceeded
/var/log/httpd/error_log-20171015:[Wed Oct 11 12:19:32.850074 2017] [:error] [pid 30538] ipa: INFO: [jsonserver_session] czechidm: group_remove_member(u'ipausers', version=u'2.156', user=u'amichejdova1'): TimeLimitExceeded
/var/log/httpd/error_log-20171015:[Wed Oct 11 13:04:55.105700 2017] [:error] [pid 4312] ipa: INFO: [jsonserver_session] czechidm: user_find(u'tvasutova', uid=u'tvasutova', timelimit=20, sizelimit=99999, all=True, version=u'2.156'): TimeLimitExceeded
/var/log/httpd/error_log-20171015:[Wed Oct 11 13:15:27.058749 2017] [:error] [pid 4082] ipa: INFO: [jsonserver_session] czechidm: user_mod(u'mprudicova', nsaccountlock=True, version=u'2.156'): TimeLimitExceeded
/var/log/httpd/error_log-20171015:[Wed Oct 11 13:22:53.496045 2017] [:error] [pid 6426] ipa: INFO: [jsonserver_session] czechidm: user_find(None, uid=u'zjedlicka', timelimit=20, sizelimit=99999, all=True, version=u'2.156'): TimeLimitExceeded
/var/log/httpd/error_log-20171015:[Wed Oct 11 14:08:12.039000 2017] [:error] [pid 12048] ipa: INFO: [jsonserver_session] czechidm: user_find(u'msimandl', uid=u'msimandl', timelimit=20, sizelimit=99999, all=True, version=u'2.156'): TimeLimitExceeded

In the log ds389 is displayed timeout exceeded in the same time while finding configuration:

[root@ipa-tst-01 ~]# grep conn=328394 /var/log/dirsrv/slapd-INTERNAL-SERVICES/access*
/var/log/dirsrv/slapd-INTERNAL-SERVICES/access.20171010-135042:[11/Oct/2017:13:15:22.596890581 +0200] conn=328394 fd=152 slot=152 connection from 10.14.145.24 to 10.14.145.24
/var/log/dirsrv/slapd-INTERNAL-SERVICES/access.20171010-135042:[11/Oct/2017:13:15:22.599036063 +0200] conn=328394 op=0 BIND dn="" method=sasl version=3 mech=GSS-SPNEGO
/var/log/dirsrv/slapd-INTERNAL-SERVICES/access.20171010-135042:[11/Oct/2017:13:15:22.609078500 +0200] conn=328394 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="uid=czechidm,cn=users,cn=accounts,dc=internal,dc=services"
/var/log/dirsrv/slapd-INTERNAL-SERVICES/access.20171010-135042:[11/Oct/2017:13:15:22.611625173 +0200] conn=328394 op=1 SRCH base="cn=ipaconfig,cn=etc,dc=internal,dc=services" scope=0 filter="(objectClass=*)" attrs=ALL
/var/log/dirsrv/slapd-INTERNAL-SERVICES/access.20171010-135042:[11/Oct/2017:13:15:27.058009572 +0200] conn=328394 op=1 RESULT err=3 tag=101 nentries=0 etime=5
/var/log/dirsrv/slapd-INTERNAL-SERVICES/access.20171010-135042:[11/Oct/2017:13:15:27.059213798 +0200] conn=328394 op=2 UNBIND
/var/log/dirsrv/slapd-INTERNAL-SERVICES/access.20171010-135042:[11/Oct/2017:13:15:27.059230063 +0200] conn=328394 op=2 fd=152 closed - U1

After turning on debug mode IPA there can be found that problem is in the method get_ipa_config:

[Fri Sep 29 11:00:01.140338 2017] [:error] [pid 5576] ipa: DEBUG: WSGI wsgi_execute PublicError: Traceback (most recent call last):
[Fri Sep 29 11:00:01.140370 2017] [:error] [pid 5576] File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 366, in wsgi_execute
[Fri Sep 29 11:00:01.140377 2017] [:error] [pid 5576] result = command(*args, **options)
[Fri Sep 29 11:00:01.140382 2017] [:error] [pid 5576] File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 449, in _call_
[Fri Sep 29 11:00:01.140387 2017] [:error] [pid 5576] return self.__do_call(*args, **options)
[Fri Sep 29 11:00:01.140401 2017] [:error] [pid 5576] File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 477, in __do_call
[Fri Sep 29 11:00:01.140406 2017] [:error] [pid 5576] ret = self.run(*args, **options)
[Fri Sep 29 11:00:01.140411 2017] [:error] [pid 5576] File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 799, in run
[Fri Sep 29 11:00:01.140416 2017] [:error] [pid 5576] return self.execute(*args, **options)
[Fri Sep 29 11:00:01.140421 2017] [:error] [pid 5576] File "/usr/lib/python2.7/site-packages/ipaserver/plugins/baseldap.py", line 1989, in execute
[Fri Sep 29 11:00:01.140426 2017] [:error] [pid 5576] config = ldap.get_ipa_config()
[Fri Sep 29 11:00:01.140431 2017] [:error] [pid 5576] File "/usr/lib/python2.7/site-packages/ipaserver/plugins/ldap2.py", line 242, in get_ipa_config
[Fri Sep 29 11:00:01.140435 2017] [:error] [pid 5576] self.handle_truncated_result(truncated)
[Fri Sep 29 11:00:01.140440 2017] [:error] [pid 5576] File "/usr/lib/python2.7/site-packages/ipapython/ipaldap.py", line 1028, in handle_truncated_result
[Fri Sep 29 11:00:01.140445 2017] [:error] [pid 5576] raise errors.TimeLimitExceeded()
[Fri Sep 29 11:00:01.140450 2017] [:error] [pid 5576] TimeLimitExceeded: Configured time limit exceeded
[Fri Sep 29 11:00:01.140455 2017] [:error] [pid 5576]

If we look at the code on the method get_ipa_config there is obvious that there is hardcoded timeout and sizelimit(and it is the cause in our opinion):

try:

    use find_entries here lest we hit an infinite recursion when
    ldap2.get_entries tries to determine default time/size limits
    (entries, truncated) = self.find_entries(
    None, attrs_list, base_dn=dn, scope=self.SCOPE_BASE,
    time_limit=2, size_limit=10
    )
    self.handle_truncated_result(truncated)
    config_entry = entries[0]


Version-Release number of selected component (if applicable):

[root@ipa-tst-01 ~]# rpm -qa | grep ipa && cat /etc/*release
ipa-client-common-4.5.0-20.el7.noarch
python-ipaddress-1.0.16-2.el7.noarch
python2-ipalib-4.5.0-20.el7.noarch
ipa-common-4.5.0-20.el7.noarch
sssd-ipa-1.15.2-50.el7.x86_64
ipa-server-common-4.5.0-20.el7.noarch
ipa-client-4.5.0-20.el7.x86_64
ipa-server-dns-4.5.0-20.el7.noarch
python-libipa_hbac-1.15.2-50.el7.x86_64
python2-ipaserver-4.5.0-20.el7.noarch
ipa-server-4.5.0-20.el7.x86_64
libipa_hbac-1.15.2-50.el7.x86_64
python2-ipaclient-4.5.0-20.el7.noarch
python-iniparse-0.4-9.el7.noarch
NAME="Red Hat Enterprise Linux Server"
VERSION="7.4 (Maipo)"
ID="rhel"
ID_LIKE="fedora"
VARIANT="Server"
VARIANT_ID="server"
VERSION_ID="7.4"
PRETTY_NAME="Red Hat Enterprise Linux Server 7.4 (Maipo)"
ANSI_COLOR="0;31"
CPE_NAME="cpe:/o:redhat:enterprise_linux:7.4:GA:server"
HOME_URL="https://www.redhat.com/"
BUG_REPORT_URL="https://bugzilla.redhat.com/"

REDHAT_BUGZILLA_PRODUCT="Red Hat Enterprise Linux 7"
REDHAT_BUGZILLA_PRODUCT_VERSION=7.4
REDHAT_SUPPORT_PRODUCT="Red Hat Enterprise Linux"
REDHAT_SUPPORT_PRODUCT_VERSION="7.4"
Red Hat Enterprise Linux Server release 7.4 (Maipo)
Red Hat Enterprise Linux Server release 7.4 (Maipo)


How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:

TimeLimitExceeded

Expected results:

We need this bug to be fixed in future freeipa/ipa versions

Additional info:

Our workaround: 
We have tried on test environment to rewrite hardcoded timelimit from 2 to 20. The error stopped to appear.
Comment 2 Rob Crittenden 2017-10-23 15:46:54 UTC 
What hardcoded timelimit? What exactly did you change?

I seem to recall a 389-ds bug related to user-specific limits, cc'ing 389-ds dev.
Comment 3 Lea Bradacova 2017-10-23 15:57:12 UTC 
A method get_ipa_config
try:

    use find_entries here lest we hit an infinite recursion when
    ldap2.get_entries tries to determine default time/size limits
    (entries, truncated) = self.find_entries(
    None, attrs_list, base_dn=dn, scope=self.SCOPE_BASE,
    time_limit=2, size_limit=10
    )
    self.handle_truncated_result(truncated)
    config_entry = entries[0]

time_limit set to 20 instead of 2
Comment 4 mreynolds 2017-10-23 16:26:44 UTC 
(In reply to Rob Crittenden from comment #2)
> What hardcoded timelimit? What exactly did you change?
> 
> I seem to recall a 389-ds bug related to user-specific limits, cc'ing 389-ds
> dev.

There was a DS ticket created where user specific resource limits were not honoured, but I just tested the server and it seems to be working fine.  I set anonymous resource time limit to 2 seconds, as well as the global time limit to 2 seconds.  Then I set a user time limit to 300 seconds, and it works as expected.  So I do not think there is a DS bug around the resource limits.
Comment 5 Rob Crittenden 2017-10-23 18:20:12 UTC 
Ok, get_ipa_config is a bit of a special case as it bootstraps the timeout for subsequent requests. This is different and completely separate from binding as a user and using 389-ds timeout values.

Is your server under serious strain? How long is this taking? (the logs will tell you).
Comment 6 Lea Bradacova 2017-10-24 11:13:23 UTC 
Created attachment 1342690 [details]
CPU Utilization graph last week
Comment 7 Lea Bradacova 2017-10-24 11:14:37 UTC 
Created attachment 1342691 [details]
Memory utilization graph last week
Comment 8 Lea Bradacova 2017-10-24 11:17:15 UTC 
Here are in attachment graphs of memory and cpu for last week from our monitoring. There is almost no load on the server. During this time the error occured 2 times:

[root@ipa-02 ~]# grep 'err=3 ' /var/log/dirsrv/slapd-INTERNAL-SERVICES/access*
/var/log/dirsrv/slapd-INTERNAL-SERVICES/access:[24/Oct/2017:08:28:39.954984501 +0200] conn=716022 op=3 RESULT err=3 tag=101 nentries=0 etime=4
/var/log/dirsrv/slapd-INTERNAL-SERVICES/access.20171022-212616:[23/Oct/2017:08:16:44.491743118 +0200] conn=676848 op=3 RESULT err=3 tag=101 nentries=0 etime=7

[root@ipa-02 ~]# grep conn=676848 /var/log/dirsrv/slapd-INTERNAL-SERVICES/access.20171022-212616
[23/Oct/2017:08:16:36.322275330 +0200] conn=676848 fd=83 slot=83 connection from 10.14.145.22 to 10.14.145.22
[23/Oct/2017:08:16:36.323317507 +0200] conn=676848 op=0 BIND dn="" method=sasl version=3 mech=GSSAPI
[23/Oct/2017:08:16:36.344171869 +0200] conn=676848 op=0 RESULT err=14 tag=97 nentries=0 etime=0, SASL bind in progress
[23/Oct/2017:08:16:36.344571433 +0200] conn=676848 op=1 BIND dn="" method=sasl version=3 mech=GSSAPI
[23/Oct/2017:08:16:36.346333801 +0200] conn=676848 op=1 RESULT err=14 tag=97 nentries=0 etime=0, SASL bind in progress
[23/Oct/2017:08:16:36.346487604 +0200] conn=676848 op=2 BIND dn="" method=sasl version=3 mech=GSSAPI
[23/Oct/2017:08:16:36.347887151 +0200] conn=676848 op=2 RESULT err=0 tag=97 nentries=0 etime=0 dn="uid=czechidm,cn=users,cn=accounts,dc=internal,dc=services"
[23/Oct/2017:08:16:36.591178422 +0200] conn=676848 op=3 SRCH base="cn=ipaconfig,cn=etc,dc=internal,dc=services" scope=0 filter="(objectClass=*)" attrs=ALL
[23/Oct/2017:08:16:44.491743118 +0200] conn=676848 op=3 RESULT err=3 tag=101 nentries=0 etime=7
[23/Oct/2017:08:16:44.493905102 +0200] conn=676848 op=4 UNBIND
[23/Oct/2017:08:16:44.493932632 +0200] conn=676848 op=4 fd=83 closed - U1
Comment 9 Florence Blanc-Renaud 2017-11-14 17:07:37 UTC 
Upstream ticket:
https://pagure.io/freeipa/issue/7260
Comment 10 thierry bordaz 2018-01-29 12:19:02 UTC 
Regarding the timelimit, you can enable log level (4 or 5=4+1) to get more information where the limit is coming from http://www.port389.org/docs/389ds/FAQ/faq.html#Troubleshooting

level 4:
will say if the limit come from the request or not
do_search - SRCH base="(null)" scope=0 deref=0 sizelimit=0 timelimit=3 attrsonly=0 filter="(objectClass=*)" attrs=ALL
 

level 5 (4+1): is much more verbose but could give information if the limit was computed
slapi_reslimit_get_integer_limit - <= returning SUCCESS, value=3



Regarding the performance, it is surprising to see a base search lasting so long.

[23/Oct/2017:08:16:36.591178422 +0200] conn=676848 op=3 SRCH base="cn=ipaconfig,cn=etc,dc=internal,dc=services" scope=0 filter="(objectClass=*)" attrs=ALL

A guess is that requesting all the attributes it can be slow down by ACI evaluation. You may retry the search being DM, or doing some pstack while the search happen
Comment 11 Rob Crittenden 2018-02-26 21:45:13 UTC 
Mark, do you think this is related to https://bugzilla.redhat.com/show_bug.cgi?id=1515190 ?
Comment 12 mreynolds 2018-02-26 23:44:05 UTC 
(In reply to Rob Crittenden from comment #11)
> Mark, do you think this is related to
> https://bugzilla.redhat.com/show_bug.cgi?id=1515190 ?

Yes it's definitely possible.  But it depends on what is set in the anonymous resource limits entry.

It's timing out after 7 seconds - that's pretty short.  What is set in the anonymous limits entry?
Comment 15 Alexander Bokovoy 2018-08-22 09:19:54 UTC 
Lea, an underlying issue in 389-ds was fixed in RHEL 7.5.z with the release of a fix for bug 1554720.

Since there were no responses on this bug for 6 months, I'm closing it.
Comment 16 Red Hat Bugzilla 2023-09-14 04:10:42 UTC 
The needinfo request[s] on this closed bug have been removed as they have been unresolved for 1000 days
Note You need to log in before you can comment on or make changes to this bug.