test_password_history_not_enforced_in_admin_reset failed in tempest test

[Hirofumi Ichihara]

http://logs.openstack.org/95/479995/1/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/181701f/logs/testr_results.html.gz

ft1.3: tempest.api.identity.admin.v3.test_users.UsersV3TestJSON.test_password_history_not_enforced_in_admin_reset[id-568cd46c-ee6c-4ab4-a33a-d3791931979e]_StringException: pythonlogging:'': {{{
2017-07-04 02:14:33,998 23518 INFO [tempest.lib.common.rest_client] Request (UsersV3TestJSON:test_password_history_not_enforced_in_admin_reset): 200 PATCH https://10.0.1.201/identity/v3/users/e70a98d099b145f4bd39637a6ebc5ff0 0.092s
2017-07-04 02:14:33,998 23518 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: {"user": {"password": "A1^PtkD~Pd1e@3P", "id": "e70a98d099b145f4bd39637a6ebc5ff0"}}
    Response - Headers: {u'x-openstack-request-id': 'req-c629cb49-12f9-4970-9cb7-00f749f1d67d', u'content-type': 'application/json', u'vary': 'X-Auth-Token', u'content-length': '502', u'server': 'Apache/2.4.18 (Ubuntu)', u'date': 'Tue, 04 Jul 2017 02:14:33 GMT', u'connection': 'close', 'content-location': 'https://10.0.1.201/identity/v3/users/e70a98d099b145f4bd39637a6ebc5ff0', 'status': '200'}
        Body: {"user": {"name": "tempest-UsersV3TestJSON-46658028", "links": {"self": "https://10.0.1.201/identity/v3/users/e70a98d099b145f4bd39637a6ebc5ff0"}, "extra": {"project_id": "48606d02759440688de7759ffe09cf86", "email": "<email address hidden>"}, "domain_id": "default", "enabled": true, "options": {}, "id": "e70a98d099b145f4bd39637a6ebc5ff0", "project_id": "48606d02759440688de7759ffe09cf86", "email": "<email address hidden>", "password_expires_at": null}}
2017-07-04 02:14:34,099 23518 INFO [tempest.lib.common.rest_client] Request (UsersV3TestJSON:test_password_history_not_enforced_in_admin_reset): 201 POST https://10.0.1.201/identity/v3/auth/tokens
2017-07-04 02:14:34,099 23518 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json'}
        Body: <omitted>
    Response - Headers: {u'x-openstack-request-id': 'req-93ea6008-f665-463d-bdb0-49ea225dad42', u'content-type': 'application/json', u'vary': 'X-Auth-Token', u'content-length': '339', u'server': 'Apache/2.4.18 (Ubuntu)', u'date': 'Tue, 04 Jul 2017 02:14:34 GMT', u'x-subject-token': '<omitted>', u'connection': 'close', 'content-location': 'https://10.0.1.201/identity/v3/auth/tokens', 'status': '201'}
        Body: {"token": {"issued_at": "2017-07-04T02:14:34.000000Z", "audit_ids": ["PZ9Yvi0CRaOVnaiAnBlEbg"], "methods": ["password"], "expires_at": "2017-07-04T03:14:34.000000Z", "user": {"password_expires_at": null, "domain": {"id": "default", "name": "Default"}, "id": "e70a98d099b145f4bd39637a6ebc5ff0", "name": "tempest-UsersV3TestJSON-46658028"}}}
2017-07-04 02:14:34,240 23518 INFO [tempest.lib.common.rest_client] Request (UsersV3TestJSON:test_password_history_not_enforced_in_admin_reset): 200 PATCH https://10.0.1.201/identity/v3/users/e70a98d099b145f4bd39637a6ebc5ff0 0.140s
2017-07-04 02:14:34,241 23518 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: {"user": {"password": "A1^PtkD~Pd1e@3P", "id": "e70a98d099b145f4bd39637a6ebc5ff0"}}
    Response - Headers: {u'x-openstack-request-id': 'req-f48d7c79-c625-4fc9-94fd-7e448a5c5e61', u'content-type': 'application/json', u'vary': 'X-Auth-Token', u'content-length': '502', u'server': 'Apache/2.4.18 (Ubuntu)', u'date': 'Tue, 04 Jul 2017 02:14:34 GMT', u'connection': 'close', 'content-location': 'https://10.0.1.201/identity/v3/users/e70a98d099b145f4bd39637a6ebc5ff0', 'status': '200'}
        Body: {"user": {"name": "tempest-UsersV3TestJSON-46658028", "links": {"self": "https://10.0.1.201/identity/v3/users/e70a98d099b145f4bd39637a6ebc5ff0"}, "extra": {"project_id": "48606d02759440688de7759ffe09cf86", "email": "<email address hidden>"}, "domain_id": "default", "enabled": true, "options": {}, "id": "e70a98d099b145f4bd39637a6ebc5ff0", "project_id": "48606d02759440688de7759ffe09cf86", "email": "<email address hidden>", "password_expires_at": null}}
2017-07-04 02:14:34,332 23518 INFO [tempest.lib.common.rest_client] Request (UsersV3TestJSON:test_password_history_not_enforced_in_admin_reset): 200 PATCH https://10.0.1.201/identity/v3/users/e70a98d099b145f4bd39637a6ebc5ff0 0.091s
2017-07-04 02:14:34,333 23518 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: {"user": {"password": "Q7#bC_r&&e=y2qA", "id": "e70a98d099b145f4bd39637a6ebc5ff0"}}
    Response - Headers: {u'x-openstack-request-id': 'req-7046e301-b22a-48a1-b33f-82f737d2a4b1', u'content-type': 'application/json', u'vary': 'X-Auth-Token', u'content-length': '502', u'server': 'Apache/2.4.18 (Ubuntu)', u'date': 'Tue, 04 Jul 2017 02:14:34 GMT', u'connection': 'close', 'content-location': 'https://10.0.1.201/identity/v3/users/e70a98d099b145f4bd39637a6ebc5ff0', 'status': '200'}
        Body: {"user": {"name": "tempest-UsersV3TestJSON-46658028", "links": {"self": "https://10.0.1.201/identity/v3/users/e70a98d099b145f4bd39637a6ebc5ff0"}, "extra": {"project_id": "48606d02759440688de7759ffe09cf86", "email": "<email address hidden>"}, "domain_id": "default", "enabled": true, "options": {}, "id": "e70a98d099b145f4bd39637a6ebc5ff0", "project_id": "48606d02759440688de7759ffe09cf86", "email": "<email address hidden>", "password_expires_at": null}}
2017-07-04 02:14:34,421 23518 INFO [tempest.lib.common.rest_client] Request (UsersV3TestJSON:test_password_history_not_enforced_in_admin_reset): 401 POST https://10.0.1.201/identity/v3/auth/tokens
2017-07-04 02:14:34,421 23518 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json'}
        Body: <omitted>
    Response - Headers: {u'www-authenticate': 'Keystone uri="https://10.0.1.201/identity"', u'content-type': 'application/json', u'vary': 'X-Auth-Token', u'content-length': '114', u'server': 'Apache/2.4.18 (Ubuntu)', u'date': 'Tue, 04 Jul 2017 02:14:34 GMT', u'connection': 'close', 'content-location': 'https://10.0.1.201/identity/v3/auth/tokens', 'status': '401', u'x-openstack-request-id': 'req-66714d9e-a9b9-48af-a251-4a510ae4f0e4'}
        Body: {"error": {"message": "The request you have made requires authentication.", "code": 401, "title": "Unauthorized"}}
2017-07-04 02:14:34,511 23518 INFO [tempest.lib.common.rest_client] Request (UsersV3TestJSON:_run_cleanups): 200 PATCH https://10.0.1.201/identity/v3/users/e70a98d099b145f4bd39637a6ebc5ff0 0.080s
2017-07-04 02:14:34,512 23518 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: {"user": {"password": "Q7#bC_r&&e=y2qA", "id": "e70a98d099b145f4bd39637a6ebc5ff0"}}
    Response - Headers: {u'x-openstack-request-id': 'req-6a14e2b1-a5b7-409a-bc51-ab4ba6334f54', u'content-type': 'application/json', u'vary': 'X-Auth-Token', u'content-length': '502', u'server': 'Apache/2.4.18 (Ubuntu)', u'date': 'Tue, 04 Jul 2017 02:14:34 GMT', u'connection': 'close', 'content-location': 'https://10.0.1.201/identity/v3/users/e70a98d099b145f4bd39637a6ebc5ff0', 'status': '200'}
        Body: {"user": {"name": "tempest-UsersV3TestJSON-46658028", "links": {"self": "https://10.0.1.201/identity/v3/users/e70a98d099b145f4bd39637a6ebc5ff0"}, "extra": {"project_id": "48606d02759440688de7759ffe09cf86", "email": "<email address hidden>"}, "domain_id": "default", "enabled": true, "options": {}, "id": "e70a98d099b145f4bd39637a6ebc5ff0", "project_id": "48606d02759440688de7759ffe09cf86", "email": "<email address hidden>", "password_expires_at": null}}
}}}

