diff --git a/common/djangoapps/util/tests/test_date_utils.py b/common/djangoapps/util/tests/test_date_utils.py index 2e64ae622d..2e7c581a70 100644 --- a/common/djangoapps/util/tests/test_date_utils.py +++ b/common/djangoapps/util/tests/test_date_utils.py @@ -6,11 +6,14 @@ import unittest from datetime import datetime, timedelta, tzinfo from unittest.mock import patch +import crum import ddt import pytest from markupsafe import Markup from pytz import utc +from django.test.client import RequestFactory + from common.djangoapps.util.date_utils import ( almost_same_datetime, get_default_time_display, get_time_display, strftime_localized, strftime_localized_html ) @@ -217,6 +220,12 @@ class StrftimeLocalizedHtmlTest(unittest.TestCase): """ Tests for strftime_localized_html. """ + def setUp(self): + super().setUp() + request = RequestFactory().request() + self.addCleanup(crum.set_current_request, None) + crum.set_current_request(request) + @ddt.data( None, 'Africa/Casablanca', diff --git a/lms/djangoapps/course_api/tests/test_views.py b/lms/djangoapps/course_api/tests/test_views.py index 6b8a1a7737..bc7496930d 100644 --- a/lms/djangoapps/course_api/tests/test_views.py +++ b/lms/djangoapps/course_api/tests/test_views.py @@ -387,7 +387,7 @@ class CourseListSearchViewTest(CourseApiTestViewMixin, ModuleStoreTestCase, Sear self.setup_user(self.audit_user) # These query counts were found empirically - query_counts = [54, 46, 46, 46, 46, 46, 46, 46, 46, 46, 16] + query_counts = [55, 46, 46, 46, 46, 46, 46, 46, 46, 46, 16] ordered_course_ids = sorted([str(cid) for cid in (course_ids + [c.id for c in self.courses])]) self.clear_caches() diff --git a/openedx/core/djangoapps/safe_sessions/middleware.py b/openedx/core/djangoapps/safe_sessions/middleware.py index 94ff67adef..1febfc0ba3 100644 --- a/openedx/core/djangoapps/safe_sessions/middleware.py +++ b/openedx/core/djangoapps/safe_sessions/middleware.py @@ -60,7 +60,7 @@ Custom Attributes: that failed when processing the response. See SafeSessionMiddleware._verify_user """ - +import inspect from base64 import b64encode from contextlib import contextmanager from hashlib import sha256 @@ -76,9 +76,22 @@ from django.utils.crypto import get_random_string from django.utils.deprecation import MiddlewareMixin from django.utils.encoding import python_2_unicode_compatible from edx_django_utils.monitoring import set_custom_attribute +from edx_toggles.toggles import WaffleFlag from openedx.core.lib.mobile_utils import is_request_from_mobile_app +# .. toggle_name: safe_session.log_request_user_changes +# .. toggle_implementation: WaffleFlag +# .. 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_use_cases: temporary +# .. toggle_creation_date: 2021-03-25 +# .. toggle_target_removal_date: 2021-05-01 +# .. toggle_tickets: https://openedx.atlassian.net/browse/ARCHBOM-1718 +LOG_REQUEST_USER_CHANGES_FLAG = WaffleFlag('safe_session.log_request_user_changes', __name__) + log = getLogger(__name__) @@ -295,6 +308,8 @@ class SafeSessionMiddleware(SessionMiddleware, MiddlewareMixin): 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_FLAG.is_enabled(): + log_request_user_changes(request) else: return self._on_user_authentication_failed(request) @@ -501,6 +516,61 @@ def _delete_cookie(request, response): ) +def log_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. + """ + original_user = getattr(request, 'user', None) + + class SafeSessionRequestWrapper(request.__class__): + """ + A wrapper class for the request object. + """ + + def __setattr__(self, name, value): + nonlocal original_user + if name == 'user': + stack = inspect.stack() + # 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[1:2]) + + if not hasattr(request, name): + original_user = value + if hasattr(value, 'id'): + log.info( + f"SafeCookieData: Setting for the first time: {value.id!r}\n" + f"{location}" + ) + else: + log.info( + 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( + 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( + 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}" + ) + + else: + # Value being set but not actually changing. + pass + return super().__setattr__(name, value) + request.__class__ = SafeSessionRequestWrapper + + def _is_from_logout(request): """ Returns whether the request has come from logout action to see if diff --git a/openedx/core/djangoapps/safe_sessions/tests/test_middleware.py b/openedx/core/djangoapps/safe_sessions/tests/test_middleware.py index d58f8f3832..c1e99ce93c 100644 --- a/openedx/core/djangoapps/safe_sessions/tests/test_middleware.py +++ b/openedx/core/djangoapps/safe_sessions/tests/test_middleware.py @@ -5,6 +5,7 @@ Unit tests for SafeSessionMiddleware from unittest.mock import patch import ddt + from crum import set_current_request from django.conf import settings from django.contrib.auth import SESSION_KEY @@ -16,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 +from ..middleware import SafeCookieData, SafeSessionMiddleware, log_request_user_changes from .test_utils import TestSafeSessionsLogMixin @@ -70,7 +71,10 @@ class TestSafeSessionProcessRequest(TestSafeSessionsLogMixin, TestCase): """ assert SafeSessionMiddleware.get_user_id_from_session(self.request) == self.user.id - def test_success(self): + @patch("openedx.core.djangoapps.safe_sessions.middleware.log_request_user_changes") + @patch("openedx.core.djangoapps.safe_sessions.middleware.LOG_REQUEST_USER_CHANGES_FLAG") + def test_success(self, mock_log_request_user_changes_flag, mock_log_request_user_changes): + mock_log_request_user_changes_flag.is_enabled.return_value = False 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) @@ -92,6 +96,20 @@ class TestSafeSessionProcessRequest(TestSafeSessionsLogMixin, TestCase): # 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") + @patch("openedx.core.djangoapps.safe_sessions.middleware.LOG_REQUEST_USER_CHANGES_FLAG") + def test_log_request_user_flag_on(self, mock_log_request_user_changes_flag, mock_log_request_user_changes): + mock_log_request_user_changes_flag.is_enabled.return_value = True + 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 + def test_success_no_cookies(self): self.assert_response() self.assert_no_user_in_session() @@ -306,3 +324,62 @@ class TestSafeSessionMiddleware(TestSafeSessionsLogMixin, TestCase): def test_error_from_mobile_app(self): self.request.META = {'HTTP_USER_AGENT': 'open edX Mobile App Version 2.1'} self.verify_error(401) + + +@ddt.ddt +class TestLogRequestUserChanges(TestCase): + """ + Test the function that instruments a request object. + + Ensure that we are logging changes to the 'user' attribute and + that the correct messages are written. + """ + + @patch("openedx.core.djangoapps.safe_sessions.middleware.log.info") + def test_initial_user_setting_logging(self, mock_log): + request = get_mock_request() + del request.user + log_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] + + @patch("openedx.core.djangoapps.safe_sessions.middleware.log.info") + def test_user_change_logging(self, mock_log): + request = get_mock_request() + original_user = UserFactory.create() + new_user = UserFactory.create() + + request.user = original_user + log_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 + + # 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] + + # Verify change back logged. + request.user = original_user + assert mock_log.call_count == 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] + + @patch("openedx.core.djangoapps.safe_sessions.middleware.log.info") + def test_user_change_with_no_ids(self, mock_log): + request = get_mock_request() + del request.user + + log_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] + + 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] diff --git a/openedx/core/djangoapps/user_api/accounts/tests/test_views.py b/openedx/core/djangoapps/user_api/accounts/tests/test_views.py index c3e2fa9dd8..6f7fa8e889 100644 --- a/openedx/core/djangoapps/user_api/accounts/tests/test_views.py +++ b/openedx/core/djangoapps/user_api/accounts/tests/test_views.py @@ -171,7 +171,7 @@ class TestOwnUsernameAPI(CacheIsolationTestCase, UserAPITestCase): Test that a client (logged in) can get her own username. """ self.client.login(username=self.user.username, password=TEST_PASSWORD) - self._verify_get_own_username(17) + self._verify_get_own_username(18) def test_get_username_inactive(self): """ @@ -181,7 +181,7 @@ class TestOwnUsernameAPI(CacheIsolationTestCase, UserAPITestCase): self.client.login(username=self.user.username, password=TEST_PASSWORD) self.user.is_active = False self.user.save() - self._verify_get_own_username(17) + self._verify_get_own_username(18) def test_get_username_not_logged_in(self): """ @@ -355,7 +355,7 @@ class TestAccountsAPI(CacheIsolationTestCase, UserAPITestCase): """ self.different_client.login(username=self.different_user.username, password=TEST_PASSWORD) self.create_mock_profile(self.user) - with self.assertNumQueries(24): + with self.assertNumQueries(25): response = self.send_get(self.different_client) self._verify_full_shareable_account_response(response, account_privacy=ALL_USERS_VISIBILITY) @@ -370,7 +370,7 @@ class TestAccountsAPI(CacheIsolationTestCase, UserAPITestCase): """ self.different_client.login(username=self.different_user.username, password=TEST_PASSWORD) self.create_mock_profile(self.user) - with self.assertNumQueries(24): + with self.assertNumQueries(25): response = self.send_get(self.different_client) self._verify_private_account_response(response) @@ -517,7 +517,7 @@ class TestAccountsAPI(CacheIsolationTestCase, UserAPITestCase): assert data['accomplishments_shared'] is False self.client.login(username=self.user.username, password=TEST_PASSWORD) - verify_get_own_information(22) + verify_get_own_information(23) # Now make sure that the user can get the same information, even if not active self.user.is_active = False @@ -537,7 +537,7 @@ class TestAccountsAPI(CacheIsolationTestCase, UserAPITestCase): legacy_profile.save() self.client.login(username=self.user.username, password=TEST_PASSWORD) - with self.assertNumQueries(22): + with self.assertNumQueries(23): response = self.send_get(self.client) for empty_field in ("level_of_education", "gender", "country", "state", "bio",): assert response.data[empty_field] is None