Keystone reads users from LDAP too slow

[Paul Karikh]

I've deployed MOS 7.0 with Fuel Keystone LDAP plugin and tried to list users with Horizon. Everything works slow, but fine and there were no errors.
After that I've created 5K users in the LDAP. Somewhere after 1.5K users Horizon requests to Keystone started to failing with timeout error.
When Horizon is waiting for Keystone response, a I see in Keystone logs (/var/log/keystone/main.log) a lot of debug lines like this:
`2015-09-17 11:37:47.990 12575 DEBUG keystone.identity.core [-] ID Mapping - Domain ID: cdb5ef2ad5324ba3b4a56cec6ac33420, Default Driver: False, Domains: False, UUIDs: False, Compatible IDs: True _set_domain_id_and_mapping /usr/lib/python2.7/dist-packages/keystone/identity/core.py:492
2015-09-17 11:37:47.991 12575 DEBUG keystone.identity.core [-] Local ID: auto_user-1067 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/dist-packages/keystone/identity/core.py:510`

After that I've deleted almost all users from LDAP (there left only auto_user0, auto_user1 and auto_user10 and admin users) and tried to fetch them again with Horizon. And I've got the same lines:

2015-09-17 11:37:47.969 12575 DEBUG keystone.identity.core [-] Local ID: auto_user-1 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/dist-packages/keystone/identity/core.py:510
2015-09-17 11:37:47.978 12575 DEBUG keystone.identity.core [-] Found existing mapping to public ID: a06df89598f65718695a3c3e138451f351416dfbd3f39fb254462f438de4c274 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/dist-packages/keystone/identity/core.py:523
2015-09-17 11:37:47.980 12575 DEBUG keystone.identity.core [-] ID Mapping - Domain ID: cdb5ef2ad5324ba3b4a56cec6ac33420, Default Driver: False, Domains: False, UUIDs: False, Compatible IDs: True _set_domain_id_and_mapping /usr/lib/python2.7/dist-packages/keystone/identity/core.py:492
2015-09-17 11:37:47.982 12575 DEBUG keystone.identity.core [-] Local ID: auto_user-10 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/dist-packages/keystone/identity/core.py:510
2015-09-17 11:37:47.989 12575 DEBUG keystone.identity.core [-] Found existing mapping to public ID: 44c396a392a341539101a28cdad4312d5113ca88c264fb4135550c0e336ae579 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/dist-packages/keystone/identity/core.py:523
2015-09-17 11:37:47.990 12575 DEBUG keystone.identity.core [-] ID Mapping - Domain ID: cdb5ef2ad5324ba3b4a56cec6ac33420, Default Driver: False, Domains: False, UUIDs: False, Compatible IDs: True _set_domain_id_and_mapping /usr/lib/python2.7/dist-packages/keystone/identity/core.py:492
2015-09-17 11:37:47.991 12575 DEBUG keystone.identity.core [-] Local ID: auto_user-1067 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/dist-packages/keystone/identity/core.py:510
2015-09-17 11:37:47.998 12575 DEBUG keystone.identity.core [-] Found existing mapping to public ID: 85ca3743b8406ffd60505fa16342f66cf3f6b7ed9d8d197e3beab28e2715930c _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/dist-packages/keystone/identity/core.py:523
2015-09-17 11:37:48.000 12575 DEBUG keystone.identity.core [-] ID Mapping - Domain ID: cdb5ef2ad5324ba3b4a56cec6ac33420, Default Driver: False, Domains: False, UUIDs: False, Compatible IDs: True _set_domain_id_and_mapping /usr/lib/python2.7/dist-packages/keystone/identity/core.py:492
2015-09-17 11:37:48.001 12575 DEBUG keystone.identity.core [-] Local ID: auto_user-1068 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/dist-packages/keystone/identity/core.py:510
2015-09-17 11:37:48.009 12575 DEBUG keystone.identity.core [-] Found existing mapping to public ID: 1de806c18b4cca49aefb0820e1097e8df5fd68ea0b1425b74643eacbc2e9d981 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/dist-packages/keystone/identity/core.py:523
2015-09-17 11:37:48.011 12575 DEBUG keystone.identity.core [-] ID Mapping - Domain ID: cdb5ef2ad5324ba3b4a56cec6ac33420, Default Driver: False, Domains: False, UUIDs: False, Compatible IDs: True _set_domain_id_and_mapping /usr/lib/python2.7/dist-packages/keystone/identity/core.py:492
2015-09-17 11:37:48.012 12575 DEBUG keystone.identity.core [-] Local ID: auto_user-1069 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/dist-packages/keystone/identity/core.py:510
2015-09-17 11:37:48.019 12575 DEBUG keystone.identity.core [-] Found existing mapping to public ID: 94f6f8fbac83e4ae87fab63758322dabfaf43b9187a77f3b50d2bb66f26be5e4 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/dist-packages/keystone/identity/core.py:523
2015-09-17 11:37:48.020 12575 DEBUG keystone.identity.core [-] ID Mapping - Domain ID: cdb5ef2ad5324ba3b4a56cec6ac33420, Default Driver: False, Domains: False, UUIDs: False, Compatible IDs: True _set_domain_id_and_mapping /usr/lib/python2.7/dist-packages/keystone/identity/core.py:492
2015-09-17 11:37:48.021 12575 DEBUG keystone.identity.core [-] Local ID: auto_user-1070

