From d0259ff38e5aa6a8fd9420f57ea4d1197b2d12f9 Mon Sep 17 00:00:00 2001 From: Robert Raposa Date: Thu, 6 Jan 2022 12:15:31 -0500 Subject: [PATCH] fix: enhance safe session monitoring (#29681) * add custom attribute for list of user ids on mismatch. * log request header for all mismatched users for all requests for N seconds after the mismatch is found, if LOG_REQUEST_USER_CHANGE_HEADERS is enabled. See toggle docs for more details. ARCHBOM-1940 --- .../courseware/tests/test_masquerade.py | 2 +- .../djangoapps/safe_sessions/middleware.py | 203 ++++++++++++++---- .../safe_sessions/tests/test_middleware.py | 41 +++- 3 files changed, 203 insertions(+), 43 deletions(-) diff --git a/lms/djangoapps/courseware/tests/test_masquerade.py b/lms/djangoapps/courseware/tests/test_masquerade.py index 00bae9cb43..5fe93f41c0 100644 --- a/lms/djangoapps/courseware/tests/test_masquerade.py +++ b/lms/djangoapps/courseware/tests/test_masquerade.py @@ -656,7 +656,7 @@ class SetupMasqueradeTests(SharedModuleStoreTestCase, ): # Warning: the SafeSessions middleware relies on the `real_user` attribute to see if a # user is masquerading as another user. If the name of this attribute is changing, please update - # the check in SafeSessionMiddleware._verify_user as well. + # the check in SafeSessionMiddleware._verify_user_unchanged as well. assert masquerade_user.real_user == self.staff assert masquerade_user == self.student assert self.request.user.masquerade_settings == masquerade_settings diff --git a/openedx/core/djangoapps/safe_sessions/middleware.py b/openedx/core/djangoapps/safe_sessions/middleware.py index 6dbe2e024f..6ab68475d7 100644 --- a/openedx/core/djangoapps/safe_sessions/middleware.py +++ b/openedx/core/djangoapps/safe_sessions/middleware.py @@ -72,7 +72,7 @@ the entire cookie and use it to impersonate the victim. Custom Attributes: safe_sessions.user_mismatch: 'request-response-mismatch' | 'request-session-mismatch' This attribute can be one of the above two values which correspond to the kind of comparison - that failed when processing the response. See SafeSessionMiddleware._verify_user + that failed when processing the response. See SafeSessionMiddleware._verify_user_and_log_mismatch """ import inspect @@ -86,6 +86,7 @@ from django.contrib.auth.models import AnonymousUser from django.contrib.auth.views import redirect_to_login from django.contrib.sessions.middleware import SessionMiddleware from django.core import signing +from django.core.cache import cache from django.http import HttpResponse from django.utils.crypto import get_random_string from django.utils.deprecation import MiddlewareMixin @@ -93,6 +94,7 @@ from django.utils.deprecation import MiddlewareMixin from edx_django_utils.monitoring import set_custom_attribute from edx_toggles.toggles import SettingToggle +from common.djangoapps.util.log_sensitive import encrypt_for_log from openedx.core.lib.mobile_utils import is_request_from_mobile_app # .. toggle_name: LOG_REQUEST_USER_CHANGES @@ -110,6 +112,23 @@ from openedx.core.lib.mobile_utils import is_request_from_mobile_app # .. toggle_tickets: https://openedx.atlassian.net/browse/ARCHBOM-1718 LOG_REQUEST_USER_CHANGES = getattr(settings, 'LOG_REQUEST_USER_CHANGES', False) +# .. toggle_name: LOG_REQUEST_USER_CHANGE_HEADERS +# .. toggle_implementation: SettingToggle +# .. toggle_default: False +# .. toggle_description: Turn this toggle on to log all request headers, for all requests, for all user ids involved in +# any user id change detected by safe sessions. The headers will provide additional debugging information. The +# headers will be logged for all requests up until LOG_REQUEST_USER_CHANGE_HEADERS_DURATION seconds after +# the time of the last mismatch. The header details will be encrypted, and only available with the private key. +# .. toggle_warnings: To work correctly, LOG_REQUEST_USER_CHANGES must be enabled and ENFORCE_SAFE_SESSIONS must be +# disabled. +# .. toggle_use_cases: opt_in +# .. toggle_creation_date: 2021-12-22 +# .. toggle_tickets: https://openedx.atlassian.net/browse/ARCHBOM-1940 +LOG_REQUEST_USER_CHANGE_HEADERS = SettingToggle('LOG_REQUEST_USER_CHANGE_HEADERS', default=False) + +# Duration in seconds to log user change request headers for additional requests; defaults to 5 minutes +LOG_REQUEST_USER_CHANGE_HEADERS_DURATION = getattr(settings, 'LOG_REQUEST_USER_CHANGE_HEADERS_DURATION', 300) + # .. toggle_name: ENFORCE_SAFE_SESSIONS # .. toggle_implementation: SettingToggle # .. toggle_default: False @@ -352,7 +371,7 @@ class SafeSessionMiddleware(SessionMiddleware, MiddlewareMixin): else: request.COOKIES[settings.SESSION_COOKIE_NAME] = safe_cookie_data.session_id # Step 2 - # Save off for debugging and logging in _verify_user + # Save off for debugging and logging in _verify_user_and_log_mismatch request.cookie_session_field = safe_cookie_data.session_id process_request_response = super().process_request(request) # Step 3 # lint-amnesty, pylint: disable=assignment-from-no-return, super-with-arguments @@ -368,6 +387,9 @@ class SafeSessionMiddleware(SessionMiddleware, MiddlewareMixin): 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: + # Although it is non-obvious, this seems to be early enough + # to track the very first setting of request.user for + # real requests, but not mocked/test requests. track_request_user_changes(request) else: # Return an error or redirect, and don't continue to @@ -401,7 +423,7 @@ class SafeSessionMiddleware(SessionMiddleware, MiddlewareMixin): response = super().process_response(request, response) # Step 1 user_id_in_session = self.get_user_id_from_session(request) - user_matches = self._verify_user(request, response, user_id_in_session) # Step 2 + user_matches = self._verify_user_and_log_mismatch(request, response, user_id_in_session) # Step 2 # If the user changed *unexpectedly* between the beginning and end of # the request (as observed by this middleware) or doesn't match the @@ -459,45 +481,50 @@ class SafeSessionMiddleware(SessionMiddleware, MiddlewareMixin): return HttpResponse(status=401) @staticmethod - def _verify_user(request, response, userid_in_session): + def _verify_user_and_log_mismatch(request, response, userid_in_session): """ - Logs an error if the user marked at the time of process_request - does not match either the current user in the request or the - given userid_in_session. + Logs an error if the user has changed unexpectedly. + + Other side effects: + - Sets a variety of custom attributes for unexpected user changes with + a 'safe_sessions.' prefix, like 'safe_sessions.session_id_changed'. + - May log additional details for users involved in a past unexpected user change, + if toggle is enabled. Uses the cache to track past user changes. Returns True if user matches in all places, False otherwise. """ - # It's expected that a small number of views may change the - # user over the course of the request. We have exemptions for - # the user changing to/from None, but the login view can - # sometimes change the user from one value to another between - # the request and response phases, specifically when the login - # page is used during an active session. - # - # The relevant views set a flag to indicate the exemption. - if getattr(response, 'safe_sessions_expected_user_change', None): + verify_user_results = SafeSessionMiddleware._verify_user_unchanged(request, response, userid_in_session) + if verify_user_results['user_unchanged'] is True: + # all is well; no unexpected user change was found + + try: + + if LOG_REQUEST_USER_CHANGE_HEADERS.is_enabled() and request.user.id is not None: + + # add a session hash custom attribute for all requests to help monitoring + # requests that come both before and after a mistmatch + session_hash = obscure_token(request.cookie_session_field) + set_custom_attribute('safe_sessions.session_id_hash.parsed_cookie', session_hash) + + # log request header if this user id was involved in an earlier mismatch + log_request_headers = cache.get( + SafeSessionMiddleware._get_recent_user_change_cache_key(request.user.id), False + ) + if log_request_headers: + log.info( + f'SafeCookieData request header for {request.user.id}: ' + f'{SafeSessionMiddleware._get_encrypted_request_headers(request)}' + ) + set_custom_attribute('safe_sessions.headers_logged', True) + + except BaseException as e: + log.exception("SafeCookieData error while logging request headers.") + return True - if not hasattr(request, 'safe_cookie_verified_user_id'): - # Skip verification if request didn't come in with a session cookie - return True - - 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 - - # 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 and\ - request.user.id is not None - - # 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 and\ - userid_in_session is not None - - if not (request_user_object_mismatch or session_user_mismatch): - # Great! No mismatch. - return True + # unpack results of an unexpected user change + request_user_object_mismatch = verify_user_results['request_user_object_mismatch'] + session_user_mismatch = verify_user_results['session_user_mismatch'] # Log accumulated information stored on request for each change of user extra_logs = [] @@ -540,6 +567,24 @@ class SafeSessionMiddleware(SessionMiddleware, MiddlewareMixin): 'An unsafe user transition was found. It either needs to be fixed or exempted.\n' + '\n'.join(request.debug_user_changes) ) + + if hasattr(request, 'user_id_list') and request.user_id_list: + user_ids_string = ','.join(str(user_id) for user_id in request.user_id_list) + set_custom_attribute('safe_sessions.user_id_list', user_ids_string) + + if LOG_REQUEST_USER_CHANGE_HEADERS.is_enabled(): + # cache the fact that we should continue logging request headers for these user ids + # for future requests until the cache values timeout. + cache_values = { + SafeSessionMiddleware._get_recent_user_change_cache_key(user_id): True + for user_id in set(request.user_id_list) + } + cache.set_many(cache_values, LOG_REQUEST_USER_CHANGE_HEADERS_DURATION) + + extra_logs.append( + f'Safe session request headers: {SafeSessionMiddleware._get_encrypted_request_headers(request)}' + ) + except BaseException as e: log.exception("SafeCookieData error while computing additional logs.") @@ -577,6 +622,69 @@ class SafeSessionMiddleware(SessionMiddleware, MiddlewareMixin): return False + @staticmethod + def _verify_user_unchanged(request, response, userid_in_session): + """ + Verifies that the user has not unexpectedly changed. + + Verifies that the user marked at the time of process_request + matches both the current user in the request and the provided + userid_in_session. + + Returns dict with the following fields: + user_unchanged: True if user matches in all places, False otherwise. + request_user_object_mismatch: True if the request.user is different + now than it was on the initial request, False otherwise. + session_user_mismatch: True if the current session user is different + than the user in the initial request. False otherwise. + + """ + # default return value + no_mismatch_dict = { + 'user_unchanged': True, + 'request_user_object_mismatch': False, + 'session_user_mismatch': False, + } + + # It's expected that a small number of views may change the + # user over the course of the request. We have exemptions for + # the user changing to/from None, but the login view can + # sometimes change the user from one value to another between + # the request and response phases, specifically when the login + # page is used during an active session. + # + + # The relevant views set a flag to indicate the exemption. + if getattr(response, 'safe_sessions_expected_user_change', None): + return no_mismatch_dict + + if not hasattr(request, 'safe_cookie_verified_user_id'): + # Skip verification if request didn't come in with a session cookie + return no_mismatch_dict + + 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 + + # 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 and\ + request.user.id is not None + + # 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 and\ + userid_in_session is not None + + if not (request_user_object_mismatch or session_user_mismatch): + # Great! No mismatch. + return no_mismatch_dict + + return { + 'user_unchanged': False, + 'request_user_object_mismatch': request_user_object_mismatch, + 'session_user_mismatch': session_user_mismatch, + } + @staticmethod def get_user_id_from_session(request): """ @@ -589,7 +697,7 @@ class SafeSessionMiddleware(SessionMiddleware, MiddlewareMixin): except KeyError: return None - # TODO move to test code, maybe rename, get rid of old Django compat stuff + # TODO move to test code, maybe rename @staticmethod def set_user_id_in_session(request, user): """ @@ -616,6 +724,22 @@ class SafeSessionMiddleware(SessionMiddleware, MiddlewareMixin): # Update the cookie's value with the safe_cookie_data. cookies[settings.SESSION_COOKIE_NAME] = str(safe_cookie_data) + @staticmethod + def _get_recent_user_change_cache_key(user_id): + """ Get cache key for flagging a recent mismatch for the provided user id. """ + return f"safe_sessions.middleware.recent_user_change_detected_{user_id}" + + @staticmethod + def _get_encrypted_request_headers(request): + """ + Return an encrypted version of the request headers preformatted for logging. + + See encrypt_for_log documentation for how to read using private key. + """ + # NOTE: request.headers seems to pick up initial values, but won't adjust as the request object is edited. + # For example, the session cookie will likely be the safe session version. + return encrypt_for_log(str(request.headers), settings.SAFE_SESSIONS_DEBUG_PUBLIC_KEY) + def obscure_token(value: Union[str, None]) -> Union[str, None]: """ @@ -715,11 +839,15 @@ def track_request_user_changes(request): 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'): + # list of string debugging info for each user change (e.g. user id, stack trace, etc.) self.debug_user_changes = [] # pylint: disable=attribute-defined-outside-init + # list of changed user ids + self.user_id_list = [] # pylint: disable=attribute-defined-outside-init if not hasattr(request, name): original_user = value if hasattr(value, 'id'): + self.user_id_list.append(value.id) self.debug_user_changes.append( f"SafeCookieData: Setting for the first time: {value.id!r}\n" f"{location}" @@ -732,6 +860,7 @@ def track_request_user_changes(request): elif value != getattr(request, name): current_user = getattr(request, name) if hasattr(value, 'id'): + self.user_id_list.append(value.id) 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" diff --git a/openedx/core/djangoapps/safe_sessions/tests/test_middleware.py b/openedx/core/djangoapps/safe_sessions/tests/test_middleware.py index 5634aaca4e..2b1657cb57 100644 --- a/openedx/core/djangoapps/safe_sessions/tests/test_middleware.py +++ b/openedx/core/djangoapps/safe_sessions/tests/test_middleware.py @@ -2,7 +2,7 @@ Unit tests for SafeSessionMiddleware """ -from unittest.mock import patch +from unittest.mock import call, patch import ddt from crum import set_current_request @@ -13,7 +13,7 @@ from django.http import HttpResponse, HttpResponseRedirect, SimpleCookie 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 ( @@ -239,7 +239,7 @@ class TestSafeSessionProcessResponse(TestSafeSessionsLogMixin, TestCase): @ddt.ddt -class TestSafeSessionMiddleware(TestSafeSessionsLogMixin, TestCase): +class TestSafeSessionMiddleware(TestSafeSessionsLogMixin, CacheIsolationTestCase): """ Test class for SafeSessionMiddleware, testing both process_request and process_response. @@ -268,7 +268,6 @@ class TestSafeSessionMiddleware(TestSafeSessionsLogMixin, TestCase): Set up request for success path -- everything up until process_response(). """ self.client.login(username=self.user.username, password='test') - self.request.user = self.user session_id = self.client.session.session_key safe_cookie_data = SafeCookieData.create(session_id, self.user.id) @@ -276,6 +275,11 @@ class TestSafeSessionMiddleware(TestSafeSessionsLogMixin, TestCase): with self.assert_not_logged(): response = SafeSessionMiddleware().process_request(self.request) + # Note: setting the user here is later than it really happens, but it enables a + # semi-accurate user change tracking. The only issue is that it changes from + # None to user, rather than being logged as the first time request.user is set, + # as actually happens in Production. + self.request.user = self.user assert response is None assert self.request.safe_cookie_verified_user_id == self.user.id @@ -409,11 +413,13 @@ class TestSafeSessionMiddleware(TestSafeSessionsLogMixin, TestCase): assert ("safe_sessions.user_mismatch", "request-response-and-session-mismatch") in set_attr_call_args @patch("openedx.core.djangoapps.safe_sessions.middleware.LOG_REQUEST_USER_CHANGES", True) - def test_warn_with_verbose_logging(self): + @patch("openedx.core.djangoapps.safe_sessions.middleware.set_custom_attribute") + def test_warn_with_verbose_logging(self, mock_set_custom_attribute): 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) + mock_set_custom_attribute.assert_has_calls([call('safe_sessions.user_id_list', '1,2')]) @patch("openedx.core.djangoapps.safe_sessions.middleware.LOG_REQUEST_USER_CHANGES", False) def test_warn_without_verbose_logging(self): @@ -422,6 +428,31 @@ class TestSafeSessionMiddleware(TestSafeSessionsLogMixin, TestCase): with self.assert_regex_not_logged('SafeCookieData: Changing request user. ', log_level='warning'): SafeSessionMiddleware().process_response(self.request, self.client.response) + @override_settings(LOG_REQUEST_USER_CHANGE_HEADERS=True) + @patch("openedx.core.djangoapps.safe_sessions.middleware.LOG_REQUEST_USER_CHANGES", True) + @patch("openedx.core.djangoapps.safe_sessions.middleware.cache") + def test_with_header_logging(self, mock_cache): + 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) + # Note: Since the test cache is not retaining its values for some reason, we'll + # simply assert that the cache is set (here) and checked (below). + mock_cache.set_many.assert_called_with( + { + 'safe_sessions.middleware.recent_user_change_detected_1': True, + 'safe_sessions.middleware.recent_user_change_detected_2': True + }, 300 + ) + + # send successful request; request header should be logged for earlier mismatched user id + self.set_up_for_success() + SafeSessionMiddleware().process_response(self.request, self.client.response) + # Note: The test cache is not returning True because it is not retaining its values + # for some reason. Rather than asserting that we log the header appropriately, we'll + # simply verify that we are checking the cache. + mock_cache.get.assert_called_with('safe_sessions.middleware.recent_user_change_detected_1', False) + def test_no_warn_on_expected_user_change(self): """ Verifies that no warnings is emitted when the user change is expected.