Andal.LND/edx-platform
6
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

feat: enhance cookie monitoring and logging

Browse Source 
Contains a number of cookie monitoring changes.

Enhancements:
- Add sampling capability for cookie logging on headers
 smaller than the threshold. For details, see
 COOKIE_SAMPLING_REQUEST_COUNT.
- Add cookie header size to log message.
- Sort logged cookies starting with largest cookie.
- Move logging from Middleware request processing
 to response processing to ensure the user id is
 available for logging for authenticated calls.
- Added cookies.header.size.computed to check
 if there are any large hidden duplicate cookies.
 Can be compared against the cookies.header.size
 custom attribute.
- Add delimiters into logs to make it simpler to parse
 when the logging tools accidentally exports multiple
 log lines together.

Removed:
- Legacy cookie capture code. This code was dangerous to
  to enable and provided more limited insight than the
  newer logging, so this was removed to simplify the code.

Other refactors:
- Switched Middleware to use new Django format, rather
 than the Mixin.
- Moved tests to its own test class. Note: this
 middleware is likely to move to a separate
 library.

ARCHBOM-2055
This commit is contained in:
Robert Raposa
2022-03-08 16:20:27 -05:00
parent 8b775961a6
commit 29e50710dc
7 changed files with 166 additions and 333 deletions
Download Patch File Download Diff File Expand all files Collapse all files

3
cms/envs/common.py
View File

@@ -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',

7
lms/djangoapps/certificates/apis/v0/tests/test_views.py
View File

@@ -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,

5
lms/djangoapps/course_api/tests/test_views.py
View File

@@ -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

3
lms/envs/common.py
View File

@@ -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

21
openedx/core/djangoapps/user_api/accounts/tests/test_views.py
View File

@@ -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

208
openedx/core/lib/request_utils.py
View File

@@ -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.<N>.name: The name of the Nth largest cookie
cookies.<N>.size: The size of the Nth largest cookie
cookies..group.<N>.name: The name of the Nth largest cookie.
cookies.group.<N>.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):

252
openedx/core/lib/tests/test_request_utils.py
View File

@@ -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):