The problem is users auto_user-1070 , auto_user-1069, auto_user-1067, etc are no more present in LDAP. And even after 24 hours after users has been deleted from LDAP there are a lot of lines where Keystone says that it maps these users. And looks like while Keystone maps users, Horizon is waiting fore response. So, even if LDAP has not so much users, Horizon can't get a response from Keystone for listing users and fails with timeout.

Here is how LDAP is configured with Keystone:
/etc/keystone/domains/keystone.keystone.tld.conf contains the followong lines

[ldap]
user_allow_update=False
user=cn=admin_ad,cn=Users,dc=keystone,dc=tld
user_filter=
user_name_attribute=cn
user_pass_attribute=userPassword
user_enabled_attribute=enabled
suffix=dc=keystone,dc=tld
password=Pass1234
url=ldap://172.16.57.78
user_allow_create=False
user_allow_delete=False
user_objectclass=person
user_tree_dn=dc=keystone,dc=tld
query_scope=sub
user_id_attribute=cn
debug_level=-1
page_size = 50

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

[Boris Bobrov (bbobrov)]

We've decided to implement limiting. The implementation is traced in PROD-2000

[Alexander Makarov (amakarov)]

We'll lower it's importance to medium as list_limit is implemented

[Davanum Srinivas (DIMS) (dims-v)]

Sasha,

What's the working done for this? Links to reviews please?

[Boris Bobrov (bbobrov)]

The actual slowness will be worked-around after list_limit for ldap is implemented: https://review.openstack.org/#/c/234849/ .

[Alexander Makarov (amakarov)]

Dims, I watch the bug status carefully - there are bugs that will not
be fixed directly.
Some of these will even become invalid when other bugs are fixed.

On Thu, Nov 26, 2015 at 12:21 PM, Boris Bobrov <email address hidden> wrote:
> The actual slowness will be worked-around after list_limit for ldap is
> implemented: https://review.openstack.org/#/c/234849/ .
>
> ** Changed in: mos/7.0.x
> Assignee: MOS Keystone (mos-keystone) => Boris Bobrov (bbobrov)
>
> ** Changed in: mos/8.0.x
> Assignee: MOS Keystone (mos-keystone) => Boris Bobrov (bbobrov)
>
> --
> You received this bug notification because you are a member of MOS
> Keystone, which is a bug assignee.
> https://bugs.launchpad.net/bugs/1496840
>
> Title:
> Keystone reads users from LDAP too slow
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/mos/+bug/1496840/+subscriptions

--
Kind Regards,
Alexander Makarov,
Senior Software Developer,

Mirantis, Inc.
35b/3, Vorontsovskaya St., 109147, Moscow, Russia

Tel.: [phone]
Tel.: [phone]

Skype: MAKAPOB.AJIEKCAHDP

[Boris Bobrov (bbobrov)]

https://review.openstack.org/#/c/234849/ -- the workaround with limiting the number of fetched users is being implemented in this chain of patches.

[Boris Bobrov (bbobrov)]

The patches might be too complex for backporting them to 7.0. I'm marking it as "won't fix" for 7.0, if you still need it, please reopen the bug.

[Davanum Srinivas (DIMS) (dims-v)]

Looks like one of the reviews in that series Boris is pointing to is still waiting to be merged in upstream

[Dmytro Fomenko (daks12)]

The same issue, customer Teradata. Fuel 7.0 + LDAP plugin. When I'm trying to list user in domain (or create project) I see a huge amount of the following message in log for 6 minutes:

