From 0714ac5f0ee21c237ca89fe4bb5aa17866208059 Mon Sep 17 00:00:00 2001 From: Feanil Patel Date: Wed, 24 Mar 2021 16:36:27 -0400 Subject: [PATCH 1/3] feat: Add more detailed request user change logging. The change is behind a WafleFlag and can be turned on to log every time the `user` attribute of an instrumented request changes. This will significantly increase log volume so it shouldn't be left on all the time but can be turned on to quickly debug issues related to sessions. Ticket: https://openedx.atlassian.net/browse/ARCHBOM-1718 --- .../djangoapps/safe_sessions/middleware.py | 72 ++++++++++++++++- .../safe_sessions/tests/test_middleware.py | 81 ++++++++++++++++++- 2 files changed, 150 insertions(+), 3 deletions(-) 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] From c2eabf6ccaf941c414bfe37758e2e5b16b68c850 Mon Sep 17 00:00:00 2001 From: Feanil Patel Date: Thu, 25 Mar 2021 10:27:26 -0400 Subject: [PATCH 2/3] test: Update query counts. The new WaffleFlag.is_enabled check in middleware increased query counts for multiple tests. --- lms/djangoapps/course_api/tests/test_views.py | 2 +- .../djangoapps/user_api/accounts/tests/test_views.py | 12 ++++++------ 2 files changed, 7 insertions(+), 7 deletions(-) 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/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 From 4f9fe5973131a7c3f0e390a60229d93d98804690 Mon Sep 17 00:00:00 2001 From: Feanil Patel Date: Thu, 25 Mar 2021 13:13:05 -0400 Subject: [PATCH 3/3] test: Fix date tests that rely on user preference. The function under test by the StrftimeLocalizedHtmlTest checks the timezone in the user preferences of the user making the request. If we don't explicitly set a request here, it will simply use the last Request that `crum` cached in the thread local cache. This broke now that we sometimes set the crum request.user to an invalid user in other tests. This change ensures that we have a valid request for these tests as a part of the setup of this test class. --- common/djangoapps/util/tests/test_date_utils.py | 9 +++++++++ 1 file changed, 9 insertions(+) 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',