cannot create (or set) a user with no password

[Rabi Mishra]

It seems the gate is broken with AutoScalingSignaltest faling.
I suspect this is due to the recent keystone change https://review.openstack.org/#/c/314284/

keystone error traceback:

2016-06-24 03:34:02.273 8966 ERROR oslo_db.sqlalchemy.exc_filters [req-99ad876c-6f1f-4742-8dcf-52d461fa0c9f 16a1dbfadccd44a3813a0e097a61ac25 - a08006a9c7c84f5ca7afaed59ac8e7a5 a08006a9c7c84f5ca7afaed59ac8e7a5 -] DBAPIError exception wrapped from (pymysql.err.IntegrityError) (1048, u"Column 'password' cannot be null") [SQL: u'INSERT INTO password (local_user_id, password, created_at, expires_at) VALUES (%(local_user_id)s, %(password)s, %(created_at)s, %(expires_at)s)'] [parameters: {'local_user_id': 36, 'password': None, 'created_at': datetime.datetime(2016, 6, 24, 3, 34, 2, 269022), 'expires_at': None}]

heat engine traceback:

http://logs.openstack.org/76/333676/1/check/gate-heat-dsvm-functional-orig-mysql-lbaasv2/516afaa/logs/screen-h-eng.txt.gz#_2016-06-24_03_34_02_280

b2c8-e27e2a774982]
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource Traceback (most recent call last):
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource File "/opt/stack/new/heat/heat/engine/resource.py", line 716, in _action_recorder
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource yield
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource File "/opt/stack/new/heat/heat/engine/resource.py", line 796, in _do_action
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource yield self.action_handler_task(action, args=handler_args)
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource File "/opt/stack/new/heat/heat/engine/scheduler.py", line 312, in wrapper
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource step = next(subtask)
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource File "/opt/stack/new/heat/heat/engine/resource.py", line 759, in action_handler_task
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource handler_data = handler(*args)
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource File "/opt/stack/new/heat/heat/engine/resources/stack_user.py", line 110, in handle_suspend
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource user_id=user_id, project_id=self.stack.stack_user_project_id)
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource File "/opt/stack/new/heat/heat/engine/clients/os/keystone/heat_keystoneclient.py", line 528, in disable_stack_domain_user
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource self.domain_admin_client.users.update(user=user_id, enabled=False)
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource File "/usr/local/lib/python2.7/dist-packages/debtcollector/renames.py", line 43, in decorator
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource return wrapped(*args, **kwargs)
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource File "/usr/local/lib/python2.7/dist-packages/positional/__init__.py", line 101, in inner
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource return wrapped(*args, **kwargs)
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource File "/usr/local/lib/python2.7/dist-packages/keystoneclient/v3/users.py", line 209, in update
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource log=False)
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource File "/usr/local/lib/python2.7/dist-packages/keystoneclient/base.py", line 227, in _update
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource **kwargs)
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 190, in patch
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource return self.request(url, 'PATCH', **kwargs)
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 335, in request
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource resp = super(LegacyJsonAdapter, self).request(*args, **kwargs)
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 103, in request
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource return self.session.request(url, method, **kwargs)
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource File "/usr/local/lib/python2.7/dist-packages/positional/__init__.py", line 101, in inner
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource return wrapped(*args, **kwargs)
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource File "/usr/local/lib/python2.7/dist-packages/keystoneauth1/session.py", line 487, in request
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource raise exceptions.from_response(resp, method, url)
2016-06-24 03:34:02.280 4863 ERROR heat.engine.resource InternalServerError: An unexpected error prevented the server from fulfilling your request. (HTTP 500) (Request-ID: req-99ad876c-6f1f-4742-8dcf-52d461fa0c9f)

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/333779

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/333779
Committed: https://git.openstack.org/cgit/openstack/heat/commit/?id=7ea3e68eb969901838293a2cbcae6024451a20d9
Submitter: Jenkins
Branch: master

