Fix Error Handling and Logging

.gitignore

@@ -16,7 +16,6 @@ dist/
 downloads/
 eggs/
 .eggs/
-lib/
 lib64/
 parts/
 sdist/

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,

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)

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(