excessive ldap requests

Bug #1405458 reported by Pavel Gluschak on 2014-12-24
24
This bug affects 5 people
Affects Status Importance Assigned to Milestone
OpenStack Identity (keystone)
Low
Unassigned

Bug Description

2014.2.1 on CentOS 7

My LDAP config:

* /etc/keystone/domains/keystone.bluepages.conf
[ldap]
url = ldap://bluepages.ibm.com
query_scope = one
user_tree_dn = c=ru,ou=bluepages,o=ibm.com
user_objectclass = ibmPerson
user_id_attribute = uid
user_name_attribute = mail
user_mail_attribute = mail
user_pass_attribute =
user_enabled_attribute =
#user_enabled_emulation = True
#user_enabled_emulation_dn = cn=openstack,ou=memberlist,ou=ibmgroups,o=ibm.com
user_allow_create = False
user_allow_update = False
user_allow_delete = False

[identity]
driver = keystone.identity.backends.ldap.Identity

I was experimenting with requesting of auth tokens:

* token-req.json
{
    "auth": {
        "identity": {
            "methods": [
                "password"
            ],
            "password": {
                "user": {
                    "domain": {
                        "name": "bluepages"
                    },
                    "name": "<email address hidden>",
                    "password": "passw0rd"
                }
            }
        }
    }
}

$ curl -si -d @token-req.json -H "Content-type: application/json" http://localhost:35357/v3/auth/tokens

This works fine, however I see excessive LDAP requests in keystone.log:

2014-12-23 21:26:48.783 24458 DEBUG keystone.common.ldap.core [-] LDAP init: url=ldap://bluepages.ibm.com _common_ldap_initialization /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:571
2014-12-23 21:26:48.783 24458 DEBUG keystone.common.ldap.core [-] LDAP init: use_tls=False tls_cacertfile=None tls_cacertdir=None tls_req_cert=2 tls_avail=1 _common_ldap_initialization /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:575
2014-12-23 21:26:48.850 24458 DEBUG keystone.common.ldap.core [-] LDAP search: base=c=ru,ou=bluepages,o=ibm.com scope=1 filterstr=(&(<email address hidden>)(objectClass=ibmPerson)) attrs=['', 'uid', 'mail'] attrsonly=0 search_s /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:926
2014-12-23 21:26:49.234 24458 DEBUG keystone.common.ldap.core [-] LDAP unbind unbind_s /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:899
2014-12-23 21:26:49.234 24458 DEBUG keystone.identity.core [-] ID Mapping - Domain ID: 9311e7259dc145a4a5acbe829f77cf1b, Default Driver: False, Domains: False, UUIDs: False, Compatible IDs: True _set_domain_id_and_mapping /usr/lib/python2.7/site-packages/keystone/identity/core.py:321
2014-12-23 21:26:49.235 24458 DEBUG keystone.identity.core [-] Local ID: R87162821 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/site-packages/keystone/identity/core.py:339
2014-12-23 21:26:49.238 24458 DEBUG keystone.identity.core [-] Found existing mapping to public ID: 8136eec10a5c7f6d61f130e875687f50368c5d8bdfd53454a9647e69b5132991 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/site-packages/keystone/identity/core.py:352
2014-12-23 21:26:49.247 24458 DEBUG keystone.common.ldap.core [-] LDAP init: url=ldap://bluepages.ibm.com _common_ldap_initialization /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:571
2014-12-23 21:26:49.247 24458 DEBUG keystone.common.ldap.core [-] LDAP init: use_tls=False tls_cacertfile=None tls_cacertdir=None tls_req_cert=2 tls_avail=1 _common_ldap_initialization /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:575
2014-12-23 21:26:49.248 24458 DEBUG keystone.common.ldap.core [-] LDAP search: base=c=ru,ou=bluepages,o=ibm.com scope=1 filterstr=(&(uid=R87162821)(objectClass=ibmPerson)) attrs=['', 'uid', 'mail'] attrsonly=0 search_s /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:926
2014-12-23 21:26:49.614 24458 DEBUG keystone.common.ldap.core [-] LDAP unbind unbind_s /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:899
2014-12-23 21:26:49.615 24458 DEBUG keystone.common.ldap.core [-] LDAP init: url=ldap://bluepages.ibm.com _common_ldap_initialization /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:571
2014-12-23 21:26:49.615 24458 DEBUG keystone.common.ldap.core [-] LDAP init: use_tls=False tls_cacertfile=None tls_cacertdir=None tls_req_cert=2 tls_avail=1 _common_ldap_initialization /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:575
2014-12-23 21:26:49.616 24458 DEBUG keystone.common.ldap.core [-] LDAP bind: who=uid=R87162821,c=ru,ou=bluepages,o=ibm.com simple_bind_s /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:891
2014-12-23 21:26:49.960 24458 DEBUG keystone.common.ldap.core [-] LDAP unbind unbind_s /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:899
2014-12-23 21:26:49.960 24458 DEBUG keystone.identity.core [-] ID Mapping - Domain ID: 9311e7259dc145a4a5acbe829f77cf1b, Default Driver: False, Domains: False, UUIDs: False, Compatible IDs: True _set_domain_id_and_mapping /usr/lib/python2.7/site-packages/keystone/identity/core.py:321
2014-12-23 21:26:49.960 24458 DEBUG keystone.identity.core [-] Local ID: R87162821 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/site-packages/keystone/identity/core.py:339
2014-12-23 21:26:49.965 24458 DEBUG keystone.identity.core [-] Found existing mapping to public ID: 8136eec10a5c7f6d61f130e875687f50368c5d8bdfd53454a9647e69b5132991 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/site-packages/keystone/identity/core.py:352
2014-12-23 21:26:50.011 24458 DEBUG keystone.common.ldap.core [-] LDAP init: url=ldap://bluepages.ibm.com _common_ldap_initialization /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:571
2014-12-23 21:26:50.011 24458 DEBUG keystone.common.ldap.core [-] LDAP init: use_tls=False tls_cacertfile=None tls_cacertdir=None tls_req_cert=2 tls_avail=1 _common_ldap_initialization /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:575
2014-12-23 21:26:50.012 24458 DEBUG keystone.common.ldap.core [-] LDAP search: base=c=ru,ou=bluepages,o=ibm.com scope=1 filterstr=(&(uid=R87162821)(objectClass=ibmPerson)) attrs=['', 'uid', 'mail'] attrsonly=0 search_s /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:926
2014-12-23 21:26:50.366 24458 DEBUG keystone.common.ldap.core [-] LDAP unbind unbind_s /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:899
2014-12-23 21:26:50.366 24458 DEBUG keystone.identity.core [-] ID Mapping - Domain ID: 9311e7259dc145a4a5acbe829f77cf1b, Default Driver: False, Domains: False, UUIDs: False, Compatible IDs: True _set_domain_id_and_mapping /usr/lib/python2.7/site-packages/keystone/identity/core.py:321
2014-12-23 21:26:50.367 24458 DEBUG keystone.identity.core [-] Local ID: R87162821 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/site-packages/keystone/identity/core.py:339
2014-12-23 21:26:50.371 24458 DEBUG keystone.identity.core [-] Found existing mapping to public ID: 8136eec10a5c7f6d61f130e875687f50368c5d8bdfd53454a9647e69b5132991 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/site-packages/keystone/identity/core.py:352
2014-12-23 21:26:50.375 24458 DEBUG keystone.common.ldap.core [-] LDAP init: url=ldap://bluepages.ibm.com _common_ldap_initialization /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:571
2014-12-23 21:26:50.375 24458 DEBUG keystone.common.ldap.core [-] LDAP init: use_tls=False tls_cacertfile=None tls_cacertdir=None tls_req_cert=2 tls_avail=1 _common_ldap_initialization /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:575
2014-12-23 21:26:50.375 24458 DEBUG keystone.common.ldap.core [-] LDAP search: base=c=ru,ou=bluepages,o=ibm.com scope=1 filterstr=(&(uid=R87162821)(objectClass=ibmPerson)) attrs=['', 'uid', 'mail'] attrsonly=0 search_s /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:926
2014-12-23 21:26:50.722 24458 DEBUG keystone.common.ldap.core [-] LDAP unbind unbind_s /usr/lib/python2.7/site-packages/keystone/common/ldap/core.py:899
2014-12-23 21:26:50.722 24458 DEBUG keystone.identity.core [-] ID Mapping - Domain ID: 9311e7259dc145a4a5acbe829f77cf1b, Default Driver: False, Domains: False, UUIDs: False, Compatible IDs: True _set_domain_id_and_mapping /usr/lib/python2.7/site-packages/keystone/identity/core.py:321

