diff --git a/CLAUDE.md b/CLAUDE.md index be6d1fd..6b2b500 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -54,6 +54,7 @@ PropelAuth via `common/auth.py`. Routes get the authenticated user from `@auth.r ## Deployment Deployed to Fly.io (`fly.toml`, app: `backend-ohack`, region: `sjc`). Uses gunicorn (`Procfile`). Port 6060. +⚠️ As of June 2026 prod runs ONE sync gunicorn worker (`Dockerfile` CMD `--workers 1`, default sync class) — a single slow request blocks the entire API. Fix plan (workers/threads, caching, Sentry error sweep, traffic evidence): `docs/perf-reliability-plan-2026-06.md`. ## Testing notes - Tests live in `api//tests/` or `test/` at the repo root. diff --git a/Dockerfile b/Dockerfile index 2568b09..4d85816 100644 --- a/Dockerfile +++ b/Dockerfile @@ -19,9 +19,13 @@ RUN python -m venv venv && \ EXPOSE 6060 # Bind to both IPv4 and IPv6 -ENV GUNICORN_CMD_ARGS="--bind=[::]:6060 --workers=2" +ENV GUNICORN_CMD_ARGS="--bind=[::]:6060" + +# Put venv on PATH so installed CLI tools (e.g. git-fame) are accessible +ENV PATH="/app/venv/bin:$PATH" # Copy project COPY . /app/ -# Run the application -CMD ["venv/bin/gunicorn", "api.wsgi:app", "--log-file=-", "--log-level", "debug", "--preload", "--workers", "1", "--timeout", "120"] \ No newline at end of file +# Run the application: gthread worker class allows concurrent I/O-bound requests +# without head-of-line blocking from a single sync worker. +CMD ["venv/bin/gunicorn", "api.wsgi:app", "--log-file=-", "--log-level", "info", "--preload", "--worker-class", "gthread", "--workers", "2", "--threads", "8", "--timeout", "120"] \ No newline at end of file diff --git a/Procfile b/Procfile index 7ddf198..060fe96 100644 --- a/Procfile +++ b/Procfile @@ -1,4 +1 @@ -#web: gunicorn api.wsgi:app --python api --log-file=- - -## For debug, use below -web: gunicorn api.wsgi:app --python api --log-file=- --log-level debug --preload --workers 1 --timeout 120 +web: gunicorn api.wsgi:app --log-file=- --log-level info --preload --worker-class gthread --workers 2 --threads 8 --timeout 120 diff --git a/api/judging/judging_service.py b/api/judging/judging_service.py index 2570673..c95f9c5 100644 --- a/api/judging/judging_service.py +++ b/api/judging/judging_service.py @@ -717,7 +717,7 @@ def get_judge_event_details(judge_id: str, event_id: str) -> Dict: user_id=judge_id, volunteer_type="judge", event_id=event_id ) if not volunteer: - logger.error(f"Judge not found for user_id {judge_id} and event_id {event_id}") + logger.info(f"Judge not found for user_id {judge_id} and event_id {event_id}") return {"error": "Judge not found"}, 404 logger.debug(f"Fetched judge details: {volunteer}") diff --git a/api/leaderboard/leaderboard_service.py b/api/leaderboard/leaderboard_service.py index 0904c61..59e54ea 100644 --- a/api/leaderboard/leaderboard_service.py +++ b/api/leaderboard/leaderboard_service.py @@ -1,38 +1,49 @@ import logging +import re +import threading +import time from typing import Dict, Any, List + +from cachetools import TTLCache, cached from db.db import get_db from common.utils.github import get_all_repos from common.utils.firebase import get_hackathon_by_event_id -import time +from common.utils.redis_cache import get_cached, set_cached logger = logging.getLogger("myapp") logger.setLevel(logging.DEBUG) -def get_github_organizations(event_id: str) -> Dict[str, Any]: - """ - Get GitHub organizations for an event. - - Args: - event_id: The event ID to get GitHub organizations for. - - Returns: - Dictionary containing GitHub organizations. - """ +_LEADERBOARD_CACHE_TTL = 300 # 5 minutes +_MENTOR_OPPS_CACHE = TTLCache(maxsize=50, ttl=300) +_MENTOR_OPPS_LOCK = threading.Lock() + +# Normalize season-YYYY -> YYYY_season aliases so legacy URLs don't 404. +# e.g. "summer-2025" -> "2025_summer" +_SEASON_YEAR_RE = re.compile(r"^(spring|summer|fall|winter)-(\d{4})$", re.IGNORECASE) + + +def _normalize_event_id(event_id: str) -> str: + m = _SEASON_YEAR_RE.match(event_id or "") + if m: + return f"{m.group(2)}_{m.group(1).lower()}" + return event_id + + +def get_github_organizations(event_id: str, hackathon: Dict = None) -> Dict[str, Any]: logger.debug("Getting GitHub organizations for event ID: %s", event_id) - + try: - # Get the hackathon document - hackathon = get_hackathon_by_event_id(event_id) + if hackathon is None: + hackathon = get_hackathon_by_event_id(event_id) if not hackathon: - logger.error("Hackathon not found for event ID: %s", event_id) + logger.info("Hackathon not found for event ID: %s", event_id) return {"github_organizations": []} - - # Get the github_org from the hackathon document + org_name = hackathon.get("github_org") if not org_name: logger.warning("GitHub organization not found in hackathon data for event ID: %s", event_id) return {"github_organizations": []} - + return { "github_organizations": [ { @@ -46,203 +57,140 @@ def get_github_organizations(event_id: str) -> Dict[str, Any]: return {"github_organizations": []} def get_github_repositories(org_name: str) -> Dict[str, Any]: - """ - Get GitHub repositories for an event. - - Args: - event_id: The event ID to get GitHub repositories for. - - Returns: - Dictionary containing GitHub repositories. - """ logger.debug("Getting GitHub repositories for org_name: %s", org_name) - # Use the database to get all repositories for the organization if not org_name: logger.error("Organization name is empty or None") return {"github_repositories": []} - - # Given the org_name, get the child repositories as part of the group - organization_ref = get_db().collection('github_organizations').document(org_name) + + organization_ref = get_db().collection('github_organizations').document(org_name) repos_ref = organization_ref.collection('github_repositories') logger.debug("Using organization reference: %s", organization_ref.id) try: - # Check if the organization exists if not organization_ref.get().exists: - logger.error("Organization %s not found in database", org_name) + logger.warning("Organization %s not found in database", org_name) return {"github_repositories": []} - - # Get all repositories for the organization + repos = repos_ref.stream() - + if not repos: logger.warning("No repositories found for organization %s", org_name) return {"github_repositories": []} - + github_repositories = [] for repo in repos: repo_data = repo.to_dict() - # Add document ID if not present if "__id__" not in repo_data: repo_data["__id__"] = repo.id - # Add organization name repo_data["org_name"] = org_name github_repositories.append(repo_data) - + return {"github_repositories": github_repositories} - + except Exception as e: logger.error("Error getting repositories for organization %s: %s", org_name, e) return {"github_repositories": []} - - -def get_github_contributors(event_id: str) -> Dict[str, Any]: - """ - Get GitHub contributors for repositories in an event. - - Args: - event_id: The event ID to get GitHub contributors for. - - Returns: - Dictionary containing GitHub contributors. - """ + +def get_github_contributors(event_id: str, hackathon: Dict = None) -> Dict[str, Any]: logger.debug("Getting GitHub contributors for event ID: %s", event_id) - + try: - # Get the hackathon document - hackathon = get_hackathon_by_event_id(event_id) + if hackathon is None: + hackathon = get_hackathon_by_event_id(event_id) if not hackathon: - logger.error("Hackathon not found for event ID: %s", event_id) + logger.info("Hackathon not found for event ID: %s", event_id) return {"github_contributors": []} - - # Get the github_org from the hackathon document + org_name = hackathon.get("github_org") if not org_name: logger.warning("GitHub organization not found in hackathon data for event ID: %s", event_id) return {"github_contributors": []} - + db = get_db() - - # Use a collection group query to search across all contributor subcollections + contributors_ref = db.collection_group('github_contributors').where("org_name", "==", org_name) - docs = contributors_ref.stream() contributors = [] for doc in docs: contribution = doc.to_dict() - # Add document ID contribution["id"] = doc.id - # Add organization and repository information repo_ref = doc.reference.parent.parent org_ref = repo_ref.parent.parent contribution["repo_name"] = repo_ref.id contribution["org_name"] = org_ref.id contributors.append(contribution) - + return {"github_contributors": contributors} - + except Exception as e: logger.error("Error getting contributors for event ID %s: %s", event_id, e) return {"github_contributors": []} -def get_github_achievements(event_id: str) -> List[Dict]: - """ - Get GitHub achievements from the achievements collection group. - - Args: - event_id: The event ID to get achievements for. - - Returns: - List of achievement objects. - """ +def get_github_achievements(event_id: str, hackathon: Dict = None) -> List[Dict]: logger.debug("Getting GitHub achievements for event ID: %s", event_id) - + try: - # Get the hackathon document - hackathon = get_hackathon_by_event_id(event_id) + if hackathon is None: + hackathon = get_hackathon_by_event_id(event_id) if not hackathon: - logger.error("Hackathon not found for event ID: %s", event_id) + logger.info("Hackathon not found for event ID: %s", event_id) return [] - - # Get the github_org from the hackathon document + org_name = hackathon.get("github_org") if not org_name: logger.warning("GitHub organization not found in hackathon data for event ID: %s", event_id) return [] - + db = get_db() - # Use the github_organizations collection, then get the achievements collection group organization_ref = db.collection('github_organizations').document(org_name) - if not organization_ref: - logger.error("Organization %s not found in database", org_name) + org_doc = organization_ref.get() + if not org_doc.exists: + logger.warning("Organization %s not found in database", org_name) return [] - # Get the organization name from the document - org_name = organization_ref.id - # Log the organization name being used - logger.debug("Using organization name: %s", org_name) - # Get the achievements collection group - # Check if the organization has a subcollection named 'achievements' - if not organization_ref.collection('achievements').get(): - logger.error("No achievements found for organization %s", org_name) - return [] - # Log the organization ID being used - logger.debug("Using organization ID: %s", organization_ref.id) - # Log the achievements collection being used - logger.debug("Using achievements collection for organization %s", org_name) - # Get the achievements collection group + achievements_ref = organization_ref.collection('achievements') - - - docs = achievements_ref.stream() - + docs = list(achievements_ref.stream()) + + if not docs: + logger.info("No achievements found for organization %s", org_name) + return [] + achievements = [] for doc in docs: achievement = doc.to_dict() - # Add document ID if not present if "__id__" not in achievement: achievement["__id__"] = doc.id achievements.append(achievement) - + logger.debug("Found %d achievements for organization %s", len(achievements), org_name) - - # Log the first few achievements to help with debugging - if achievements: - logger.debug("First achievement example: %s", str(achievements[0])) - else: - logger.warning("No achievements found for organization %s", org_name) - - # Sort achievements by their timestamp if available + achievements.sort(key=lambda x: x.get("timestamp", ""), reverse=True) - + return achievements - + except Exception as e: logger.error("Error getting achievements for event ID %s: %s", event_id, e, exc_info=True) return [] def calculate_general_stats(contributors: List[Dict]) -> List[Dict]: """Calculate general statistics based on contributor data.""" - # Calculate totals from real data total_commits = sum(c.get('commits', 0) for c in contributors) total_prs = sum(c.get('pull_requests', {}).get('merged', 0) for c in contributors) total_issues_closed = sum(c.get('issues', {}).get('closed', 0) for c in contributors) - - # Calculate lines of code if available + total_additions = sum(c.get('additions', 0) for c in contributors) total_deletions = sum(c.get('deletions', 0) for c in contributors) total_lines = total_additions - total_deletions if total_additions > 0 or total_deletions > 0 else 0 - - # Count unique contributors + unique_contributors = set() for c in contributors: if c.get('login'): unique_contributors.add(c.get('login')) - - # Create a list for stats with real data + stats = [ { "stat": "GitHub Commits", @@ -253,7 +201,7 @@ def calculate_general_stats(contributors: List[Dict]) -> List[Dict]: { "stat": "Pull Requests", "value": total_prs, - "icon": "merge", + "icon": "merge", "description": "Merged pull requests across all teams" }, { @@ -269,130 +217,73 @@ def calculate_general_stats(contributors: List[Dict]) -> List[Dict]: "description": "Issues closed during the hackathon" } ] - - # Add lines of code if we have that data + if total_lines > 0: stats.append({ - "stat": "Lines of Code", + "stat": "Lines of Code", "value": total_lines, "icon": "integration_instructions", "description": "Net lines of code added" }) - + return stats def categorize_individual_achievements(achievements: List[Dict]) -> List[Dict]: - """ - Categorize and format individual achievements. - - Args: - achievements: List of achievement objects - - Returns: - List of formatted individual achievements - """ logger.debug("Starting categorize_individual_achievements with %d total achievements", len(achievements)) - - # Filter for individual achievements (those with a person field) + individual_achievements = [a for a in achievements if "person" in a] logger.debug("Found %d individual achievements with 'person' field", len(individual_achievements)) - + if not individual_achievements: - logger.warning("No individual achievements found. Sample of first achievements: %s", + logger.info("No individual achievements found. Sample of first achievements: %s", str(achievements[:3]) if achievements else "[]") return [] - - # Log a sample of achievements for debugging - logger.debug("Sample of first individual achievement: %s", - str(individual_achievements[0]) if individual_achievements else "None") - - # Ensure each achievement has all required fields + for i, achievement in enumerate(individual_achievements): - # Log the achievement ID being processed logger.debug("Processing achievement %d: %s", i, achievement.get("__id__", "unknown_id")) - - # Set default values for any missing fields + if "icon" not in achievement: achievement["icon"] = "star" - logger.debug("Added default icon 'star' to achievement %s", achievement.get("__id__", "unknown_id")) - if "value" not in achievement: achievement["value"] = "-" - logger.debug("Added default value '-' to achievement %s", achievement.get("__id__", "unknown_id")) - if "description" not in achievement: achievement["description"] = achievement.get("title", "Achievement") - logger.debug("Added default description to achievement %s", achievement.get("__id__", "unknown_id")) - - # Ensure person field has all required subfields + if "person" in achievement: person = achievement["person"] - logger.debug("Person data for achievement %s: %s", - achievement.get("__id__", "unknown_id"), str(person)) - if "name" not in person: person["name"] = person.get("githubUsername", "Unknown") - logger.debug("Added default name from githubUsername: %s", person["name"]) - if "avatar" not in person: person["avatar"] = f"https://avatars.githubusercontent.com/{person.get('githubUsername', 'unknown')}" - logger.debug("Added default avatar URL for user: %s", person.get("githubUsername", "unknown")) - if "team" not in person or not person["team"]: repo_name = achievement.get("repo", "") if "--" in repo_name: person["team"] = "Team " + repo_name.split("--")[-1][:15] else: person["team"] = repo_name - logger.debug("Added derived team name: %s from repo: %s", - person["team"], achievement.get("repo", "")) - - # Sort achievements to highlight the most interesting ones first + priority_titles = ["Most Commits", "Epic PR", "First to Commit", "Night Owl"] - + try: sorted_achievements = sorted( - individual_achievements, + individual_achievements, key=lambda x: ( priority_titles.index(x.get("title", "")) if x.get("title", "") in priority_titles else 999, x.get("timestamp", "") ) ) - logger.debug("Successfully sorted %d achievements", len(sorted_achievements)) except Exception as e: logger.error("Error sorting achievements: %s", e) - logger.error("Achievement titles: %s", [a.get("title") for a in individual_achievements]) - # Fall back to unsorted if there's an error sorted_achievements = individual_achievements - - # Limit to top achievements + result = sorted_achievements[:8] logger.debug("Returning %d individual achievements", len(result)) - - # Log the titles of achievements being returned - logger.debug("Achievement titles being returned: %s", - [a.get("title") for a in result]) - return result def categorize_team_achievements(achievements: List[Dict], contributors: List[Dict]) -> List[Dict]: - """ - Generate team achievements based on available data. - - Args: - achievements: List of achievement objects - contributors: List of contributor data - - Returns: - List of team achievements - """ - # Check if there are any team achievements in the achievements list - # Exclude mentor_opportunity entries — those are handled separately team_achievements = [a for a in achievements if "team" in a and "person" not in a and a.get("type") != "mentor_opportunity"] - - # If we have team achievements, use them + if team_achievements: - # Ensure each achievement has all required fields for achievement in team_achievements: if "icon" not in achievement: achievement["icon"] = "group" @@ -400,18 +291,14 @@ def categorize_team_achievements(achievements: List[Dict], contributors: List[Di achievement["value"] = "-" if "description" not in achievement: achievement["description"] = achievement.get("title", "Team Achievement") - - # Return top team achievements (limit to 4) return team_achievements[:4] - - # Otherwise, calculate team achievements from contributor data - # Group contributors by repository + teams_data = {} for contributor in contributors: repo_name = contributor.get('repo_name') if not repo_name: continue - + if repo_name not in teams_data: teams_data[repo_name] = { 'commits': 0, @@ -419,13 +306,11 @@ def categorize_team_achievements(achievements: List[Dict], contributors: List[Di 'contributors': set(), 'team_name': repo_name.split('--')[-1] if '--' in repo_name else repo_name } - - # Add contributor metrics to team totals + teams_data[repo_name]['commits'] += contributor.get('commits', 0) teams_data[repo_name]['prs_merged'] += contributor.get('pull_requests', {}).get('merged', 0) teams_data[repo_name]['contributors'].add(contributor.get('login')) - - # Convert teams_data to a list for sorting + teams_list = [] for repo, data in teams_data.items(): teams_list.append({ @@ -435,15 +320,13 @@ def categorize_team_achievements(achievements: List[Dict], contributors: List[Di 'prs_merged': data['prs_merged'], 'contributor_count': len(data['contributors']) }) - - # Sort teams by different metrics to find the achievements + most_productive = sorted(teams_list, key=lambda x: x['commits'], reverse=True) most_collaborative = sorted(teams_list, key=lambda x: x['prs_merged'], reverse=True) largest_team = sorted(teams_list, key=lambda x: x['contributor_count'], reverse=True) - + calculated_team_achievements = [] - - # Add most productive team (most commits) + if most_productive and most_productive[0]['commits'] > 0: calculated_team_achievements.append({ "title": "Most Productive Team", @@ -454,8 +337,7 @@ def categorize_team_achievements(achievements: List[Dict], contributors: List[Di "description": "Highest number of code commits during the hackathon", "teamPage": most_productive[0]['repo_name'] }) - - # Add most collaborative team (most PRs) + if most_collaborative and most_collaborative[0]['prs_merged'] > 0: calculated_team_achievements.append({ "title": "Most Collaborative", @@ -466,8 +348,7 @@ def categorize_team_achievements(achievements: List[Dict], contributors: List[Di "description": "Highest number of pull requests merged", "teamPage": most_collaborative[0]['repo_name'] }) - - # Add largest team (most contributors) + if largest_team and largest_team[0]['contributor_count'] > 0: calculated_team_achievements.append({ "title": "Largest Team", @@ -478,22 +359,12 @@ def categorize_team_achievements(achievements: List[Dict], contributors: List[Di "description": "Team with the most contributors", "teamPage": largest_team[0]['repo_name'] }) - + return calculated_team_achievements[:4] def categorize_mentor_opportunities(achievements: List[Dict]) -> List[Dict]: - """ - Extract mentor opportunity entries (teams that could use support). - - Args: - achievements: List of achievement objects - - Returns: - List of mentor opportunity entries - """ opportunities = [a for a in achievements if a.get("type") == "mentor_opportunity"] - # Ensure each entry has required fields for opp in opportunities: if "icon" not in opp: opp["icon"] = "rocket_launch" @@ -505,16 +376,12 @@ def categorize_mentor_opportunities(achievements: List[Dict]) -> List[Dict]: return opportunities +@cached(cache=_MENTOR_OPPS_CACHE, lock=_MENTOR_OPPS_LOCK) def collect_mentor_panel_opportunities(event_id: str) -> List[Dict]: """ - Derive mentor-boost opportunities from the per-team mentor panel state: - - Any team with an open mentor flag (raised by a mentor) - - Any team that has had NO mentor touch in the last 4 hours during a - live event window (start_date <= now <= end_date + 1 day) - - These are appended to the existing GitHub-derived opportunities so the - "Teams Ready for a Boost" widget on /hack/#stats covers both - coding-activity AND mentor-coverage gaps. + Derive mentor-boost opportunities from the per-team mentor panel state. + Cached 5 min; short-circuits before any Firestore reads when the event + is not in its live window (start_date <= now <= end_date + 1 day). """ from datetime import datetime, timedelta from common.utils.firebase import get_hackathon_by_event_id @@ -538,10 +405,16 @@ def collect_mentor_panel_opportunities(event_id: str) -> List[Dict]: end_date = datetime.fromisoformat(hackathon["end_date"].replace("Z", "")) except Exception: pass + is_live = bool( start_date and end_date and start_date <= now <= (end_date + timedelta(days=1)) ) + # Short-circuit before any Firestore reads when outside the live window. + if not is_live: + logger.debug("collect_mentor_panel_opportunities: event %s is not live — returning []", event_id) + return opportunities + try: db = get_db() team_docs = db.collection("teams").where("hackathon_event_id", "==", event_id).stream() @@ -557,7 +430,6 @@ def collect_mentor_panel_opportunities(event_id: str) -> List[Dict]: team_name = t.get("name") or "Unnamed team" team_id = snap.id - # Open flag → one opportunity per flag (cap at 2 per team to limit noise) flags = t.get("mentor_flags") or [] open_flags = [f for f in flags if not f.get("resolved_at")][:2] for f in open_flags: @@ -574,75 +446,51 @@ def collect_mentor_panel_opportunities(event_id: str) -> List[Dict]: "members": len(t.get("users") or []), }) - # No mentor touch in 4h during a live event - if is_live: - last_touched_iso = t.get("mentor_last_touched_at") - touched_recently = False - if last_touched_iso: - try: - last_touched = datetime.fromisoformat(last_touched_iso.replace("Z", "")) - if last_touched >= stale_threshold: - touched_recently = True - except Exception: - pass - if not touched_recently: - opportunities.append({ - "type": "mentor_opportunity", - "team": team_name, - "teamPage": f"https://www.ohack.dev/hack/{event_id}/team/{team_id}", - "icon": "schedule", - "value": "No mentor touch in 4h", - "description": ( - "No mentor has checked on this team in the last 4 hours — drop by!" - ), - "members": len(t.get("users") or []), - }) + last_touched_iso = t.get("mentor_last_touched_at") + touched_recently = False + if last_touched_iso: + try: + last_touched = datetime.fromisoformat(last_touched_iso.replace("Z", "")) + if last_touched >= stale_threshold: + touched_recently = True + except Exception: + pass + if not touched_recently: + opportunities.append({ + "type": "mentor_opportunity", + "team": team_name, + "teamPage": f"https://www.ohack.dev/hack/{event_id}/team/{team_id}", + "icon": "schedule", + "value": "No mentor touch in 4h", + "description": "No mentor has checked on this team in the last 4 hours — drop by!", + "members": len(t.get("users") or []), + }) except Exception as e: logger.warning("collect_mentor_panel_opportunities: skipped a team: %s", e) continue return opportunities -def get_leaderboard_analytics(event_id: str, contributors: List[Dict], achievements: List[Dict]) -> Dict[str, Any]: - """ - Generate leaderboard analytics including statistics and achievements. - - Args: - event_id: The event ID - contributors: List of contributor data - achievements: List of achievement data - - Returns: - Dictionary containing leaderboard analytics - """ - # Default values in case we can't find the data +def get_leaderboard_analytics(event_id: str, contributors: List[Dict], achievements: List[Dict], hackathon: Dict = None) -> Dict[str, Any]: event_name = None github_org = None - + try: - # Get the hackathon document - hackathon = get_hackathon_by_event_id(event_id) + if hackathon is None: + hackathon = get_hackathon_by_event_id(event_id) if hackathon: - # Get the event name from the hackathon title if "title" in hackathon: event_name = hackathon["title"] - - # Get the github_org from the hackathon document if "github_org" in hackathon: github_org = hackathon["github_org"] except Exception as e: logger.error("Error getting hackathon data for event ID %s: %s", event_id, e) - - # Calculate general stats from contributor data + general_stats = calculate_general_stats(contributors) - - # Process achievements individual_achievements = categorize_individual_achievements(achievements) team_achievements = categorize_team_achievements(achievements, contributors) mentor_opportunities = categorize_mentor_opportunities(achievements) - # Append mentor-panel-derived opportunities (open flags + stale touch). - # Best-effort: any failure here must not break the broader leaderboard. try: mentor_opportunities = mentor_opportunities + collect_mentor_panel_opportunities(event_id) except Exception as e: @@ -659,26 +507,31 @@ def get_leaderboard_analytics(event_id: str, contributors: List[Dict], achieveme def get_github_leaderboard(event_id: str) -> Dict[str, Any]: """ - Get GitHub leaderboard data for an event. - - Args: - event_id: The event ID to get leaderboard data for. - - Returns: - Dictionary containing all GitHub leaderboard data. + Get GitHub leaderboard data for an event. Cached 5 minutes in Redis. """ + # Normalize season-YYYY -> YYYY_season (e.g. "summer-2025" -> "2025_summer") + normalized_id = _normalize_event_id(event_id) + if normalized_id != event_id: + logger.info("get_github_leaderboard: normalized event_id %s -> %s", event_id, normalized_id) + event_id = normalized_id + + cache_key = f"leaderboard:{event_id}" + cached_result = get_cached(cache_key) + if cached_result is not None: + logger.debug("get_github_leaderboard: cache hit for %s", event_id) + return cached_result + start_time = time.time() logger.debug("Getting GitHub leaderboard for event ID: %s", event_id) - - # Get organization and repository data - org_start = time.time() - org_name = get_github_organizations(event_id) - org_duration = time.time() - org_start - logger.debug("get_github_organizations took %.2f seconds", org_duration) - - if org_name["github_organizations"] == []: - logger.warning("No GitHub organizations found for event ID: %s", event_id) - return { + + # Fetch hackathon ONCE and pass down to all helpers. + hackathon = get_hackathon_by_event_id(event_id) + + org_data = get_github_organizations(event_id, hackathon=hackathon) + + if not org_data["github_organizations"]: + logger.info("No GitHub organizations found for event ID: %s", event_id) + result = { "github_organizations": [], "github_repositories": [], "github_contributors": [], @@ -688,46 +541,24 @@ def get_github_leaderboard(event_id: str) -> Dict[str, Any]: "teamAchievements": [], "mentorOpportunities": [] } - - repos_start = time.time() - repos = get_github_repositories(org_name["github_organizations"][0]["name"]) - repos_duration = time.time() - repos_start - logger.debug("get_github_repositories took %.2f seconds", repos_duration) - - # Get contributor data - contributors_start = time.time() - contributors_response = get_github_contributors(event_id) + set_cached(cache_key, result, ttl=_LEADERBOARD_CACHE_TTL) + return result + + repos = get_github_repositories(org_data["github_organizations"][0]["name"]) + contributors_response = get_github_contributors(event_id, hackathon=hackathon) contributors = contributors_response.get("github_contributors", []) - contributors_duration = time.time() - contributors_start - logger.debug("get_github_contributors took %.2f seconds and found %d contributors", - contributors_duration, len(contributors)) - - # Get achievement data from the new achievements collection - achievements_start = time.time() - achievements = get_github_achievements(event_id) - achievements_duration = time.time() - achievements_start - logger.debug("get_github_achievements took %.2f seconds and found %d achievements", - achievements_duration, len(achievements)) - - # Calculate analytics for the leaderboard - analytics_start = time.time() - analytics = get_leaderboard_analytics(event_id, contributors, achievements) - analytics_duration = time.time() - analytics_start - logger.debug("get_leaderboard_analytics took %.2f seconds", analytics_duration) - - # Log the count of achievements in the final result for debugging - individual_count = len(analytics.get("individualAchievements", [])) - team_count = len(analytics.get("teamAchievements", [])) - logger.debug("Final counts - Individual achievements: %d, Team achievements: %d", - individual_count, team_count) - + achievements = get_github_achievements(event_id, hackathon=hackathon) + analytics = get_leaderboard_analytics(event_id, contributors, achievements, hackathon=hackathon) + total_duration = time.time() - start_time logger.debug("Total get_github_leaderboard execution took %.2f seconds", total_duration) - - return { - "github_organizations": org_name["github_organizations"], + + result = { + "github_organizations": org_data["github_organizations"], "github_repositories": repos["github_repositories"], "github_contributors": contributors, - "github_achievements": achievements, # Include the full achievements list + "github_achievements": achievements, **analytics } + set_cached(cache_key, result, ttl=_LEADERBOARD_CACHE_TTL) + return result diff --git a/api/messages/messages_service.py b/api/messages/messages_service.py index 98e9eb4..c11ea09 100644 --- a/api/messages/messages_service.py +++ b/api/messages/messages_service.py @@ -13,6 +13,7 @@ from common.log import get_logger, debug, error import firebase_admin +import threading from firebase_admin import credentials, firestore from cachetools import cached, TTLCache @@ -81,6 +82,9 @@ def clear_cache(): def save_helping_status_old(propel_user_id, json): logger.info(f"save_helping_status {propel_user_id} // {json}") slack_user = get_slack_user_from_propel_user_id(propel_user_id) + if slack_user is None: + logger.warning(f"Could not resolve Slack user for propel_user_id={propel_user_id}") + return None user_id = slack_user["sub"] helping_status = json["status"] # helping or not_helping @@ -248,7 +252,7 @@ def get_problem_statement_from_id_old(problem_id): doc = db.collection('problem_statements').document(problem_id) return doc -@cached(cache=TTLCache(maxsize=100, ttl=600)) +@cached(cache=TTLCache(maxsize=100, ttl=600), lock=threading.Lock()) def get_single_problem_statement_old(project_id): logger.debug(f"get_single_problem_statement start project_id={project_id}") db = get_db() @@ -257,10 +261,13 @@ def get_single_problem_statement_old(project_id): if doc is None: logger.warning("get_single_problem_statement end (no results)") return {} - else: + else: result = doc_to_json(docid=doc.id, doc=doc) + if result is None: + logger.warning(f"get_single_problem_statement doc_to_json returned None for project_id={project_id}") + return {} result["id"] = doc.id - + logger.info(f"get_single_problem_statement end (with result):{result}") return result return {} @@ -281,7 +288,7 @@ def get_problem_statement_list_old(): logger.debug(results) return { "problem_statements": results } -@cached(cache=TTLCache(maxsize=100, ttl=10)) +@cached(cache=TTLCache(maxsize=100, ttl=10), lock=threading.Lock()) @limits(calls=100, period=ONE_MINUTE) def get_github_profile(github_username): logger.debug(f"Getting Github Profile for {github_username}") @@ -294,7 +301,7 @@ def get_github_profile(github_username): # -------------------- User functions to be deleted ---------------------------------------- # # 10 minute cache for 100 objects LRU -@cached(cache=TTLCache(maxsize=100, ttl=600)) +@cached(cache=TTLCache(maxsize=100, ttl=600), lock=threading.Lock()) @limits(calls=100, period=ONE_MINUTE) def get_profile_metadata_old(propel_id): logger.debug("Profile Metadata") @@ -393,7 +400,7 @@ def _lean_admin_profile(doc): # 5-minute TTL is enough to absorb tab refreshes / multiple admins loading the # page in close succession while still picking up new signups within minutes. -@cached(cache=TTLCache(maxsize=1, ttl=300), key=lambda: "all") +@cached(cache=TTLCache(maxsize=1, ttl=300), lock=threading.Lock(), key=lambda: "all") def get_all_profiles(): db = get_db() docs = db.collection('users').stream() @@ -591,7 +598,7 @@ def save_profile_metadata_old(propel_id, json): "Saved Profile Metadata" ) -@cached(cache=TTLCache(maxsize=100, ttl=600), key=lambda id: id) +@cached(cache=TTLCache(maxsize=100, ttl=600), lock=threading.Lock(), key=lambda id: id) def get_user_by_id_old(id): logger.debug(f"Attempting to get user by ID: {id}") db = get_db() @@ -618,7 +625,7 @@ def get_user_by_id_old(id): return res except NotFound: - logger.error(f"Document with ID {id} not found in 'users' collection") + logger.info(f"Document with ID {id} not found in 'users' collection") return {} except Exception as e: logger.error(f"Error retrieving user data for ID {id}: {str(e)}") diff --git a/api/messages/messages_views.py b/api/messages/messages_views.py index eb23cdc..94d284b 100644 --- a/api/messages/messages_views.py +++ b/api/messages/messages_views.py @@ -721,7 +721,10 @@ def all_profiles(): def submit_feedback(): logger.info("POST /feedback called") if auth_user and auth_user.user_id: - return vars(save_feedback(auth_user.user_id, request.get_json())) + result = save_feedback(auth_user.user_id, request.get_json()) + if result is None: + return {"error": "User not found"}, 404 + return vars(result) else: return {"error": "Unauthorized"}, 401 diff --git a/api/users/users_views.py b/api/users/users_views.py index fd090c9..8aa70f1 100644 --- a/api/users/users_views.py +++ b/api/users/users_views.py @@ -58,30 +58,35 @@ def get_profile_by_db_id(id): @bp.route("/volunteering", methods=["POST"]) @auth.require_user -def save_volunteering_time(): - if auth_user and auth_user.user_id: +def save_volunteering_time(): + if auth_user and auth_user.user_id: u: User | None = users_service.save_volunteering_time(auth_user.user_id, request.get_json()) - return vars(u) if u is not None else None + if u is None: + return {"error": "User not found or unable to save volunteering time"}, 404 + return vars(u) else: - return None - + return {"error": "Unauthorized"}, 401 + @bp.route("/volunteering", methods=["GET"]) @auth.require_user -def get_volunteering_time(): +def get_volunteering_time(): # Get url params start_date = request.args.get('startDate') end_date = request.args.get('endDate') - + if auth_user and auth_user.user_id: - allVolunteering, totalActiveHours, totalCommitmentHours = users_service.get_volunteering_time(auth_user.user_id, start_date, end_date) + result = users_service.get_volunteering_time(auth_user.user_id, start_date, end_date) + if result is None: + return {"error": "User not found"}, 404 + allVolunteering, totalActiveHours, totalCommitmentHours = result return { "totalActiveHours": totalActiveHours, "totalCommitmentHours": totalCommitmentHours, - "allVolunteering": allVolunteering + "allVolunteering": allVolunteering } else: - return None + return {"error": "Unauthorized"}, 401 @bp.route("/admin/volunteering", methods=["GET"]) diff --git a/common/utils/firestore_helpers.py b/common/utils/firestore_helpers.py index 2a1b334..c756f1f 100644 --- a/common/utils/firestore_helpers.py +++ b/common/utils/firestore_helpers.py @@ -1,3 +1,4 @@ +import threading import time from functools import wraps @@ -57,7 +58,7 @@ def wrapper(*args, **kwargs): return wrapper -@cached(cache=TTLCache(maxsize=2000, ttl=3600), key=hash_key) +@cached(cache=TTLCache(maxsize=2000, ttl=3600), lock=threading.Lock(), key=hash_key) def doc_to_json(docid=None, doc=None, depth=0): if not docid: logger.debug("docid is NoneType") diff --git a/common/utils/slack.py b/common/utils/slack.py index dfb1486..0d07c4b 100644 --- a/common/utils/slack.py +++ b/common/utils/slack.py @@ -127,23 +127,41 @@ def get_client(): client = WebClient(token=token) return client +_EMAIL_USER_CACHE = TTLCache(maxsize=500, ttl=86400) # 24h — email→user rarely changes +_EMAIL_USER_MISS_CACHE = TTLCache(maxsize=500, ttl=3600) # 1h negative cache +_EMAIL_USER_LOCK = threading.Lock() + + +@sleep_and_retry +@limits(calls=20, period=60) def get_slack_user_by_email(email): """ - Get Slack user by email address. - - :param email: Email address of the user - :return: User information if found, None otherwise + Get Slack user by email address. Cached 24h (hits) / 1h (misses). + users.lookupByEmail is tightly rate-limited — cache aggressively. """ + if not email: + return None + with _EMAIL_USER_LOCK: + if email in _EMAIL_USER_MISS_CACHE: + return None + if email in _EMAIL_USER_CACHE: + return _EMAIL_USER_CACHE[email] + client = get_client() try: result = client.users_lookupByEmail(email=email) - return result["user"] + user = result["user"] + with _EMAIL_USER_LOCK: + _EMAIL_USER_CACHE[email] = user + return user except SlackApiError as e: - logger.error(f"Error fetching user by email {email}: {e}") + logger.warning(f"Could not look up Slack user by email {email}: {e}") + with _EMAIL_USER_LOCK: + _EMAIL_USER_MISS_CACHE[email] = True return None -@cached(cache=TTLCache(maxsize=100, ttl=60)) # Cache for 1 minute +@cached(cache=TTLCache(maxsize=100, ttl=60), lock=threading.Lock()) # Cache for 1 minute @sleep_and_retry @limits(calls=20, period=60) # Rate limiting def get_channel_id_from_channel_name(channel_name): @@ -188,7 +206,7 @@ def get_channel_id_from_channel_name(channel_name): return None -@cached(cache=TTLCache(maxsize=50, ttl=60)) # Cache for 1 minute +@cached(cache=TTLCache(maxsize=50, ttl=60), lock=threading.Lock()) # Cache for 1 minute def is_channel_id(channel_id): # Use conversation_info to check if channel_id is valid client = get_client() @@ -196,8 +214,8 @@ def is_channel_id(channel_id): result = client.conversations_info(channel=channel_id) return True except SlackApiError as e: - logger.error(f"Error checking channel ID {channel_id}: {e}") - return False + logger.debug(f"is_channel_id: conversations.info failed for {channel_id}: {e}") + return False def add_bot_to_channel(channel_id): @@ -336,8 +354,7 @@ def send_slack(message="", channel="", icon_emoji=None, username="Hackathon Bot" response = client.chat_postMessage(**kwargs) except SlackApiError as e: - logger.error(e.response["error"]) - assert e.response["error"] + logger.warning(f"send_slack failed for channel={channel_id}: {e.response.get('error', e)}") def async_send_slack(message="", channel="", icon_emoji=None, username="Hackathon Bot", blocks=None): diff --git a/docs/perf-reliability-plan-2026-06.md b/docs/perf-reliability-plan-2026-06.md new file mode 100644 index 0000000..66a1633 --- /dev/null +++ b/docs/perf-reliability-plan-2026-06.md @@ -0,0 +1,225 @@ +# Backend Performance & Reliability Plan — June 2026 + +**Executor:** Sonnet 4.6 (Claude Code). Work through phases in order. Each task lists files, the change, and acceptance criteria. +**Repos:** `backend-ohack.dev` (primary) and `frontend-ohack.dev` (Phase 5 tracking fixes). + +## Execution guardrails + +- Line numbers below were verified June 2026 but may drift — always `grep` for the quoted code before editing. +- **`api/messages/messages_views.py` and `api/messages/messages_service.py` are frozen for NEW code** (backend CLAUDE.md). In-place bug fixes to existing functions are allowed; anything new goes in a per-domain blueprint/service. If a fix grows beyond a guard clause, migrate the function out instead. +- Logging: use the structured helpers in `common/log.py` (`error()`, `warning()`, `info()`). The Sentry-spam fixes below are mostly "downgrade expected conditions from error → warning/info". +- Tests: `pytest` from repo root (conda env `py39_ohack_backend`). Heavy external deps are pre-mocked in `sys.modules` — follow existing test patterns. +- Caching: `common/utils/redis_cache.py` (Redis with TTLCache fallback, `@cached_with_key()`) already exists and is used by `api/slack/slack_service.py` and `services/volunteers_service.py`. Prefer it for expensive/shared results. Plain `cachetools.TTLCache` is fine for per-process short-TTL caches, but see P0-1 thread-safety note. +- Do not cache OAuth **tokens** in Redis. PropelAuth responses containing access tokens stay in in-process memory only (short TTL). + +## Evidence (what drove these priorities) + +**Sentry span export, prod, 2026-05-29 → 2026-06-12 (n=12,835):** + +| transaction | calls | p50 | p95 | total time | +|---|---|---|---|---| +| `get_hackathon_funnel_aggregate_api` | 119 | **7.7s** | 12.4s | 661s | +| `get_single_hackathon_by_event` | 871 | 2.6ms | **4.6s** | 531s | +| `api-messages.profile` | 960 | 3.1ms | **2.1s** | 416s | +| `api-leaderboard.get_leaderboard_by_event_id` | 548 | **727ms** | 1.5s | 339s | +| `get_npos_by_hackathon_id_api` | 558 | 171ms | 529ms | 119s | +| `save_profile` | 145 | 781ms | 1.0s | 113s | +| volunteer-by-event ×4 (mentor/hacker/judge/volunteer) | ~2,848 | 63–109ms | ~300ms | 271s | +| `planning.get_board` | 26 | 2.4s | 2.9s | 59s | +| `volunteers.admin_list_resend_emails` | 4 | **~20s** | 20s | 40s | +| `get_praises` | 45 | 1.9ms | 3.6s | 44s | +| `get_privacy_settings` | 113 | 328ms | 607ms | 40s | +| `get_my_volunteer_status_for_event` | 39 | 611ms | 1.4s | 24s | +| `get_judge_application` / `get_hacker_application` | 89 / 73 | ~500ms | ~900ms | 77s | +| `get_single_problem` / `list_hackathons` | 1,333 / 1,256 | ~2ms | — | healthy | + +**GA (Mar 13 – Jun 10):** top public pages are `/hack` (4.6k views — calls the 7.7s funnel aggregate via `HackathonStoryStrip`), home (3.4k), onboarding (3.4k), event pages, `/profile` (1.3k). Two tracking anomalies: `(not set)` page title is the #2 row (9,675 views / 4,092 users), and "Team Management - Opportunity Hack Admin" logged **22,647 views from 3 users** (shallow-route page_view spam — Phase 5). + +**Top Sentry error issues:** PropelAuth OAuth lookup failures (734), leaderboard "org/achievements not found" (275+275), `get_giveaway` TypeError (133), leaderboard "Hackathon not found: summer-2025" (57), plus ~10 smaller unhandled TypeErrors detailed below. + +--- + +## Phase 0 — Deployment & concurrency (highest leverage, smallest diff) + +### P0-1: Fix gunicorn — prod serves ONE request at a time + +`Dockerfile` CMD is: + +``` +CMD ["venv/bin/gunicorn", "api.wsgi:app", "--log-file=-", "--log-level", "debug", "--preload", "--workers", "1", "--timeout", "120"] +``` + +One **sync** worker on a 1-CPU/1GB Fly VM = a single 7.7s funnel-aggregate request (or a 20s resend-emails request) head-of-line-blocks every other user. This explains the huge p95s on otherwise-cached endpoints (e.g. `get_single_hackathon_by_event` p50 2.6ms / p95 4.6s). The workload is almost entirely I/O-bound (Firestore, PropelAuth, Slack, GitHub). + +**Change (Dockerfile + Procfile, keep both in sync):** + +``` +--worker-class gthread --workers 2 --threads 8 --timeout 120 --log-level info +``` + +- Keep `--preload`. Remove `debug` log level in prod (it's noisy and slow). +- Also fix the latent `git-fame` PATH bug while in the Dockerfile (see P2-6): add `ENV PATH="/app/venv/bin:$PATH"`. +- **Thread-safety follow-up (required):** with `gthread`, the module-level `cachetools.TTLCache`s are hit concurrently. `@cached(...)` without a lock can corrupt the underlying dict under threads. Sweep all `@cached(cache=TTLCache(...))` usages (`grep -rn "TTLCache" services/ api/ common/`) and add `lock=threading.Lock()` to each `@cached` decorator (cachetools supports `@cached(cache=..., lock=...)`). This is mechanical; do it in the same PR. +- Memory check: 2 preloaded workers of this app fit in 1GB; if Fly OOMs, drop to `--workers 1 --threads 16` (still fixes head-of-line blocking). + +**Acceptance:** deploy boots; `fly logs` shows gthread workers; p95 of `get_single_hackathon_by_event` drops to <500ms within a day. + +### P0-2: Crash-bug sweep — unhandled TypeErrors returning 500s + +Most share one root cause: `get_slack_user_from_propel_user_id()` / `get_oauth_user_from_propel_user_id()` (in `services/users_service.py`) can return `None`, and callers immediately subscript it. + +1. **Add a shared resolver helper** (new code → put in `services/users_service.py` or a small new module, NOT messages_service): + ```python + def resolve_db_user_or_none(propel_user_id): + """propel UUID → (slack_user_dict, db_user) or (None, None); never raises.""" + ``` + Then guard each caller and return a proper 4xx JSON response instead of crashing: + - `services/feedback_service.py` ~line 32 — `slack_user["sub"]` after `get_slack_user_from_propel_user_id` (Sentry: `get_feedback` TypeError, 3 events). + - `services/giveaway_service.py` ~lines 20–21, 46–47 — same pattern (Sentry: `get_giveaway` TypeError, **133 events**). Also `get_all_giveaways` ~line 70: `get_user_by_id_old` result can be None before `giveaway["user"] = user` consumers subscript it. + - `api/messages/messages_service.py` ~lines 83–84 (`register_helping_status`) — same pattern (11 events). In-place guard only (frozen file). +2. **`api/users/users_views.py` `save_volunteering_time`** (~lines 59–67): returns `None` → Flask "did not return a valid response" (21 events). Return `({"error": "..."}, 400/404)` on every path. Also fix the three implicit `return` (None) paths in `services/users_service.py::save_volunteering_time` (~391, 400, 418) to return explicit errors the view can map. +3. **`get_volunteering_time`** — view at `api/users/users_views.py` ~line 77 unpacks a 3-tuple; service (~line 437/446) returns `None` on missing oauth user / missing db user. Make the service raise a typed error or return `(None, None, None)` and have the view return 404 (6 events). +4. **`services/users_service.py::get_profile_metadata`** ~line 317: `save_user(...)` returns `None` when PropelAuth gave empty values → `db_id.id` AttributeError (10 events, plus 10 paired "Empty values provided for user save"). Guard `db_id is None` → return 4xx; downgrade the "Empty values" log to warning. +5. **`api/messages/messages_service.py::get_single_problem_statement*`** ~line 261: `doc_to_json` can return None → `result["id"] = doc.id` TypeError (2 events). Guard, return `{}`/404. +6. **`services/hackathons_service.py::update_*_by_event_id`** (~line 717): Sentry KeyError `"'slack_user_id' is not contained in the data"`. Firestore `DocumentSnapshot.get(field)` **raises KeyError** when the field is absent — use `doc.to_dict().get('slack_user_id')` instead, and if it's falsy, skip all Slack messaging for that volunteer (log warning) but still complete the update and return the success Message (6 events across mentor/hacker variants). + +**Acceptance:** each listed Sentry issue's code path has an explicit guard + non-500 response; add/extend unit tests for the None paths where a test scaffold already exists. + +--- + +## Phase 1 — Hot-path performance + +### P1-1: `get_hackathon_funnel_aggregate` — 7.7s p50, fired by `/hack` (top page) + +`services/hackathons_service.py` ~339–502, route in messages_views (`/api/messages/hackathons/funnel/aggregate`). + +Problems: streams **every** hackathon doc, reads each one's `funnel/summary` subdoc sequentially, and runs a **per-hackathon** `volunteers.where(event_id==X).where(volunteer_type=="hacker")` query. `@cached(TTLCache(maxsize=1, ttl=600))` means a full 7.7–14s recompute every 10 minutes — and on the current single sync worker, every recompute blocks the whole site. + +**Changes:** +1. Replace the per-hackathon volunteers query with **one** query: `db.collection("volunteers").where("volunteer_type", "==", "hacker").stream()` selecting only `event_id` (use `.select(["event_id"])`), then `Counter` by event_id in memory. (If volunteer count is huge, use Firestore **count aggregation queries** per event in parallel instead — but single-scan-and-count is simpler and fine at OHack scale.) +2. Batch the funnel `summary` subdoc reads: build all `DocumentReference`s first, then one `db.get_all(refs)`. +3. Cache the final aggregate in **Redis** via the existing `cached_with_key()` helper, TTL **6 hours** (the data is historical; it only moves during an event). Keep the in-process TTLCache as fallback. On cache-compute, log duration. +4. Frontend already tolerates slow/skeleton states (`HackathonStoryStrip` reserves height) — no frontend change needed. + +**Acceptance:** endpoint p50 < 300ms warm, recompute < 2s; `/hack` no longer shows multi-second funnel skeletons. + +### P1-2: Leaderboard — 548 calls × 727ms + 607 error events / 2 weeks + +`api/leaderboard/leaderboard_service.py` (+ `leaderboard_views.py`). + +1. **Hackathon fetched 5× per request** (`get_hackathon_by_event_id` at ~25, ~115, ~164, ~624, and ~526 inside `collect_mentor_panel_opportunities`). Fetch once in `get_github_leaderboard(event_id)`, pass the doc down as a parameter. +2. **Cache the whole response**: `@cached_with_key("leaderboard", ttl=300)` on `get_github_leaderboard`. GitHub-derived stats don't change minute-to-minute. +3. **Fix broken existence checks:** ~line 180 `if not organization_ref:` (a DocumentReference is always truthy) and ~line 189 `if not organization_ref.collection('achievements').get()` (dead check). Use `.get().exists` / stream-and-check. +4. **Log-level hygiene:** "Hackathon not found for event ID" (~27, ~117, ~167), "Organization … not found in database" (~73, ~181), "No achievements found" (~190) are expected conditions handled gracefully — downgrade `error` → `info`/`warning`. This kills 607 Sentry events/2wk. +5. **`collect_mentor_panel_opportunities`** (~508–604) runs a full teams scan on every leaderboard request. Cache it for 5 min, and short-circuit (return `[]`) when `now` is outside the event live window (`start_date <= now <= end_date + 1d`) **before** any Firestore reads. +6. **Data fixes (one-time, do with Greg's confirmation):** + - Some hackathon doc has `github_org: "safespace-app-for-teens"` but no matching doc in `github_organizations` (275+275 errors). Either create the org doc, clear the field, or fix the slug. + - Something requests event id `summer-2025` (57 errors) which doesn't exist (canonical is likely `2025_summer`). Grep the frontend for the caller of `/api/leaderboard/summer-2025`; apply the same `season-YYYY → YYYY_season` alias normalization the frontend uses for event pages, or normalize the alias server-side in `get_hackathon_by_event_id`. + +**Acceptance:** leaderboard p50 < 100ms warm; the three Sentry issues stop accruing. + +### P1-3: Cache PropelAuth OAuth lookups (affects ~6 endpoints + login) + +`services/users_service.py::get_oauth_user_from_propel_user_id` (~172–222) makes a blocking HTTP call to PropelAuth on **every** call, sometimes followed by a second HTTP call to Slack/Google token endpoints. Callers: profile save/load, volunteering time, privacy settings, mentor/judge status (`_resolve_caller` in `api/mentors/mentors_service.py`), application gets. This is why `get_privacy_settings` is 328ms p50, `get_my_volunteer_status_for_event` 611ms, judge/hacker application gets ~500ms, and `api-messages.profile` p95 2.1s. + +**Changes:** +1. Add `@cached(cache=TTLCache(maxsize=512, ttl=600), lock=threading.Lock())` to `get_oauth_user_from_propel_user_id` (in-process ONLY — the payload contains access tokens; do not put it in Redis). +2. **Negative caching:** when PropelAuth returns 404 for a propel_id, cache the `None` result too (a smaller TTLCache, ttl=300) so a deleted/broken user with an active session (the source of the **734** "Could not get OAuth user from PropelAuth" errors — note Sentry shows one propel_id `ef56954d-…` dominating) doesn't hammer PropelAuth on every request. Have `get_privacy_settings` return 404 (not None→500-ish) so the frontend stops retrying. +3. Downgrade the "Could not get OAuth user" logs at the 5 call sites (~337, 380, 436, 542, 561) from `error` → `warning` — it's an expected client-state condition now handled with a 404. + +**Acceptance:** `get_privacy_settings` p50 < 50ms warm; `get_my_volunteer_status_for_event` p50 < 200ms; PropelAuth error volume drops to near zero. + +### P1-4: `api-messages.profile` (login path, 960 calls, p95 2.1s) + +`api/messages/messages_service.py::get_profile_metadata_old` (~299–335). It does PropelAuth HTTP → `save_user_old` Firestore write → history read, per login. P1-3's cache removes the PropelAuth call. Additionally (in-place edits only — frozen file): +- Skip the `save_user_old` write when nothing changed except `last_login`, unless last_login is > 1 hour stale (read-compare-write you're already doing the read for). This halves write load on the hottest auth path. + +**Acceptance:** profile p95 < 800ms. + +--- + +## Phase 2 — Secondary wins & hygiene + +### P2-1: `get_npos_by_hackathon_id` N+1 (558 calls, 171ms p50) +`services/nonprofits_service.py` ~154–162: per-ref `.get()` loop → replace with one `db.get_all(npo_refs)`. Keep `doc_to_json` conversion. **Acceptance:** p50 < 80ms. + +### P2-2: Slack utils hardening (`common/utils/slack.py`) +1. `get_slack_user_by_email` (~130–143): add the same decorator stack its sibling has (`@cached(TTLCache(maxsize=500, ttl=86400), lock=...)`, `@sleep_and_retry`, `@limits(calls=20, period=60)`); `users.lookupByEmail` is tightly rate-limited (Sentry: 28 failures). Cache None results too (ttl ~3600) so unknown emails don't refetch. Downgrade the failure log to warning — application submission already proceeds without slack_user_id. +2. `send_slack` (~307–340): replace `assert e.response["error"]` in the except branch with a `warning()` log; never let a Slack failure raise out of business logic. Audit callers in `register_helping_status` (messages_service ~160–182): wrap channel sends in try/except so `is_archived` / `channel_not_found` (Sentry, 7 events) don't fail the user's request — log warning and continue. +3. `is_channel_id` (~192–200): downgrade the `conversations.info` failure log to `debug` — falling back to name lookup is the designed path (Sentry: "Error checking channel ID 2026_summer_wial"). +4. **invalid_blocks** (Sentry, `update_mentor_application`): in `services/volunteers_service.py::send_slack_volunteer_notification` (~381–507), Slack caps a section `text` object at **3000 chars**. Truncate each detail line (esp. `availableDays`, free-text fields) to ~500 chars and the joined section to 2900 with an ellipsis; if over, split into multiple section blocks (max 50 blocks). + +### P2-3: `planning.get_board` (2.4s p50, low volume) +`api/planning/planning_views.py` ~151–200: three sequential subcollection streams + profile resolution. Low call count — keep it cheap: run the three streams concurrently via `concurrent.futures.ThreadPoolExecutor` (safe under gthread), and confirm `_resolve_public_user_profiles` batches user reads with `db.get_all` (fix if it loops `.get()`). **Acceptance:** p50 < 1.2s. + +### P2-4: `admin_list_resend_emails` ~20s spans +`services/volunteers_service.py` ~2890–2976. Design intent is background refresh + immediate cached return, but 20s server spans show the fetch sometimes runs inline (cold Redis / lock miss). Verify the cold path returns `{emails: [], syncing: true}` immediately and **always** delegates the 30-page Resend crawl to the background thread; add a module-level "refresh in flight" guard so concurrent admins can't trigger parallel crawls. **Acceptance:** no request span > 2s on this endpoint. + +### P2-5: `get_praises` p95 3.6s +Same per-process cold-cache pattern (`services/news_service.py` area, `@cached` ttl 600). After P0-1 the blocking-induced tail should mostly disappear; if a cold compute is still >2s, batch its Firestore reads the same way as P2-1. Verify, don't over-engineer. + +### P2-6: Fix `git-fame` FileNotFoundError (certificates) +`api/certificates/scan_repo.py` ~118 runs `subprocess.run(["git-fame", ...])`. `git-fame==2.0.1` IS in requirements.txt and pip-installs its CLI into `/app/venv/bin/`, but the Dockerfile never puts the venv on PATH (CMD calls `venv/bin/gunicorn` by explicit path). Add `ENV PATH="/app/venv/bin:$PATH"` to the Dockerfile (done in P0-1) **or** invoke as `[sys.executable, "-m", "gitfame", ...]`. Prefer the PATH fix + a startup log if `shutil.which("git-fame")` is None. + +### P2-7: Sentry log-level sweep +After the targeted fixes above, do one pass: `grep -rn "error(logger" services/ api/ common/ | grep -iv except` and downgrade any "expected absence" conditions (not-found lookups that return gracefully) to warning/info. Goal: Sentry error feed = actionable issues only. + +--- + +## Phase 3 — Frontend ↔ backend traffic shape (optional, propose-only) + +The event page (`/hack/[event_id]`) fans out to ~8 backend calls (4 separate volunteer-type fetches, leaderboard, funnel, npos, teams, github). With Phase 0–1 done this is tolerable. **Do not build now** — leave a note in the plan PR description proposing a consolidated `GET /api/hackathon//page-bundle` for a future cycle. + +--- + +## Phase 4 — Verification (backend) + +1. `pytest` green; `pylint api/ common/ db/ model/ services/` no new errors. +2. Deploy to staging (fly `backend-ohack-staging` exists per Sentry), smoke: `/api/messages/hackathons/funnel/aggregate` (<2s cold), leaderboard for a real + a bogus event id (200 empty, no error logs), `/api/users/volunteering` GET/POST with a bad token (4xx not 500). +3. After prod deploy, watch Sentry for 48h: the 15 listed issues should stop accruing; span p95s should compress per acceptance criteria. Mark each Sentry issue Resolved so regressions re-alert. + +--- + +## Phase 5 — Frontend event-tracking fixes (`frontend-ohack.dev`) + +The GA export shows three measurement defects that corrupt the traffic data this plan is based on — fix them so the next optimization cycle has clean numbers. + +### P5-1: Double page_view per call in `src/lib/ga/index.js::pageview()` +It fires `gtag('config', GA_ID, pageParams)` (which sends a page_view by default) **and** `gtag('event', 'page_view', pageParams)`. Keep only the `event` call; never re-issue `config` per page (it also resets config state). + +### P5-2: SPA pageview wiring + shallow-route spam +There is **no** `routeChangeComplete` subscription in `_app.js`; SPA pageviews come from GA4 Enhanced Measurement history tracking, which fires on **every** `pushState`/`replaceState` — including the app's many shallow `router.replace` query-param writes (admin `?section=`/`?subtab=`, the 250ms-debounced `?q=` search sync, dialog-state params). Result: "Team Management" admin logged 22,647 views from 3 users, drowning real traffic. + +1. In `_app.js`, subscribe once: + ```js + useEffect(() => { + const onDone = (url, { shallow }) => { if (!shallow) ga.pageview(url); }; + router.events.on("routeChangeComplete", onDone); + return () => router.events.off("routeChangeComplete", onDone); + }, [router.events]); + ``` + Fire `pageview` inside a `setTimeout(0)`/microtask so `next/head` has applied the new `document.title` (this also fixes most of the 9,675 `(not set)` titles). +2. **Manual step for Greg (cannot be done in code):** in GA4 Admin → Data Streams → Enhanced Measurement, turn OFF "Page changes based on browser history events". Without this, step 1 double-counts. Call this out in the PR description. +3. Initial load stays tracked by the `gtag('config', …)` in `_document.js` — leave it, but add `send_page_view: true` explicitly and the `page_title` param. + +### P5-3: Title coverage + admin segmentation +- `(not set)` (9.7k views) and the bare `| Opportunity Hack` (76 views) rows mean some routes render without a ``. Sweep `src/pages/admin/**` and any page not setting `<Head><title>` (grep for pages lacking `title`), add stable titles. +- Set a GA user property on admin routes (`traffic_segment: 'admin'` via `gtag('set', 'user_properties', …)` when `pathname.startsWith('/admin')`) so admin usage can be excluded from acquisition reporting. + +### P5-4: Key-event gaps worth closing (small) +- The judge funnel is the largest organic cluster (~3k views across judge pages) but `hackathon-judge-opportunities` rows show near-zero key events. Ensure judge/mentor/hacker application forms fire `trackEvent` for form start AND submit (check `src/components/ApplicationForm/*` and the four `*-application.js` pages; add `EventCategory.FORM` start/complete events where missing). +- `Application error: a client-side exception has occurred` appeared as a page title (42 users). Add a GA `exception` event (and consider Sentry browser SDK if absent) in the Next.js error boundary / `_error.js` so client crashes are measurable. + +### P5-5: Verification (frontend) +`npm run build` green; with GA DebugView, click around: one page_view per real navigation, zero on admin `?section=` switches and search keystrokes, titles populated. + +--- + +## Suggested PR slicing + +1. PR-1 (backend): P0-1 Dockerfile/Procfile + TTLCache locks + P2-6 PATH fix. +2. PR-2 (backend): P0-2 crash-bug sweep (pure guards, low risk). +3. PR-3 (backend): P1-1 funnel aggregate + P1-2 leaderboard. +4. PR-4 (backend): P1-3/P1-4 PropelAuth caching + profile path; P2-1…P2-5, P2-7. +5. PR-5 (frontend): Phase 5 tracking fixes. +6. Data fixes (P1-2 item 6) — separate, after Greg confirms the intended `github_org` / event-id values. diff --git a/services/feedback_service.py b/services/feedback_service.py index ee21f63..6627488 100644 --- a/services/feedback_service.py +++ b/services/feedback_service.py @@ -1,4 +1,5 @@ import os +import threading import uuid from datetime import datetime @@ -29,6 +30,9 @@ def save_feedback(propel_user_id, json): send_slack_audit(action="save_feedback", message="Saving", payload=json) slack_user = get_slack_user_from_propel_user_id(propel_user_id) + if slack_user is None: + logger.warning(f"Could not resolve Slack user for propel_user_id={propel_user_id}") + return None user_db_id = get_user_from_slack_id(slack_user["sub"]).id feedback_giver_id = slack_user["sub"] @@ -114,7 +118,7 @@ def notify_feedback_receiver(feedback_receiver_id): logger.warning(f"User with ID {feedback_receiver_id} not found") -@cached(cache=TTLCache(maxsize=100, ttl=600)) +@cached(cache=TTLCache(maxsize=100, ttl=600), lock=threading.Lock()) @limits(calls=100, period=ONE_MINUTE) def get_user_feedback(propel_user_id): logger.info(f"Getting feedback for propel_user_id: {propel_user_id}") diff --git a/services/giveaway_service.py b/services/giveaway_service.py index c6eeba7..a87a16f 100644 --- a/services/giveaway_service.py +++ b/services/giveaway_service.py @@ -18,6 +18,9 @@ def save_giveaway(propel_user_id, json): send_slack_audit(action="submit_giveaway", message="Submitting", payload=json) slack_user = get_slack_user_from_propel_user_id(propel_user_id) + if slack_user is None: + logger.warning(f"Could not resolve Slack user for propel_user_id={propel_user_id}") + return None user_db_id = get_user_from_slack_id(slack_user["sub"]).id giveaway_id = json.get("giveaway_id") giveaway_data = json.get("giveaway_data", {}) @@ -44,6 +47,9 @@ def get_user_giveaway(propel_user_id): db = get_db() slack_user = get_slack_user_from_propel_user_id(propel_user_id) + if slack_user is None: + logger.warning(f"Could not resolve Slack user for propel_user_id={propel_user_id}") + return {"giveaways": []} db_user_id = get_user_from_slack_id(slack_user["sub"]).id giveaway_docs = db.collection('giveaways').where("user_id", "==", db_user_id).stream() @@ -64,11 +70,13 @@ def get_all_giveaways(): giveaways = {} for doc in docs: giveaway = doc.to_dict() - user_id = giveaway["user_id"] + user_id = giveaway.get("user_id") + if not user_id: + continue if user_id not in giveaways: from api.messages.messages_service import get_user_by_id_old user = get_user_by_id_old(user_id) - giveaway["user"] = user + giveaway["user"] = user if user is not None else {} giveaways[user_id] = giveaway return {"giveaways": list(giveaways.values())} diff --git a/services/hackathons_service.py b/services/hackathons_service.py index 46e6bae..eb69751 100644 --- a/services/hackathons_service.py +++ b/services/hackathons_service.py @@ -1,6 +1,8 @@ import uuid import os import random +import threading +from collections import Counter from datetime import datetime, timedelta from cachetools import cached, TTLCache @@ -16,6 +18,7 @@ get_volunteer_from_db_by_event, get_volunteer_checked_in_from_db_by_event, ) +from common.utils.redis_cache import get_cached, set_cached from common.utils.validators import validate_hackathon_data_partial from common.utils.firestore_helpers import ( doc_to_json, @@ -40,13 +43,14 @@ def _get_db(): def clear_cache(): - """Clear all hackathon-related caches.""" + """Clear all hackathon-related caches (in-process + Redis).""" + from common.utils.redis_cache import delete_cached clear_all_caches() get_single_hackathon_event.cache_clear() get_single_hackathon_id.cache_clear() get_hackathon_list.cache_clear() get_hackathon_funnel.cache_clear() - get_hackathon_funnel_aggregate.cache_clear() + delete_cached(_FUNNEL_AGG_CACHE_KEY) def add_nonprofit_to_hackathon(json): @@ -138,7 +142,7 @@ def remove_nonprofit_from_hackathon(json): } -@cached(cache=TTLCache(maxsize=100, ttl=20)) +@cached(cache=TTLCache(maxsize=100, ttl=20), lock=threading.Lock()) @limits(calls=2000, period=ONE_MINUTE) def get_single_hackathon_id(id): logger.debug(f"get_single_hackathon_id start id={id}") @@ -157,7 +161,7 @@ def get_single_hackathon_id(id): return {} -@cached(cache=TTLCache(maxsize=100, ttl=10)) +@cached(cache=TTLCache(maxsize=100, ttl=10), lock=threading.Lock()) @limits(calls=2000, period=ONE_MINUTE) def get_volunteer_by_event(event_id, volunteer_type, admin=False): logger.debug(f"get {volunteer_type} start event_id={event_id}") @@ -177,7 +181,7 @@ def get_volunteer_by_event(event_id, volunteer_type, admin=False): return results -@cached(cache=TTLCache(maxsize=100, ttl=5)) +@cached(cache=TTLCache(maxsize=100, ttl=5), lock=threading.Lock()) def get_volunteer_checked_in_by_event(event_id, volunteer_type): logger.debug(f"get {volunteer_type} start event_id={event_id}") @@ -196,7 +200,7 @@ def get_volunteer_checked_in_by_event(event_id, volunteer_type): return results -@cached(cache=TTLCache(maxsize=200, ttl=300)) +@cached(cache=TTLCache(maxsize=200, ttl=300), lock=threading.Lock()) @limits(calls=2000, period=ONE_MINUTE) def get_hackathon_funnel(event_id): """ @@ -334,7 +338,10 @@ def get_hackathon_funnel(event_id): return result -@cached(cache=TTLCache(maxsize=1, ttl=600)) +_FUNNEL_AGG_CACHE_KEY = "funnel_aggregate:v1" +_FUNNEL_AGG_REDIS_TTL = 6 * 3600 # 6 hours — historical data rarely changes + + @limits(calls=200, period=ONE_MINUTE) def get_hackathon_funnel_aggregate(): """ @@ -346,9 +353,20 @@ def get_hackathon_funnel_aggregate(): - events_total: int total hackathons iterated - events_with_summary: int how many have a funnel/summary doc - events_with_winners: int how many have at least one winning team + + Performance: caches in Redis (6h TTL) with in-process TTLCache fallback. + On a cache miss, batches all funnel/summary sub-doc reads in one + db.get_all() call and replaces per-event volunteers queries with a single + global query + Counter. """ - logger.debug("get_hackathon_funnel_aggregate start") - from collections import Counter as _Counter + cached_result = get_cached(_FUNNEL_AGG_CACHE_KEY) + if cached_result is not None: + logger.debug("get_hackathon_funnel_aggregate: Redis/local cache hit") + return cached_result + + import time as _time + _t0 = _time.time() + logger.info("get_hackathon_funnel_aggregate: cache miss — recomputing") db = _get_db() @@ -362,7 +380,7 @@ def get_hackathon_funnel_aggregate(): ) summed = {k: 0 for k in agg_summary_keys} - breakdowns = {k: _Counter() for k in agg_breakdown_keys} + breakdowns = {k: Counter() for k in agg_breakdown_keys} applied_as_hacker_total = 0 formed_team_total = 0 @@ -380,20 +398,43 @@ def get_hackathon_funnel_aggregate(): events_with_summary = 0 events_with_winners = 0 - for hackathon_doc in db.collection("hackathons").stream(): - events_total += 1 + # Step 1: Fetch all hackathon docs in one scan. + hackathon_docs = list(db.collection("hackathons").stream()) + events_total = len(hackathon_docs) + + # Step 2: Batch-fetch all funnel/summary sub-docs in ONE round-trip. + summary_refs = [ + db.collection("hackathons").document(h.id).collection("funnel").document("summary") + for h in hackathon_docs + ] + summary_snaps = list(db.get_all(summary_refs)) if summary_refs else [] + summary_by_hackathon_id = { + snap.reference.parent.parent.id: snap + for snap in summary_snaps + if snap is not None + } + + # Step 3: One global hacker query → Counter by event_id (replaces N per-event queries). + try: + hacker_counts = Counter( + doc.to_dict().get("event_id") + for doc in db.collection("volunteers") + .where(filter=firestore.FieldFilter("volunteer_type", "==", "hacker")) + .select(["event_id"]) + .stream() + if doc.to_dict().get("event_id") + ) + except Exception as e: + logger.warning(f"get_hackathon_funnel_aggregate: global hacker count failed: {e}") + hacker_counts = Counter() + + # Step 4: Process each hackathon with pre-fetched data. + for hackathon_doc in hackathon_docs: h_data = hackathon_doc.to_dict() or {} event_id = h_data.get("event_id") - # Pull the devpost summary doc, if present. - summary_snap = ( - db.collection("hackathons") - .document(hackathon_doc.id) - .collection("funnel") - .document("summary") - .get() - ) - if summary_snap.exists: + summary_snap = summary_by_hackathon_id.get(hackathon_doc.id) + if summary_snap and summary_snap.exists: events_with_summary += 1 s = summary_snap.to_dict() or {} for k in agg_summary_keys: @@ -423,8 +464,6 @@ def get_hackathon_funnel_aggregate(): if hasattr(u, "id") and u.id ] unique_member_ids.update(user_ids) - # Per-event dedupe (same person on two winning teams in one - # event won't double-count). Across events: no dedup. if status == "FOUNDING_ENGINEERS": founding_engineers_teams_total += 1 won_prize_teams_total += 1 @@ -448,20 +487,8 @@ def get_hackathon_funnel_aggregate(): if event_winners: events_with_winners += 1 - # Hacker applicants for this event (volunteers/{event_id}+hacker). if event_id: - try: - applied_as_hacker_total += sum( - 1 - for _ in db.collection("volunteers") - .where(filter=firestore.FieldFilter("event_id", "==", event_id)) - .where(filter=firestore.FieldFilter("volunteer_type", "==", "hacker")) - .stream() - ) - except Exception as e: - logger.warning( - f"get_hackathon_funnel_aggregate: hacker count failed for {event_id}: {e}" - ) + applied_as_hacker_total += hacker_counts.get(event_id, 0) aggregated_summary = { **summed, @@ -494,11 +521,16 @@ def get_hackathon_funnel_aggregate(): "events_with_summary": events_with_summary, "events_with_winners": events_with_winners, } + + elapsed = _time.time() - _t0 logger.info( - f"get_hackathon_funnel_aggregate end events={events_total} " - f"with_summary={events_with_summary} with_winners={events_with_winners} " - f"won={won_prize_total}p founding={founding_engineers_total}p teams={teams_total}" + f"get_hackathon_funnel_aggregate computed in {elapsed:.2f}s: " + f"events={events_total} with_summary={events_with_summary} " + f"with_winners={events_with_winners} won={won_prize_total}p " + f"founding={founding_engineers_total}p teams={teams_total}" ) + + set_cached(_FUNNEL_AGG_CACHE_KEY, result, ttl=_FUNNEL_AGG_REDIS_TTL) return result @@ -549,7 +581,7 @@ def _enrich_teams_users_batch(teams, db): return teams -@cached(cache=TTLCache(maxsize=100, ttl=600)) +@cached(cache=TTLCache(maxsize=100, ttl=600), lock=threading.Lock()) @limits(calls=2000, period=ONE_MINUTE) def get_single_hackathon_event(hackathon_id): logger.debug(f"get_single_hackathon_event start hackathon_id={hackathon_id}") @@ -574,7 +606,7 @@ def get_single_hackathon_event(hackathon_id): return {} -@cached(cache=TTLCache(maxsize=100, ttl=3600), key=lambda is_current_only: str(is_current_only)) +@cached(cache=TTLCache(maxsize=100, ttl=3600), lock=threading.Lock(), key=lambda is_current_only: str(is_current_only)) @limits(calls=200, period=ONE_MINUTE) @log_execution_time def get_hackathon_list(is_current_only=None): @@ -714,9 +746,12 @@ def update_hackathon_volunteers(event_id, volunteer_type, json, propel_id): doc_ref.update(json) - slack_user_id = doc.get('slack_user_id') + slack_user_id = doc.to_dict().get('slack_user_id') if doc_dict else None + + if not slack_user_id: + logger.warning(f"Volunteer {volunteer_id} has no slack_user_id; skipping Slack welcome message") - hackathon_welcome_message = f"🎉 Welcome <@{slack_user_id}> [{doc_volunteer_type}]." + hackathon_welcome_message = f"🎉 Welcome <@{slack_user_id}> [{doc_volunteer_type}]." if slack_user_id else None base_message = f"🎉 Welcome to Opportunity Hack {event_id}! You're checked in as a {doc_volunteer_type}.\n\n" @@ -759,20 +794,23 @@ def update_hackathon_volunteers(event_id, volunteer_type, json, propel_id): """ if json.get("checkedIn") is True and "checkedIn" not in doc_dict.keys() and doc_dict.get("checkedIn") != True: - logger.info(f"Volunteer {volunteer_id} just checked in, sending welcome message to {slack_user_id}") - invite_user_to_channel(slack_user_id, "hackathon-welcome") - - logger.info(f"Sending Slack message to volunteer {volunteer_id} in channel #{slack_user_id} and #hackathon-welcome") - async_send_slack( - channel="#hackathon-welcome", - message=hackathon_welcome_message - ) - - logger.info(f"Sending Slack DM to volunteer {volunteer_id} in channel #{slack_user_id}") - async_send_slack( - channel=slack_user_id, - message=slack_message_content - ) + if slack_user_id: + logger.info(f"Volunteer {volunteer_id} just checked in, sending welcome message to {slack_user_id}") + invite_user_to_channel(slack_user_id, "hackathon-welcome") + + logger.info(f"Sending Slack message to volunteer {volunteer_id} in channel #{slack_user_id} and #hackathon-welcome") + async_send_slack( + channel="#hackathon-welcome", + message=hackathon_welcome_message + ) + + logger.info(f"Sending Slack DM to volunteer {volunteer_id} in channel #{slack_user_id}") + async_send_slack( + channel=slack_user_id, + message=slack_message_content + ) + else: + logger.warning(f"Volunteer {volunteer_id} checked in but no slack_user_id — skipping Slack welcome") else: logger.info(f"Volunteer {volunteer_id} checked in again, no welcome message sent.") diff --git a/services/news_service.py b/services/news_service.py index 2715a73..8565106 100644 --- a/services/news_service.py +++ b/services/news_service.py @@ -1,4 +1,5 @@ import os +import threading import time from datetime import datetime @@ -211,7 +212,7 @@ def save_praise(json): return Message("Saved praise") -@cached(cache=TTLCache(maxsize=100, ttl=600)) +@cached(cache=TTLCache(maxsize=100, ttl=600), lock=threading.Lock()) def get_all_praises(): results = get_recent_praises() @@ -232,7 +233,7 @@ def get_all_praises(): return Message(results) -@cached(cache=TTLCache(maxsize=100, ttl=600)) +@cached(cache=TTLCache(maxsize=100, ttl=600), lock=threading.Lock()) def get_praises_about_user(user_id): results = get_praises_by_user_id(user_id) @@ -257,7 +258,7 @@ def _is_publicly_visible(doc_dict): return status not in ("draft", "archived") -@cached(cache=TTLCache(maxsize=100, ttl=32600), key=lambda news_limit, news_id: f"{news_limit}-{news_id}") +@cached(cache=TTLCache(maxsize=100, ttl=32600), lock=threading.Lock(), key=lambda news_limit, news_id: f"{news_limit}-{news_id}") def get_news(news_limit=3, news_id=None): logger.debug("Get News") db = get_db() diff --git a/services/nonprofits_service.py b/services/nonprofits_service.py index 905c1fb..638bd5a 100644 --- a/services/nonprofits_service.py +++ b/services/nonprofits_service.py @@ -151,15 +151,22 @@ def get_npos_by_hackathon_id(id): npo_refs = doc_dict["nonprofits"] logger.info(f"get_npos_by_hackathon_id found {len(npo_refs)} nonprofit references") - for npo_ref in npo_refs: - try: - npo_doc = npo_ref.get() + try: + npo_snaps = list(db.get_all(npo_refs)) + for npo_doc in npo_snaps: if npo_doc.exists: npo = doc_to_json(docid=npo_doc.id, doc=npo_doc) npos.append(npo) - except Exception as e: - logger.error(f"Error processing nonprofit reference: {e}") - continue + except Exception as e: + logger.warning(f"get_npos_by_hackathon_id batch read failed, falling back: {e}") + for npo_ref in npo_refs: + try: + npo_doc = npo_ref.get() + if npo_doc.exists: + npos.append(doc_to_json(docid=npo_doc.id, doc=npo_doc)) + except Exception as inner_e: + logger.warning(f"Error processing nonprofit reference: {inner_e}") + continue return { "nonprofits": npos diff --git a/services/planning_mention_notifier.py b/services/planning_mention_notifier.py index 4aab288..42970c7 100644 --- a/services/planning_mention_notifier.py +++ b/services/planning_mention_notifier.py @@ -20,6 +20,7 @@ import logging import os import re +import threading from cachetools import TTLCache, cached logger = logging.getLogger("planning_mention_notifier") @@ -40,7 +41,7 @@ def parse_mention_ids(text: str): # Cache PropelAuth OAuth lookups for 5 minutes — heavy network call, and # Slack ID / email don't change in that window. -@cached(cache=TTLCache(maxsize=500, ttl=300)) +@cached(cache=TTLCache(maxsize=500, ttl=300), lock=threading.Lock()) def _get_oauth_user_cached(propel_id): try: from services.users_service import get_oauth_user_from_propel_user_id diff --git a/services/problem_statements_service.py b/services/problem_statements_service.py index 62f80f3..93aea12 100644 --- a/services/problem_statements_service.py +++ b/services/problem_statements_service.py @@ -1,4 +1,5 @@ from datetime import datetime +import threading from ratelimit import limits from common.utils.slack import invite_user_to_channel, send_slack, send_slack_audit from common.utils.oauth_providers import extract_slack_user_id, is_slack_user_id @@ -64,7 +65,7 @@ def validate_problem_statement(data): # Add any additional validation logic here return True -@cached(cache=TTLCache(maxsize=100, ttl=CACHE_TTL)) +@cached(cache=TTLCache(maxsize=100, ttl=CACHE_TTL), lock=threading.Lock()) def get_problem_statement(id): """Get a single problem statement by ID""" debug(logger, "get_problem_statement start", id=id) diff --git a/services/teams_service.py b/services/teams_service.py index 2cb0989..aca6c6c 100644 --- a/services/teams_service.py +++ b/services/teams_service.py @@ -410,14 +410,14 @@ def join_team(propel_user_id, json): slack_user = get_slack_user_from_propel_user_id(propel_user_id) if not slack_user or "sub" not in slack_user: - logger.error(f"Could not resolve Slack user for propel_user_id={propel_user_id}") + logger.warning(f"Could not resolve Slack user for propel_user_id={propel_user_id}") return Message("Error: User not found") slack_user_id = slack_user["sub"] slack_member_id = extract_slack_user_id(slack_user_id) user = get_user_from_slack_id(slack_user_id) if user is None: - logger.error(f"Could not resolve database user for slack_user_id={slack_user_id}") + logger.warning(f"Could not resolve database user for slack_user_id={slack_user_id}") return Message("Error: User not found") userid = user.id @@ -484,14 +484,14 @@ def unjoin_team(propel_user_id, json): slack_user = get_slack_user_from_propel_user_id(propel_user_id) if not slack_user or "sub" not in slack_user: - logger.error(f"Could not resolve Slack user for propel_user_id={propel_user_id}") + logger.warning(f"Could not resolve Slack user for propel_user_id={propel_user_id}") return Message("Error: User not found") slack_user_id = slack_user["sub"] slack_member_id = extract_slack_user_id(slack_user_id) user = get_user_from_slack_id(slack_user_id) if user is None: - logger.error(f"Could not resolve database user for slack_user_id={slack_user_id}") + logger.warning(f"Could not resolve database user for slack_user_id={slack_user_id}") return Message("Error: User not found") userid = user.id diff --git a/services/users_service.py b/services/users_service.py index b75cfd5..4aa8e33 100644 --- a/services/users_service.py +++ b/services/users_service.py @@ -1,5 +1,6 @@ from datetime import datetime import os +import threading from ratelimit import limits import requests from common.utils.slack import send_slack_audit @@ -169,19 +170,27 @@ def get_user_from_propel_user_id(propel_id): return get_user_from_slack_id(user_id) +# Two-tier PropelAuth cache: positive results (10 min) + negative sentinel (5 min). +# Intentionally in-process only — the payload contains OAuth access tokens. +_PROPEL_CACHE = TTLCache(maxsize=512, ttl=600) +_PROPEL_MISS_CACHE = TTLCache(maxsize=512, ttl=300) +_PROPEL_LOCK = threading.Lock() +_PROPEL_MISS = object() # sentinel so we can cache None explicitly + + def get_oauth_user_from_propel_user_id(propel_id): """ Get user details from any OAuth provider via PropelAuth. - This function detects which OAuth provider (Slack, Google, etc.) was used - and fetches user details from the appropriate provider's API. - - Args: - propel_id: The PropelAuth user ID - - Returns: - dict: User details with normalized fields including 'sub' (user ID) + Cached in-process (10 min hit / 5 min miss) — do NOT put in Redis since + the response contains OAuth access tokens. """ + with _PROPEL_LOCK: + if propel_id in _PROPEL_MISS_CACHE: + return None + if propel_id in _PROPEL_CACHE: + return _PROPEL_CACHE[propel_id] + url = f"{os.getenv('PROPEL_AUTH_URL')}/api/backend/v1/user/{propel_id}/oauth_token" debug(logger, "Propel API URL", url=url) @@ -194,6 +203,8 @@ def get_oauth_user_from_propel_user_id(propel_id): if resp.status_code != 200: warning(logger, "PropelAuth API returned non-200", status=resp.status_code, propel_id=propel_id) + with _PROPEL_LOCK: + _PROPEL_MISS_CACHE[propel_id] = _PROPEL_MISS return None json_resp = resp.json() logger.debug(f"Propel RESP JSON: {json_resp}") @@ -203,23 +214,34 @@ def get_oauth_user_from_propel_user_id(propel_id): if provider is None or token_data is None: warning(logger, "Could not detect OAuth provider from PropelAuth response", response=json_resp) + with _PROPEL_LOCK: + _PROPEL_MISS_CACHE[propel_id] = _PROPEL_MISS return None access_token = token_data.get('access_token') if not access_token: warning(logger, "No access token found in PropelAuth response", provider=provider, response=json_resp) + with _PROPEL_LOCK: + _PROPEL_MISS_CACHE[propel_id] = _PROPEL_MISS return None debug(logger, "Detected OAuth provider", provider=provider) # Fetch user details from the appropriate provider if provider == 'slack': - return get_slack_user_from_token(access_token) + result = get_slack_user_from_token(access_token) elif provider == 'google': - return get_google_user_from_token(access_token) + result = get_google_user_from_token(access_token) else: warning(logger, "Unsupported OAuth provider", provider=provider) - return None + result = None + + with _PROPEL_LOCK: + if result is not None: + _PROPEL_CACHE[propel_id] = result + else: + _PROPEL_MISS_CACHE[propel_id] = _PROPEL_MISS + return result def get_slack_user_from_propel_user_id(propel_id): @@ -286,7 +308,7 @@ def get_profile_by_db_id(id): return res # 10 minute cache for 100 objects LRU -@cached(cache=TTLCache(maxsize=100, ttl=600)) +@cached(cache=TTLCache(maxsize=100, ttl=600), lock=threading.Lock()) @limits(calls=100, period=ONE_MINUTE) def get_profile_metadata(propel_id): logger.debug("Profile Metadata") @@ -313,6 +335,10 @@ def get_profile_metadata(propel_id): propel_id=propel_id ) + if db_id is None: + warning(logger, "save_user returned None — PropelAuth provided empty values", propel_id=propel_id) + return None + # Get all of the user history and profile data from the DB response = get_history(db_id.id) logger.debug(f"get_profile_metadata {response}") @@ -334,7 +360,7 @@ def save_profile_metadata(propel_id, json): oauth_user = get_oauth_user_from_propel_user_id(propel_id) if oauth_user is None: - error(logger, "Could not get OAuth user from PropelAuth", propel_id=propel_id) + warning(logger, "Could not get OAuth user from PropelAuth", propel_id=propel_id) return None user_id = oauth_user["sub"] @@ -377,7 +403,7 @@ def save_volunteering_time(propel_id, json): logger.info(f"Save Volunteering Time for {propel_id} {json}") oauth_user = get_oauth_user_from_propel_user_id(propel_id) if oauth_user is None: - error(logger, "Could not get OAuth user from PropelAuth", propel_id=propel_id) + warning(logger, "Could not get OAuth user from PropelAuth", propel_id=propel_id) return None user_id = oauth_user["sub"] @@ -387,7 +413,7 @@ def save_volunteering_time(propel_id, json): # Get the user user = fetch_user_by_user_id(user_id) if user is None: - error(logger, "User not found", user_id=user_id) + warning(logger, "User not found", user_id=user_id) return timestamp = datetime.now().isoformat() + "Z" @@ -433,7 +459,7 @@ def get_volunteering_time(propel_id, start_date, end_date): logger.info(f"Get Volunteering Time for {propel_id} {start_date} {end_date}") oauth_user = get_oauth_user_from_propel_user_id(propel_id) if oauth_user is None: - error(logger, "Could not get OAuth user from PropelAuth", propel_id=propel_id) + warning(logger, "Could not get OAuth user from PropelAuth", propel_id=propel_id) return None user_id = oauth_user["sub"] @@ -443,7 +469,8 @@ def get_volunteering_time(propel_id, start_date, end_date): # Get the user user = fetch_user_by_user_id(user_id) if user is None: - return + warning(logger, "User not found", user_id=user_id) + return None # Filter the volunteering data volunteeringActiveTime = [] @@ -539,7 +566,7 @@ def get_privacy_settings(propel_id): logger.info(f"Get Privacy Settings for {propel_id}") oauth_user = get_oauth_user_from_propel_user_id(propel_id) if oauth_user is None: - error(logger, "Could not get OAuth user from PropelAuth", propel_id=propel_id) + warning(logger, "Could not get OAuth user from PropelAuth", propel_id=propel_id) return None user_id = oauth_user["sub"] @@ -547,7 +574,7 @@ def get_privacy_settings(propel_id): # Get the user user = fetch_user_by_user_id(user_id) if user is None: - error(logger, "User not found", user_id=user_id) + warning(logger, "User not found", user_id=user_id) return None return user.get_privacy_settings() @@ -558,7 +585,7 @@ def update_privacy_settings(propel_id, data): logger.info(f"Update Privacy Settings for {propel_id} {data}") oauth_user = get_oauth_user_from_propel_user_id(propel_id) if oauth_user is None: - error(logger, "Could not get OAuth user from PropelAuth", propel_id=propel_id) + warning(logger, "Could not get OAuth user from PropelAuth", propel_id=propel_id) return None user_id = oauth_user["sub"] @@ -566,7 +593,7 @@ def update_privacy_settings(propel_id, data): # Get the user user = fetch_user_by_user_id(user_id) if user is None: - error(logger, "User not found", user_id=user_id) + warning(logger, "User not found", user_id=user_id) return None # Update the privacy settings diff --git a/services/volunteers_service.py b/services/volunteers_service.py index 72d86ba..4a84129 100644 --- a/services/volunteers_service.py +++ b/services/volunteers_service.py @@ -466,18 +466,40 @@ def send_slack_volunteer_notification(volunteer_data: Dict[str, Any], is_update: available_days = volunteer_data.get('availableDays', '') if available_days: - detail_lines.append(f"*Available Days:* {available_days}") + days_str = str(available_days) + if len(days_str) > 500: + days_str = days_str[:497] + "…" + detail_lines.append(f"*Available Days:* {days_str}") skills = volunteer_data.get('skills', '') if skills: - detail_lines.append(f"*Skills:* {skills}") + skills_str = str(skills)[:500] if len(str(skills)) > 500 else str(skills) + detail_lines.append(f"*Skills:* {skills_str}") experience = volunteer_data.get('experience', '') if experience: - detail_lines.append(f"*Experience:* {experience}") + exp_str = str(experience)[:500] if len(str(experience)) > 500 else str(experience) + detail_lines.append(f"*Experience:* {exp_str}") if detail_lines: - blocks.append({"type": "section", "text": {"type": "mrkdwn", "text": "\n".join(detail_lines)}}) + # Slack section text cap is 3000 chars; split if needed (max 50 blocks total). + section_text = "\n".join(detail_lines) + if len(section_text) <= 2900: + blocks.append({"type": "section", "text": {"type": "mrkdwn", "text": section_text}}) + else: + # Split into ≤2900-char chunks + chunk, chunks = [], [] + for line in detail_lines: + candidate = "\n".join(chunk + [line]) + if len(candidate) > 2900 and chunk: + chunks.append("\n".join(chunk)) + chunk = [line] + else: + chunk.append(line) + if chunk: + chunks.append("\n".join(chunk)) + for c in chunks[:48]: # leave room for header + footer blocks + blocks.append({"type": "section", "text": {"type": "mrkdwn", "text": c}}) # Context footer — timestamp + Slack workspace lookup result context_elements = [