db_sync is not called during action managed upgrade from mitaka to newton

[Nobuto Murata]

After trying an upgrade from mitaka to newton using Juju actions, /var/log/keystone/keystone.log is full of "Unknown column" DB error. After executing `keystone-manage db_sync` on one unit, the keystone service becomes working again. db_sync is missing on action managed upgrade?

ERROR DBAPIError exception wrapped from (pymysql.err.InternalError) (1054, u"Unknown column 'user.created_at' in 'field list'") [SQL: u'SELECT user.enabled AS user_enabled, user.id AS user_id, user.extra AS user_extra, user.default_project_id AS user_default_project_id, user.created_at AS user_created_at, user.last_active_at AS user_last_active_at \nFROM user INNER JOIN local_user ON user.id = local_user.user_id \nWHERE local_user.name = %(name_1)s AND local_user.domain_id = %(domain_id_1)s'] [parameters: {u'domain_id_1': 'default', u'name_1': u'admin'}]
ERROR DBAPIError exception wrapped from (pymysql.err.InternalError) (1054, u"Unknown column 'user.created_at' in 'field list'") [SQL: u'SELECT user.enabled AS user_enabled, user.id AS user_id, user.extra AS user_extra, user.default_project_id AS user_default_project_id, user.created_at AS user_created_at, user.last_active_at AS user_last_active_at \nFROM user INNER JOIN local_user ON user.id = local_user.user_id \nWHERE local_user.name = %(name_1)s AND local_user.domain_id = %(domain_id_1)s'] [parameters: {u'domain_id_1': u'default', u'name_1': u'ceilometer'}]
ERROR DBAPIError exception wrapped from (pymysql.err.InternalError) (1054, u"Unknown column 'user.created_at' in 'field list'") [SQL: u'SELECT user.enabled AS user_enabled, user.id AS user_id, user.extra AS user_extra, user.default_project_id AS user_default_project_id, user.created_at AS user_created_at, user.last_active_at AS user_last_active_at \nFROM user INNER JOIN local_user ON user.id = local_user.user_id \nWHERE local_user.name = %(name_1)s AND local_user.domain_id = %(domain_id_1)s'] [parameters: {u'domain_id_1': u'default', u'name_1': u'neutron'}]
ERROR DBAPIError exception wrapped from (pymysql.err.InternalError) (1054, u"Unknown column 'user.created_at' in 'field list'") [SQL: u'SELECT user.enabled AS user_enabled, user.id AS user_id, user.extra AS user_extra, user.default_project_id AS user_default_project_id, user.created_at AS user_created_at, user.last_active_at AS user_last_active_at \nFROM user INNER JOIN local_user ON user.id = local_user.user_id \nWHERE local_user.name = %(name_1)s AND local_user.domain_id = %(domain_id_1)s'] [parameters: {u'domain_id_1': u'default', u'name_1': u'nova'}]
u"Unknown column 'user.created_at' in 'field list'") [SQL: u'SELECT user.enabled AS user_enabled, user.id AS user_id, user.extra AS user_extra, user.default_project_id AS user_default_project_id, user.created_at AS user_created_at, user.last_active_at AS user_last_active_at \nFROM user INNER JOIN local_user ON user.id = local_user.user_id \nWHERE local_user.name = %(name_1)s AND local_user.domain_id = %(domain_id_1)s'] [parameters: {u'domain_id_1': 'default', u'name_1': u'admin'}]
u"Unknown column 'user.created_at' in 'field list'") [SQL: u'SELECT user.enabled AS user_enabled, user.id AS user_id, user.extra AS user_extra, user.default_project_id AS user_default_project_id, user.created_at AS user_created_at, user.last_active_at AS user_last_active_at \nFROM user INNER JOIN local_user ON user.id = local_user.user_id \nWHERE local_user.name = %(name_1)s AND local_user.domain_id = %(domain_id_1)s'] [parameters: {u'domain_id_1': u'default', u'name_1': u'ceilometer'}]
u"Unknown column 'user.created_at' in 'field list'") [SQL: u'SELECT user.enabled AS user_enabled, user.id AS user_id, user.extra AS user_extra, user.default_project_id AS user_default_project_id, user.created_at AS user_created_at, user.last_active_at AS user_last_active_at \nFROM user INNER JOIN local_user ON user.id = local_user.user_id \nWHERE local_user.name = %(name_1)s AND local_user.domain_id = %(domain_id_1)s'] [parameters: {u'domain_id_1': u'default', u'name_1': u'neutron'}]
u"Unknown column 'user.created_at' in 'field list'") [SQL: u'SELECT user.enabled AS user_enabled, user.id AS user_id, user.extra AS user_extra, user.default_project_id AS user_default_project_id, user.created_at AS user_created_at, user.last_active_at AS user_last_active_at \nFROM user INNER JOIN local_user ON user.id = local_user.user_id \nWHERE local_user.name = %(name_1)s AND local_user.domain_id = %(domain_id_1)s'] [parameters: {u'domain_id_1': u'default', u'name_1': u'nova'}]

[Nobuto Murata (nobuto)]

I could not reproduce this issue with my laptop environment. I can see "Migrating the keystone database" during the upgrade.

$ juju run-action keystone/0 openstack-upgrade
$ juju show-action-output 309d18e8-eac8-4819-8b9e-f2fa12116c45
results:
  outcome: success, upgrade completed.
status: completed
timing:
  completed: 2016-12-02 21:11:44 +0000 UTC
  enqueued: 2016-12-02 21:10:08 +0000 UTC
  started: 2016-12-02 21:10:09 +0000 UTC

$ juju debug-log --replay | grep -i database
...
unit-keystone-0: 22:11:03 INFO unit.keystone/0.juju-log Migrating the keystone database.
unit-keystone-0: 22:11:35 DEBUG unit.keystone/0.juju-log Database is initialised

[Felipe Reyes (freyes)]

I could artificially reproduce this issue -> http://pastebin.ubuntu.com/23585380/

Steps:

1) check which unit is the leader, e.g. keystone/0
2) run the upgrade action in /1 and /2
3) Once 2) is done, shutdown /0 unit to force juju to choose a new leader
4) run the upgrade action in /0

So this situation may happen in the field, if for any reason juju decides to choose as a leader a unit where the migration was already run, then the db migrations won't ever be run[0]

[0] https://github.com/openstack/charm-keystone/blob/master/hooks/keystone_utils.py#L541

[Nobuto Murata (nobuto)]

@Felipe,

I'm not sure I fully understand. In that situation, is running openstack-upgrade action not on the leader unit just first an operational error? Or is it possible to save that kind of pitfalls with charms by running db_sync on any units as db_sync is idempotent?

[Felipe Reyes (freyes)]

> In that situation, is running openstack-upgrade action not on the leader unit just first an operational error?

The leader is the first unit that should be upgraded[0], otherwise we may end up in the scenario I previously described.

> Or is it possible to save that kind of pitfalls with charms by running db_sync on any units as db_sync is idempotent?

db_sync is idempotent, but we need to make sure that the units don't run the migrations concurrently, in the absence of a locking mechanism, the leader is expected to run db_sync.

[0] https://github.com/openstack-charmers/openstack-charms-demos/blob/master/nyc/do-upgrade.py#L312

[Launchpad Janitor (janitor)]

[Expired for OpenStack keystone charm because there has been no activity for 60 days.]