1) Why did it perform 2 search requests before bind? The first one with filterstr=(&(<email address hidden>)(objectClass=ibmPerson)) is sufficient to get dn to bind against.
2) I also don't understand two identical search requests with filterstr=(&(uid=R87162821)(objectClass=ibmPerson)) after bind was successfully performed. So instead of doing search&bind, it does search+search+bind+search+search...

Morgan Fainberg (mdrnstm) wrote :

This is a relatively known issue. We are aware that our LDAP driver is very chatty and that it can be a bottle neck.

Changed in keystone:
status: New → Triaged
importance: Undecided → Medium
Grzegorz Grasza (xek) on 2015-11-19
Changed in keystone:
assignee: nobody → Grzegorz Grasza (xek)
Steve Martinelli (stevemar) wrote :

updating the description to remove #3 (enabled emulation slows ldap down) as it's covered in https://bugs.launchpad.net/keystone/+bug/1299033

description: updated
Changed in keystone:
assignee: Grzegorz Grasza (xek) → Alicja Kwasniewska (alicja-kwasniewska)
Grzegorz Grasza (xek) on 2016-02-11
Changed in keystone:
assignee: Alicja Kwasniewska (alicja-kwasniewska) → nobody
Morgan Fainberg (mdrnstm) wrote :

This fix: https://review.openstack.org/#/c/272007/ should help move us in the right direction

Morgan Fainberg (mdrnstm) wrote :

lowering priority since new code is being developed for py3 compat against the ldap3 library instead of retrofitting the current code to use ldap3. tagged as "ldap-legacy" so it can be closed when/if the current driver is deprecated in favor of the new py3 compatible code

tags: added: ldap-legacy
Changed in keystone:
importance: Medium → Low
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers