From 1876e0771a45df6e53ec758876cb3993c5686f46 Mon Sep 17 00:00:00 2001 From: alexis Date: Sat, 3 Jan 2026 21:12:48 +0800 Subject: [PATCH 1/5] feat: add log filter --- .gitignore | 1 - apps/auth/utils.py | 4 ++- apps/auth/views.py | 4 ++- apps/web/views.py | 3 +- lib/logging.py | 81 ++++++++++++++++++++++++++++++++++++++++++++++ 5 files changed, 89 insertions(+), 4 deletions(-) create mode 100644 lib/logging.py diff --git a/.gitignore b/.gitignore index a18385a..43836a2 100644 --- a/.gitignore +++ b/.gitignore @@ -16,7 +16,6 @@ dist/ downloads/ eggs/ .eggs/ -lib/ lib64/ parts/ sdist/ diff --git a/apps/auth/utils.py b/apps/auth/utils.py index 4c60c36..b7b4ab2 100644 --- a/apps/auth/utils.py +++ b/apps/auth/utils.py @@ -14,7 +14,9 @@ from apps.web.models import Student -logger = logging.getLogger(__name__) +from lib.logging import add_sanitization_to_logger + +logger = add_sanitization_to_logger(logging.getLogger(__name__)) AUTH_SETTINGS = settings.AUTH PASSWORD_LENGTH_MIN = AUTH_SETTINGS["PASSWORD_LENGTH_MIN"] diff --git a/apps/auth/views.py b/apps/auth/views.py index df1672d..90dff58 100644 --- a/apps/auth/views.py +++ b/apps/auth/views.py @@ -21,7 +21,9 @@ from apps.auth import utils from apps.web.models import Student -logger = logging.getLogger(__name__) +from lib.logging import add_sanitization_to_logger + +logger = add_sanitization_to_logger(logging.getLogger(__name__)) AUTH_SETTINGS = settings.AUTH diff --git a/apps/web/views.py b/apps/web/views.py index 47e177e..c43f153 100644 --- a/apps/web/views.py +++ b/apps/web/views.py @@ -28,8 +28,9 @@ from lib.departments import get_department_name from lib.grades import numeric_value_for_grade from lib.terms import numeric_value_of_term +from lib.logging import add_sanitization_to_logger -logger = logging.getLogger(__name__) +logger = add_sanitization_to_logger(logging.getLogger(__name__)) class CoursesPagination(pagination.PageNumberPagination): diff --git a/lib/logging.py b/lib/logging.py new file mode 100644 index 0000000..68ce93c --- /dev/null +++ b/lib/logging.py @@ -0,0 +1,81 @@ +import logging +import re + + +class SanitizationFilter(logging.Filter): + """ + A logging filter that sanitizes log messages to prevent log injection. + Automatically removes control characters, ANSI escape sequences, and truncates long messages. + """ + + def __init__(self, max_length=1000): + super().__init__() + self.max_length = max_length + + def filter(self, record): + """Filter and sanitize the log record.""" + # Sanitize any string arguments first + if hasattr(record, "args") and record.args: + sanitized_args = tuple( + self._sanitize_value(arg) if isinstance(arg, str) else arg + for arg in record.args + ) + record.args = sanitized_args + + # Sanitize the main message + if hasattr(record, "msg"): + record.msg = self._sanitize_value(record.msg) + + # Override getMessage to return sanitized message + if hasattr(record, "getMessage"): + original_get_message = record.getMessage + + def get_sanitized_message(): + message = original_get_message() + return self._sanitize_value(message) + + record.getMessage = get_sanitized_message + + return True + + def _sanitize_value(self, value): + """ + Sanitize a value to prevent log injection. + + Args: + value: The value to sanitize (can be any type) + + Returns: + A safe string for logging + """ + if value is None: + return "None" + + # Convert to string + str_value = str(value) + + # Truncate to max_length to prevent log flooding + if len(str_value) > self.max_length: + str_value = str_value[: self.max_length] + "...[truncated]" + + # Remove control characters that could cause log injection + # Remove \r, \n, \t and other control characters + str_value = re.sub(r"[\r\n\t\x00-\x08\x0B\x0C\x0E-\x1F\x7F]", "", str_value) + + # Remove potential ANSI escape sequences used for terminal control + str_value = re.sub(r"\x1B\[[0-9;]*[mK]", "", str_value) + + return str_value + + +def add_sanitization_to_logger(logger, max_length=1000): + """ + Add sanitization filter to a logger instance. + + Args: + logger: The logger instance to add the filter to + max_length: Maximum length for log messages + """ + sanitization_filter = SanitizationFilter(max_length) + logger.addFilter(sanitization_filter) + return logger From 5a914e58a228278d6983a0314e8feec725ddfe47 Mon Sep 17 00:00:00 2001 From: alexis Date: Wed, 21 Jan 2026 09:36:12 +0800 Subject: [PATCH 2/5] format: run ruff format --- apps/auth/utils.py | 1 - apps/auth/views.py | 1 - apps/web/views.py | 2 +- 3 files changed, 1 insertion(+), 3 deletions(-) diff --git a/apps/auth/utils.py b/apps/auth/utils.py index b7b4ab2..ced440c 100644 --- a/apps/auth/utils.py +++ b/apps/auth/utils.py @@ -13,7 +13,6 @@ from rest_framework.response import Response from apps.web.models import Student - from lib.logging import add_sanitization_to_logger logger = add_sanitization_to_logger(logging.getLogger(__name__)) diff --git a/apps/auth/views.py b/apps/auth/views.py index 90dff58..16698f3 100644 --- a/apps/auth/views.py +++ b/apps/auth/views.py @@ -20,7 +20,6 @@ from apps.auth import utils from apps.web.models import Student - from lib.logging import add_sanitization_to_logger logger = add_sanitization_to_logger(logging.getLogger(__name__)) diff --git a/apps/web/views.py b/apps/web/views.py index c43f153..458a6ba 100644 --- a/apps/web/views.py +++ b/apps/web/views.py @@ -27,8 +27,8 @@ ) from lib.departments import get_department_name from lib.grades import numeric_value_for_grade -from lib.terms import numeric_value_of_term from lib.logging import add_sanitization_to_logger +from lib.terms import numeric_value_of_term logger = add_sanitization_to_logger(logging.getLogger(__name__)) From 417f864bbe8b29f3f974f09a343401a4b9a681a1 Mon Sep 17 00:00:00 2001 From: barca0927 Date: Mon, 2 Feb 2026 17:00:08 +0800 Subject: [PATCH 3/5] refactor: unify log placeholders and complete log context --- apps/auth/utils.py | 26 ++++++++++++------------ apps/auth/views.py | 49 ++++++++++++++++++++++++---------------------- apps/web/views.py | 6 +++--- 3 files changed, 43 insertions(+), 38 deletions(-) diff --git a/apps/auth/utils.py b/apps/auth/utils.py index ced440c..eb70b6a 100644 --- a/apps/auth/utils.py +++ b/apps/auth/utils.py @@ -42,14 +42,15 @@ def get_survey_details(action: str) -> dict[str, Any] | None: action_details = QUEST_SETTINGS.get(action.upper()) if not action_details: - logger.error("Invalid quest action requested: %s", action) + logger.error("Invalid quest action requested in get_survey_details: %r, valid actions: %r", + action, ["signup", "login", "reset_password"]) return None try: question_id = int(action_details.get("QUESTIONID")) except (ValueError, TypeError): logger.error( - "Could not parse 'QUESTIONID' for action '%s'. Check your settings.", action + "Could not parse 'QUESTIONID' for action %r (value=%r). Reason: QUESTIONID isn't a valid number. Check your settings.", action, action_details.get("QUESTIONID") ) return None @@ -76,18 +77,18 @@ async def verify_turnstile_token( }, ) if not response.json().get("success"): - logger.warning("Turnstile verification failed: %s", response.json()) + logger.warning("Turnstile verification failed. Response: %r", response.json()) return False, Response( {"error": "Turnstile verification failed"}, status=403 ) return True, None except httpx.TimeoutException: - logger.error("Turnstile verification timed out") + logger.error("Turnstile verification timed out after %r seconds", OTP_TIMEOUT) return False, Response( {"error": "Turnstile verification timed out"}, status=504 ) - except Exception: - logger.error("Turnstile verification error") + except Exception as e: + logger.error("Turnstile verification failed with unexpected error: %r", e) return False, Response({"error": "Turnstile verification error"}, status=500) @@ -142,19 +143,19 @@ async def get_latest_answer( response.raise_for_status() # Raise an exception for bad status codes full_data = response.json() except httpx.TimeoutException: - logger.error("Questionnaire API query timed out") + logger.error("Questionnaire API query timed out after %r seconds for action %r, account %r", OTP_TIMEOUT, action, account) return None, Response( {"error": "Questionnaire API query timed out"}, status=504, ) - except httpx.RequestError: - logger.error("Error querying questionnaire API") + except httpx.RequestError as e: + logger.error("Failed to query questionnaire API for action %r, account %r (URL: %r, error: %r)", action, account, full_url_path, e) return None, Response( {"error": "Failed to query questionnaire API"}, status=500, ) - except Exception: - logger.error("An unexpected error occurred") + except Exception as e: + logger.error("Unexpected error while ing questionnaire response for action %r, account %r: %r", action, account, e) return None, Response({"error": "An unexpected error occurred"}, status=500) # Filter and return only the required fields from the first row @@ -190,7 +191,8 @@ async def get_latest_answer( key in filtered_data and filtered_data[key] is not None for key in ["id", "submitted_at", "account", "otp"] ): - logger.warning("Missing required field(s) in questionnaire response") + missing_fields = [key for key in ["id", "submitted_at", "account", "otp"] if key not in filtered_data or filtered_data[key] is None] + logger.warning("Missing required field(s) in questionnaire response for action %r, account %r. Missing: %r", action, account, missing_fields) return None, Response( {"error": "Missing required field(s) in questionnaire response"}, status=400, diff --git a/apps/auth/views.py b/apps/auth/views.py index 16698f3..6a5dea3 100644 --- a/apps/auth/views.py +++ b/apps/auth/views.py @@ -49,11 +49,11 @@ def auth_initiate_api(request): turnstile_token = request.data.get("turnstile_token") if not action or not turnstile_token: - logger.warning("Missing action or turnstile_token in auth_initiate_api") + logger.warning("Missing action or turnstile_token in auth_initiate_api, action: %r, turnstile_token_present: %r", action, bool(turnstile_token)) return Response({"error": "Missing action or turnstile_token"}, status=400) if action not in ACTION_LIST: - logger.warning("Invalid action '%s' in auth_initiate_api", action) + logger.warning("Invalid action '%r' in auth_initiate_api", action) return Response({"error": "Invalid action"}, status=400) client_ip = ( @@ -68,7 +68,9 @@ def auth_initiate_api(request): ) if not success: logger.warning( - "verify_turnstile_token failed in auth_initiate_api:%s", + "Turnstile verification failed: action=%r, client_ip=%r, response=%r", + action, + client_ip, error_response.data, ) return error_response @@ -91,11 +93,11 @@ def auth_initiate_api(request): existing_state = json.loads(existing_state_data) r.delete(existing_state_key) logger.info( - "Cleaned up existing temp_token_state for action %s", + "Cleaned up existing temp_token_state for action %r", existing_state.get("action", "unknown"), ) except Exception: - logger.warning("Error cleaning up existing temp_token") + logger.warning("Error cleaning up existing temp_token (hash: %r)", existing_hash) # Store OTP -> temp_token mapping with initiated_at timestamp current_time = time.time() @@ -111,15 +113,15 @@ def auth_initiate_api(request): json.dumps(temp_token_state), ) - logger.info("Created auth intent for action %s with OTP and temp_token", action) + logger.info("Created auth intent for action %r with OTP and temp_token", action) details = utils.get_survey_details(action) if not details: - logger.error("Invalid action '%s' when fetching survey details", action) + logger.error("Invalid action '%r' when fetching survey details", action) return Response({"error": "Invalid action"}, status=400) survey_url = details.get("url") if not survey_url: - logger.error("Survey URL missing for %s", action) + logger.error("Survey URL missing for %r", action) return Response( {"error": "Something went wrong when fetching the survey URL"}, status=500, @@ -147,7 +149,7 @@ def verify_callback_api(request): Handles the verification of questionnaire callback using temp_token from cookie. """ logger.info( - "verify_callback_api called for account=%s, action=%s", + "verify_callback_api called for account=%r, action=%r", request.data.get("account"), request.data.get("action"), ) @@ -157,11 +159,11 @@ def verify_callback_api(request): action = request.data.get("action") if not account or not answer_id or not action: - logger.warning("Missing account, answer_id, or action in verify_callback_api") + logger.warning("Missing required parameters in verify_callback_api (account: %r, answer_id: %r, action: %r)", request.data.get("account"), request.data.get("answer_id"), request.data.get("action")) return Response({"error": "Missing account, answer_id, or action"}, status=400) if action not in ACTION_LIST: - logger.warning("Invalid action '%s' in verify_callback_api", action) + logger.warning("Invalid action '%r' in verify_callback_api", action) return Response({"error": "Invalid action"}, status=400) # Get temp_token from HttpOnly cookie @@ -193,7 +195,7 @@ def verify_callback_api(request): return Response({"error": "Invalid temp token state"}, status=401) if state_data.get("action") != action: - logger.warning("Action mismatch in verify_callback_api") + logger.warning("Action mismatch in verify_callback_api: expected %r, got %r", state_data.get("action"), action) return Response({"error": "Action mismatch"}, status=403) # Step 2: Apply rate limiting per temp_token to prevent brute-force attempts @@ -223,7 +225,7 @@ def verify_callback_api(request): # Check if this is the submission we're looking for if str(latest_answer.get("id")) != str(answer_id): - logger.warning("Answer ID mismatch in verify_callback_api") + logger.warning("Answer ID mismatch in verify_callback_api: expected %r, got %r", latest_answer.get("id"), answer_id) return Response({"error": "Answer ID mismatch"}, status=403) # Extract OTP and quest_id from submission @@ -251,7 +253,7 @@ def verify_callback_api(request): # Step 5: StepVerify temp_token matches if expected_temp_token != temp_token: - logger.warning("Invalid temp_token in verify_callback_api") + logger.warning("Invalid temp_token in verify_callback_api: expected %r, got %r", expected_temp_token, temp_token) return Response({"error": "Invalid temp_token"}, status=401) # Step 6: Validate submission timestamp after OTP extraction @@ -270,7 +272,7 @@ def verify_callback_api(request): ) except (ValueError, TypeError): - logger.error("Error parsing submission timestamp") + logger.error("Error parsing submission timestamp string %r", latest_answer.get("submitted_at")) return Response({"error": "Invalid submission timestamp"}, status=401) # Step 7: Update state to verified and add user details @@ -289,7 +291,7 @@ def verify_callback_api(request): r.delete(rate_limit_key) logger.info( - "Successfully verified temp_token for user %s with action %s", + "Successfully verified temp_token for user %r with action %r", account, action, ) @@ -301,15 +303,16 @@ def verify_callback_api(request): if user is None: if error_response: logger.error( - "Failed to create session for login: %s", + "Failed to create session: account=%r, action=%r, error=%r", + account, action, getattr(error_response, "data", {}).get("error", "Unknown error"), ) return error_response else: - logger.error("Failed to create user session in verify_callback_api") + logger.error("Failed to create user session in verify_callback_api for account %r, action %r", account, action) return Response({"error": "Failed to create user session"}, status=500) if not user.is_active: - logger.warning("Inactive user attempted OAuth login: %s", account) + logger.warning("Inactive user attempted OAuth login: %r", account) return Response({"error": "User account is inactive"}, status=403) try: # Create Django session @@ -319,7 +322,7 @@ def verify_callback_api(request): r.delete(state_key) except Exception: logger.exception( - "Error during login session creation or cleanup for user %s", account + "Error during login session creation or cleanup for user %r", account ) return Response({"error": "Failed to finalize login process"}, status=500) @@ -423,7 +426,7 @@ def auth_signup_api(request) -> Response: return response except Exception: - logger.error("Error in auth_signup_api") + logger.error("Error in auth_signup_api for account %r", request.data.get("account")) return Response({"error": "Failed to complete signup"}, status=500) @@ -465,7 +468,7 @@ def auth_reset_password_api(request) -> Response: return response except Exception: - logger.error("Error in auth_reset_password_api") + logger.error("Error in auth_reset_password_api for account %r", account) return Response({"error": "Failed to reset password"}, status=500) @@ -513,7 +516,7 @@ def auth_login_api(request) -> Response: @permission_classes([AllowAny]) def auth_logout_api(request) -> Response: logger.info( - "auth_logout_api called for user=%s", + "auth_logout_api called for user=%r", getattr(request.user, "username", None), ) """Logout a user.""" diff --git a/apps/web/views.py b/apps/web/views.py index 458a6ba..cd1f055 100644 --- a/apps/web/views.py +++ b/apps/web/views.py @@ -48,7 +48,7 @@ def user_status(request): - Anonymous user: {"isAuthenticated": false} """ if request.user.is_authenticated: - logger.info("User is authenticated") + logger.info("User is authenticated, user_id=%d", request.user.id) return Response({"isAuthenticated": True, "username": request.user.username}) else: logger.info("User is not authenticated") @@ -285,7 +285,7 @@ def post(self, request, *args, **kwargs): # Validate and save review using ReviewSerializer serializer = ReviewSerializer(data=request.data) if not serializer.is_valid(): - logger.warning("Review serializer errors: %s", serializer.errors) + logger.warning("Failed to validate review for course %d, user %d, serializer errors: %r", course.id, request.user.id, serializer.errors) return Response(serializer.errors, status=status.HTTP_400_BAD_REQUEST) serializer.save(course=course, user=request.user) @@ -575,7 +575,7 @@ def review_vote_api(request, review_id): if kudos_count is None or dislike_count is None: # Review doesn't exist - logger.warning("Review %s not found for voting", str(review_id)) + logger.warning("Review %r not found for voting, user_id=%d", review_id, request.user.id) return Response({"detail": "Review not found"}, status=404) return Response( From 2ddc03703f9a2080f68fbecfd1d8005439cecc5a Mon Sep 17 00:00:00 2001 From: barca0927 Date: Tue, 3 Feb 2026 14:31:05 +0800 Subject: [PATCH 4/5] refactor: fix wrong log content and clean sensitive info --- apps/auth/views.py | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/apps/auth/views.py b/apps/auth/views.py index 6a5dea3..8a94ebd 100644 --- a/apps/auth/views.py +++ b/apps/auth/views.py @@ -49,7 +49,7 @@ def auth_initiate_api(request): turnstile_token = request.data.get("turnstile_token") if not action or not turnstile_token: - logger.warning("Missing action or turnstile_token in auth_initiate_api, action: %r, turnstile_token_present: %r", action, bool(turnstile_token)) + logger.warning("Missing action or turnstile_token in auth_initiate_api, action: %r", action) return Response({"error": "Missing action or turnstile_token"}, status=400) if action not in ACTION_LIST: @@ -68,9 +68,8 @@ def auth_initiate_api(request): ) if not success: logger.warning( - "Turnstile verification failed: action=%r, client_ip=%r, response=%r", + "Turnstile verification failed: action=%r, response=%r", action, - client_ip, error_response.data, ) return error_response @@ -97,7 +96,7 @@ def auth_initiate_api(request): existing_state.get("action", "unknown"), ) except Exception: - logger.warning("Error cleaning up existing temp_token (hash: %r)", existing_hash) + logger.warning("Error cleaning up existing temp_token") # Store OTP -> temp_token mapping with initiated_at timestamp current_time = time.time() @@ -253,7 +252,7 @@ def verify_callback_api(request): # Step 5: StepVerify temp_token matches if expected_temp_token != temp_token: - logger.warning("Invalid temp_token in verify_callback_api: expected %r, got %r", expected_temp_token, temp_token) + logger.warning("Invalid temp_token in verify_callback_api: temp_token mismatch") return Response({"error": "Invalid temp_token"}, status=401) # Step 6: Validate submission timestamp after OTP extraction From a614f9254be5f07f35e52997faceb704ef10581f Mon Sep 17 00:00:00 2001 From: barca0927 Date: Tue, 3 Feb 2026 14:48:46 +0800 Subject: [PATCH 5/5] refactor: add mask_identifier for sensitive info --- apps/auth/views.py | 52 +++++++++++++++++++++++++++++++++++----------- 1 file changed, 40 insertions(+), 12 deletions(-) diff --git a/apps/auth/views.py b/apps/auth/views.py index 8a94ebd..0005c04 100644 --- a/apps/auth/views.py +++ b/apps/auth/views.py @@ -24,6 +24,29 @@ logger = add_sanitization_to_logger(logging.getLogger(__name__)) +def mask_identifier(val: str | None) -> str: + """Return a masked version of an identifier (email or username) for safe logging.""" + if not val: + return "None" + try: + s = str(val) + except Exception: + return "[unrepresentable]" + # Mask emails keeping domain + if "@" in s: + name, domain = s.split("@", 1) + if len(name) <= 1: + masked_name = "*" + elif len(name) == 2: + masked_name = name[0] + "*" + else: + masked_name = name[0] + "***" + name[-1] + return f"{masked_name}@{domain}" + # Fallback: keep first 4 chars + if len(s) <= 4: + return s[0] + "***" + return s[:4] + "...[masked]" + AUTH_SETTINGS = settings.AUTH OTP_TIMEOUT = AUTH_SETTINGS["OTP_TIMEOUT"] @@ -95,8 +118,8 @@ def auth_initiate_api(request): "Cleaned up existing temp_token_state for action %r", existing_state.get("action", "unknown"), ) - except Exception: - logger.warning("Error cleaning up existing temp_token") + except Exception as e: + logger.warning("Error cleaning up existing temp_token: %r", e) # Store OTP -> temp_token mapping with initiated_at timestamp current_time = time.time() @@ -149,7 +172,7 @@ def verify_callback_api(request): """ logger.info( "verify_callback_api called for account=%r, action=%r", - request.data.get("account"), + mask_identifier(request.data.get("account")), request.data.get("action"), ) # Get required parameters from request @@ -158,7 +181,12 @@ def verify_callback_api(request): action = request.data.get("action") if not account or not answer_id or not action: - logger.warning("Missing required parameters in verify_callback_api (account: %r, answer_id: %r, action: %r)", request.data.get("account"), request.data.get("answer_id"), request.data.get("action")) + logger.warning( + "Missing required parameters in verify_callback_api (account: %r, answer_id: %r, action: %r)", + mask_identifier(request.data.get("account")), + request.data.get("answer_id"), + request.data.get("action"), + ) return Response({"error": "Missing account, answer_id, or action"}, status=400) if action not in ACTION_LIST: @@ -291,7 +319,7 @@ def verify_callback_api(request): logger.info( "Successfully verified temp_token for user %r with action %r", - account, + mask_identifier(account), action, ) @@ -303,16 +331,16 @@ def verify_callback_api(request): if error_response: logger.error( "Failed to create session: account=%r, action=%r, error=%r", - account, action, + mask_identifier(account), action, getattr(error_response, "data", {}).get("error", "Unknown error"), ) return error_response else: - logger.error("Failed to create user session in verify_callback_api for account %r, action %r", account, action) + logger.error("Failed to create user session: account=%r, action=%r", mask_identifier(account), action) return Response({"error": "Failed to create user session"}, status=500) if not user.is_active: - logger.warning("Inactive user attempted OAuth login: %r", account) - return Response({"error": "User account is inactive"}, status=403) + logger.warning("Inactive user attempted OAuth login: %r", mask_identifier(account)) + return Response({"error": "User account is inactive"}, status=403) try: # Create Django session login(request, user) @@ -321,9 +349,9 @@ def verify_callback_api(request): r.delete(state_key) except Exception: logger.exception( - "Error during login session creation or cleanup for user %r", account + "Error during login session creation or cleanup for user %r", mask_identifier(account) ) - return Response({"error": "Failed to finalize login process"}, status=500) + return Response({"error": "Failed to finalize login process"}, status=500) # Create response response = Response( @@ -516,7 +544,7 @@ def auth_login_api(request) -> Response: def auth_logout_api(request) -> Response: logger.info( "auth_logout_api called for user=%r", - getattr(request.user, "username", None), + mask_identifier(getattr(request.user, "username", None)), ) """Logout a user.""" logout(request)