yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1636495] [NEW] Failures during db_sync --contract during Mitaka to Newton (live) upgrade

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Jesse Keating <omgjlk@xxxxxxxxxx>
Date: Tue, 25 Oct 2016 12:43:19 -0000
Reply-to: Bug 1636495 <1636495@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

I'm testing the live migration workflows moving from Mitaka to Newton.

In my scenario, I have two keystone server VM, and haproxy in front of
them. Both are running Mitaka and are fully functional. During the
upgrade I run Rally to repeatedly create and then delete users. Rally is
performing these 15 at a time as fast as possible.

During the upgrade, while both are still running Mitaka, I add the
Newton code to a new filesystem path, and I put the Newton version of
configuration in place. I perform db_sync --expand call which is
successful. I then perform a db_sync --migrate call, also successful
(successful means the db_sync command exited 0 and the user
creation/deletion does not experience a failure). Next I perform a
rolling restart of Keystone services, disabling each keystone from the
haproxy before restarting it. Again, success.

However, to finalize the upgrade, there is a db_sync call to --contract.
Both servers are running new Newton code at this point, and rally
continues. During the --contract call some small number of the user
create/delete actions are failing with:

2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters [req-88df4389
-f5f8-4332-a0d7-33eefa20a8ac 243ffe0eeb67454a83b8b0b21525bf3a f2970151809044f2aa
78fc75e43e3dc6 - default default] DBAPIError exception wrapped from (pymysql.err
.InternalError) (1054, u"Unknown column 'password.created_at' in 'field list'")
[SQL: u'SELECT password.id AS password_id, password.local_user_id AS password_lo
cal_user_id, password.password AS password_password, password.created_at AS pass
word_created_at, password.expires_at AS password_expires_at, password.self_servi
ce AS password_self_service, local_user_1.id AS local_user_1_id \nFROM (SELECT u
ser.id AS user_id \nFROM user \nWHERE user.id = %(param_1)s) AS anon_1 INNER JOI
N local_user AS local_user_1 ON anon_1.user_id = local_user_1.user_id INNER JOIN
 password ON local_user_1.id = password.local_user_id ORDER BY local_user_1.id,
password.created_at'] [parameters: {u'param_1': u'90602d52e1904e43bce1c2b82e46f2
6d'}]

2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters Traceback (mo
st recent call last):
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/
openstack/current/keystone/local/lib/python2.7/site-packages/sqlalchemy/engine/b
ase.py", line 1139, in _execute_context
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     context)
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/
openstack/current/keystone/local/lib/python2.7/site-packages/sqlalchemy/engine/d
efault.py", line 450, in do_execute
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     cursor.ex
ecute(statement, parameters)
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/
openstack/current/keystone/local/lib/python2.7/site-packages/pymysql/cursors.py", line 167, in execute
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     result = self._query(query)
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/openstack/current/keystone/local/lib/python2.7/site-packages/pymysql/cursors.py", line 323, in _query
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     conn.query(q)
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/openstack/current/keystone/local/lib/python2.7/site-packages/pymysql/connections.py", line 836, in query
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/openstack/current/keystone/local/lib/python2.7/site-packages/pymysql/connections.py", line 1020, in _read_query_result
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     result.read()
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/openstack/current/keystone/local/lib/python2.7/site-packages/pymysql/connections.py", line 1303, in read
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     first_packet = self.connection._read_packet()
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/openstack/current/keystone/local/lib/python2.7/site-packages/pymysql/connections.py", line 982, in _read_packet
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     packet.check_error()
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/openstack/current/keystone/local/lib/python2.7/site-packages/pymysql/connections.py", line 394, in check_error
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     err.raise_mysql_exception(self._data)
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/openstack/current/keystone/local/lib/python2.7/site-packages/pymysql/err.py", line 120, in raise_mysql_exception
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     _check_mysql_exception(errinfo)
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/openstack/current/keystone/local/lib/python2.7/site-packages/pymysql/err.py", line 115, in _check_mysql_exception
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     raise InternalError(errno, errorvalue)
2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters InternalError: (1054, u"Unknown column 'password.created_at' in 'field list'")


Speaking on IRC, this may be related to https://review.openstack.org/#/c/367025/

** 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/1636495

Title:
  Failures during db_sync --contract during Mitaka to Newton (live)
  upgrade

Status in OpenStack Identity (keystone):
  New

