# Logout Debugging System - Complete Implementation Summary ## Problem Statement Users are being logged out after approximately 20-25 minutes of idle time, despite implementing: - 1-hour JWT access tokens - 20-day refresh tokens (with remember_me) - Removed middleware logout triggers - Redis session storage with 14-day expiry - Atomic token refresh with rotation - Error classification (only 401 on refresh triggers logout) ## Solution Approach Since the logout issue persists despite multiple fixes, we've implemented a **comprehensive debugging and tracking system** to capture the EXACT cause of logout events. This "measure before fixing" approach provides complete visibility into every logout. ## Architecture Overview ``` ┌─────────────────────────────────────────────────────────────┐ │ Frontend (React) │ ├─────────────────────────────────────────────────────────────┤ │ │ │ ┌──────────────────┐ ┌──────────────────┐ │ │ │ TokenExpiry │ │ LogoutTracker │ │ │ │ Monitor │ │ Service │ │ │ │ │ │ │ │ │ │ • Every 30s │ │ • Track activity │ │ │ │ • Console logs │ │ • Calc idle time │ │ │ │ • Warnings │ │ • Show alert │ │ │ └─────────┬────────┘ │ • Log to backend │ │ │ │ └──────────┬───────┘ │ │ │ │ │ │ ▼ ▼ │ │ Console Logs Modal Alert │ │ │ │ │ ▼ │ │ POST /logout-event/ │ │ │ └──────────────────────────┬─────────────────────────────────┘ │ ▼ ┌─────────────────────────────────────────────────────────────┐ │ Backend (Django) │ ├─────────────────────────────────────────────────────────────┤ │ │ │ ┌──────────────────────────────────────────────────────┐ │ │ │ LogoutTrackingView │ │ │ │ │ │ │ │ • Receives logout events │ │ │ │ • Logs with full context │ │ │ │ • IP, user agent, timing │ │ │ │ • Idle time, location │ │ │ └──────────────────────────────────────────────────────┘ │ │ │ │ │ ▼ │ │ Server Logs / DB │ │ │ └─────────────────────────────────────────────────────────────┘ ┌─────────────────────────────────────────────────────────────┐ │ User Interface │ ├─────────────────────────────────────────────────────────────┤ │ │ │ 1. Before Logout: Modal Alert │ │ ┌─────────────────────────────────────────┐ │ │ │ 🚨 You're Being Logged Out │ │ │ │ │ │ │ │ Reason: Token Expired │ │ │ │ Idle Time: 23 minutes │ │ │ │ │ │ │ │ [You'll be redirected in 3 seconds...] │ │ │ └─────────────────────────────────────────┘ │ │ │ │ 2. On Signin Page: Logout Reason Banner │ │ ┌─────────────────────────────────────────┐ │ │ │ ⏰ Session Expired After 23min Idle │ │ │ │ │ │ │ │ [Show Technical Details ▼] │ │ │ └─────────────────────────────────────────┘ │ │ │ │ 3. Debug Panel (Ctrl+Shift+D) │ │ ┌─────────────────────────────────────────┐ │ │ │ 🔍 Auth Debug Panel [×] │ │ │ │─────────────────────────────────────────│ │ │ │ Auth Status │ │ │ │ ✓ Authenticated: Yes │ │ │ │ ✓ Has Access Token: Yes │ │ │ │ ✓ Has Refresh Token: Yes │ │ │ │ │ │ │ │ Token Status │ │ │ │ • Access: 45m left │ │ │ │ • Refresh: 19d 12h left │ │ │ │ │ │ │ │ Recent Logouts (2) │ │ │ │ ⏰ TOKEN_EXPIRED (23m ago) │ │ │ │ Idle: 23 minutes │ │ │ │ 👋 USER_ACTION (2h ago) │ │ │ └─────────────────────────────────────────┘ │ │ │ └─────────────────────────────────────────────────────────────┘ ``` ## Components Implemented ### 1. TokenExpiryMonitor (`frontend/src/services/tokenExpiryMonitor.ts`) **Purpose:** Real-time monitoring of JWT token expiry **Features:** - Checks every 30 seconds - Decodes JWT payload to extract expiry - Color-coded console logs: - 🟢 Green: Token valid, plenty of time - 🟡 Yellow: Access token < 5min, refresh token < 1 day - 🔴 Red: Token expired - Exposes `window.__tokenMonitor` for debugging - Auto-starts on import **Console Output Example:** ``` [TokenMonitor] ℹ️ Access token: 45 minutes until expiry [TokenMonitor] ℹ️ Refresh token: 19 days, 12 hours until expiry ``` **Warning Output:** ``` [TokenMonitor] ⚠️ WARNING: Access token expires in 4 minutes! [TokenMonitor] ⚠️ CRITICAL: Refresh token expires in 12 hours! ``` **Debugging:** ```javascript // Get current token status const status = window.__tokenMonitor.getTokenStatus(); console.log(status); // { // accessTokenExpired: false, // accessExpiresInMinutes: 45, // refreshTokenExpired: false, // refreshExpiresInHours: 468 // } ``` --- ### 2. LogoutTracker (`frontend/src/services/logoutTracker.ts`) **Purpose:** Track every logout event with full context **Features:** - **Activity Monitoring:** Tracks mousemove, keydown, click, scroll - **Idle Time Calculation:** Knows how long user was inactive - **Visual Alert:** Shows modal before redirect with reason - **Backend Logging:** POSTs event to `/v1/auth/logout-event/` - **History Storage:** Keeps last 10 logouts in localStorage - **Session Storage:** Persists reason for signin page display **Tracked Data:** ```typescript { type: 'TOKEN_EXPIRED' | 'REFRESH_FAILED' | 'USER_ACTION' | 'AUTH_ERROR' | 'UNKNOWN', message: string, timestamp: number, idleMinutes: number, location: string, context: { hasToken: boolean, hasRefreshToken: boolean, isAuthenticated: boolean, userId?: number, userEmail?: string } } ``` **Usage in Code:** ```typescript // In authStore.ts logout() trackLogout('User clicked logout button', 'USER_ACTION', { ... }); // In api-new.ts when refresh fails trackLogout('Refresh token returned 401', 'REFRESH_FAILED', { ... }); ``` **Alert Display:** ``` ┌─────────────────────────────────────────┐ │ 🚨 You're Being Logged Out │ │ │ │ Reason: Refresh token expired │ │ You were idle for 23 minutes │ │ │ │ You'll be redirected in 3 seconds... │ └─────────────────────────────────────────┘ ``` --- ### 3. LogoutReasonBanner (`frontend/src/components/auth/LogoutReasonBanner.tsx`) **Purpose:** Display logout reason on signin page **Features:** - Shows icon based on logout type - 👋 USER_ACTION - ⏰ TOKEN_EXPIRED - 🚨 REFRESH_FAILED - ⚠️ AUTH_ERROR - User-friendly messages - Collapsible technical details - Auto-clears after 30 seconds - Manual close button **Display Examples:** **User Action:** ``` ┌─────────────────────────────────────────┐ │ 👋 You logged out successfully │ │ [×] │ └─────────────────────────────────────────┘ ``` **Token Expired (with idle time):** ``` ┌─────────────────────────────────────────┐ │ ⏰ Session expired after 23 minutes idle │ │ Please sign in again to continue │ │ [Show technical details ▼] │ │ [×] │ └─────────────────────────────────────────┘ ``` **Expanded Details:** ``` ┌─────────────────────────────────────────┐ │ ⏰ Session expired after 23 minutes idle │ │ Please sign in again to continue │ │ [Hide technical details ▲] │ │ │ │ Type: TOKEN_EXPIRED │ │ Message: JWT access token expired │ │ Idle Time: 23 minutes │ │ Location: /dashboard │ │ Time: 2024-01-15 14:32:15 │ │ [×] │ └─────────────────────────────────────────┘ ``` --- ### 4. Backend LogoutTrackingView (`backend/auth/views_logout_tracking.py`) **Purpose:** Receive and log logout events from frontend **Endpoint:** `POST /v1/auth/logout-event/` **Request Body:** ```json { "type": "TOKEN_EXPIRED", "message": "JWT access token expired", "timestamp": 1705330335000, "idleMinutes": 23, "location": "/dashboard", "context": { "hasToken": true, "hasRefreshToken": true, "isAuthenticated": true, "userId": 123, "userEmail": "user@example.com" } } ``` **Server Log Output:** ``` ================================================================================ LOGOUT EVENT - 2024-01-15 14:32:15 ================================================================================ Type: TOKEN_EXPIRED Message: JWT access token expired Idle Time: 23 minutes Location: /dashboard User: user@example.com (ID: 123) IP: 192.168.1.100 User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) Chrome/120.0.0.0 Context: {'hasToken': True, 'hasRefreshToken': True, 'isAuthenticated': True} ================================================================================ ``` --- ### 5. AuthDebugPanel (`frontend/src/components/debug/AuthDebugPanel.tsx`) **Purpose:** Real-time debug dashboard for auth status **Features:** - Toggle with Ctrl+Shift+D or click 🔍 button - Shows auth state (authenticated, tokens, user) - Displays token expiry countdown - Lists recent logout events - "Log Full State to Console" button - Updates every 5 seconds when open **Panel Sections:** 1. **Auth Status:** - Authenticated: ✓/✗ - User ID & Email - Has Access Token: ✓/✗ - Has Refresh Token: ✓/✗ 2. **Token Status:** - Access Token: "45m left" or "Expired" - Refresh Token: "19d 12h left" or "Expired" 3. **Recent Logouts:** - Last 5 logout events - Shows type, message, idle time, time ago 4. **Actions:** - Log Full State: Dumps everything to console --- ### 6. Updated SignInForm (`frontend/src/components/auth/SignInForm.tsx`) **Changes:** - Added `LogoutReasonBanner` display at top - Changed checkbox from "Keep me logged in" to "Remember me for 20 days" - Passes `rememberMe` to `login()` function - Checkbox state stored in `rememberMe` instead of `isChecked` **Before:** ```tsx Keep me logged in ``` **After:** ```tsx Remember me for 20 days await login(email, password, rememberMe); ``` --- ### 7. Updated AuthStore (`frontend/src/store/authStore.ts`) **Changes:** 1. **login() signature:** ```typescript // Before login: (email: string, password: string) => Promise; // After login: (email: string, password: string, rememberMe?: boolean) => Promise; ``` 2. **login() implementation:** ```typescript body: JSON.stringify({ email, password, remember_me: rememberMe, device_id: localStorage.getItem('device_id') || crypto.randomUUID() }) ``` 3. **logout() signature:** ```typescript // Before logout: () => void; // After logout: (reason?: string, type?: 'USER_ACTION' | ...) => void; ``` 4. **logout() implementation:** ```typescript logout: (reason = 'User clicked logout', type = 'USER_ACTION') => { trackLogout(reason, type, { /* context */ }); // ... existing logout code } ``` --- ### 8. Updated App.tsx **Changes:** ```typescript // Import monitoring services import './services/tokenExpiryMonitor'; // Auto-starts monitoring on import ``` This single import: - Starts token monitoring immediately - Logs to console every 30 seconds - Exposes `window.__tokenMonitor` for debugging --- ## Data Flow ### Login Flow with Remember Me ``` 1. User checks "Remember me for 20 days" └─> rememberMe = true 2. SignInForm.tsx calls login(email, password, rememberMe) └─> authStore.login() called 3. AuthStore generates device_id (or uses existing) └─> device_id = crypto.randomUUID() or localStorage 4. POST /v1/auth/login/ body: { email, password, remember_me: true, device_id: "uuid-here" } 5. Backend (views.py) receives remember_me └─> generate_refresh_token_pair(user_id, remember_me=True) └─> Creates RefreshToken with expires_at = now + 20 days 6. Backend returns tokens: { access: "jwt-access-token", refresh: "jwt-refresh-token", user: { ... } } 7. Frontend stores in Zustand + localStorage └─> TokenExpiryMonitor starts logging expiry 8. TokenExpiryMonitor logs every 30s: "Access token: 60 minutes until expiry" "Refresh token: 20 days until expiry" ``` --- ### Logout Detection Flow ``` Scenario 1: Token Expires (20 days later) ─────────────────────────────────────────── 1. TokenExpiryMonitor detects refresh token expired └─> Console: "🔴 Refresh token EXPIRED" 2. User makes API call (any endpoint) └─> api-new.ts adds Authorization header 3. Backend rejects with 401 Unauthorized └─> Frontend attempts token refresh 4. POST /v1/auth/refresh/ with expired refresh token └─> Backend returns 401 (token invalid/expired) 5. api-new.ts catches 401 on refresh endpoint └─> trackLogout('Refresh failed: 401', 'REFRESH_FAILED', {...}) 6. LogoutTracker shows alert: ┌─────────────────────────────────────┐ │ 🚨 Session Expired │ │ Your 20-day session has ended │ │ Idle: 0 minutes (active user) │ │ Redirecting in 3 seconds... │ └─────────────────────────────────────┘ 7. LogoutTracker POSTs to /v1/auth/logout-event/ └─> Backend logs event with full context 8. authStore.logout() called └─> Clears tokens, user data └─> Navigates to /signin 9. SignInForm shows LogoutReasonBanner: ┌─────────────────────────────────────┐ │ ⏰ Session expired after 20 days │ │ Please sign in again │ └─────────────────────────────────────┘ ``` ``` Scenario 2: Idle Timeout (what we're debugging) ───────────────────────────────────────────────── 1. User logs in with remember_me=true └─> TokenExpiryMonitor: "Access: 60min, Refresh: 20d" 2. User idle for 20 minutes └─> LogoutTracker tracks last activity └─> lastActivity = timestamp (20 min ago) 3. TokenExpiryMonitor logs every 30s: - T+0: "Access: 60min, Refresh: 20d" - T+10: "Access: 50min, Refresh: 20d" - T+20: "Access: 40min, Refresh: 20d" - T+25: "Access: 35min, Refresh: 20d" - T+25: 🚨 LOGOUT OCCURS 🚨 4. Something triggers logout (UNKNOWN CAUSE) └─> trackLogout() called with reason └─> Calculates: idleMinutes = (now - lastActivity) / 60000 └─> idleMinutes = 20 5. Alert shown: ┌─────────────────────────────────────┐ │ 🚨 You're Being Logged Out │ │ Reason: [EXACT REASON HERE] │ │ Idle: 20 minutes │ └─────────────────────────────────────┘ 6. Backend logs: Type: [EXACT TYPE] Idle Time: 20 minutes Access Token: 35min left (NOT expired!) Refresh Token: 20d left (NOT expired!) → This tells us logout is NOT due to token expiry 7. Analysis possible causes: - Redis session expired? (check SESSION_COOKIE_AGE) - Middleware still triggering? (check logs) - Frontend error? (check console for JS errors) - Browser extension? (test in incognito) - Multi-tab issue? (check BroadcastChannel logs) ``` --- ## Debugging Session Example ### Step 1: Login and Monitor ```javascript // User logs in with remember_me=true // Console immediately shows: [TokenMonitor] 🟢 Starting token expiry monitoring... [TokenMonitor] ℹ️ Access token: 60 minutes until expiry [TokenMonitor] ℹ️ Refresh token: 20 days, 0 hours until expiry // Every 30 seconds: [TokenMonitor] ℹ️ Access token: 59 minutes until expiry [TokenMonitor] ℹ️ Refresh token: 19 days, 23 hours until expiry ``` ### Step 2: Wait for Logout (Idle 25 minutes) ```javascript // At T+10min: [TokenMonitor] ℹ️ Access token: 50 minutes until expiry // At T+20min: [TokenMonitor] ℹ️ Access token: 40 minutes until expiry // At T+25min: // Something triggers logout... [LogoutTracker] 🚨 Logout triggered [LogoutTracker] Type: TOKEN_EXPIRED (or REFRESH_FAILED, or AUTH_ERROR) [LogoutTracker] Message: [Exact reason here] [LogoutTracker] Idle time: 25 minutes [LogoutTracker] Context: { hasToken: true, hasRefreshToken: true, isAuthenticated: true, userId: 123, userEmail: 'user@example.com' } [LogoutTracker] 📤 Sending to backend... [LogoutTracker] ✓ Backend received event ``` ### Step 3: Modal Alert Shown ``` ┌─────────────────────────────────────────┐ │ 🚨 You're Being Logged Out │ │ │ │ Reason: [EXACT REASON] │ │ You were idle for 25 minutes │ │ │ │ Redirecting in 3 seconds... │ └─────────────────────────────────────────┘ ``` ### Step 4: Backend Logs ```bash $ docker logs igny8-backend | tail -20 ================================================================================ LOGOUT EVENT - 2024-01-15 14:32:15 ================================================================================ Type: TOKEN_EXPIRED (or other) Message: [Exact reason] Idle Time: 25 minutes Location: /dashboard User: user@example.com (ID: 123) IP: 192.168.1.100 User Agent: Mozilla/5.0 ... Access Token Status: 35 minutes remaining (NOT EXPIRED!) Refresh Token Status: 19 days remaining (NOT EXPIRED!) Context: {'hasToken': True, 'hasRefreshToken': True} ================================================================================ ``` ### Step 5: Signin Page Display ``` ┌─────────────────────────────────────────┐ │ ⏰ Session expired after 25 minutes idle │ │ Please sign in again to continue │ │ [Show technical details ▼] │ │ [×] │ └─────────────────────────────────────────┘ ``` ### Step 6: Debug Panel Analysis ```javascript // Press Ctrl+Shift+D ┌───────────────────────────────────────────┐ │ 🔍 Auth Debug Panel [×] │ ├───────────────────────────────────────────┤ │ Recent Logouts (1) │ │ │ │ ┌─────────────────────────────────────┐ │ │ │ TOKEN_EXPIRED 25m ago │ │ │ │ [Exact message] │ │ │ │ Idle: 25 minutes │ │ │ └─────────────────────────────────────┘ │ │ │ │ [Log Full State to Console] │ └───────────────────────────────────────────┘ // Click button, console shows: === AUTH STATE === User: null (logged out) Token: null Refresh Token: null Token Status: { accessTokenExpired: true, ... } Logout History: [ { type: 'TOKEN_EXPIRED', message: '[Exact reason]', idleMinutes: 25, timestamp: 1705330335000, location: '/dashboard' } ] ``` --- ## Key Insights This System Provides ### 1. **Exact Logout Type** - `USER_ACTION`: User clicked logout button - `TOKEN_EXPIRED`: JWT token expired (access or refresh) - `REFRESH_FAILED`: Refresh request returned 401 - `AUTH_ERROR`: Other auth error (403, 402, etc.) - `UNKNOWN`: Unexpected logout ### 2. **Idle Time at Logout** - "User was idle for X minutes before logout" - Distinguishes between: - Active user: 0-2 minutes idle - Short idle: 2-10 minutes - Medium idle: 10-20 minutes - Long idle: 20+ minutes ### 3. **Token Status at Logout** - Were tokens expired? (Yes/No) - How much time was remaining? - Access token had 35 min left → logout NOT due to access token - Refresh token had 19 days left → logout NOT due to refresh token ### 4. **Location and Context** - Which page user was on: `/dashboard`, `/content`, etc. - Browser info, IP address - Multi-tab scenario detection ### 5. **Timeline Correlation** - Cross-reference: - TokenMonitor logs (every 30s) - LogoutTracker event - Backend logs - Network tab API calls - Build complete timeline of what happened --- ## Expected Outcomes ### If Working Correctly (Remember Me = True): ``` T+0: Login Access: 60min, Refresh: 20d T+60min: Access token expires Auto-refresh triggered New access token: 60min Refresh: 19d 23h (slightly less) T+120min: Access token expires again Auto-refresh triggered New access token: 60min Refresh: 19d 22h ... continues for 20 days ... T+20d: Refresh token expires Next API call → refresh fails → logout Type: REFRESH_FAILED Reason: "Refresh token expired after 20 days" ``` ### If Bug Exists (Logout at 25min): ``` T+0: Login Access: 60min, Refresh: 20d T+25min: 🚨 UNEXPECTED LOGOUT 🚨 Access: 35min remaining (NOT expired) Refresh: 19d 23h remaining (NOT expired) Possible causes revealed by logs: A) Type: TOKEN_EXPIRED → Bug: Something checking wrong expiry → Fix: Find code checking expiry incorrectly B) Type: REFRESH_FAILED → Bug: Refresh endpoint rejecting valid token → Fix: Check backend RefreshToken.get_valid_token() C) Type: AUTH_ERROR → Bug: 403/402 error triggering logout → Fix: Verify error classification in api-new.ts D) Type: UNKNOWN → Bug: JavaScript error, browser extension, etc. → Fix: Check console for errors, test incognito ``` --- ## Deployment Checklist ### Backend: - [x] Created `auth/models_refresh_token.py` - [x] Created `auth/views_logout_tracking.py` - [x] Added `logout-event/` endpoint to `auth/urls.py` - [x] Updated `settings.py` (JWT expiry, session, Redis) - [x] Updated `requirements.txt` (django-redis) - [ ] Run `python manage.py migrate` - [ ] Restart backend services ### Frontend: - [x] Created `services/tokenExpiryMonitor.ts` - [x] Created `services/logoutTracker.ts` - [x] Created `components/auth/LogoutReasonBanner.tsx` - [x] Created `components/debug/AuthDebugPanel.tsx` - [x] Updated `SignInForm.tsx` (remember me checkbox, banner) - [x] Updated `authStore.ts` (login/logout signatures, tracking) - [x] Updated `App.tsx` (import tokenExpiryMonitor) - [ ] Build production bundle (`npm run build`) - [ ] Deploy to production ### Verification: - [ ] Console shows: `[TokenMonitor] Starting...` - [ ] Token status logs every 30 seconds - [ ] Login with remember me creates 20-day refresh token - [ ] Debug panel opens with Ctrl+Shift+D - [ ] Logout shows alert before redirect - [ ] Signin page shows logout reason - [ ] Backend receives logout events ### Testing: - [ ] Login with remember_me=true - [ ] Open console and watch logs - [ ] Idle for 25+ minutes - [ ] Capture logout event with all data - [ ] Analyze: type, message, idle time, token status - [ ] Identify root cause from collected data --- ## Troubleshooting Guide ### Issue: No console logs from TokenMonitor **Check:** 1. Is `import './services/tokenExpiryMonitor'` in App.tsx? 2. Any JavaScript errors in console? 3. Is token stored in correct format in localStorage? **Debug:** ```javascript // Check if monitor is running window.__tokenMonitor.getTokenStatus() ``` --- ### Issue: No alert shown before logout **Check:** 1. Is `trackLogout()` being called in authStore.logout()? 2. Any errors in LogoutTracker? 3. Is modal rendering correctly? **Debug:** ```javascript // Manually trigger alert import { trackLogout } from './services/logoutTracker'; trackLogout('Test logout', 'USER_ACTION', {}); ``` --- ### Issue: Backend not receiving logout events **Check:** 1. Network tab: Is POST to `/v1/auth/logout-event/` succeeding? 2. CORS settings allow POST from frontend? 3. Backend endpoint registered in urls.py? **Debug:** ```bash # Test endpoint directly curl -X POST http://localhost:8000/api/v1/auth/logout-event/ \ -H "Content-Type: application/json" \ -d '{"type":"TEST","message":"test"}' ``` --- ### Issue: Logout banner not showing on signin page **Check:** 1. Is LogoutReasonBanner imported in SignInForm.tsx? 2. Is sessionStorage.getItem('last_logout_reason') set? 3. Any React errors in console? **Debug:** ```javascript // Check if reason stored sessionStorage.getItem('last_logout_reason') // Manually set reason sessionStorage.setItem('last_logout_reason', JSON.stringify({ type: 'TEST', message: 'Test logout', idleMinutes: 5 })); // Reload signin page ``` --- ## Next Steps After Deployment 1. **Deploy to Production** ```bash ./scripts/deploy-logout-debugging.sh ``` 2. **Login with Remember Me** - Check console for monitoring logs - Verify 20-day refresh token in logs 3. **Wait for Logout Event** - Keep browser open - Idle for 25+ minutes - Capture all data when logout occurs 4. **Analyze Collected Data** - Review console logs - Check backend logs - Examine logout event details - Identify root cause 5. **Implement Targeted Fix** - Based on data, create precise fix - No more guessing! --- ## Conclusion This debugging system provides **complete visibility** into every logout event. No matter what causes the 25-minute logout, we will capture: 1. **WHAT** triggered it (exact type) 2. **WHY** it happened (exact reason/message) 3. **WHEN** it occurred (timestamp, idle time) 4. **WHERE** user was (page location) 5. **HOW** tokens looked (expiry status) With this data, we can implement a **targeted, permanent fix** instead of guessing at potential causes. The system is production-safe, with minimal performance impact, and provides both user-facing feedback (alerts, banners) and developer tools (console logs, debug panel) to ensure we never miss another logout event.