fix: Add more info in warning log messages.

If this happens, it's usefule to know what main view code was being
targetd so that we can more easily investigate what might have caused
this issue.

Add a new custom attribute 'safe_sessions.user_mismatch' to find
requests that had this issue in our monitoring system.
This commit is contained in:
Feanil Patel
2021-03-18 10:31:49 -04:00
parent 2545e6e174
commit 416407fd73
3 changed files with 32 additions and 15 deletions

View File

@@ -54,6 +54,10 @@ to the browser that the cookie should be sent only over an
SSL-protected channel. Otherwise, a session hijacker could copy
the entire cookie and use it to impersonate the victim.
Custom Attributes:
safe_sessions.user_mismatch: 'request-response-mismatch' | 'request-session-mismatch'
This attribute can be one of the above two values which correspond to the kind of comparison
that failed when processing the response. See SafeSessionMiddleware._verify_user
"""
@@ -72,6 +76,7 @@ from django.http import HttpResponse
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 six import text_type # pylint: disable=ungrouped-imports
@@ -372,18 +377,24 @@ class SafeSessionMiddleware(SessionMiddleware, MiddlewareMixin):
# conditionally set the log level.
log_func = log.debug if request.user.id is None else log.warning
log_func(
u"SafeCookieData user at request '{0}' does not match user at response: '{1}'".format(
request.safe_cookie_verified_user_id,
request.user.id,
(
"SafeCookieData user at request '{0}' does not match user at response: '{1}' "
"for request path '{2}'"
).format(
request.safe_cookie_verified_user_id, request.user.id, request.path,
),
)
set_custom_attribute("safe_sessions.user_mismatch", "request-response-mismatch")
if request.safe_cookie_verified_user_id != userid_in_session:
log.warning(
u"SafeCookieData user at request '{0}' does not match user in session: '{1}'".format( # pylint: disable=logging-format-interpolation
request.safe_cookie_verified_user_id,
userid_in_session,
(
"SafeCookieData user at request '{0}' does not match user in session: '{1}' "
"for request path '{2}'"
).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")
@staticmethod
def get_user_id_from_session(request):

View File

@@ -185,10 +185,10 @@ class TestSafeSessionProcessResponse(TestSafeSessionsLogMixin, TestCase):
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'):
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):
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):
@@ -196,7 +196,7 @@ class TestSafeSessionProcessResponse(TestSafeSessionsLogMixin, TestCase):
self.request.user = AnonymousUser()
self.request.session[SESSION_KEY] = self.user.id
with self.assert_no_error_logged():
with self.assert_logged_for_request_user_mismatch(self.user.id, None, 'debug'):
with self.assert_logged_for_request_user_mismatch(self.user.id, None, 'debug', self.request.path):
self.assert_response(set_request_user=False, set_session_cookie=True)
def test_update_cookie_data_at_step_3(self):

View File

@@ -116,28 +116,34 @@ class TestSafeSessionsLogMixin(object):
yield
@contextmanager
def assert_logged_for_request_user_mismatch(self, user_at_request, user_at_response, log_level):
def assert_logged_for_request_user_mismatch(self, user_at_request, user_at_response, log_level, request_path):
"""
Asserts that warning was logged when request.user
was not equal to user at response
"""
with self.assert_logged_with_message(
u"SafeCookieData user at request '{}' does not match user at response: '{}'".format(
user_at_request, user_at_response
(
"SafeCookieData user at request '{}' does not match user at response: '{}' "
"for request path '{}'"
).format(
user_at_request, user_at_response, request_path
),
log_level=log_level,
):
yield
@contextmanager
def assert_logged_for_session_user_mismatch(self, user_at_request, user_in_session):
def assert_logged_for_session_user_mismatch(self, user_at_request, user_in_session, request_path):
"""
Asserts that warning was logged when request.user
was not equal to user at session
"""
with self.assert_logged_with_message(
u"SafeCookieData user at request '{}' does not match user in session: '{}'".format(
user_at_request, user_in_session
(
"SafeCookieData user at request '{}' does not match user in session: '{}' "
"for request path '{}'"
).format(
user_at_request, user_in_session, request_path
),
log_level='warning',
):