Add auth profile timing instrumentation

2026-05-31 18:27:04 +08:00
parent 46effcd45f
commit a4253c224a
5 changed files with 683 additions and 259 deletions
@@ -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<T>(name: string, action: () => Promise<T>): Promise<T>;
+  measureSync<T>(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<T>(name: string, action: () => Promise<T>) {
+      const stageStartedAt = authMeNowMs();
+      try {
+        return await action();
+      } finally {
+        recordStage(name, stageStartedAt);
+      }
+    },
+    measureSync<T>(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",
+    );
  }
 }

@@ -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",
+  );
+}
@@ -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
@@ -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")
@@ -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]: