From a4253c224afa797e36ff34a2cd0bfcc1848a1aad Mon Sep 17 00:00:00 2001 From: "2569718930@qq.com" <2569718930@qq.com> Date: Sun, 31 May 2026 18:27:04 +0800 Subject: [PATCH] Add auth profile timing instrumentation --- frontend/app/api/auth/me/route.ts | 367 +++++++++---- .../authTimingInstrumentation.test.ts | 43 ++ tests/test_auth_timing_instrumentation.py | 39 ++ web/routers/auth.py | 12 +- web/services/auth_api.py | 481 +++++++++++------- 5 files changed, 683 insertions(+), 259 deletions(-) create mode 100644 frontend/components/ops/__tests__/authTimingInstrumentation.test.ts create mode 100644 tests/test_auth_timing_instrumentation.py diff --git a/frontend/app/api/auth/me/route.ts b/frontend/app/api/auth/me/route.ts index c36dc5d6..d50701cf 100644 --- a/frontend/app/api/auth/me/route.ts +++ b/frontend/app/api/auth/me/route.ts @@ -27,6 +27,104 @@ import { const API_BASE = process.env.POLYWEATHER_API_BASE_URL; +type AuthMeTimingStage = { + durationMs: number; + name: string; +}; + +type AuthMeTimer = { + hasAuthorization: boolean; + hasSupabaseCookie: boolean; + measure(name: string, action: () => Promise): Promise; + measureSync(name: string, action: () => T): T; + preferSnapshot: boolean; + stages: AuthMeTimingStage[]; + totalMs(): number; +}; + +function authMeNowMs() { + return typeof performance !== "undefined" ? performance.now() : Date.now(); +} + +function createAuthMeTimer(req: NextRequest): AuthMeTimer { + const startedAt = authMeNowMs(); + const stages: AuthMeTimingStage[] = []; + const recordStage = (name: string, stageStartedAt: number) => { + stages.push({ + durationMs: Math.round((authMeNowMs() - stageStartedAt) * 10) / 10, + name, + }); + }; + + return { + hasAuthorization: Boolean(req.headers.get("authorization")), + hasSupabaseCookie: hasRequestSupabaseSessionCookie(req), + async measure(name: string, action: () => Promise) { + const stageStartedAt = authMeNowMs(); + try { + return await action(); + } finally { + recordStage(name, stageStartedAt); + } + }, + measureSync(name: string, action: () => T) { + const stageStartedAt = authMeNowMs(); + try { + return action(); + } finally { + recordStage(name, stageStartedAt); + } + }, + preferSnapshot: req.nextUrl.searchParams.get("prefer_snapshot") === "1", + stages, + totalMs() { + return Math.round((authMeNowMs() - startedAt) * 10) / 10; + }, + }; +} + +function formatServerTiming(stages: AuthMeTimingStage[], totalMs: number) { + return [...stages, { durationMs: totalMs, name: "total" }] + .map(({ durationMs, name }) => { + const safeName = name.replace(/[^A-Za-z0-9_-]/g, "_"); + return `${safeName};dur=${Math.max(0, durationMs).toFixed(1)}`; + }) + .join(", "); +} + +function finishAuthMeResponse( + response: NextResponse, + timer: AuthMeTimer, + outcome: string, + extra?: { backendServerTiming?: string }, +) { + const total = timer.totalMs(); + const ownServerTiming = formatServerTiming(timer.stages, total); + const backendServerTiming = String(extra?.backendServerTiming || "").trim(); + response.headers.set( + "Server-Timing", + backendServerTiming + ? `${ownServerTiming}, ${backendServerTiming}` + : ownServerTiming, + ); + console.info( + "[auth-me-timing]", + JSON.stringify({ + backendServerTiming: backendServerTiming || undefined, + hasAuthorization: timer.hasAuthorization, + hasSupabaseCookie: timer.hasSupabaseCookie, + outcome, + preferSnapshot: timer.preferSnapshot, + stagesMs: Object.fromEntries( + timer.stages.map((stage) => [stage.name, stage.durationMs]), + ), + status: response.status, + totalMs: total, + }), + ); + return response; +} + async function trackAuthDiagnosticEvent( req: NextRequest, { @@ -273,21 +371,30 @@ function hasRequestSupabaseSessionCookie(req: NextRequest) { } export async function GET(req: NextRequest) { + const timer = createAuthMeTimer(req); const requestHost = req.headers.get("x-forwarded-host") || req.headers.get("host") || req.nextUrl.host; if ( isLocalFullAccessHost(requestHost) || isLocalFullAccessHost(req.nextUrl.hostname) ) { - return NextResponse.json(getLocalDevAuthPayload(), { - headers: { "Cache-Control": "no-store" }, - }); + return finishAuthMeResponse( + NextResponse.json(getLocalDevAuthPayload(), { + headers: { "Cache-Control": "no-store" }, + }), + timer, + "local_full_access", + ); } if (!API_BASE) { - return NextResponse.json( - { error: "POLYWEATHER_API_BASE_URL is not configured" }, - { status: 500 }, + return finishAuthMeResponse( + NextResponse.json( + { error: "POLYWEATHER_API_BASE_URL is not configured" }, + { status: 500 }, + ), + timer, + "missing_api_base", ); } @@ -297,16 +404,21 @@ export async function GET(req: NextRequest) { !req.headers.get("authorization") && hasRequestSupabaseSessionCookie(req) ) { - const snapshotPayload = entitlementSnapshotToAuthPayload( - readEntitlementSnapshot(req), + const snapshotPayload = timer.measureSync( + "snapshot_cookie", + () => entitlementSnapshotToAuthPayload(readEntitlementSnapshot(req)), ); if (snapshotPayload) { - return NextResponse.json( - { - ...snapshotPayload, - entitlement_snapshot_reason: "prefer_snapshot_fast_path", - }, - { headers: { "Cache-Control": "no-store" } }, + return finishAuthMeResponse( + NextResponse.json( + { + ...snapshotPayload, + entitlement_snapshot_reason: "prefer_snapshot_fast_path", + }, + { headers: { "Cache-Control": "no-store" } }, + ), + timer, + "prefer_snapshot_fast_path", ); } } @@ -315,11 +427,17 @@ export async function GET(req: NextRequest) { let bearerIdentity: VerifiedBearerIdentity | null | undefined; const getBearerIdentityOnce = async () => { if (bearerIdentity !== undefined) return bearerIdentity; - bearerIdentity = await getVerifiedBearerIdentity(req); + bearerIdentity = await timer.measure( + "bearer_identity", + () => getVerifiedBearerIdentity(req), + ); return bearerIdentity; }; try { - auth = await buildBackendRequestHeaders(req); + auth = await timer.measure( + "auth_headers", + () => buildBackendRequestHeaders(req), + ); if ( hasSupabaseServerEnv() && !auth.authUserId && @@ -331,7 +449,11 @@ export async function GET(req: NextRequest) { points: 0, }); if (!preferSnapshot) clearEntitlementSnapshotCookie(response); - return applyAuthResponseCookies(response, auth.response); + return finishAuthMeResponse( + applyAuthResponseCookies(response, auth.response), + timer, + "no_session", + ); } if (preferSnapshot) { @@ -347,24 +469,35 @@ export async function GET(req: NextRequest) { response: auth.response, userId: identity.userId, }); - if (snapshotResponse) return snapshotResponse; + if (snapshotResponse) { + return finishAuthMeResponse( + snapshotResponse, + timer, + "prefer_snapshot", + ); + } } } + if (!auth) throw new Error("auth headers unavailable"); + const backendAuth = auth; const controller = new AbortController(); const timeoutId = setTimeout(() => controller.abort(), 6000); let res: Response; try { - res = await fetch(`${API_BASE}/api/auth/me`, { - headers: auth.headers, - cache: "no-store", - signal: controller.signal, - }); + res = await timer.measure("backend_fetch", async () => + await fetch(`${API_BASE}/api/auth/me`, { + headers: backendAuth.headers, + cache: "no-store", + signal: controller.signal, + }), + ); } finally { clearTimeout(timeoutId); } + const backendServerTiming = res.headers.get("server-timing") || ""; if (res.status === 401 || res.status === 403) { - const raw = await res.text(); + const raw = await timer.measure("backend_read", () => res.text()); const authIdentity = auth.authUserId ? { email: auth.authEmail || null, userId: auth.authUserId } : await getBearerIdentityOnce(); @@ -372,30 +505,45 @@ export async function GET(req: NextRequest) { authIdentity?.userId && isSubscriptionRequiredBackendResponse(res.status, raw) ) { - return subscriptionRequiredAuthProfileResponse({ - email: authIdentity.email, - response: auth.response, - userId: authIdentity.userId, - }); + return finishAuthMeResponse( + subscriptionRequiredAuthProfileResponse({ + email: authIdentity.email, + response: auth.response, + userId: authIdentity.userId, + }), + timer, + "subscription_required", + { backendServerTiming }, + ); } if (auth.authUserId) { - return degradedAuthProfileResponse({ - email: auth.authEmail || null, - reason: `backend_${res.status}`, - req, - response: auth.response, - userId: auth.authUserId, - }); + return finishAuthMeResponse( + await degradedAuthProfileResponse({ + email: auth.authEmail || null, + reason: `backend_${res.status}`, + req, + response: auth.response, + userId: auth.authUserId, + }), + timer, + `degraded_backend_${res.status}`, + { backendServerTiming }, + ); } const identity = await getBearerIdentityOnce(); if (identity) { - return degradedAuthProfileResponse({ - email: identity.email, - reason: `backend_${res.status}`, - req, - response: auth.response, - userId: identity.userId, - }); + return finishAuthMeResponse( + await degradedAuthProfileResponse({ + email: identity.email, + reason: `backend_${res.status}`, + req, + response: auth.response, + userId: identity.userId, + }), + timer, + `degraded_backend_${res.status}`, + { backendServerTiming }, + ); } const response = NextResponse.json({ authenticated: false, @@ -403,33 +551,53 @@ export async function GET(req: NextRequest) { points: 0, }); clearEntitlementSnapshotCookie(response); - return applyAuthResponseCookies(response, auth.response); + return finishAuthMeResponse( + applyAuthResponseCookies(response, auth.response), + timer, + `anonymous_backend_${res.status}`, + { backendServerTiming }, + ); } if (!res.ok) { - const raw = await res.text(); + const raw = await timer.measure("backend_read", () => res.text()); if (auth.authUserId) { - return degradedAuthProfileResponse({ - email: auth.authEmail || null, - reason: `backend_${res.status}`, - req, - response: auth.response, - userId: auth.authUserId, - }); + return finishAuthMeResponse( + await degradedAuthProfileResponse({ + email: auth.authEmail || null, + reason: `backend_${res.status}`, + req, + response: auth.response, + userId: auth.authUserId, + }), + timer, + `degraded_backend_${res.status}`, + { backendServerTiming }, + ); } const identity = await getBearerIdentityOnce(); if (identity) { - return degradedAuthProfileResponse({ - email: identity.email, - reason: `backend_${res.status}`, - req, - response: auth.response, - userId: identity.userId, - }); + return finishAuthMeResponse( + await degradedAuthProfileResponse({ + email: identity.email, + reason: `backend_${res.status}`, + req, + response: auth.response, + userId: identity.userId, + }), + timer, + `degraded_backend_${res.status}`, + { backendServerTiming }, + ); } const response = buildUpstreamErrorResponse(res.status, raw); - return applyAuthResponseCookies(response, auth.response); + return finishAuthMeResponse( + applyAuthResponseCookies(response, auth.response), + timer, + `upstream_${res.status}`, + { backendServerTiming }, + ); } - const data = await res.json(); + const data = await timer.measure("backend_read", () => res.json()); if (data?.authenticated === true && data?.subscription_active == null) { const userId = String(data.user_id || auth.authUserId || "").trim(); if (userId) { @@ -440,47 +608,76 @@ export async function GET(req: NextRequest) { response: auth.response, userId, }); - if (snapshotResponse) return snapshotResponse; + if (snapshotResponse) { + return finishAuthMeResponse( + snapshotResponse, + timer, + "subscription_unknown_snapshot", + { backendServerTiming }, + ); + } } } const response = NextResponse.json(data); applyEntitlementSnapshotFromAuthPayload(response, data); - return applyAuthResponseCookies(response, auth.response); + return finishAuthMeResponse( + applyAuthResponseCookies(response, auth.response), + timer, + "ok", + { backendServerTiming }, + ); } catch (error) { if (auth?.authUserId) { - return degradedAuthProfileResponse({ - email: auth.authEmail || null, - reason: String(error), - req, - response: auth.response, - userId: auth.authUserId, - }); + return finishAuthMeResponse( + await degradedAuthProfileResponse({ + email: auth.authEmail || null, + reason: String(error), + req, + response: auth.response, + userId: auth.authUserId, + }), + timer, + "exception_degraded", + ); } const identity = await getBearerIdentityOnce(); if (identity) { - return degradedAuthProfileResponse({ - email: identity.email, - reason: String(error), - req, - response: auth?.response || null, - userId: identity.userId, - }); + return finishAuthMeResponse( + await degradedAuthProfileResponse({ + email: identity.email, + reason: String(error), + req, + response: auth?.response || null, + userId: identity.userId, + }), + timer, + "exception_degraded", + ); } - const snapshotPayload = entitlementSnapshotToAuthPayload( - readEntitlementSnapshot(req), + const snapshotPayload = timer.measureSync( + "snapshot_cookie", + () => entitlementSnapshotToAuthPayload(readEntitlementSnapshot(req)), ); if (snapshotPayload) { const snapshotResponse = NextResponse.json({ ...snapshotPayload, entitlement_snapshot_reason: "exception_snapshot", }); - return applyAuthResponseCookies(snapshotResponse, auth?.response || null); + return finishAuthMeResponse( + applyAuthResponseCookies(snapshotResponse, auth?.response || null), + timer, + "exception_snapshot", + ); } - return unauthenticatedAuthProfileResponse({ - reason: String(error), - req, - response: auth?.response || null, - }); + return finishAuthMeResponse( + await unauthenticatedAuthProfileResponse({ + reason: String(error), + req, + response: auth?.response || null, + }), + timer, + "exception_anonymous", + ); } } diff --git a/frontend/components/ops/__tests__/authTimingInstrumentation.test.ts b/frontend/components/ops/__tests__/authTimingInstrumentation.test.ts new file mode 100644 index 00000000..056c03ea --- /dev/null +++ b/frontend/components/ops/__tests__/authTimingInstrumentation.test.ts @@ -0,0 +1,43 @@ +import fs from "node:fs"; +import path from "node:path"; + +function assert(condition: unknown, message: string) { + if (!condition) throw new Error(message); +} + +export function runTests() { + const projectRoot = process.cwd(); + const authMeRouteSource = fs.readFileSync( + path.join(projectRoot, "app", "api", "auth", "me", "route.ts"), + "utf8", + ); + + assert( + authMeRouteSource.includes("createAuthMeTimer") && + authMeRouteSource.includes("finishAuthMeResponse"), + "/api/auth/me proxy must centralize timing so every return path can emit instrumentation", + ); + assert( + authMeRouteSource.includes('"Server-Timing"') && + authMeRouteSource.includes("auth_headers") && + authMeRouteSource.includes("backend_fetch") && + authMeRouteSource.includes("total"), + "/api/auth/me proxy must expose stage durations through Server-Timing for HAR inspection", + ); + const finishStart = authMeRouteSource.indexOf("function finishAuthMeResponse"); + const finishEnd = authMeRouteSource.indexOf("async function trackAuthDiagnosticEvent"); + const finishSource = + finishStart >= 0 && finishEnd > finishStart + ? authMeRouteSource.slice(finishStart, finishEnd) + : ""; + assert( + finishSource.includes("[auth-me-timing]") && + finishSource.includes("hasAuthorization") && + finishSource.includes("hasSupabaseCookie") && + !finishSource.includes("authUserId") && + !finishSource.includes("authEmail") && + !finishSource.includes("userId") && + !finishSource.includes("email"), + "/api/auth/me proxy timing logs must include request shape but avoid raw user ids or emails", + ); +} diff --git a/tests/test_auth_timing_instrumentation.py b/tests/test_auth_timing_instrumentation.py new file mode 100644 index 00000000..95eb1ba1 --- /dev/null +++ b/tests/test_auth_timing_instrumentation.py @@ -0,0 +1,39 @@ +from pathlib import Path + + +ROOT = Path(__file__).resolve().parents[1] + + +def test_auth_me_backend_records_stage_timing_without_sensitive_identity(): + source = (ROOT / "web" / "services" / "auth_api.py").read_text(encoding="utf-8") + + assert "_AuthMeTimer" in source + assert "auth_me_timing" in source + for stage in [ + "assert_entitlement", + "bind_identity", + "ensure_signup_trial", + "subscription_window", + "auth_points", + "weekly_profile", + "telegram_pricing", + "referral_summary", + "total", + ]: + assert stage in source + + log_start = source.index("def _log_auth_me_timing") + log_end = source.index("def _require_auth_identity_without_subscription_gate") + log_source = source[log_start:log_end] + assert "auth_user_id" not in log_source + assert "auth_email" not in log_source + + +def test_auth_me_backend_exposes_server_timing_header_for_proxy_logs(): + router_source = (ROOT / "web" / "routers" / "auth.py").read_text( + encoding="utf-8" + ) + + assert "Response" in router_source + assert "auth_me_server_timing" in router_source + assert '"Server-Timing"' in router_source diff --git a/web/routers/auth.py b/web/routers/auth.py index 5ab076e2..d3baf07f 100644 --- a/web/routers/auth.py +++ b/web/routers/auth.py @@ -1,6 +1,6 @@ """Authentication API routes.""" -from fastapi import APIRouter, Request +from fastapi import APIRouter, Request, Response from web.core import ReferralApplyRequest, TelegramBindTokenRequest, TelegramLoginRequest from web.services.auth_api import ( @@ -15,8 +15,14 @@ router = APIRouter(tags=["auth"]) @router.get("/api/auth/me") -async def auth_me(request: Request): - return get_auth_me_payload(request) +async def auth_me(request: Request, response: Response): + payload = get_auth_me_payload(request) + server_timing = str( + getattr(request.state, "auth_me_server_timing", "") or "" + ).strip() + if server_timing: + response.headers["Server-Timing"] = server_timing + return payload @router.post("/api/auth/telegram/login") diff --git a/web/services/auth_api.py b/web/services/auth_api.py index 2259c011..96372638 100644 --- a/web/services/auth_api.py +++ b/web/services/auth_api.py @@ -2,9 +2,11 @@ from __future__ import annotations -from typing import Any, Dict +import time +from typing import Any, Callable, Dict, Optional, TypeVar from fastapi import HTTPException, Request +from loguru import logger from src.auth.telegram_group_pricing import TelegramGroupPricing from src.database.db_manager import DBManager @@ -12,6 +14,70 @@ from web.core import ReferralApplyRequest, TelegramLoginRequest import web.routes as legacy_routes +T = TypeVar("T") + + +class _AuthMeTimer: + def __init__(self, request: Request): + self.request = request + self.started = time.perf_counter() + self.timings_ms: Dict[str, float] = {} + + def measure(self, stage: str, action: Callable[[], T]) -> T: + started = time.perf_counter() + try: + return action() + finally: + self.timings_ms[stage] = round( + (time.perf_counter() - started) * 1000.0, + 1, + ) + + def finish( + self, + *, + authenticated: Optional[bool], + outcome: str, + status_code: int, + subscription_active: Optional[bool], + ) -> None: + self.timings_ms["total"] = round( + (time.perf_counter() - self.started) * 1000.0, + 1, + ) + server_timing = ", ".join( + f"backend_{stage};dur={max(0.0, duration):.1f}" + for stage, duration in self.timings_ms.items() + ) + self.request.state.auth_me_server_timing = server_timing + _log_auth_me_timing( + authenticated=authenticated, + outcome=outcome, + status_code=status_code, + subscription_active=subscription_active, + timings_ms=self.timings_ms, + ) + + +def _log_auth_me_timing( + *, + authenticated: Optional[bool], + outcome: str, + status_code: int, + subscription_active: Optional[bool], + timings_ms: Dict[str, float], +) -> None: + logger.info( + "auth_me_timing outcome={} status_code={} authenticated={} " + "subscription_active={} timings_ms={}", + outcome, + status_code, + authenticated, + subscription_active, + timings_ms, + ) + + def _require_auth_identity_without_subscription_gate(request: Request) -> Dict[str, str]: request.state.skip_subscription_gate = True legacy_routes._assert_entitlement(request) @@ -27,180 +93,253 @@ def _subscription_row_is_trial(row: Any) -> bool: def get_auth_me_payload(request: Request) -> Dict[str, Any]: - request.state.skip_subscription_gate = True - legacy_routes._assert_entitlement(request) - if not str(getattr(request.state, "auth_user_id", "") or "").strip(): - legacy_routes._bind_optional_supabase_identity(request) + timer = _AuthMeTimer(request) + authenticated_for_log: Optional[bool] = None + outcome = "ok" + status_code = 200 + subscription_active_for_log: Optional[bool] = None - user_id = getattr(request.state, "auth_user_id", None) - email = getattr(request.state, "auth_email", None) - subscription_required = bool( - legacy_routes.SUPABASE_ENTITLEMENT.enabled - and legacy_routes.SUPABASE_ENTITLEMENT.require_subscription - ) - subscription_active = None - subscription_plan_code = None - subscription_source = None - subscription_is_trial = False - subscription_starts_at = None - subscription_expires_at = None - subscription_total_expires_at = None - subscription_queued_days = 0 - subscription_queued_count = 0 - referral = None - - if legacy_routes.SUPABASE_ENTITLEMENT.enabled and user_id: - try: - legacy_routes.SUPABASE_ENTITLEMENT.ensure_signup_trial(user_id, email) - try: - subscription_window = legacy_routes.SUPABASE_ENTITLEMENT.get_subscription_window( - user_id, - respect_requirement=False, - bypass_cache=True, - unknown_on_error=True, - ) - except TypeError: - subscription_window = legacy_routes.SUPABASE_ENTITLEMENT.get_subscription_window( - user_id, - respect_requirement=False, - ) - latest_subscription = None - latest_known_subscription = None - subscription_window_unknown = ( - isinstance(subscription_window, dict) - and subscription_window.get("unknown") is True + try: + request.state.skip_subscription_gate = True + timer.measure("assert_entitlement", lambda: legacy_routes._assert_entitlement(request)) + if not str(getattr(request.state, "auth_user_id", "") or "").strip(): + timer.measure( + "bind_identity", + lambda: legacy_routes._bind_optional_supabase_identity(request), ) - subscription_window_known = ( - isinstance(subscription_window, dict) - and not subscription_window_unknown - ) - if subscription_window_known: - current_subscription = subscription_window.get("current") - if isinstance(current_subscription, dict): - latest_subscription = current_subscription - rows = subscription_window.get("rows") - if not latest_subscription and isinstance(rows, list): - latest_known_subscription = next( - (row for row in rows if isinstance(row, dict)), - None, - ) - if ( - not latest_subscription - and not latest_known_subscription - and not subscription_window_unknown - and not subscription_window_known - and not subscription_required - ): - latest_subscription = ( - legacy_routes.SUPABASE_ENTITLEMENT.get_latest_active_subscription( - user_id, - respect_requirement=False, - ) - ) - subscription_active = ( - None if subscription_window_unknown else bool(latest_subscription) - ) - if ( - subscription_required - and subscription_active is False - ): - raise HTTPException(status_code=403, detail="Subscription required") - - if not subscription_window_unknown and not latest_known_subscription: - latest_known_subscription = latest_subscription - if not subscription_window_unknown and not latest_known_subscription: - latest_known_subscription = ( - legacy_routes.SUPABASE_ENTITLEMENT.get_latest_subscription_any_status( - user_id - ) - ) - if isinstance(latest_subscription, dict): - subscription_plan_code = latest_subscription.get("plan_code") - subscription_source = latest_subscription.get("source") - subscription_is_trial = _subscription_row_is_trial(latest_subscription) - subscription_starts_at = latest_subscription.get("starts_at") - subscription_expires_at = latest_subscription.get("expires_at") - elif isinstance(latest_known_subscription, dict): - subscription_plan_code = latest_known_subscription.get("plan_code") - subscription_source = latest_known_subscription.get("source") - subscription_is_trial = _subscription_row_is_trial(latest_known_subscription) - subscription_starts_at = latest_known_subscription.get("starts_at") - subscription_expires_at = latest_known_subscription.get("expires_at") - if subscription_window_known: - subscription_total_expires_at = subscription_window.get("total_expires_at") - subscription_queued_days = int(subscription_window.get("queued_days") or 0) - subscription_queued_count = int(subscription_window.get("queued_count") or 0) - referral = legacy_routes.SUPABASE_ENTITLEMENT.get_referral_summary(user_id) - except HTTPException: - raise - except Exception: - if subscription_required: - raise HTTPException(status_code=403, detail="Subscription required") - subscription_active = None - subscription_plan_code = None - subscription_source = None - subscription_is_trial = False - subscription_starts_at = None - subscription_expires_at = None - subscription_total_expires_at = None - subscription_queued_days = 0 - subscription_queued_count = 0 - referral = None - - points = legacy_routes._resolve_auth_points(request) - weekly_profile = legacy_routes._resolve_weekly_profile(request) - telegram_pricing = None - if user_id: - try: - pricing = TelegramGroupPricing() - if pricing.configured: - linked = DBManager().get_user_by_supabase_user_id(user_id) - telegram_id = ( - int(linked.get("telegram_id") or 0) - if isinstance(linked, dict) - else 0 - ) - telegram_pricing = pricing.resolve_price_for_telegram_id( - telegram_id or None - ) - except Exception: - telegram_pricing = None - - return { - "authenticated": bool(user_id), - "user_id": user_id, - "email": email, - "points": points, - "weekly_points": weekly_profile["weekly_points"], - "weekly_rank": weekly_profile["weekly_rank"], - "entitlement_mode": ( - "supabase_required" - if legacy_routes.SUPABASE_ENTITLEMENT.enabled - and legacy_routes._SUPABASE_AUTH_REQUIRED - else "supabase_optional" - if legacy_routes.SUPABASE_ENTITLEMENT.enabled - else "legacy_token" - if legacy_routes._ENTITLEMENT_GUARD_ENABLED - else "disabled" - ), - "auth_required": bool( + user_id = getattr(request.state, "auth_user_id", None) + email = getattr(request.state, "auth_email", None) + authenticated_for_log = bool(user_id) + subscription_required = bool( legacy_routes.SUPABASE_ENTITLEMENT.enabled - and legacy_routes._SUPABASE_AUTH_REQUIRED - ), - "subscription_required": subscription_required, - "subscription_active": subscription_active, - "subscription_plan_code": subscription_plan_code, - "subscription_source": subscription_source, - "subscription_is_trial": subscription_is_trial, - "subscription_starts_at": subscription_starts_at, - "subscription_expires_at": subscription_expires_at, - "subscription_total_expires_at": subscription_total_expires_at, - "subscription_queued_days": subscription_queued_days, - "subscription_queued_count": subscription_queued_count, - "telegram_pricing": telegram_pricing, - "referral": referral, - } + and legacy_routes.SUPABASE_ENTITLEMENT.require_subscription + ) + subscription_active = None + subscription_plan_code = None + subscription_source = None + subscription_is_trial = False + subscription_starts_at = None + subscription_expires_at = None + subscription_total_expires_at = None + subscription_queued_days = 0 + subscription_queued_count = 0 + referral = None + + if legacy_routes.SUPABASE_ENTITLEMENT.enabled and user_id: + try: + timer.measure( + "ensure_signup_trial", + lambda: legacy_routes.SUPABASE_ENTITLEMENT.ensure_signup_trial( + user_id, + email, + ), + ) + try: + subscription_window = timer.measure( + "subscription_window", + lambda: legacy_routes.SUPABASE_ENTITLEMENT.get_subscription_window( + user_id, + respect_requirement=False, + bypass_cache=True, + unknown_on_error=True, + ), + ) + except TypeError: + subscription_window = timer.measure( + "subscription_window", + lambda: legacy_routes.SUPABASE_ENTITLEMENT.get_subscription_window( + user_id, + respect_requirement=False, + ), + ) + latest_subscription = None + latest_known_subscription = None + subscription_window_unknown = ( + isinstance(subscription_window, dict) + and subscription_window.get("unknown") is True + ) + subscription_window_known = ( + isinstance(subscription_window, dict) + and not subscription_window_unknown + ) + if subscription_window_known: + current_subscription = subscription_window.get("current") + if isinstance(current_subscription, dict): + latest_subscription = current_subscription + rows = subscription_window.get("rows") + if not latest_subscription and isinstance(rows, list): + latest_known_subscription = next( + (row for row in rows if isinstance(row, dict)), + None, + ) + if ( + not latest_subscription + and not latest_known_subscription + and not subscription_window_unknown + and not subscription_window_known + and not subscription_required + ): + latest_subscription = timer.measure( + "latest_active_subscription", + lambda: legacy_routes.SUPABASE_ENTITLEMENT.get_latest_active_subscription( + user_id, + respect_requirement=False, + ), + ) + + subscription_active = ( + None if subscription_window_unknown else bool(latest_subscription) + ) + subscription_active_for_log = subscription_active + if subscription_required and subscription_active is False: + raise HTTPException(status_code=403, detail="Subscription required") + + if not subscription_window_unknown and not latest_known_subscription: + latest_known_subscription = latest_subscription + if not subscription_window_unknown and not latest_known_subscription: + latest_known_subscription = timer.measure( + "latest_subscription_history", + lambda: legacy_routes.SUPABASE_ENTITLEMENT.get_latest_subscription_any_status( + user_id + ), + ) + if isinstance(latest_subscription, dict): + subscription_plan_code = latest_subscription.get("plan_code") + subscription_source = latest_subscription.get("source") + subscription_is_trial = _subscription_row_is_trial( + latest_subscription + ) + subscription_starts_at = latest_subscription.get("starts_at") + subscription_expires_at = latest_subscription.get("expires_at") + elif isinstance(latest_known_subscription, dict): + subscription_plan_code = latest_known_subscription.get("plan_code") + subscription_source = latest_known_subscription.get("source") + subscription_is_trial = _subscription_row_is_trial( + latest_known_subscription + ) + subscription_starts_at = latest_known_subscription.get("starts_at") + subscription_expires_at = latest_known_subscription.get("expires_at") + if subscription_window_known: + subscription_total_expires_at = subscription_window.get( + "total_expires_at" + ) + subscription_queued_days = int( + subscription_window.get("queued_days") or 0 + ) + subscription_queued_count = int( + subscription_window.get("queued_count") or 0 + ) + referral = timer.measure( + "referral_summary", + lambda: legacy_routes.SUPABASE_ENTITLEMENT.get_referral_summary( + user_id + ), + ) + except HTTPException: + raise + except Exception: + if subscription_required: + raise HTTPException(status_code=403, detail="Subscription required") + subscription_active = None + subscription_active_for_log = None + subscription_plan_code = None + subscription_source = None + subscription_is_trial = False + subscription_starts_at = None + subscription_expires_at = None + subscription_total_expires_at = None + subscription_queued_days = 0 + subscription_queued_count = 0 + referral = None + + points = timer.measure( + "auth_points", + lambda: legacy_routes._resolve_auth_points(request), + ) + weekly_profile = timer.measure( + "weekly_profile", + lambda: legacy_routes._resolve_weekly_profile(request), + ) + + def resolve_telegram_pricing() -> Any: + if not user_id: + return None + pricing = TelegramGroupPricing() + if not pricing.configured: + return None + linked = DBManager().get_user_by_supabase_user_id(user_id) + telegram_id = ( + int(linked.get("telegram_id") or 0) if isinstance(linked, dict) else 0 + ) + return pricing.resolve_price_for_telegram_id(telegram_id or None) + + telegram_pricing = None + if user_id: + try: + telegram_pricing = timer.measure( + "telegram_pricing", + resolve_telegram_pricing, + ) + except Exception: + telegram_pricing = None + + payload = { + "authenticated": bool(user_id), + "user_id": user_id, + "email": email, + "points": points, + "weekly_points": weekly_profile["weekly_points"], + "weekly_rank": weekly_profile["weekly_rank"], + "entitlement_mode": ( + "supabase_required" + if legacy_routes.SUPABASE_ENTITLEMENT.enabled + and legacy_routes._SUPABASE_AUTH_REQUIRED + else "supabase_optional" + if legacy_routes.SUPABASE_ENTITLEMENT.enabled + else "legacy_token" + if legacy_routes._ENTITLEMENT_GUARD_ENABLED + else "disabled" + ), + "auth_required": bool( + legacy_routes.SUPABASE_ENTITLEMENT.enabled + and legacy_routes._SUPABASE_AUTH_REQUIRED + ), + "subscription_required": subscription_required, + "subscription_active": subscription_active, + "subscription_plan_code": subscription_plan_code, + "subscription_source": subscription_source, + "subscription_is_trial": subscription_is_trial, + "subscription_starts_at": subscription_starts_at, + "subscription_expires_at": subscription_expires_at, + "subscription_total_expires_at": subscription_total_expires_at, + "subscription_queued_days": subscription_queued_days, + "subscription_queued_count": subscription_queued_count, + "telegram_pricing": telegram_pricing, + "referral": referral, + } + authenticated_for_log = bool(payload["authenticated"]) + subscription_active_for_log = ( + payload["subscription_active"] + if isinstance(payload["subscription_active"], bool) + else None + ) + return payload + except HTTPException as exc: + outcome = f"http_{exc.status_code}" + status_code = exc.status_code + raise + except Exception: + outcome = "exception" + status_code = 500 + raise + finally: + timer.finish( + authenticated=authenticated_for_log, + outcome=outcome, + status_code=status_code, + subscription_active=subscription_active_for_log, + ) def apply_referral_code(request: Request, body: ReferralApplyRequest) -> Dict[str, Any]: