feat: time-based logging for userid mismatches by rgraber · Pull Request #28917 · openedx/openedx-platform

rgraber · 2021-10-04T13:57:39Z

Description

Modify LOG_REQUEST_USER_CHANGES toggle with a memcache key that is set to True after the SafeSession middleware finds a userid mismatch, expiring after 300s.

Supporting information

https://openedx.atlassian.net/browse/ARCHBOM-1876

Deadline

None

rgraber · 2021-10-07T12:24:44Z

jenkins run python

rgraber · 2021-10-07T18:27:27Z

jenkins run python

robrap

Thanks @rgraber. I'd like to discuss some thoughts I had which reviewing.

openedx/core/djangoapps/safe_sessions/middleware.py

robrap · 2021-10-07T18:58:56Z

openedx/core/djangoapps/safe_sessions/middleware.py

                request.safe_cookie_verified_user_id = user_id  # Step 5
-                if LOG_REQUEST_USER_CHANGES:
+                request.safe_cookie_session_id = safe_cookie_data.session_id
+                if cache.get(USER_MISMATCH_CACHE_KEY, False) and LOG_REQUEST_USER_CHANGES:


I was going to add a comment to explain how this was working, and now I have questions about the design.
Why do we log here vs save off information to log later? Are we afraid of losing data during exceptions? Other?
Sorry - this might lead to a larger design discussion.

Note: maybe this isn't important, but the reason I bring it up because I was noting to myself that the current design always misses the first blip. So, if we have rare occurrences of a single issue that are spaced more than 5 minutes apart, we'll never get the logs, right?

We need to decide if we will be using New Relic to detect issues only, or adding a Splunk alert. If we are happy with New Relic only, then we can probably solve for the missing blip problem if it actually occurs (i.e. we get a New Relic alert, but find no logs in Splunk).

Here is a potential comment for this line:

# Log useful debugging info from the request after having detected any recent mismatches # during any response. This will result in a missing log for the very first mismatch, but # hopefully the error will come in batches with logs to debug. If not, we'll need to enhance.

My impression was that we would be relying on New Relic and using Splunk for debugging, as you mentioned. I'm happy to add a comment to that effect.

I'd appreciate a comment like the one I had crafted, but not sure if others feel the same.

I found the shorter one I used easier to grok but I'm also willing to be overruled

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

rgraber · 2021-10-13T12:42:24Z

jenkins run all

rgraber · 2021-10-13T14:03:55Z

jenkins run all

openedx/core/djangoapps/safe_sessions/middleware.py

timmc-edx · 2021-10-13T16:13:44Z

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

            yield
-
-    @contextmanager
-    def assert_logged_for_request_user_mismatch(self, user_at_request, user_at_response, log_level, request_path):


I ended up using this in my PR -- which I had forgotten to merge until just a few minutes ago.

timmc-edx · 2021-10-13T16:17:08Z

openedx/core/djangoapps/safe_sessions/middleware.py

+                if not cache.touch(USER_MISMATCH_CACHE_KEY, 300):
+                    cache.set(USER_MISMATCH_CACHE_KEY, True, 300)


What's the benefit of this touch/set approach?

It felt conceptually closer to "extend the timeout period for every incident" but I'm not married to it

timmc-edx · 2021-10-13T16:21:54Z

openedx/core/djangoapps/safe_sessions/middleware.py

+            # The user at response time (and in the session) is expected to be None when the user
+            # is logging out so do not treat it as a mismatch


I think we can do away with (or improve) this aspect of the logic by checking against the new response field I'm setting in #28983.

timmc-edx · 2021-10-13T16:22:58Z

openedx/core/djangoapps/safe_sessions/middleware.py

+                            "SafeCookieData user at request '{}' does not match user in response: '{}' "
+                            "for request path '{}'. {}"


Nit: It's not really in the response, it's request.user.id at response time -- the original message was a bit telegraphic here.

timmc-edx · 2021-10-13T16:24:50Z

openedx/core/djangoapps/safe_sessions/middleware.py

+                else:
+                    # both session user and user in response are different than user in request


I believe this will actually end up running for both the "both" and the "neither" case, but I'm having some trouble with the negated logic in the first two guards.

The neither case should be taken care of by the top-level if, but I see your point about confusing logic

robrap

Apologies for lots of comments. I should probably re-read first, but I am sending these early to head to lunch. Happy to discuss in person later.

robrap · 2021-10-13T14:47:32Z

openedx/core/djangoapps/safe_sessions/middleware.py

I still think RECENT_USER_MISMATCH_CACHE_KEY adds clarity to the expiration of what is being cached. I noted this in https://github.com/edx/edx-platform/pull/28917#discussion_r724420744 as a non-blocking issue. Can you either update, or confirm that you saw this and want to go with the original name. Thanks.

Not married to it. Will update.

robrap · 2021-10-13T14:57:03Z

openedx/core/djangoapps/safe_sessions/middleware.py

                request.safe_cookie_verified_user_id = user_id  # Step 5
-                if LOG_REQUEST_USER_CHANGES:
+                request.safe_cookie_session_id = safe_cookie_data.session_id
+                if cache.get(USER_MISMATCH_CACHE_KEY, False) and LOG_REQUEST_USER_CHANGES:


I'd appreciate a comment like the one I had crafted, but not sure if others feel the same.

