TOTP previous windows passcode test fails intermittently

Bug #1843464 reported by Colleen Murphy
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Identity (keystone)
Fix Released
Medium
Gage Hugo

Bug Description

The keystone.tests.unit.test_v3_auth.TestAuthTOTP.test_with_passcode_in_previous_windows_extended test fails in CI occasionally, with traceback:

Traceback (most recent call last):
  File "/home/zuul/src/opendev.org/openstack/keystone/keystone/tests/unit/test_v3_auth.py", line 5443, in test_with_passcode_in_previous_windows_extended
    self.v3_create_token(auth_data, expected_status=http_client.CREATED)
  File "/home/zuul/src/opendev.org/openstack/keystone/keystone/tests/unit/test_v3.py", line 448, in v3_create_token
    expected_status=expected_status)
  File "/home/zuul/src/opendev.org/openstack/keystone/keystone/tests/unit/rest.py", line 211, in admin_request
    return self._request(app=self.public_app, **kwargs)
  File "/home/zuul/src/opendev.org/openstack/keystone/keystone/tests/unit/rest.py", line 200, in _request
    response = self.restful_request(**kwargs)
  File "/home/zuul/src/opendev.org/openstack/keystone/keystone/tests/unit/rest.py", line 185, in restful_request
    **kwargs)
  File "/home/zuul/src/opendev.org/openstack/keystone/keystone/tests/unit/rest.py", line 89, in request
    **kwargs)
  File "/home/zuul/src/opendev.org/openstack/keystone/.tox/py36/lib/python3.6/site-packages/webtest/app.py", line 589, in request
    expect_errors=expect_errors,
  File "/home/zuul/src/opendev.org/openstack/keystone/.tox/py36/lib/python3.6/site-packages/webtest/app.py", line 654, in do_request
    self._check_status(status, res)
  File "/home/zuul/src/opendev.org/openstack/keystone/.tox/py36/lib/python3.6/site-packages/webtest/app.py", line 689, in _check_status
    "Bad response: %s (not %s)\n%s", res_status, status, res)
webtest.app.AppError: Bad response: 401 UNAUTHORIZED (not HTTPStatus.CREATED)
b'{"error":{"code":401,"message":"The request you have made requires authentication.","title":"Unauthorized"}}\n'

Example failure: https://bb58e5c931fd1f60f908-f87a01575e4cebb7b630bab88ef312d9.ssl.cf1.rackcdn.com/681161/1/check/openstack-tox-py36/922e3ff/testr_results.html.gz

Seems like perhaps the freezegun functionality isn't working as expected.

Colleen Murphy (krinkle)
Changed in keystone:
status: New → Triaged
tags: added: test-improvement
Changed in keystone:
importance: Undecided → Medium
Revision history for this message
Gage Hugo (gagehugo) wrote :

Traceback (most recent call last):
  File "/home/zuul/src/opendev.org/openstack/keystone/keystone/tests/unit/test_v3_auth.py", line 5443, in test_with_passcode_in_previous_windows_extended
    self.v3_create_token(auth_data, expected_status=http_client.CREATED)
  File "/home/zuul/src/opendev.org/openstack/keystone/keystone/tests/unit/test_v3.py", line 448, in v3_create_token
    expected_status=expected_status)
  File "/home/zuul/src/opendev.org/openstack/keystone/keystone/tests/unit/rest.py", line 211, in admin_request
    return self._request(app=self.public_app, **kwargs)
  File "/home/zuul/src/opendev.org/openstack/keystone/keystone/tests/unit/rest.py", line 200, in _request
    response = self.restful_request(**kwargs)
  File "/home/zuul/src/opendev.org/openstack/keystone/keystone/tests/unit/rest.py", line 185, in restful_request
    **kwargs)
  File "/home/zuul/src/opendev.org/openstack/keystone/keystone/tests/unit/rest.py", line 89, in request
    **kwargs)
  File "/home/zuul/src/opendev.org/openstack/keystone/.tox/py36/lib/python3.6/site-packages/webtest/app.py", line 589, in request
    expect_errors=expect_errors,
  File "/home/zuul/src/opendev.org/openstack/keystone/.tox/py36/lib/python3.6/site-packages/webtest/app.py", line 654, in do_request
    self._check_status(status, res)
  File "/home/zuul/src/opendev.org/openstack/keystone/.tox/py36/lib/python3.6/site-packages/webtest/app.py", line 689, in _check_status
    "Bad response: %s (not %s)\n%s", res_status, status, res)
webtest.app.AppError: Bad response: 401 UNAUTHORIZED (not HTTPStatus.CREATED)
b'{"error":{"code":401,"message":"The request you have made requires authentication.","title":"Unauthorized"}}\n'

Revision history for this message
Gage Hugo (gagehugo) wrote :

I've not been able to recreate this locally with the time set to 2 minutes, however it does seem to be reproducible (albeit somewhat randomly) on the gate.

Revision history for this message
Guang Yee (guang-yee) wrote :

I wonder if there's a problem with using freezegun and running the tests in parallel. Maybe we need to put a locking mechanism around that code?

Changed in keystone:
assignee: nobody → Gage Hugo (gagehugo)
status: Triaged → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to keystone (master)

Reviewed: https://review.opendev.org/684397
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=6525203c1af9ecdf7c23af3f25e45f0db9f6fed2
Submitter: Zuul
Branch: master

commit 6525203c1af9ecdf7c23af3f25e45f0db9f6fed2
Author: Gage Hugo <email address hidden>
Date: Tue Sep 24 11:34:37 2019 -0500

    Change time faking for totp test

    This change moves the time mocking from using freezegun to
    using oslo.utils TimeFixture for the unit test
    test_with_passcode_in_previous_windows_extended, which was
    occasionally failing with 401 errors due to
    the totp creation time not properly be faked with
    4 extended windows.

    Closes-Bug: #1843464

    Change-Id: I3aefd99907fbc2d03538c9814f7279b282715679

Changed in keystone:
status: In Progress → Fix Released
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to keystone (stable/train)

Fix proposed to branch: stable/train
Review: https://review.opendev.org/728271

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to keystone (stable/train)

Reviewed: https://review.opendev.org/728271
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=247227f3f367be37db3292ecae130e3e02f18063
Submitter: Zuul
Branch: stable/train

commit 247227f3f367be37db3292ecae130e3e02f18063
Author: Gage Hugo <email address hidden>
Date: Tue Sep 24 11:34:37 2019 -0500

    Change time faking for totp test

    This change moves the time mocking from using freezegun to
    using oslo.utils TimeFixture for the unit test
    test_with_passcode_in_previous_windows_extended, which was
    occasionally failing with 401 errors due to
    the totp creation time not properly be faked with
    4 extended windows.

    Closes-Bug: #1843464

    Change-Id: I3aefd99907fbc2d03538c9814f7279b282715679
    (cherry picked from commit 6525203c1af9ecdf7c23af3f25e45f0db9f6fed2)

tags: added: in-stable-train
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/keystone 16.0.2

This issue was fixed in the openstack/keystone 16.0.2 release.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.