diff --git a/CHANGELOG.md b/CHANGELOG.md index f074701..561e354 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -25,6 +25,14 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - **Login page footer**: now includes Privacy Policy and Terms of Service links alongside the existing Impressum / Datenschutz links. - **Register page consent text**: "By creating an account you agree to our Terms of Service and Privacy Policy" notice added below the sign-up form. - **Datenschutz cross-link**: German privacy page now links to the English `/privacy` page in section 2 and the bottom footer bar. +- **Proactive Gmail token refresh task** (`refresh_gmail_tokens`): new Celery Beat task running every 45 minutes that refreshes any Gmail access token expiring within the next 30 minutes. Tokens with unknown expiry are also refreshed. Revoked tokens are immediately detected, marked invalid, and the user is notified. This prevents the first email delivery after a long idle period from triggering a synchronous in-band token exchange. +- **In-depth OAuth logging**: added `DEBUG`/`INFO`/`WARNING`/`ERROR` log lines at every significant step of the OAuth flow across `auth_service.py`, `auth.py`, `providers.py`, and `gmail_service.py`. Logged events include: authorize-URL generation, code exchange (with scopes and `has_refresh_token` flag), user-profile fetch, API access verification, credential create/update/delete, label updates, debug-email injection, auto-refresh detection, and proactive refresh. Token values are never logged; only metadata (email, expiry, boolean presence, scopes) is recorded. + +### Changed + +- **`GmailAuthError` exception class** added to `gmail_service.py` (subclass of `GmailInjectionError`): raised specifically when `google.auth.exceptions.RefreshError` is caught (i.e. the refresh token was revoked or invalid). This gives callers a typed signal distinct from ordinary API errors. +- **Improved error logging** for Gmail token failures: log messages now include the token expiry timestamp and distinguish between "refresh token revoked" and "API HTTP error" scenarios, making it much easier to diagnose authentication problems in the application logs. +- **Structured exception handling** in `process_mail_account`: `GmailAuthError` is now caught separately from generic exceptions so that revocation is detected reliably even when the error does not contain "401", "403", or "invalid_grant" in its string representation. ## v0.6.5 (2026-04-07) @@ -526,6 +534,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - **Duration display rounding bug**: `formatDuration` in the frontend Processing Logs page now uses `Math.floor` instead of `Math.round` for the seconds component, eliminating the "60s" artefact that appeared for durations very close to a whole minute boundary. +- **Frontend dependency conflict**: Bumped `react` from `19.2.4` to `19.2.5` in `frontend/package.json` to match `react-dom@19.2.5`, resolving the `ERESOLVE` peer-dependency conflict that broke `npm ci`. ### Changed - **Decoupled Gmail permissions from Google Sign-In**: The "Sign in with Google" OAuth flow now only requests basic profile scopes (`openid`, `email`, `profile`) instead of also requesting Gmail API scopes (`gmail.insert`, `gmail.labels`, `gmail.readonly`). Users can grant Gmail access separately via the "Connect Gmail" button in Settings. This results in a simpler, permission-free login experience. diff --git a/backend/app/api/v1/endpoints/auth.py b/backend/app/api/v1/endpoints/auth.py index a6420aa..ac9ae2d 100644 --- a/backend/app/api/v1/endpoints/auth.py +++ b/backend/app/api/v1/endpoints/auth.py @@ -182,6 +182,10 @@ async def google_oauth( Authenticate with Google OAuth2. Exchange authorization code for access token and user info. """ + logger.debug( + "OAuth [Google sign-in]: callback received (redirect_uri=%s)", + auth_request.redirect_uri, + ) # Get user info from Google user_info = await oauth_service.get_google_user_info( @@ -190,6 +194,10 @@ async def google_oauth( if not user_info.get("verified_email"): OAUTH_CALLBACKS_TOTAL.labels(provider="google", status="error").inc() + logger.warning( + "OAuth [Google sign-in]: rejecting unverified email=%s", + user_info.get("email"), + ) raise HTTPException( status_code=status.HTTP_400_BAD_REQUEST, detail="Email not verified with Google", @@ -209,6 +217,11 @@ async def google_oauth( if not user.google_id: user.google_id = google_id # type: ignore[assignment] user.oauth_provider = "google" # type: ignore[assignment] + logger.info( + "OAuth [Google sign-in]: linked Google ID to existing account " + "(email=%s)", + email, + ) # Update last login user.last_login_at = datetime.now(timezone.utc) # type: ignore[assignment] @@ -249,6 +262,10 @@ async def google_oauth( # Create tokens tokens = oauth_service.create_tokens_for_user(user) + logger.debug( + "OAuth [Google sign-in]: sign-in complete, JWT tokens issued for user_id=%s", + user.id, + ) OAUTH_CALLBACKS_TOTAL.labels(provider="google", status="success").inc() return tokens @@ -257,6 +274,12 @@ async def google_oauth( @router.get("/google/authorize-url") async def get_google_authorize_url(redirect_uri: str): """Get Google OAuth2 authorization URL for sign-in (profile scopes only).""" + logger.debug( + "OAuth [Google sign-in]: authorization URL requested " + "(redirect_uri=%s, scopes=%s)", + redirect_uri, + GOOGLE_LOGIN_SCOPES, + ) scope = urlquote(" ".join(GOOGLE_LOGIN_SCOPES)) auth_url = ( "https://accounts.google.com/o/oauth2/v2/auth" diff --git a/backend/app/api/v1/endpoints/providers.py b/backend/app/api/v1/endpoints/providers.py index 5d814db..99de832 100644 --- a/backend/app/api/v1/endpoints/providers.py +++ b/backend/app/api/v1/endpoints/providers.py @@ -217,6 +217,13 @@ async def save_gmail_credential( Save Gmail API OAuth2 credentials for the current user. These are used to inject emails directly into Gmail via the API. """ + logger.debug( + "OAuth [Gmail credential]: verifying credentials for user_id=%s " + "(gmail=%s, has_refresh_token=%s)", + current_user.id, + credential_in.gmail_email, + bool(credential_in.refresh_token), + ) # Verify the credentials work gmail_service = GmailService( access_token=credential_in.access_token, @@ -227,6 +234,12 @@ async def save_gmail_credential( is_valid = await gmail_service.verify_access() if not is_valid: + logger.warning( + "OAuth [Gmail credential]: credential verification failed for user_id=%s " + "(gmail=%s)", + current_user.id, + credential_in.gmail_email, + ) raise HTTPException( status_code=status.HTTP_400_BAD_REQUEST, detail="Gmail API credentials are invalid or expired", @@ -258,6 +271,11 @@ async def save_gmail_credential( existing.last_verified_at = datetime.now(timezone.utc) # type: ignore[assignment] await db.commit() await db.refresh(existing) + logger.info( + "OAuth [Gmail credential]: updated credential for user_id=%s (gmail=%s)", + current_user.id, + credential_in.gmail_email, + ) return existing else: # Create new @@ -273,6 +291,11 @@ async def save_gmail_credential( db.add(credential) await db.commit() await db.refresh(credential) + logger.info( + "OAuth [Gmail credential]: created new credential for user_id=%s (gmail=%s)", + current_user.id, + credential_in.gmail_email, + ) return credential @@ -313,6 +336,11 @@ async def delete_gmail_credential( detail="No Gmail credentials found", ) + logger.info( + "OAuth [Gmail credential]: deleting credential for user_id=%s (gmail=%s)", + current_user.id, + credential.gmail_email, + ) await db.delete(credential) await db.commit() @@ -335,9 +363,17 @@ async def update_gmail_import_labels( detail="No Gmail credentials found. Connect Gmail first.", ) + validated = _validated_import_label_templates(labels_in.import_label_templates) + logger.info( + "OAuth [Gmail credential]: updating import labels for user_id=%s " + "(gmail=%s, labels=%s)", + current_user.id, + credential.gmail_email, + validated, + ) credential.scopes = build_gmail_credential_scopes( # type: ignore[assignment] extract_granted_scopes(credential.scopes), - _validated_import_label_templates(labels_in.import_label_templates), + validated, ) await db.commit() await db.refresh(credential) @@ -363,6 +399,13 @@ async def get_gmail_authorize_url( detail="Google OAuth2 is not configured on this server.", ) + logger.info( + "OAuth [Gmail connect]: authorization URL requested for user_id=%s " + "(redirect_uri=%s, scopes=%s)", + current_user.id, + redirect_uri, + GMAIL_API_SCOPES, + ) scope = urlquote(" ".join(GMAIL_API_SCOPES)) url = ( "https://accounts.google.com/o/oauth2/v2/auth" @@ -393,6 +436,10 @@ async def send_gmail_debug_email( Useful for verifying that Gmail API delivery is working end-to-end without requiring an active mail-account polling cycle. """ + logger.info( + "OAuth [Gmail debug-email]: debug injection requested by user_id=%s", + current_user.id, + ) result = await db.execute( select(GmailCredential).where( GmailCredential.user_id == current_user.id, @@ -402,11 +449,23 @@ async def send_gmail_debug_email( credential = result.scalar_one_or_none() if not credential: + logger.warning( + "OAuth [Gmail debug-email]: no valid credential found for user_id=%s", + current_user.id, + ) raise HTTPException( status_code=status.HTTP_400_BAD_REQUEST, detail="No valid Gmail credentials found. Connect Gmail first.", ) + logger.debug( + "OAuth [Gmail debug-email]: using credential for user_id=%s (gmail=%s, " + "token_expiry=%s, has_refresh_token=%s)", + current_user.id, + credential.gmail_email, + credential.token_expiry, + bool(credential.encrypted_refresh_token), + ) access_token = decrypt_credential(credential.encrypted_access_token) # type: ignore[arg-type] refresh_token = ( decrypt_credential(credential.encrypted_refresh_token) # type: ignore[arg-type] @@ -427,6 +486,12 @@ async def send_gmail_debug_email( import_label_templates=credential.import_label_templates, ) except GmailInjectionError as exc: + logger.error( + "OAuth [Gmail debug-email]: injection failed for user_id=%s (gmail=%s): %s", + current_user.id, + credential.gmail_email, + exc, + ) raise HTTPException( status_code=status.HTTP_502_BAD_GATEWAY, detail=f"Gmail injection failed: {exc}", @@ -435,6 +500,12 @@ async def send_gmail_debug_email( # Persist refreshed token if the google-auth library renewed it refreshed = gmail_service.get_refreshed_token() if refreshed: + logger.debug( + "OAuth [Gmail debug-email]: access token was auto-refreshed for " + "user_id=%s; persisting new expiry=%s", + current_user.id, + refreshed.get("expiry"), + ) credential.encrypted_access_token = encrypt_credential( # type: ignore[assignment] refreshed["access_token"] ) @@ -442,6 +513,13 @@ async def send_gmail_debug_email( credential.token_expiry = refreshed["expiry"] # type: ignore[assignment] await db.commit() + logger.info( + "OAuth [Gmail debug-email]: injection succeeded for user_id=%s (gmail=%s, " + "message_id=%s)", + current_user.id, + credential.gmail_email, + inject_result.get("message_id"), + ) return { "message": "Debug email injected successfully", "message_id": inject_result.get("message_id"), @@ -482,7 +560,18 @@ async def gmail_oauth_callback( detail="Google OAuth2 is not configured on this server.", ) + logger.info( + "OAuth [Gmail connect]: callback received for user_id=%s (redirect_uri=%s)", + current_user.id, + callback_in.redirect_uri, + ) + # Exchange code for tokens + logger.debug( + "OAuth [Gmail connect]: exchanging authorization code for tokens " + "(user_id=%s)", + current_user.id, + ) async with httpx.AsyncClient() as client: token_resp = await client.post( "https://oauth2.googleapis.com/token", @@ -496,7 +585,13 @@ async def gmail_oauth_callback( ) if token_resp.status_code != 200: - logger.error(f"Gmail token exchange failed: {token_resp.text}") + logger.error( + "OAuth [Gmail connect]: token exchange failed for user_id=%s " + "(status=%s, body=%s)", + current_user.id, + token_resp.status_code, + token_resp.text, + ) raise HTTPException( status_code=status.HTTP_400_BAD_REQUEST, detail="Failed to exchange authorization code with Google.", @@ -506,13 +601,41 @@ async def gmail_oauth_callback( access_token: Optional[str] = token_data.get("access_token") refresh_token: Optional[str] = token_data.get("refresh_token") + logger.debug( + "OAuth [Gmail connect]: token exchange succeeded for user_id=%s — " + "scopes=%s, has_refresh_token=%s, expires_in=%s", + current_user.id, + token_data.get("scope", ""), + bool(refresh_token), + token_data.get("expires_in"), + ) + if not access_token: + logger.error( + "OAuth [Gmail connect]: Google response contained no access_token " + "for user_id=%s (keys_present=%s)", + current_user.id, + list(token_data.keys()), + ) raise HTTPException( status_code=status.HTTP_400_BAD_REQUEST, detail="Google did not return an access token.", ) + if not refresh_token: + logger.warning( + "OAuth [Gmail connect]: Google did not return a refresh_token for " + "user_id=%s — token refresh may fail after 1 hour. " + "This can happen if the user has previously authorised the app and " + "access_type=offline was not honoured.", + current_user.id, + ) + # Fetch the Gmail email address to associate with this credential + logger.debug( + "OAuth [Gmail connect]: fetching Google profile for user_id=%s", + current_user.id, + ) async with httpx.AsyncClient() as client: profile_resp = await client.get( "https://www.googleapis.com/oauth2/v2/userinfo", @@ -522,6 +645,20 @@ async def gmail_oauth_callback( gmail_email = current_user.email # fallback if profile_resp.status_code == 200: gmail_email = profile_resp.json().get("email", current_user.email) + logger.debug( + "OAuth [Gmail connect]: Google profile retrieved for user_id=%s " + "(gmail=%s)", + current_user.id, + gmail_email, + ) + else: + logger.warning( + "OAuth [Gmail connect]: could not fetch Google profile for user_id=%s " + "(status=%s); falling back to account email=%s", + current_user.id, + profile_resp.status_code, + current_user.email, + ) # Calculate token expiry (Google access tokens last 1 hour) token_expiry = datetime.now(timezone.utc) + timedelta( @@ -529,6 +666,11 @@ async def gmail_oauth_callback( ) # Verify the credentials actually work with the Gmail API + logger.debug( + "OAuth [Gmail connect]: verifying Gmail API access for user_id=%s (gmail=%s)", + current_user.id, + gmail_email, + ) gmail_service = GmailService( access_token=access_token, refresh_token=refresh_token, @@ -537,6 +679,12 @@ async def gmail_oauth_callback( ) is_valid = await gmail_service.verify_access() if not is_valid: + logger.error( + "OAuth [Gmail connect]: Gmail API access verification failed for " + "user_id=%s (gmail=%s) — ensure gmail.insert scope was granted", + current_user.id, + gmail_email, + ) raise HTTPException( status_code=status.HTTP_400_BAD_REQUEST, detail="Obtained tokens but could not verify Gmail API access. " @@ -566,6 +714,15 @@ async def gmail_oauth_callback( existing.last_verified_at = datetime.now(timezone.utc) # type: ignore[assignment] await db.commit() await db.refresh(existing) + logger.info( + "OAuth [Gmail connect]: updated credential for user_id=%s " + "(gmail=%s, token_expiry=%s, has_refresh_token=%s, scopes=%s)", + current_user.id, + gmail_email, + token_expiry, + bool(encrypted_refresh), + token_data.get("scope", ""), + ) return existing else: credential = GmailCredential( @@ -581,4 +738,13 @@ async def gmail_oauth_callback( db.add(credential) await db.commit() await db.refresh(credential) + logger.info( + "OAuth [Gmail connect]: created new credential for user_id=%s " + "(gmail=%s, token_expiry=%s, has_refresh_token=%s, scopes=%s)", + current_user.id, + gmail_email, + token_expiry, + bool(encrypted_refresh), + token_data.get("scope", ""), + ) return credential diff --git a/backend/app/services/auth_service.py b/backend/app/services/auth_service.py index de3458e..fbf5b43 100644 --- a/backend/app/services/auth_service.py +++ b/backend/app/services/auth_service.py @@ -49,6 +49,11 @@ class OAuthService: """ try: # Exchange code for token + logger.debug( + "OAuth [Google sign-in]: exchanging authorization code for tokens " + "(redirect_uri=%s)", + redirect_uri, + ) async with httpx.AsyncClient() as client: token_response = await client.post( "https://oauth2.googleapis.com/token", @@ -62,7 +67,12 @@ class OAuthService: ) if token_response.status_code != 200: - logger.error(f"Google token exchange failed: {token_response.text}") + logger.error( + "OAuth [Google sign-in]: token exchange failed " + "(status=%s, body=%s)", + token_response.status_code, + token_response.text, + ) raise HTTPException( status_code=status.HTTP_400_BAD_REQUEST, detail="Failed to exchange authorization code", @@ -72,12 +82,26 @@ class OAuthService: access_token = token_data.get("access_token") if not access_token: + logger.error( + "OAuth [Google sign-in]: token exchange response contained " + "no access_token (keys_present=%s)", + list(token_data.keys()), + ) raise HTTPException( status_code=status.HTTP_400_BAD_REQUEST, detail="No access token received", ) + logger.debug( + "OAuth [Google sign-in]: token exchange succeeded — " + "scopes=%s, has_refresh_token=%s, expires_in=%s", + token_data.get("scope", ""), + bool(token_data.get("refresh_token")), + token_data.get("expires_in"), + ) + # Get user info + logger.debug("OAuth [Google sign-in]: fetching Google user profile") user_info_response = await client.get( "https://www.googleapis.com/oauth2/v2/userinfo", headers={"Authorization": f"Bearer {access_token}"}, @@ -85,7 +109,10 @@ class OAuthService: if user_info_response.status_code != 200: logger.error( - f"Google user info fetch failed: {user_info_response.text}" + "OAuth [Google sign-in]: user-info fetch failed " + "(status=%s, body=%s)", + user_info_response.status_code, + user_info_response.text, ) raise HTTPException( status_code=status.HTTP_400_BAD_REQUEST, @@ -93,6 +120,12 @@ class OAuthService: ) user_info = user_info_response.json() + logger.debug( + "OAuth [Google sign-in]: user profile retrieved — " + "email=%s, verified=%s", + user_info.get("email"), + user_info.get("verified_email"), + ) return { "email": user_info.get("email"), @@ -109,7 +142,7 @@ class OAuthService: except HTTPException: raise except Exception as e: - logger.error(f"OAuth error: {e}") + logger.error("OAuth [Google sign-in]: unexpected error: %s", e) raise HTTPException( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, detail="OAuth authentication failed", @@ -126,6 +159,7 @@ class OAuthService: Returns: Dict with access_token, refresh_token, and token_type """ + logger.debug("OAuth: issuing application JWT tokens for user_id=%s", user.id) access_token = create_access_token(data={"sub": str(user.id)}) refresh_token = create_refresh_token(data={"sub": str(user.id)}) diff --git a/backend/app/services/gmail_service.py b/backend/app/services/gmail_service.py index e848ae2..3fde4c7 100644 --- a/backend/app/services/gmail_service.py +++ b/backend/app/services/gmail_service.py @@ -11,11 +11,13 @@ import base64 import logging import textwrap import time -from datetime import datetime, timezone +from datetime import datetime, timedelta, timezone from email.mime.text import MIMEText from email.utils import format_datetime from typing import Optional, Dict, Any +import google.auth.exceptions +from google.auth.transport.requests import Request as GoogleAuthRequest from google.oauth2.credentials import Credentials from googleapiclient.discovery import build from googleapiclient.errors import HttpError @@ -43,6 +45,12 @@ class GmailInjectionError(Exception): pass +class GmailAuthError(GmailInjectionError): + """Raised when Gmail OAuth2 authentication fails (token expired or revoked).""" + + pass + + class GmailService: """ Service for injecting emails into Gmail via the Gmail API. @@ -79,6 +87,13 @@ class GmailService: scopes=GMAIL_SCOPES, ) self._service = None + logger.debug( + "OAuth [GmailService]: initialized — has_refresh_token=%s, " + "has_client_id=%s, has_client_secret=%s", + bool(refresh_token), + bool(client_id), + bool(client_secret), + ) @property def service(self): @@ -161,6 +176,16 @@ class GmailService: logger.error(error_msg) # Surface 401 so callers can mark credentials as invalid raise GmailInjectionError(error_msg) + except google.auth.exceptions.RefreshError as e: + _dur = time.perf_counter() - _start + GMAIL_API_REQUESTS_TOTAL.labels(operation="inject", status="error").inc() + GMAIL_API_DURATION_SECONDS.labels(operation="inject").observe(_dur) + error_msg = ( + f"Gmail token refresh failed — the refresh token may have been revoked. " + f"The user must re-authorise. Detail: {e}" + ) + logger.error(error_msg) + raise GmailAuthError(error_msg) except Exception as e: _dur = time.perf_counter() - _start GMAIL_API_REQUESTS_TOTAL.labels(operation="inject", status="error").inc() @@ -190,6 +215,15 @@ class GmailService: email = result.get("emailAddress", "unknown") logger.info(f"Gmail API access verified for: {email}") return True + except google.auth.exceptions.RefreshError as e: + _dur = time.perf_counter() - _start + GMAIL_API_REQUESTS_TOTAL.labels(operation="verify", status="error").inc() + GMAIL_API_DURATION_SECONDS.labels(operation="verify").observe(_dur) + logger.error( + f"Gmail token refresh failed during access verification — " + f"refresh token may be revoked. Detail: {e}" + ) + return False except Exception as e: _dur = time.perf_counter() - _start GMAIL_API_REQUESTS_TOTAL.labels(operation="verify", status="error").inc() @@ -217,7 +251,21 @@ class GmailService: operation="get_profile", status="success" ).inc() GMAIL_API_DURATION_SECONDS.labels(operation="get_profile").observe(_dur) - return result.get("emailAddress") + email = result.get("emailAddress") + logger.debug("OAuth [GmailService]: fetched email address=%s", email) + return email + except google.auth.exceptions.RefreshError as e: + _dur = time.perf_counter() - _start + GMAIL_API_REQUESTS_TOTAL.labels( + operation="get_profile", status="error" + ).inc() + GMAIL_API_DURATION_SECONDS.labels(operation="get_profile").observe(_dur) + logger.error( + "OAuth [GmailService]: token refresh failed while fetching email " + "address — refresh token may be revoked. Detail: %s", + e, + ) + return None except Exception as e: _dur = time.perf_counter() - _start GMAIL_API_REQUESTS_TOTAL.labels( @@ -286,6 +334,16 @@ class GmailService: error_msg = f"Gmail API error while managing label '{name}': {e.reason if hasattr(e, 'reason') else str(e)}" logger.error(error_msg) raise GmailInjectionError(error_msg) + except google.auth.exceptions.RefreshError as e: + _dur = time.perf_counter() - _start + GMAIL_API_REQUESTS_TOTAL.labels(operation="get_label", status="error").inc() + GMAIL_API_DURATION_SECONDS.labels(operation="get_label").observe(_dur) + error_msg = ( + f"Gmail token refresh failed while managing label '{name}' — " + f"refresh token may be revoked. Detail: {e}" + ) + logger.error(error_msg) + raise GmailAuthError(error_msg) except Exception as e: _dur = time.perf_counter() - _start GMAIL_API_REQUESTS_TOTAL.labels(operation="get_label", status="error").inc() @@ -376,6 +434,78 @@ class GmailService: return label_ids + def is_token_expiring_soon(self, within_minutes: int = 30) -> bool: + """ + Return True if the access token has already expired or will expire + within *within_minutes* minutes. + + When ``credentials.expiry`` is None the expiry is unknown, which is + treated as expiring soon so a proactive refresh is performed. + + Args: + within_minutes: Threshold in minutes before which a token is + considered "expiring soon". + + Returns: + True if the token needs refreshing, False otherwise. + """ + if self.credentials.expiry is None: + return True + threshold = datetime.now(timezone.utc) + timedelta(minutes=within_minutes) + expiry = self.credentials.expiry + # google-auth stores expiry as a naive UTC datetime; make it tz-aware. + if expiry.tzinfo is None: + expiry = expiry.replace(tzinfo=timezone.utc) + return expiry <= threshold + + async def proactive_refresh(self) -> Dict[str, Any]: + """ + Explicitly refresh the access token using the stored refresh token. + + Unlike the lazy refresh that happens automatically during API calls, + this method triggers a refresh regardless of whether the current + access token has expired. Use this from a scheduled task to keep + tokens fresh and to detect revocation early. + + Returns: + Dict with ``access_token`` and ``expiry`` (datetime | None) + representing the newly obtained access token. + + Raises: + GmailAuthError: If the refresh token is missing, has been revoked, + or the refresh request fails for an auth-related reason. + GmailInjectionError: For unexpected non-auth errors. + """ + if not self.credentials.refresh_token: + raise GmailAuthError( + "Cannot refresh: no refresh token stored. " + "Re-authorise Gmail to obtain a new refresh token." + ) + + loop = asyncio.get_event_loop() + try: + await loop.run_in_executor( + None, + lambda: self.credentials.refresh(GoogleAuthRequest()), + ) + GMAIL_TOKEN_REFRESHES_TOTAL.inc() + logger.info( + "Gmail access token refreshed proactively; new expiry: %s", + self.credentials.expiry, + ) + return { + "access_token": self.credentials.token, + "expiry": self.credentials.expiry, + } + except google.auth.exceptions.RefreshError as e: + error_msg = f"Gmail refresh token has been revoked or is invalid — the user must re-authorise. Detail: {e}" + logger.error(error_msg) + raise GmailAuthError(error_msg) + except Exception as e: + raise GmailInjectionError( + f"Unexpected error during Gmail token refresh: {e}" + ) + def get_refreshed_token(self) -> Optional[Dict[str, Any]]: """ Return the current access token and expiry if the token was refreshed @@ -392,6 +522,11 @@ class GmailService: current_token = self.credentials.token if current_token and current_token != self._initial_access_token: GMAIL_TOKEN_REFRESHES_TOTAL.inc() + logger.debug( + "OAuth [GmailService]: access token was auto-refreshed during API " + "call; new expiry=%s", + self.credentials.expiry, + ) return { "access_token": current_token, "expiry": self.credentials.expiry, diff --git a/backend/app/workers/celery_app.py b/backend/app/workers/celery_app.py index 9ae8dc7..0486764 100644 --- a/backend/app/workers/celery_app.py +++ b/backend/app/workers/celery_app.py @@ -43,6 +43,10 @@ celery_app.conf.beat_schedule = { minute="*" ), # Every minute (per-account interval gates actual work) }, + "refresh-gmail-tokens": { + "task": "app.workers.tasks.refresh_gmail_tokens", + "schedule": crontab(minute="*/45"), # Every 45 minutes + }, "cleanup-old-logs": { "task": "app.workers.tasks.cleanup_old_logs", "schedule": crontab(hour=3, minute=0), # Daily at 3 AM diff --git a/backend/app/workers/tasks.py b/backend/app/workers/tasks.py index 65f32e2..3d14b36 100644 --- a/backend/app/workers/tasks.py +++ b/backend/app/workers/tasks.py @@ -32,11 +32,11 @@ from app.models.database_models import ( UserSmtpConfig, ) from app.services.mail_processor import MailProcessor -from app.services.gmail_service import GmailService +from app.services.gmail_service import GmailService, GmailAuthError from app.services.config_service import ConfigService from app.services.notification_service import send_user_notification from app.core.config import settings -from sqlalchemy import select, delete +from sqlalchemy import select, delete, or_ logger = logging.getLogger(__name__) @@ -156,6 +156,27 @@ async def process_mail_account(account_id: int): if gmail_cred.encrypted_refresh_token else None ) + # Log token expiry to help diagnose timeout issues. + if gmail_cred.token_expiry: + _now = datetime.now(timezone.utc) + _expiry = gmail_cred.token_expiry + if _expiry.tzinfo is None: + _expiry = _expiry.replace(tzinfo=timezone.utc) + _secs = (_expiry - _now).total_seconds() + if _secs < 0: + logger.info( + "Gmail access token for user %s expired %.0f s ago; " + "google-auth will refresh automatically using the refresh token.", + account.user_id, + -_secs, + ) + elif _secs < 300: + logger.info( + "Gmail access token for user %s expires in %.0f s; " + "will be refreshed on the first API call.", + account.user_id, + _secs, + ) gmail_service = GmailService( access_token=access_token, refresh_token=refresh_token, @@ -324,10 +345,46 @@ async def process_mail_account(account_id: int): ) emails_failed += 1 + except GmailAuthError as e: + # Token refresh failed: refresh token is likely revoked. + # Mark the credential invalid so the user is prompted to + # re-authorise, and stop retrying for this run. + if use_gmail_api and gmail_cred: + gmail_cred.is_valid = False # type: ignore[assignment] + GMAIL_CREDENTIALS_INVALIDATED_TOTAL.inc() + logger.warning( + "Gmail credentials revoked for user %s " + "(account %s, token_expiry=%s). " + "User must re-authorise. Error: %s", + account.user_id, + account.id, + getattr(gmail_cred, "token_expiry", "unknown"), + e, + ) + try: + async with async_session_maker() as notif_db: + await send_user_notification( + db=notif_db, + user_id=int(account.user_id), + title="InboxRescue: Gmail Authorization Expired", + body=( + f"Your Gmail credentials for account '{account.name}' " + f"have been revoked or have expired. " + f"Please re-authorize Gmail access in Settings." + ), + notify_on_error=True, + ) + except Exception as notify_exc: + logger.warning( + "Failed to send revocation notification: %s", notify_exc + ) + error_msg = str(e) + emails_failed += 1 + except Exception as e: error_str = str(e).lower() - # If Gmail returns 401/403 the refresh token was revoked – - # mark credentials invalid so the user gets notified. + # Catch any remaining auth-style errors that slipped through + # (e.g. HttpError 401/403 returned after a successful refresh). if ( use_gmail_api and gmail_cred @@ -340,8 +397,13 @@ async def process_mail_account(account_id: int): gmail_cred.is_valid = False # type: ignore[assignment] GMAIL_CREDENTIALS_INVALIDATED_TOTAL.inc() logger.warning( - f"Gmail credentials revoked for user {account.user_id}. " - "User must re-authorise." + "Gmail credentials invalidated for user %s " + "(account %s, token_expiry=%s) due to HTTP auth error. " + "User must re-authorise. Error: %s", + account.user_id, + account.id, + getattr(gmail_cred, "token_expiry", "unknown"), + e, ) try: async with async_session_maker() as notif_db: @@ -349,14 +411,23 @@ async def process_mail_account(account_id: int): db=notif_db, user_id=int(account.user_id), title="InboxRescue: Gmail Authorization Expired", - body=f"Your Gmail credentials for account '{account.name}' have been revoked. Please re-authorize Gmail access in Settings.", + body=( + f"Your Gmail credentials for account '{account.name}' " + f"have been revoked. Please re-authorize Gmail access " + f"in Settings." + ), notify_on_error=True, ) except Exception as notify_exc: logger.warning( f"Failed to send revocation notification: {notify_exc}" ) - logger.error(f"Error delivering email: {e}") + logger.error( + "Error delivering email (account %s, uid=%s): %s", + account.id, + uid, + e, + ) error_msg = str(e) emails_failed += 1 @@ -728,3 +799,160 @@ async def cleanup_old_logs(days_to_keep: int = 30): CELERY_TASK_DURATION_SECONDS.labels(task_name="cleanup_old_logs").observe( _task_duration ) + + +@celery_app.task(base=AsyncTask, name="app.workers.tasks.refresh_gmail_tokens") +async def refresh_gmail_tokens(): + """ + Proactively refresh Gmail OAuth2 access tokens that are close to expiry. + + Runs every 45 minutes via Celery Beat. Any credential whose access token + expires within the next 30 minutes (or whose expiry is unknown) is + refreshed using its stored refresh token. + + Benefits: + - Keeps the DB's ``encrypted_access_token`` and ``token_expiry`` columns + up to date so mail-processing tasks never start with an already-expired + token (which would cause a delayed in-band refresh). + - Detects revoked refresh tokens early, before they block email delivery, + and sends the user a re-authorisation notification. + + Credentials without a refresh token are skipped — they cannot be refreshed + automatically and will simply fail on the next delivery attempt. + """ + _task_start = time.monotonic() + async with async_session_maker() as db: + try: + # Find all valid credentials with a refresh token whose access + # token expires within the next 30 minutes (or expiry is unknown). + refresh_threshold = datetime.now(timezone.utc) + timedelta(minutes=30) + cred_result = await db.execute( + select(GmailCredential).where( + GmailCredential.is_valid == True, # noqa: E712 + GmailCredential.encrypted_refresh_token.is_not(None), + or_( + GmailCredential.token_expiry.is_(None), + GmailCredential.token_expiry <= refresh_threshold, + ), + ) + ) + credentials_to_refresh = cred_result.scalars().all() + + if not credentials_to_refresh: + logger.debug("refresh_gmail_tokens: no credentials need refreshing") + _task_duration = time.monotonic() - _task_start + CELERY_TASKS_TOTAL.labels( + task_name="refresh_gmail_tokens", status="success" + ).inc() + CELERY_TASK_DURATION_SECONDS.labels( + task_name="refresh_gmail_tokens" + ).observe(_task_duration) + return + + logger.info( + "refresh_gmail_tokens: refreshing %d credential(s)", + len(credentials_to_refresh), + ) + + refreshed_count = 0 + failed_count = 0 + + for cred in credentials_to_refresh: + access_token = decrypt_credential(cred.encrypted_access_token) # type: ignore[arg-type] + refresh_token = decrypt_credential(cred.encrypted_refresh_token) # type: ignore[arg-type] + + gmail_service = GmailService( + access_token=access_token, + refresh_token=refresh_token, + client_id=settings.GOOGLE_CLIENT_ID, + client_secret=settings.GOOGLE_CLIENT_SECRET, + ) + + try: + new_token_info = await gmail_service.proactive_refresh() + cred.encrypted_access_token = encrypt_credential( # type: ignore[assignment] + new_token_info["access_token"] + ) + if new_token_info.get("expiry"): + cred.token_expiry = new_token_info["expiry"] # type: ignore[assignment] + cred.last_verified_at = datetime.now(timezone.utc) # type: ignore[assignment] + logger.info( + "refresh_gmail_tokens: refreshed token for user %s " + "(gmail=%s, new_expiry=%s)", + cred.user_id, + cred.gmail_email, + new_token_info.get("expiry"), + ) + refreshed_count += 1 + + except GmailAuthError as e: + # Refresh token is revoked — mark the credential invalid + # and notify the user. + cred.is_valid = False # type: ignore[assignment] + GMAIL_CREDENTIALS_INVALIDATED_TOTAL.inc() + logger.warning( + "refresh_gmail_tokens: refresh token revoked for user %s " + "(gmail=%s). Marking invalid. Error: %s", + cred.user_id, + cred.gmail_email, + e, + ) + failed_count += 1 + try: + async with async_session_maker() as notif_db: + await send_user_notification( + db=notif_db, + user_id=int(cred.user_id), + title="InboxRescue: Gmail Re-authorisation Required", + body=( + "Your Gmail access has been revoked. " + "Please open Settings → Gmail API and click " + "'Connect Gmail' to restore email delivery." + ), + notify_on_error=True, + ) + except Exception as notify_exc: + logger.warning( + "refresh_gmail_tokens: failed to send revocation " + "notification for user %s: %s", + cred.user_id, + notify_exc, + ) + + except Exception as e: + # Non-auth error (e.g. network timeout) — log but do not + # mark as invalid; it may succeed on the next run. + logger.warning( + "refresh_gmail_tokens: unexpected error refreshing token " + "for user %s (gmail=%s): %s", + cred.user_id, + cred.gmail_email, + e, + ) + failed_count += 1 + + await db.commit() + + logger.info( + "refresh_gmail_tokens: finished — %d refreshed, %d failed", + refreshed_count, + failed_count, + ) + + _task_duration = time.monotonic() - _task_start + CELERY_TASKS_TOTAL.labels( + task_name="refresh_gmail_tokens", status="success" + ).inc() + CELERY_TASK_DURATION_SECONDS.labels( + task_name="refresh_gmail_tokens" + ).observe(_task_duration) + + except Exception as e: + logger.error("refresh_gmail_tokens: unexpected error: %s", e) + _task_duration = time.monotonic() - _task_start + CELERY_TASKS_TOTAL.labels( + task_name="refresh_gmail_tokens", status="failure" + ).inc() + CELERY_TASK_DURATION_SECONDS.labels( + task_name="refresh_gmail_tokens" + ).observe(_task_duration) diff --git a/frontend/package-lock.json b/frontend/package-lock.json index 83149ab..617574a 100644 --- a/frontend/package-lock.json +++ b/frontend/package-lock.json @@ -12,7 +12,7 @@ "axios": "^1.15.0", "lucide-react": "^1.8.0", "next": "16.2.3", - "react": "19.2.4", + "react": "19.2.5", "react-dom": "19.2.5", "zustand": "^5.0.12" }, @@ -8908,9 +8908,9 @@ "license": "MIT" }, "node_modules/react": { - "version": "19.2.4", - "resolved": "https://registry.npmjs.org/react/-/react-19.2.4.tgz", - "integrity": "sha512-9nfp2hYpCwOjAN+8TZFGhtWEwgvWHXqESH8qT89AT/lWklpLON22Lc8pEtnpsZz7VmawabSU0gCjnj8aC0euHQ==", + "version": "19.2.5", + "resolved": "https://registry.npmjs.org/react/-/react-19.2.5.tgz", + "integrity": "sha512-llUJLzz1zTUBrskt2pwZgLq59AemifIftw4aB7JxOqf1HY2FDaGDxgwpAPVzHU1kdWabH7FauP4i1oEeer2WCA==", "license": "MIT", "engines": { "node": ">=0.10.0" diff --git a/frontend/package.json b/frontend/package.json index 49459b4..492d7c0 100644 --- a/frontend/package.json +++ b/frontend/package.json @@ -15,7 +15,7 @@ "axios": "^1.15.0", "lucide-react": "^1.8.0", "next": "16.2.3", - "react": "19.2.4", + "react": "19.2.5", "react-dom": "19.2.5", "zustand": "^5.0.12" },