Public bug reported:
If two clients attempt to update the same user, they are susceptible to
a race condition in the update_user method of the sql driver:
I ran into this by using multiple (16) clients to run a script that
updates the password for a user:
#!/bin/bash
set -xo
function cleanup {
for key in $( set | awk '{FS="="} /^OS_/ {print $1}' ); do unset $key ;
done
exit
}
trap cleanup SIGINT
USERNAME=test-user
while true
do
PASSWORD=$(uuidgen)
openstack --os-cloud openstack user set --password $PASSWORD $USERNAME
if [ $? -ne 0 ]; then
echo -e "\e[31mFAIL"
cleanup
fi
done
Depending on the number of processes and threads, you will see an HTTP
500 with the following error either in keystone's log or http error
logs:
[Tue Jun 30 16:29:45.241150 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/keystone/identity/core.py", line 1182, in
update_user
[Tue Jun 30 16:29:45.241152 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] ref = self._update_user_with_federated_objects(user,
driver, entity_id)
[Tue Jun 30 16:29:45.241157 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/keystone/identity/core.py", line 1136, in
_update_user_with_federated_objects
[Tue Jun 30 16:29:45.241159 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] user = driver.update_user(entity_id, user)
[Tue Jun 30 16:29:45.241163 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/keystone/common/sql/core.py", line 518, in
wrapper
[Tue Jun 30 16:29:45.241166 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] return method(*args, **kwargs)
[Tue Jun 30 16:29:45.241170 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/keystone/identity/backends/sql.py", line 239,
in update_user
[Tue Jun 30 16:29:45.241172 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] user_ref.to_dict(include_extra_dict=True))
[Tue Jun 30 16:29:45.241176 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File "/usr/lib64/python3.6/contextlib.py", line 88, in
__exit__
[Tue Jun 30 16:29:45.241179 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] next(self.gen)
[Tue Jun 30 16:29:45.241183 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/oslo_db/sqlalchemy/enginefacade.py", line
1064, in _transaction_scope
[Tue Jun 30 16:29:45.241185 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] yield resource
[Tue Jun 30 16:29:45.241189 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File "/usr/lib64/python3.6/contextlib.py", line 88, in
__exit__
[Tue Jun 30 16:29:45.241192 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] next(self.gen)
[Tue Jun 30 16:29:45.241195 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/oslo_db/sqlalchemy/enginefacade.py", line
666, in _session
[Tue Jun 30 16:29:45.241198 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] self.session.rollback()
[Tue Jun 30 16:29:45.241202 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/oslo_utils/excutils.py", line 220, in __exit__
[Tue Jun 30 16:29:45.241204 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] self.force_reraise()
[Tue Jun 30 16:29:45.241208 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/oslo_utils/excutils.py", line 196, in
force_reraise
[Tue Jun 30 16:29:45.241212 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] six.reraise(self.type_, self.value, self.tb)
[Tue Jun 30 16:29:45.241216 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File "/usr/lib/python3.6/site-packages/six.py", line
703, in reraise
[Tue Jun 30 16:29:45.241219 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] raise value
[Tue Jun 30 16:29:45.241223 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/oslo_db/sqlalchemy/enginefacade.py", line
663, in _session
[Tue Jun 30 16:29:45.241225 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] self._end_session_transaction(self.session)
[Tue Jun 30 16:29:45.241229 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/oslo_db/sqlalchemy/enginefacade.py", line
691, in _end_session_transaction
[Tue Jun 30 16:29:45.241232 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] session.commit()
[Tue Jun 30 16:29:45.241236 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 1026, in
commit
[Tue Jun 30 16:29:45.241238 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] self.transaction.commit()
[Tue Jun 30 16:29:45.241242 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 493, in
commit
[Tue Jun 30 16:29:45.241245 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] self._prepare_impl()
[Tue Jun 30 16:29:45.241248 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 472, in
_prepare_impl
[Tue Jun 30 16:29:45.241251 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] self.session.flush()
[Tue Jun 30 16:29:45.241255 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 2451, in
flush
[Tue Jun 30 16:29:45.241257 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] self._flush(objects)
[Tue Jun 30 16:29:45.241261 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 2589, in
_flush
[Tue Jun 30 16:29:45.241264 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] transaction.rollback(_capture_exception=True)
[Tue Jun 30 16:29:45.241267 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/util/langhelpers.py", line 68,
in __exit__
[Tue Jun 30 16:29:45.241270 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] compat.reraise(exc_type, exc_value, exc_tb)
[Tue Jun 30 16:29:45.241274 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 129, in
reraise
[Tue Jun 30 16:29:45.241276 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] raise value
[Tue Jun 30 16:29:45.241280 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 2549, in
_flush
[Tue Jun 30 16:29:45.241283 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] flush_context.execute()
[Tue Jun 30 16:29:45.241286 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/unitofwork.py", line 422, in
execute
[Tue Jun 30 16:29:45.241289 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] rec.execute(self)
[Tue Jun 30 16:29:45.241293 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/unitofwork.py", line 589, in
execute
[Tue Jun 30 16:29:45.241295 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] uow,
[Tue Jun 30 16:29:45.241299 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/persistence.py", line 236,
in save_obj
[Tue Jun 30 16:29:45.241303 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] update,
[Tue Jun 30 16:29:45.241307 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/persistence.py", line 1011,
in _emit_update_statements
[Tue Jun 30 16:29:45.241310 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] % (table.description, len(records), rows)
[Tue Jun 30 16:29:45.241325 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] sqlalchemy.orm.exc.StaleDataError: UPDATE statement on
table 'password' expected to update 1 row(s); 0 were matched.
[0] http://paste.openstack.org/show/795389/
** Affects: keystone
Importance: Undecided
Status: New
--
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Identity (keystone).
https://bugs.launchpad.net/bugs/1885753
Title:
Stale data causes keystone to raise an HTTP 500 during update updates
Status in OpenStack Identity (keystone):
New
Bug description:
If two clients attempt to update the same user, they are susceptible
to a race condition in the update_user method of the sql driver:
I ran into this by using multiple (16) clients to run a script that
updates the password for a user:
#!/bin/bash
set -xo
function cleanup {
for key in $( set | awk '{FS="="} /^OS_/ {print $1}' ); do unset $key ;
done
exit
}
trap cleanup SIGINT
USERNAME=test-user
while true
do
PASSWORD=$(uuidgen)
openstack --os-cloud openstack user set --password $PASSWORD $USERNAME
if [ $? -ne 0 ]; then
echo -e "\e[31mFAIL"
cleanup
fi
done
Depending on the number of processes and threads, you will see an HTTP
500 with the following error either in keystone's log or http error
logs:
[Tue Jun 30 16:29:45.241150 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/keystone/identity/core.py", line 1182, in
update_user
[Tue Jun 30 16:29:45.241152 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] ref = self._update_user_with_federated_objects(user,
driver, entity_id)
[Tue Jun 30 16:29:45.241157 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/keystone/identity/core.py", line 1136, in
_update_user_with_federated_objects
[Tue Jun 30 16:29:45.241159 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] user = driver.update_user(entity_id, user)
[Tue Jun 30 16:29:45.241163 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/keystone/common/sql/core.py", line 518, in
wrapper
[Tue Jun 30 16:29:45.241166 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] return method(*args, **kwargs)
[Tue Jun 30 16:29:45.241170 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/keystone/identity/backends/sql.py", line 239,
in update_user
[Tue Jun 30 16:29:45.241172 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] user_ref.to_dict(include_extra_dict=True))
[Tue Jun 30 16:29:45.241176 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File "/usr/lib64/python3.6/contextlib.py", line 88, in
__exit__
[Tue Jun 30 16:29:45.241179 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] next(self.gen)
[Tue Jun 30 16:29:45.241183 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/oslo_db/sqlalchemy/enginefacade.py", line
1064, in _transaction_scope
[Tue Jun 30 16:29:45.241185 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] yield resource
[Tue Jun 30 16:29:45.241189 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File "/usr/lib64/python3.6/contextlib.py", line 88, in
__exit__
[Tue Jun 30 16:29:45.241192 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] next(self.gen)
[Tue Jun 30 16:29:45.241195 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/oslo_db/sqlalchemy/enginefacade.py", line
666, in _session
[Tue Jun 30 16:29:45.241198 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] self.session.rollback()
[Tue Jun 30 16:29:45.241202 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/oslo_utils/excutils.py", line 220, in __exit__
[Tue Jun 30 16:29:45.241204 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] self.force_reraise()
[Tue Jun 30 16:29:45.241208 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/oslo_utils/excutils.py", line 196, in
force_reraise
[Tue Jun 30 16:29:45.241212 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] six.reraise(self.type_, self.value, self.tb)
[Tue Jun 30 16:29:45.241216 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File "/usr/lib/python3.6/site-packages/six.py", line
703, in reraise
[Tue Jun 30 16:29:45.241219 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] raise value
[Tue Jun 30 16:29:45.241223 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/oslo_db/sqlalchemy/enginefacade.py", line
663, in _session
[Tue Jun 30 16:29:45.241225 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] self._end_session_transaction(self.session)
[Tue Jun 30 16:29:45.241229 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib/python3.6/site-packages/oslo_db/sqlalchemy/enginefacade.py", line
691, in _end_session_transaction
[Tue Jun 30 16:29:45.241232 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] session.commit()
[Tue Jun 30 16:29:45.241236 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 1026, in
commit
[Tue Jun 30 16:29:45.241238 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] self.transaction.commit()
[Tue Jun 30 16:29:45.241242 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 493, in
commit
[Tue Jun 30 16:29:45.241245 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] self._prepare_impl()
[Tue Jun 30 16:29:45.241248 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 472, in
_prepare_impl
[Tue Jun 30 16:29:45.241251 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] self.session.flush()
[Tue Jun 30 16:29:45.241255 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 2451, in
flush
[Tue Jun 30 16:29:45.241257 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] self._flush(objects)
[Tue Jun 30 16:29:45.241261 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 2589, in
_flush
[Tue Jun 30 16:29:45.241264 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] transaction.rollback(_capture_exception=True)
[Tue Jun 30 16:29:45.241267 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/util/langhelpers.py", line 68,
in __exit__
[Tue Jun 30 16:29:45.241270 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] compat.reraise(exc_type, exc_value, exc_tb)
[Tue Jun 30 16:29:45.241274 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 129, in
reraise
[Tue Jun 30 16:29:45.241276 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] raise value
[Tue Jun 30 16:29:45.241280 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/session.py", line 2549, in
_flush
[Tue Jun 30 16:29:45.241283 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] flush_context.execute()
[Tue Jun 30 16:29:45.241286 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/unitofwork.py", line 422, in
execute
[Tue Jun 30 16:29:45.241289 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] rec.execute(self)
[Tue Jun 30 16:29:45.241293 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/unitofwork.py", line 589, in
execute
[Tue Jun 30 16:29:45.241295 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] uow,
[Tue Jun 30 16:29:45.241299 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/persistence.py", line 236,
in save_obj
[Tue Jun 30 16:29:45.241303 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] update,
[Tue Jun 30 16:29:45.241307 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] File
"/usr/lib64/python3.6/site-packages/sqlalchemy/orm/persistence.py", line 1011,
in _emit_update_statements
[Tue Jun 30 16:29:45.241310 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] % (table.description, len(records), rows)
[Tue Jun 30 16:29:45.241325 2020] [wsgi:error] [pid 33] [remote
192.168.24.11:56242] sqlalchemy.orm.exc.StaleDataError: UPDATE statement on
table 'password' expected to update 1 row(s); 0 were matched.
[0] http://paste.openstack.org/show/795389/
To manage notifications about this bug go to:
https://bugs.launchpad.net/keystone/+bug/1885753/+subscriptions
--
Mailing list: https://launchpad.net/~yahoo-eng-team
Post to : yahoo-eng-team@lists.launchpad.net
Unsubscribe : https://launchpad.net/~yahoo-eng-team
More help : https://help.launchpad.net/ListHelp