Traceback (most recent call last):
  File "tempest/api/identity/admin/v3/test_users.py", line 171, in test_password_history_not_enforced_in_admin_reset
    self.token.auth(user_id=user_id, password=old_password)
  File "tempest/lib/services/identity/v3/token_client.py", line 132, in auth
    resp, body = self.post(self.auth_url, body=body)
  File "tempest/lib/common/rest_client.py", line 270, in post
    return self.request('POST', url, extra_headers, headers, body, chunked)
  File "tempest/lib/services/identity/v3/token_client.py", line 161, in request
    raise exceptions.Unauthorized(resp_body['error']['message'])
tempest.lib.exceptions.Unauthorized: Unauthorized
Details: The request you have made requires authentication.

[Gage Hugo (gagehugo)]

So it looks like the change[0] passed after a rebase? Not sure how to recreate this.

[0] https://review.openstack.org/#/c/479995/

[Matt Riedemann (mriedem)]

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22UsersV3TestJSON%3Atest_password_history_not_enforced_in_admin_reset%5C%22%20AND%20message%3A%5C%22401%20POST%5C%22%20AND%20message%3A%5C%22%2Fidentity%2Fv3%2Fauth%2Ftokens%5C%22%20AND%20tags%3A%5C%22console%5C%22&from=7d