commit 7ea3e68eb969901838293a2cbcae6024451a20d9
Author: Rabi Mishra <email address hidden>
Date: Fri Jun 24 12:24:29 2016 +0530

    Skip AutoScalingSignalTest.test_signal_during_suspend

    This seems to be broken by[1]

    [1] https://review.openstack.org/#/c/314284

    Change-Id: I00e439cc0b94b4ed2d88ddfbb91568e804313ae5
    Related-Bug: #1595819

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/333854

[Steve Martinelli (stevemar)]

So we definitely merged a migration that affected the password table. Looking at https://review.openstack.org/#/c/314284/ -- I don't see anything that could have affected the code that allows for Null passwords when creating/updating a user, but the exception "Column 'password' cannot be null" clearly indicates such.

What I do find suspicious is the time stamps in the test failure and the keystone error:

The keystone error is at 03:34:02.273 : http://logs.openstack.org/76/333676/1/check/gate-heat-dsvm-functional-orig-mysql-lbaasv2/516afaa/logs/apache/keystone.txt.gz?level=ERROR#_2016-06-24_03_34_02_273
Similar to the heat error 03:34:02:280 : http://logs.openstack.org/76/333676/1/check/gate-heat-dsvm-functional-orig-mysql-lbaasv2/516afaa/logs/screen-h-eng.txt.gz?level=ERROR#_2016-06-24_03_34_02_280

But the failed test is 20 minutes later: 03:54:09:180 http://logs.openstack.org/76/333676/1/check/gate-heat-dsvm-functional-orig-mysql-lbaasv2/516afaa/console.html#_2016-06-24_03_54_09_180402

This may be unrelated but I wanted to point it out anyway.

[Rabi Mishra (rabi)]

The test has timed out after 20mins as we did not handle the error from keystone well and wait for scaling group resource to go to SUSPEND_COMPLETE/FAILED which never happens. I've submitted a related patch for this bug to fix that.

[Steve Martinelli (stevemar)]

Gotcha. Thanks for the info.

The keystone error is easily re-creatable on a keystone only setup by just doing:

  $ openstack user create tempo --debug

In the keystone logs:

2016-06-24 05:08:18.701 76356 ERROR oslo_db.sqlalchemy.exc_filters [req-10b0b459-2bb6-4e19-b70a-92147a90a6bd c6de05b4530848748c977c79c4364a0b 9ece489efd7d4146a9a4aa7e81663e40 - default default] DBAPIError exception wrapped from (pymysql.err.IntegrityError) (1048, u"Column 'password' cannot be null") [SQL: u'INSERT INTO password (local_user_id, password, created_at, expires_at) VALUES (%(local_user_id)s, %(password)s, %(created_at)s, %(expires_at)s)'] [parameters: {'local_user_id': 5, 'password': None, 'created_at': datetime.datetime(2016, 6, 24, 12, 8, 18, 696911), 'expires_at': None}]
2016-06-24 05:08:18.701 76356 TRACE oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
2016-06-24 05:08:18.701 76356 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context
2016-06-24 05:08:18.701 76356 TRACE oslo_db.sqlalchemy.exc_filters context)
2016-06-24 05:08:18.701 76356 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 450, in do_execute
2016-06-24 05:08:18.701 76356 TRACE oslo_db.sqlalchemy.exc_filters cursor.execute(statement, parameters)
2016-06-24 05:08:18.701 76356 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 161, in execute
2016-06-24 05:08:18.701 76356 TRACE oslo_db.sqlalchemy.exc_filters result = self._query(query)
2016-06-24 05:08:18.701 76356 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 317, in _query
2016-06-24 05:08:18.701 76356 TRACE oslo_db.sqlalchemy.exc_filters conn.query(q)
2016-06-24 05:08:18.701 76356 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 835, in query
2016-06-24 05:08:18.701 76356 TRACE oslo_db.sqlalchemy.exc_filters self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2016-06-24 05:08:18.701 76356 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1019, in _read_query_result
2016-06-24 05:08:18.701 76356 TRACE oslo_db.sqlalchemy.exc_filters result.read()
2016-06-24 05:08:18.701 76356 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1302, in read
2016-06-24 05:08:18.701 76356 TRACE oslo_db.sqlalchemy.exc_filters first_packet = self.connection._read_packet()
2016-06-24 05:08:18.701 76356 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 981, in _read_packet
2016-06-24 05:08:18.701 76356 TRACE oslo_db.sqlalchemy.exc_filters packet.check_error()
2016-06-24 05:08:18.701 76356 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 393, in check_error
2016-06-24 05:08:18.701 76356 TRACE oslo_db.sqlalch...

