Lockouts no longer functioning after upgrading from 5.0.18 to 5.0.19

[whwkong]

(Hey everyone, thanks for making axes such a wonderful project! I know a lot of hard work was put into this!)

I've been using django-axes for nearly a year (edit: since 4.5.x) without any problems, and recently upgraded from 5.0.18 to 5.0.19 and my unit tests now indicate that lockouts are no longer working.

The lockouts are based on user login plus IP. We are using axes with django_rest_framework 3.8.2 and django_allauth 0.40.0.

Some relevant settings:

AUTHENTICATION_BACKENDS = (
    "axes.backends.AxesBackend",
    "django.contrib.auth.backends.ModelBackend",
    "allauth.account.auth_backends.AuthenticationBackend",
}
CACHES = {
    "default": {"BACKEND": "django.core.cache.backends.locmem.LocMemCache"},
    "axes_cache": {"BACKEND": "django.core.cache.backends.dummy.DummyCache"},
}
AXES_CACHE = "axes_cache"
AXES_LOCK_OUT_BY_COMBINATION_USER_AND_IP = True

With axes 5.0.18, after two unsuccessful local attempts against the same login:

[in]: from axes.models import AccessAttempt
[in]: qs = AccessAttempt.objects.all()
[in]: len(qs)
[out]: 1

[in]: attempt = qs.first()
[in]: vars(attempt)
[out]:
{'_state': <django.db.models.base.ModelState at 0x7fd6214d5dd8>,
 'id': 68,
 'user_agent': 'Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/75.0.3770.80 Safari/537.36',
 'ip_address': '127.0.0.1',
 'username': 'somebody@example.com',
 'http_accept': 'application/json',
 'path_info': '/account/login/',
 'attempt_time': datetime.datetime(2019, 11, 28, 21, 22, 5, 592513, tzinfo=<UTC>),
 'get_data': '\n---------\n',
 'post_data': 'login=somebody@example.com\n---------\nlogin=somebody@example.com',
 'failures_since_start': 2}

With 5.0.18 both attempts are correctly represented by the same model instance.

After upgrading to axes 5.0.19, when I run the same test as above:

[in]: qs = AccessAttempt.objects.all()
[in]: len(qs)
[out]: 2

[in]: a_1 = qs.first()
[in]: a_2 = qs.last()
[in]: vars(a_1)
[out]:
{'_state': <django.db.models.base.ModelState at 0x7f20ebe4ae48>,
 'id': 69,
 'user_agent': 'Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/75.0.3770.80 Safari/537.36',
 'ip_address': '127.0.0.1',
 'username': 'someone_else@example.com',
 'http_accept': 'application/json',
 'path_info': '/account/login/',
 'attempt_time': datetime.datetime(2019, 11, 28, 21, 27, 7, 300416, tzinfo=<UTC>),
 'get_data': '',
 'post_data': 'login=someone_else@example.com',
 'failures_since_start': 1}

[in]: vars(a_2)
[out]:
{'_state': <django.db.models.base.ModelState at 0x7f20ebe4aa20>,
 'id': 70,
 'user_agent': 'Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/75.0.3770.80 Safari/537.36',
 'ip_address': '127.0.0.1',
 'username': 'someone_else@example.com',
 'http_accept': 'application/json',
 'path_info': '/account/login/',
 'attempt_time': datetime.datetime(2019, 11, 28, 21, 27, 8, 883077, tzinfo=<UTC>),
 'get_data': '',
 'post_data': 'login=someone_else@example.com',
 'failures_since_start': 1}

With 5.0.19, both attempts with the same login and IP are recorded to separate model instances and there is no lockout on subsequent attempts.

Has anyone else experienced anything like this?

[aleksihakli]

Hey @whwkong! The following functional updates have been made after 5.0.18, could one of them be the culprit?

1. https://github.com/jazzband/django-axes/commit/0b8bea5d647caf7fafd6e7d231cc5e9a7a1ecb03
2. https://github.com/jazzband/django-axes/commit/b8ef12ce840fb1a355ccaddf82c85e61d5ce3ba3
3. https://github.com/jazzband/django-axes/commit/4253fddd7ec0707cdc9e0dd67895e8b39183b1aa

Is it possible for you to post a more complete test set? The username and IP look the same, so it's hard to discern where the different might be.

EDIT: Seems like the username is updating and a new record is still being created for the different username. Seems to me like https://github.com/jazzband/django-axes/commit/0b8bea5d647caf7fafd6e7d231cc5e9a7a1ecb03 could be causing this bug. Would it be possible for you to open a PR that reproduces this bug and provides a test which fails when running with the configuration you are using? This way we could confirm the bug with a unit test or integration test and then introduce a patch that fixes the bug. This needs further investigation before a possible rollback is made.

[aleksihakli]

@hramezani could you check if https://github.com/jazzband/django-axes/commit/0b8bea5d647caf7fafd6e7d231cc5e9a7a1ecb03 or another 5.0.19 release patch is causing this?

[hramezani]

