From 541505bf7436d54182d909e0eaed850417e818c4 Mon Sep 17 00:00:00 2001 From: sachin9082 Date: Thu, 2 Oct 2025 20:28:36 -0400 Subject: [PATCH 1/2] process: bug fixing for auto logout --- DEBUG_SESSION_TIMEOUT.md | 242 ++++++++++++++++++++++ ROLLBACK_AUTO_LOGOUT.md | 243 ++++++++++++++++++++++ SESSION_TIMEOUT_ANALYSIS.md | 297 +++++++++++++++++++++++++++ server/auth/user_manager_postgres.py | 42 +++- 4 files changed, 821 insertions(+), 3 deletions(-) create mode 100644 DEBUG_SESSION_TIMEOUT.md create mode 100644 ROLLBACK_AUTO_LOGOUT.md create mode 100644 SESSION_TIMEOUT_ANALYSIS.md diff --git a/DEBUG_SESSION_TIMEOUT.md b/DEBUG_SESSION_TIMEOUT.md new file mode 100644 index 0000000..948faf2 --- /dev/null +++ b/DEBUG_SESSION_TIMEOUT.md @@ -0,0 +1,242 @@ +# Session Timeout Debugging Guide + +**Issue:** Users are getting logged out after 5-6 minutes instead of 1 hour +**Status:** πŸ” DEBUGGING MODE ACTIVE + +--- + +## πŸ” Debug Logging Added + +I've added comprehensive logging to track exactly what's happening with session timeouts. + +### Where to Find Logs + +**Local Development:** +```bash +# Server logs will show in terminal where you run server.py +python server/server.py +``` + +**AWS Production:** +```bash +# View ECS logs +aws logs tail /aws/ecs/pythonide --follow --region us-east-2 --filter-pattern "[SESSION-DEBUG]" + +# Or via AWS Console: +# ECS > Clusters > pythonide-cluster > Tasks > View logs in CloudWatch +``` + +--- + +## πŸ“Š What the Logs Will Show + +### On Login (Session Creation): +``` +[SESSION-CREATE] Creating session for user sa9082 +[SESSION-CREATE] Current time: 2025-10-02 15:30:00 (type: , tz: None) +[SESSION-CREATE] Expires at: 2025-10-03 15:30:00 +[SESSION-CREATE] Initial last_activity: 2025-10-02 15:30:00 +[SESSION-CREATE] Session created successfully for sa9082 +``` + +### On Activity Update (Every WebSocket Message): +``` +[ACTIVITY-UPDATE] Updating session activity to: 2025-10-02 15:35:00 (type: , tz: None) +[ACTIVITY-UPDATE] Session activity updated successfully +``` + +### On Session Validation (Every Request): +``` +[SESSION-DEBUG] User: sa9082 +[SESSION-DEBUG] Current time: 2025-10-02 15:36:00 (type: , tz: None) +[SESSION-DEBUG] Last activity raw: 2025-10-02 15:35:00 (type: ) +[SESSION-DEBUG] Already datetime: 2025-10-02 15:35:00 (tz: None) +[SESSION-DEBUG] Final last_activity: 2025-10-02 15:35:00 (tz: None) +[SESSION-DEBUG] Idle duration: 0:01:00 (seconds: 60.0) +[SESSION-DEBUG] Timeout threshold: 1:00:00 (seconds: 3600.0) +[SESSION-DEBUG] Will logout? False +``` + +### On Auto-Logout (If Triggered): +``` +[SESSION-TIMEOUT] User sa9082 logged out due to inactivity +[SESSION-TIMEOUT] Idle duration: 1:05:23 > threshold: 1:00:00 +[SESSION-TIMEOUT] Last activity was: 2025-10-02 14:30:00 +``` + +--- + +## 🎯 What to Look For + +### 1. **Timezone Issues** +Look for any timezone mismatches: +``` +❌ BAD: tz: (timezone-aware) +βœ… GOOD: tz: None (timezone-naive) +``` + +If you see timezone-aware datetimes, the timezone stripping isn't working. + +### 2. **Time Discrepancies** +Check if times are being stored/read differently: +``` +Created: 2025-10-02 15:00:00 +Read back: 2025-10-02 19:00:00 ❌ 4-hour difference! +``` + +This would indicate timezone conversion is happening in PostgreSQL. + +### 3. **Idle Duration Calculation** +The math should be straightforward: +``` +Current: 2025-10-02 15:06:00 +Last: 2025-10-02 15:00:00 +Idle: 0:06:00 (360 seconds) βœ… Correct +``` + +If you see something like: +``` +Current: 2025-10-02 15:06:00 +Last: 2025-10-02 15:00:00 +Idle: 4:06:00 (14760 seconds) ❌ Wrong! Timezone issue +``` + +--- + +## πŸ”¬ Step-by-Step Debugging Process + +### Step 1: Test Login +1. Login to the IDE +2. Check server logs for `[SESSION-CREATE]` messages +3. **Verify:** Current time and last_activity should match +4. **Verify:** Both should have `tz: None` + +### Step 2: Test Activity Updates +1. Type something in the IDE or run code +2. Check logs for `[ACTIVITY-UPDATE]` messages +3. **Verify:** Activity updates are happening +4. **Verify:** Times have `tz: None` + +### Step 3: Wait 6 Minutes +1. Don't interact with IDE for exactly 6 minutes +2. Then type something or run code +3. Check logs for `[SESSION-DEBUG]` messages +4. **Look at:** + - `Idle duration: X:XX:XX` + - `Will logout? True/False` + +### Step 4: Analyze the Logout +If you get logged out at 6 minutes: +- Check the `[SESSION-DEBUG]` logs just before logout +- Look at the idle duration calculation +- Compare `last_activity` raw value vs final value + +--- + +## πŸ› Possible Root Causes + +### Cause 1: PostgreSQL Timezone Conversion +**Symptom:** Times change when read from database +**Debug:** Compare `[SESSION-CREATE]` time vs `[SESSION-DEBUG]` Last activity raw + +**Fix if found:** +```sql +-- Check PostgreSQL timezone setting +SHOW timezone; + +-- If not UTC, the times might be getting converted +``` + +### Cause 2: psycopg2 Timezone Handling +**Symptom:** `last_activity` has timezone when read even though we stored naive datetime +**Debug:** Look at `Last activity raw` - does it have a timezone? + +**Fix if found:** +```python +# In database.py, when creating connection pool +connect_args = { + 'timezone': None, # Force naive datetime handling +} +``` + +### Cause 3: Background Cleanup Job +**Symptom:** No timeout in validate_session, but user still gets logged out +**Debug:** Search logs for `cleanup_idle_sessions` + +**Fix if found:** The background job at line 608-660 might have wrong timeout + +### Cause 4: Multiple validate_session Calls +**Symptom:** validate_session is called many times per minute +**Debug:** Count how many `[SESSION-DEBUG]` messages appear per minute + +**Fix if found:** Reduce validation frequency or cache results + +--- + +## πŸ”§ Quick Diagnostic Commands + +### Check Database Session Table +```sql +-- Connect to PostgreSQL +psql -h pythonide-db.c1u6aa2mqwwf.us-east-2.rds.amazonaws.com -U pythonide_admin -d pythonide + +-- Check current sessions +SELECT username, last_activity, + NOW() as current_time, + NOW() - last_activity as idle_duration, + EXTRACT(EPOCH FROM (NOW() - last_activity)) as idle_seconds +FROM sessions s +JOIN users u ON s.user_id = u.id +WHERE is_active = true; + +-- Check PostgreSQL timezone +SHOW timezone; + +-- Check data type of last_activity +SELECT column_name, data_type, datetime_precision +FROM information_schema.columns +WHERE table_name = 'sessions' AND column_name = 'last_activity'; +``` + +### Check Server Logs +```bash +# Local +tail -f server/pythonide.log | grep SESSION + +# AWS +aws logs tail /aws/ecs/pythonide --follow --region us-east-2 --filter-pattern SESSION +``` + +--- + +## πŸ“‹ Information to Collect + +When you test, please collect: + +1. **Login logs** - Full `[SESSION-CREATE]` block +2. **Activity logs** - At least 2 `[ACTIVITY-UPDATE]` entries +3. **Validation logs** - At least 3 `[SESSION-DEBUG]` blocks (right after login, after 3 min, after 6 min) +4. **Timeout logs** - If logout happens, the `[SESSION-TIMEOUT]` block +5. **Database query** - Result of checking `last_activity` in database directly + +--- + +## πŸ”„ Rollback Option (If Needed) + +If debugging doesn't work out, I can provide a clean rollback that: +- βœ… Keeps single-session enforcement (this works) +- ❌ Removes auto-logout after inactivity +- πŸ“ Saves the timeout code for future debugging + +Just let me know if you want the rollback! + +--- + +## πŸ“ Next Steps + +1. **Deploy this debug version** to your environment +2. **Login and test** following the debugging process above +3. **Share the logs** - I'll analyze them to find the exact issue +4. **Fix or rollback** based on findings + +The debug logs will tell us EXACTLY what's going wrong! diff --git a/ROLLBACK_AUTO_LOGOUT.md b/ROLLBACK_AUTO_LOGOUT.md new file mode 100644 index 0000000..5792a1f --- /dev/null +++ b/ROLLBACK_AUTO_LOGOUT.md @@ -0,0 +1,243 @@ +# Rollback Auto-Logout (Keep Single-Session) + +**Purpose:** Remove auto-logout after inactivity while keeping single-session enforcement + +--- + +## 🎯 What This Rollback Does + +### βœ… Keeps (Working Features): +- Single-session enforcement (only 1 active session per user) +- Session activity tracking +- Session token validation +- WebSocket authentication +- Database-level session invalidation + +### ❌ Removes (Problematic Feature): +- Auto-logout after 1 hour of inactivity +- Idle duration checking +- Background cleanup job for idle sessions + +--- + +## πŸ“ Files to Modify + +### 1. `server/auth/user_manager_postgres.py` + +**Changes in `validate_session()` method (lines 170-216):** + +Remove the entire auto-logout block and replace with just session validation. + +**Before (lines 170-216):** +```python +# AUTO-LOGOUT: Check for 1-hour inactivity timeout +last_activity = session.get("last_activity") +# ... all the timeout logic ... +if idle_duration > INACTIVITY_TIMEOUT: + self.logout(token) + return None +``` + +**After:** +```python +# Auto-logout temporarily disabled for debugging +# Single-session enforcement still active (see line 89-102) +# Activity tracking still active (update_session_activity still called) +``` + +**Changes in `cleanup_idle_sessions()` method (lines 608-660):** + +Make this method a no-op (do nothing). + +**Before:** +```python +def cleanup_idle_sessions(self): + # ... cleanup logic ... +``` + +**After:** +```python +def cleanup_idle_sessions(self): + """ + Cleanup idle sessions - TEMPORARILY DISABLED + Returns empty list to keep IdleSessionCleanupJob happy + """ + return [] # No users to cleanup +``` + +--- + +## πŸ”§ Rollback Script + +Here's the exact code to apply: + +### File: `server/auth/user_manager_postgres.py` + +**1. Replace lines 170-216 with:** +```python + # AUTO-LOGOUT: TEMPORARILY DISABLED FOR DEBUGGING + # Single-session enforcement is still active (working correctly) + # Activity tracking is still active (update_session_activity still called) + # + # The inactivity timeout logic has been disabled because users were + # getting logged out prematurely (5-6 minutes instead of 1 hour). + # + # To re-enable auto-logout after debugging: + # 1. Review DEBUG_SESSION_TIMEOUT.md for debugging steps + # 2. Collect logs to identify the root cause + # 3. Fix the timezone/timing issue + # 4. Restore the timeout logic from git history + + # For now, just validate the session exists and is active + # (expires_at is still checked at line 152) +``` + +**2. Replace the `cleanup_idle_sessions()` method (lines 608-660) with:** +```python + def cleanup_idle_sessions(self): + """ + Cleanup sessions that have been idle for more than 1 hour. + TEMPORARILY DISABLED - Returns empty list. + + This is called periodically by background job but does nothing + until the auto-logout timeout issue is debugged and fixed. + + To re-enable: + 1. Debug the timeout calculation issue + 2. Restore original code from git history (commit before rollback) + 3. Test thoroughly before deploying + """ + logger.info("Idle session cleanup temporarily disabled (rollback)") + return [] # No users to cleanup +``` + +--- + +## πŸš€ How to Apply Rollback + +### Option 1: Manual Edit (Recommended) +1. Open `server/auth/user_manager_postgres.py` +2. Find line 170 (start of auto-logout block) +3. Replace lines 170-216 with the code above +4. Find the `cleanup_idle_sessions()` method +5. Replace with the disabled version above +6. Save and deploy + +### Option 2: Use Git +```bash +# If you want to revert the entire auto-logout feature +git log --oneline | grep -i "timeout\|logout\|activity" + +# Find the commit before auto-logout was added +# Then revert just those changes + +# Or create a new branch with rollback +git checkout -b rollback/disable-auto-logout +# Make changes +git commit -m "Rollback: Disable auto-logout, keep single-session" +``` + +--- + +## βœ… What Will Still Work After Rollback + +### 1. Single-Session Enforcement βœ… +**Location:** `user_manager_postgres.py` lines 89-102 + +Users can only have 1 active session. If they login from a new location, the old session is invalidated. + +**Test:** +1. Login from Browser A +2. Login from Browser B with same user +3. Browser A session should be terminated + +### 2. Session Activity Tracking βœ… +**Location:** `user_manager_postgres.py` lines 230-255 + +The `last_activity` column is still updated on every WebSocket message. + +**Why keep it:** +- Ready for when auto-logout is fixed +- Can be used for analytics +- Doesn't hurt anything + +### 3. Session Expiration (24 hours) βœ… +**Location:** `user_manager_postgres.py` line 152 + +Sessions still expire after 24 hours (based on `expires_at` column). + +**Test:** +- Login and note the time +- Session will expire 24 hours later +- User will need to login again + +### 4. WebSocket Authentication βœ… +**Location:** All WebSocket handlers + +All WebSocket connections still require authentication. + +--- + +## ❌ What Will Stop Working After Rollback + +### 1. Auto-Logout After Inactivity ❌ +Users will NOT be logged out if they're inactive for more than 1 hour. + +**Impact:** +- Sessions can stay active for up to 24 hours +- Users need to manually logout +- Shared computers: users should click "Logout" button + +### 2. Idle Session Cleanup Job ❌ +The background job still runs but does nothing. + +**Impact:** +- Minimal - it's just an empty loop +- Can be fully disabled if needed + +--- + +## πŸ” After Rollback: How to Debug + +1. **Deploy the debug logging version** (already added in this session) +2. **Test and collect logs** following `DEBUG_SESSION_TIMEOUT.md` +3. **Analyze logs** to find the timing issue +4. **Fix the root cause** +5. **Re-enable auto-logout** by restoring the code + +--- + +## πŸ“Š Comparison + +| Feature | With Auto-Logout | After Rollback | +|---------|------------------|----------------| +| Single-session enforcement | βœ… Works | βœ… Works | +| Activity tracking | βœ… Works | βœ… Works | +| Auto-logout (1hr idle) | ❌ Buggy (5-6min) | ⏸️ Disabled | +| Session expiration (24hr) | βœ… Works | βœ… Works | +| WebSocket auth | βœ… Works | βœ… Works | +| User experience | 😞 Frustrating | 😊 Better | + +--- + +## 🎯 Recommendation + +**I recommend:** + +1. **Apply the rollback now** - Improve user experience immediately +2. **Deploy debug logging** - So we can collect data in background +3. **Collect logs over next few days** - From real usage +4. **Analyze and fix** - Find the root cause +5. **Re-enable auto-logout** - Once properly debugged + +This way: +- βœ… Users aren't frustrated +- βœ… Single-session still works +- βœ… We can debug properly +- βœ… Fix can be tested before re-deployment + +--- + +## 🚨 If You Want to Apply This Rollback + +Just say "Apply rollback" and I'll make the code changes immediately! diff --git a/SESSION_TIMEOUT_ANALYSIS.md b/SESSION_TIMEOUT_ANALYSIS.md new file mode 100644 index 0000000..47f33a4 --- /dev/null +++ b/SESSION_TIMEOUT_ANALYSIS.md @@ -0,0 +1,297 @@ +# Deep Analysis: Session Timeout Issue + +**Created:** October 2, 2025 +**Issue:** Users logged out after 5-6 minutes instead of 1 hour + +--- + +## πŸ” Complete Code Flow Analysis + +### 1. Session Creation (Login) +**File:** `auth/user_manager_postgres.py` lines 104-128 + +**Flow:** +```python +current_time = datetime.now() # timezone-naive +expires_at = current_time + timedelta(hours=24) + +INSERT INTO sessions (user_id, token, expires_at, last_activity) +VALUES (user_id, token, expires_at, current_time) +``` + +**Potential Issues:** +- βœ… current_time is timezone-naive (correct) +- βœ… last_activity is set explicitly +- ❓ How does PostgreSQL store this datetime? + +--- + +### 2. Activity Updates (Every WebSocket Message) +**File:** `handlers/authenticated_ws_handler.py` lines 280, 291 + +**Triggered by:** +- Every authenticated WebSocket message (line 291) +- Every keepalive pong (line 280) + +**Flow:** +```python +current_time = datetime.now() # timezone-naive + +UPDATE sessions SET last_activity = current_time +WHERE token = session_id AND is_active = true +``` + +**Frequency:** Every 30-60 seconds (due to keepalive pings) + +**Potential Issues:** +- βœ… Updates are happening frequently +- βœ… Uses timezone-naive datetime.now() +- ❓ Does PostgreSQL convert this on storage? + +--- + +### 3. Session Validation (On Every Request) +**File:** `auth/user_manager_postgres.py` lines 144-228 + +**When called:** +- WebSocket connection open (line 366 in authenticated_ws_handler.py) +- Possibly other API endpoints + +**Flow:** +```python +# 1. Fetch session from database +SELECT s.*, u.username FROM sessions s JOIN users u +WHERE s.token = token AND s.is_active = true AND s.expires_at > NOW() + +# 2. Get last_activity (this is the problem area) +last_activity = session.get("last_activity") + +# 3. Calculate idle duration +idle_duration = datetime.now() - last_activity + +# 4. Check if > 1 hour +if idle_duration > timedelta(hours=1): + logout() +``` + +**Potential Issues:** +- ❓ What type/timezone is `last_activity` when read from PostgreSQL? +- ❓ Is the subtraction giving correct result? +- ❓ Is validation called too frequently? + +--- + +## πŸ› Most Likely Root Causes + +### Theory #1: PostgreSQL Timezone Conversion (90% probability) + +**Scenario:** +```python +# We store +datetime.now() = 2025-10-02 15:00:00 (naive, Eastern Time) + +# PostgreSQL might interpret this as UTC +# When read back, psycopg2 might add timezone +last_activity = 2025-10-02 15:00:00+00:00 (UTC) + +# Then when we compare +current = 2025-10-02 15:06:00 (Eastern, naive) +last = 2025-10-02 15:00:00+00:00 (UTC, aware) + +# Python sees this as +current (Eastern 3:06 PM) - last (UTC 3:00 PM = Eastern 11:00 AM) += 4 hours 6 minutes ❌ WRONG! +``` + +**How to confirm:** +Look in debug logs for `Last activity raw` - if it has a timezone, this is the issue. + +**Fix:** +```python +# In database.py connection config +connection_params = { + 'options': '-c timezone=UTC', # Force specific timezone +} +``` + +--- + +### Theory #2: psycopg2 Returns Timezone-Aware Datetimes (80% probability) + +**Scenario:** +Even though we store naive datetimes, psycopg2 might return them as timezone-aware based on server settings. + +**How to confirm:** +Debug logs will show: `(type: , tz: )` + +**Fix:** +```python +# After reading from database, always strip timezone +if hasattr(last_activity, 'tzinfo') and last_activity.tzinfo is not None: + last_activity = last_activity.replace(tzinfo=None) +``` + +This is already in the code, but might not be working if the timezone is getting re-added somewhere. + +--- + +### Theory #3: Server Timezone != User Timezone (50% probability) + +**Scenario:** +``` +Server (AWS): UTC timezone +User: Eastern Time (-4 hours from UTC) + +Store: 15:00:00 (user's local time, but server thinks it's UTC) +Read: 15:00:00 (server interprets as UTC) +Current: 19:00:00 (server's UTC time) +Diff: 4 hours ❌ +``` + +**How to confirm:** +Compare `[SESSION-CREATE] Current time` with your actual local time. + +**Fix:** +Always use UTC everywhere: +```python +from datetime import timezone +current_time = datetime.now(timezone.utc).replace(tzinfo=None) +``` + +--- + +### Theory #4: Background Cleanup Job Interference (20% probability) + +**File:** `auth/user_manager_postgres.py` lines 608-660, 677-698 + +**Scenario:** +The IdleSessionCleanupJob runs every 5 minutes and might have a bug. + +**How to confirm:** +Search logs for "cleanup_idle_sessions" or "Terminated idle WebSocket" + +**Fix:** +Disable the cleanup job temporarily (see rollback guide). + +--- + +## πŸ”¬ PostgreSQL Column Type Investigation + +The `last_activity` column type is critical: + +```sql +-- Check the exact data type +SELECT column_name, data_type, datetime_precision, + column_default, is_nullable +FROM information_schema.columns +WHERE table_name = 'sessions' AND column_name = 'last_activity'; +``` + +**Possible results:** +- `TIMESTAMP WITHOUT TIME ZONE` βœ… Good - stores as-is, no conversion +- `TIMESTAMP WITH TIME ZONE` ❌ Bad - PostgreSQL converts to UTC +- `TIMESTAMP` ❓ Ambiguous - depends on server settings + +--- + +## πŸ“Š Validation Frequency Analysis + +**Current setup:** +- `update_session_activity()` called every ~45 seconds (keepalive ping) +- `validate_session()` called on: + - WebSocket open (once per connection) + - Possibly on every HTTP request + +**This should be fine** - updates are more frequent than validation. + +But if `validate_session()` is called on EVERY WebSocket message (not just on open), that could cause performance issues and make the bug more noticeable. + +--- + +## 🎯 Debugging Strategy + +### Phase 1: Deploy Debug Logging (DONE) +βœ… Added comprehensive logging to all session methods + +### Phase 2: Collect Logs (NEXT) +Test the system and collect: +1. Login logs - verify initial timestamp +2. Activity update logs - verify updates happen +3. Validation logs - see the exact calculation +4. Timeout logs - if logout happens, see why + +### Phase 3: Analyze Logs +Look for: +- Timezone mismatches +- Time discrepancies +- Incorrect idle duration calculations + +### Phase 4: Fix or Rollback +- If issue is clear: Apply targeted fix +- If issue is unclear: Rollback and debug offline + +--- + +## πŸ’‘ Recommended Next Steps + +**Option A: Debug First (Recommended if you can tolerate the issue for 1-2 days)** +1. Deploy the debug logging version +2. Have a few users test it +3. Collect and analyze logs +4. Apply targeted fix +5. Re-enable with confidence + +**Option B: Rollback Now (Recommended if users are frustrated)** +1. Apply the rollback (removes auto-logout, keeps single-session) +2. Deploy debug logging in background +3. Collect logs from normal usage +4. Fix offline +5. Re-enable when ready + +--- + +## πŸ”§ Quick Fixes to Try (If You Want) + +### Fix #1: Force UTC Everywhere +```python +# In user_manager_postgres.py, replace all datetime.now() with: +from datetime import timezone +datetime.now(timezone.utc).replace(tzinfo=None) +``` + +### Fix #2: Check PostgreSQL Timezone Setting +```sql +-- On database +SHOW timezone; + +-- If not 'UTC', change it +ALTER DATABASE pythonide SET timezone TO 'UTC'; +``` + +### Fix #3: Use Unix Timestamps Instead +```python +# Store as integer (seconds since epoch) +import time +last_activity = int(time.time()) + +# Compare +idle_seconds = time.time() - last_activity +if idle_seconds > 3600: # 1 hour + logout() +``` + +This eliminates ALL timezone issues. + +--- + +## πŸ“ Summary + +**Most Likely Cause:** PostgreSQL timezone conversion + +**Certainty:** 80% + +**Best Next Step:** Deploy debug logging and collect data OR apply rollback + +**Long-term Fix:** Switch to UTC timestamps or Unix epoch time + +Let me know which approach you prefer! diff --git a/server/auth/user_manager_postgres.py b/server/auth/user_manager_postgres.py index f2fb646..02a1f9d 100644 --- a/server/auth/user_manager_postgres.py +++ b/server/auth/user_manager_postgres.py @@ -106,6 +106,12 @@ def authenticate(self, username, password): current_time = datetime.now() expires_at = current_time + timedelta(hours=24) + # DEBUG LOGGING - Remove after debugging + logger.info(f"[SESSION-CREATE] Creating session for user {username}") + logger.info(f"[SESSION-CREATE] Current time: {current_time} (type: {type(current_time)}, tz: {current_time.tzinfo})") + logger.info(f"[SESSION-CREATE] Expires at: {expires_at}") + logger.info(f"[SESSION-CREATE] Initial last_activity: {current_time}") + session_query = ( """ INSERT INTO sessions (user_id, token, expires_at, last_activity) @@ -119,6 +125,7 @@ def authenticate(self, username, password): ) self.db.execute_query(session_query, (user_id, token, expires_at, current_time)) + logger.info(f"[SESSION-CREATE] Session created successfully for {username}") # Update last login update_query = ( @@ -169,28 +176,51 @@ def validate_session(self, token): # AUTO-LOGOUT: Check for 1-hour inactivity timeout last_activity = session.get("last_activity") + + # DEBUG LOGGING - Remove after debugging + current_time = datetime.now() + logger.info(f"[SESSION-DEBUG] User: {session['username']}") + logger.info(f"[SESSION-DEBUG] Current time: {current_time} (type: {type(current_time)}, tz: {current_time.tzinfo})") + logger.info(f"[SESSION-DEBUG] Last activity raw: {last_activity} (type: {type(last_activity)})") + if last_activity: + original_last_activity = last_activity # Store original for logging + # Handle both string and datetime types, ensuring timezone-naive comparison if isinstance(last_activity, str): # Parse ISO format string and strip timezone info to match datetime.now() last_activity = datetime.fromisoformat(last_activity.replace("Z", "+00:00")) + logger.info(f"[SESSION-DEBUG] Parsed from string: {last_activity} (tz: {last_activity.tzinfo})") # Convert to naive datetime by removing timezone info if last_activity.tzinfo is not None: last_activity = last_activity.replace(tzinfo=None) + logger.info(f"[SESSION-DEBUG] After stripping timezone: {last_activity}") elif isinstance(last_activity, datetime): + logger.info(f"[SESSION-DEBUG] Already datetime: {last_activity} (tz: {last_activity.tzinfo})") # If datetime object has timezone, remove it for consistent comparison if last_activity.tzinfo is not None: last_activity = last_activity.replace(tzinfo=None) + logger.info(f"[SESSION-DEBUG] After stripping timezone: {last_activity}") # Both datetimes are now timezone-naive, safe to subtract - idle_duration = datetime.now() - last_activity + idle_duration = current_time - last_activity INACTIVITY_TIMEOUT = timedelta(hours=1) # 1 hour timeout + # DEBUG LOGGING + logger.info(f"[SESSION-DEBUG] Final last_activity: {last_activity} (tz: {last_activity.tzinfo})") + logger.info(f"[SESSION-DEBUG] Idle duration: {idle_duration} (seconds: {idle_duration.total_seconds()})") + logger.info(f"[SESSION-DEBUG] Timeout threshold: {INACTIVITY_TIMEOUT} (seconds: {INACTIVITY_TIMEOUT.total_seconds()})") + logger.info(f"[SESSION-DEBUG] Will logout? {idle_duration > INACTIVITY_TIMEOUT}") + if idle_duration > INACTIVITY_TIMEOUT: # Session expired due to inactivity - logger.info(f"Session for {session['username']} expired due to inactivity ({idle_duration})") + logger.warning(f"[SESSION-TIMEOUT] User {session['username']} logged out due to inactivity") + logger.warning(f"[SESSION-TIMEOUT] Idle duration: {idle_duration} > threshold: {INACTIVITY_TIMEOUT}") + logger.warning(f"[SESSION-TIMEOUT] Last activity was: {original_last_activity}") self.logout(token) return None + else: + logger.warning(f"[SESSION-DEBUG] No last_activity found for user {session['username']}") # With RealDictCursor, this will always be a dict return { @@ -207,6 +237,11 @@ def validate_session(self, token): def update_session_activity(self, token): """Update last_activity timestamp for a session""" try: + current_time = datetime.now() + + # DEBUG LOGGING - Remove after debugging + logger.info(f"[ACTIVITY-UPDATE] Updating session activity to: {current_time} (type: {type(current_time)}, tz: {current_time.tzinfo})") + query = ( """ UPDATE sessions SET last_activity = %s @@ -219,7 +254,8 @@ def update_session_activity(self, token): """ ) - self.db.execute_query(query, (datetime.now(), token)) + self.db.execute_query(query, (current_time, token)) + logger.info(f"[ACTIVITY-UPDATE] Session activity updated successfully") return True except Exception as e: logger.error(f"Failed to update session activity: {e}") From c20ea86e40e69da35fb0768cb87d62decc4c6f35 Mon Sep 17 00:00:00 2001 From: sachin9082 Date: Thu, 2 Oct 2025 20:36:08 -0400 Subject: [PATCH 2/2] Rollback: Disable auto-logout after inactivity - Temporarily disable 1-hour inactivity timeout - Single-session enforcement still active - Session activity tracking preserved for debugging - Auto-logout will be fixed and re-enabled after proper debugging --- server/auth/user_manager_postgres.py | 123 +++++++-------------------- 1 file changed, 31 insertions(+), 92 deletions(-) diff --git a/server/auth/user_manager_postgres.py b/server/auth/user_manager_postgres.py index 02a1f9d..107e61a 100644 --- a/server/auth/user_manager_postgres.py +++ b/server/auth/user_manager_postgres.py @@ -174,53 +174,25 @@ def validate_session(self, token): session = sessions[0] - # AUTO-LOGOUT: Check for 1-hour inactivity timeout - last_activity = session.get("last_activity") - - # DEBUG LOGGING - Remove after debugging - current_time = datetime.now() - logger.info(f"[SESSION-DEBUG] User: {session['username']}") - logger.info(f"[SESSION-DEBUG] Current time: {current_time} (type: {type(current_time)}, tz: {current_time.tzinfo})") - logger.info(f"[SESSION-DEBUG] Last activity raw: {last_activity} (type: {type(last_activity)})") - - if last_activity: - original_last_activity = last_activity # Store original for logging - - # Handle both string and datetime types, ensuring timezone-naive comparison - if isinstance(last_activity, str): - # Parse ISO format string and strip timezone info to match datetime.now() - last_activity = datetime.fromisoformat(last_activity.replace("Z", "+00:00")) - logger.info(f"[SESSION-DEBUG] Parsed from string: {last_activity} (tz: {last_activity.tzinfo})") - # Convert to naive datetime by removing timezone info - if last_activity.tzinfo is not None: - last_activity = last_activity.replace(tzinfo=None) - logger.info(f"[SESSION-DEBUG] After stripping timezone: {last_activity}") - elif isinstance(last_activity, datetime): - logger.info(f"[SESSION-DEBUG] Already datetime: {last_activity} (tz: {last_activity.tzinfo})") - # If datetime object has timezone, remove it for consistent comparison - if last_activity.tzinfo is not None: - last_activity = last_activity.replace(tzinfo=None) - logger.info(f"[SESSION-DEBUG] After stripping timezone: {last_activity}") - - # Both datetimes are now timezone-naive, safe to subtract - idle_duration = current_time - last_activity - INACTIVITY_TIMEOUT = timedelta(hours=1) # 1 hour timeout - - # DEBUG LOGGING - logger.info(f"[SESSION-DEBUG] Final last_activity: {last_activity} (tz: {last_activity.tzinfo})") - logger.info(f"[SESSION-DEBUG] Idle duration: {idle_duration} (seconds: {idle_duration.total_seconds()})") - logger.info(f"[SESSION-DEBUG] Timeout threshold: {INACTIVITY_TIMEOUT} (seconds: {INACTIVITY_TIMEOUT.total_seconds()})") - logger.info(f"[SESSION-DEBUG] Will logout? {idle_duration > INACTIVITY_TIMEOUT}") - - if idle_duration > INACTIVITY_TIMEOUT: - # Session expired due to inactivity - logger.warning(f"[SESSION-TIMEOUT] User {session['username']} logged out due to inactivity") - logger.warning(f"[SESSION-TIMEOUT] Idle duration: {idle_duration} > threshold: {INACTIVITY_TIMEOUT}") - logger.warning(f"[SESSION-TIMEOUT] Last activity was: {original_last_activity}") - self.logout(token) - return None - else: - logger.warning(f"[SESSION-DEBUG] No last_activity found for user {session['username']}") + # AUTO-LOGOUT: TEMPORARILY DISABLED + # + # The auto-logout after 1 hour of inactivity has been temporarily disabled + # because users were getting logged out prematurely (5-6 minutes instead of 1 hour). + # + # Single-session enforcement (lines 89-102) is still ACTIVE and working correctly. + # Activity tracking (update_session_activity) is still ACTIVE for future debugging. + # + # Session still expires after 24 hours (checked at line 152 via expires_at column). + # + # TO RE-ENABLE AFTER FIXING: + # 1. Switch back to the feat/user-session branch (has the full implementation) + # 2. Review DEBUG_SESSION_TIMEOUT.md for debugging steps + # 3. Collect production logs to identify root cause + # 4. Fix the timezone/timing issue + # 5. Test thoroughly with debug logging + # 6. Merge the fix back + # + # Original code preserved in git history and feat/user-session branch # With RealDictCursor, this will always be a dict return { @@ -644,54 +616,21 @@ def get_all_users_for_admin(self, admin_username): def cleanup_idle_sessions(self): """ Cleanup sessions that have been idle for more than 1 hour. - This is called periodically by background job. - """ - try: - INACTIVITY_TIMEOUT = timedelta(hours=1) # 1 hour timeout - cutoff_time = datetime.now() - INACTIVITY_TIMEOUT - - query = ( - """ - UPDATE sessions SET is_active = false - WHERE last_activity < %s AND is_active = true - """ - if self.db.is_postgres - else """ - UPDATE sessions SET is_active = 0 - WHERE last_activity < ? AND is_active = 1 - """ - ) - - result = self.db.execute_query(query, (cutoff_time,)) + TEMPORARILY DISABLED - Returns empty list. - # Get list of affected users to terminate their WebSocket connections - affected_query = ( - """ - SELECT DISTINCT u.username - FROM sessions s - JOIN users u ON s.user_id = u.id - WHERE s.last_activity < %s AND s.is_active = false - """ - if self.db.is_postgres - else """ - SELECT DISTINCT u.username - FROM sessions s - JOIN users u ON s.user_id = u.id - WHERE s.last_activity < ? AND s.is_active = 0 - """ - ) - - affected_users = self.db.execute_query(affected_query, (cutoff_time,)) - - if affected_users: - logger.info(f"Cleaned up {len(affected_users)} idle sessions") - return [user["username"] for user in affected_users] + This is called periodically by IdleSessionCleanupJob (every 5 minutes) + but does nothing until the auto-logout timeout issue is debugged and fixed. - return [] + The background job will continue running but won't terminate any sessions. - except Exception as e: - logger.error(f"Error cleaning up idle sessions: {e}") - return [] + TO RE-ENABLE AFTER FIXING: + 1. Switch back to feat/user-session branch (has full implementation) + 2. Debug and fix the timeout calculation issue + 3. Test thoroughly with debug logging + 4. Restore this method from git history + """ + logger.debug("Idle session cleanup temporarily disabled (rollback)") + return [] # No users to cleanup # Background job for idle session cleanup