yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1885753] [NEW] Stale data causes keystone to raise an HTTP 500 during update updates

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Lance Bragstad <1885753@xxxxxxxxxxxxxxxxxx>
Date: Tue, 30 Jun 2020 16:37:58 -0000
Reply-to: Bug 1885753 <1885753@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
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
Follow ups

[Bug 1885753] Re: Stale data causes keystone to raise an HTTP 500 during user password updates
From: David Wilde, 2023-02-01