[Steve Martinelli (stevemar)]

From master:

mysql> describe password;
+---------------+--------------+------+-----+---------+----------------+
| Field | Type | Null | Key | Default | Extra |
+---------------+--------------+------+-----+---------+----------------+
| id | int(11) | NO | PRI | NULL | auto_increment |
| local_user_id | int(11) | NO | MUL | NULL | |
| password | varchar(128) | NO | | NULL | |
| created_at | datetime | YES | | NULL | |
| expires_at | datetime | YES | | NULL | |
+---------------+--------------+------+-----+---------+----------------+
5 rows in set (0.00 sec)

[Steve Martinelli (stevemar)]

from tag 10.0.0.0b1

mysql> describe password;
+---------------+--------------+------+-----+---------+----------------+
| Field | Type | Null | Key | Default | Extra |
+---------------+--------------+------+-----+---------+----------------+
| id | int(11) | NO | PRI | NULL | auto_increment |
| local_user_id | int(11) | NO | MUL | NULL | |
| password | varchar(128) | NO | | NULL | |
+---------------+--------------+------+-----+---------+----------------+
3 rows in set (0.00 sec)

[OpenStack Infra (hudson-openstack)]

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

[Steve Martinelli (stevemar)]

Tested on newton-1 and i am able to create a user with no password, so we're OK on that front.

[Samuel de Medeiros Queiroz (samueldmq)]

The issue is that migration 90 [1] makes password column nullable=False, while the model sets it to nullable=True (which is the default) [2]. New installations, e.g gates running on master, pass the tests we have for that behavior [3], while deployment which had run that migration fail.

Besides fixing the issue in keystone side, we should follow up and create a test to ensure the result of migrations *always* match the current models.

[1] https://github.com/openstack/keystone/blob/312a041/keystone/common/sql/migrate_repo/versions/090_add_local_user_and_password_tables.py#L41
[2] https://github.com/openstack/keystone/blob/498ea91/keystone/identity/backends/sql_model.py#L157
[3] https://github.com/openstack/keystone/blob/498ea91/keystone/tests/unit/test_backend_sql.py#L229-L250

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/333919
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=e04c5614377a7209bde7904a37ac80e6d98bc620
Submitter: Jenkins
Branch: master

commit e04c5614377a7209bde7904a37ac80e6d98bc620
Author: Ronald De Rose <email address hidden>
Date: Fri Jun 24 14:06:06 2016 +0000

    Fixes failure when password is null

    This patch allows the password column to be null which is the expected
    behavior.

    Note: We do have tests in place that should have caught this. However,
    the SQL model for Password did not explicitly set the nullable column
    attribute, so it defaulted to true, even though the migration set it to
    false.

    Closes-Bug: #1595819

    Change-Id: I487072a5b1aeabebd1d2006781fa5dc568160ec5

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/333854
Committed: https://git.openstack.org/cgit/openstack/heat/commit/?id=1424a764078028266cb65fff25e12723e2079a73
Submitter: Jenkins
Branch: master

commit 1424a764078028266cb65fff25e12723e2079a73
Author: Rabi Mishra <email address hidden>
Date: Fri Jun 24 16:15:36 2016 +0530

    Wait for stack status instead of group status

    SUSPEND happens in reverse order, so waiting for the group to reach
    SUSPEND_COMPLETE/SUSPEND_FAILED would result in timeout, if SUSPEND
    for the policy resource fails.

    Change-Id: Ie690d49734d164554ee6cf6c11f8c45a2832a8fe
    Related-Bug: #1595819

[Davanum Srinivas (DIMS) (dims-v)]

This issue was fixed in the openstack/keystone 10.0.0.0b2 development milestone.