2016-01-26 17:28:20.295 8365 DEBUG keystone.identity.core [-] Local ID: jb1800906 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/dist-packages/keystone/identity/core.py:510
2016-01-26 17:28:20.298 8365 DEBUG keystone.identity.core [-] Found existing mapping to public ID: c1273166d7321e614fa7aa5c87c080cb94a9aa6e9a77da891fe4abdc5e0f1a49 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/dist-packages/keystone/identity/core.py:523
2016-01-26 17:28:20.298 8365 DEBUG keystone.identity.core [-] ID Mapping - Domain ID: b0ded156c4e940e5b5dc6649ae248ee4, Default Driver: False, Domains: False, UUIDs: False, Compatible IDs: True _set_domain_id_and_mapping /usr/lib/python2.7/dist-packages/keystone/identity/core.py:492
2016-01-26 17:28:20.298 8365 DEBUG keystone.identity.core [-] Local ID: ef1296204 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/dist-packages/keystone/identity/core.py:510
2016-01-26 17:28:20.300 8365 DEBUG keystone.identity.core [-] Found existing mapping to public ID: dba646a4cebf7f4399506fc37b31033e1525aa55b7fd5c7ba0d940b5da590644 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/dist-packages/keystone/identity/core.py:523
2016-01-26 17:28:20.301 8365 DEBUG keystone.identity.core [-] ID Mapping - Domain ID: b0ded156c4e940e5b5dc6649ae248ee4, Default Driver: False, Domains: False, UUIDs: False, Compatible IDs: True _set_domain_id_and_mapping /usr/lib/python2.7/dist-packages/keystone/identity/core.py:492
2016-01-26 17:28:20.301 8365 DEBUG keystone.identity.core [-] Local ID: ia1830000 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/dist-packages/keystone/identity/core.py:510
2016-01-26 17:28:20.303 8365 DEBUG keystone.identity.core [-] Found existing mapping to public ID: 6352b363edee1a85b5fafbff813070bfac61a6d8f4bbcfe1e0b9501579977f6d _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/dist-packages/keystone/identity/core.py:523
2016-01-26 17:28:20.304 8365 DEBUG keystone.identity.core [-] ID Mapping - Domain ID: b0ded156c4e940e5b5dc6649ae248ee4, Default Driver: False, Domains: False, UUIDs: False, Compatible IDs: True _set_domain_id_and_mapping /usr/lib/python2.7/dist-packages/keystone/identity/core.py:492
2016-01-26 17:28:20.304 8365 DEBUG keystone.identity.core [-] Local ID: js1426454 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/dist-packages/keystone/identity/core.py:510
2016-01-26 17:28:20.306 8365 DEBUG keystone.identity.core [-] Found existing mapping to public ID: 94b8237ed3559dcd8a8bd5df2a0d6a7e8b98a45216458f0a80d1e66a160c5d17 _set_domain_id_and_mapping_for_single_ref /usr/lib/python2.7/dist-packages/keystone/identity/core.py:523
2016-01-26 17:28:20.306 8365 DEBUG keystone.identity.core [-] ID Mapping - Domain ID: b0ded156c4e940e5b5dc6649ae248ee4, Default Driver: False, Domains: False, UUIDs: False, Compatible IDs: True _set_domain_id_and_mapping /usr/lib/python2.7/dist-packages/keystone/identity/core.py:492
2016-01-26 17:28:20.307 8365 DEBUG keystone.identity.c...

[Boris Bobrov (bbobrov)]

I am setting it as "won't fix" for 7.0 and 8.0 because the workaround with limiting turned out to be a whole new feature. The proper fix is very complex too and will require rewriting id_mapping_api.

As a workaround, I suggest you to filter users using filters in keystone.conf. If you want to fix it in code, I suggest you to have a look at function _set_domain_id_and_mapping_for_single_ref and how it's used. The problem is that public id is being queried per user, so for N users there will be N queries.

[Boris Bobrov (bbobrov)]

I am setting this as wont fix for 9.0, because it was not fixed in upstream. This will be worked on in 10.0.

[Boris Bobrov (bbobrov)]

This is being fixed in upstream under bugreport https://bugs.launchpad.net/keystone/+bug/1582585

[Maria Zlatkova (mzlatkova)]

Adding the release-notes tag back to describe the bug in 9.2 known issues.

[Maria Zlatkova (mzlatkova)]

A release note has been added to 9.2 known issues: https://review.fuel-infra.org/#/c/29742.

[Denis Meltsaykin (dmeltsaykin)]

Won't fix for 9.x-updates, since it is marked as known issue in 9.2