diff --git a/CHANGELOG.md b/CHANGELOG.md index 20554f2..1b9641d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,11 @@ ### Changes +- Fixed playtime briefly landing in the offline file every time the session was refreshed: the tracker now retries with the fresh session immediately, and the session is refreshed earlier so a token never expires in the middle of a tick. +- Fixed playtime stopping to count while a game was running: the tracker now asks for a fresh session as soon as the server rejects an increment, pauses its requests instead of retrying every minute, and credits the minutes it stored offline as soon as the session works again. +- Fixed playtime that was stored offline being stranded until an app restart: offline minutes are now synced in the background and immediately when the connection or the session returns. +- Fixed the time tracker re-scanning every installed game's folder every minute, which could delay ticks on large installations. +- Fixed playtime being lost when a game's launcher briefly restarts the game process: tracking now continues for a short grace period instead of ending the session. - Added a Refresh button to the window title bar that reloads the current page. - Auto-install on Linux now makes extracted shell scripts (`.sh`/`.bash`/`.run`/etc.) executable automatically. - Fixed "Open Folder" doing nothing on Linux: folder and URL opening now use the official `tauri-plugin-opener`, with WSL support preserved. diff --git a/src-tauri/src/games.rs b/src-tauri/src/games.rs index 903250e..a129eca 100644 --- a/src-tauri/src/games.rs +++ b/src-tauri/src/games.rs @@ -396,20 +396,72 @@ pub(crate) fn open_external_url(url: String) -> Result<(), String> { .map_err(|e| format!("Failed to open URL: {e}")) } +/// Safety limits for the recursive candidate walk: a game folder can contain +/// a huge file tree (or a junction to one), and the walk runs on every tracker +/// tick for every installed game. +const MAX_CANDIDATE_DEPTH: usize = 6; +const MAX_CANDIDATE_ENTRIES: usize = 20_000; + pub(crate) fn collect_launch_candidates( root: &Path, current: &Path, results: &mut Vec, ) -> Result<(), String> { - let entries = - fs::read_dir(current).map_err(|e| format!("Failed to read installation folder: {e}"))?; + let mut visited = 0usize; + collect_launch_candidates_inner(root, current, results, 0, &mut visited) +} + +fn collect_launch_candidates_inner( + root: &Path, + current: &Path, + results: &mut Vec, + depth: usize, + visited: &mut usize, +) -> Result<(), String> { + if depth > MAX_CANDIDATE_DEPTH || *visited >= MAX_CANDIDATE_ENTRIES { + return Ok(()); + } + + // A folder we cannot read (permissions, deleted mid-walk) must not abort + // the whole scan: skip it and keep the other candidates. + let entries = match fs::read_dir(current) { + Ok(entries) => entries, + Err(error) => { + log::warn!( + "Skipping unreadable folder during launch candidate scan: {} ({error})", + current.display() + ); + return Ok(()); + } + }; for entry in entries { - let entry = entry.map_err(|e| format!("Failed to read installation folder entry: {e}"))?; + if *visited >= MAX_CANDIDATE_ENTRIES { + log::warn!( + "Launch candidate scan stopped after {MAX_CANDIDATE_ENTRIES} entries in {}", + root.display() + ); + return Ok(()); + } + + let Ok(entry) = entry else { + continue; + }; + *visited += 1; + let path = entry.path(); + let Ok(file_type) = entry.file_type() else { + continue; + }; - if path.is_dir() { - collect_launch_candidates(root, &path, results)?; + // Never follow links/junctions: they can point at a parent folder and + // turn this walk into an endless loop. + if file_type.is_symlink() { + continue; + } + + if file_type.is_dir() { + collect_launch_candidates_inner(root, &path, results, depth + 1, visited)?; continue; } diff --git a/src-tauri/src/lib.rs b/src-tauri/src/lib.rs index ff64d8d..f6772a3 100644 --- a/src-tauri/src/lib.rs +++ b/src-tauri/src/lib.rs @@ -5,6 +5,7 @@ mod downloads; mod extraction; mod installation; mod launch_log; +mod tracker_log; mod games; mod fs_commands; mod time_tracker; @@ -461,6 +462,12 @@ pub fn run() { )?; } + // ── Time tracker diagnostics log ─────────────────────────────────── + // Records every tracker tick, match transition and credit outcome. + // Disabled for now via `tracker_log::ENABLED`; the tracker keeps its + // counters in memory either way. + tracker_log::init(app.handle()); + // ── System tray with Show / Quit menu ────────────────────────────── let show_item = MenuItemBuilder::with_id("show", "Show").build(app)?; @@ -591,6 +598,13 @@ pub fn run() { time_tracker::delete_offline_time_file, time_tracker::sync_offline_time, time_tracker::debug_tracker_scan, + time_tracker::get_tracker_status, + time_tracker::reset_tracker_ledger, + tracker_log::get_tracker_log, + tracker_log::clear_tracker_log, + tracker_log::open_tracker_log_folder, + tracker_log::read_tracker_log_file, + tracker_log::tracker_log_line, settings::get_start_minimized, settings::set_start_minimized, settings::get_minimize_on_game_launch, diff --git a/src-tauri/src/settings.rs b/src-tauri/src/settings.rs index 56820cc..9e3a638 100644 --- a/src-tauri/src/settings.rs +++ b/src-tauri/src/settings.rs @@ -1,9 +1,11 @@ use serde::{Deserialize, Serialize}; use std::collections::HashSet; use std::path::PathBuf; +use std::sync::{Mutex, OnceLock}; +use std::time::UNIX_EPOCH; use tauri::Manager; -#[derive(Serialize, Deserialize, Default)] +#[derive(Serialize, Deserialize, Default, Clone)] pub(crate) struct AppSettings { #[serde(default)] pub start_minimized: bool, @@ -49,16 +51,55 @@ pub(crate) fn settings_path(app: &tauri::AppHandle) -> PathBuf { app.path().app_data_dir().unwrap().join("gamevault-settings.json") } +/// Last parsed settings, keyed by the file's modification time. +/// +/// The time tracker reads the ignore list every 60 s tick; re-reading and +/// parsing the JSON from disk every time is pure overhead. +static SETTINGS_CACHE: OnceLock>> = OnceLock::new(); + +fn settings_cache() -> &'static Mutex> { + SETTINGS_CACHE.get_or_init(|| Mutex::new(None)) +} + +fn settings_modified_ms(path: &std::path::Path) -> u64 { + std::fs::metadata(path) + .and_then(|metadata| metadata.modified()) + .ok() + .and_then(|time| time.duration_since(UNIX_EPOCH).ok()) + .map(|duration| duration.as_millis() as u64) + .unwrap_or(0) +} + pub(crate) fn load_settings(app: &tauri::AppHandle) -> AppSettings { let path = settings_path(app); - if path.exists() { - if let Ok(data) = std::fs::read_to_string(&path) { - if let Ok(settings) = serde_json::from_str::(&data) { - return settings; + let modified = settings_modified_ms(&path); + + if modified != 0 { + if let Ok(cache) = settings_cache().lock() { + if let Some((cached_modified, settings)) = cache.as_ref() { + if *cached_modified == modified { + return settings.clone(); + } } } } - AppSettings::default() + + let settings = if path.exists() { + std::fs::read_to_string(&path) + .ok() + .and_then(|data| serde_json::from_str::(&data).ok()) + .unwrap_or_default() + } else { + AppSettings::default() + }; + + if modified != 0 { + if let Ok(mut cache) = settings_cache().lock() { + *cache = Some((modified, settings.clone())); + } + } + + settings } pub(crate) fn save_settings(app: &tauri::AppHandle, settings: &AppSettings) -> Result<(), String> { @@ -67,7 +108,13 @@ pub(crate) fn save_settings(app: &tauri::AppHandle, settings: &AppSettings) -> R std::fs::create_dir_all(parent).map_err(|e| format!("Failed to create config dir: {}", e))?; } let data = serde_json::to_string_pretty(settings).map_err(|e| format!("Failed to serialize: {}", e))?; - std::fs::write(&path, &data).map_err(|e| format!("Failed to write config: {}", e)) + std::fs::write(&path, &data).map_err(|e| format!("Failed to write config: {}", e))?; + + // Update the cache in place so the next reader does not re-parse the file. + if let Ok(mut cache) = settings_cache().lock() { + *cache = Some((settings_modified_ms(&path), settings.clone())); + } + Ok(()) } #[tauri::command] diff --git a/src-tauri/src/state.rs b/src-tauri/src/state.rs index d62b2d7..1a51aaf 100644 --- a/src-tauri/src/state.rs +++ b/src-tauri/src/state.rs @@ -31,6 +31,128 @@ pub(crate) fn tracker_stop_tx() -> &'static Mutex>> { TRACKER_STOP_TX.get_or_init(|| Mutex::new(None)) } +/// Live counters for the native time tracker, surfaced in the diagnostics dump. +/// +/// The tracker credits one minute per matched tick, so `lost_ticks` and the +/// per-game ledgers below are the evidence trail for playtime that ended up +/// lower than what was actually played. +#[derive(Clone, Default, serde::Serialize)] +#[serde(rename_all = "camelCase")] +pub(crate) struct TrackerRuntimeStats { + pub running: bool, + pub started_at: Option, + pub tick_count: u64, + /// Seconds between expected ticks (the tracker interval). + pub tick_interval_secs: u64, + /// Ticks the interval expected but the loop did not run (sleep, freeze, starvation). + pub lost_ticks: u64, + /// Ticks that fired back-to-back to catch up after a stall. + pub catch_up_ticks: u64, + pub last_tick_at: Option, + pub last_tick_gap_secs: Option, + pub last_tick_duration_ms: Option, + pub last_tick_summary: Option, + pub last_error: Option, + pub consecutive_failures: u64, + /// Number of increments the server rejected with 401/403 (expired token). + pub auth_rejected_count: u64, + /// Consecutive auth rejections since the last successful increment. + pub auth_streak: u64, + /// While set (unix ms in the future) the tracker stores playtime offline + /// instead of asking a server that is rejecting its session. + pub auth_backoff_until: Option, + /// Ticks that were stored offline without a request because of the backoff. + pub skipped_auth_ticks: u64, + /// Last time the frontend was notified about an expired session. + pub last_auth_event_at: Option, + pub stop_reason: Option, + pub log_path: Option, +} + +/// Per-game playtime accounting: what the wall clock suggested versus what the +/// server actually credited, plus the reason for every lost tick. +#[derive(Clone, Default, serde::Serialize)] +#[serde(rename_all = "camelCase")] +pub(crate) struct GamePlayLedger { + pub game_id: i64, + pub game_title: String, + /// Currently matched to a running process. + pub matched: bool, + /// Seconds since the last time this game was matched. + pub first_matched_at: Option, + pub last_matched_at: Option, + pub matched_ticks: u64, + /// Increments the server accepted. + pub credited_ticks: u64, + /// Increments that failed but were written to the offline file. + pub offline_ticks: u64, + /// Minutes that were never recorded anywhere. + pub lost_ticks: u64, + /// Lost ticks attributed to a tick gap (sleep/resume, freeze, starvation). + pub dropped_ticks: u64, + /// Matches lost although the game was played before (launcher exit, re-exec…). + pub match_flaps: u64, + pub credited_minutes: u64, + pub offline_minutes: u64, + /// Minutes synced from an offline file of an earlier session. + pub replayed_minutes: u64, + pub observed_seconds: u64, + /// Ticks the game was not matched since the last match (grace counter). + pub missing_ticks: u64, + /// Last `minutes_played` the server reported for this game. + pub last_server_minutes: Option, + /// Why the game was not matched/credited on the last tick. + pub last_skip_reason: Option, +} + +static TRACKER_STATS: OnceLock> = OnceLock::new(); +static TRACKER_LEDGER: OnceLock>> = OnceLock::new(); + +pub(crate) fn tracker_stats() -> &'static Mutex { + TRACKER_STATS.get_or_init(|| Mutex::new(TrackerRuntimeStats::default())) +} + +pub(crate) fn tracker_ledger() -> &'static Mutex> { + TRACKER_LEDGER.get_or_init(|| Mutex::new(HashMap::new())) +} + +/// Clears the playtime ledger and resets counters for a new tracker session. +pub(crate) fn reset_tracker_stats(started_at: u64, tick_interval_secs: u64) { + if let Ok(mut stats) = tracker_stats().lock() { + let log_path = stats.log_path.clone(); + *stats = TrackerRuntimeStats { + running: true, + started_at: Some(started_at), + tick_interval_secs, + log_path, + ..TrackerRuntimeStats::default() + }; + } + if let Ok(mut ledger) = tracker_ledger().lock() { + ledger.clear(); + } +} + +/// Snapshot of the ledger, sorted by game id for stable output. +pub(crate) fn tracker_ledger_snapshot() -> Vec { + tracker_ledger() + .lock() + .map(|ledger| { + let mut games: Vec = ledger.values().cloned().collect(); + games.sort_by_key(|game| game.game_id); + games + }) + .unwrap_or_default() +} + +/// Minutes that are stored offline and still waiting for a successful sync. +pub(crate) fn pending_offline_minutes() -> u64 { + tracker_ledger() + .lock() + .map(|ledger| ledger.values().map(|game| game.offline_minutes).sum()) + .unwrap_or(0) +} + /// Latest known state of an extraction, per game. /// /// Extraction runs on a detached blocking task that keeps going when the diff --git a/src-tauri/src/time_tracker.rs b/src-tauri/src/time_tracker.rs index 4df30dc..f05dc0b 100644 --- a/src-tauri/src/time_tracker.rs +++ b/src-tauri/src/time_tracker.rs @@ -1,15 +1,82 @@ +use crate::events::InstalledGameInfo; use crate::games::{collect_launch_candidates, list_installed_games_blocking}; use crate::settings::load_settings; -use crate::state::{tracker_config, tracker_stop_tx, TrackerConfig}; +use crate::state::{ + pending_offline_minutes, reset_tracker_stats, tracker_config, tracker_ledger, + tracker_ledger_snapshot, tracker_stats, tracker_stop_tx, GamePlayLedger, TrackerConfig, + TrackerRuntimeStats, +}; +use crate::tracker_log; use crate::util::{is_ignored_executable, paths_match}; use serde::Serialize; -use std::collections::HashMap; +use std::collections::{HashMap, HashSet}; use std::fs; use std::path::{Path, PathBuf}; -use std::time::Duration; +use std::sync::{Mutex, OnceLock}; +use std::time::{Duration, Instant, UNIX_EPOCH}; use sysinfo::{ProcessRefreshKind, ProcessesToUpdate, System}; +use tauri::Emitter; use tokio::sync::watch; +/// Seconds between tracker ticks. One matched tick credits exactly one minute, +/// so every skipped tick is a minute of playtime that never reaches the server. +const TICK_INTERVAL_SECS: u64 = 60; +/// A tick that fires earlier than this is a catch-up burst after a stall. +const CATCH_UP_TOLERANCE_SECS: u64 = 5; +/// Backoff after repeated session rejections: retry after 1, 2, 5, then 15 min. +const AUTH_BACKOFF_SECS: [u64; 4] = [60, 120, 300, 900]; +/// Ticks a game may be missing before the match counts as lost. Launchers that +/// hand the game to a new process would otherwise lose a minute per restart. +const MATCH_GRACE_TICKS: u64 = 2; +/// How long a scanned candidate list is reused before walking the folders again. +const CANDIDATE_CACHE_TTL_SECS: u64 = 600; +/// At most one `tracker-auth-expired` event per minute. +const AUTH_EVENT_THROTTLE_MS: u64 = 60_000; +/// Event telling the frontend that the tracker's session was rejected. +const AUTH_EXPIRED_EVENT: &str = "tracker-auth-expired"; + +/// Event payload for [`AUTH_EXPIRED_EVENT`]. +#[derive(Serialize, Clone)] +#[serde(rename_all = "camelCase")] +pub(crate) struct TrackerAuthExpiredEvent { + pub at: u64, + pub auth_rejected_count: u64, + pub pending_offline_minutes: u64, + pub retry_in_secs: u64, +} + +/// A previously scanned candidate list, reused while the folder is unchanged. +#[derive(Clone)] +struct CachedCandidates { + scan_dir: PathBuf, + dir_modified_ms: u64, + scanned_at_ms: u64, + candidates: Vec, +} + +static CANDIDATE_CACHE: OnceLock>> = OnceLock::new(); + +fn candidate_cache() -> &'static Mutex> { + CANDIDATE_CACHE.get_or_init(|| Mutex::new(HashMap::new())) +} + +fn dir_modified_ms(path: &Path) -> u64 { + fs::metadata(path) + .and_then(|metadata| metadata.modified()) + .ok() + .and_then(|time| time.duration_since(UNIX_EPOCH).ok()) + .map(|duration| duration.as_millis() as u64) + .unwrap_or(0) +} + +fn is_shortcut(path: &Path) -> bool { + path + .extension() + .and_then(|ext| ext.to_str()) + .map(|ext| ext.eq_ignore_ascii_case("lnk")) + .unwrap_or(false) +} + #[tauri::command] pub(crate) fn start_game_time_tracker( app: tauri::AppHandle, @@ -19,9 +86,19 @@ pub(crate) fn start_game_time_tracker( download_path: Option, download_paths: Option>, ) -> Result<(), String> { + let previous_running = tracker_stats() + .lock() + .map(|stats| stats.running) + .unwrap_or(false); + if let Ok(mut tx) = tracker_stop_tx().lock() { if let Some(sender) = tx.take() { let _ = sender.send(true); + tracker_log::push( + "info", + "lifecycle", + "restarting tracker: stopping the previous loop", + ); } } @@ -35,6 +112,27 @@ pub(crate) fn start_game_time_tracker( }, }; + tracker_log::push_kv( + "info", + "lifecycle", + &[ + ("event", "start".to_string()), + ("server_url", server_url.clone()), + ("user_id", user_id.to_string()), + ("token", tracker_log::redact_token(&access_token)), + ("roots", paths.len().to_string()), + ( + "root_list", + if paths.is_empty() { + "none".to_string() + } else { + paths.join(", ") + }, + ), + ("previous_loop_running", previous_running.to_string()), + ], + ); + let config = TrackerConfig { server_url, user_id, @@ -46,6 +144,11 @@ pub(crate) fn start_game_time_tracker( *cfg = Some(config); } + if let Ok(mut stats) = tracker_stats().lock() { + stats.log_path = tracker_log::log_path(); + } + reset_tracker_stats(tracker_log::now_ms(), TICK_INTERVAL_SECS); + let (stop_tx, stop_rx) = watch::channel(false); if let Ok(mut tx) = tracker_stop_tx().lock() { *tx = Some(stop_tx); @@ -57,7 +160,9 @@ pub(crate) fn start_game_time_tracker( } #[tauri::command] -pub(crate) fn stop_game_time_tracker() -> Result<(), String> { +pub(crate) fn stop_game_time_tracker(reason: Option) -> Result<(), String> { + let reason = reason.unwrap_or_else(|| "unspecified".to_string()); + if let Ok(mut tx) = tracker_stop_tx().lock() { if let Some(sender) = tx.take() { let _ = sender.send(true); @@ -66,31 +171,156 @@ pub(crate) fn stop_game_time_tracker() -> Result<(), String> { if let Ok(mut cfg) = tracker_config().lock() { *cfg = None; } + if let Ok(mut stats) = tracker_stats().lock() { + stats.running = false; + stats.stop_reason = Some(reason.clone()); + } + + tracker_log::push("info", "lifecycle", &format!("tracker stop requested (reason={reason})")); Ok(()) } #[tauri::command] pub(crate) fn update_tracker_auth(access_token: String) -> Result<(), String> { + let mut updated = false; if let Ok(mut cfg) = tracker_config().lock() { if let Some(ref mut c) = *cfg { - c.access_token = access_token; + c.access_token = access_token.clone(); + updated = true; } } + + // A fresh token ends the rejection streak: retry immediately instead of + // waiting out the backoff. + let cleared_backoff = if let Ok(mut stats) = tracker_stats().lock() { + let was_backing_off = stats.auth_backoff_until.is_some(); + stats.auth_backoff_until = None; + stats.auth_streak = 0; + was_backing_off + } else { + false + }; + if cleared_backoff { + tracker_log::push( + "info", + "http", + "auth_backoff_cleared: fresh session token arrived, resuming requests", + ); + } + + tracker_log::push_kv( + "info", + "lifecycle", + &[ + ("event", "auth_updated".to_string()), + ("applied_to_running_tracker", updated.to_string()), + ("token", tracker_log::redact_token(&access_token)), + ], + ); Ok(()) } +/// One entry of the per-game accounting ledger, used for log lines. +#[derive(Clone)] +struct SkipReason { + game_id: i64, + title: String, + reason: String, +} + async fn game_time_tracker_loop(mut stop_rx: watch::Receiver, app: tauri::AppHandle) { - let mut interval = tokio::time::interval(Duration::from_secs(60)); + let mut interval = tokio::time::interval(Duration::from_secs(TICK_INTERVAL_SECS)); + interval.set_missed_tick_behavior(tokio::time::MissedTickBehavior::Burst); interval.tick().await; + tracker_log::push( + "info", + "lifecycle", + &format!("tracker loop started (interval={TICK_INTERVAL_SECS}s, missed_tick_behavior=burst)"), + ); + + let mut previous_tick_at: Option = None; + let mut in_catch_up_burst = false; + let mut logged_skips: HashMap = HashMap::new(); + let mut logged_candidates: HashMap = HashMap::new(); + let mut logged_backoff_until: Option = None; + loop { tokio::select! { _ = interval.tick() => {}, _ = stop_rx.changed() => { + let reason = tracker_stats() + .lock() + .ok() + .and_then(|stats| stats.stop_reason.clone()) + .unwrap_or_else(|| "stop signal (no reason recorded)".to_string()); + tracker_log::push("info", "lifecycle", &format!("tracker loop stopping: {reason}")); break; } } + let tick_start = Instant::now(); + let now_ms = tracker_log::now_ms(); + let tick_number = match tracker_stats().lock() { + Ok(mut stats) => { + stats.tick_count += 1; + stats.last_tick_at = Some(now_ms); + stats.tick_count + } + Err(_) => 0, + }; + + // ── Tick timing: detect stalls, gaps and catch-up bursts ─────────────── + let mut dropped_ticks = 0u64; + if let Some(previous) = previous_tick_at { + let gap_secs = tick_start.duration_since(previous).as_secs(); + let catch_up = gap_secs + CATCH_UP_TOLERANCE_SECS < TICK_INTERVAL_SECS; + if catch_up && !in_catch_up_burst { + tracker_log::push( + "warn", + "tick", + &format!( + "catch-up burst started: the previous iteration was stalled (gap {gap_secs}s, previous gap {}s)", + tracker_stats() + .lock() + .ok() + .and_then(|stats| stats.last_tick_gap_secs.map(|value| value.to_string())) + .unwrap_or_else(|| "unknown".to_string()) + ), + ); + } + in_catch_up_burst = catch_up; + if catch_up { + if let Ok(mut stats) = tracker_stats().lock() { + stats.catch_up_ticks += 1; + } + } else if gap_secs > TICK_INTERVAL_SECS + CATCH_UP_TOLERANCE_SECS { + dropped_ticks = dropped_ticks_for_gap(gap_secs); + tracker_log::push_kv( + "warn", + "tick", + &[ + ("event", "tick_gap".to_string()), + ("tick", tick_number.to_string()), + ("gap_secs", gap_secs.to_string()), + ("dropped_ticks", dropped_ticks.to_string()), + ( + "hint", + "device sleep/hibernate, app freeze or tick starvation: playtime in this window may be lost" + .to_string(), + ), + ], + ); + } + if let Ok(mut stats) = tracker_stats().lock() { + stats.last_tick_gap_secs = Some(gap_secs); + if dropped_ticks > 0 { + stats.lost_ticks += dropped_ticks; + } + } + } + previous_tick_at = Some(tick_start); + let config = match tracker_config().lock() { Ok(guard) => match guard.clone() { Some(c) => c, @@ -100,24 +330,76 @@ async fn game_time_tracker_loop(mut stop_rx: watch::Receiver, app: tauri:: }; if config.download_paths.is_empty() || config.server_url.is_empty() { + tracker_log::push_kv( + "warn", + "tick", + &[ + ("event", "tick_skipped".to_string()), + ("tick", tick_number.to_string()), + ("reason", "tracker has no roots or no server url".to_string()), + ], + ); continue; } - // Collect installed games from all root paths + // ── Library scan ─────────────────────────────────────────────────────── + let library_start = Instant::now(); let mut installed = Vec::new(); for path in &config.download_paths { - if let Ok(games) = list_installed_games_blocking(path.clone()) { - installed.extend(games); + match list_installed_games_blocking(path.clone()) { + Ok(games) => { + if games.is_empty() { + tracker_log::push_kv( + "warn", + "scan", + &[ + ("event", "root_no_games".to_string()), + ("root", path.clone()), + ], + ); + } + installed.extend(games); + } + Err(error) => tracker_log::push_kv( + "error", + "scan", + &[ + ("event", "root_scan_failed".to_string()), + ("root", path.clone()), + ("error", error), + ], + ), } } + let library_ms = library_start.elapsed().as_millis() as u64; if installed.is_empty() { + mark_all_unmatched("no_installed_games"); + tracker_log::push_kv( + "warn", + "tick", + &[ + ("event", "no_installed_games".to_string()), + ("tick", tick_number.to_string()), + ("roots", config.download_paths.len().to_string()), + ("library_ms", library_ms.to_string()), + ], + ); continue; } + // ── Executable candidates per installed game ─────────────────────────── + let ignored = load_settings(&app).ignored_executables; + let candidates_start = Instant::now(); let mut game_exe_map: HashMap> = HashMap::new(); + let mut game_titles: HashMap = HashMap::new(); + let mut skips: HashMap = HashMap::new(); + let mut cache_hits = 0usize; + let mut cache_misses = 0usize; for game in &installed { + game_titles.insert(game.game_id, game.game_title.clone()); + // The configured installation dir may not exist (e.g. no "Installation" // subfolder); fall back to the version dir so the game is still tracked. let configured_install = PathBuf::from(&game.installation_directory); @@ -126,40 +408,169 @@ async fn game_time_tracker_loop(mut stop_rx: watch::Receiver, app: tauri:: scan_dir = PathBuf::from(&game.version_directory); } if !scan_dir.exists() || !scan_dir.is_dir() { + skips.insert( + game.game_id, + SkipReason { + game_id: game.game_id, + title: game.game_title.clone(), + reason: format!( + "version_dir_missing (install='{}', version='{}')", + game.installation_directory, game.version_directory + ), + }, + ); continue; } - let ignored = load_settings(&app).ignored_executables; + // Walking a game folder is expensive (large trees) and used to run on + // every tick for every game. Reuse the last result while the folder is + // unchanged and the cache is still fresh. + let dir_modified = dir_modified_ms(&scan_dir); + let cached = candidate_cache() + .lock() + .ok() + .and_then(|cache| cache.get(&game.game_id).cloned()); + let mut scan_failed = false; + let cache_hit = matches!( + cached.as_ref(), + Some(entry) + if entry.scan_dir == scan_dir + && entry.dir_modified_ms == dir_modified + && now_ms.saturating_sub(entry.scanned_at_ms) < CANDIDATE_CACHE_TTL_SECS * 1000 + ); + let scanned: Vec = if cache_hit { + cache_hits += 1; + cached.map(|entry| entry.candidates).unwrap_or_default() + } else { + cache_misses += 1; + let mut rel_candidates = Vec::new(); + if collect_launch_candidates(&scan_dir, &scan_dir, &mut rel_candidates).is_err() { + scan_failed = true; + } + let scanned: Vec = rel_candidates + .iter() + .map(|rel| scan_dir.join(rel.replace('/', std::path::MAIN_SEPARATOR_STR))) + .collect(); + if let Ok(mut cache) = candidate_cache().lock() { + cache.insert( + game.game_id, + CachedCandidates { + scan_dir: scan_dir.clone(), + dir_modified_ms: dir_modified, + scanned_at_ms: now_ms, + candidates: scanned.clone(), + }, + ); + } + scanned + }; // Always include the exact launcher the user runs (from the per-game - // config), then any executables found by scanning the install dir. + // config), then the scanned executables, de-duplicated. + let found = scanned.len(); let mut abs_paths: Vec = Vec::new(); - if let Some(rel_exe) = read_configured_launch_executable(Path::new(&game.version_directory)) { + let mut seen: HashSet = HashSet::new(); + let configured_launcher = + read_configured_launch_executable(Path::new(&game.version_directory)); + if let Some(rel_exe) = configured_launcher.clone() { let abs = scan_dir.join(rel_exe); - if abs.exists() && !is_ignored_executable(&abs, &ignored) { + if abs.exists() && !is_ignored_executable(&abs, &ignored) && !is_shortcut(&abs) { + seen.insert(abs.to_string_lossy().to_ascii_lowercase()); abs_paths.push(abs); } } - let mut candidates = Vec::new(); - if collect_launch_candidates(&scan_dir, &scan_dir, &mut candidates).is_ok() { - for rel in candidates { - let abs = scan_dir.join(rel.replace('/', std::path::MAIN_SEPARATOR_STR)); - if !is_ignored_executable(&abs, &ignored) { - abs_paths.push(abs); - } + let mut ignored_count = 0usize; + for abs in scanned { + // A shortcut is never the process that runs the game. + if is_shortcut(&abs) { + continue; + } + if is_ignored_executable(&abs, &ignored) { + ignored_count += 1; + continue; + } + let key = abs.to_string_lossy().to_ascii_lowercase(); + if seen.insert(key) { + abs_paths.push(abs); } } - if !abs_paths.is_empty() { - game_exe_map.entry(game.game_id).or_default().extend(abs_paths); + if abs_paths.is_empty() { + let reason = if scan_failed { + format!("launch_candidate_scan_failed in {}", scan_dir.to_string_lossy()) + } else if found > 0 && ignored_count > 0 { + format!( + "all_candidates_ignored ({found} candidates, {ignored_count} ignored by the ignore list)" + ) + } else if configured_launcher.is_some() { + "no_exe_candidates (configured launch executable is missing)".to_string() + } else { + format!("no_exe_candidates (found {found} candidates in {})", scan_dir.to_string_lossy()) + }; + skips.insert( + game.game_id, + SkipReason { + game_id: game.game_id, + title: game.game_title.clone(), + reason, + }, + ); + continue; } + + if logged_candidates.get(&game.game_id) != Some(&abs_paths.len()) { + logged_candidates.insert(game.game_id, abs_paths.len()); + let mut listed = abs_paths + .iter() + .take(8) + .map(|path| path.to_string_lossy().to_string()) + .collect::>() + .join(" | "); + if abs_paths.len() > 8 { + listed.push_str(&format!(" | … (+{} more)", abs_paths.len() - 8)); + } + tracker_log::push_kv( + "info", + "game", + &[ + ("event", "candidates".to_string()), + ("game", game.game_id.to_string()), + ("title", game.game_title.clone()), + ("count", abs_paths.len().to_string()), + ("cache", if cache_hit { "hit".to_string() } else { "miss".to_string() }), + ("exes", listed), + ], + ); + } + + game_exe_map + .entry(game.game_id) + .or_default() + .extend(abs_paths); + } + + let candidates_ms = candidates_start.elapsed().as_millis() as u64; + + for skip in skips.values() { + log_skip_once(&mut logged_skips, skip); } if game_exe_map.is_empty() { + tracker_log::push_kv( + "warn", + "tick", + &[ + ("event", "no_executable_candidates".to_string()), + ("tick", tick_number.to_string()), + ("installed", installed.len().to_string()), + ], + ); continue; } + // ── Process matching ─────────────────────────────────────────────────── + let process_start = Instant::now(); let mut sys = System::new(); // `refresh_processes` alone does not load `cmd()` in sysinfo 0.33 — the // process argv (which is what matches a running game) stays empty. Use @@ -171,41 +582,810 @@ async fn game_time_tracker_loop(mut stop_rx: watch::Receiver, app: tauri:: ); let processes: Vec<&sysinfo::Process> = sys.processes().values().collect(); + let process_ms = process_start.elapsed().as_millis() as u64; + let match_start = Instant::now(); let mut matched_game_ids: Vec = Vec::new(); - for (game_id, exe_paths) in &game_exe_map { - let is_running = exe_paths.iter().any(|game_exe| { - processes - .iter() - .any(|process| process_matches_game(process, game_exe)) - }); - if is_running { + let matching: Vec = processes + .iter() + .filter(|process| exe_paths.iter().any(|game_exe| process_matches_game(process, game_exe))) + .map(|process| describe_process(process)) + .collect(); + let title = game_titles.get(game_id).cloned().unwrap_or_default(); + let reason = if matching.is_empty() { + // Distinguish "the game closed" from "the game is running but our + // candidate paths do not match it" — the second one is a bug report. + if candidate_name_seen(&processes, exe_paths) { + Some("exe_seen_but_unmatched") + } else { + Some("process_gone") + } + } else { + None + }; + + let state = update_ledger( + *game_id, + &title, + !matching.is_empty(), + &matching, + reason, + dropped_ticks, + now_ms, + ); + if !matches!(state, LedgerMatch::Lost) { matched_game_ids.push(*game_id); } } + // Games without executable candidates can never match: record why. + for skip in skips.values() { + update_ledger( + skip.game_id, + &skip.title, + false, + &[], + Some(skip.reason.as_str()), + dropped_ticks, + now_ms, + ); + } + + let match_ms = match_start.elapsed().as_millis() as u64; + if matched_game_ids.is_empty() { + tracker_log::push_kv( + "tick", + "tick", + &[ + ("event", "no_match".to_string()), + ("tick", tick_number.to_string()), + ("installed", installed.len().to_string()), + ("games_with_exe", game_exe_map.len().to_string()), + ("processes", processes.len().to_string()), + ("match_ms", match_ms.to_string()), + ], + ); continue; } + // ── Credit time ──────────────────────────────────────────────────────── let client = reqwest::Client::new(); - for game_id in matched_game_ids { - let url = format!( - "{}/api/progresses/user/{}/game/{}/increment", - config.server_url, config.user_id, game_id + let http_start = Instant::now(); + let backoff_until = tracker_stats() + .lock() + .ok() + .and_then(|stats| stats.auth_backoff_until); + let backing_off = backoff_until.map(|until| until > now_ms).unwrap_or(false); + + if backing_off && logged_backoff_until != backoff_until { + logged_backoff_until = backoff_until; + tracker_log::push_kv( + "warn", + "http", + &[ + ("event", "auth_backoff_active".to_string()), + ( + "retry_in_secs", + (backoff_until.unwrap_or(now_ms).saturating_sub(now_ms) / 1000).to_string(), + ), + ( + "message", + "the session is still rejected: playtime keeps being stored offline, requests are paused" + .to_string(), + ), + ], ); - let result = client - .put(&url) - .header("Authorization", format!("Bearer {}", config.access_token)) - .header("Accept", "application/json") - .send() - .await; - - if result.is_err() { - save_offline_time(&config.download_paths, config.user_id, game_id); + } else if !backing_off { + logged_backoff_until = None; + } + + let mut credited = 0u64; + let mut offline = 0u64; + let mut lost = 0u64; + for game_id in &matched_game_ids { + let outcome = if backing_off { + // Do not hammer a server that rejects our session: keep the minute, + // store it offline and try again after the backoff. + if let Ok(mut stats) = tracker_stats().lock() { + stats.skipped_auth_ticks += 1; + } + save_offline_time(&installed, &config, *game_id); + CreditOutcome::Offline { + reason: "auth backoff (session rejected, request skipped)".to_string(), + } + } else { + increment_game_time(&app, &client, &config, *game_id, &installed).await + }; + + match outcome { + CreditOutcome::Credited { .. } => { + credited += 1; + bump_credit_stats(true, false); + } + CreditOutcome::Offline { ref reason } => { + offline += 1; + bump_credit_stats(false, false); + record_failure(reason); + } + CreditOutcome::Lost { ref reason } => { + lost += 1; + bump_credit_stats(false, false); + record_failure(reason); + } + } + record_credit(*game_id, outcome); + } + let http_ms = http_start.elapsed().as_millis() as u64; + + let duration_ms = tick_start.elapsed().as_millis() as u64; + let summary = format!( + "tick {tick_number} | installed={} with_exe={} processes={} matched={} credited={credited} offline={offline} lost={lost} | library={library_ms}ms candidates={candidates_ms}ms cache={cache_hits}/{cache_misses} process={process_ms}ms match={match_ms}ms http={http_ms}ms total={duration_ms}ms", + installed.len(), + game_exe_map.len(), + processes.len(), + matched_game_ids.len(), + ); + tracker_log::push("tick", "tick", &summary); + if let Ok(mut stats) = tracker_stats().lock() { + stats.last_tick_summary = Some(summary); + stats.last_tick_duration_ms = Some(duration_ms); + } + + for (phase, value) in [ + ("library", library_ms), + ("candidates", candidates_ms), + ("process", process_ms), + ("match", match_ms), + ("http", http_ms), + ] { + if value > 1000 { + tracker_log::push_kv( + "warn", + "tick", + &[ + ("event", "slow_phase".to_string()), + ("tick", tick_number.to_string()), + ("phase", phase.to_string()), + ("phase_ms", value.to_string()), + ("total_ms", duration_ms.to_string()), + ], + ); + } + } + + if duration_ms > TICK_INTERVAL_SECS * 1000 { + tracker_log::push_kv( + "warn", + "tick", + &[ + ("event", "tick_starvation".to_string()), + ("tick", tick_number.to_string()), + ("duration_ms", duration_ms.to_string()), + ("interval_ms", (TICK_INTERVAL_SECS * 1000).to_string()), + ], + ); + } + } + + tracker_log::push("info", "lifecycle", "tracker loop exited"); + if let Ok(mut stats) = tracker_stats().lock() { + stats.running = false; + } +} + +/// Records that no game could be matched this tick, e.g. an empty library scan. +fn mark_all_unmatched(reason: &str) { + if let Ok(mut ledger) = tracker_ledger().lock() { + for entry in ledger.values_mut() { + if entry.matched { + entry.matched = false; + } + entry.last_skip_reason = Some(reason.to_string()); + } + } +} + +/// Logs a missing-executable reason once per change instead of every tick. +fn log_skip_once(logged: &mut HashMap, skip: &SkipReason) { + let changed = logged + .get(&skip.game_id) + .map(|previous| previous != &skip.reason) + .unwrap_or(true); + if !changed { + return; + } + logged.insert(skip.game_id, skip.reason.clone()); + tracker_log::push_kv( + "warn", + "game", + &[ + ("event", "unmatched".to_string()), + ("game", skip.game_id.to_string()), + ("title", skip.title.clone()), + ("reason", skip.reason.clone()), + ], + ); +} + +/// What a ledger update means for the current tick. +enum LedgerMatch { + /// Process still running — credit normally. + Matched, + /// Process vanished but the game may still be running (launcher hand-off) — + /// still credit, for at most [`MATCH_GRACE_TICKS`] ticks. + Grace { remaining: u64 }, + /// The game is not running (or never was) — do not credit. + Lost, +} + +/// Keeps the per-game ledger in sync and logs match transitions. +fn update_ledger( + game_id: i64, + title: &str, + matched: bool, + matching_processes: &[String], + fallback_reason: Option<&str>, + dropped_ticks: u64, + now_ms: u64, +) -> LedgerMatch { + let Ok(mut ledger) = tracker_ledger().lock() else { + return if matched { LedgerMatch::Matched } else { LedgerMatch::Lost }; + }; + let entry = ledger.entry(game_id).or_default(); + entry.game_id = game_id; + if !title.is_empty() { + entry.game_title = title.to_string(); + } + + if dropped_ticks > 0 && (matched || entry.matched) { + entry.lost_ticks += dropped_ticks; + entry.dropped_ticks += dropped_ticks; + tracker_log::push_kv( + "warn", + "game", + &[ + ("event", "gap_undercount_risk".to_string()), + ("game", game_id.to_string()), + ("title", entry.game_title.clone()), + ("dropped_ticks", dropped_ticks.to_string()), + ("lost_ticks_total", entry.lost_ticks.to_string()), + ( + "hint", + "the game was matched around the gap, so this playtime was very likely never credited" + .to_string(), + ), + ], + ); + } + + if matched { + if !entry.matched { + if entry.first_matched_at.is_none() { + entry.first_matched_at = Some(now_ms); + tracker_log::push_kv( + "info", + "game", + &[ + ("event", "match_started".to_string()), + ("game", game_id.to_string()), + ("title", entry.game_title.clone()), + ("processes", matching_processes.join(" | ")), + ], + ); + } else { + entry.match_flaps += 1; + let away_secs = entry + .last_matched_at + .map(|last| now_ms.saturating_sub(last) / 1000) + .unwrap_or(0); + tracker_log::push_kv( + "warn", + "game", + &[ + ("event", "match_resumed".to_string()), + ("game", game_id.to_string()), + ("title", entry.game_title.clone()), + ("away_secs", away_secs.to_string()), + ("flaps_total", entry.match_flaps.to_string()), + ("processes", matching_processes.join(" | ")), + ( + "hint", + "playtime during this window was not credited (launcher exited, re-exec or missing candidate)" + .to_string(), + ), + ], + ); } + entry.matched = true; } + entry.missing_ticks = 0; + entry.matched_ticks += 1; + entry.last_matched_at = Some(now_ms); + entry.observed_seconds += TICK_INTERVAL_SECS; + entry.last_skip_reason = None; + return LedgerMatch::Matched; + } + + // Not matched on this tick. + let reason = fallback_reason.unwrap_or("no_matching_process"); + entry.last_skip_reason = Some(reason.to_string()); + + if entry.matched { + entry.missing_ticks += 1; + + // A game can briefly disappear from the process list while it keeps + // running (launcher hand-off, protection re-exec). Keep crediting for a + // couple of ticks instead of losing that playtime. + if entry.missing_ticks <= MATCH_GRACE_TICKS { + entry.matched_ticks += 1; + entry.observed_seconds += TICK_INTERVAL_SECS; + tracker_log::push_kv( + "info", + "game", + &[ + ("event", "match_grace".to_string()), + ("game", game_id.to_string()), + ("title", entry.game_title.clone()), + ("tick", entry.missing_ticks.to_string()), + ("grace_ticks", MATCH_GRACE_TICKS.to_string()), + ("reason", reason.to_string()), + ], + ); + return LedgerMatch::Grace { + remaining: MATCH_GRACE_TICKS - entry.missing_ticks, + }; + } + + entry.matched = false; + entry.missing_ticks = 0; + tracker_log::push_kv( + "warn", + "game", + &[ + ("event", "match_lost".to_string()), + ("game", game_id.to_string()), + ("title", entry.game_title.clone()), + ("reason", reason.to_string()), + ("matched_ticks", entry.matched_ticks.to_string()), + ("credited_minutes", entry.credited_minutes.to_string()), + ( + "observed_minutes", + (entry.observed_seconds / TICK_INTERVAL_SECS).to_string(), + ), + ], + ); + log_session_summary(entry, pending_offline_minutes()); + return LedgerMatch::Lost; + } + + LedgerMatch::Lost +} + +/// One decisive line per game session: what was played, what was credited and +/// why the numbers differ. +fn log_session_summary(entry: &GamePlayLedger, pending_offline_minutes: u64) { + let observed = entry.observed_seconds / TICK_INTERVAL_SECS; + let accounted = entry.credited_minutes + entry.offline_minutes + entry.lost_ticks; + + let verdict = if entry.offline_minutes > 0 && entry.credited_minutes == 0 { + format!( + "{} of {} played minutes were stored offline because the server rejected the session; they are credited when the session works again", + entry.offline_minutes, observed + ) + } else if entry.offline_minutes > 0 { + format!( + "{} of {} played minutes were stored offline (rejected session), {} were credited", + entry.offline_minutes, observed, entry.credited_minutes + ) + } else if observed > accounted { + format!( + "{} of {} played minutes could not be credited ({} lost, {} dropped during a tick gap)", + observed - accounted, + observed, + entry.lost_ticks, + entry.dropped_ticks + ) + } else { + "all matched minutes were credited".to_string() + }; + + tracker_log::push_kv( + "info", + "session", + &[ + ("event", "session_summary".to_string()), + ("game", entry.game_id.to_string()), + ("title", entry.game_title.clone()), + ("observed_minutes", observed.to_string()), + ("credited_minutes", entry.credited_minutes.to_string()), + ("offline_minutes", entry.offline_minutes.to_string()), + ("lost_minutes", entry.lost_ticks.to_string()), + ("dropped_minutes", entry.dropped_ticks.to_string()), + ("match_flaps", entry.match_flaps.to_string()), + ( + "replayed_minutes", + entry.replayed_minutes.to_string(), + ), + ( + "server_minutes", + entry + .last_server_minutes + .map(|minutes| minutes.to_string()) + .unwrap_or_else(|| "unknown".to_string()), + ), + ("pending_offline_minutes", pending_offline_minutes.to_string()), + ("verdict", verdict), + ], + ); +} + +/// True when a process runs with the same file name as one of the candidates: +/// the game is probably running, but the full paths did not match. +fn candidate_name_seen(processes: &[&sysinfo::Process], candidates: &[PathBuf]) -> bool { + let names: HashSet = candidates + .iter() + .filter_map(|path| path.file_name()) + .map(|name| name.to_string_lossy().to_ascii_lowercase()) + .collect(); + if names.is_empty() { + return false; + } + + processes.iter().any(|process| { + process + .exe() + .and_then(|exe| exe.file_name()) + .map(|name| names.contains(&name.to_string_lossy().to_ascii_lowercase())) + .unwrap_or(false) + }) +} + +/// Ticks the interval expected but that never ran, from an observed gap. +/// +/// Rounds to the nearest interval and never counts the tick that just ran, so a +/// 3 minute sleep reports 2 lost ticks and stays silent below the tolerance. +pub(crate) fn dropped_ticks_for_gap(gap_secs: u64) -> u64 { + if gap_secs <= TICK_INTERVAL_SECS + CATCH_UP_TOLERANCE_SECS { + 0 + } else { + (gap_secs + TICK_INTERVAL_SECS / 2) / TICK_INTERVAL_SECS - 1 + } +} + +/// Why a single increment was credited, stored offline or dropped. +enum CreditOutcome { + Credited { server_minutes: Option }, + Offline { reason: String }, + Lost { reason: String }, +} + +/// Applies one credit attempt to the per-game ledger. +fn record_credit(game_id: i64, outcome: CreditOutcome) { + let Ok(mut ledger) = tracker_ledger().lock() else { + return; + }; + let entry = ledger.entry(game_id).or_default(); + entry.game_id = game_id; + + match outcome { + CreditOutcome::Credited { server_minutes } => { + entry.credited_ticks += 1; + entry.credited_minutes += 1; + if let Some(minutes) = server_minutes { + let delta = entry.last_server_minutes.map(|previous| minutes - previous); + entry.last_server_minutes = Some(minutes); + tracker_log::push_kv( + "info", + "credit", + &[ + ("event", "credited".to_string()), + ("game", game_id.to_string()), + ("title", entry.game_title.clone()), + ("server_minutes", minutes.to_string()), + ( + "server_delta", + delta + .map(|value| value.to_string()) + .unwrap_or_else(|| "unknown".to_string()), + ), + ( + "expected_delta", + "1".to_string(), + ), + ("credited_minutes", entry.credited_minutes.to_string()), + ( + "observed_minutes", + (entry.observed_seconds / TICK_INTERVAL_SECS).to_string(), + ), + ], + ); + } + } + CreditOutcome::Offline { reason } => { + entry.offline_ticks += 1; + entry.offline_minutes += 1; + tracker_log::push_kv( + "warn", + "credit", + &[ + ("event", "credited_offline".to_string()), + ("game", game_id.to_string()), + ("title", entry.game_title.clone()), + ("reason", reason), + ("offline_minutes", entry.offline_minutes.to_string()), + ], + ); + } + CreditOutcome::Lost { reason } => { + entry.lost_ticks += 1; + tracker_log::push_kv( + "error", + "credit", + &[ + ("event", "credit_lost".to_string()), + ("game", game_id.to_string()), + ("title", entry.game_title.clone()), + ("reason", reason), + ("lost_ticks_total", entry.lost_ticks.to_string()), + ], + ); + } + } +} + +/// Short, single-line process description for log lines. +fn describe_process(process: &sysinfo::Process) -> String { + let exe = process + .exe() + .map(|path| path.to_string_lossy().to_string()) + .unwrap_or_else(|| { + let cmd: Vec = process + .cmd() + .iter() + .map(|part| part.to_string_lossy().to_string()) + .collect(); + let joined = cmd.join(" "); + if joined.is_empty() { + "unknown".to_string() + } else { + joined + } + }); + format!("{exe} (pid {})", process.pid()) +} + +/// What the tracker should do with an increment response. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub(crate) enum CreditDisposition { + /// 2xx: the minute was counted by the server. + Success, + /// 401/403 (expired token), 408/429 (retry later) or 5xx: store offline. + SaveOffline, + /// Anything else (e.g. 404): do not count, do not store offline. + Drop, +} + +pub(crate) fn classify_status(status: u16) -> CreditDisposition { + if (200..300).contains(&status) { + CreditDisposition::Success + } else if matches!(status, 401 | 403 | 408 | 429) || status >= 500 { + CreditDisposition::SaveOffline + } else { + CreditDisposition::Drop + } +} + +/// Extracts `minutes_played` from an increment response, when the server sends it. +pub(crate) fn parse_server_minutes(body: &str) -> Option { + let value: serde_json::Value = serde_json::from_str(body).ok()?; + value.get("minutes_played").and_then(|minutes| minutes.as_i64()) +} + +fn excerpt(text: &str, max: usize) -> String { + let cleaned = text.replace('\n', " ").replace('\r', " ").trim().to_string(); + if cleaned.chars().count() <= max { + return cleaned; + } + let mut short: String = cleaned.chars().take(max).collect(); + short.push('…'); + short +} + +fn bump_credit_stats(success: bool, auth_rejected: bool) { + if let Ok(mut stats) = tracker_stats().lock() { + if success { + stats.consecutive_failures = 0; + stats.last_error = None; + // A working session ends the rejection streak and any backoff. + stats.auth_streak = 0; + stats.auth_backoff_until = None; + } else { + stats.consecutive_failures += 1; + } + if auth_rejected { + stats.auth_rejected_count += 1; + } + } +} + +fn record_failure(reason: &str) { + if let Ok(mut stats) = tracker_stats().lock() { + stats.last_error = Some(reason.to_string()); + } +} + +/// The server rejected our session: stop asking for a while, keep storing the +/// minute offline, and (throttled) tell the frontend so it can refresh the +/// token instead of letting the tracker run on an expired one for an hour. +fn apply_auth_backoff(app: &tauri::AppHandle, status: u16) { + let now = tracker_log::now_ms(); + let (streak, retry_in_secs, rejected_total, should_emit) = { + let Ok(mut stats) = tracker_stats().lock() else { + return; + }; + stats.auth_streak += 1; + stats.consecutive_failures += 1; + stats.auth_rejected_count += 1; + + let index = (stats.auth_streak as usize - 1).min(AUTH_BACKOFF_SECS.len() - 1); + let retry_in_secs = AUTH_BACKOFF_SECS[index]; + stats.auth_backoff_until = Some(now + retry_in_secs * 1000); + + let should_emit = stats + .last_auth_event_at + .map(|last| now.saturating_sub(last) >= AUTH_EVENT_THROTTLE_MS) + .unwrap_or(true); + if should_emit { + stats.last_auth_event_at = Some(now); + } + + ( + stats.auth_streak, + retry_in_secs, + stats.auth_rejected_count, + should_emit, + ) + }; + + tracker_log::push_kv( + "warn", + "http", + &[ + ("event", "auth_backoff".to_string()), + ("status", status.to_string()), + ("streak", streak.to_string()), + ("retry_in_secs", retry_in_secs.to_string()), + ( + "message", + "the server rejected the session — playtime is stored offline and requests are paused" + .to_string(), + ), + ], + ); + + if should_emit { + let _ = app.emit( + AUTH_EXPIRED_EVENT, + TrackerAuthExpiredEvent { + at: now, + auth_rejected_count: rejected_total, + pending_offline_minutes: pending_offline_minutes(), + retry_in_secs, + }, + ); + } +} + +/// The access token the tracker is currently configured with. +fn current_access_token() -> Option { + tracker_config() + .lock() + .ok() + .and_then(|config| config.as_ref().map(|config| config.access_token.clone())) +} + +/// Sends one increment request with a given token. +async fn send_increment( + client: &reqwest::Client, + url: &str, + access_token: &str, +) -> Result { + client + .put(url) + .header("Authorization", format!("Bearer {access_token}")) + .header("Accept", "application/json") + .send() + .await +} + +/// Sends one minute increment and reports what happened to it. +/// +/// A rejected session is retried once with a newer token if the frontend +/// refreshed it in the meantime — the tracker's tick usually starts a moment +/// before the token refresh lands, so without this every refresh would waste a +/// minute into the offline file (and delete it again seconds later). +async fn increment_game_time( + app: &tauri::AppHandle, + client: &reqwest::Client, + config: &TrackerConfig, + game_id: i64, + installed: &[InstalledGameInfo], +) -> CreditOutcome { + let url = format!( + "{}/api/progresses/user/{}/game/{}/increment", + config.server_url, config.user_id, game_id + ); + + let response = match send_increment(client, &url, &config.access_token).await { + Ok(response) => response, + Err(error) => { + let reason = format!("network error: {error}"); + save_offline_time(installed, config, game_id); + return CreditOutcome::Offline { reason }; + } + }; + + let status = response.status(); + let body = response.text().await.unwrap_or_default(); + + match classify_status(status.as_u16()) { + CreditDisposition::Success => CreditOutcome::Credited { + server_minutes: parse_server_minutes(&body), + }, + CreditDisposition::SaveOffline => { + if matches!(status.as_u16(), 401 | 403) { + if let Some(fresh) = current_access_token() { + if fresh != config.access_token { + match send_increment(client, &url, &fresh).await { + Ok(retry) if retry.status().is_success() => { + let retry_body = retry.text().await.unwrap_or_default(); + tracker_log::push_kv( + "info", + "http", + &[ + ("event", "auth_retried".to_string()), + ("game", game_id.to_string()), + ("outcome", "credited with the refreshed session".to_string()), + ], + ); + return CreditOutcome::Credited { + server_minutes: parse_server_minutes(&retry_body), + }; + } + Ok(retry) => tracker_log::push_kv( + "warn", + "http", + &[ + ("event", "auth_retried".to_string()), + ("game", game_id.to_string()), + ("outcome", "still rejected".to_string()), + ("status", retry.status().as_u16().to_string()), + ], + ), + Err(error) => tracker_log::push_kv( + "warn", + "http", + &[ + ("event", "auth_retried".to_string()), + ("game", game_id.to_string()), + ("outcome", format!("network error: {error}")), + ], + ), + } + } + } + apply_auth_backoff(app, status.as_u16()); + } + save_offline_time(installed, config, game_id); + CreditOutcome::Offline { + reason: format!("http {} ({})", status.as_u16(), excerpt(&body, 160)), + } + } + CreditDisposition::Drop => CreditOutcome::Lost { + reason: format!("http {} ({})", status.as_u16(), excerpt(&body, 160)), + }, } } @@ -247,37 +1427,106 @@ fn read_configured_launch_executable(version_dir: &Path) -> Option { Some(PathBuf::from(exe)) } -fn save_offline_time(download_paths: &[String], user_id: i64, game_id: i64) { - let mut installed = Vec::new(); - for path in download_paths { - if let Ok(games) = list_installed_games_blocking(path.to_string()) { - installed.extend(games); - } - } +/// Builds the offline file content, keeping `accumulated_minutes` monotonic. +/// +/// This is the safety net for every minute the server did not accept: the file +/// is only ever incremented and is replayed once a session works again. Older +/// files (written before `updated_at`/`server_url` existed) are still readable, +/// because only `accumulated_minutes` matters for the count. +fn offline_payload( + existing: Option<&str>, + user_id: i64, + game_id: i64, + server_url: &str, + at_ms: u64, +) -> (i64, serde_json::Value) { + let current_minutes = existing + .and_then(|content| serde_json::from_str::(content).ok()) + .and_then(|json| { + json + .get("accumulated_minutes") + .and_then(|value| value.as_i64()) + }) + .unwrap_or(0) + .max(0); + + let accumulated = current_minutes + 1; + let data = serde_json::json!({ + "user_id": user_id, + "game_id": game_id, + "accumulated_minutes": accumulated, + "updated_at": at_ms / 1000, + "server_url": server_url, + }); + (accumulated, data) +} - let target = match installed.iter().find(|g| g.game_id == game_id) { - Some(g) => g, - None => return, +/// Stores one uncredited minute in the game's offline file. Returns the path it +/// wrote to, so the caller can log where the playtime went. +fn save_offline_time( + installed: &[InstalledGameInfo], + config: &TrackerConfig, + game_id: i64, +) -> Option { + let target = match installed.iter().find(|game| game.game_id == game_id) { + Some(game) => game, + None => { + tracker_log::push_kv( + "error", + "offline", + &[ + ("event", "offline_save_failed".to_string()), + ("game", game_id.to_string()), + ( + "reason", + "the game is no longer in the library, so the minute could not be stored offline" + .to_string(), + ), + ], + ); + return None; + } }; let offline_file = PathBuf::from(&target.version_directory).join(".gamevault.offline_time.json"); + let existing = fs::read_to_string(&offline_file).ok(); + let (accumulated, data) = offline_payload( + existing.as_deref(), + config.user_id, + game_id, + &config.server_url, + tracker_log::now_ms(), + ); - let mut current_minutes: i64 = 0; - if offline_file.exists() { - if let Ok(content) = fs::read_to_string(&offline_file) { - if let Ok(json) = serde_json::from_str::(&content) { - current_minutes = json.get("accumulated_minutes").and_then(|v| v.as_i64()).unwrap_or(0); - } + match fs::write(&offline_file, serde_json::to_string(&data).unwrap_or_default()) { + Ok(()) => { + tracker_log::push_kv( + "info", + "offline", + &[ + ("event", "offline_saved".to_string()), + ("game", game_id.to_string()), + ("title", target.game_title.clone()), + ("accumulated_minutes", accumulated.to_string()), + ("path", offline_file.to_string_lossy().to_string()), + ], + ); + Some(offline_file) + } + Err(error) => { + tracker_log::push_kv( + "error", + "offline", + &[ + ("event", "offline_save_failed".to_string()), + ("game", game_id.to_string()), + ("error", error.to_string()), + ("path", offline_file.to_string_lossy().to_string()), + ], + ); + None } } - - let data = serde_json::json!({ - "user_id": user_id, - "game_id": game_id, - "accumulated_minutes": current_minutes + 1 - }); - - let _ = fs::write(&offline_file, serde_json::to_string(&data).unwrap_or_default()); } // ── Offline time tracking commands ──────────────────────────────────────────── @@ -289,6 +1538,8 @@ pub(crate) struct OfflineTimeFile { user_id: i64, game_id: i64, accumulated_minutes: i64, + /// Unix seconds of the last write (0 for files from older builds). + updated_at: i64, } #[tauri::command] @@ -332,11 +1583,13 @@ fn walk_offline_time_files(dir: &Path, results: &mut Vec) -> st let user_id = json.get("user_id").and_then(|v| v.as_i64()).unwrap_or(0); let game_id = json.get("game_id").and_then(|v| v.as_i64()).unwrap_or(0); let accumulated_minutes = json.get("accumulated_minutes").and_then(|v| v.as_i64()).unwrap_or(0); + let updated_at = json.get("updated_at").and_then(|v| v.as_i64()).unwrap_or(0); results.push(OfflineTimeFile { path: path.to_string_lossy().to_string(), user_id, game_id, accumulated_minutes, + updated_at, }); } } @@ -350,6 +1603,14 @@ pub(crate) fn delete_offline_time_file(path: String) -> Result<(), String> { let p = Path::new(&path); if p.exists() { fs::remove_file(p).map_err(|e| format!("Failed to delete offline time file: {e}"))?; + tracker_log::push_kv( + "info", + "offline", + &[ + ("event", "offline_file_deleted".to_string()), + ("path", path.clone()), + ], + ); } Ok(()) } @@ -361,20 +1622,82 @@ pub(crate) async fn sync_offline_time( user_id: i64, game_id: i64, minutes: i64, + reason: Option, ) -> Result { + let reason = reason.unwrap_or_else(|| "unspecified".to_string()); let url = format!( "{}/api/progresses/user/{}/game/{}/increment/{}", server_url, user_id, game_id, minutes ); let client = reqwest::Client::new(); - let resp = client + let resp = match client .put(&url) .header("Authorization", format!("Bearer {}", access_token)) .header("Accept", "application/json") .send() .await - .map_err(|e| format!("Sync request failed: {e}"))?; - Ok(resp.status().is_success()) + { + Ok(resp) => resp, + Err(error) => { + tracker_log::push_kv( + "warn", + "offline", + &[ + ("event", "offline_replay_failed".to_string()), + ("game", game_id.to_string()), + ("minutes", minutes.to_string()), + ("reason", reason), + ("error", error.to_string()), + ], + ); + return Err(format!("Sync request failed: {error}")); + } + }; + + let status = resp.status(); + let success = status.is_success(); + let body = resp.text().await.unwrap_or_default(); + + tracker_log::push_kv( + if success { "info" } else { "warn" }, + "offline", + &[ + ("event", "offline_replayed".to_string()), + ("game", game_id.to_string()), + ("minutes", minutes.to_string()), + ("user_id", user_id.to_string()), + ("reason", reason.clone()), + ("status", status.as_u16().to_string()), + ("success", success.to_string()), + ( + "message", + if success { + "offline playtime was credited by the server".to_string() + } else { + "offline playtime was rejected and kept for the next attempt".to_string() + }, + ), + ], + ); + + // Keep the ledger in sync: those minutes are no longer waiting offline. + if success { + if let Ok(mut ledger) = tracker_ledger().lock() { + let entry = ledger.entry(game_id).or_default(); + entry.game_id = game_id; + entry.offline_minutes = entry + .offline_minutes + .saturating_sub(minutes.max(0) as u64); + // Replayed minutes belong to an earlier session, so they are counted + // separately and never inflate this session's credited total. + entry.replayed_minutes += minutes.max(0) as u64; + if let Some(server_minutes) = parse_server_minutes(&body) { + entry.last_server_minutes = Some(server_minutes); + } + } + } + + Ok(success) } // ── Debug diagnostics ──────────────────────────────────────────────────────── @@ -539,3 +1862,149 @@ fn debug_tracker_scan_blocking( process_matches, }) } + +// ── Runtime status ─────────────────────────────────────────────────────────── + +/// Diagnostics snapshot: loop counters plus the per-game playtime ledger. +#[derive(serde::Serialize)] +#[serde(rename_all = "camelCase")] +pub(crate) struct TrackerStatus { + pub tracker_running: bool, + pub stats: TrackerRuntimeStats, + pub games: Vec, + pub log_path: Option, + /// Minutes stored offline that still need a successful sync. + pub pending_offline_minutes: u64, +} + +#[tauri::command] +pub(crate) fn get_tracker_status() -> TrackerStatus { + let mut stats = tracker_stats().lock().map(|stats| stats.clone()).unwrap_or_default(); + stats.log_path = tracker_log::log_path(); + + let running = tracker_config().lock().map(|config| config.is_some()).unwrap_or(false) + || stats.running; + stats.running = running; + + TrackerStatus { + tracker_running: running, + stats, + games: tracker_ledger_snapshot(), + log_path: tracker_log::log_path(), + pending_offline_minutes: pending_offline_minutes(), + } +} + +/// Clears the playtime ledger so a fresh measurement can be taken. +#[tauri::command] +pub(crate) fn reset_tracker_ledger() -> Result<(), String> { + if let Ok(mut ledger) = tracker_ledger().lock() { + ledger.clear(); + } + if let Ok(mut stats) = tracker_stats().lock() { + let started_at = tracker_log::now_ms(); + let lost_ticks = stats.lost_ticks; + stats.tick_count = 0; + stats.lost_ticks = 0; + stats.catch_up_ticks = 0; + stats.consecutive_failures = 0; + stats.auth_rejected_count = 0; + stats.started_at = Some(started_at); + tracker_log::push( + "info", + "lifecycle", + &format!("tracker counters reset (previous lost_ticks={lost_ticks})"), + ); + } + Ok(()) +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn classifies_increment_responses() { + assert_eq!(classify_status(200), CreditDisposition::Success); + assert_eq!(classify_status(204), CreditDisposition::Success); + // Expired token / server problems: keep the minute offline. + assert_eq!(classify_status(401), CreditDisposition::SaveOffline); + assert_eq!(classify_status(403), CreditDisposition::SaveOffline); + assert_eq!(classify_status(408), CreditDisposition::SaveOffline); + assert_eq!(classify_status(429), CreditDisposition::SaveOffline); + assert_eq!(classify_status(500), CreditDisposition::SaveOffline); + assert_eq!(classify_status(503), CreditDisposition::SaveOffline); + // Provider errors must not create offline time (game gone, bad request). + assert_eq!(classify_status(400), CreditDisposition::Drop); + assert_eq!(classify_status(404), CreditDisposition::Drop); + } + + #[test] + fn parses_server_reported_minutes() { + assert_eq!( + parse_server_minutes(r#"{"minutes_played": 61, "state": "playing"}"#), + Some(61) + ); + assert_eq!(parse_server_minutes(r#"{"minutes_played": null}"#), None); + assert_eq!(parse_server_minutes(""), None); + assert_eq!(parse_server_minutes(""), None); + } + + #[test] + fn estimates_dropped_ticks_from_a_gap() { + // Rounds to the nearest tick and never reports the tick that just ran. + assert_eq!(dropped_ticks_for_gap(60), 0); + assert_eq!(dropped_ticks_for_gap(65), 0); + assert_eq!(dropped_ticks_for_gap(90), 1); + assert_eq!(dropped_ticks_for_gap(180), 2); + assert_eq!(dropped_ticks_for_gap(3_600), 59); + } + + #[test] + fn excerpts_long_bodies() { + assert_eq!(excerpt("short", 20), "short"); + assert_eq!(excerpt("line\nbreak", 40), "line break"); + let trimmed = excerpt(&"x".repeat(30), 10); + assert_eq!(trimmed.chars().count(), 11); + assert!(trimmed.ends_with('…')); + } + + #[test] + fn offline_payload_counts_up_from_legacy_files() { + // A file from an older build only has accumulated_minutes. + let legacy = r#"{"user_id": 1, "game_id": 2341, "accumulated_minutes": 61}"#; + let (accumulated, data) = offline_payload(Some(legacy), 1, 2341, "https://example.test", 1_700_000_000_000); + assert_eq!(accumulated, 62); + assert_eq!(data["accumulated_minutes"].as_i64(), Some(62)); + assert_eq!(data["game_id"].as_i64(), Some(2341)); + assert_eq!(data["user_id"].as_i64(), Some(1)); + assert_eq!(data["updated_at"].as_i64(), Some(1_700_000_000)); + assert_eq!(data["server_url"].as_str(), Some("https://example.test")); + } + + #[test] + fn offline_payload_starts_at_one_and_survives_damage() { + let (first, _) = offline_payload(None, 1, 7, "https://example.test", 0); + assert_eq!(first, 1); + + // Unreadable/garbage content must not reset the counter backwards. + let (from_garbage, _) = offline_payload(Some(""), 1, 7, "https://example.test", 0); + assert_eq!(from_garbage, 1); + + // Negative values (hand-edited file) are clamped, never decreased further. + let negative = r#"{"accumulated_minutes": -5}"#; + let (clamped, _) = offline_payload(Some(negative), 1, 7, "https://example.test", 0); + assert_eq!(clamped, 1); + } + + #[test] + fn auth_backoff_grows_and_caps() { + let retry_for = |streak: usize| AUTH_BACKOFF_SECS[(streak - 1).min(AUTH_BACKOFF_SECS.len() - 1)]; + assert_eq!(retry_for(1), 60); + assert_eq!(retry_for(2), 120); + assert_eq!(retry_for(3), 300); + assert_eq!(retry_for(4), 900); + // Stays capped: an hour-long rejection streak must not grow unbounded. + assert_eq!(retry_for(60), 900); + } +} diff --git a/src-tauri/src/tracker_log.rs b/src-tauri/src/tracker_log.rs new file mode 100644 index 0000000..be76177 --- /dev/null +++ b/src-tauri/src/tracker_log.rs @@ -0,0 +1,489 @@ +//! Time tracker diagnostics log. +//! +//! The game time tracker credits exactly one minute per matched tick, so a +//! playtime that ends up lower than what was actually played is always caused +//! by lost ticks (sleep/resume, freeze, starvation), lost matches (launcher +//! exits, protection re-exec, missing executables) or dropped requests (expired +//! token, server errors, offline). Everything that can lose a minute is +//! recorded here, always on — also in release builds — so a bug report can show +//! the expected-versus-credited timeline per game. +//! +//! The log is written to a rotating file in the app log directory +//! (`tracker-logs/tracker.log`) and kept in a bounded in-memory tail that the +//! settings dump reads. Secrets are never logged: tokens are reduced to a +//! fingerprint via [`redact_token`]. + +use serde::Serialize; +use std::collections::VecDeque; +use std::fs::{self, File, OpenOptions}; +use std::io::{BufWriter, Read, Seek, SeekFrom, Write}; +use std::path::{Path, PathBuf}; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::sync::{Arc, Mutex, OnceLock}; +use std::time::{SystemTime, UNIX_EPOCH}; +use tauri::{AppHandle, Manager}; + +/// Maximum number of lines kept in memory (oldest are dropped). +const MAX_TAIL_LINES: usize = 3_000; +/// Rotate the active file once it grows past this size. +const MAX_FILE_BYTES: u64 = 8 * 1024 * 1024; +/// Number of rotated log files kept on disk (oldest are deleted). +const MAX_LOG_FILES: usize = 10; +/// Active log file name inside the tracker log directory. +const ACTIVE_FILE_NAME: &str = "tracker.log"; + +/// Master switch for the always-on tracker log. +/// +/// While this is `false`, no file is written and no line is recorded: the +/// tracker still keeps its counters and the per-game playtime ledger in memory, +/// but nothing is persisted. Flip it back to `true` (and restore the hook's +/// `tracker_log_line` call in `useGameTimeTracker.ts`) to record the full +/// tick-by-tick trace again for diagnostics. +pub(crate) const ENABLED: bool = false; + +#[derive(Serialize, Clone)] +#[serde(rename_all = "camelCase")] +pub struct TrackerLogLine { + pub seq: u64, + /// Milliseconds since the unix epoch. + pub at: u64, + /// `info`, `warn`, `error` or `tick`. + pub level: String, + /// Coarse origin, e.g. `lifecycle`, `tick`, `game`, `http`, `ledger`, `app`. + pub category: String, + pub text: String, +} + +pub(crate) struct TrackerLog { + seq: AtomicU64, + written: AtomicU64, + lines: Mutex>, + file: Mutex>>, + path: Mutex>, +} + +static LOG: OnceLock>>> = OnceLock::new(); + +fn store() -> &'static Mutex>> { + LOG.get_or_init(|| Mutex::new(None)) +} + +/// Milliseconds since the unix epoch. +pub(crate) fn now_ms() -> u64 { + SystemTime::now() + .duration_since(UNIX_EPOCH) + .map(|duration| duration.as_millis() as u64) + .unwrap_or(0) +} + +/// Absolute path of the directory holding the tracker logs. +pub(crate) fn log_directory(app: &AppHandle) -> Option { + let dir = app.path().app_log_dir().ok()?.join("tracker-logs"); + fs::create_dir_all(&dir).ok()?; + Some(dir) +} + +/// Starts (or restarts) the tracker log. Safe to call more than once. +pub(crate) fn init(app: &AppHandle) { + if !ENABLED { + return; + } + + let Some(dir) = log_directory(app) else { + return; + }; + + let path = dir.join(ACTIVE_FILE_NAME); + let file = OpenOptions::new() + .create(true) + .append(true) + .open(&path) + .ok() + .map(BufWriter::new); + + let written = file + .as_ref() + .and_then(|_| fs::metadata(&path).ok()) + .map(|metadata| metadata.len()) + .unwrap_or(0); + + let log = Arc::new(TrackerLog { + seq: AtomicU64::new(0), + written: AtomicU64::new(written), + lines: Mutex::new(VecDeque::new()), + file: Mutex::new(file), + path: Mutex::new(Some(path)), + }); + + match store().lock() { + Ok(mut guard) => *guard = Some(log.clone()), + Err(_) => return, + } + + prune_old_files(&dir); + push( + "info", + "lifecycle", + &format!("=== tracker log started (v{}) ===", env!("CARGO_PKG_VERSION")), + ); +} + +/// Returns the active log file path, if the logger has been initialized. +pub(crate) fn log_path() -> Option { + store() + .lock() + .ok() + .and_then(|guard| guard.as_ref().cloned()) + .and_then(|log| { + log + .path + .lock() + .ok() + .and_then(|value| value.as_ref().map(|p| p.to_string_lossy().to_string())) + }) +} + +/// Appends one line to the in-memory tail and the log file. +pub(crate) fn push(level: &str, category: &str, text: &str) { + if !ENABLED { + return; + } + + match level { + "error" => log::error!("[tracker:{category}] {text}"), + "warn" => log::warn!("[tracker:{category}] {text}"), + _ => log::info!("[tracker:{category}] {text}"), + } + + let log = match store().lock() { + Ok(guard) => guard.as_ref().cloned(), + Err(_) => None, + }; + let Some(log) = log else { + return; + }; + + let seq = log.seq.fetch_add(1, Ordering::SeqCst); + let at = now_ms(); + let line = TrackerLogLine { + seq, + at, + level: level.to_string(), + category: category.to_string(), + text: text.to_string(), + }; + + if let Ok(mut lines) = log.lines.lock() { + lines.push_back(line.clone()); + while lines.len() > MAX_TAIL_LINES { + lines.pop_front(); + } + } + + let rendered = format_line(&line) + "\n"; + let mut rotate = false; + if let Ok(mut guard) = log.file.lock() { + if let Some(writer) = guard.as_mut() { + if writer.write_all(rendered.as_bytes()).is_ok() && writer.flush().is_ok() { + let total = log + .written + .fetch_add(rendered.len() as u64, Ordering::SeqCst) + + rendered.len() as u64; + rotate = total >= MAX_FILE_BYTES; + } + } + } + if rotate { + rotate_active_file(&log); + } +} + +/// Appends a `key=value` line. Values are quoted when they contain a space. +pub(crate) fn push_kv(level: &str, category: &str, fields: &[(&str, String)]) { + push(level, category, &format_kv(fields)); +} + +/// Renders fields as `key=value` pairs, quoting values that need it. +pub(crate) fn format_kv(fields: &[(&str, String)]) -> String { + fields + .iter() + .map(|(key, value)| { + if value.contains(' ') || value.is_empty() { + format!("{key}=\"{value}\"") + } else { + format!("{key}={value}") + } + }) + .collect::>() + .join(" ") +} + +fn rotate_active_file(log: &Arc) { + let path = match log.path.lock() { + Ok(guard) => guard.clone(), + Err(_) => None, + }; + let Some(path) = path else { + return; + }; + let directory = match path.parent() { + Some(directory) => directory.to_path_buf(), + None => return, + }; + + // Drop the writer first so the file handle is closed before renaming. + if let Ok(mut guard) = log.file.lock() { + *guard = None; + } + + let rotated = directory.join(format!("tracker-{}.log", now_ms() / 1000)); + let renamed = fs::rename(&path, &rotated).is_ok(); + + if let Ok(mut guard) = log.file.lock() { + *guard = OpenOptions::new() + .create(true) + .append(true) + .open(&path) + .ok() + .map(BufWriter::new); + } + log.written.store(0, Ordering::SeqCst); + + if renamed { + push( + "info", + "lifecycle", + &format!( + "rotated tracker log to {}", + rotated.file_name().unwrap_or_default().to_string_lossy() + ), + ); + prune_old_files(&directory); + } +} + +fn prune_old_files(directory: &Path) { + let Ok(entries) = fs::read_dir(directory) else { + return; + }; + let mut files: Vec = entries + .flatten() + .map(|entry| entry.path()) + .filter(|path| { + path + .file_name() + .map(|name| name.to_string_lossy().starts_with("tracker-")) + .unwrap_or(false) + }) + .collect(); + files.sort(); + while files.len() > MAX_LOG_FILES { + let oldest = files.remove(0); + let _ = fs::remove_file(oldest); + } +} + +/// Formats one line: `2026-09-26 10:15:23.123 [tick] text`. +fn format_line(line: &TrackerLogLine) -> String { + format!( + "{} [{}] {}", + format_timestamp(line.at), + line.level, + line.text + ) +} + +/// Formats unix milliseconds as `YYYY-MM-DD HH:MM:SS.mmm` (UTC). +pub(crate) fn format_timestamp(unix_ms: u64) -> String { + let secs = (unix_ms / 1000) as i64; + let millis = (unix_ms % 1000) as u32; + let days = secs.div_euclid(86_400); + let rest = secs.rem_euclid(86_400); + let (year, month, day) = civil_from_days(days); + format!( + "{year:04}-{month:02}-{day:02} {:02}:{:02}:{:02}.{millis:03}", + rest / 3600, + (rest % 3600) / 60, + rest % 60 + ) +} + +/// Howard Hinnant's civil-from-days algorithm (days since 1970-01-01 → Y/M/D). +fn civil_from_days(days: i64) -> (i64, u32, u32) { + let z = days + 719_468; + let era = if z >= 0 { z } else { z - 146_096 } / 146_097; + let doe = (z - era * 146_097) as i64; + let yoe = (doe - doe / 1460 + doe / 36_524 - doe / 146_096) / 365; + let year = yoe + era * 400; + let doy = doe - (365 * yoe + yoe / 4 - yoe / 100); + let mp = (5 * doy + 2) / 153; + let day = (doy - (153 * mp + 2) / 5 + 1) as u32; + let month = if mp < 10 { mp + 3 } else { mp - 9 } as u32; + (if month <= 2 { year + 1 } else { year }, month, day) +} + +/// Never log a raw token: returns a fingerprint with length and last 6 chars. +pub(crate) fn redact_token(token: &str) -> String { + if token.is_empty() { + return "none".to_string(); + } + let tail: String = token + .chars() + .rev() + .take(6) + .collect::>() + .into_iter() + .rev() + .collect(); + format!("", token.chars().count(), tail) +} + +/// Returns the in-memory tail, oldest first. +pub(crate) fn tail(limit: usize) -> Vec { + let log = match store().lock() { + Ok(guard) => guard.as_ref().cloned(), + Err(_) => None, + }; + let Some(log) = log else { + return Vec::new(); + }; + let lines = match log.lines.lock() { + Ok(lines) => lines, + Err(_) => return Vec::new(), + }; + let skip = lines.len().saturating_sub(limit); + lines.iter().skip(skip).cloned().collect() +} + +fn clear(app: &AppHandle) { + let log = match store().lock() { + Ok(guard) => guard.as_ref().cloned(), + Err(_) => None, + }; + if let Some(log) = log.as_ref() { + if let Ok(mut lines) = log.lines.lock() { + lines.clear(); + } + // Close the writer before the file is deleted below. + if let Ok(mut guard) = log.file.lock() { + *guard = None; + } + } + + let Some(directory) = log_directory(app) else { + return; + }; + if let Ok(entries) = fs::read_dir(&directory) { + for entry in entries.flatten() { + let _ = fs::remove_file(entry.path()); + } + } + + if let Some(log) = log { + let path = directory.join(ACTIVE_FILE_NAME); + if let Ok(mut guard) = log.file.lock() { + *guard = OpenOptions::new() + .create(true) + .append(true) + .open(&path) + .ok() + .map(BufWriter::new); + } + if let Ok(mut guard) = log.path.lock() { + *guard = Some(path); + } + log.written.store(0, Ordering::SeqCst); + } + push("info", "lifecycle", "tracker log cleared"); +} + +// ── Commands ─────────────────────────────────────────────────────────────── + +#[tauri::command] +pub(crate) fn get_tracker_log(limit: Option) -> Vec { + tail(limit.unwrap_or(MAX_TAIL_LINES).min(MAX_TAIL_LINES)) +} + +#[tauri::command] +pub(crate) fn clear_tracker_log(app: AppHandle) -> Result<(), String> { + clear(&app); + Ok(()) +} + +#[tauri::command] +pub(crate) fn open_tracker_log_folder(app: AppHandle) -> Result<(), String> { + let dir = log_directory(&app).ok_or_else(|| "Log directory unavailable".to_string())?; + crate::games::open_in_file_explorer(dir.to_string_lossy().to_string()) +} + +/// Reads the tail of a tracker log file (for rotated files). +#[tauri::command] +pub(crate) fn read_tracker_log_file(path: String, max_bytes: Option) -> Result { + let mut file = + File::open(&path).map_err(|error| format!("Failed to open tracker log: {error}"))?; + let length = file + .metadata() + .map_err(|error| format!("Failed to read tracker log: {error}"))? + .len(); + let max_bytes = max_bytes.unwrap_or(512 * 1024); + let start = length.saturating_sub(max_bytes); + if start > 0 { + file.seek(SeekFrom::Start(start)) + .map_err(|error| format!("Failed to read tracker log: {error}"))?; + } + let mut buffer = String::new(); + file + .read_to_string(&mut buffer) + .map_err(|error| format!("Failed to read tracker log: {error}"))?; + if start > 0 { + if let Some(index) = buffer.find('\n') { + buffer.drain(..=index); + } + } + Ok(buffer) +} + +/// Lets the frontend record lifecycle decisions in the same log. +#[tauri::command] +pub(crate) fn tracker_log_line(level: String, category: String, message: String) { + push(&level, &format!("app:{category}"), &message); +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn formats_unix_millis_as_utc_timestamp() { + assert_eq!(format_timestamp(0), "1970-01-01 00:00:00.000"); + assert_eq!(format_timestamp(1_000), "1970-01-01 00:00:01.000"); + // Well-known epoch: 2020-09-13 12:26:40 UTC + assert_eq!(format_timestamp(1_600_000_000_000), "2020-09-13 12:26:40.000"); + // Leap-day sanity check: 2024-02-29 00:00:00 UTC + assert_eq!(format_timestamp(1_709_164_800_000), "2024-02-29 00:00:00.000"); + } + + #[test] + fn redacts_tokens() { + assert_eq!(redact_token(""), "none"); + let redacted = redact_token("abcdefghijklmnop"); + assert!(!redacted.contains("abcdefghij")); + assert!(redacted.contains("klmnop")); + assert!(redacted.contains("16")); + } + + #[test] + fn formats_key_value_lines() { + let text = format_kv(&[ + ("tick", "7".to_string()), + ("game", "42".to_string()), + ("title", "My Game".to_string()), + ]); + assert_eq!(text, "tick=7 game=42 title=\"My Game\""); + } + + #[test] + fn tail_is_empty_without_logger() { + assert!(tail(10).is_empty()); + } +} diff --git a/src/hooks/useGameTimeTracker.ts b/src/hooks/useGameTimeTracker.ts index d1b3fae..c291a76 100644 --- a/src/hooks/useGameTimeTracker.ts +++ b/src/hooks/useGameTimeTracker.ts @@ -1,15 +1,190 @@ -import { useEffect, useRef } from "react"; +import { useCallback, useEffect, useRef } from "react"; import { useAuth } from "@/context/AuthContext"; import { useOnlineStatus } from "@/context/OfflineContext"; import { isTauriApp } from "@/utils/tauri"; import { getRootPaths } from "@/utils/rootPaths"; +/** + * Game time tracker lifecycle controller. + * + * The actual tracking runs in the Rust backend (`src-tauri/src/time_tracker.rs`): + * it polls every 60 seconds, matches running processes to installed games and + * credits one minute per matched game. This hook only starts/stops that native + * loop and replays playtime that was recorded offline. + * + * Every decision and every previously swallowed `invoke` failure is written to + * the native tracker log, because the loop credits exactly one minute per tick: + * a playtime that ends up lower than what was played is always caused by a + * missed tick, a lost process match or a rejected request, and the log has to + * show which one it was. + */ + +interface OfflineTimeFile { + path: string; + userId: number; + gameId: number; + accumulatedMinutes: number; + /** Unix seconds of the last write; 0 for files from older builds. */ + updatedAt: number; +} + +/** Payload of the native `tracker-auth-expired` event. */ +interface TrackerAuthExpiredPayload { + at: number; + authRejectedCount: number; + pendingOfflineMinutes: number; + retryInSecs: number; +} + +/** Only the part of the native tracker status this hook needs. */ +interface TrackerStatusSummary { + pendingOfflineMinutes: number; +} + +const AUTH_EXPIRED_EVENT = "tracker-auth-expired"; + +/** + * How often the hook refreshes the session and hands it to the native tracker. + * + * Must stay well below the server's access-token lifetime (a few minutes), + * otherwise the tracker always runs one tick on a token that just expired. + */ +const KEEP_ALIVE_MS = 60 * 1000; +/** How often pending offline playtime is retried in the background. */ +const PENDING_RETRY_MS = 5 * 60 * 1000; + +/** + * Mirrors a frontend lifecycle line to the console. + * + * The native tracker log is disabled (`tracker_log::ENABLED` in + * `src-tauri/src/tracker_log.rs`), so nothing is sent over IPC. Re-add the + * `tracker_log_line` invoke here when the native log is switched back on. + */ +async function logTrackerLine( + level: "info" | "warn" | "error", + category: string, + message: string, +): Promise { + if (level === "error") { + console.error(`[tracker:${category}]`, message); + } else if (level === "warn") { + console.warn(`[tracker:${category}]`, message); + } else { + console.debug(`[tracker:${category}]`, message); + } +} + +/** + * Invokes a tracker command and records failures. + * + * These calls used to be `.catch(() => {})`, which hid a tracker that never + * started or never stopped. + */ +async function invokeTracker( + command: string, + args?: Record, +): Promise { + try { + const { invoke } = await import("@tauri-apps/api/core"); + return await invoke(command, args); + } catch (error) { + await logTrackerLine("error", "invoke", `${command} failed: ${String(error)}`); + return null; + } +} + +/** + * Replays every offline time file and logs what was found, credited or kept. + * + * `reason` ends up in the log so a failed replay can be traced back to startup + * or a reconnect. + */ +async function reconcileOfflineTime(options: { + serverUrl: string; + accessToken: string; + reason: string; +}): Promise { + const rootPaths = getRootPaths(); + if (!rootPaths.length) { + await logTrackerLine( + "warn", + "offline", + `${options.reason}: no root paths configured, skipping offline replay`, + ); + return; + } + + let files = 0; + let creditedMinutes = 0; + let pendingMinutes = 0; + let oldestFileMinutes = 0; + + for (const root of rootPaths) { + const offlineFiles = + (await invokeTracker("get_offline_time_files", { + selectedRoot: root.path, + })) ?? []; + + for (const file of offlineFiles) { + files += 1; + + if (file.updatedAt) { + const ageMinutes = Math.max( + 0, + Math.round(Date.now() / 1000 - file.updatedAt) / 60, + ); + oldestFileMinutes = Math.max(oldestFileMinutes, Math.round(ageMinutes)); + } + + if (!file.accumulatedMinutes || file.accumulatedMinutes <= 0) { + await invokeTracker("delete_offline_time_file", { path: file.path }); + continue; + } + + const success = await invokeTracker("sync_offline_time", { + serverUrl: options.serverUrl, + accessToken: options.accessToken, + userId: file.userId, + gameId: file.gameId, + minutes: file.accumulatedMinutes, + reason: options.reason, + }); + + if (success) { + creditedMinutes += file.accumulatedMinutes; + await invokeTracker("delete_offline_time_file", { path: file.path }); + } else { + pendingMinutes += file.accumulatedMinutes; + } + } + } + + const age = oldestFileMinutes > 0 ? `, oldest file ${oldestFileMinutes} min old` : ""; + await logTrackerLine( + pendingMinutes > 0 ? "warn" : "info", + "offline", + `${options.reason}: ${files} offline file(s), credited ${creditedMinutes} min, ${pendingMinutes} min kept for the next attempt${age}`, + ); +} + export function useGameTimeTracker() { - const { serverUrl, user, auth } = useAuth(); + const { serverUrl, user, auth, getAccessToken } = useAuth(); const { onReconnect } = useOnlineStatus(); const startedRef = useRef<{ serverUrl: string; userId: number } | null>(null); const syncInFlightRef = useRef(false); const initialSyncDoneRef = useRef(false); + /** Token last handed to the native tracker (avoids duplicate pushes). */ + const pushedTokenRef = useRef(null); + + /** + * Hands a (possibly refreshed) token to the native tracker — but only when it + * actually changed, so the log does not fill up with duplicate auth lines. + */ + const pushToken = useCallback((token: string) => { + if (pushedTokenRef.current === token) return; + pushedTokenRef.current = token; + void invokeTracker("update_tracker_auth", { accessToken: token }); + }, []); // Start / restart tracker as soon as credentials are available. We key the // "started" state on server+user so a token refresh (handled by @@ -21,52 +196,83 @@ export function useGameTimeTracker() { const accessToken = auth?.access_token; const downloadPaths = getRootPaths().map((p) => p.path); - if (!serverUrl || !userId || !accessToken || !downloadPaths.length) { - // If tracker was running but credentials are gone (logout), stop it + if (!serverUrl || !userId || !accessToken) { if (startedRef.current) { + // Logout or a genuinely missing session: stop the native loop. startedRef.current = null; - import("@tauri-apps/api/core").then(({ invoke }) => { - invoke("stop_game_time_tracker").catch(() => {}); + void logTrackerLine( + "info", + "lifecycle", + "stopping tracker: credentials are gone (logout or missing session)", + ); + void invokeTracker("stop_game_time_tracker", { + reason: "credentials unavailable (logout or missing session)", }); + } else { + void logTrackerLine("info", "lifecycle", "tracker idle: waiting for credentials"); + } + return; + } + + if (!downloadPaths.length) { + if (startedRef.current) { + // Root paths can be momentarily empty (storage still loading). The + // native loop re-reads the library every tick, so keep it running + // instead of tearing down a session that is tracking a running game. + void logTrackerLine( + "warn", + "lifecycle", + "root paths are empty but the session is valid — keeping the tracker running", + ); + } else { + void logTrackerLine( + "warn", + "lifecycle", + "tracker idle: no download root paths configured", + ); } return; } const started = startedRef.current; - if ( - started && - started.serverUrl === serverUrl && - started.userId === userId - ) { + if (started && started.serverUrl === serverUrl && started.userId === userId) { // Same session (token may have refreshed); leave the loop running. return; } // New session or a changed server/user — (re)start with fresh credentials. if (started) { - import("@tauri-apps/api/core").then(({ invoke }) => { - invoke("stop_game_time_tracker").catch(() => {}); - }); + void logTrackerLine( + "info", + "lifecycle", + `restarting tracker for a new session (server=${serverUrl}, user=${userId}, roots=${downloadPaths.length})`, + ); + } else { + void logTrackerLine( + "info", + "lifecycle", + `starting tracker (server=${serverUrl}, user=${userId}, roots=${downloadPaths.length})`, + ); } + startedRef.current = { serverUrl, userId }; - import("@tauri-apps/api/core").then(({ invoke }) => { - invoke("start_game_time_tracker", { - serverUrl, - userId, - accessToken, - downloadPath: null, - downloadPaths, - }).catch(() => {}); + pushedTokenRef.current = accessToken; + void invokeTracker("start_game_time_tracker", { + serverUrl, + userId, + accessToken, + downloadPath: null, + downloadPaths, }); }, [serverUrl, user?.id, auth?.access_token]); // Stop the tracker on unmount. useEffect(() => { return () => { + if (!startedRef.current) return; startedRef.current = null; - import("@tauri-apps/api/core").then(({ invoke }) => { - invoke("stop_game_time_tracker").catch(() => {}); - }); + void logTrackerLine("info", "lifecycle", "stopping tracker: hook unmounted"); + void invokeTracker("stop_game_time_tracker", { reason: "hook unmounted" }); }; }, []); @@ -75,11 +281,8 @@ export function useGameTimeTracker() { if (!isTauriApp() || !startedRef.current) return; const accessToken = auth?.access_token; if (!accessToken) return; - - import("@tauri-apps/api/core").then(({ invoke }) => { - invoke("update_tracker_auth", { accessToken }).catch(() => {}); - }); - }, [auth?.access_token]); + pushToken(accessToken); + }, [auth?.access_token, pushToken]); // Sync any lingering offline time on startup (handles case where user // went offline, closed the app, then restarted while online) @@ -89,105 +292,218 @@ export function useGameTimeTracker() { if (initialSyncDoneRef.current) return; initialSyncDoneRef.current = true; - (async () => { + void reconcileOfflineTime({ + serverUrl, + accessToken: auth.access_token, + reason: "startup", + }); + }, [serverUrl, auth?.access_token]); + + // Sync offline time when coming back online + useEffect(() => { + if (!isTauriApp()) return; + + const unregister = onReconnect(async () => { + if (syncInFlightRef.current) return; + syncInFlightRef.current = true; + try { - const rootPaths = getRootPaths(); - if (!rootPaths.length) return; - - const { invoke } = await import("@tauri-apps/api/core"); - - for (const root of rootPaths) { - const files = await invoke("get_offline_time_files", { - selectedRoot: root.path, - }).catch(() => [] as any[]); - - for (const file of files) { - if (!file.accumulatedMinutes || file.accumulatedMinutes <= 0) { - await invoke("delete_offline_time_file", { - path: file.path, - }).catch(() => {}); - continue; + await reconcileOfflineTime({ + serverUrl, + accessToken: auth?.access_token || "", + reason: "reconnect", + }); + } finally { + syncInFlightRef.current = false; + } + }); + + return unregister; + }, [onReconnect, serverUrl, auth?.access_token]); + + // The native tracker tells us when the server rejects its session. Without + // this, the tracker kept using an expired token for as long as the UI made + // no authenticated request (an hour of playtime ended up offline). + useEffect(() => { + if (!isTauriApp()) return; + + let unlisten: (() => void) | undefined; + let disposed = false; + + void (async () => { + try { + const { listen } = await import("@tauri-apps/api/event"); + const stop = await listen( + AUTH_EXPIRED_EVENT, + async (event) => { + const { authRejectedCount, pendingOfflineMinutes, retryInSecs } = + event.payload; + await logTrackerLine( + "warn", + "auth", + `server rejected the session (${authRejectedCount} rejection(s), ${pendingOfflineMinutes} min stored offline, next retry in ${retryInSecs}s) — requesting a fresh session`, + ); + + // Refreshes the token when it is near expiry (single-flight). + const token = await getAccessToken(); + if (!token) { + await logTrackerLine( + "error", + "auth", + "no fresh session available — playtime keeps being stored offline", + ); + return; } + pushToken(token); + + if (syncInFlightRef.current) return; + syncInFlightRef.current = true; try { - const success = await invoke("sync_offline_time", { + await reconcileOfflineTime({ serverUrl, - accessToken: auth.access_token, - userId: file.userId, - gameId: file.gameId, - minutes: file.accumulatedMinutes, + accessToken: token, + reason: "auth-refresh", }); - - if (success) { - await invoke("delete_offline_time_file", { - path: file.path, - }).catch(() => {}); - } - } catch { - // Retry on next reconnect + } finally { + syncInFlightRef.current = false; } - } + }, + ); + + if (disposed) { + stop(); + } else { + unlisten = stop; } - } catch { - // Silently fail + } catch (error) { + await logTrackerLine( + "error", + "auth", + `could not subscribe to ${AUTH_EXPIRED_EVENT}: ${String(error)}`, + ); } })(); - }, [serverUrl, auth?.access_token]); - // Sync offline time when coming back online + return () => { + disposed = true; + unlisten?.(); + }; + }, [getAccessToken, pushToken, serverUrl]); + + // Keep the native tracker's session copy fresh. Token refresh is otherwise + // lazy (nothing asks for a new token while the UI sits idle), and a token + // that is only refreshed at its expiry moment is always rejected once before + // it lands — so this refreshes well ahead of the deadline. useEffect(() => { if (!isTauriApp()) return; - const unregister = onReconnect(async () => { + const id = window.setInterval(() => { + if (!startedRef.current) return; + void getAccessToken().then((token) => { + if (token) { + pushToken(token); + } + }); + }, KEEP_ALIVE_MS); + + return () => window.clearInterval(id); + }, [getAccessToken, pushToken]); + + // Retry playtime that is waiting offline, without needing an app restart. + useEffect(() => { + if (!isTauriApp()) return; + + const id = window.setInterval(async () => { if (syncInFlightRef.current) return; - syncInFlightRef.current = true; + const status = await invokeTracker("get_tracker_status"); + if (!status || status.pendingOfflineMinutes <= 0) return; + + const token = await getAccessToken(); + if (!token) return; + pushToken(token); + + syncInFlightRef.current = true; try { - const rootPaths = getRootPaths(); - if (!rootPaths.length) return; - - const { invoke } = await import("@tauri-apps/api/core"); - - for (const root of rootPaths) { - const files = await invoke("get_offline_time_files", { - selectedRoot: root.path, - }).catch(() => [] as any[]); - - for (const file of files) { - if (!file.accumulatedMinutes || file.accumulatedMinutes <= 0) { - // Delete empty files - await invoke("delete_offline_time_file", { - path: file.path, - }).catch(() => {}); - continue; - } + await reconcileOfflineTime({ + serverUrl, + accessToken: token, + reason: "periodic-retry", + }); + } finally { + syncInFlightRef.current = false; + } + }, PENDING_RETRY_MS); - try { - const success = await invoke("sync_offline_time", { - serverUrl, - accessToken: auth?.access_token || "", - userId: file.userId, - gameId: file.gameId, - minutes: file.accumulatedMinutes, - }); + return () => window.clearInterval(id); + }, [getAccessToken, pushToken, serverUrl]); - if (success) { - await invoke("delete_offline_time_file", { - path: file.path, - }).catch(() => {}); - } - } catch { - // Retry on next reconnect - } - } - } - } catch { - // Silently fail — retry on next reconnect + // The browser reporting "online" is the earliest signal that the server is + // reachable again — replay immediately instead of waiting for the poller. + useEffect(() => { + if (!isTauriApp()) return; + + const handleOnline = async () => { + if (syncInFlightRef.current) return; + + const token = await getAccessToken(); + if (!token) return; + pushToken(token); + + syncInFlightRef.current = true; + try { + await reconcileOfflineTime({ + serverUrl, + accessToken: token, + reason: "browser-online", + }); } finally { syncInFlightRef.current = false; } - }); + }; - return unregister; - }, [onReconnect, serverUrl, auth?.access_token]); + window.addEventListener("online", handleOnline); + return () => window.removeEventListener("online", handleOnline); + }, [getAccessToken, pushToken, serverUrl]); + + // Record window visibility and connectivity next to the tracker ticks, so a + // sleep/resume or an offline window lines up with the tick gaps in the log. + useEffect(() => { + if (!isTauriApp()) return; + + const handleVisibility = () => { + void logTrackerLine("info", "app", `window visibility: ${document.visibilityState}`); + }; + const handleFocus = () => { + void logTrackerLine("info", "app", "window focused"); + }; + const handleBlur = () => { + void logTrackerLine("info", "app", "window blurred"); + }; + const handleOnline = () => { + void logTrackerLine("info", "app", "browser reports online"); + }; + const handleOffline = () => { + void logTrackerLine( + "warn", + "app", + "browser reports offline — playtime is stored offline until the connection returns", + ); + }; + + document.addEventListener("visibilitychange", handleVisibility); + window.addEventListener("focus", handleFocus); + window.addEventListener("blur", handleBlur); + window.addEventListener("online", handleOnline); + window.addEventListener("offline", handleOffline); + + return () => { + document.removeEventListener("visibilitychange", handleVisibility); + window.removeEventListener("focus", handleFocus); + window.removeEventListener("blur", handleBlur); + window.removeEventListener("online", handleOnline); + window.removeEventListener("offline", handleOffline); + }; + }, []); }