Skip to content

feat: time-based logging for userid mismatches #28917

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
rgraber wants to merge 3 commits into from
Closed

feat: time-based logging for userid mismatches #28917

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
8a79343
feat: time-based logging for session mismatches
Oct 4, 2021
18dcb11
fix: easy PR comments
Oct 13, 2021
3eb4940
fix: better logging message
Oct 13, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
97 changes: 69 additions & 28 deletions openedx/core/djangoapps/safe_sessions/middleware.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -88,6 +88,8 @@
from django.http import HttpResponse
from django.utils.crypto import get_random_string
from django.utils.deprecation import MiddlewareMixin
from django.core.cache import cache


from edx_django_utils.monitoring import set_custom_attribute

Expand All @@ -96,13 +98,16 @@
# .. 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 enable 5 minutes of logging anytime the `user` attribute of the request
# object gets changed after a mismatch incident. This will also log the location where the change is coming from to
# quickly find issues. The 5 minutes will be reset after every incident.
# .. toggle_warnings: This logging may be very verbose if there are many user id mimatches over a long period of time.
# This toggle can be disabled as a safety valve in such an event.
# .. toggle_use_cases: opt_in
# .. toggle_creation_date: 2021-03-25
# .. toggle_tickets: https://openedx.atlassian.net/browse/ARCHBOM-1718
LOG_REQUEST_USER_CHANGES = getattr(settings, 'LOG_REQUEST_USER_CHANGES', False)
RECENT_USER_MISMATCH_CACHE_KEY = 'safe_sessions.middleware.recent_user_mismatch_detected'

log = getLogger(__name__)

Expand Down Expand Up @@ -321,7 +326,10 @@ def process_request(self, request):
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
if LOG_REQUEST_USER_CHANGES:
request.safe_cookie_session_id = safe_cookie_data.session_id
if cache.get(RECENT_USER_MISMATCH_CACHE_KEY, False) and LOG_REQUEST_USER_CHANGES:
# Note: this logging will only be enabled after we have already detected a user mismatch,
# so we will miss the logs for the initial request that activated the logging.
log_request_user_changes(request)
else:
# Return an error or redirect, and don't continue to
Expand Down Expand Up @@ -353,6 +361,7 @@ def process_response(self, request, response):
Step 4. Delete the cookie, if it's marked for deletion.

"""

response = super().process_response(request, response) # Step 1

if not _is_cookie_marked_for_deletion(request) and _is_cookie_present(response):
Expand Down Expand Up @@ -408,34 +417,66 @@ def _verify_user(request, response, userid_in_session):
return

if hasattr(request, 'safe_cookie_verified_user_id'):

if hasattr(request.user, 'real_user'):
# 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")

# 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
Comment on lines +426 to +427
Copy link
Contributor

@timmc-edx timmc-edx Oct 13, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

is_request_response_mismatch = request.safe_cookie_verified_user_id != request.user.id\
and request.user.id is not None
is_request_session_mismatch = request.safe_cookie_verified_user_id != userid_in_session\
and userid_in_session is not None

session_at_response = None
if hasattr(request, 'session') and hasattr(request.session, 'session_key'):
Copy link
Contributor

@robrap robrap Oct 13, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nit: Other code in this file seems like it was using:

if request.session.get(SESSION_KEY):

Consistency might have make this simpler to follow. Also, although I don't know why we there is a constant for SESSION_KEY, the fact that you are not using the constant would break things if someone were to change that setting.

Copy link
Contributor Author

@rgraber rgraber Oct 13, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I saw both used throughout the code. Some of it I think had to do with ease of mocking for tests, but I'll see what happens if I change it

session_at_response = request.session.session_key

if is_request_response_mismatch or is_request_session_mismatch:
cache.set(RECENT_USER_MISMATCH_CACHE_KEY, True, 300)
session_has_changed = not request.safe_cookie_session_id == session_at_response
# remove the stored old session id for security
del request.safe_cookie_session_id

# for security, don't log the actual session id, just whether or not it changed
log_session_suffix = 'Session id has changed.' if session_has_changed else 'Session id has not changed'

if is_request_response_mismatch and not is_request_session_mismatch:
log.warning(
(
"SafeCookieData user in 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_session_suffix
),
)
set_custom_attribute("safe_sessions.user_mismatch", "request-response-mismatch")
elif is_request_session_mismatch and not is_request_response_mismatch:
log.warning(
(
"SafeCookieData user in 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_session_suffix
),
)
set_custom_attribute("safe_sessions.user_mismatch", "request-session-mismatch")
else:
# both session user and user in response are different than user in request
Comment on lines +468 to +469
Copy link
Contributor

@timmc-edx timmc-edx Oct 13, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

@rgraber rgraber Oct 13, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

log.warning(
(
"SafeCookieData user in initial request '{}' does not match user in session: '{}' "
"or 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_session_suffix
),
)
set_custom_attribute("safe_sessions.user_mismatch", "request-response-and-session-mismatch")

@staticmethod
def get_user_id_from_session(request):
Expand Down
Loading