diff --git a/openedx/core/djangoapps/safe_sessions/middleware.py b/openedx/core/djangoapps/safe_sessions/middleware.py index ad2bd2cb8a..c8fd952276 100644 --- a/openedx/core/djangoapps/safe_sessions/middleware.py +++ b/openedx/core/djangoapps/safe_sessions/middleware.py @@ -96,9 +96,13 @@ from openedx.core.lib.mobile_utils import is_request_from_mobile_app # .. 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 provide additional debugging information in the case of a user +# verification error. It will track anytime the `user` attribute of a request object is changed and store this +# information on the request. This will also track the location where the change is coming from to quickly find +# issues. If user verification fails at response time, all of the information about these +# changes will be logged. +# .. toggle_warnings: Adds some processing overhead to all requests to gather debug info. Will also double the logging +# for failed verification checks. # .. toggle_use_cases: opt_in # .. toggle_creation_date: 2021-03-25 # .. toggle_tickets: https://openedx.atlassian.net/browse/ARCHBOM-1718 @@ -316,13 +320,16 @@ class SafeSessionMiddleware(SessionMiddleware, MiddlewareMixin): # return the response. return process_request_response + # Note: request.session.get(SESSION_KEY) and request.session.session_key are different things. The former + # contains the session user, the latter is the session id if cookie_data_string and request.session.get(SESSION_KEY): 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 + request.safe_cookie_verified_session_id = request.session.session_key if LOG_REQUEST_USER_CHANGES: - log_request_user_changes(request) + track_request_user_changes(request) else: # Return an error or redirect, and don't continue to # the underlying view. @@ -412,30 +419,57 @@ class SafeSessionMiddleware(SessionMiddleware, MiddlewareMixin): # 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") + + # determine if the request.user is different now than it was on the initial request + request_user_object_mismatch = request.safe_cookie_verified_user_id != request.user.id + + # determine if the current session user is different than the user in the initial request + session_user_mismatch = request.safe_cookie_verified_user_id != userid_in_session + + if request_user_object_mismatch or session_user_mismatch: + # Log accumulated information stored on request for each change of user + if hasattr(request, 'debug_user_changes'): + log.warning('An unsafe user transition was found. It either needs to be fixed or exempted.\n {}' + .format('\n'.join(request.debug_user_changes))) + + session_id_changed = hasattr(request.session, 'session_key') and\ + request.safe_cookie_verified_session_id != request.session.session_key + # delete old session id for security + del request.safe_cookie_verified_session_id + + log_suffix = 'Session changed.' if session_id_changed else 'Session did not change.' + + if request_user_object_mismatch and not session_user_mismatch: + log.warning( + ( + "SafeCookieData user at 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_suffix + ), + ) + set_custom_attribute("safe_sessions.user_mismatch", "request-response-mismatch") + elif session_user_mismatch and not request_user_object_mismatch: + log.warning( + ( + "SafeCookieData user at 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_suffix + ), + ) + set_custom_attribute("safe_sessions.user_mismatch", "request-session-mismatch") + else: + log.warning( + ( + "SafeCookieData user at initial request '{}' matches neither user in session: '{}' " + "nor 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_suffix + ), + ) + set_custom_attribute("safe_sessions.user_mismatch", "request-response-and-session-mismatch") @staticmethod def get_user_id_from_session(request): @@ -542,12 +576,12 @@ def _delete_cookie(request, response): ) -def log_request_user_changes(request): +def track_request_user_changes(request): """ - Instrument the request object so that we log changes to the `user` attribute. This is done by - changing the `__class__` attribute of the request object to point to a new class we created - on the fly which is exactly the same as the underlying request class but with an override for - the `__setattr__` function to catch the attribute chages. + Instrument the request object so that we store changes to the `user` attribute for future logging + if needed for debugging user mismatches. This is done by changing the `__class__` attribute of the request + object to point to a new class we created on the fly which is exactly the same as the underlying request class but + with an override for the `__setattr__` function to catch the attribute changes. """ original_user = getattr(request, 'user', None) @@ -563,28 +597,31 @@ def log_request_user_changes(request): # Written this way in case you need more of the stack for debugging. location = "\n".join("%30s : %s:%d" % (t[3], t[1], t[2]) for t in stack[0:12]) + if not hasattr(self, 'debug_user_changes'): + self.debug_user_changes = [] # pylint: disable=attribute-defined-outside-init + if not hasattr(request, name): original_user = value if hasattr(value, 'id'): - log.info( + self.debug_user_changes.append( f"SafeCookieData: Setting for the first time: {value.id!r}\n" f"{location}" ) else: - log.info( + self.debug_user_changes.append( f"SafeCookieData: Setting for the first time, but user has no id: {value!r}\n" f"{location}" ) elif value != getattr(request, name): current_user = getattr(request, name) if hasattr(value, 'id'): - log.info( + self.debug_user_changes.append( f"SafeCookieData: Changing request user. " f"Originally {original_user.id!r}, now {current_user.id!r} and will become {value.id!r}\n" f"{location}" ) else: - log.info( + self.debug_user_changes.append( f"SafeCookieData: Changing request user but user has no id. " f"Originally {original_user!r}, now {current_user!r} and will become {value!r}\n" f"{location}" diff --git a/openedx/core/djangoapps/safe_sessions/tests/test_middleware.py b/openedx/core/djangoapps/safe_sessions/tests/test_middleware.py index ce49f5bd95..b65da7e93e 100644 --- a/openedx/core/djangoapps/safe_sessions/tests/test_middleware.py +++ b/openedx/core/djangoapps/safe_sessions/tests/test_middleware.py @@ -17,7 +17,7 @@ from django.test.utils import override_settings from openedx.core.djangolib.testing.utils import get_mock_request 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, track_request_user_changes, mark_user_change_as_expected from .test_utils import TestSafeSessionsLogMixin @@ -72,7 +72,7 @@ class TestSafeSessionProcessRequest(TestSafeSessionsLogMixin, TestCase): 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") + @patch("openedx.core.djangoapps.safe_sessions.middleware.track_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 @@ -99,7 +99,7 @@ class TestSafeSessionProcessRequest(TestSafeSessionsLogMixin, TestCase): 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") + @patch("openedx.core.djangoapps.safe_sessions.middleware.track_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 @@ -192,22 +192,15 @@ class TestSafeSessionProcessResponse(TestSafeSessionsLogMixin, TestCase): with self.assert_not_logged(): self.assert_response(set_request_user=True, set_session_cookie=True) + # error case is tested in TestSafeSessionMiddleware since it requires more setup def test_confirm_user_at_step_2(self): 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): self.request.safe_cookie_verified_user_id = self.user.id + self.request.safe_cookie_verified_session_id = '1' self.request.user = AnonymousUser() self.request.session[SESSION_KEY] = self.user.id with self.assert_no_error_logged(): @@ -328,7 +321,7 @@ class TestSafeSessionMiddleware(TestSafeSessionsLogMixin, TestCase): self.request.META = {'HTTP_USER_AGENT': 'open edX Mobile App Version 2.1'} self.verify_error(401) - def test_warn_on_user_change(self): + def test_warn_on_user_change_before_response(self): """ Verifies that warnings are emitted and custom attributes set if the user changes unexpectedly between request and response. @@ -338,12 +331,57 @@ class TestSafeSessionMiddleware(TestSafeSessionsLogMixin, TestCase): # 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_for_request_user_mismatch(self.user.id, self.request.user.id, 'warning', '/', False): 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") + def test_warn_on_user_change_from_session(self): + """ + Verifies that warnings are emitted and custom attributes set if + the user in the request does not match the user in the session. + """ + self.set_up_for_success() + different_user = UserFactory() + SafeSessionMiddleware.set_user_id_in_session(self.request, different_user) + with self.assert_logged_for_session_user_mismatch(self.user.id, different_user.id, self.request.path, + False): + 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-session-mismatch") + + def test_warn_on_user_change_in_both(self): + """ + Verifies that warnings are emitted and custom attributes set if + the user in the initial request does not match the user at response time or the user in the session. + """ + self.set_up_for_success() + different_user = UserFactory() + SafeSessionMiddleware.set_user_id_in_session(self.request, different_user) + self.request.user = UserFactory.create() + with self.assert_logged_for_both_mismatch(self.user.id, different_user.id, + self.request.user.id, self.request.path, False): + 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-and-session-mismatch") + + @patch("openedx.core.djangoapps.safe_sessions.middleware.LOG_REQUEST_USER_CHANGES", True) + def test_warn_with_verbose_logging(self): + self.set_up_for_success() + self.request.user = UserFactory.create() + with self.assert_logged('SafeCookieData: Changing request user. ', log_level='warning'): + SafeSessionMiddleware().process_response(self.request, self.client.response) + + @patch("openedx.core.djangoapps.safe_sessions.middleware.LOG_REQUEST_USER_CHANGES", False) + def test_warn_without_verbose_logging(self): + self.set_up_for_success() + self.request.user = UserFactory.create() + with self.assert_regex_not_logged('SafeCookieData: Changing request user. ', log_level='warning'): + SafeSessionMiddleware().process_response(self.request, self.client.response) + def test_no_warn_on_expected_user_change(self): """ Verifies that no warnings is emitted when the user change is expected. @@ -365,7 +403,7 @@ class TestSafeSessionMiddleware(TestSafeSessionsLogMixin, TestCase): @ddt.ddt -class TestLogRequestUserChanges(TestCase): +class TestTrackRequestUserChanges(TestCase): """ Test the function that instruments a request object. @@ -373,51 +411,46 @@ class TestLogRequestUserChanges(TestCase): that the correct messages are written. """ - @patch("openedx.core.djangoapps.safe_sessions.middleware.log.info") - def test_initial_user_setting_logging(self, mock_log): + def test_initial_user_setting_tracking(self): request = get_mock_request() del request.user - log_request_user_changes(request) + track_request_user_changes(request) request.user = UserFactory.create() - assert mock_log.called - assert "Setting for the first time" in mock_log.call_args[0][0] + assert "Setting for the first time" in request.debug_user_changes[0] - @patch("openedx.core.djangoapps.safe_sessions.middleware.log.info") - def test_user_change_logging(self, mock_log): + def test_user_change_logging(self): request = get_mock_request() original_user = UserFactory.create() new_user = UserFactory.create() request.user = original_user - log_request_user_changes(request) + track_request_user_changes(request) # Verify that we don't log if set to same as current value. request.user = original_user - assert not mock_log.called + assert len(request.debug_user_changes) == 0 # Verify logging on change. request.user = new_user - assert mock_log.called - assert f"Changing request user. Originally {original_user.id!r}" in mock_log.call_args[0][0] - assert f"will become {new_user.id!r}" in mock_log.call_args[0][0] + assert len(request.debug_user_changes) == 1 + assert f"Changing request user. Originally {original_user.id!r}" in request.debug_user_changes[0] + assert f"will become {new_user.id!r}" in request.debug_user_changes[0] # Verify change back logged. request.user = original_user - assert mock_log.call_count == 2 + assert len(request.debug_user_changes) == 2 expected_msg = f"Originally {original_user.id!r}, now {new_user.id!r} and will become {original_user.id!r}" - assert expected_msg in mock_log.call_args[0][0] + assert expected_msg in request.debug_user_changes[1] - @patch("openedx.core.djangoapps.safe_sessions.middleware.log.info") - def test_user_change_with_no_ids(self, mock_log): + def test_user_change_with_no_ids(self): request = get_mock_request() del request.user - log_request_user_changes(request) + track_request_user_changes(request) request.user = object() - assert mock_log.called - assert "Setting for the first time, but user has no id" in mock_log.call_args[0][0] + assert "Setting for the first time, but user has no id" in request.debug_user_changes[0] request.user = object() - assert mock_log.call_count == 2 - assert "Changing request user but user has no id." in mock_log.call_args[0][0] + assert len(request.debug_user_changes) == 2 + assert "Changing request user but user has no id." in request.debug_user_changes[1] diff --git a/openedx/core/djangoapps/safe_sessions/tests/test_utils.py b/openedx/core/djangoapps/safe_sessions/tests/test_utils.py index 7c722f2a17..c6c1977a50 100644 --- a/openedx/core/djangoapps/safe_sessions/tests/test_utils.py +++ b/openedx/core/djangoapps/safe_sessions/tests/test_utils.py @@ -1,8 +1,7 @@ """ Shared test utilities for Safe Sessions tests """ - - +import pytest from contextlib import contextmanager from unittest.mock import patch @@ -23,6 +22,16 @@ class TestSafeSessionsLogMixin: assert mock_log.called self.assertRegex(mock_log.call_args_list[0][0][0], log_string) + @contextmanager + def assert_regex_not_logged(self, log_string, log_level): + """ + Asserts that the logger was not called with the given + log_level and with a regex of the given string. + """ + with pytest.raises(AssertionError): + with self.assert_logged(log_string, log_level=log_level): + yield + @contextmanager def assert_logged_with_message(self, log_string, log_level='error'): """ @@ -115,34 +124,58 @@ class TestSafeSessionsLogMixin: yield @contextmanager - def assert_logged_for_request_user_mismatch(self, user_at_request, user_at_response, log_level, request_path): + def assert_logged_for_request_user_mismatch(self, user_at_request, user_at_response, log_level, request_path, + session_changed): """ Asserts that warning was logged when request.user was not equal to user at response """ + session_suffix = 'Session changed.' if session_changed else 'Session did not change.' with self.assert_logged_with_message( ( - "SafeCookieData user at request '{}' does not match user at response: '{}' " - "for request path '{}'" + "SafeCookieData user at initial request '{}' does not match user at response time: '{}' " + "for request path '{}'. {}" ).format( - user_at_request, user_at_response, request_path + user_at_request, user_at_response, request_path, session_suffix ), log_level=log_level, ): yield @contextmanager - def assert_logged_for_session_user_mismatch(self, user_at_request, user_in_session, request_path): + def assert_logged_for_session_user_mismatch(self, user_at_request, user_in_session, request_path, session_changed): """ Asserts that warning was logged when request.user was not equal to user at session """ + session_suffix = 'Session changed.' if session_changed else 'Session did not change.' + with self.assert_logged_with_message( ( - "SafeCookieData user at request '{}' does not match user in session: '{}' " - "for request path '{}'" + "SafeCookieData user at initial request '{}' does not match user in session: '{}' " + "for request path '{}'. {}" ).format( - user_at_request, user_in_session, request_path + user_at_request, user_in_session, request_path, session_suffix + ), + log_level='warning', + ): + yield + + @contextmanager + def assert_logged_for_both_mismatch(self, user_at_request, user_in_session, user_at_response, request_path, + session_changed): + """ + Asserts that warning was logged when request.user + was not equal to user at session + """ + session_suffix = 'Session changed.' if session_changed else 'Session did not change.' + + with self.assert_logged_with_message( + ( + "SafeCookieData user at initial request '{}' matches neither user in session: '{}' " + "nor user at response time: '{}' for request path '{}'. {}" + ).format( + user_at_request, user_in_session, user_at_response, request_path, session_suffix ), log_level='warning', ):