POST v3/auth/tokens API is returning unexpected 500 error when ldap credentials are incorrect

[prashkre]

When keystone is configured with ldap server as identity backend, if incorrect credentials were configured under [ldap] section [1] of domains conf file, then POST request on /v3/auth/tokens API with users in ldap is returning unexpected 500 error [0] with stacktrace[2] shown below.
Instead of unexpected error user should be given a proper message about invalid credentials configured.

[0]
{"error": {"message": "An unexpected error prevented the server from fulfilling your request.", "code": 500, "title": "Internal Server Error"}}

[1]
[ldap]
url = ldap://9.9.9.9
user = cn=root
password = <<incorrect password>>

[2]Stacktrace:
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi [req-7b62d1db-64bd-4961-819e-0815bc355636 02b49a455f5c9d9561881683c0f09919c5ab38a6eeed6de5c4ae3523df2dc706 36b96caa022742a1b74692b29bd044a7 - 3ae481350a504cbdaf35e18b8753d002 3ae481350a504cbdaf35e18b8753d002] {'desc': 'Invalid credentials'}
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi Traceback (most recent call last):
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 228, in __call__
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi result = method(req, **params)
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/common/controller.py", line 235, in wrapper
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi return f(self, request, filters, **kwargs)
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/controllers.py", line 230, in list_users
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi refs = self.identity_api.list_users(domain_scope=domain, hints=hints)
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/common/manager.py", line 123, in wrapped
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi __ret_val = __f(*args, **kwargs)
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/core.py", line 413, in wrapper
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi return f(self, *args, **kwargs)
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/core.py", line 423, in wrapper
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi return f(self, *args, **kwargs)
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/core.py", line 1027, in list_users
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi ref_list = self._handle_federated_attributes_in_hints(driver, hints)
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/core.py", line 1010, in _handle_federated_attributes_in_hints
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi return driver.list_users(hints)
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/backends/ldap/core.py", line 88, in list_users
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi return self.user.get_all_filtered(hints)
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/backends/ldap/core.py", line 353, in get_all_filtered
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi for user in self.get_all(query, hints)]
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/backends/ldap/core.py", line 345, in get_all
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi hints=hints)
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/backends/ldap/common.py", line 1872, in get_all
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi return super(EnabledEmuMixIn, self).get_all(ldap_filter, hints)
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/backends/ldap/common.py", line 1518, in get_all
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi for x in self._ldap_get_all(hints, ldap_filter)]
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/common/driver_hints.py", line 42, in wrapper
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi return f(self, hints, *args, **kwargs)
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/backends/ldap/common.py", line 1474, in _ldap_get_all
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi with self.get_connection() as conn:
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/backends/ldap/common.py", line 1280, in get_connection
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi conn.simple_bind_s(user, password)
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/backends/ldap/common.py", line 915, in simple_bind_s
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi clientctrls=clientctrls)
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/keystone/identity/backends/ldap/common.py", line 762, in simple_bind_s
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi with self._get_pool_connection() as conn:
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib64/python2.7/contextlib.py", line 17, in __enter__
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi return self.gen.next()
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/ldappool/__init__.py", line 291, in connection
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi conn = self._get_connection(bind, passwd)
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/ldappool/__init__.py", line 244, in _get_connection
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi conn = self._create_connector(bind, passwd)
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi File "/usr/lib/python2.7/site-packages/ldappool/__init__.py", line 221, in _create_connector
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi raise exc
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi INVALID_CREDENTIALS: {'desc': 'Invalid credentials'}
2017-04-20 09:09:08.304 12300 ERROR keystone.common.wsgi
2017-04-20 09:09:13.177 12300 DEBUG keystone.middleware.auth [req-ab1bbb86-490f-44e9-9c34-57c24b6af1fb - - - - -] Authenticating user token process_request /usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py:401

[Boris Bobrov (bbobrov)]

You should fix your keystone.conf. If you set incorrect password for database, or incorrect name for an identity backend, or incorrect value to any other option, nothing is going to work too. I think it is fine that it fails this way.

[Matthew Edmonds (edmondsw)]

I agree with Boris. I don't think there's a better HTTP status code to return, and I don't think we should expose to the caller that the LDAP credentials are invalid... that is something that only an admin should be privy to.

[prashkre (prashkre)]

I agree that we should not reveal to user that LDAP credentials are incorrect, but the error in the logs leaks information to user that keystone is configured with LDAP as identity backend. so I think it's better we handle ldap.INVALID_CREDENTIALS like we do at [0] and give a generic message at [1] something like "unable to connect to identity repository" with 500 error instead of 504.

[0] https://github.com/openstack/keystone/blob/master/keystone/identity/backends/ldap/common.py#L1285

[1]https://github.com/openstack/keystone/blob/master/keystone/exception.py#L598

[Matthew Edmonds (edmondsw)]

That I would agree with.

[Boris Bobrov (bbobrov)]

We are now giving error code 500, and this is the correct code. 504 is Gateway Timeout, means that one server did not receive a timely response from another server. There is a timely response, and the response says that the server is mis configured.

> but the error in the logs leaks information to user that keystone is configured with LDAP as identity backend

Logs are ops-only thing. Users don't see logs, only operators do.

Sorry, i still believe current behavior is exactly what we want.

[Boris Bobrov (bbobrov)]

After talking to Matthew, i've filed https://bugs.launchpad.net/keystone/+bug/1687115

[Matthew Edmonds (edmondsw)]

I don't think this is totally invalid. It's right to return a 500, but I think we could improve the error message that goes with that. I.e., add code to raise LDAPServerConnectionError once the bug Breton opened in comment 6 is addressed.

[Lance Bragstad (lbragstad)]

Agreed, fixing this should be a follow on to the bug in comment #6.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/475929

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/475929
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=91f3a2044bb45c29f9a5f771d21ed1c250116aee
Submitter: Jenkins
Branch: master

commit 91f3a2044bb45c29f9a5f771d21ed1c250116aee
Author: Gage Hugo <email address hidden>
Date: Tue Jun 20 16:13:33 2017 -0500

    Clarify LDAP invalid credentials exception

    This change catches the invalid credentials exception
    when binding with LDAP and responds with a more clear error
    message of "Invalid username or password" instead of just
    supplying the default 500 error message.

    Change-Id: I523dd816333ad76cde8f18ae0fa43040a4478524
    Closes-Bug: #1684994

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/keystone 12.0.0.0b3 development milestone.