yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1405458] [NEW] excessive ldap requests

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Pavel Gluschak <trustytwelve@xxxxxxxxx>
Date: Wed, 24 Dec 2014 17:36:36 -0000
Reply-to: Bug 1405458 <1405458@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

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": "XXXXX@xxxxxxxxxx",
                    "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=(&(mail=XXXXX@xxxxxxxxxx)(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=(&(mail=XXXXX@xxxxxxxxxx)(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...
3) If I additionally enable "user_enabled_emulation", LDAP backend performs x2 more search requests, which degrades performance significantly. But seems like it's already addressed in #1299033.

** Affects: keystone
     Importance: Undecided
         Status: New


** Tags: ldap

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to Keystone.
https://bugs.launchpad.net/bugs/1405458

Title:
  excessive ldap requests

Status in OpenStack Identity (Keystone):
  New

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": "XXXXX@xxxxxxxxxx",
                      "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=(&(mail=XXXXX@xxxxxxxxxx)(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=(&(mail=XXXXX@xxxxxxxxxx)(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...
  3) If I additionally enable "user_enabled_emulation", LDAP backend performs x2 more search requests, which degrades performance significantly. But seems like it's already addressed in #1299033.

To manage notifications about this bug go to:
https://bugs.launchpad.net/keystone/+bug/1405458/+subscriptions
Follow ups

[Bug 1405458] [NEW] excessive ldap requests
From: Pavel Gluschak, 2014-12-24
References

[Bug 1405458] [NEW] excessive ldap requests
From: Pavel Gluschak, 2014-12-24