http://logs.openstack.org/99/460399/2/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/f7eb334/logs/testr_results.html.gz
ft1.2: tempest.api.identity.v3.test_users.IdentityV3UsersTest.test_user_account_lockout[id-a7ad8bbf-2cff-4520-8c1d-96332e151658]_StringException: pythonlogging:'': {{{
2017-05-24 21:05:50,147 32293 INFO [tempest.lib.common.rest_client] Request (IdentityV3UsersTest:test_user_account_lockout): 201 POST https://15.184.66.148/identity/v3/auth/tokens
2017-05-24 21:05:50,147 32293 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Accept': 'application/json', 'Content-Type': 'application/json'}
Body: <omitted>
Response - Headers: {u'vary': 'X-Auth-Token', 'content-location': 'https://15.184.66.148/identity/v3/auth/tokens', u'connection': 'close', u'content-length': '344', u'x-openstack-request-id': 'req-11e47cfa-6b25-47d4-977a-94f3e6d95665', 'status': '201', u'server': 'Apache/2.4.18 (Ubuntu)', u'date': 'Wed, 24 May 2017 21:05:50 GMT', u'x-subject-token': '<omitted>', u'content-type': 'application/json'}
Body: {"token": {"issued_at": "2017-05-24T21:05:50.000000Z", "audit_ids": ["GQR0RZcDSWC_bslZSUzpGg"], "methods": ["password"], "expires_at": "2017-05-24T22:05:50.000000Z", "user": {"password_expires_at": null, "domain": {"id": "default", "name": "Default"}, "id": "415e3f0e215f44a586bdf62e7ea6e02d", "name": "tempest-IdentityV3UsersTest-343470382"}}}
2017-05-24 21:05:50,237 32293 INFO [tempest.lib.common.rest_client] Request (IdentityV3UsersTest:test_user_account_lockout): 401 POST https://15.184.66.148/identity/v3/auth/tokens
2017-05-24 21:05:50,238 32293 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Accept': 'application/json', 'Content-Type': 'application/json'}
Body: <omitted>
Response - Headers: {u'vary': 'X-Auth-Token', 'content-location': 'https://15.184.66.148/identity/v3/auth/tokens', u'connection': 'close', u'content-length': '114', u'x-openstack-request-id': 'req-0a45b9b8-4c7c-409c-9c8d-f6b2661c234f', 'status': '401', u'server': 'Apache/2.4.18 (Ubuntu)', u'date': 'Wed, 24 May 2017 21:05:50 GMT', u'content-type': 'application/json', u'www-authenticate': 'Keystone uri="https://15.184.66.148/identity"'}
Body: {"error": {"message": "The request you have made requires authentication.", "code": 401, "title": "Unauthorized"}}
2017-05-24 21:05:54,909 32293 INFO [tempest.lib.common.rest_client] Request (IdentityV3UsersTest:test_user_account_lockout): 401 POST https://15.184.66.148/identity/v3/auth/tokens
2017-05-24 21:05:54,910 32293 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Accept': 'application/json', 'Content-Type': 'application/json'}
Body: <omitted>
Response - Headers: {u'vary': 'X-Auth-Token', 'content-location': 'https://15.184.66.148/identity/v3/auth/tokens', u'connection': 'close', u'content-length': '114', u'x-openstack-request-id': 'req-3dbd065f-826b-497d-86bc-2bc78a0de997', 'status': '401', u'server': 'Apache/2.4.18 (Ubuntu)', u'date': 'Wed, 24 May 2017 21:05:50 GMT', u'content-type': 'application/json', u'www-authenticate': 'Keystone uri="https://15.184.66.148/identity"'}
Body: {"error": {"message": "The request you have made requires authentication.", "code": 401, "title": "Unauthorized"}}
2017-05-24 21:05:55,106 32293 INFO [tempest.lib.common.rest_client] Request (IdentityV3UsersTest:test_user_account_lockout): 201 POST https://15.184.66.148/identity/v3/auth/tokens
2017-05-24 21:05:55,106 32293 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Accept': 'application/json', 'Content-Type': 'application/json'}
Body: <omitted>
Response - Headers: {u'vary': 'X-Auth-Token', 'content-location': 'https://15.184.66.148/identity/v3/auth/tokens', u'connection': 'close', u'content-length': '344', u'x-openstack-request-id': 'req-1d367c81-2ffa-4812-904a-16be33d12fc0', 'status': '201', u'server': 'Apache/2.4.18 (Ubuntu)', u'date': 'Wed, 24 May 2017 21:05:54 GMT', u'x-subject-token': '<omitted>', u'content-type': 'application/json'}
Body: {"token": {"issued_at": "2017-05-24T21:05:55.000000Z", "audit_ids": ["qlWnVS-MShm4hcBujHTL1g"], "methods": ["password"], "expires_at": "2017-05-24T22:05:55.000000Z", "user": {"password_expires_at": null, "domain": {"id": "default", "name": "Default"}, "id": "415e3f0e215f44a586bdf62e7ea6e02d", "name": "tempest-IdentityV3UsersTest-343470382"}}}
}}}
Traceback (most recent call last):
File "tempest/api/identity/v3/test_users.py", line 154, in test_user_account_lockout
password=password)
File "/opt/stack/new/tempest/.tox/tempest/local/lib/python2.7/site-packages/testtools/testcase.py", line 485, in assertRaises
self.assertThat(our_callable, matcher)
File "/opt/stack/new/tempest/.tox/tempest/local/lib/python2.7/site-packages/testtools/testcase.py", line 498, in assertThat
raise mismatch_error
testtools.matchers._impl.MismatchError: <bound method V3TokenClient.auth of <tempest.lib.services.identity.v3.token_client.V3TokenClient object at 0x7f0083561c90>> returned {u'token': {u'expires_at': u'2017-05-24T22:05:55.000000Z', u'audit_ids': [u'qlWnVS-MShm4hcBujHTL1g'], u'issued_at': u'2017-05-24T21:05:55.000000Z', u'methods': [u'password'], u'user': {u'domain': {u'id': u'default', u'name': u'Default'}, u'id': u'415e3f0e215f44a586bdf62e7ea6e02d', u'password_expires_at': None, u'name': u'tempest-IdentityV3UsersTest-343470382'}}}
The last authN attempt succeeded because it happened after lockout timeout (5 seconds). Looks like req-3dbd065f-826b-497d-86bc-2bc78a0de997 took longer than usual (~4seconds).
I'm not sure how much keystone can do to fix this. Keystone seems to be doing what is expected, but request latency could be causing skew to account for this case. One thing we might be able to do is bump up the user_lockout_ duration from 5 to something greater. While that specific test will run slower, it will be isolated to that specific test.
[0] https:/ /github. com/openstack/ tempest/ blob/b9b03484e5 0024112bd325182 165945656be9f55 /tempest/ config. py#L182- L185