Bug description:
  I'm testing the live migration workflows moving from Mitaka to Newton.

  In my scenario, I have two keystone server VM, and haproxy in front of
  them. Both are running Mitaka and are fully functional. During the
  upgrade I run Rally to repeatedly create and then delete users. Rally
  is performing these 15 at a time as fast as possible.

  During the upgrade, while both are still running Mitaka, I add the
  Newton code to a new filesystem path, and I put the Newton version of
  configuration in place. I perform db_sync --expand call which is
  successful. I then perform a db_sync --migrate call, also successful
  (successful means the db_sync command exited 0 and the user
  creation/deletion does not experience a failure). Next I perform a
  rolling restart of Keystone services, disabling each keystone from the
  haproxy before restarting it. Again, success.

  However, to finalize the upgrade, there is a db_sync call to
  --contract. Both servers are running new Newton code at this point,
  and rally continues. During the --contract call some small number of
  the user create/delete actions are failing with:

  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters [req-88df4389
  -f5f8-4332-a0d7-33eefa20a8ac 243ffe0eeb67454a83b8b0b21525bf3a f2970151809044f2aa
  78fc75e43e3dc6 - default default] DBAPIError exception wrapped from (pymysql.err
  .InternalError) (1054, u"Unknown column 'password.created_at' in 'field list'")
  [SQL: u'SELECT password.id AS password_id, password.local_user_id AS password_lo
  cal_user_id, password.password AS password_password, password.created_at AS pass
  word_created_at, password.expires_at AS password_expires_at, password.self_servi
  ce AS password_self_service, local_user_1.id AS local_user_1_id \nFROM (SELECT u
  ser.id AS user_id \nFROM user \nWHERE user.id = %(param_1)s) AS anon_1 INNER JOI
  N local_user AS local_user_1 ON anon_1.user_id = local_user_1.user_id INNER JOIN
   password ON local_user_1.id = password.local_user_id ORDER BY local_user_1.id,
  password.created_at'] [parameters: {u'param_1': u'90602d52e1904e43bce1c2b82e46f2
  6d'}]

  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters Traceback (mo
  st recent call last):
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/
  openstack/current/keystone/local/lib/python2.7/site-packages/sqlalchemy/engine/b
  ase.py", line 1139, in _execute_context
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     context)
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/
  openstack/current/keystone/local/lib/python2.7/site-packages/sqlalchemy/engine/d
  efault.py", line 450, in do_execute
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     cursor.ex
  ecute(statement, parameters)
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/
  openstack/current/keystone/local/lib/python2.7/site-packages/pymysql/cursors.py", line 167, in execute
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     result = self._query(query)
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/openstack/current/keystone/local/lib/python2.7/site-packages/pymysql/cursors.py", line 323, in _query
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     conn.query(q)
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/openstack/current/keystone/local/lib/python2.7/site-packages/pymysql/connections.py", line 836, in query
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/openstack/current/keystone/local/lib/python2.7/site-packages/pymysql/connections.py", line 1020, in _read_query_result
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     result.read()
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/openstack/current/keystone/local/lib/python2.7/site-packages/pymysql/connections.py", line 1303, in read
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     first_packet = self.connection._read_packet()
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/openstack/current/keystone/local/lib/python2.7/site-packages/pymysql/connections.py", line 982, in _read_packet
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     packet.check_error()
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/openstack/current/keystone/local/lib/python2.7/site-packages/pymysql/connections.py", line 394, in check_error
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     err.raise_mysql_exception(self._data)
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/openstack/current/keystone/local/lib/python2.7/site-packages/pymysql/err.py", line 120, in raise_mysql_exception
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     _check_mysql_exception(errinfo)
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters   File "/opt/openstack/current/keystone/local/lib/python2.7/site-packages/pymysql/err.py", line 115, in _check_mysql_exception
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters     raise InternalError(errno, errorvalue)
  2016-10-25 10:53:22.797 13980 ERROR oslo_db.sqlalchemy.exc_filters InternalError: (1054, u"Unknown column 'password.created_at' in 'field list'")

  
  Speaking on IRC, this may be related to https://review.openstack.org/#/c/367025/

To manage notifications about this bug go to:
https://bugs.launchpad.net/keystone/+bug/1636495/+subscriptions
Follow ups

[Bug 1636495] Re: Failures during db_sync --contract during Mitaka to Newton (live) upgrade
From: Launchpad Bug Tracker, 2019-01-01