From e3a4e596fce1a2c49f5fec43df5305eb0d034419 Mon Sep 17 00:00:00 2001
From: Jeremiah Lowin <153965+jlowin@users.noreply.github.com>
Date: Wed, 31 Dec 2025 13:37:53 -0500
Subject: [PATCH] Add debug logging for OAuth token expiry diagnostics (#2789)

---
 src/fastmcp/server/auth/oauth_proxy.py | 33 +++++++++++++++++++++++++-
 1 file changed, 32 insertions(+), 1 deletion(-)

diff --git a/src/fastmcp/server/auth/oauth_proxy.py b/src/fastmcp/server/auth/oauth_proxy.py
index af5a7dd8b..c19ea013a 100644
--- a/src/fastmcp/server/auth/oauth_proxy.py
+++ b/src/fastmcp/server/auth/oauth_proxy.py
@@ -1221,12 +1221,24 @@ class OAuthProxy(OAuthProvider):
         # - 1 year if no refresh token (likely API-key-style token like GitHub OAuth Apps)
         if "expires_in" in idp_tokens:
             expires_in = int(idp_tokens["expires_in"])
+            logger.debug(
+                "Access token TTL: %d seconds (from IdP expires_in)", expires_in
+            )
         elif self._fallback_access_token_expiry_seconds is not None:
             expires_in = self._fallback_access_token_expiry_seconds
+            logger.debug(
+                "Access token TTL: %d seconds (using configured fallback)", expires_in
+            )
         elif idp_tokens.get("refresh_token"):
             expires_in = DEFAULT_ACCESS_TOKEN_EXPIRY_SECONDS
+            logger.debug(
+                "Access token TTL: %d seconds (default, has refresh token)", expires_in
+            )
         else:
             expires_in = DEFAULT_ACCESS_TOKEN_EXPIRY_NO_REFRESH_SECONDS
+            logger.debug(
+                "Access token TTL: %d seconds (default, no refresh token)", expires_in
+            )
 
         # Calculate refresh token expiry if provided by upstream
         # Some providers include refresh_expires_in, some don't
@@ -1467,10 +1479,21 @@ class OAuthProxy(OAuthProvider):
         # (user override still applies if set)
         if "expires_in" in token_response:
             new_expires_in = int(token_response["expires_in"])
+            logger.debug(
+                "Refreshed access token TTL: %d seconds (from IdP expires_in)",
+                new_expires_in,
+            )
         elif self._fallback_access_token_expiry_seconds is not None:
             new_expires_in = self._fallback_access_token_expiry_seconds
+            logger.debug(
+                "Refreshed access token TTL: %d seconds (using configured fallback)",
+                new_expires_in,
+            )
         else:
             new_expires_in = DEFAULT_ACCESS_TOKEN_EXPIRY_SECONDS
+            logger.debug(
+                "Refreshed access token TTL: %d seconds (default)", new_expires_in
+            )
         upstream_token_set.access_token = token_response["access_token"]
         upstream_token_set.expires_at = time.time() + new_expires_in
 
@@ -1622,7 +1645,10 @@ class OAuthProxy(OAuthProvider):
             # 2. Look up upstream token via JTI mapping
             jti_mapping = await self._jti_mapping_store.get(key=jti)
             if not jti_mapping:
-                logger.debug("JTI mapping not found: %s", jti)
+                logger.info(
+                    "JTI mapping not found (token may have expired): jti=%s...",
+                    jti[:16],
+                )
                 return None
 
             upstream_token_set = await self._upstream_token_store.get(
@@ -1865,6 +1891,11 @@ class OAuthProxy(OAuthProvider):
                 logger.debug(
                     f"Successfully exchanged IdP code for tokens (transaction: {txn_id}, PKCE: {bool(proxy_code_verifier)})"
                 )
+                logger.debug(
+                    "IdP token response: expires_in=%s, has_refresh_token=%s",
+                    idp_tokens.get("expires_in"),
+                    "refresh_token" in idp_tokens,
+                )
 
             except Exception as e:
                 logger.error("IdP token exchange failed: %s", e)