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..eb70b6a 100644 --- a/apps/auth/utils.py +++ b/apps/auth/utils.py @@ -13,8 +13,9 @@ from rest_framework.response import Response from apps.web.models import Student +from lib.logging import add_sanitization_to_logger -logger = logging.getLogger(__name__) +logger = add_sanitization_to_logger(logging.getLogger(__name__)) AUTH_SETTINGS = settings.AUTH PASSWORD_LENGTH_MIN = AUTH_SETTINGS["PASSWORD_LENGTH_MIN"] @@ -41,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 @@ -75,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) @@ -141,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 @@ -189,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 df1672d..0005c04 100644 --- a/apps/auth/views.py +++ b/apps/auth/views.py @@ -20,8 +20,32 @@ from apps.auth import utils from apps.web.models import Student +from lib.logging import add_sanitization_to_logger -logger = logging.getLogger(__name__) +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 @@ -48,11 +72,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", action) 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 = ( @@ -67,7 +91,8 @@ def auth_initiate_api(request): ) if not success: logger.warning( - "verify_turnstile_token failed in auth_initiate_api:%s", + "Turnstile verification failed: action=%r, response=%r", + action, error_response.data, ) return error_response @@ -90,11 +115,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") + 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() @@ -110,15 +135,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, @@ -146,8 +171,8 @@ 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", - request.data.get("account"), + "verify_callback_api called for account=%r, action=%r", + mask_identifier(request.data.get("account")), request.data.get("action"), ) # Get required parameters from request @@ -156,11 +181,16 @@ 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)", + 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: - 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 @@ -192,7 +222,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 @@ -222,7 +252,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 @@ -250,7 +280,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: temp_token mismatch") return Response({"error": "Invalid temp_token"}, status=401) # Step 6: Validate submission timestamp after OTP extraction @@ -269,7 +299,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 @@ -288,8 +318,8 @@ def verify_callback_api(request): r.delete(rate_limit_key) logger.info( - "Successfully verified temp_token for user %s with action %s", - account, + "Successfully verified temp_token for user %r with action %r", + mask_identifier(account), action, ) @@ -300,16 +330,17 @@ 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", + 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") + 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: %s", 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) @@ -318,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 %s", 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( @@ -422,7 +453,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) @@ -464,7 +495,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) @@ -512,8 +543,8 @@ def auth_login_api(request) -> Response: @permission_classes([AllowAny]) def auth_logout_api(request) -> Response: logger.info( - "auth_logout_api called for user=%s", - getattr(request.user, "username", None), + "auth_logout_api called for user=%r", + mask_identifier(getattr(request.user, "username", None)), ) """Logout a user.""" logout(request) diff --git a/apps/web/views.py b/apps/web/views.py index 47e177e..cd1f055 100644 --- a/apps/web/views.py +++ b/apps/web/views.py @@ -27,9 +27,10 @@ ) from lib.departments import get_department_name from lib.grades import numeric_value_for_grade +from lib.logging import add_sanitization_to_logger from lib.terms import numeric_value_of_term -logger = logging.getLogger(__name__) +logger = add_sanitization_to_logger(logging.getLogger(__name__)) class CoursesPagination(pagination.PageNumberPagination): @@ -47,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") @@ -284,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) @@ -574,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( 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