@aleksihakli sure. will check it. I think this https://github.com/jazzband/django-axes/commit/0b8bea5d647caf7fafd6e7d231cc5e9a7a1ecb03 is causing. based on this comment here https://github.com/jazzband/django-axes/blob/9d18bfc8921e364100a1cde6eab1b53f45940b93/axes/handlers/database.py#L119 I think we can revert this commit.

[hramezani]

Just created a PR to test this issue. I don't know if I understood it correctly or not.

[whwkong]

@hramezani I believe the new PR captures the problem. Thank you.

[hramezani]

@whwkong You are welcome. Here is the newly added test case description: I tried user failed login with two times with same username and enable AXES_LOCK_OUT_BY_COMBINATION_USER_AND_IP. After the second failed login we have just one record in AccessAttempt model. I think this test case does not capture the problem. Rather, it proves that everything is right. Please give us more information about your fail test.

[aleksihakli]

@hramezani test upstreamed.

@whwkong I'll leave this issue open for a while, but in order to change behaviour and implementation, I'd like to see a test that either produces an error (either a true negative or false positive) with the current configuration.

[whwkong]

@aleksihakli @hramezani You are correct, the new test passes.

After some testing 7d22d88 passes my tests b8ef12c does not pass.

Please give me some time to look at this more closely and hopefully write some tests.

[whwkong]

(Note: I added the Django authentication backend dict to my original question body)

After poking around, the problem is with the AxesDatabaseHandler._get_user_attempts() method from commit b8ef12c.

Running full integration test (my app uses axes + drf + allauth), the first time AxesDatabaseHandler._get_user_attempts() is called, the credentials argument is None.

In subsequent calls, the credentials argument is correctly filled out, eg: {"login": "somebody", "password": "123"}. However, the request.axes_user_attempts attribute is now populated, and the cached result is returned.

Removing the caching or amending ._get_user_attempts() to the following passes my tests.

class AxesDatabaseHandler(AxesHandler):
    def _get_user_attempts(self, request, credentials: dict = None):
        if not hasattr(request, "axes_user_attempts"):
            request.axes_user_attempts = {
                str(credentials): get_user_attempts(request, credentials)
            }

        try:
            return request.axes_user_attempts[str(credentials)]
        except KeyError:
            request.axes_user_attempts[str(credentials)] = get_user_attempts(
                request,
                credentials,
            )
        return request.axes_user_attempts[str(credentials)]

For the first _get_user_attempts() call with credentials=None the stack trace is:

