diff --git a/cms/envs/common.py b/cms/envs/common.py index b73a411b07..cd7eb4b9de 100644 --- a/cms/envs/common.py +++ b/cms/envs/common.py @@ -763,8 +763,7 @@ MIDDLEWARE = [ # Cookie monitoring 'openedx.core.lib.request_utils.CookieMonitoringMiddleware', - # After cookie monitoring, but before anything else that looks at - # cookies, especially the session middleware + # Before anything that looks at cookies, especially the session middleware 'openedx.core.djangoapps.cookie_metadata.middleware.CookieNameChange', 'openedx.core.djangoapps.header_control.middleware.HeaderControlMiddleware', diff --git a/lms/djangoapps/certificates/apis/v0/tests/test_views.py b/lms/djangoapps/certificates/apis/v0/tests/test_views.py index 4262631653..9e62eab6d8 100644 --- a/lms/djangoapps/certificates/apis/v0/tests/test_views.py +++ b/lms/djangoapps/certificates/apis/v0/tests/test_views.py @@ -21,6 +21,7 @@ from lms.djangoapps.certificates.tests.factories import GeneratedCertificateFact from openedx.core.djangoapps.content.course_overviews.tests.factories import CourseOverviewFactory from openedx.core.djangoapps.user_api.tests.factories import UserPreferenceFactory from openedx.core.djangoapps.user_authn.tests.utils import JWT_AUTH_TYPES, AuthAndScopesTestMixin, AuthType +from openedx.core.djangoapps.waffle_utils.testutils import WAFFLE_TABLES from xmodule.modulestore.tests.django_utils import SharedModuleStoreTestCase # lint-amnesty, pylint: disable=wrong-import-order from xmodule.modulestore.tests.factories import CourseFactory # lint-amnesty, pylint: disable=wrong-import-order @@ -308,7 +309,7 @@ class CertificatesListRestApiTest(AuthAndScopesTestMixin, SharedModuleStoreTestC def test_query_counts(self): # Test student with no certificates student_no_cert = UserFactory.create(password=self.user_password) - with self.assertNumQueries(18): + with self.assertNumQueries(17, table_ignorelist=WAFFLE_TABLES): resp = self.get_response( AuthType.jwt, requesting_user=self.global_staff, @@ -318,7 +319,7 @@ class CertificatesListRestApiTest(AuthAndScopesTestMixin, SharedModuleStoreTestC assert len(resp.data) == 0 # Test student with 1 certificate - with self.assertNumQueries(12): + with self.assertNumQueries(12, table_ignorelist=WAFFLE_TABLES): resp = self.get_response( AuthType.jwt, requesting_user=self.global_staff, @@ -358,7 +359,7 @@ class CertificatesListRestApiTest(AuthAndScopesTestMixin, SharedModuleStoreTestC download_url='www.google.com', grade="0.88", ) - with self.assertNumQueries(12): + with self.assertNumQueries(12, table_ignorelist=WAFFLE_TABLES): resp = self.get_response( AuthType.jwt, requesting_user=self.global_staff, diff --git a/lms/djangoapps/course_api/tests/test_views.py b/lms/djangoapps/course_api/tests/test_views.py index 984472eaba..1606418bd2 100644 --- a/lms/djangoapps/course_api/tests/test_views.py +++ b/lms/djangoapps/course_api/tests/test_views.py @@ -26,6 +26,7 @@ from common.djangoapps.course_modes.tests.factories import CourseModeFactory from common.djangoapps.student.auth import add_users from common.djangoapps.student.roles import CourseInstructorRole, CourseStaffRole from common.djangoapps.student.tests.factories import AdminFactory +from openedx.core.djangoapps.waffle_utils.testutils import WAFFLE_TABLES from openedx.core.lib.api.view_utils import LazySequence from openedx.features.content_type_gating.models import ContentTypeGatingConfig from openedx.features.course_duration_limits.models import CourseDurationLimitConfig @@ -416,14 +417,14 @@ class CourseListSearchViewTest(CourseApiTestViewMixin, ModuleStoreTestCase, Sear self.setup_user(self.audit_user) # These query counts were found empirically - query_counts = [54, 46, 46, 46, 46, 46, 46, 46, 46, 46, 16] + query_counts = [50, 46, 46, 46, 46, 46, 46, 46, 46, 46, 16] ordered_course_ids = sorted([str(cid) for cid in (course_ids + [c.id for c in self.courses])]) self.clear_caches() for page in range(1, 12): RequestCache.clear_all_namespaces() - with self.assertNumQueries(query_counts[page - 1]): + with self.assertNumQueries(query_counts[page - 1], table_ignorelist=WAFFLE_TABLES): response = self.verify_response(params={'page': page, 'page_size': 30}) assert 'results' in response.data diff --git a/lms/envs/common.py b/lms/envs/common.py index 60ab1084d7..3602943ca7 100644 --- a/lms/envs/common.py +++ b/lms/envs/common.py @@ -2067,8 +2067,7 @@ MIDDLEWARE = [ # Generate code ownership attributes. Keep this immediately after RequestCacheMiddleware. 'edx_django_utils.monitoring.CodeOwnerMonitoringMiddleware', - # After cookie monitoring, but before anything else that looks at - # cookies, especially the session middleware + # Before anything that looks at cookies, especially the session middleware 'openedx.core.djangoapps.cookie_metadata.middleware.CookieNameChange', # Monitoring and logging middleware diff --git a/openedx/core/djangoapps/user_api/accounts/tests/test_views.py b/openedx/core/djangoapps/user_api/accounts/tests/test_views.py index eab01eb100..981f1f5f5b 100644 --- a/openedx/core/djangoapps/user_api/accounts/tests/test_views.py +++ b/openedx/core/djangoapps/user_api/accounts/tests/test_views.py @@ -24,6 +24,7 @@ from openedx.core.djangoapps.oauth_dispatch.jwt import create_jwt_for_user from openedx.core.djangoapps.user_api.accounts import ACCOUNT_VISIBILITY_PREF_KEY from openedx.core.djangoapps.user_api.models import UserPreference from openedx.core.djangoapps.user_api.preferences.api import set_user_preference +from openedx.core.djangoapps.waffle_utils.testutils import WAFFLE_TABLES from openedx.core.djangolib.testing.utils import CacheIsolationTestCase, skip_unless_lms from openedx.features.name_affirmation_api.utils import get_name_affirmation_service @@ -208,7 +209,7 @@ class TestOwnUsernameAPI(CacheIsolationTestCase, UserAPITestCase): """ Internal helper to perform the actual assertion """ - with self.assertNumQueries(queries): + with self.assertNumQueries(queries, table_ignorelist=WAFFLE_TABLES): response = self.send_get(self.client, expected_status=expected_status) if expected_status == 200: data = response.data @@ -220,7 +221,7 @@ class TestOwnUsernameAPI(CacheIsolationTestCase, UserAPITestCase): Test that a client (logged in) can get her own username. """ self.client.login(username=self.user.username, password=TEST_PASSWORD) - self._verify_get_own_username(17) + self._verify_get_own_username(16) def test_get_username_inactive(self): """ @@ -230,7 +231,7 @@ class TestOwnUsernameAPI(CacheIsolationTestCase, UserAPITestCase): self.client.login(username=self.user.username, password=TEST_PASSWORD) self.user.is_active = False self.user.save() - self._verify_get_own_username(17) + self._verify_get_own_username(16) def test_get_username_not_logged_in(self): """ @@ -239,7 +240,7 @@ class TestOwnUsernameAPI(CacheIsolationTestCase, UserAPITestCase): """ # verify that the endpoint is inaccessible when not logged in - self._verify_get_own_username(13, expected_status=401) + self._verify_get_own_username(12, expected_status=401) @ddt.ddt @@ -256,7 +257,7 @@ class TestAccountsAPI(CacheIsolationTestCase, UserAPITestCase): """ ENABLED_CACHES = ['default'] - TOTAL_QUERY_COUNT = 26 + TOTAL_QUERY_COUNT = 25 FULL_RESPONSE_FIELD_COUNT = 30 def setUp(self): @@ -520,7 +521,7 @@ class TestAccountsAPI(CacheIsolationTestCase, UserAPITestCase): """ self.different_client.login(username=self.different_user.username, password=TEST_PASSWORD) self.create_mock_profile(self.user) - with self.assertNumQueries(self._get_num_queries(self.TOTAL_QUERY_COUNT)): + with self.assertNumQueries(self._get_num_queries(self.TOTAL_QUERY_COUNT), table_ignorelist=WAFFLE_TABLES): response = self.send_get(self.different_client) self._verify_full_shareable_account_response(response, account_privacy=ALL_USERS_VISIBILITY) @@ -535,7 +536,7 @@ class TestAccountsAPI(CacheIsolationTestCase, UserAPITestCase): """ self.different_client.login(username=self.different_user.username, password=TEST_PASSWORD) self.create_mock_profile(self.user) - with self.assertNumQueries(self._get_num_queries(self.TOTAL_QUERY_COUNT)): + with self.assertNumQueries(self._get_num_queries(self.TOTAL_QUERY_COUNT), table_ignorelist=WAFFLE_TABLES): response = self.send_get(self.different_client) self._verify_private_account_response(response) @@ -660,7 +661,7 @@ class TestAccountsAPI(CacheIsolationTestCase, UserAPITestCase): """ Internal helper to perform the actual assertions """ - with self.assertNumQueries(queries): + with self.assertNumQueries(queries, table_ignorelist=WAFFLE_TABLES): response = self.send_get(self.client) data = response.data assert self.FULL_RESPONSE_FIELD_COUNT == len(data) @@ -686,7 +687,7 @@ class TestAccountsAPI(CacheIsolationTestCase, UserAPITestCase): assert data['accomplishments_shared'] is False self.client.login(username=self.user.username, password=TEST_PASSWORD) - verify_get_own_information(self._get_num_queries(24)) + verify_get_own_information(self._get_num_queries(23)) # Now make sure that the user can get the same information, even if not active self.user.is_active = False @@ -706,7 +707,7 @@ class TestAccountsAPI(CacheIsolationTestCase, UserAPITestCase): legacy_profile.save() self.client.login(username=self.user.username, password=TEST_PASSWORD) - with self.assertNumQueries(self._get_num_queries(24)): + with self.assertNumQueries(self._get_num_queries(23), table_ignorelist=WAFFLE_TABLES): response = self.send_get(self.client) for empty_field in ("level_of_education", "gender", "country", "state", "bio",): assert response.data[empty_field] is None diff --git a/openedx/core/lib/request_utils.py b/openedx/core/lib/request_utils.py index 0de99c00d7..54e395d14a 100644 --- a/openedx/core/lib/request_utils.py +++ b/openedx/core/lib/request_utils.py @@ -1,16 +1,15 @@ """ Utility functions related to HTTP requests """ import logging +import random import re from urllib.parse import urlparse import crum from django.conf import settings from django.test.client import RequestFactory -from django.utils.deprecation import MiddlewareMixin from edx_django_utils.cache import RequestCache from edx_django_utils.monitoring import set_custom_attribute -from edx_toggles.toggles import WaffleFlag from opaque_keys import InvalidKeyError from opaque_keys.edx.keys import CourseKey from rest_framework.views import exception_handler @@ -20,18 +19,6 @@ from openedx.core.djangoapps.site_configuration import helpers as configuration_ # accommodates course api urls, excluding any course api routes that do not fall under v*/courses, such as v1/blocks. COURSE_REGEX = re.compile(fr'^(.*?/course(s)?/)(?!v[0-9]+/[^/]+){settings.COURSE_ID_PATTERN}') -# .. toggle_name: request_utils.capture_cookie_sizes -# .. toggle_implementation: WaffleFlag -# .. toggle_default: False -# .. toggle_description: Enables more detailed capturing of cookie sizes for monitoring purposes. This can be useful for tracking -# down large cookies if requests are nearing limits on the total size of cookies. See the -# CookieMonitoringMiddleware docstring for details on the monitoring custom attributes that will be set. -# .. toggle_warnings: Enabling this flag will add a number of custom attributes, and could adversely affect other -# monitoring. Only enable temporarily, or lower TOP_N_COOKIES_CAPTURED and TOP_N_COOKIE_GROUPS_CAPTURED django -# settings to capture less data. -# .. toggle_use_cases: open_edx -# .. toggle_creation_date: 2019-02-22 -CAPTURE_COOKIE_SIZES = WaffleFlag('request_utils.capture_cookie_sizes', __name__) log = logging.getLogger(__name__) @@ -103,162 +90,107 @@ def course_id_from_url(url): return None -class CookieMonitoringMiddleware(MiddlewareMixin): +class CookieMonitoringMiddleware: """ Middleware for monitoring the size and growth of all our cookies, to see if we're running into browser limits. """ - def process_request(self, request): + + def __init__(self, get_response): + self.get_response = get_response + + def __call__(self, request): + response = self.get_response(request) + # monitor after response to ensure logging can include user id where possible. + try: + self.log_and_monitor_cookies(request) + except BaseException: + log.exception("Unexpected error logging and monitoring cookies.") + return response + + def log_and_monitor_cookies(self, request): """ - Emit custom attributes for cookie size values for every cookie we have. + Add logging and custom attributes for monitoring cookie sizes. Don't log contents of cookies because that might cause a security issue. We just want to see if any cookies are growing out of control. - A useful NRQL Query: - SELECT count(*), max(`cookies.max.group.size`) from Transaction FACET - `cookies.max.group.name` + Useful NRQL Queries: - SELECT * FROM Transaction WHERE cookies_total_size > 6000 + # Always available + SELECT * FROM Transaction WHERE cookies.header.size > 6000 Attributes that are added by this middleware: - cookies.header.size: The total size in bytes of the cookie header + For all requests: - If CAPTURE_COOKIE_SIZES is enabled, additional attributes will be added: + cookies.header.size: The total size in bytes of the cookie header - cookies..name: The name of the Nth largest cookie - cookies..size: The size of the Nth largest cookie - cookies..group..name: The name of the Nth largest cookie. - cookies.group..size: The size of the Nth largest cookie group. - cookies.max.name: The name of the largest cookie sent by the user. - cookies.max.size: The size of the largest cookie sent by the user. - cookies.max.group.name: The name of the largest group of cookies. A single cookie - counts as a group of one for this calculation. - cookies.max.group.size: The sum total size of all the cookies in the largest group. - cookies_total_size: The sum total size of all cookies in this request. + If COOKIE_HEADER_SIZE_LOGGING_THRESHOLD is reached: + + cookies.header.size.calculated Related Settings (see annotations for details): - - `request_utils.capture_cookie_sizes` - - TOP_N_COOKIES_CAPTURED - - TOP_N_COOKIE_GROUPS_CAPTURED - - COOKIE_SIZE_LOGGING_THRESHOLD + - COOKIE_HEADER_SIZE_LOGGING_THRESHOLD + - COOKIE_SAMPLING_REQUEST_COUNT """ raw_header_cookie = request.META.get('HTTP_COOKIE', '') cookie_header_size = len(raw_header_cookie.encode('utf-8')) + # .. custom_attribute_name: cookies.header.size + # .. custom_attribute_description: The total size in bytes of the cookie header. set_custom_attribute('cookies.header.size', cookie_header_size) - # .. setting_name: COOKIE_SIZE_LOGGING_THRESHOLD + # .. setting_name: COOKIE_HEADER_SIZE_LOGGING_THRESHOLD # .. setting_default: None - # .. setting_description: The minimum size for logging a list of cookie names and sizes. Should be set - # to a relatively high threshold (suggested 9-10K) to avoid flooding the logs. - logging_threshold = getattr(settings, "COOKIE_SIZE_LOGGING_THRESHOLD", None) + # .. setting_description: The minimum size for the full cookie header to log a list of cookie names and sizes. + # Should be set to a relatively high threshold (suggested 9-10K) to avoid flooding the logs. + logging_threshold = getattr(settings, "COOKIE_HEADER_SIZE_LOGGING_THRESHOLD", None) - if logging_threshold and cookie_header_size >= logging_threshold: - sizes = ', '.join(f"{name}: {len(value)}" for (name, value) in sorted(request.COOKIES.items())) - log.info(f"Large (>= {logging_threshold}) cookie header detected. Cookie sizes: {sizes}") - - if not CAPTURE_COOKIE_SIZES.is_enabled(): + if not logging_threshold: return - # .. setting_name: TOP_N_COOKIES_CAPTURED - # .. setting_default: 8 - # .. setting_description: The number of the largest cookies to capture when monitoring. Capture fewer cookies - # if you need to save on monitoring resources. - # .. setting_warning: Depends on the `request_utils.capture_cookie_sizes` toggle being enabled. - top_n_cookies_captured = getattr(settings, "TOP_N_COOKIES_CAPTURED", 8) - # .. setting_name: TOP_N_COOKIE_GROUPS_CAPTURED - # .. setting_default: 5 - # .. setting_description: The number of the largest cookie groups to capture when monitoring. Capture - # fewer cookies if you need to save on monitoring resources. - # .. setting_warning: Depends on the `request_utils.capture_cookie_sizes` toggle being enabled. - top_n_cookie_groups_captured = getattr(settings, "TOP_N_COOKIE_GROUPS_CAPTURED", 5) + is_large_cookie_header_detected = cookie_header_size >= logging_threshold + if not is_large_cookie_header_detected: + # .. setting_name: COOKIE_SAMPLING_REQUEST_COUNT + # .. setting_default: None + # .. setting_description: This setting enables sampling cookie header logging for cookie headers smaller + # than COOKIE_HEADER_SIZE_LOGGING_THRESHOLD. The cookie header logging will happen randomly for each + # request with a chance of 1 in COOKIE_SAMPLING_REQUEST_COUNT. For example, to see approximately one + # sampled log message every 10 minutes, set COOKIE_SAMPLING_REQUEST_COUNT to the average number of + # requests in 10 minutes. + # .. setting_warning: This setting requires COOKIE_HEADER_SIZE_LOGGING_THRESHOLD to be enabled to take + # effect. + sampling_request_count = getattr(settings, "COOKIE_SAMPLING_REQUEST_COUNT", None) - cookie_names_to_size = {} - cookie_groups_to_size = {} + # if the cookie header size is lower than the threshold, skip logging unless configured to do + # random sampling and we choose the lucky number (in this case, 1). + if not sampling_request_count or random.randint(1, sampling_request_count) > 1: + return - for name, value in request.COOKIES.items(): - # Get cookie size for all cookies. - cookie_size = len(value) - cookie_names_to_size[name] = cookie_size + # Sort starting with largest cookies + sorted_cookie_items = sorted(request.COOKIES.items(), key=lambda x: len(x[1]), reverse=True) + sizes = ', '.join(f"{name}: {len(value)}" for (name, value) in sorted_cookie_items) + if is_large_cookie_header_detected: + log_prefix = f"Large (>= {logging_threshold}) cookie header detected." + else: + log_prefix = f"Sampled small (< {logging_threshold}) cookie header." + log.info(f"{log_prefix} BEGIN-COOKIE-SIZES(total={cookie_header_size}) {sizes} END-COOKIE-SIZES") + # The computed header size can be used to double check that there aren't large cookies that are + # duplicates in the original header (from different domains) that aren't being accounted for. + cookies_header_size_computed = max( + 0, sum(len(name) + len(value) + 3 for (name, value) in request.COOKIES.items()) - 2 + ) - # Group cookies by their prefix seperated by a period or underscore - grouping_name = re.split('[._]', name, 1)[0] - if grouping_name and grouping_name != name: - # Add or update the size for this group. - cookie_groups_to_size[grouping_name] = cookie_groups_to_size.get(grouping_name, 0) + cookie_size - - if cookie_names_to_size: - self.set_custom_attributes_for_top_n( - cookie_names_to_size, - top_n_cookies_captured, - attribute_prefix='cookies', - ) - - max_cookie_name = max(cookie_names_to_size, key=lambda name: cookie_names_to_size[name]) - max_cookie_size = cookie_names_to_size[max_cookie_name] - - set_custom_attribute('cookies.max.name', max_cookie_name) - set_custom_attribute('cookies.max.size', max_cookie_size) - - if cookie_groups_to_size: - self.set_custom_attributes_for_top_n( - cookie_groups_to_size, - top_n_cookie_groups_captured, - attribute_prefix='cookies.group', - ) - - max_group_cookie_name = max(cookie_groups_to_size, key=lambda name: cookie_groups_to_size[name]) - max_group_cookie_size = cookie_groups_to_size[max_group_cookie_name] - - # If a single cookies is bigger than any group of cookies, we want max_group... to reflect that. - # Treating an individual cookie as a group of 1 for calculating the max. - if max_group_cookie_size < max_cookie_size: - max_group_cookie_name = max_cookie_name - max_group_cookie_size = max_cookie_size - - set_custom_attribute('cookies.max.group.name', max_group_cookie_name) - set_custom_attribute('cookies.max.group.size', max_group_cookie_size) - - total_cookie_size = sum(cookie_names_to_size.values()) - set_custom_attribute('cookies_total_size', total_cookie_size) - log.debug('cookies_total_size = %d', total_cookie_size) - - top_n_cookies = sorted( - cookie_names_to_size, - key=lambda x: cookie_names_to_size[x], - reverse=True, - )[:top_n_cookies_captured] - top_n_cookies_size = sum([cookie_names_to_size[name] for name in top_n_cookies]) - set_custom_attribute('cookies_unaccounted_size', total_cookie_size - top_n_cookies_size) - - set_custom_attribute('cookies_total_num', len(cookie_names_to_size)) - - def set_custom_attributes_for_top_n(self, names_to_size, top_n_captured, attribute_prefix): - """ - Sets custom metric for the top N biggest cookies or cookie groups. - - Arguments: - names_to_size: Dict of sizes keyed by cookie name or cookie group name - top_n_captured: Number of largest sizes to monitor. - attribute_prefix: Prefix (cookies|cookies.group) to use in the custom attribute name. - """ - top_n_cookies = sorted( - names_to_size, - key=lambda x: names_to_size[x], - reverse=True, - )[:top_n_captured] - for count, name in enumerate(top_n_cookies, start=1): - size = names_to_size[name] - name_attribute = f'{attribute_prefix}.{count}.name' - size_attribute = f'{attribute_prefix}.{count}.size' - - set_custom_attribute(name_attribute, name) - set_custom_attribute(size_attribute, size) - log.debug('%s = %d', name, size) + # .. custom_attribute_name: cookies.header.size.computed + # .. custom_attribute_description: The computed total size in bytes of the cookie header, based on the + # cookies found in request.COOKIES. This value will only be captured for cookie headers larger than + # COOKIE_HEADER_SIZE_LOGGING_THRESHOLD. The value can be used to double check that there aren't large + # cookies that are duplicates in the cookie header (from different domains) that aren't being accounted + # for. + set_custom_attribute('cookies.header.size.computed', cookies_header_size_computed) def expected_error_exception_handler(exc, context): diff --git a/openedx/core/lib/tests/test_request_utils.py b/openedx/core/lib/tests/test_request_utils.py index af6f7bc44d..7290723cbc 100644 --- a/openedx/core/lib/tests/test_request_utils.py +++ b/openedx/core/lib/tests/test_request_utils.py @@ -102,190 +102,90 @@ class RequestUtilTestCase(unittest.TestCase): assert course_id.course == course assert course_id.run == run - @patch("openedx.core.lib.request_utils.CAPTURE_COOKIE_SIZES") - @patch("openedx.core.lib.request_utils.set_custom_attribute") - def test_basic_cookie_monitoring(self, mock_set_custom_attribute, mock_capture_cookie_sizes): - mock_capture_cookie_sizes.is_enabled.return_value = False - middleware = CookieMonitoringMiddleware() - cookies_dict = {'a': 'b'} +@ddt.ddt +class CookieMonitoringMiddlewareTestCase(unittest.TestCase): + """ + Tests for CookieMonitoringMiddleware. + """ + def setUp(self): + super().setUp() + self.mock_response = Mock() - factory = RequestFactory() - for name, value in cookies_dict.items(): - factory.cookies[name] = value - - mock_request = factory.request() - - middleware.process_request(mock_request) - - mock_set_custom_attribute.assert_called_once_with('cookies.header.size', 3) - - @patch("openedx.core.lib.request_utils.CAPTURE_COOKIE_SIZES") - @patch("openedx.core.lib.request_utils.set_custom_attribute") - def test_cookie_monitoring(self, mock_set_custom_attribute, mock_capture_cookie_sizes): - - mock_capture_cookie_sizes.is_enabled.return_value = True - middleware = CookieMonitoringMiddleware() - - cookies_dict = { - "a": "." * 100, - "_b": "." * 13, - "_c_": "." * 13, - "a.b": "." * 10, - "a.c": "." * 10, - "b.": "." * 13, - "b_a": "." * 15, - "b_c": "." * 15, - "d": "." * 3, - } - - factory = RequestFactory() - for name, value in cookies_dict.items(): - factory.cookies[name] = value - - mock_request = factory.request() - - middleware.process_request(mock_request) - - mock_set_custom_attribute.assert_has_calls([ - call('cookies.1.name', 'a'), - call('cookies.1.size', 100), - call('cookies.2.name', 'b_a'), - call('cookies.2.size', 15), - call('cookies.3.name', 'b_c'), - call('cookies.3.size', 15), - call('cookies.4.name', '_b'), - call('cookies.4.size', 13), - call('cookies.5.name', '_c_'), - call('cookies.5.size', 13), - call('cookies.6.name', 'b.'), - call('cookies.6.size', 13), - call('cookies.7.name', 'a.b'), - call('cookies.7.size', 10), - call('cookies.8.name', 'a.c'), - call('cookies.8.size', 10), - call('cookies.group.1.name', 'b'), - call('cookies.group.1.size', 43), - call('cookies.group.2.name', 'a'), - call('cookies.group.2.size', 20), - call('cookies.max.name', 'a'), - call('cookies.max.size', 100), - call('cookies.max.group.name', 'a'), - call('cookies.max.group.size', 100), - call('cookies_total_size', 192), - call('cookies_unaccounted_size', 3), - call('cookies_total_num', 9), - call('cookies.header.size', 238) - ], any_order=True) - - @patch("openedx.core.lib.request_utils.CAPTURE_COOKIE_SIZES") - @patch("openedx.core.lib.request_utils.set_custom_attribute") - def test_cookie_monitoring_max_group(self, mock_set_custom_attribute, mock_capture_cookie_sizes): - - mock_capture_cookie_sizes.is_enabled.return_value = True - middleware = CookieMonitoringMiddleware() - - cookies_dict = { - "a": "." * 10, - "b_a": "." * 15, - "b_c": "." * 20, - } - - factory = RequestFactory() - for name, value in cookies_dict.items(): - factory.cookies[name] = value - - mock_request = factory.request() - - middleware.process_request(mock_request) - - mock_set_custom_attribute.assert_has_calls([ - call('cookies.1.name', 'b_c'), - call('cookies.1.size', 20), - call('cookies.2.name', 'b_a'), - call('cookies.2.size', 15), - call('cookies.3.name', 'a'), - call('cookies.3.size', 10), - call('cookies.group.1.name', 'b'), - call('cookies.group.1.size', 35), - call('cookies.max.name', 'b_c'), - call('cookies.max.size', 20), - call('cookies.max.group.name', 'b'), - call('cookies.max.group.size', 35), - call('cookies_total_size', 45) - ], any_order=True) - - @patch("openedx.core.lib.request_utils.CAPTURE_COOKIE_SIZES") - @patch("openedx.core.lib.request_utils.set_custom_attribute") - def test_cookie_monitoring_no_cookies(self, mock_set_custom_attribute, mock_capture_cookie_sizes): - - mock_capture_cookie_sizes.is_enabled.return_value = True - middleware = CookieMonitoringMiddleware() - - cookies_dict = {} - - factory = RequestFactory() - for name, value in cookies_dict.items(): - factory.cookies[name] = value - - mock_request = factory.request() - - middleware.process_request(mock_request) - - mock_set_custom_attribute.assert_has_calls([ - call('cookies_total_size', 0), - call('cookies.header.size', 0) - ], any_order=True) - - @patch("openedx.core.lib.request_utils.CAPTURE_COOKIE_SIZES") - @patch("openedx.core.lib.request_utils.set_custom_attribute") - def test_cookie_monitoring_no_groups(self, mock_set_custom_attribute, mock_capture_cookie_sizes): - - mock_capture_cookie_sizes.is_enabled.return_value = True - middleware = CookieMonitoringMiddleware() - - cookies_dict = { - "a": "." * 10, - "b": "." * 15, - } - - factory = RequestFactory() - for name, value in cookies_dict.items(): - factory.cookies[name] = value - - mock_request = factory.request() - - middleware.process_request(mock_request) - - mock_set_custom_attribute.assert_has_calls([ - call('cookies.max.name', 'b'), - call('cookies.max.size', 15), - call('cookies.1.name', 'b'), - call('cookies.1.size', 15), - call('cookies.2.name', 'a'), - call('cookies.2.size', 10), - call('cookies_total_size', 25), - ], any_order=True) - - @override_settings(COOKIE_SIZE_LOGGING_THRESHOLD=1) - @patch("openedx.core.lib.request_utils.CAPTURE_COOKIE_SIZES.is_enabled", return_value=False) @patch('openedx.core.lib.request_utils.log', autospec=True) - def test_log_cookie_sizes(self, mock_logger, _): - middleware = CookieMonitoringMiddleware() + @patch("openedx.core.lib.request_utils.set_custom_attribute") + @ddt.data( + (None, None), # logging threshold not defined + (5, None), # logging threshold too high + (5, 9999999999999999999), # logging threshold too high, and random sampling impossibly unlikely + ) + @ddt.unpack + def test_cookie_monitoring_with_no_logging( + self, logging_threshold, sampling_request_count, mock_set_custom_attribute, mock_logger + ): + middleware = CookieMonitoringMiddleware(self.mock_response) + cookies_dict = {'a': 'y'} + + with override_settings(COOKIE_HEADER_SIZE_LOGGING_THRESHOLD=logging_threshold): + with override_settings(COOKIE_SAMPLING_REQUEST_COUNT=sampling_request_count): + middleware(self.get_mock_request(cookies_dict)) + + # expect monitoring of header size for all requests + mock_set_custom_attribute.assert_called_once_with('cookies.header.size', 3) + # cookie logging was not enabled, so nothing should be logged + mock_logger.info.assert_not_called() + + @override_settings(COOKIE_HEADER_SIZE_LOGGING_THRESHOLD=1) + @patch('openedx.core.lib.request_utils.log', autospec=True) + @patch("openedx.core.lib.request_utils.set_custom_attribute") + def test_log_cookie_with_threshold_met(self, mock_set_custom_attribute, mock_logger): + middleware = CookieMonitoringMiddleware(self.mock_response) cookies_dict = { - "a": "." * 10, - "b": "." * 15, + "a": "yy", + "b": "xxx", + "c": "z", } + + middleware(self.get_mock_request(cookies_dict)) + + mock_set_custom_attribute.assert_has_calls([ + call('cookies.header.size', 16), + call('cookies.header.size.computed', 16) + ]) + mock_logger.info.assert_called_once_with( + "Large (>= 1) cookie header detected. BEGIN-COOKIE-SIZES(total=16) b: 3, a: 2, c: 1 END-COOKIE-SIZES" + ) + + @override_settings(COOKIE_HEADER_SIZE_LOGGING_THRESHOLD=9999) + @override_settings(COOKIE_SAMPLING_REQUEST_COUNT=1) + @patch('openedx.core.lib.request_utils.log', autospec=True) + @patch("openedx.core.lib.request_utils.set_custom_attribute") + def test_log_cookie_with_sampling(self, mock_set_custom_attribute, mock_logger): + middleware = CookieMonitoringMiddleware(self.mock_response) + cookies_dict = { + "a": "yy", + "b": "xxx", + "c": "z", + } + + middleware(self.get_mock_request(cookies_dict)) + + mock_set_custom_attribute.assert_has_calls([ + call('cookies.header.size', 16), + call('cookies.header.size.computed', 16) + ]) + mock_logger.info.assert_called_once_with( + "Sampled small (< 9999) cookie header. BEGIN-COOKIE-SIZES(total=16) b: 3, a: 2, c: 1 END-COOKIE-SIZES" + ) + + def get_mock_request(self, cookies_dict): + """ + Return mock request with the provided cookies in the header. + """ factory = RequestFactory() for name, value in cookies_dict.items(): factory.cookies[name] = value - mock_request = factory.request() - - middleware.process_request(mock_request) - - mock_logger.info.assert_called_once_with( - "Large (>= 1) cookie header detected. Cookie sizes: a: 10, b: 15" - ) + return factory.request() class TestGetExpectedErrorSettingsDict(unittest.TestCase):