Merge pull request #27062 from edx/feanil/more_logging

fix: Add more info in warning log messages.

openedx/core/djangoapps/safe_sessions/middleware.py

@@ -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):

openedx/core/djangoapps/safe_sessions/tests/test_middleware.py

@@ -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):

openedx/core/djangoapps/safe_sessions/tests/test_utils.py

@@ -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',
         ):