Merge pull request #11734 from edx/security/quiet_safe_sessions

Quiet the safe sessions logging for expected use cases

openedx/core/djangoapps/safe_sessions/middleware.py

@@ -223,7 +223,7 @@ class SafeCookieData(object):
             # 3rd party Auth and external Auth transactions
             # as some of the session requests are made as
             # Anonymous users.
-            log.warning(
+            log.debug(
                 "SafeCookieData received empty user_id '%s' for session_id '%s'.",
                 user_id,
                 session_id,
@@ -360,7 +360,11 @@ class SafeSessionMiddleware(SessionMiddleware):
         """
         if hasattr(request, 'safe_cookie_verified_user_id'):
             if request.safe_cookie_verified_user_id != request.user.id:
-                log.warning(
+                # The user at response time is expected to be None when the user
+                # is logging out. To prevent extra noise in the logs,
+                # conditionally set the log level.
+                log_func = log.debug if request.user.id is None else log.warning
+                log_func(
                     "SafeCookieData user at request '{0}' does not match user at response: '{1}'".format(  # pylint: disable=logging-format-interpolation
                         request.safe_cookie_verified_user_id,
                         request.user.id,

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

@@ -193,7 +193,7 @@ 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):
+        with self.assert_logged_for_request_user_mismatch("different_user", self.user.id, 'warning'):
             self.assert_response(set_request_user=True, set_session_cookie=True)
 
         with self.assert_logged_for_session_user_mismatch("different_user", self.user.id):
@@ -204,7 +204,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):
+            with self.assert_logged_for_request_user_mismatch(self.user.id, None, 'debug'):
                 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_safe_cookie_data.py

@@ -102,7 +102,7 @@ class TestSafeCookieData(TestSafeSessionsLogMixin, TestCase):
 
     @ddt.data(None, '')
     def test_create_no_user_id(self, user_id):
-        with self.assert_logged('SafeCookieData received empty user_id', 'warning'):
+        with self.assert_logged('SafeCookieData received empty user_id', 'debug'):
             safe_cookie_data = SafeCookieData.create(self.session_id, user_id)
             self.assertTrue(safe_cookie_data.verify(user_id))
 

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

@@ -114,7 +114,7 @@ class TestSafeSessionsLogMixin(object):
             yield
 
     @contextmanager
-    def assert_logged_for_request_user_mismatch(self, user_at_request, user_at_response):
+    def assert_logged_for_request_user_mismatch(self, user_at_request, user_at_response, log_level):
         """
         Asserts that warning was logged when request.user
         was not equal to user at response
@@ -123,7 +123,7 @@ class TestSafeSessionsLogMixin(object):
             "SafeCookieData user at request '{}' does not match user at response: '{}'".format(
                 user_at_request, user_at_response
             ),
-            log_level='warning',
+            log_level=log_level,
         ):
             yield