32 hits in 7 days, check and gate queues, all failures.

[Gage Hugo (gagehugo)]

Was able to recreate this somewhat, ran the test 100 times and got a random failure.

http://paste.openstack.org/show/614979/

[Lance Bragstad (lbragstad)]

We made some good progress on this today and ended up figuring out the issue. Full logs and context can be found in IRC [0].

The crux of the issue is that keystone relies on datetime objects in MySQL, which are subject to differences in rounding depending on the MySQL version. This is especially true when precision under a second is required. The second part of the issue is that during the update of passwords, keystone asks the backend for all passwords, ordered by their creation time [1]. If a password is updated twice within a second - both passwords will have the same creation time making it possible of the old password to be returned ahead of the newly created passed.

To fix this, we shouldn't rely on native datetime formats with MySQL. Instead, keystone should store the datetime as an integer (which is more precise) and marshal the integer to a datetime object in the application. The result will be that MySQL will return passwords ordered by an integer, which is more precise, and leave the datetime conversion to keystone.

This should be done consistently in all places where keystone relies on datetime from MySQL.

[0] http://eavesdrop.openstack.org/irclogs/%23openstack-keystone/%23openstack-keystone.2017-08-11.log.html#t2017-08-11T14:53:24
[1] https://github.com/openstack/keystone/blob/6621c7810772eb076917ff7a959e77e13a0d6b85/keystone/identity/backends/sql_model.py#L276-L281

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/pike
Review: https://review.openstack.org/493260

[OpenStack Infra (hudson-openstack)]

Change abandoned by Morgan Fainberg (<email address hidden>) on branch: stable/pike
Review: https://review.openstack.org/493260
Reason: Will re-cherry-pick

[OpenStack Infra (hudson-openstack)]

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

commit 38974af24c47a6c26bb627250657a4d9ed5aa881
Author: Morgan Fainberg <email address hidden>
Date: Fri Aug 11 14:56:30 2017 -0700

    Add int storage of datetime for password created/expires

    Due to MySQL (in some versions) not storing datetime resolution below
    one second, keystone occasionally ends up with weird behavior such as
    a New password not being valid. The password created at and expires at
    columns now store both datetime (for rolling upgrades) and integers.

    Keystone from Pike and beyond leans on the new created_at_int column
    and expires_at_int column.

    Change-Id: I2c219b4b9b353f1e2cce6088849a773196f0e443
    Closes-Bug: #1702211

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/493260
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=66a1047e8c9b58a1d52f8f4417ca5d4c74a4997f
Submitter: Jenkins
Branch: stable/pike

commit 66a1047e8c9b58a1d52f8f4417ca5d4c74a4997f
Author: Morgan Fainberg <email address hidden>
Date: Fri Aug 11 14:56:30 2017 -0700

    Add int storage of datetime for password created/expires

    Due to MySQL (in some versions) not storing datetime resolution below
    one second, keystone occasionally ends up with weird behavior such as
    a New password not being valid. The password created at and expires at
    columns now store both datetime (for rolling upgrades) and integers.

    Keystone from Pike and beyond leans on the new created_at_int column
    and expires_at_int column.

    Change-Id: I2c219b4b9b353f1e2cce6088849a773196f0e443
    Closes-Bug: #1702211

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/keystone 12.0.0.0rc2 release candidate.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/keystone 13.0.0.0b1 development milestone.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/530550
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=07b07d5b83a75219581dabd703020c7a1fd0415e
Submitter: Zuul
Branch: master

commit 07b07d5b83a75219581dabd703020c7a1fd0415e
Author: Colleen Murphy <email address hidden>
Date: Sat Dec 30 17:47:46 2017 +0100

    Add expired_at_int column to trusts

    We've already converted Password objects to use the DateTimeInt format
    for its datetime attributes[1]. This was necessary to cope with
    differences in date storage formats between different DBMSs that was
    causing intermittent test failures. While we're not experiencing those
    CI problems any more, the DateTimeInt format is the way forward for
    consistent datetime storage. This patch converts the trust table and
    model to use the new format.

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

    Related-bug: #1702211

    Change-Id: If524c743170924e5b8cfdafa862ed31b06db018c