yahoo-eng-team team mailing list archive

[Lance Bragstad <lbragstad@xxxxxxxxx>]

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

** Changed in: keystone
       Status: New => Invalid

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Identity (keystone).
https://bugs.launchpad.net/bugs/1693917

Title:
  test_user_account_lockout failed in gate because authN attempts took
  longer than usual

Status in OpenStack Identity (keystone):
  Invalid

Bug description:
  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).

To manage notifications about this bug go to:
https://bugs.launchpad.net/keystone/+bug/1693917/+subscriptions