[44]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/django/utils/deprecation.py(91)__call__()
-> response = response or self.get_response(request)
[45]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/django/core/handlers/exception.py(34)inner()
-> response = get_response(request)
[46]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/axes/middleware.py(30)__call__()
-> response = self.get_response(request)
[47]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/django/core/handlers/exception.py(34)inner()
-> response = get_response(request)
[48]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/django/core/handlers/base.py(124)_get_response()
-> response = wrapped_callback(request, *callback_args, **callback_kwargs)
[49]   /usr/lib/python3.7/contextlib.py(74)inner()
-> return func(*args, **kwds)
[50]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/django/views/decorators/csrf.py(54)wrapped_view()
-> return view_func(*args, **kwargs)
[51]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/django/views/generic/base.py(68)view()
-> return self.dispatch(request, *args, **kwargs)
[52]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/django/utils/decorators.py(45)_wrapper()
-> return bound_method(*args, **kwargs)
[53]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/axes/decorators.py(9)inner()
-> if AxesProxyHandler.is_allowed(request):
[54]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/axes/handlers/proxy.py(83)is_allowed()
-> return cls.get_implementation().is_allowed(request, credentials)
[55]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/axes/handlers/base.py(72)is_allowed()
-> if self.is_locked(request, credentials):
[56]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/axes/handlers/database.py(88)is_locked()
-> return super().is_locked(request, credentials)
[57]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/axes/handlers/base.py(135)is_locked()
-> return self.get_failures(request, credentials) >= get_failure_limit(
[58]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/axes/handlers/database.py(77)get_failures()
-> attempts = self._get_user_attempts(request, credentials)
[59] > /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/axes/handlers/database.py(41)_get_user_attempts()
-> if not hasattr(request, "axes_user_attempts"):

So the request has yet to pass through the allauth backend at this point.

For the second ._get_user_attempts() call with credentials properly filled out, the stack trace is:

[45]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/django/core/handlers/exception.py(34)inner()
-> response = get_response(request)
[46]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/axes/middleware.py(30)__call__()
-> response = self.get_response(request)
[47]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/django/core/handlers/exception.py(34)inner()
-> response = get_response(request)
[48]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/django/core/handlers/base.py(124)_get_response()
-> response = wrapped_callback(request, *callback_args, **callback_kwargs)
[49]   /usr/lib/python3.7/contextlib.py(74)inner()
-> return func(*args, **kwds)
[50]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/django/views/decorators/csrf.py(54)wrapped_view()
-> return view_func(*args, **kwargs)
[51]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/django/views/generic/base.py(68)view()
-> return self.dispatch(request, *args, **kwargs)
[52]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/django/utils/decorators.py(45)_wrapper()
-> return bound_method(*args, **kwargs)
[53]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/axes/decorators.py(10)inner()
-> return func(request, *args, **kwargs)
[54]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/django/utils/decorators.py(45)_wrapper()
-> return bound_method(*args, **kwargs)
[55]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/django/views/decorators/debug.py(76)sensitive_post_parameters_wrapper()
-> return view(request, *args, **kwargs)
[56]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/rest_auth/views.py(49)dispatch()
-> return super(LoginView, self).dispatch(*args, **kwargs)
[57]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/rest_framework/views.py(480)dispatch()
-> response = handler(request, *args, **kwargs)
[58]   /home/prometheus/bhtai/zenos.backend/apps/users/views.py(68)post()
-> if self.serializer.is_valid():
[59]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/rest_framework/serializers.py(236)is_valid()
-> self._validated_data = self.run_validation(self.initial_data)
[60]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/rest_framework/serializers.py(437)run_validation()
-> value = self.validate(value)
[61]   /home/prometheus/bhtai/zenos.backend/apps/users/serializers.py(107)validate()
-> user = self._validate_username(username, password)
[62]   /home/prometheus/bhtai/zenos.backend/apps/users/serializers.py(60)_validate_username()
-> user = self.authenticate(username=username, password=password)
[63]   /home/prometheus/bhtai/zenos.backend/apps/users/serializers.py(76)authenticate()
-> return authenticate(*args, request=request, **credentials)
[64]   /home/prometheus/bhtai/zenos.backend/apps/users/utils.py(43)authenticate()
-> axes_backend.authenticate(request, **credentials)
[65]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/axes/helpers.py(411)inner()
-> return func(*args, **kwargs)
[66]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/axes/backends.py(44)authenticate()
-> if AxesProxyHandler.is_allowed(request, credentials):
[67]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/axes/handlers/proxy.py(83)is_allowed()
-> return cls.get_implementation().is_allowed(request, credentials)
[68]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/axes/handlers/base.py(72)is_allowed()
-> if self.is_locked(request, credentials):
[69]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/axes/handlers/database.py(88)is_locked()
-> return super().is_locked(request, credentials)
[70]   /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/axes/handlers/base.py(135)is_locked()
-> return self.get_failures(request, credentials) >= get_failure_limit(
[71] > /home/prometheus/.virtualenvs/v_zenos.backend/lib/python3.7/site-packages/axes/handlers/database.py(77)get_failures()
-> attempts = self._get_user_attempts(request, credentials)

It's only after the serializers fill out the credentials dict (at [63] above) that it is then passed to AxesDatabaseHandler._get_user_attempts().

Since the unit tests that @hramezani wrote does not properly simulate the above scenario in an integrated app, I'm not sure if I'm familiar enough with axes to write a good test case for this.

[whwkong]

I forgot to mention: My app does not use session authentication (edit: there is no authentication via a form and django.contrib.auth is never called; everything is done through drf); I use allauth and issue jwt tokens upon authentication.

[hramezani]

I think the problem cames from the first attempt to AxesDatabaseHandler._get_user_attempts(), where the credential is None. I think the source of the problem is in integrating with Django Allauth. based on the integration-with-django-allauth:

This is not the case with Allauth. Allauth always uses the login key in post POST data but it becomes username key in credentials dict in signal handler.

here is my the scenario which I think cause the problem:

1. First unsuccessful login:
   1. In first attempt to AxesDatabaseHandler._get_user_attempts() the credential is None(as you said), AccessAttempt is empty, So request.axes_user_attempts is empty.
   2. In user_login_failed a new record with the credential will be created. (because we have credential here)
2. Second unsuccessful login:
   1. In first attempt to AxesDatabaseHandler._get_user_attempts() the credential is None(as you said), AccessAttempt has one record but with a username, So request.axes_user_attempts is empty because the last record which is inserted in step 1 has the credential and we don't have it hew
   2. In user_login_failed a new record with the credential will be created because request.axes_user_attempts is empty.

this is just my assumption. you can check your integration with Django Allauth again. @aleksihakli can correct me if I am wrong.

[aleksihakli]

I was suspecting this might be due to the caching that has been introduced. I think we can either

1. disable caching,
2. implement a specific fix for allauth, or
3. implement a generic flag for toggling the caching.

Which option do you think is correct?

[hramezani]

@aleksihakli I think it is better to disable it. because it is going to be more complicated and maybe error prune in the future. If you agree with me I can create a PR and revert my commit.

[whwkong]

I think the problem cames from the first attempt to AxesDatabaseHandler._get_user_attempts(), where the credential is None. I think the source of the problem is in integrating with Django Allauth. based on the integration-with-django-allauth:

This is not the case with Allauth. Allauth always uses the login key in post POST data but it becomes username key in credentials dict in signal handler.

here is my the scenario which I think cause the problem: ... this is just my assumption. you can check your integration with Django Allauth again.

Yes, this is a correct description of the problem.

[aleksihakli]

@hramezani I agree with you. As the caching is supplementary it is probably better to opt for behaviour that is always be correct than to introduce possibilities for bugs. I think that a rollback and possibly adding a comment about caching being dangerous is the best option here.

[aleksihakli]

Fix upstreamed and published on PyPI in release 5.0.20.