Merge pull request #27138 from edx/feanil/add_request_user_change_logging

feat: Add more detailed request user change logging.

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

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]

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