Andal.LND/edx-platform
6
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

feat: only log requests that fail user verification in SafeSessionMiddleware (#29028)

Browse Source 
* feat: only log requests that fail user verification in SafeSessionMiddleware
ARCHBOM-1923
This commit is contained in:
Rebecca Graber
2021-10-15 10:52:13 -04:00
committed by GitHub
parent 03bf61da8d
commit 2200b5382e
3 changed files with 186 additions and 83 deletions
Download Patch File Download Diff File Expand all files Collapse all files

111
openedx/core/djangoapps/safe_sessions/middleware.py
View File

@@ -96,9 +96,13 @@ from openedx.core.lib.mobile_utils import is_request_from_mobile_app
# .. toggle_name: LOG_REQUEST_USER_CHANGES
# .. toggle_implementation: SettingToggle
# .. 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_description: Turn this toggle on to provide additional debugging information in the case of a user
# verification error. It will track anytime the `user` attribute of a request object is changed and store this
# information on the request. This will also track the location where the change is coming from to quickly find
# issues. If user verification fails at response time, all of the information about these
# changes will be logged.
# .. toggle_warnings: Adds some processing overhead to all requests to gather debug info. Will also double the logging
# for failed verification checks.
# .. toggle_use_cases: opt_in
# .. toggle_creation_date: 2021-03-25
# .. toggle_tickets: https://openedx.atlassian.net/browse/ARCHBOM-1718
@@ -316,13 +320,16 @@ class SafeSessionMiddleware(SessionMiddleware, MiddlewareMixin):
# return the response.
return process_request_response
# Note: request.session.get(SESSION_KEY) and request.session.session_key are different things. The former
# contains the session user, the latter is the session id
if cookie_data_string and request.session.get(SESSION_KEY):
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
request.safe_cookie_verified_session_id = request.session.session_key
if LOG_REQUEST_USER_CHANGES:
log_request_user_changes(request)
track_request_user_changes(request)
else:
# Return an error or redirect, and don't continue to
# the underlying view.
@@ -412,30 +419,57 @@ class SafeSessionMiddleware(SessionMiddleware, MiddlewareMixin):
# 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
# The user at response time is expected to be None when the user
# is logging out. We won't log that.
if request.safe_cookie_verified_user_id != request.user.id and request.user.id is not None:
log.warning(
(
"SafeCookieData user at request '{}' does not match user at response: '{}' "
"for request path '{}'"
).format( # pylint: disable=logging-format-interpolation
request.safe_cookie_verified_user_id, request.user.id, request.path,
),
)
set_custom_attribute("safe_sessions.user_mismatch", "request-response-mismatch")
# The user session at response time is expected to be None when the user
# is logging out. We won't log that.
if request.safe_cookie_verified_user_id != userid_in_session and userid_in_session is not None:
log.warning(
(
"SafeCookieData user at request '{}' does not match user in session: '{}' "
"for request path '{}'"
).format( # pylint: disable=logging-format-interpolation
request.safe_cookie_verified_user_id, userid_in_session, request.path,
),
)
set_custom_attribute("safe_sessions.user_mismatch", "request-session-mismatch")
# 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
# 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
if request_user_object_mismatch or session_user_mismatch:
# Log accumulated information stored on request for each change of user
if hasattr(request, 'debug_user_changes'):
log.warning('An unsafe user transition was found. It either needs to be fixed or exempted.\n {}'
.format('\n'.join(request.debug_user_changes)))
session_id_changed = hasattr(request.session, 'session_key') and\
request.safe_cookie_verified_session_id != request.session.session_key
# delete old session id for security
del request.safe_cookie_verified_session_id
log_suffix = 'Session changed.' if session_id_changed else 'Session did not change.'
if request_user_object_mismatch and not session_user_mismatch:
log.warning(
(
"SafeCookieData user at initial request '{}' does not match user at response time: '{}' "
"for request path '{}'. {}"
).format( # pylint: disable=logging-format-interpolation
request.safe_cookie_verified_user_id, request.user.id, request.path, log_suffix
),
)
set_custom_attribute("safe_sessions.user_mismatch", "request-response-mismatch")
elif session_user_mismatch and not request_user_object_mismatch:
log.warning(
(
"SafeCookieData user at initial request '{}' does not match user in session: '{}' "
"for request path '{}'. {}"
).format( # pylint: disable=logging-format-interpolation
request.safe_cookie_verified_user_id, userid_in_session, request.path, log_suffix
),
)
set_custom_attribute("safe_sessions.user_mismatch", "request-session-mismatch")
else:
log.warning(
(
"SafeCookieData user at initial request '{}' matches neither user in session: '{}' "
"nor user at response time: '{}' for request path '{}'. {}"
).format( # pylint: disable=logging-format-interpolation
request.safe_cookie_verified_user_id, userid_in_session, request.user.id, request.path,
log_suffix
),
)
set_custom_attribute("safe_sessions.user_mismatch", "request-response-and-session-mismatch")
@staticmethod
def get_user_id_from_session(request):
@@ -542,12 +576,12 @@ def _delete_cookie(request, response):
)
def log_request_user_changes(request):
def track_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.
Instrument the request object so that we store changes to the `user` attribute for future logging
if needed for debugging user mismatches. 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 changes.
"""
original_user = getattr(request, 'user', None)
@@ -563,28 +597,31 @@ def log_request_user_changes(request):
# 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[0:12])
if not hasattr(self, 'debug_user_changes'):
self.debug_user_changes = [] # pylint: disable=attribute-defined-outside-init
if not hasattr(request, name):
original_user = value
if hasattr(value, 'id'):
log.info(
self.debug_user_changes.append(
f"SafeCookieData: Setting for the first time: {value.id!r}\n"
f"{location}"
)
else:
log.info(
self.debug_user_changes.append(
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(
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"
f"{location}"
)
else:
log.info(
self.debug_user_changes.append(
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}"

105
openedx/core/djangoapps/safe_sessions/tests/test_middleware.py
View File

@@ -17,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, log_request_user_changes, mark_user_change_as_expected
from ..middleware import SafeCookieData, SafeSessionMiddleware, track_request_user_changes, mark_user_change_as_expected
from .test_utils import TestSafeSessionsLogMixin
@@ -72,7 +72,7 @@ class TestSafeSessionProcessRequest(TestSafeSessionsLogMixin, TestCase):
assert SafeSessionMiddleware.get_user_id_from_session(self.request) == self.user.id
@patch("openedx.core.djangoapps.safe_sessions.middleware.LOG_REQUEST_USER_CHANGES", False)
@patch("openedx.core.djangoapps.safe_sessions.middleware.log_request_user_changes")
@patch("openedx.core.djangoapps.safe_sessions.middleware.track_request_user_changes")
def test_success(self, mock_log_request_user_changes):
self.client.login(username=self.user.username, password='test')
session_id = self.client.session.session_key
@@ -99,7 +99,7 @@ class TestSafeSessionProcessRequest(TestSafeSessionsLogMixin, TestCase):
assert not mock_log_request_user_changes.called
@patch("openedx.core.djangoapps.safe_sessions.middleware.LOG_REQUEST_USER_CHANGES", True)
@patch("openedx.core.djangoapps.safe_sessions.middleware.log_request_user_changes")
@patch("openedx.core.djangoapps.safe_sessions.middleware.track_request_user_changes")
def test_log_request_user_on(self, mock_log_request_user_changes):
self.client.login(username=self.user.username, password='test')
session_id = self.client.session.session_key
@@ -192,22 +192,15 @@ class TestSafeSessionProcessResponse(TestSafeSessionsLogMixin, TestCase):
with self.assert_not_logged():
self.assert_response(set_request_user=True, set_session_cookie=True)
# error case is tested in TestSafeSessionMiddleware since it requires more setup
def test_confirm_user_at_step_2(self):
self.request.safe_cookie_verified_user_id = self.user.id
with self.assert_not_logged():
self.assert_response(set_request_user=True, set_session_cookie=True)
def test_different_user_at_step_2_error(self):
self.request.safe_cookie_verified_user_id = "different_user"
with self.assert_logged_for_request_user_mismatch("different_user", self.user.id, 'warning', self.request.path):
self.assert_response(set_request_user=True, set_session_cookie=True)
with self.assert_logged_for_session_user_mismatch("different_user", self.user.id, self.request.path):
self.assert_response(set_request_user=True, set_session_cookie=True)
def test_anonymous_user(self):
self.request.safe_cookie_verified_user_id = self.user.id
self.request.safe_cookie_verified_session_id = '1'
self.request.user = AnonymousUser()
self.request.session[SESSION_KEY] = self.user.id
with self.assert_no_error_logged():
@@ -328,7 +321,7 @@ class TestSafeSessionMiddleware(TestSafeSessionsLogMixin, TestCase):
self.request.META = {'HTTP_USER_AGENT': 'open edX Mobile App Version 2.1'}
self.verify_error(401)
def test_warn_on_user_change(self):
def test_warn_on_user_change_before_response(self):
"""
Verifies that warnings are emitted and custom attributes set if
the user changes unexpectedly between request and response.
@@ -338,12 +331,57 @@ class TestSafeSessionMiddleware(TestSafeSessionsLogMixin, TestCase):
# But then user changes unexpectedly
self.request.user = UserFactory.create()
with self.assert_logged_for_request_user_mismatch(self.user.id, self.request.user.id, 'warning', '/'):
with self.assert_logged_for_request_user_mismatch(self.user.id, self.request.user.id, 'warning', '/', False):
with patch('openedx.core.djangoapps.safe_sessions.middleware.set_custom_attribute') as mock_attr:
response = SafeSessionMiddleware().process_response(self.request, self.client.response)
assert response.status_code == 200
mock_attr.assert_called_with("safe_sessions.user_mismatch", "request-response-mismatch")
def test_warn_on_user_change_from_session(self):
"""
Verifies that warnings are emitted and custom attributes set if
the user in the request does not match the user in the session.
"""
self.set_up_for_success()
different_user = UserFactory()
SafeSessionMiddleware.set_user_id_in_session(self.request, different_user)
with self.assert_logged_for_session_user_mismatch(self.user.id, different_user.id, self.request.path,
False):
with patch('openedx.core.djangoapps.safe_sessions.middleware.set_custom_attribute') as mock_attr:
response = SafeSessionMiddleware().process_response(self.request, self.client.response)
assert response.status_code == 200
mock_attr.assert_called_with("safe_sessions.user_mismatch", "request-session-mismatch")
def test_warn_on_user_change_in_both(self):
"""
Verifies that warnings are emitted and custom attributes set if
the user in the initial request does not match the user at response time or the user in the session.
"""
self.set_up_for_success()
different_user = UserFactory()
SafeSessionMiddleware.set_user_id_in_session(self.request, different_user)
self.request.user = UserFactory.create()
with self.assert_logged_for_both_mismatch(self.user.id, different_user.id,
self.request.user.id, self.request.path, False):
with patch('openedx.core.djangoapps.safe_sessions.middleware.set_custom_attribute') as mock_attr:
response = SafeSessionMiddleware().process_response(self.request, self.client.response)
assert response.status_code == 200
mock_attr.assert_called_with("safe_sessions.user_mismatch", "request-response-and-session-mismatch")
@patch("openedx.core.djangoapps.safe_sessions.middleware.LOG_REQUEST_USER_CHANGES", True)
def test_warn_with_verbose_logging(self):
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)
@patch("openedx.core.djangoapps.safe_sessions.middleware.LOG_REQUEST_USER_CHANGES", False)
def test_warn_without_verbose_logging(self):
self.set_up_for_success()
self.request.user = UserFactory.create()
with self.assert_regex_not_logged('SafeCookieData: Changing request user. ', log_level='warning'):
SafeSessionMiddleware().process_response(self.request, self.client.response)
def test_no_warn_on_expected_user_change(self):
"""
Verifies that no warnings is emitted when the user change is expected.
@@ -365,7 +403,7 @@ class TestSafeSessionMiddleware(TestSafeSessionsLogMixin, TestCase):
@ddt.ddt
class TestLogRequestUserChanges(TestCase):
class TestTrackRequestUserChanges(TestCase):
"""
Test the function that instruments a request object.
@@ -373,51 +411,46 @@ class TestLogRequestUserChanges(TestCase):
that the correct messages are written.
"""
@patch("openedx.core.djangoapps.safe_sessions.middleware.log.info")
def test_initial_user_setting_logging(self, mock_log):
def test_initial_user_setting_tracking(self):
request = get_mock_request()
del request.user
log_request_user_changes(request)
track_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]
assert "Setting for the first time" in request.debug_user_changes[0]
@patch("openedx.core.djangoapps.safe_sessions.middleware.log.info")
def test_user_change_logging(self, mock_log):
def test_user_change_logging(self):
request = get_mock_request()
original_user = UserFactory.create()
new_user = UserFactory.create()
request.user = original_user
log_request_user_changes(request)
track_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
assert len(request.debug_user_changes) == 0
# 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]
assert len(request.debug_user_changes) == 1
assert f"Changing request user. Originally {original_user.id!r}" in request.debug_user_changes[0]
assert f"will become {new_user.id!r}" in request.debug_user_changes[0]
# Verify change back logged.
request.user = original_user
assert mock_log.call_count == 2
assert len(request.debug_user_changes) == 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]
assert expected_msg in request.debug_user_changes[1]
@patch("openedx.core.djangoapps.safe_sessions.middleware.log.info")
def test_user_change_with_no_ids(self, mock_log):
def test_user_change_with_no_ids(self):
request = get_mock_request()
del request.user
log_request_user_changes(request)
track_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]
assert "Setting for the first time, but user has no id" in request.debug_user_changes[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]
assert len(request.debug_user_changes) == 2
assert "Changing request user but user has no id." in request.debug_user_changes[1]

53
openedx/core/djangoapps/safe_sessions/tests/test_utils.py
View File

@@ -1,8 +1,7 @@
"""
Shared test utilities for Safe Sessions tests
"""
import pytest
from contextlib import contextmanager
from unittest.mock import patch
@@ -23,6 +22,16 @@ class TestSafeSessionsLogMixin:
assert mock_log.called
self.assertRegex(mock_log.call_args_list[0][0][0], log_string)
@contextmanager
def assert_regex_not_logged(self, log_string, log_level):
"""
Asserts that the logger was not called with the given
log_level and with a regex of the given string.
"""
with pytest.raises(AssertionError):
with self.assert_logged(log_string, log_level=log_level):
yield
@contextmanager
def assert_logged_with_message(self, log_string, log_level='error'):
"""
@@ -115,34 +124,58 @@ class TestSafeSessionsLogMixin:
yield
@contextmanager
def assert_logged_for_request_user_mismatch(self, user_at_request, user_at_response, log_level, request_path):
def assert_logged_for_request_user_mismatch(self, user_at_request, user_at_response, log_level, request_path,
session_changed):
"""
Asserts that warning was logged when request.user
was not equal to user at response
"""
session_suffix = 'Session changed.' if session_changed else 'Session did not change.'
with self.assert_logged_with_message(
(
"SafeCookieData user at request '{}' does not match user at response: '{}' "
"for request path '{}'"
"SafeCookieData user at initial request '{}' does not match user at response time: '{}' "
"for request path '{}'. {}"
).format(
user_at_request, user_at_response, request_path
user_at_request, user_at_response, request_path, session_suffix
),
log_level=log_level,
):
yield
@contextmanager
def assert_logged_for_session_user_mismatch(self, user_at_request, user_in_session, request_path):
def assert_logged_for_session_user_mismatch(self, user_at_request, user_in_session, request_path, session_changed):
"""
Asserts that warning was logged when request.user
was not equal to user at session
"""
session_suffix = 'Session changed.' if session_changed else 'Session did not change.'
with self.assert_logged_with_message(
(
"SafeCookieData user at request '{}' does not match user in session: '{}' "
"for request path '{}'"
"SafeCookieData user at initial request '{}' does not match user in session: '{}' "
"for request path '{}'. {}"
).format(
user_at_request, user_in_session, request_path
user_at_request, user_in_session, request_path, session_suffix
),
log_level='warning',
):
yield
@contextmanager
def assert_logged_for_both_mismatch(self, user_at_request, user_in_session, user_at_response, request_path,
session_changed):
"""
Asserts that warning was logged when request.user
was not equal to user at session
"""
session_suffix = 'Session changed.' if session_changed else 'Session did not change.'
with self.assert_logged_with_message(
(
"SafeCookieData user at initial request '{}' matches neither user in session: '{}' "
"nor user at response time: '{}' for request path '{}'. {}"
).format(
user_at_request, user_in_session, user_at_response, request_path, session_suffix
),
log_level='warning',
):