LDAP fails with paging support, "Critical extension is unavailable" 500 error

[Ionuț Arțăriși]

Keystone raises a 500 error when trying to use paging on an LDAP server that doesn't support it (by setting [ldap] page_size to a non-zero integer)

# keystone user-list
An unexpected error prevented the server from fulfilling your request. {'desc': 'Critical extension is unavailable'} (HTTP 500)

And this is the keystone.log traceback:

2014-08-18 10:48:09.684 21606 ERROR keystone.common.wsgi [-] {'desc': 'Critical extension is unavailable'}
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi Traceback (most recent call last):
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi File "/usr/lib64/python2.6/site-packages/keystone/common/wsgi.py", line 207, in __call__
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi result = method(context, **params)
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi File "/usr/lib64/python2.6/site-packages/keystone/identity/controllers.py", line 112, in get_users
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi user_list = self.identity_api.list_users()
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi File "/usr/lib64/python2.6/site-packages/keystone/common/manager.py", line 47, in wrapper
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi return f(self, *args, **kwargs)
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi File "/usr/lib64/python2.6/site-packages/keystone/identity/core.py", line 189, in wrapper
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi return f(self, *args, **kwargs)
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi File "/usr/lib64/python2.6/site-packages/keystone/identity/core.py", line 328, in list_users
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi ref_list = driver.list_users(hints or driver_hints.Hints())
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi File "/usr/lib64/python2.6/site-packages/keystone/identity/backends/hybrid.py", line 112, in list_users
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi ldap_users = self.user.get_all_filtered()
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi File "/usr/lib64/python2.6/site-packages/keystone/identity/backends/ldap.py", line 245, in get_all_filtered
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi return [identity.filter_user(user) for user in self.get_all()]
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi File "/usr/lib64/python2.6/site-packages/keystone/common/ldap/core.py", line 1009, in get_all
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi return super(EnabledEmuMixIn, self).get_all(ldap_filter)
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi File "/usr/lib64/python2.6/site-packages/keystone/common/ldap/core.py", line 628, in get_all
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi for x in self._ldap_get_all(ldap_filter)]
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi File "/usr/lib64/python2.6/site-packages/keystone/common/ldap/core.py", line 603, in _ldap_get_all
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi attrs)
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi File "/usr/lib64/python2.6/site-packages/keystone/common/ldap/core.py", line 809, in search_s
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi ldap_result = self.paged_search_s(dn, scope, query, attrlist)
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi File "/usr/lib64/python2.6/site-packages/keystone/common/ldap/core.py", line 845, in paged_search_s
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi rtype, rdata, rmsgid, serverctrls = self.conn.result3(msgid)
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi File "/usr/lib64/python2.6/site-packages/ldap/ldapobject.py", line 432, in result3
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi ldap_result = self._ldap_call(self._l.result3,msgid,all,timeout)
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi File "/usr/lib64/python2.6/site-packages/ldap/ldapobject.py", line 96, in _ldap_call
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi result = func(*args,**kwargs)
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi UNAVAILABLE_CRITICAL_EXTENSION: {'desc': 'Critical extension is unavailable'}
2014-08-18 10:48:09.684 21606 TRACE keystone.common.wsgi

IMHO, there should be a better error message and no 500 error should be raised.

[Lance Bragstad (lbragstad)]

Ionut,

There seems to be a better error message in the code. Judging by the trace provided this isn't running on the latest Keystone. What version are you seeing this with? I think the version you're running with predates the LDAP refactor [1], which improves that error message and it's much more descriptive [2].

I would suggest updating if you can and see if you can recreate the issue.

If the call still fails in _paged_search_s [3], then we should think about wrapping it in a try/except and handling it that way.

[1] https://github.com/openstack/keystone/commit/ebb59a75cecc71ca7cc137e16056a4c8b513fd8d
[2] https://github.com/openstack/keystone/blob/2e4977076c6a48a472ff227c85f7e150438029ca/keystone/common/ldap/core.py#L988-L990
[3] https://github.com/openstack/keystone/blob/2e4977076c6a48a472ff227c85f7e150438029ca/keystone/common/ldap/core.py#L967

[Ionuț Arțăriși (mapleoin)]

Lance, this was on Icehouse. I haven't tried it on master yet and possibly it is already fixed there like you say.

[Nathan Kinder (nkinder)]

The fix would be to make Keystone search the rootDSE at startup to see if the Simple Paged Results control is supported. If it is not supported, we should log a warning and not attempt to use the control. The specific control OID we need to look for is:

  1.2.840.113556.1.4.319

This will be supplied in the rootDSE as a value of the 'supportedControl' attribute if it is supported.

[Steve Martinelli (stevemar)]

this was fixed in Juno

[Suraj Chandegave (surajchandegave)]

Hi Steve,

Can you please share git commit link to the code fix done for this defect ?

Thanks,
Suraj