normandy icon indicating copy to clipboard operation
normandy copied to clipboard

Intermittent test failure with timing in cache tests

Open jaredlockhart opened this issue 6 years ago • 0 comments

I just got a test failure that passed the second time I ran it, looks like an intermittent failure (which is probably backed up by the comment inside the test):

============================================================================================== FAILURES ===============================================================================================
_____________________________________________________________________________ TestBearerTokenAuthentication.test_caching ______________________________________________________________________________

self = <normandy.base.tests.api.test_authentication.TestBearerTokenAuthentication object at 0x7f1e3bc99ed0>, bare_api_client = <rest_framework.test.APIClient object at 0x7f1e3bd3d490>
requestsmock = <requests_mock.mocker.Mocker object at 0x7f1e3bcdef50>, settings = <pytest_django.fixtures.SettingsWrapper object at 0x7f1e3bca33d0>

    def test_caching(self, bare_api_client, requestsmock, settings):
        user = UserFactory()
        user_data = json.dumps(
            {"email": user.email, "given_name": user.first_name, "family_name": user.last_name}
        ).encode("utf-8")

        # The reason for the `+ 2` here is that if we only add +1 second, there's a small
        # chance that the `time.mktime(utcnow)` done here is *different* from the
        # `time.mktime(utcnow)` that happens within the `fetch_oidc_user_profile()` method
        # inside BearerTokenAuthentication.
        # I.e.
        #
        #    print(time.mktime(datetime.utcnow().timetuple()))  # outputs 1534380068.0
        #    time.sleep(0.1)
        #    print(time.mktime(datetime.utcnow().timetuple()))  # outputs 1534380069.0
        #
        # Note! This doesn't always happen. Run those three lines 100 times and it's
        # guaranteed to be different ~10% of the time. That's when the milliseconds is 900 and
        # with the sleep(0.1) it will round up to the next second.
        # By adding +2 to the mock here we allow a whole 1 second between now and when
        # the `fetch_oidc_user_profile()` uses `time.mktime(datetime.utcnow().timetuple())`.
        ratelimit_reset = int(time.mktime(datetime.utcnow().timetuple())) + 2
        requestsmock.get(
            settings.OIDC_USER_ENDPOINT,
            [
                {
                    "content": user_data,
                    "status_code": 200,
                    "headers": {"X-RateLimit-Reset": f"{ratelimit_reset}"},
                },
                {"status_code": 401},
            ],
        )

        response = bare_api_client.post(
            "/bearer/", {"example": "example"}, HTTP_AUTHORIZATION="Bearer valid-token"
        )
        assert response.status_code == 200
        assert response.data.get("user") == user.email

        # Response should be cached and you shouldn't hit the 401
        response = bare_api_client.post(
            "/bearer/", {"example": "example"}, HTTP_AUTHORIZATION="Bearer valid-token"
        )
        assert response.status_code == 200
        assert response.data.get("user") == user.email

        # Sleep till cache expires
        time.sleep(2)
        response = bare_api_client.post(
            "/bearer/", {"example": "example"}, HTTP_AUTHORIZATION="Bearer valid-token"
        )
>       assert response.status_code == 401
E       assert 200 == 401
E        +  where 200 = <Response status_code=200, "application/json">.status_code

normandy/base/tests/api/test_authentication.py:133: AssertionError

jaredlockhart avatar Oct 07 '19 20:10 jaredlockhart