fix!: session ID stability while maintaining inactivity timeout

openedx/core/djangoapps/session_inactivity_timeout/middleware.py

@@ -14,18 +14,24 @@
 
 
 from datetime import datetime, timedelta
+import logging
 
 from django.conf import settings
 from django.contrib import auth
 from django.utils.deprecation import MiddlewareMixin
+from edx_django_utils import monitoring as monitoring_utils
 
-LAST_TOUCH_KEYNAME = 'SessionInactivityTimeout:last_touch'
+
+log = logging.getLogger(__name__)
+
+LAST_TOUCH_KEYNAME = 'SessionInactivityTimeout:last_touch_str'
 
 
 class SessionInactivityTimeout(MiddlewareMixin):
     """
     Middleware class to keep track of activity on a given session
     """
+
     def process_request(self, request):
         """
         Standard entry point for processing requests in Django
@@ -34,27 +40,81 @@ def process_request(self, request):
             #Can't log out if not logged in
             return
 
+        # .. setting_name: SESSION_INACTIVITY_TIMEOUT_IN_SECONDS
+        # .. setting_default: None
+        # .. setting_description: If set, this is used to end the session when there is no activity for N seconds.
+        # .. setting_warning:  Keep in sync with SESSION_COOKIE_AGE and must be larger than SESSION_ACTIVITY_SAVE_DELAY_SECONDS.
         timeout_in_seconds = getattr(settings, "SESSION_INACTIVITY_TIMEOUT_IN_SECONDS", None)
 
+        current_time = datetime.utcnow()
         # Do we have this feature enabled?
         if timeout_in_seconds:
-            # what time is it now?
-            utc_now = datetime.utcnow()
+            # .. setting_name: SESSION_ACTIVITY_SAVE_DELAY_SECONDS
+            # .. setting_default: 900 (15 minutes in seconds)
+            # .. setting_description: How often to allow a full session save (in seconds).
+            #   This controls how frequently the session ID might change.
+            #   A user could be inactive for almost SESSION_ACTIVITY_SAVE_DELAY_SECONDS but since their session
+            #   isn't being saved during that time, their last activity timestamp isn't being updated.
+            #   When they hit the inactivity timeout, it will be based on the last saved activity time.
+            #   So the effective timeout could be as short as:
+            #   SESSION_INACTIVITY_TIMEOUT_IN_SECONDS - SESSION_ACTIVITY_SAVE_DELAY_SECONDS.
+            #   This means users might be logged out earlier than expected in some edge cases.
+            # .. setting_warning:  Must be smaller than SESSION_INACTIVITY_TIMEOUT_IN_SECONDS.
+            frequency_time_in_seconds = getattr(settings, "SESSION_ACTIVITY_SAVE_DELAY_SECONDS", 900)
 
             # Get the last time user made a request to server, which is stored in session data
-            last_touch = request.session.get(LAST_TOUCH_KEYNAME)
+            last_touch_str = request.session.get(LAST_TOUCH_KEYNAME)
 
             # have we stored a 'last visited' in session? NOTE: first time access after login
             # this key will not be present in the session data
-            if last_touch:
-                # compute the delta since last time user came to the server
-                time_since_last_activity = utc_now - last_touch
-
-                # did we exceed the timeout limit?
-                if time_since_last_activity > timedelta(seconds=timeout_in_seconds):
-                    # yes? Then log the user out
-                    del request.session[LAST_TOUCH_KEYNAME]
-                    auth.logout(request)
-                    return
-
-            request.session[LAST_TOUCH_KEYNAME] = utc_now
+            if last_touch_str:
+                try:
+                    last_touch = datetime.fromisoformat(last_touch_str)
+                    time_since_last_activity = current_time - last_touch
+
+                    has_exceeded_timeout_limit = time_since_last_activity > timedelta(seconds=timeout_in_seconds)
+
+                    # .. custom_attribute_name: session_inactivity.has_exceeded_timeout_limit
+                    # .. custom_attribute_description: Boolean indicating whether the user's session has exceeded the
+                    #   inactivity timeout limit and should be logged out.
+                    monitoring_utils.set_custom_attribute(
+                        'session_inactivity.has_exceeded_timeout_limit',
+                        has_exceeded_timeout_limit
+                    )
+
+                    if has_exceeded_timeout_limit:
+                        del request.session[LAST_TOUCH_KEYNAME]
+                        auth.logout(request)
+                        return
+                except (ValueError, TypeError) as e:
+                    # If parsing fails, log warning and then treat as if no timestamp exists
+                    log.warning("Parsing last touch time failed: %s", e)
+                    # .. custom_attribute_name: session_inactivity.last_touch_error
+                    # .. custom_attribute_description: Boolean. True if parsing the last activity timestamp failed for this request, indicating a session data error.
+                    monitoring_utils.set_custom_attribute('session_inactivity.last_touch_error', str(e))
+                    monitoring_utils.record_exception()
+
+            else:
+                # .. custom_attribute_name: session_inactivity.first_login
+                # .. custom_attribute_description: Boolean. True if the user has no stored activity timestamp for this request.
+                monitoring_utils.set_custom_attribute('session_inactivity.first_login', True)
+                log.debug("No previous activity timestamp found (first login)")
+
+            current_time_str = current_time.isoformat()
+
+            has_save_delay_been_exceeded = (
+                last_touch_str and
+                datetime.fromisoformat(last_touch_str) + timedelta(seconds=frequency_time_in_seconds) < current_time
+            )
+            proceed_with_period_save = not last_touch_str or has_save_delay_been_exceeded
+            # .. custom_attribute_name: session_inactivity.proceed_with_period_save
+            # .. custom_attribute_description: Boolean indicating whether a session save should proceed based on the
+            #   save delay frequency. True when either no previous timestamp exists (first login) or the save delay
+            #   period has been exceeded since the last timestamp update.
+            monitoring_utils.set_custom_attribute(
+                'session_inactivity.proceed_with_period_save',
+                proceed_with_period_save
+            )
+            if proceed_with_period_save:
+                # Allow a full session save periodically
+                request.session[LAST_TOUCH_KEYNAME] = current_time_str

openedx/core/djangoapps/session_inactivity_timeout/tests/__init__.py

@@ -0,0 +1,3 @@
+"""
+Tests for session inactivity timeout middleware.
+"""

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

@@ -0,0 +1,216 @@
+"""
+Unit tests for SessionInactivityTimeout middleware.
+"""
+
+from datetime import datetime, timedelta
+from unittest.mock import patch, call, ANY
+
+import ddt
+from django.contrib.auth.models import AnonymousUser
+from django.contrib.sessions.backends.db import SessionStore
+from django.test import TestCase, override_settings
+
+from common.djangoapps.student.tests.factories import UserFactory
+from openedx.core.djangolib.testing.utils import get_mock_request
+
+from openedx.core.djangoapps.session_inactivity_timeout.middleware import (
+    SessionInactivityTimeout,
+    LAST_TOUCH_KEYNAME,
+)
+
+
+@ddt.ddt
+class SessionInactivityTimeoutTestCase(TestCase):
+    """
+    Test case for SessionInactivityTimeout middleware
+    """
+    def setUp(self):
+        super().setUp()
+        self.user = UserFactory.create()
+        self.middleware = SessionInactivityTimeout(get_response=lambda request: None)
+        self.request = get_mock_request(self.user)
+
+        self.request.session = SessionStore()
+        self.request.session.create()
+        self.request.session.modified = False
+
+    def test_process_request_unauthenticated_user_does_nothing(self):
+        self.request.user = AnonymousUser()
+        response = self.middleware.process_request(self.request)  # lint-amnesty, pylint: disable=assignment-from-none
+        assert response is None
+        assert LAST_TOUCH_KEYNAME not in self.request.session
+
+    @ddt.data(
+        None,  # No timestamp key in session
+        "",    # Empty string timestamp in session
+    )
+    @override_settings(SESSION_INACTIVITY_TIMEOUT_IN_SECONDS=300)
+    @patch("openedx.core.djangoapps.session_inactivity_timeout.middleware.datetime")
+    @patch("openedx.core.djangoapps.session_inactivity_timeout.middleware.log")
+    @patch(
+        "openedx.core.djangoapps.session_inactivity_timeout.middleware.monitoring_utils"
+    )
+    def test_process_request_first_visit_sets_timestamp(
+        self, timestamp_value, mock_monitoring, mock_log, mock_datetime
+    ):
+        if timestamp_value is not None:
+            self.request.session[LAST_TOUCH_KEYNAME] = timestamp_value
+        # else: leave the session without the timestamp key (None case)
+
+        mock_now = datetime(2025, 6, 16, 12, 0, 0)
+        mock_datetime.utcnow.return_value = mock_now
+
+        response = self.middleware.process_request(self.request)  # lint-amnesty, pylint: disable=assignment-from-none
+
+        assert response is None
+        assert self.request.session[LAST_TOUCH_KEYNAME] == mock_now.isoformat()
+        mock_log.debug.assert_called_once_with("No previous activity timestamp found (first login)")
+
+        mock_monitoring.set_custom_attribute.assert_has_calls([
+            call("session_inactivity.first_login", True),
+            call("session_inactivity.proceed_with_period_save", True),
+        ], any_order=True)
+
+    @ddt.data(
+        "invalid-timestamp",     # Invalid ISO format
+        "2025-13-01T12:00:00",  # Invalid date
+    )
+    @override_settings(SESSION_INACTIVITY_TIMEOUT_IN_SECONDS=300)
+    @patch("openedx.core.djangoapps.session_inactivity_timeout.middleware.log")
+    @patch("openedx.core.djangoapps.session_inactivity_timeout.middleware.monitoring_utils")
+    def test_process_request_invalid_timestamp_handling(
+        self, invalid_timestamp, mock_monitoring, mock_log
+    ):
+        self.request.session[LAST_TOUCH_KEYNAME] = invalid_timestamp
+
+        # The middleware should raise an exception when it tries to parse the invalid timestamp
+        # in the save delay logic (after already catching it once in the timeout logic)
+        with self.assertRaises(ValueError):
+            self.middleware.process_request(self.request)
+
+        mock_log.warning.assert_called_once()
+
+        mock_monitoring.set_custom_attribute.assert_any_call("session_inactivity.last_touch_error", ANY)
+        mock_monitoring.record_exception.assert_called_once()
+
+    @ddt.data(
+        # (timeout_seconds, seconds_elapsed, should_logout)
+        (300, 299, False),   # 299 sec < 300 sec timeout, no logout
+        (300, 300, False),   # 300 sec = 300 sec timeout, no logout (not exceeded)
+        (300, 301, True),    # 301 sec > 300 sec timeout, logout occurs
+    )
+    @ddt.unpack
+    @patch("openedx.core.djangoapps.session_inactivity_timeout.middleware.datetime")
+    @patch("openedx.core.djangoapps.session_inactivity_timeout.middleware.monitoring_utils")
+    def test_process_request_timeout_behavior(
+        self, timeout_seconds, seconds_elapsed, should_logout,
+        mock_monitoring, mock_datetime
+    ):
+        with override_settings(SESSION_INACTIVITY_TIMEOUT_IN_SECONDS=timeout_seconds):
+            assert self.request.user.is_authenticated
+
+            last_touch = datetime(2025, 6, 16, 12, 0, 0)
+            current_time = last_touch + timedelta(seconds=seconds_elapsed)
+            self.request.session[LAST_TOUCH_KEYNAME] = last_touch.isoformat()
+            mock_datetime.utcnow.return_value = current_time
+            mock_datetime.fromisoformat = datetime.fromisoformat
+
+            response = self.middleware.process_request(self.request)  # lint-amnesty, pylint: disable=assignment-from-none
+
+            assert response is None
+
+            if should_logout:
+                assert LAST_TOUCH_KEYNAME not in self.request.session
+                assert not self.request.user.is_authenticated
+                mock_monitoring.set_custom_attribute.assert_any_call(
+                    "session_inactivity.has_exceeded_timeout_limit", True
+                )
+            else:
+                assert self.request.user.is_authenticated
+                assert LAST_TOUCH_KEYNAME in self.request.session
+                mock_monitoring.set_custom_attribute.assert_any_call(
+                    "session_inactivity.has_exceeded_timeout_limit", False
+                )
+
+    @ddt.data(
+        # (save_delay_seconds, seconds_elapsed, should_save)
+        # Test save delay behavior (with long timeout to avoid logout)
+        (900, 899, False),   # 899 sec < 900 sec save delay, no save
+        (900, 900, False),   # 900 sec = 900 sec save delay, no save (not exceeded)
+        (900, 901, True),    # 901 sec > 900 sec save delay, save occurs
+    )
+    @ddt.unpack
+    @patch("openedx.core.djangoapps.session_inactivity_timeout.middleware.datetime")
+    @patch("openedx.core.djangoapps.session_inactivity_timeout.middleware.monitoring_utils")
+    def test_process_request_save_behavior(
+        self, save_delay_seconds, seconds_elapsed, should_save,
+        mock_monitoring, mock_datetime
+    ):
+        with override_settings(
+            SESSION_INACTIVITY_TIMEOUT_IN_SECONDS=3600,  # Long timeout to avoid logout
+            SESSION_ACTIVITY_SAVE_DELAY_SECONDS=save_delay_seconds
+        ):
+            assert self.request.user.is_authenticated
+
+            last_touch = datetime(2025, 6, 16, 12, 0, 0)
+            current_time = last_touch + timedelta(seconds=seconds_elapsed)
+            self.request.session[LAST_TOUCH_KEYNAME] = last_touch.isoformat()
+            mock_datetime.utcnow.return_value = current_time
+            mock_datetime.fromisoformat = datetime.fromisoformat
+
+            response = self.middleware.process_request(self.request)  # lint-amnesty, pylint: disable=assignment-from-none
+
+            assert response is None
+            assert self.request.user.is_authenticated
+            assert LAST_TOUCH_KEYNAME in self.request.session
+
+            if should_save:
+                assert self.request.session[LAST_TOUCH_KEYNAME] == current_time.isoformat()
+                mock_monitoring.set_custom_attribute.assert_has_calls([
+                    call("session_inactivity.has_exceeded_timeout_limit", False),
+                    call("session_inactivity.proceed_with_period_save", True),
+                ], any_order=True)
+            else:
+                # Session should not be saved, timestamp remains the same
+                assert self.request.session[LAST_TOUCH_KEYNAME] == last_touch.isoformat()
+                mock_monitoring.set_custom_attribute.assert_has_calls([
+                    call("session_inactivity.has_exceeded_timeout_limit", False),
+                    call("session_inactivity.proceed_with_period_save", False),
+                ], any_order=True)
+
+    @ddt.data(
+        # (seconds_elapsed, should_save) - testing around default 900 second save delay
+        (899, False),   # 899 sec < 900 sec default, no save
+        (900, False),   # 900 sec = 900 sec default, no save (not exceeded)
+        (901, True),    # 901 sec > 900 sec default, save occurs
+    )
+    @ddt.unpack
+    @override_settings(SESSION_INACTIVITY_TIMEOUT_IN_SECONDS=3600)
+    @patch("openedx.core.djangoapps.session_inactivity_timeout.middleware.datetime")
+    @patch("openedx.core.djangoapps.session_inactivity_timeout.middleware.monitoring_utils")
+    def test_process_request_uses_default_save_frequency(
+        self, seconds_elapsed, should_save, mock_monitoring, mock_datetime
+    ):
+        # Don't set SESSION_ACTIVITY_SAVE_DELAY_SECONDS to test default behavior
+        last_touch = datetime(2025, 6, 16, 12, 0, 0)
+        current_time = last_touch + timedelta(seconds=seconds_elapsed)
+        self.request.session[LAST_TOUCH_KEYNAME] = last_touch.isoformat()
+        mock_datetime.utcnow.return_value = current_time
+        mock_datetime.fromisoformat = datetime.fromisoformat
+
+        response = self.middleware.process_request(self.request)  # lint-amnesty, pylint: disable=assignment-from-none
+
+        assert response is None
+
+        if should_save:
+            assert self.request.session[LAST_TOUCH_KEYNAME] == current_time.isoformat()
+            mock_monitoring.set_custom_attribute.assert_has_calls([
+                call("session_inactivity.has_exceeded_timeout_limit", False),
+                call("session_inactivity.proceed_with_period_save", True),
+            ], any_order=True)
+        else:
+            assert self.request.session[LAST_TOUCH_KEYNAME] == last_touch.isoformat()
+            mock_monitoring.set_custom_attribute.assert_has_calls([
+                call("session_inactivity.has_exceeded_timeout_limit", False),
+                call("session_inactivity.proceed_with_period_save", False),
+            ], any_order=True)