test_user_account_lockout failed in gate because authN attempts took longer than usual

[Ihar Hrachyshka]

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

[Lance Bragstad (lbragstad)]

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/b9b03484e50024112bd325182165945656be9f55/tempest/config.py#L182-L185

[Lance Bragstad (lbragstad)]

I posted a possible solution in case it's appropriate to reopen or track this against tempest instead.

https://review.openstack.org/#/c/472793/

[Lance Bragstad (lbragstad)]

I've posted a patch to devstack instead that overrides the default in devstack, too [0].

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

[Lance Bragstad (lbragstad)]

Adding tempest and devstack to this bug so we get eyes on this from those teams. They'll probably have better insight into what the best path forward would be given the patches in comment #2 and #3.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/473488
Committed: https://git.openstack.org/cgit/openstack-dev/devstack/commit/?id=dcd4b64c990660f9b11b999a3b70e17c36323c4c
Submitter: Jenkins
Branch: master

commit dcd4b64c990660f9b11b999a3b70e17c36323c4c
Author: Lance Bragstad <email address hidden>
Date: Mon Jun 12 14:41:42 2017 +0000

    Increase KEYSTONE_LOCKOUT_DURATION to 10

    Transient failures were being reported because the current lockout
    period for users was too short. While this does increase the
    run time IdentityV3UsersTest.test_user_account_lockout, it
    allows for more flexibility if there is network latency or some
    other factor that cause the lockout to expired before the
    next authentication.

    Change-Id: I61bc39bbc35ac414b4a72929a90845956c99eb1a
    Closes-Bug: 1693917

[Matthew Edmonds (edmondsw)]

The fact that this was changed in devstack but not also correspondingly changed in tempest breaks any CI that is using both, unless it explicitly overrides the default for one or the other (or disables security_compliance). They should match so that isn't necessary.

[OpenStack Infra (hudson-openstack)]

Change abandoned by Lance Bragstad (<email address hidden>) on branch: master
Review: https://review.openstack.org/472793
Reason: Sounds like we've reached a conclusion. Abandoning this per comments from Sean and Masayuki.

Thanks!

[Lance Bragstad (lbragstad)]

Marking the tempest bug as invalid per the comments in this patch:

https://review.openstack.org/#/c/472793/