cannot create (or set) a user with no password

Bug #1595819 reported by Rabi Mishra
10
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Heat
Invalid
High
Unassigned
OpenStack Identity (keystone)
Critical
Ron De Rose

Bug Description

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)

Rabi Mishra (rabi)
Changed in heat:
importance: Undecided → High
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix proposed to heat (master)

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

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix merged to heat (master)

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

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix proposed to heat (master)

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

Revision history for this message
Steve Martinelli (stevemar) wrote : Re: functional.test_autoscaling.AutoScalingSignalTest failure

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.

Revision history for this message
Rabi Mishra (rabi) wrote :

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.

Revision history for this message
Steve Martinelli (stevemar) wrote :
Download full text (4.8 KiB)

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...

Read more...

Revision history for this message
Steve Martinelli (stevemar) wrote :

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)

Revision history for this message
Steve Martinelli (stevemar) wrote :

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)

Changed in keystone:
assignee: nobody → Ron De Rose (ronald-de-rose)
Changed in heat:
assignee: nobody → Ron De Rose (ronald-de-rose)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to keystone (master)

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

Changed in keystone:
status: New → In Progress
Revision history for this message
Steve Martinelli (stevemar) wrote :

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

Changed in keystone:
importance: Undecided → Critical
milestone: none → newton-2
summary: - functional.test_autoscaling.AutoScalingSignalTest failure
+ cannot create (or set) a user with no password
Revision history for this message
Samuel de Medeiros Queiroz (samueldmq) wrote :

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

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to keystone (master)

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

Changed in keystone:
status: In Progress → Fix Released
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix merged to heat (master)

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

Revision history for this message
Davanum Srinivas (DIMS) (dims-v) wrote : Fix included in openstack/keystone 10.0.0.0b2

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

Changed in heat:
assignee: Ron De Rose (ronald-de-rose) → nobody
status: New → Invalid
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers