diff --git a/src/openhuman/app_state/ops.rs b/src/openhuman/app_state/ops.rs index d94a49b86..d05d7a9fd 100644 --- a/src/openhuman/app_state/ops.rs +++ b/src/openhuman/app_state/ops.rs @@ -14,11 +14,13 @@ use serde_json::Value; use tempfile::NamedTempFile; use crate::api::config::effective_backend_api_url; -use crate::api::jwt::{bearer_authorization_value, get_session_token}; +use crate::api::jwt::bearer_authorization_value; use crate::openhuman::autocomplete::AutocompleteStatus; use crate::openhuman::config::rpc as config_rpc; use crate::openhuman::config::Config; -use crate::openhuman::credentials::session_support::build_session_state; +use crate::openhuman::credentials::session_support::{ + load_app_session_profile, session_state_from_profile, session_token_from_profile, +}; use crate::openhuman::inference::LocalAiStatus; use crate::openhuman::screen_intelligence::AccessibilityStatus; use crate::openhuman::service::{ServiceState, ServiceStatus}; @@ -446,8 +448,16 @@ async fn build_runtime_snapshot(config: &Config) -> RuntimeSnapshot { pub async fn snapshot() -> Result, String> { let config = config_rpc::load_config_with_timeout().await?; - let mut auth = build_session_state(&config)?; - let session_token = get_session_token(&config)?; + // Load the `app-session` auth profile exactly once and derive both + // the session-state view and the raw token from it. The previous + // implementation called `build_session_state` + `get_session_token` + // separately, which acquired the auth-profile file lock twice per + // snapshot. On Windows this doubled the surface area for the + // "Timed out waiting for auth profile lock" failure reported in + // Sentry against `openhuman.app_state_snapshot`. + let session_profile = load_app_session_profile(&config)?; + let mut auth = session_state_from_profile(session_profile.as_ref()); + let session_token = session_token_from_profile(session_profile.as_ref()); let stored_user = sanitize_snapshot_user(auth.user.clone()); let current_user = if let Some(token) = session_token.clone().filter(|t| !t.trim().is_empty()) { match fetch_current_user_cached(&config, &token).await { diff --git a/src/openhuman/credentials/profiles.rs b/src/openhuman/credentials/profiles.rs index 75d97b51b..c2a589f7a 100644 --- a/src/openhuman/credentials/profiles.rs +++ b/src/openhuman/credentials/profiles.rs @@ -7,13 +7,22 @@ use std::fs::{self, OpenOptions}; use std::io::Write; use std::path::{Path, PathBuf}; use std::thread; -use std::time::Duration; +use std::time::{Duration, Instant}; const CURRENT_SCHEMA_VERSION: u32 = 1; const PROFILES_FILENAME: &str = "auth-profiles.json"; const LOCK_FILENAME: &str = "auth-profiles.lock"; const LOCK_WAIT_MS: u64 = 50; const LOCK_TIMEOUT_MS: u64 = 10_000; +/// A lock file that has existed for longer than this is treated as leaked +/// (its owner crashed without unlinking it, or `fs::remove_file` in the +/// guard's `Drop` was rejected by Windows AV/indexer and the file got +/// orphaned with the still-alive owner's pid in it). No legitimate +/// auth-profile operation holds the lock for anywhere near this long — +/// load+save is a tiny JSON read followed by an atomic rename. The +/// threshold is intentionally well above any realistic operation time +/// so we never reclaim under a slow-but-legitimate holder. +const STALE_LOCK_AGE_MS: u64 = 30_000; #[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize)] #[serde(rename_all = "kebab-case")] @@ -529,8 +538,21 @@ impl AuthProfilesStore { .with_context(|| "Failed to create auth profile lock directory".to_string())?; } - let mut waited = 0_u64; + // Drive timeout + stale-recheck off wall-clock elapsed time, not the + // sum of explicit `thread::sleep(LOCK_WAIT_MS)` calls. The earlier + // counter-based approach excluded time spent inside + // `retry_with_backoff` (which can sleep up to ~30s on its own + // schedule before returning AlreadyExists) and the lock-file I/O + // syscalls. Under Windows AV contention that drift could push + // both `LOCK_TIMEOUT_MS` and `next_stale_recheck_ms` significantly + // later than intended. + let started_at = Instant::now(); let mut cleared_stale = false; + // Periodically re-probe for stale locks during the busy-wait. A + // lock that started fresh (live pid, recent mtime) can age past + // STALE_LOCK_AGE_MS while we wait, and we want to recover from + // that without bailing at the LOCK_TIMEOUT_MS boundary. + let mut next_stale_recheck_ms: u64 = 1_000; loop { let open_result = crate::openhuman::util::retry_with_backoff( "create auth profile lock", @@ -586,12 +608,25 @@ impl AuthProfilesStore { if self.clear_lock_if_stale() { continue; } + } else { + let elapsed_ms = started_at.elapsed().as_millis() as u64; + if elapsed_ms >= next_stale_recheck_ms { + // The age-based reclaim check is cheap (one + // `fs::metadata` call in the common case) and + // safely no-ops on fresh, legitimate locks. + // Re-probing periodically lets us recover from + // a leaked-mid-wait lock without bailing at + // the 10s timeout. + next_stale_recheck_ms = next_stale_recheck_ms.saturating_add(1_000); + if self.clear_lock_if_stale() { + continue; + } + } } - if waited >= LOCK_TIMEOUT_MS { + if started_at.elapsed().as_millis() as u64 >= LOCK_TIMEOUT_MS { anyhow::bail!("Timed out waiting for auth profile lock"); } thread::sleep(Duration::from_millis(LOCK_WAIT_MS)); - waited = waited.saturating_add(LOCK_WAIT_MS); } else { // Sentry OPENHUMAN-TAURI-H8 collapses every // non-AlreadyExists, non-transient `create_new` @@ -609,12 +644,46 @@ impl AuthProfilesStore { } } - /// Returns `true` if an existing lock file was detected as stale (its - /// recorded PID is no longer running) and successfully removed. - /// Malformed locks (no `pid=` line) and locks whose PID is still alive - /// are left in place so the caller falls back to the normal busy-wait - /// and timeout path. + /// Returns `true` if an existing lock file was detected as stale and + /// successfully removed. Two cases reclaim: + /// + /// 1. The recorded `pid=` line points at a process that is no longer + /// running — classic crashed-owner recovery (Issue #1612). + /// 2. The lock file's mtime is older than [`STALE_LOCK_AGE_MS`]. This + /// catches the Windows case where the previous owner's + /// `AuthProfileLockGuard::drop` could not unlink the file (AV / + /// indexer briefly held a handle) and orphaned the lock with its + /// still-alive pid inside — every subsequent acquirer would + /// otherwise spin the full 10s `LOCK_TIMEOUT_MS` and bail. No + /// legitimate auth-profile op holds the lock long enough to be + /// affected, so a too-old lock is unambiguously a leak. + /// + /// Malformed locks (no `pid=` line) are reclaimed only when they are + /// also too old, since a fresh malformed lock might still indicate an + /// in-flight writer that crashed between `create_new` and the `pid=` + /// write. fn clear_lock_if_stale(&self) -> bool { + let metadata = match fs::metadata(&self.lock_path) { + Ok(m) => m, + Err(e) if e.kind() == std::io::ErrorKind::NotFound => return false, + Err(e) => { + tracing::warn!( + target: "auth-profiles", + "[credentials] failed to stat lock file at {} for stale check: {e}", + self.lock_path.display() + ); + return false; + } + }; + + let too_old = match metadata.modified() { + Ok(mtime) => std::time::SystemTime::now() + .duration_since(mtime) + .map(|age| age >= Duration::from_millis(STALE_LOCK_AGE_MS)) + .unwrap_or(false), + Err(_) => false, + }; + let content = match fs::read_to_string(&self.lock_path) { Ok(s) => s, Err(e) if e.kind() == std::io::ErrorKind::NotFound => return false, @@ -632,24 +701,34 @@ impl AuthProfilesStore { .lines() .find_map(|line| line.trim().strip_prefix("pid=")?.trim().parse::().ok()); - let Some(pid) = pid else { - tracing::warn!( - target: "auth-profiles", - "[credentials] lock at {} has no parseable pid line; leaving in place", - self.lock_path.display() - ); - return false; + let reclaim_reason: Option = match pid { + Some(pid) if !is_pid_alive(pid) => Some(format!("pid {pid} not alive")), + Some(pid) if too_old => Some(format!( + "lock file older than {STALE_LOCK_AGE_MS}ms (recorded pid {pid}, presumed leaked)" + )), + None if too_old => Some(format!( + "lock file older than {STALE_LOCK_AGE_MS}ms with no parseable pid" + )), + Some(_) => return false, + None => { + tracing::warn!( + target: "auth-profiles", + "[credentials] lock at {} has no parseable pid line; leaving in place", + self.lock_path.display() + ); + return false; + } }; - if is_pid_alive(pid) { + let Some(reason) = reclaim_reason else { return false; - } + }; match fs::remove_file(&self.lock_path) { Ok(()) => { tracing::info!( target: "auth-profiles", - "[credentials] removed stale auth profile lock at {} (pid {pid} not alive)", + "[credentials] removed stale auth profile lock at {} ({reason})", self.lock_path.display() ); true @@ -658,7 +737,7 @@ impl AuthProfilesStore { Err(e) => { tracing::warn!( target: "auth-profiles", - "[credentials] failed to remove stale lock at {}: {e}", + "[credentials] failed to remove stale lock at {} ({reason}): {e}", self.lock_path.display() ); false @@ -706,7 +785,35 @@ struct AuthProfileLockGuard { impl Drop for AuthProfileLockGuard { fn drop(&mut self) { - let _ = fs::remove_file(&self.lock_path); + // Best-effort unlink with retries. On Windows, antivirus and the + // search indexer routinely hold a transient handle on a file just + // after it is written, which makes `fs::remove_file` fail with + // `PermissionDenied`. A failed unlink here leaks the lock file + // with the still-alive owner pid inside, which would cause every + // subsequent acquirer to spin the full `LOCK_TIMEOUT_MS` and bail + // with "Timed out waiting for auth profile lock". The age-based + // reclaim in `clear_lock_if_stale` is the safety net; this retry + // loop is the first line of defence so we don't rely on it. + for attempt in 0..5u32 { + match fs::remove_file(&self.lock_path) { + Ok(()) => return, + Err(e) if e.kind() == std::io::ErrorKind::NotFound => return, + Err(e) => { + if attempt + 1 == 5 { + tracing::warn!( + target: "auth-profiles", + "[credentials] failed to remove auth profile lock at {} after {} attempts: {e}. \ + The age-based stale-lock reclaim will recover within {}ms.", + self.lock_path.display(), + attempt + 1, + STALE_LOCK_AGE_MS, + ); + return; + } + thread::sleep(Duration::from_millis(50u64.saturating_mul(1u64 << attempt))); + } + } + } } } diff --git a/src/openhuman/credentials/profiles_tests.rs b/src/openhuman/credentials/profiles_tests.rs index 68056e9f2..d01a299ee 100644 --- a/src/openhuman/credentials/profiles_tests.rs +++ b/src/openhuman/credentials/profiles_tests.rs @@ -442,6 +442,59 @@ fn acquire_lock_writes_pid_so_future_callers_can_recover() { assert!(!lock_path.exists(), "guard must remove lock on drop"); } +/// Sentry "Timed out waiting for auth profile lock" recovery: a lock +/// file that has been around for longer than `STALE_LOCK_AGE_MS` is +/// treated as leaked even if its recorded pid is still alive. This +/// covers the Windows AV / indexer case where `Drop::drop` on the +/// previous guard could not unlink the file and orphaned it with the +/// still-alive owner pid inside. +#[test] +fn clear_lock_if_stale_reclaims_lock_older_than_threshold_even_with_live_pid() { + let tmp = TempDir::new().unwrap(); + let store = AuthProfilesStore::new(tmp.path(), false); + + let lock_path = tmp.path().join(LOCK_FILENAME); + std::fs::write(&lock_path, format!("pid={}\n", std::process::id())).unwrap(); + // Backdate the lock-file mtime well past STALE_LOCK_AGE_MS. + let aged = + std::time::SystemTime::now() - std::time::Duration::from_millis(STALE_LOCK_AGE_MS + 5_000); + std::fs::OpenOptions::new() + .write(true) + .open(&lock_path) + .expect("reopen lock for set_modified") + .set_modified(aged) + .expect("backdate lock mtime"); + + assert!( + store.clear_lock_if_stale(), + "an aged lock with a live pid must be reclaimed (leaked-by-failed-unlink case)" + ); + assert!(!lock_path.exists(), "stale lock should have been removed"); +} + +#[test] +fn clear_lock_if_stale_reclaims_aged_malformed_lock() { + let tmp = TempDir::new().unwrap(); + let store = AuthProfilesStore::new(tmp.path(), false); + + let lock_path = tmp.path().join(LOCK_FILENAME); + std::fs::write(&lock_path, "garbage without a pid line\n").unwrap(); + let aged = + std::time::SystemTime::now() - std::time::Duration::from_millis(STALE_LOCK_AGE_MS + 5_000); + std::fs::OpenOptions::new() + .write(true) + .open(&lock_path) + .expect("reopen lock for set_modified") + .set_modified(aged) + .expect("backdate lock mtime"); + + assert!( + store.clear_lock_if_stale(), + "an aged malformed lock should be reclaimed" + ); + assert!(!lock_path.exists()); +} + /// Sentry OPENHUMAN-TAURI-H8: when `OpenOptions::create_new` fails with /// anything other than `AlreadyExists`, the error surfaced to Sentry /// must embed the underlying `io::ErrorKind` and `raw_os_error()` so we diff --git a/src/openhuman/credentials/session_support.rs b/src/openhuman/credentials/session_support.rs index 8fdb62263..add4255ea 100644 --- a/src/openhuman/credentials/session_support.rs +++ b/src/openhuman/credentials/session_support.rs @@ -2,7 +2,7 @@ use crate::openhuman::config::Config; -use super::profiles::{AuthProfileKind, TokenSet}; +use super::profiles::{AuthProfile, AuthProfileKind, TokenSet}; use super::responses::{AuthProfileSummary, AuthStateResponse}; use super::AuthService; @@ -87,18 +87,37 @@ fn session_user_value( } pub fn build_session_state(config: &Config) -> Result { - let auth_service = AuthService::from_config(config); - let profile = auth_service - .get_profile(APP_SESSION_PROVIDER, None) - .map_err(|e| e.to_string())?; + let profile = load_app_session_profile(config)?; + Ok(session_state_from_profile(profile.as_ref())) +} +pub fn get_session_token(config: &Config) -> Result, String> { + let profile = load_app_session_profile(config)?; + Ok(session_token_from_profile(profile.as_ref())) +} + +/// Load the `app-session` profile once. Callers that need both the +/// session-state view (`session_state_from_profile`) AND the raw token +/// (`session_token_from_profile`) should call this once and pass the +/// result to both helpers — every load takes the auth-profile store +/// lock, and on Windows the `app_state_snapshot` hot path used to take +/// it twice per call which materially increased lock contention +/// (Sentry: "Timed out waiting for auth profile lock"). +pub fn load_app_session_profile(config: &Config) -> Result, String> { + let auth_service = AuthService::from_config(config); + auth_service + .get_profile(APP_SESSION_PROVIDER, None) + .map_err(|e| e.to_string()) +} + +pub fn session_state_from_profile(profile: Option<&AuthProfile>) -> AuthStateResponse { let Some(profile) = profile else { - return Ok(AuthStateResponse { + return AuthStateResponse { is_authenticated: false, user_id: None, user: None, profile_id: None, - }); + }; }; let is_authenticated = profile @@ -107,20 +126,24 @@ pub fn build_session_state(config: &Config) -> Result .map(|token| !token.trim().is_empty()) .unwrap_or(false); - Ok(AuthStateResponse { + AuthStateResponse { is_authenticated, user_id: profile.metadata.get("user_id").cloned(), - user: session_user_value(&profile), - profile_id: Some(profile.id), - }) + user: session_user_value(profile), + profile_id: Some(profile.id.clone()), + } } -pub fn get_session_token(config: &Config) -> Result, String> { - let auth_service = AuthService::from_config(config); - let profile = auth_service - .get_profile(APP_SESSION_PROVIDER, None) - .map_err(|e| e.to_string())?; - Ok(profile.and_then(|entry| entry.token)) +pub fn session_token_from_profile(profile: Option<&AuthProfile>) -> Option { + // Mirror the `is_authenticated` check in `session_state_from_profile` + // (trim + non-empty) so the two views of the same profile never + // disagree — i.e. we never return `Some(" ")` while reporting + // `is_authenticated = false`. + profile + .and_then(|entry| entry.token.as_deref()) + .map(str::trim) + .filter(|token| !token.is_empty()) + .map(str::to_string) } #[cfg(test)] @@ -316,6 +339,29 @@ mod tests { assert!(get_session_token(&config).unwrap().is_none()); } + /// Regression for CodeRabbit feedback on PR #2085: a profile whose + /// token is whitespace-only must come back as `None`, matching the + /// `is_authenticated` view (which trims + filters empty). + #[test] + fn session_token_from_profile_normalises_blank_tokens_to_none() { + let p_blank = profile_fixture(AuthProfileKind::Token, Some(" ")); + assert!(session_token_from_profile(Some(&p_blank)).is_none()); + + let p_empty = profile_fixture(AuthProfileKind::Token, Some("")); + assert!(session_token_from_profile(Some(&p_empty)).is_none()); + + let p_none = profile_fixture(AuthProfileKind::Token, None); + assert!(session_token_from_profile(Some(&p_none)).is_none()); + + let p_real = profile_fixture(AuthProfileKind::Token, Some(" tok ")); + // Trim leaks into the returned value — this matches the + // `is_authenticated` semantic that " tok " is a real token. + assert_eq!( + session_token_from_profile(Some(&p_real)).as_deref(), + Some("tok") + ); + } + #[test] fn get_session_token_returns_stored_token_when_present() { let tmp = TempDir::new().unwrap();