OpenStack Identity (keystone)

keystone returns 500 on password change

Bug #1714937 reported by Dr. Jens Harbott
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Identity (keystone)
Invalid
Low
Vishakha Agarwal
OpenStack Identity (keystone) queens-rc1

Bug Description

$ openstack user set --password-prompt demo
User Password:
Repeat User Password:
An unexpected error prevented the server from fulfilling your request. (HTTP 500) (Request-ID: req-175ea0bf-02d3-4d73-a3ca-662612c36543)
$

Although there is an error, the password has been changed, though.

Traceback from keystone log:

Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: DEBUG keystone.common.authorization [None req-175ea0bf-02d3-4d73-a3ca-662612c36543 None None] RBAC: Authorizing identity:update_user(user_id=30f37144f2494fd5b46d97acb72de22c, user={u'password': u'***', u'enabl
ed': True}) {{(pid=1804) _build_policy_check_credentials /opt/stack/keystone/keystone/common/authorization.py:137}}
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: DEBUG keystone.policy.backends.rules [None req-175ea0bf-02d3-4d73-a3ca-662612c36543 None None] enforce identity:update_user: {'is_delegated_auth': False, 'access_token_id': None, 'user_id': u'd55b3e8a3e084ba6a
061b73c33112b05', 'roles': [u'admin'], 'user_domain_id': u'default', 'consumer_id': None, 'trustee_id': None, 'is_domain': False, 'is_admin_project': True, 'trustor_id': None, 'token': <KeystoneToken (audit_id=eW1jzYlhS7q_7vZMyN-T_A, audit_chain_id=eW1jzYlhS7q_7vZMyN-T_A)
at 0x7f7dc22b8990>, 'project_id': u'a42a75e7ca804a6288f3eb51c0fd9eb7', 'trust_id': None, 'project_domain_id': u'default'} {{(pid=1804) enforce /opt/stack/keystone/keystone/policy/backends/rules.py:33}}
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: DEBUG oslo_policy.policy [None req-175ea0bf-02d3-4d73-a3ca-662612c36543 None None] The policy file policy.json could not be found. {{(pid=1804) load_rules /usr/local/lib/python2.7/dist-packages/oslo_policy/pol
icy.py:532}}
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: DEBUG keystone.common.authorization [None req-175ea0bf-02d3-4d73-a3ca-662612c36543 None None] RBAC: Authorization granted {{(pid=1804) check_policy /opt/stack/keystone/keystone/common/authorization.py:240}}
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: DEBUG keystone.notifications [None req-175ea0bf-02d3-4d73-a3ca-662612c36543 None None] Invoking callback _user_callback for event identity invalidate_user_tokens internal for {'resource_info': u'30f37144f2494f
d5b46d97acb72de22c'} {{(pid=1804) notify_event_callbacks /opt/stack/keystone/keystone/notifications.py:297}}
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: DEBUG keystone.notifications [None req-175ea0bf-02d3-4d73-a3ca-662612c36543 None None] Invoking callback _delete_user_tokens_callback for event identity invalidate_user_tokens internal for {'resource_info': u'
30f37144f2494fd5b46d97acb72de22c'} {{(pid=1804) notify_event_callbacks /opt/stack/keystone/keystone/notifications.py:297}}
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: WARNING stevedore.named [None req-175ea0bf-02d3-4d73-a3ca-662612c36543 None None] Could not load blah
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi [None req-175ea0bf-02d3-4d73-a3ca-662612c36543 None None] (u'Unable to find %(name)r driver in %(namespace)r.', {'namespace': 'keystone.token.persistence', 'name': 'blah'}): ImportEr
ror: (u'Unable to find %(name)r driver in %(namespace)r.', {'namespace': 'keystone.token.persistence', 'name': 'blah'})
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi Traceback (most recent call last):
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/common/wsgi.py", line 228, in __call__
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi result = method(req, **params)
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/common/controller.py", line 94, in inner
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi return f(self, request, *args, **kwargs)
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/identity/controllers.py", line 255, in update_user
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi return self._update_user(request, user_id, user)
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/identity/controllers.py", line 248, in _update_user
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi user_id, user, initiator=request.audit_initiator
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/common/manager.py", line 110, in wrapped
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi __ret_val = __f(*args, **kwargs)
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/identity/core.py", line 414, in wrapper
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi return f(self, *args, **kwargs)
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/identity/core.py", line 424, in wrapper
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi return f(self, *args, **kwargs)
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/identity/core.py", line 1106, in update_user
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi self.emit_invalidate_user_token_persistence(user_id)
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/common/manager.py", line 110, in wrapped
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi __ret_val = __f(*args, **kwargs)
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/identity/core.py", line 1275, in emit_invalidate_user_token_persistence
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi notifications.INVALIDATE_USER_TOKEN_PERSISTENCE, user_id
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/notifications.py", line 178, in internal
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi public, reason)
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/notifications.py", line 119, in _emit
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi public=public)
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/notifications.py", line 405, in _send_notification
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi notify_event_callbacks(SERVICE, resource_type, operation, payload)
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/notifications.py", line 298, in notify_event_callbacks
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi cb(service, resource_type, operation, payload)
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/token/provider.py", line 297, in _delete_user_tokens_callback
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi self._persistence.delete_tokens_for_user(user_id)
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/token/provider.py", line 116, in _persistence
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi self._persistence_manager = persistence.PersistenceManager()
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/common/dependency.py", line 155, in wrapper
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi self.__wrapped_init__(*args, **kwargs)
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/token/persistence/core.py", line 50, in __init__
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi super(PersistenceManager, self).__init__(CONF.token.driver)
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/common/manager.py", line 169, in __init__
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi self.driver = load_driver(self.driver_namespace, driver_name)
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi File "/opt/stack/keystone/keystone/common/manager.py", line 75, in load_driver
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi raise ImportError(msg, {'name': driver_name, 'namespace': namespace})
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi ImportError: (u'Unable to find %(name)r driver in %(namespace)r.', {'namespace': 'keystone.token.persistence', 'name': 'blah'})
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: ERROR keystone.common.wsgi
Sep 04 11:36:44 jh-devstack-02 <email address hidden>[1797]: [pid: 1804|app: 0|req: 4/7] 192.168.0.23 () {72 vars in 1467 bytes} [Mon Sep 4 11:36:44 2017] PATCH /identity/v3/users/30f37144f2494fd5b46d97acb72de22c => generated 143 bytes in 225 msecs (HTTP/1.1 500) 5 hea
ders in 196 bytes (2 switches on core 0)

Turns out that in contrast to the comments in keystone.conf, the [token]driver setting is not ignored when changing passwords. All other actions seem to be working fine, though.

[token]
provider = fernet
# DEPRECATED: Entry point for the token persistence backend driver in the
# `keystone.token.persistence` namespace. Keystone provides the `sql` driver.
# The `sql` option (default) depends on the options in your `[database]`
# section. If you're using the `fernet` `[token] provider`, this backend will
# not be utilized to persist tokens at all. (string value)
# This option is deprecated for removal since P.
# Its value may be silently ignored in the future.
#driver = sql
driver = blah

Originally noticed this when I still had an old "driver = memcache_pool" option in there after upgrade from Newton to Ocata, but the issue seems still to be present in master.

Revision history for this message
Gage Hugo (gagehugo) wrote :

I can recreate this:

http://paste.openstack.org/show/620669/

Password for pwdtest user was updated in the database.

Changed in keystone:
status: New → Confirmed
Revision history for this message
Lance Bragstad (lbragstad) wrote :

It seems that the implementation of keystone token persistence layer could be improved to be *completely* decoupled when using fernet. Then the documentation string will be true.

Is there anything else we can improve while we making this change?

Changed in keystone:
importance: Undecided → Low
Vishakha Agarwal (vishakha.agarwal)
Changed in keystone:
assignee: nobody → Vishakha Agarwal (vishakha.agarwal)
Revision history for this message
Dr. Jens Harbott (j-harbott) wrote :

The behaviour has changed a bit in master, keystone now crashes immediately with a broken setting like "token.driver = blah".

As a sidenode, devstack still seems to be setting "driver = sql" explicitly, would be nice to get rid of that in order to avoid the deprecation warnings.

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to keystone (master)

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

Changed in keystone:
status: Confirmed → In Progress
Lance Bragstad (lbragstad)
Changed in keystone:
milestone: none → queens-rc1
Revision history for this message
Lance Bragstad (lbragstad) wrote :

We're going to have to cut rc1 without this fix. If we get the fix landed before final release we can backport it and cut rc2.

Revision history for this message
Lance Bragstad (lbragstad) wrote :

I was able to verify comment #3. Keystone fails to start if not configured with a proper token storage driver. This seems reasonable since it's consistent when loading other backends or plugins.

I don't think there is anything specific to fix in keystone here. We're planning on removing the UUID token provider and the sql token driver in Rocky. Moving forward, people can still provide their own token providers, but they'll need to include the token storage bit in the token provider. Previously, keystone would treat token providers and token drivers differently. Token providers simply issued a token and token drivers were responsible for storing it if the provider required persistence. Since we've simplified a lot of the token provider API with non-persistent formats, it is arguable simpler to just have providers that require storage deal with it separately, rather than provide hooks in the token provider API to persist things based on properties of the token provider.

Hopefully this helps clear things up. If you are implementing a token provider and would like help adding the token storage logic, please let us know.

Lance Bragstad (lbragstad)
Changed in keystone:
status: In Progress → Invalid
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Change abandoned on keystone (master)

Change abandoned by Morgan Fainberg (<email address hidden>) on branch: master
Review: https://review.openstack.org/537322
Reason: See comment.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.