merge time-tracker_logger into develop

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.

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<String>,
 ) -> 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<String>,
+    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;
         }
 

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,

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<Mutex<Option<(u64, AppSettings)>>> = OnceLock::new();
+
+fn settings_cache() -> &'static Mutex<Option<(u64, AppSettings)>> {
+  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::<AppSettings>(&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::<AppSettings>(&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]

src-tauri/src/state.rs

@@ -31,6 +31,128 @@ pub(crate) fn tracker_stop_tx() -> &'static Mutex<Option<watch::Sender<bool>>> {
   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<u64>,
+  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<u64>,
+  pub last_tick_gap_secs: Option<u64>,
+  pub last_tick_duration_ms: Option<u64>,
+  pub last_tick_summary: Option<String>,
+  pub last_error: Option<String>,
+  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<u64>,
+  /// 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<u64>,
+  pub stop_reason: Option<String>,
+  pub log_path: Option<String>,
+}
+
+/// 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<u64>,
+  pub last_matched_at: Option<u64>,
+  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<i64>,
+  /// Why the game was not matched/credited on the last tick.
+  pub last_skip_reason: Option<String>,
+}
+
+static TRACKER_STATS: OnceLock<Mutex<TrackerRuntimeStats>> = OnceLock::new();
+static TRACKER_LEDGER: OnceLock<Mutex<HashMap<i64, GamePlayLedger>>> = OnceLock::new();
+
+pub(crate) fn tracker_stats() -> &'static Mutex<TrackerRuntimeStats> {
+  TRACKER_STATS.get_or_init(|| Mutex::new(TrackerRuntimeStats::default()))
+}
+
+pub(crate) fn tracker_ledger() -> &'static Mutex<HashMap<i64, GamePlayLedger>> {
+  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<GamePlayLedger> {
+  tracker_ledger()
+    .lock()
+    .map(|ledger| {
+      let mut games: Vec<GamePlayLedger> = 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