openedx/core/djangoapps/safe_sessions/middleware.py

robrap · 2021-10-13T15:16:50Z

openedx/core/djangoapps/safe_sessions/middleware.py

Nit: I've been asked to indent multi-line paragraphs and got used to it. I do think it reads more easily. This is a non-blocking comment for your consideration. Note that it would affect other comments, such as one where you removed the indent from the second line of a comment.

robrap · 2021-10-13T15:17:19Z

openedx/core/djangoapps/safe_sessions/middleware.py

Note: Here is an example where you removed an indent. See earlier comment.

robrap · 2021-10-13T16:14:56Z

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

+    def test_success(self, mock_log_request_user_changes, toggle, cache_flag, should_log):
+        with patch("openedx.core.djangoapps.safe_sessions.middleware.LOG_REQUEST_USER_CHANGES", toggle):
+            self.client.login(username=self.user.username, password='test')
+            cache.set(USER_MISMATCH_CACHE_KEY, cache_flag)


It feels like we should assert USER_MISMATCH_CACHE_KEY at the end as well. At this time, does a normal login trigger a mismatch? Would the cache always be True? Maybe this will change after Tim's work, but would capture how it should be working now.

robrap · 2021-10-13T16:17:05Z

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

                object.
            set_session_cookie - If True, a session_id is set in the
-                session cookie in the response.
+                session cookie in the response.c


Typo added.

robrap · 2021-10-13T16:17:23Z

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

-                session cookie in the response.
+                session cookie in the response.c
        """
+        print('assert response')


Left from debugging?

robrap · 2021-10-13T16:26:53Z

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

+    def test_different_user_at_step_2_error(self, mock_cache_set, change_response_user,
+                                            change_session_user, mismatch_location, change_session):
+        new_user = UserFactory()
+        self.request.safe_cookie_verified_user_id = self.user.id


I wonder if there is a way to mock slightly less in this test? Could we call the actual middleware on the request and have it do this instead, and then muck with stuff, and then call the middleware on the response?

robrap · 2021-10-13T16:30:10Z

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

-    def test_success(self):
+    @patch("django.core.cache.cache.set")
+    @patch("django.core.cache.cache.touch")
+    def test_success(self, mock_cache_set, mock_cache_touch):


I'm curious if we could test the consequences of this, rather than the cache value itself? For example, using multiple calls with or without a mismatch and showing that logging happens where and when we expect. Food for thought.

edx-status-bot · 2021-10-13T17:58:57Z

Your PR has finished running tests. The following contexts failed:

jenkins/django-3.2/quality

rgraber · 2021-10-13T18:10:41Z

Closing in favor or ARCHBOM-1923

rgraber force-pushed the rsgraber/ARCHBOM-1876-log-safe-session-mismatches-better branch from fb477d9 to ae22654 Compare October 6, 2021 19:21

rgraber marked this pull request as ready for review October 6, 2021 19:37

rgraber force-pushed the rsgraber/ARCHBOM-1876-log-safe-session-mismatches-better branch from b01bfcb to 8f0a5c0 Compare October 7, 2021 18:01

robrap reviewed Oct 7, 2021

View reviewed changes

rgraber force-pushed the rsgraber/ARCHBOM-1876-log-safe-session-mismatches-better branch from e3c22bb to 626d1ec Compare October 8, 2021 18:31

rgraber force-pushed the rsgraber/ARCHBOM-1876-log-safe-session-mismatches-better branch from 8f08ac0 to 7823210 Compare October 13, 2021 14:34

timmc-edx reviewed Oct 13, 2021

View reviewed changes

openedx/core/djangoapps/safe_sessions/middleware.py Outdated Show resolved Hide resolved

feat: time-based logging for session mismatches

8a79343

rgraber force-pushed the rsgraber/ARCHBOM-1876-log-safe-session-mismatches-better branch from 7823210 to 8a79343 Compare October 13, 2021 16:12

timmc-edx reviewed Oct 13, 2021

View reviewed changes

robrap reviewed Oct 13, 2021

View reviewed changes

Rebecca Graber added 2 commits October 13, 2021 13:12

fix: easy PR comments

18dcb11

fix: better logging message

3eb4940

rgraber closed this Oct 13, 2021

rgraber deleted the rsgraber/ARCHBOM-1876-log-safe-session-mismatches-better branch October 13, 2021 18:10

		if not cache.touch(USER_MISMATCH_CACHE_KEY, 300):
		cache.set(USER_MISMATCH_CACHE_KEY, True, 300)

		# The user at response time (and in the session) is expected to be None when the user
		# is logging out so do not treat it as a mismatch

		"SafeCookieData user at request '{}' does not match user in response: '{}' "
		"for request path '{}'. {}"

		else:
		# both session user and user in response are different than user in request

Conversation

rgraber commented Oct 4, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Description

Supporting information

Deadline

Uh oh!

rgraber commented Oct 7, 2021

Uh oh!

rgraber commented Oct 7, 2021

Uh oh!

robrap left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

rgraber commented Oct 13, 2021

Uh oh!

rgraber commented Oct 13, 2021

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

robrap left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

edx-status-bot commented Oct 13, 2021

Uh oh!

rgraber commented Oct 13, 2021

rgraber commented Oct 4, 2021 •

edited

Loading