diff --git a/openedx/core/djangoapps/safe_sessions/middleware.py b/openedx/core/djangoapps/safe_sessions/middleware.py index ad2bd2cb8a19..7e118796eed3 100644 --- a/openedx/core/djangoapps/safe_sessions/middleware.py +++ b/openedx/core/djangoapps/safe_sessions/middleware.py @@ -88,6 +88,8 @@ from django.http import HttpResponse from django.utils.crypto import get_random_string from django.utils.deprecation import MiddlewareMixin +from django.core.cache import cache + from edx_django_utils.monitoring import set_custom_attribute @@ -96,13 +98,16 @@ # .. toggle_name: LOG_REQUEST_USER_CHANGES # .. toggle_implementation: SettingToggle # .. toggle_default: False -# .. toggle_description: Turn this toggle on to log anytime the `user` attribute of the request object gets -# changed. This will also log the location where the change is coming from to quickly find issues. -# .. toggle_warnings: This logging will be very verbose and so should probably not be left on all the time. +# .. toggle_description: Turn this toggle on to enable 5 minutes of logging anytime the `user` attribute of the request +# object gets changed after a mismatch incident. This will also log the location where the change is coming from to +# quickly find issues. The 5 minutes will be reset after every incident. +# .. toggle_warnings: This logging may be very verbose if there are many user id mimatches over a long period of time. +# This toggle can be disabled as a safety valve in such an event. # .. toggle_use_cases: opt_in # .. toggle_creation_date: 2021-03-25 # .. toggle_tickets: https://openedx.atlassian.net/browse/ARCHBOM-1718 LOG_REQUEST_USER_CHANGES = getattr(settings, 'LOG_REQUEST_USER_CHANGES', False) +RECENT_USER_MISMATCH_CACHE_KEY = 'safe_sessions.middleware.recent_user_mismatch_detected' log = getLogger(__name__) @@ -321,7 +326,10 @@ def process_request(self, request): user_id = self.get_user_id_from_session(request) if safe_cookie_data.verify(user_id): # Step 4 request.safe_cookie_verified_user_id = user_id # Step 5 - if LOG_REQUEST_USER_CHANGES: + request.safe_cookie_session_id = safe_cookie_data.session_id + if cache.get(RECENT_USER_MISMATCH_CACHE_KEY, False) and LOG_REQUEST_USER_CHANGES: + # Note: this logging will only be enabled after we have already detected a user mismatch, + # so we will miss the logs for the initial request that activated the logging. log_request_user_changes(request) else: # Return an error or redirect, and don't continue to @@ -353,6 +361,7 @@ def process_response(self, request, response): Step 4. Delete the cookie, if it's marked for deletion. """ + response = super().process_response(request, response) # Step 1 if not _is_cookie_marked_for_deletion(request) and _is_cookie_present(response): @@ -408,34 +417,66 @@ def _verify_user(request, response, userid_in_session): return if hasattr(request, 'safe_cookie_verified_user_id'): + if hasattr(request.user, 'real_user'): # If a view overrode the request.user with a masqueraded user, this will # revert/clean-up that change during response processing. request.user = request.user.real_user - # The user at response time is expected to be None when the user - # is logging out. We won't log that. - if request.safe_cookie_verified_user_id != request.user.id and request.user.id is not None: - log.warning( - ( - "SafeCookieData user at request '{}' does not match user at response: '{}' " - "for request path '{}'" - ).format( # pylint: disable=logging-format-interpolation - request.safe_cookie_verified_user_id, request.user.id, request.path, - ), - ) - set_custom_attribute("safe_sessions.user_mismatch", "request-response-mismatch") - # The user session at response time is expected to be None when the user - # is logging out. We won't log that. - if request.safe_cookie_verified_user_id != userid_in_session and userid_in_session is not None: - log.warning( - ( - "SafeCookieData user at request '{}' does not match user in session: '{}' " - "for request path '{}'" - ).format( # pylint: disable=logging-format-interpolation - request.safe_cookie_verified_user_id, userid_in_session, request.path, - ), - ) - set_custom_attribute("safe_sessions.user_mismatch", "request-session-mismatch") + + # The user at response time (and in the session) is expected to be None when the user + # is logging out so do not treat it as a mismatch + is_request_response_mismatch = request.safe_cookie_verified_user_id != request.user.id\ + and request.user.id is not None + is_request_session_mismatch = request.safe_cookie_verified_user_id != userid_in_session\ + and userid_in_session is not None + + session_at_response = None + if hasattr(request, 'session') and hasattr(request.session, 'session_key'): + session_at_response = request.session.session_key + + if is_request_response_mismatch or is_request_session_mismatch: + cache.set(RECENT_USER_MISMATCH_CACHE_KEY, True, 300) + session_has_changed = not request.safe_cookie_session_id == session_at_response + # remove the stored old session id for security + del request.safe_cookie_session_id + + # for security, don't log the actual session id, just whether or not it changed + log_session_suffix = 'Session id has changed.' if session_has_changed else 'Session id has not changed' + + if is_request_response_mismatch and not is_request_session_mismatch: + log.warning( + ( + "SafeCookieData user in initial request '{}' does not match user at response time: '{}' " + "for request path '{}'. {}" + ).format( # pylint: disable=logging-format-interpolation + request.safe_cookie_verified_user_id, request.user.id, request.path, + log_session_suffix + ), + ) + set_custom_attribute("safe_sessions.user_mismatch", "request-response-mismatch") + elif is_request_session_mismatch and not is_request_response_mismatch: + log.warning( + ( + "SafeCookieData user in initial request '{}' does not match user in session: '{}' " + "for request path '{}'. {}" + ).format( # pylint: disable=logging-format-interpolation + request.safe_cookie_verified_user_id, userid_in_session, request.path, + log_session_suffix + ), + ) + set_custom_attribute("safe_sessions.user_mismatch", "request-session-mismatch") + else: + # both session user and user in response are different than user in request + log.warning( + ( + "SafeCookieData user in initial request '{}' does not match user in session: '{}' " + "or user at response time: {} for request path '{}'. {}" + ).format( # pylint: disable=logging-format-interpolation + request.safe_cookie_verified_user_id, userid_in_session, request.user.id, request.path, + log_session_suffix + ), + ) + set_custom_attribute("safe_sessions.user_mismatch", "request-response-and-session-mismatch") @staticmethod def get_user_id_from_session(request): diff --git a/openedx/core/djangoapps/safe_sessions/tests/test_middleware.py b/openedx/core/djangoapps/safe_sessions/tests/test_middleware.py index ce49f5bd9568..cea007d4622d 100644 --- a/openedx/core/djangoapps/safe_sessions/tests/test_middleware.py +++ b/openedx/core/djangoapps/safe_sessions/tests/test_middleware.py @@ -2,11 +2,12 @@ Unit tests for SafeSessionMiddleware """ -from unittest.mock import patch +from unittest.mock import patch, MagicMock import ddt from crum import set_current_request +from django.core.cache import cache from django.conf import settings from django.contrib.auth import SESSION_KEY from django.contrib.auth.models import AnonymousUser @@ -14,18 +15,22 @@ from django.test import TestCase from django.test.utils import override_settings -from openedx.core.djangolib.testing.utils import get_mock_request +from openedx.core.djangolib.testing.utils import get_mock_request, CacheIsolationTestCase from common.djangoapps.student.tests.factories import UserFactory -from ..middleware import SafeCookieData, SafeSessionMiddleware, log_request_user_changes, mark_user_change_as_expected +from ..middleware import SafeCookieData, SafeSessionMiddleware, log_request_user_changes, mark_user_change_as_expected,\ +RECENT_USER_MISMATCH_CACHE_KEY from .test_utils import TestSafeSessionsLogMixin -class TestSafeSessionProcessRequest(TestSafeSessionsLogMixin, TestCase): +@ddt.ddt +class TestSafeSessionProcessRequest(TestSafeSessionsLogMixin, CacheIsolationTestCase): """ Test class for SafeSessionMiddleware.process_request """ + ENABLED_CACHES = ['default'] + def setUp(self): super().setUp() self.user = UserFactory.create() @@ -71,42 +76,42 @@ def assert_user_in_session(self): """ assert SafeSessionMiddleware.get_user_id_from_session(self.request) == self.user.id - @patch("openedx.core.djangoapps.safe_sessions.middleware.LOG_REQUEST_USER_CHANGES", False) - @patch("openedx.core.djangoapps.safe_sessions.middleware.log_request_user_changes") - def test_success(self, mock_log_request_user_changes): - self.client.login(username=self.user.username, password='test') - session_id = self.client.session.session_key - safe_cookie_data = SafeCookieData.create(session_id, self.user.id) - - # pre-verify steps 3, 4, 5 - assert getattr(self.request, 'session', None) is None - assert getattr(self.request, 'safe_cookie_verified_user_id', None) is None - - # verify step 1: safe cookie data is parsed - self.assert_response(safe_cookie_data) - self.assert_user_in_session() - - # verify step 2: cookie value is replaced with parsed session_id - assert self.request.COOKIES[settings.SESSION_COOKIE_NAME] == session_id - - # verify step 3: session set in request - assert self.request.session is not None - - # verify steps 4, 5: user_id stored for later verification - assert self.request.safe_cookie_verified_user_id == self.user.id - - # verify extra request_user_logging not called. - assert not mock_log_request_user_changes.called - - @patch("openedx.core.djangoapps.safe_sessions.middleware.LOG_REQUEST_USER_CHANGES", True) @patch("openedx.core.djangoapps.safe_sessions.middleware.log_request_user_changes") - def test_log_request_user_on(self, mock_log_request_user_changes): - self.client.login(username=self.user.username, password='test') - session_id = self.client.session.session_key - safe_cookie_data = SafeCookieData.create(session_id, self.user.id) - - self.assert_response(safe_cookie_data) - assert mock_log_request_user_changes.called + @ddt.unpack + @ddt.data( + {'toggle': True, 'cache_flag': True, 'should_log': True}, + {'toggle': True, 'cache_flag': False, 'should_log': False}, + {'toggle': False, 'cache_flag': True, 'should_log': False}, + {'toggle': False, 'cache_flag': False, 'should_log': False}, + ) + def test_success(self, mock_log_request_user_changes, toggle, cache_flag, should_log): + with patch("openedx.core.djangoapps.safe_sessions.middleware.LOG_REQUEST_USER_CHANGES", toggle): + self.client.login(username=self.user.username, password='test') + cache.set(RECENT_USER_MISMATCH_CACHE_KEY, cache_flag) + session_id = self.client.session.session_key + safe_cookie_data = SafeCookieData.create(session_id, self.user.id) + + # pre-verify steps 3, 4, 5 + assert getattr(self.request, 'session', None) is None + assert getattr(self.request, 'safe_cookie_verified_user_id', None) is None + + # verify step 1: safe cookie data is parsed + self.assert_response(safe_cookie_data) + self.assert_user_in_session() + + # verify step 2: cookie value is replaced with parsed session_id + assert self.request.COOKIES[settings.SESSION_COOKIE_NAME] == session_id + + # verify step 3: session set in request + assert self.request.session is not None + + # verify steps 4, 5: user_id stored for later verification + assert self.request.safe_cookie_verified_user_id == self.user.id + + if should_log: + assert mock_log_request_user_changes.called + else: + assert not mock_log_request_user_changes.called def test_success_no_cookies(self): self.assert_response() @@ -136,17 +141,24 @@ def test_invalid_user_at_step_4(self): @ddt.ddt -class TestSafeSessionProcessResponse(TestSafeSessionsLogMixin, TestCase): +class TestSafeSessionProcessResponse(TestSafeSessionsLogMixin, CacheIsolationTestCase): """ Test class for SafeSessionMiddleware.process_response """ + ENABLED_CACHES = ['default'] + + @classmethod + def setUpClass(cls): + super().setUpClass() + cls.MOCK_USER = UserFactory() + def setUp(self): super().setUp() - self.user = UserFactory.create() + self.user = self.MOCK_USER self.addCleanup(set_current_request, None) self.request = get_mock_request() - self.request.session = {} + self.request.session = MagicMock() self.client.response = HttpResponse() self.client.response.cookies = SimpleCookie() @@ -188,30 +200,90 @@ def assert_response_with_delete_cookie( self.assert_response(set_request_user=set_request_user, set_session_cookie=set_session_cookie) assert mock_delete_cookie.called == expect_delete_called - def test_success(self): + @patch("django.core.cache.cache.set") + @patch("django.core.cache.cache.touch") + def test_success(self, mock_cache_set, mock_cache_touch): with self.assert_not_logged(): self.assert_response(set_request_user=True, set_session_cookie=True) + assert not mock_cache_set.called + assert not mock_cache_touch.called - def test_confirm_user_at_step_2(self): + @patch("django.core.cache.cache.set") + @patch("django.core.cache.cache.touch") + def test_confirm_user_at_step_2(self, mock_cache_set, mock_cache_touch): self.request.safe_cookie_verified_user_id = self.user.id with self.assert_not_logged(): self.assert_response(set_request_user=True, set_session_cookie=True) - - def test_different_user_at_step_2_error(self): - self.request.safe_cookie_verified_user_id = "different_user" - - with self.assert_logged_for_request_user_mismatch("different_user", self.user.id, 'warning', self.request.path): - self.assert_response(set_request_user=True, set_session_cookie=True) - - with self.assert_logged_for_session_user_mismatch("different_user", self.user.id, self.request.path): - self.assert_response(set_request_user=True, set_session_cookie=True) - - def test_anonymous_user(self): + assert not mock_cache_set.called + assert not mock_cache_touch.called + + @patch("django.core.cache.cache.set") + @ddt.unpack + @ddt.data( + {'change_response_user': True, 'change_session_user': False, 'mismatch_location': 'at response time', + 'change_session': True}, + {'change_response_user': False, 'change_session_user': True, 'mismatch_location': 'in session', + 'change_session': True}, + {'change_response_user': True, 'change_session_user': True, 'mismatch_location': 'both', + 'change_session': True}, + {'change_response_user': True, 'change_session_user': False, 'mismatch_location': 'at response time', + 'change_session': False}, + {'change_response_user': False, 'change_session_user': True, 'mismatch_location': 'in session', + 'change_session': False}, + {'change_response_user': True, 'change_session_user': True, 'mismatch_location': 'both', + 'change_session': False}, + ) + def test_different_user_at_step_2_error(self, mock_cache_set, change_response_user, + change_session_user, mismatch_location, change_session): + new_user = UserFactory() + self.request.safe_cookie_verified_user_id = self.user.id + session_user_id = self.user.id + + if change_response_user: + self.request.user = new_user + if change_session_user: + session_user_id = new_user.id + + self.request.safe_cookie_session_id = "some_other_session" if change_session else "some_session_id" + self.request.session.configure_mock(**{'session_key': 'some_session_id'}) + + log_session_suffix = 'Session id has changed.' if change_session else 'Session id has not changed' + + with patch("openedx.core.djangoapps.safe_sessions.middleware.SafeSessionMiddleware.get_user_id_from_session", + return_value=session_user_id): + if not mismatch_location == 'both': + with self.assert_logged_with_message( + ( + "SafeCookieData user in initial request '{}' does not match user {}: '{}' " + "for request path '{}'. {}" + ).format( + self.MOCK_USER.id, mismatch_location, new_user.id, self.request.path, log_session_suffix + ), + log_level='warning', + ): + self.assert_response(set_request_user=False, set_session_cookie=True) + assert mock_cache_set.called + else: + with self.assert_logged_with_message( + ( + "SafeCookieData user in initial request '{}' does not match user in session: '{}' " + "or user at response time: {} for request path '{}'. {}" + ).format( + self.MOCK_USER.id, new_user.id, new_user.id, self.request.path, log_session_suffix + ), + log_level='warning', + ): + self.assert_response(set_request_user=False, set_session_cookie=True) + assert mock_cache_set.called + + @patch("django.core.cache.cache.set") + def test_anonymous_user(self, mock_cache_set): self.request.safe_cookie_verified_user_id = self.user.id self.request.user = AnonymousUser() self.request.session[SESSION_KEY] = self.user.id with self.assert_no_error_logged(): self.assert_response(set_request_user=False, set_session_cookie=True) + assert not mock_cache_set.called def test_update_cookie_data_at_step_3(self): self.assert_response(set_request_user=True, set_session_cookie=True) @@ -338,11 +410,19 @@ def test_warn_on_user_change(self): # But then user changes unexpectedly self.request.user = UserFactory.create() - with self.assert_logged_for_request_user_mismatch(self.user.id, self.request.user.id, 'warning', '/'): + with self.assert_logged_with_message( + ( + "SafeCookieData user in initial request '{}' does not match user at response time: '{}' " + "for request path '{}'. Session id has not changed" + ).format( + self.user.id, self.request.user.id, self.request.path + ), + log_level='warning', + ): with patch('openedx.core.djangoapps.safe_sessions.middleware.set_custom_attribute') as mock_attr: response = SafeSessionMiddleware().process_response(self.request, self.client.response) - assert response.status_code == 200 - mock_attr.assert_called_with("safe_sessions.user_mismatch", "request-response-mismatch") + assert response.status_code == 200 + mock_attr.assert_called_once_with("safe_sessions.user_mismatch", "request-response-mismatch") def test_no_warn_on_expected_user_change(self): """ diff --git a/openedx/core/djangoapps/safe_sessions/tests/test_utils.py b/openedx/core/djangoapps/safe_sessions/tests/test_utils.py index 7c722f2a1764..aa55af46160a 100644 --- a/openedx/core/djangoapps/safe_sessions/tests/test_utils.py +++ b/openedx/core/djangoapps/safe_sessions/tests/test_utils.py @@ -113,37 +113,3 @@ def assert_invalid_session_id(self): """ with self.assert_logged('SafeCookieData not created due to invalid value for session_id'): yield - - @contextmanager - def assert_logged_for_request_user_mismatch(self, user_at_request, user_at_response, log_level, request_path): - """ - Asserts that warning was logged when request.user - was not equal to user at response - """ - with self.assert_logged_with_message( - ( - "SafeCookieData user at request '{}' does not match user at response: '{}' " - "for request path '{}'" - ).format( - user_at_request, user_at_response, request_path - ), - log_level=log_level, - ): - yield - - @contextmanager - def assert_logged_for_session_user_mismatch(self, user_at_request, user_in_session, request_path): - """ - Asserts that warning was logged when request.user - was not equal to user at session - """ - with self.assert_logged_with_message( - ( - "SafeCookieData user at request '{}' does not match user in session: '{}' " - "for request path '{}'" - ).format( - user_at_request, user_in_session, request_path - ), - log_level='warning', - ): - yield