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
This commit is contained in:
Feanil Patel
@@ -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
|
||||
|
||||
@@ -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]
|
||||
|
||||
Reference in New Issue
Block a user