Account is locked out and cannot have password updated.

[Clark Boylan]

We are seeing this in tempest testing. In some tempest runs the test to change the user password fails because the account is locked out. Example traceback can be found at http://logs.openstack.org/21/485221/2/gate/gate-tempest-dsvm-neutron-full-ubuntu-xenial/4ecd651/console.html#_2017-07-20_01_14_10_769485 and is pasted here so that log expiry doesn't delete it under us:

2017-07-20 01:14:10.769485 | tempest.api.identity.v3.test_users.IdentityV3UsersTest.test_user_update_own_password[id-ad71bd23-12ad-426b-bb8b-195d2b635f27]
2017-07-20 01:14:10.769531 | -----------------------------------------------------------------------------------------------------------------------------
2017-07-20 01:14:10.769545 |
2017-07-20 01:14:10.769562 | Captured traceback:
2017-07-20 01:14:10.769580 | ~~~~~~~~~~~~~~~~~~~
2017-07-20 01:14:10.769602 | Traceback (most recent call last):
2017-07-20 01:14:10.769639 | File "tempest/api/identity/v3/test_users.py", line 89, in test_user_update_own_password
2017-07-20 01:14:10.769672 | self._update_password(original_password=old_pass, password=new_pass)
2017-07-20 01:14:10.769707 | File "tempest/api/identity/v3/test_users.py", line 42, in _update_password
2017-07-20 01:14:10.769732 | original_password=original_password)
2017-07-20 01:14:10.769769 | File "tempest/lib/services/identity/v3/users_client.py", line 60, in update_user_password
2017-07-20 01:14:10.769801 | resp, _ = self.post('users/%s/password' % user_id, update_user)
2017-07-20 01:14:10.769831 | File "tempest/lib/common/rest_client.py", line 270, in post
2017-07-20 01:14:10.769864 | return self.request('POST', url, extra_headers, headers, body, chunked)
2017-07-20 01:14:10.769895 | File "tempest/lib/common/rest_client.py", line 659, in request
2017-07-20 01:14:10.769919 | self._error_checker(resp, resp_body)
2017-07-20 01:14:10.769951 | File "tempest/lib/common/rest_client.py", line 755, in _error_checker
2017-07-20 01:14:10.769979 | raise exceptions.Unauthorized(resp_body, resp=resp)
2017-07-20 01:14:10.770005 | tempest.lib.exceptions.Unauthorized: Unauthorized
2017-07-20 01:14:10.770054 | Details: {u'code': 401, u'title': u'Unauthorized', u'message': u'The account is locked for user: b99de038ad484b1fb4d65aebefd4464d.'}
2017-07-20 01:14:10.770068 |
2017-07-20 01:14:10.770081 |
2017-07-20 01:14:10.770099 | Captured pythonlogging:
2017-07-20 01:14:10.770118 | ~~~~~~~~~~~~~~~~~~~~~~~
2017-07-20 01:14:10.770193 | 2017-07-20 00:54:16,576 23533 INFO [tempest.lib.common.rest_client] Request (IdentityV3UsersTest:test_user_update_own_password): 401 POST https://198.72.124.157/identity/v3/users/b99de038ad484b1fb4d65aebefd4464d/password 0.049s
2017-07-20 01:14:10.770284 | 2017-07-20 00:54:16,576 23533 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'X-Auth-Token': '<omitted>', 'Accept': 'application/json'}
2017-07-20 01:14:10.770331 | Body: {"user": {"password": "M8*qsS56SFEo%s4", "original_password": "T4+DR4vL577eGl_"}}
2017-07-20 01:14:10.770475 | Response - Headers: {u'content-type': 'application/json', u'date': 'Thu, 20 Jul 2017 00:54:16 GMT', u'vary': 'X-Auth-Token', u'server': 'Apache/2.4.18 (Ubuntu)', u'connection': 'close', u'x-openstack-request-id': 'req-20995818-e4f4-4aaa-bdc1-d91c145ca562', u'www-authenticate': 'Keystone uri="https://198.72.124.157/identity"', u'content-length': '129', 'status': '401', 'content-location': 'https://198.72.124.157/identity/v3/users/b99de038ad484b1fb4d65aebefd4464d/password'}
2017-07-20 01:14:10.770528 | Body: {"error": {"message": "The account is locked for user: b99de038ad484b1fb4d65aebefd4464d.", "code": 401, "title": "Unauthorized"}}
2017-07-20 01:14:10.770599 | 2017-07-20 00:54:16,614 23533 INFO [tempest.lib.common.rest_client] Request (IdentityV3UsersTest:_run_cleanups): 401 POST https://198.72.124.157/identity/v3/users/b99de038ad484b1fb4d65aebefd4464d/password 0.036s
2017-07-20 01:14:10.770669 | 2017-07-20 00:54:16,614 23533 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'X-Auth-Token': '<omitted>', 'Accept': 'application/json'}
2017-07-20 01:14:10.770709 | Body: {"user": {"password": "H1!w*#WDyqGDBod", "original_password": "M8*qsS56SFEo%s4"}}
2017-07-20 01:14:10.770857 | Response - Headers: {u'content-type': 'application/json', u'date': 'Thu, 20 Jul 2017 00:54:16 GMT', u'vary': 'X-Auth-Token', u'server': 'Apache/2.4.18 (Ubuntu)', u'connection': 'close', u'x-openstack-request-id': 'req-3427cb2f-65a2-4411-8005-9d9108d868e7', u'www-authenticate': 'Keystone uri="https://198.72.124.157/identity"', u'content-length': '129', 'status': '401', 'content-location': 'https://198.72.124.157/identity/v3/users/b99de038ad484b1fb4d65aebefd4464d/password'}
2017-07-20 01:14:10.770914 | Body: {"error": {"message": "The account is locked for user: b99de038ad484b1fb4d65aebefd4464d.", "code": 401, "title": "Unauthorized"}}
2017-07-20 01:14:10.770929 |
2017-07-20 01:14:10.770942 |
2017-07-20 01:14:10.770960 | Captured traceback-1:
2017-07-20 01:14:10.770978 | ~~~~~~~~~~~~~~~~~~~~~
2017-07-20 01:14:10.771001 | Traceback (most recent call last):
2017-07-20 01:14:10.771034 | File "tempest/api/identity/v3/test_users.py", line 64, in _restore_password
2017-07-20 01:14:10.771062 | original_password=new_pass, password=random_pass)
2017-07-20 01:14:10.771096 | File "tempest/api/identity/v3/test_users.py", line 42, in _update_password
2017-07-20 01:14:10.771120 | original_password=original_password)
2017-07-20 01:14:10.771157 | File "tempest/lib/services/identity/v3/users_client.py", line 60, in update_user_password
2017-07-20 01:14:10.771188 | resp, _ = self.post('users/%s/password' % user_id, update_user)
2017-07-20 01:14:10.771218 | File "tempest/lib/common/rest_client.py", line 270, in post
2017-07-20 01:14:10.771251 | return self.request('POST', url, extra_headers, headers, body, chunked)
2017-07-20 01:14:10.771282 | File "tempest/lib/common/rest_client.py", line 659, in request
2017-07-20 01:14:10.771306 | self._error_checker(resp, resp_body)
2017-07-20 01:14:10.771346 | File "tempest/lib/common/rest_client.py", line 755, in _error_checker
2017-07-20 01:14:10.789250 | raise exceptions.Unauthorized(resp_body, resp=resp)
2017-07-20 01:14:10.789306 | tempest.lib.exceptions.Unauthorized: Unauthorized
2017-07-20 01:14:10.789359 | Details: {u'code': 401, u'title': u'Unauthorized', u'message': u'The account is locked for user: b99de038ad484b1fb4d65aebefd4464d.'}

I'm not sure if this is a keystone issue or a tempest test bug so going to file it against both then start tracking it with elastic-recheck.

[chandan kumar (chkumar246)]

Is this issue still poping up?

[Lance Bragstad (lbragstad)]

bug 1702211 was opened around the same time frame, and we landed a fix for it in Pike. I wonder if that had something to do with this report, too. It certainly was a transient issue based on SQL. We fixed it by migrating to a more precise date format and making keystone responsible for marshaling the date to something it expects instead of letting SQL handle things.

[Lance Bragstad (lbragstad)]

I'll wait for someone from infra to confirm this isn't happening anymore before closing.