From bf625fac2c2ce55d1e92c04890a96e040a4dd8eb Mon Sep 17 00:00:00 2001 From: zhom <2717306+zhom@users.noreply.github.com> Date: Thu, 8 Oct 2026 23:13:19 +0400 Subject: [PATCH] refactor: better logs --- AGENTS.md | 19 +- e2e/app/Cargo.lock | 2 +- e2e/tests/browser.test.mjs | 6 +- e2e/tests/smoke.test.mjs | 24 +- e2e/tests/ui.test.mjs | 38 +- src-tauri/src/agent_console.rs | 2 +- src-tauri/src/api_client.rs | 71 +- src-tauri/src/api_server.rs | 67 +- src-tauri/src/app_auto_updater.rs | 681 ++++++++++-------- src-tauri/src/app_dirs.rs | 7 +- src-tauri/src/auto_updater.rs | 234 +++--- src-tauri/src/bin/proxy_server.rs | 189 +++-- src-tauri/src/browser.rs | 6 +- src-tauri/src/browser_runner.rs | 653 +++++++---------- src-tauri/src/browser_version_manager.rs | 23 +- src-tauri/src/cdp_target.rs | 18 +- src-tauri/src/cloud_auth.rs | 204 +++--- src-tauri/src/commercial_license.rs | 4 +- src-tauri/src/cookie_bot.rs | 15 +- src-tauri/src/default_browser.rs | 10 +- src-tauri/src/dns_blocklist.rs | 91 ++- src-tauri/src/downloaded_browsers_registry.rs | 268 +++---- src-tauri/src/downloader.rs | 149 ++-- src-tauri/src/ephemeral_dirs.rs | 175 ++++- src-tauri/src/extension_fetch.rs | 12 +- src-tauri/src/extension_manager.rs | 43 +- src-tauri/src/extraction.rs | 153 ++-- src-tauri/src/fingerprint_consistency.rs | 10 +- src-tauri/src/fs_secure.rs | 5 +- src-tauri/src/geoip_downloader.rs | 7 +- src-tauri/src/geolocation.rs | 4 +- src-tauri/src/group_bookmarks.rs | 6 +- src-tauri/src/group_manager.rs | 16 +- src-tauri/src/launch_gate.rs | 41 +- src-tauri/src/launch_gate_prefs.rs | 8 +- src-tauri/src/legacy_autostart.rs | 131 ++++ src-tauri/src/lib.rs | 283 ++++---- src-tauri/src/log_streak.rs | 391 ++++++++++ src-tauri/src/mcp_remote.rs | 45 +- src-tauri/src/mcp_server.rs | 53 +- src-tauri/src/platform_browser.rs | 89 +-- src-tauri/src/process_report.rs | 63 ++ src-tauri/src/profile/clear_on_close.rs | 13 +- src-tauri/src/profile/manager.rs | 259 ++++--- src-tauri/src/profile/password.rs | 18 +- src-tauri/src/profile/portable.rs | 5 +- src-tauri/src/profile/trash.rs | 30 +- src-tauri/src/profile_generation_limiter.rs | 2 +- src-tauri/src/profile_import/copy.rs | 10 +- src-tauri/src/profile_import/keyring.rs | 14 +- src-tauri/src/profile_import/mod.rs | 2 +- src-tauri/src/profile_import/os_crypt.rs | 2 +- src-tauri/src/profile_import/rewrite.rs | 5 +- src-tauri/src/profile_importer.rs | 25 +- src-tauri/src/proxy_distribution.rs | 2 +- src-tauri/src/proxy_manager.rs | 238 +++--- src-tauri/src/proxy_runner.rs | 71 +- src-tauri/src/proxy_server.rs | 284 ++++---- src-tauri/src/proxy_udp.rs | 8 +- src-tauri/src/recipes.rs | 6 +- src-tauri/src/remote_handoff.rs | 43 +- src-tauri/src/remote_session.rs | 33 +- src-tauri/src/settings_manager.rs | 28 +- src-tauri/src/socks5_local.rs | 84 ++- src-tauri/src/sync/engine.rs | 529 +++++--------- src-tauri/src/sync/manifest.rs | 7 +- src-tauri/src/sync/mod.rs | 12 +- src-tauri/src/sync/pending_deletes.rs | 8 +- src-tauri/src/sync/preflight.rs | 4 +- src-tauri/src/sync/scheduler.rs | 249 ++++--- src-tauri/src/sync/subscription.rs | 65 +- src-tauri/src/synchronizer.rs | 125 ++-- src-tauri/src/team_lock.rs | 43 +- src-tauri/src/traffic_stats.rs | 7 +- src-tauri/src/vault.rs | 2 +- src-tauri/src/version_updater.rs | 101 +-- src-tauri/src/vpn/socks5_server.rs | 53 +- src-tauri/src/vpn/wireguard.rs | 4 +- .../src/vpn_extension_detect/browser_scan.rs | 2 +- src-tauri/src/vpn_extension_detect/mod.rs | 2 +- src-tauri/src/vpn_worker_runner.rs | 64 +- src-tauri/src/wayfern_cdp.rs | 8 +- src-tauri/src/wayfern_identity_storage.rs | 40 +- src-tauri/src/wayfern_manager.rs | 467 ++++++------ src-tauri/src/wayfern_terms.rs | 14 +- src-tauri/src/window_decorations.rs | 18 +- src-tauri/src/xray_worker_runner.rs | 65 +- src/components/agent-profiles.tsx | 55 +- src/components/profile-data-table.tsx | 2 +- src/components/table-controls.tsx | 126 ++-- src/lib/logger.ts | 22 +- 91 files changed, 4353 insertions(+), 3239 deletions(-) create mode 100644 src-tauri/src/legacy_autostart.rs create mode 100644 src-tauri/src/log_streak.rs create mode 100644 src-tauri/src/process_report.rs diff --git a/AGENTS.md b/AGENTS.md index ef593312..2fd2e9c2 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -77,7 +77,7 @@ donutbrowser/ │ │ ├── extension_fetch.rs # Web Store link/id and direct .crx/.zip import, CRX3 unwrapping │ │ ├── group_manager.rs # Profile group management │ │ ├── synchronizer.rs # Real-time profile synchronizer (pause/resume, hold a follower out, window layouts) -│ │ ├── daemon/ # Background daemon + tray icon (currently disabled) +│ │ ├── legacy_autostart.rs # Removes the autostart entry the removed tray daemon (0.14-0.17) left behind │ │ └── cloud_auth.rs # Cloud authentication │ ├── tests/ # Integration tests │ └── Cargo.toml # Rust dependencies @@ -167,11 +167,24 @@ evidence to the owning suite. `e2e:smoke` fails if command registration and the Three log surfaces, in order of usefulness: -- Donut Browser GUI: `~/Library/Logs/com.donutbrowser/DonutBrowser.log` on macOS (newest = active session; older `DonutBrowser_.log` are rotated). The GUI, Tauri, `browser_runner`, `proxy_manager`, and `sync` all log here. Search for `Wayfern`, `Starting local proxy`, `Configured local proxy` to find a launch chain. Dev builds write to `DonutBrowserDev.log` instead. -- donut-proxy worker: `$TMPDIR/donut-proxy-.log`. One file per proxy worker process (each profile launch spawns a fresh one). Map a worker to its launch via the `Cleanup: browser PID X is dead, stopping proxy worker ` lines in DonutBrowser.log, or by mtime. Upstream rejects (status lines like `HTTP/1.1 402 user reached limit`) and tunnel errors are at WARN. Accepted CONNECT requests are at DEBUG on purpose, so the log is not a list of visited sites; use `RUST_LOG=donut_proxy=debug` to see them. Anything finer is at TRACE and requires `RUST_LOG=donut_proxy=trace`. The `Upstream CONNECT response coalesced N byte(s) of payload` warning (those bytes would be dropped without forwarding) marks a real bug in `handle_connect_from_buffer` if it ever fires. +- Donut Browser GUI: `~/Library/Logs/com.donutbrowser/DonutBrowser.log` on macOS (newest = active session; older `DonutBrowser_.log` are rotated). The GUI, Tauri, `browser_runner`, `proxy_manager`, and `sync` all log here, and uncaught frontend errors arrive with the `webview` target. Search for `profile=` to follow a launch: `Proxy worker started`, then `Browser launched` (or `Browser launch failed` / `Browser launch blocked`), then `Browser stopped` or `Browser exited`. Dev builds write to `DonutBrowserDev.log` instead. +- donut-proxy worker: `$TMPDIR/donut-proxy-.log`. One file per worker process (each profile launch spawns a fresh one); same line shape as the app log, with UTC timestamps. Its first line is `Worker started kind=proxy|vpn id= pid= listen= upstream= ...` (never credentials) and, when it stops on its own, its last is `Worker exiting ... reason=`; a worker the app kills writes no last line, so read the app's `Proxy worker stopped id=` instead. Map a worker to its launch via `Proxy worker started id= ... profile=` and `Proxy worker stopped id= ... reason=...` (`browser_exited()`, `orphan_at_startup`, ...) in DonutBrowser.log. Upstream rejects (status lines like `HTTP/1.1 402 user reached limit`) and tunnel errors are at WARN as `CONNECT tunnel failed err="..." suppressed_30s=N`, at most once per 30s per message, with the destination host replaced by ``. Destinations (accepted CONNECT requests, per-request detail) are at DEBUG or TRACE on purpose, so the log is not a list of visited sites; set `RUST_LOG=donutbrowser_lib::proxy_server=debug` (or `=trace`) in the app's environment to see them; it overrides the INFO default. Linux/Windows swap `~/Library/Logs/com.donutbrowser/` for the platform-appropriate location (see `app_dirs::app_name()`), but the `$TMPDIR` worker logs are always under the system temp dir. +### Writing log lines + +Agents read these files; people rarely do. Every line must tell an agent something it cannot get elsewhere, at the lowest byte cost. + +- Line shape: `[2026-10-08 17:53:49.362][sync::scheduler][INFO] Profile synced profile= files=12 bytes=4096 elapsed_ms=812`. The target drops the `donutbrowser_lib::` prefix (`app` is `lib.rs`). Start with what happened, then the facts as `key=value`. Quote values that can hold spaces: `err="..."`. +- Each session opens with `Donut started version=... os=... pid=...`, and closes with `Donut exiting browsers=[...] proxy_workers=[...] ...`, which lists what outlives the app as `id@pid` (`process_report.rs`). The same fields follow `Found from an earlier run` at startup. +- Name entities by id: `profile=`, `proxy=`, `vpn=`, `group=`, `pid=`. Never log profile names, emails, visited URLs, or credentials: people attach these files to public issues. +- Levels: `error` = an operation the person asked for failed, or data is at risk. `warn` = degraded or unexpected, but work continues. `info` = a state change worth knowing later (start, launch, spawn, exit, kill, sync result, install), once per change. `debug` = per-poll, per-request, per-file and steady-state detail ("already in sync", "using cache", "nothing to do"). The file keeps `info` and above. +- A loop or retry never logs each tick or attempt. A failure that can repeat goes through `log_streak`: `Streak` (one line when it starts, one reminder an hour, one line with the count when it recovers; a failure within a minute of a recovery continues the streak as a flap), `KeyedStreak` when the failure belongs to one entity (one streak per `profile=`/`key=`, so one entity's success never hides another's failure), or `Throttle` for events that are normal one at a time but noisy in bulk, such as refused requests (one line per key per window, with `suppressed=N`). +- No banners and no `Starting X...` line before a result line: put `elapsed_ms` on the result line. +- Log an error chain once (`err=...`); do not wrap it in the same context again (`Failed to X: Failed to X: ...`). +- Processes: log every spawn with `pid` and what it serves, and every exit or kill with `pid` and the exit status. Child process output (browser stdout, worker stderr) is `debug` unless it explains a failure. + ## Code Quality - Don't leave comments that don't add value diff --git a/e2e/app/Cargo.lock b/e2e/app/Cargo.lock index c18b29b9..5cd6be9f 100644 --- a/e2e/app/Cargo.lock +++ b/e2e/app/Cargo.lock @@ -1706,7 +1706,7 @@ dependencies = [ [[package]] name = "donutbrowser" -version = "0.31.3" +version = "0.32.0" dependencies = [ "aes 0.9.3", "aes-gcm 0.11.1", diff --git a/e2e/tests/browser.test.mjs b/e2e/tests/browser.test.mjs index 27a58f0c..6bad0959 100644 --- a/e2e/tests/browser.test.mjs +++ b/e2e/tests/browser.test.mjs @@ -345,9 +345,13 @@ test("real Wayfern fingerprinting, terms, API automation, CDP, cookies, and proc // The new-profile form (which needs a downloaded browser and its release // types, so it renders here and not in the UI suite): session restore is - // on by default and the checkbox is a live control. + // on by default and the checkbox is a live control. It sits under the + // collapsed advanced options. await app.clickSelector('[aria-label="Profiles"]'); await app.clickText("New"); + await app.clickText(en.createProfile.advancedOptions, { + roles: ["button"], + }); const restoreChecked = () => app.execute( `return document.querySelector("#restore-session")?.getAttribute("aria-checked") ?? null;`, diff --git a/e2e/tests/smoke.test.mjs b/e2e/tests/smoke.test.mjs index db565768..7a0b1bd1 100644 --- a/e2e/tests/smoke.test.mjs +++ b/e2e/tests/smoke.test.mjs @@ -1,5 +1,5 @@ import assert from "node:assert/strict"; -import { readFile } from "node:fs/promises"; +import { readdir, readFile } from "node:fs/promises"; import path from "node:path"; import test from "node:test"; import { appFromEnvironment, withApp } from "../lib/app.mjs"; @@ -351,6 +351,28 @@ test("tray labels, hide-to-tray, and confirmed quit follow the native lifecycle" ); app.session = null; await exitingSession.close().catch(() => {}); + + // Agents read this file: each session opens with its facts, closes with + // what outlives it, and no line repeats the crate name. + const logDir = path.join(app.dataRoot, "logs"); + const logText = ( + await Promise.all( + ( + await readdir(logDir) + ) + .filter((name) => name.endsWith(".log")) + .map((name) => readFile(path.join(logDir, name), "utf8")), + ) + ).join("\n"); + assert.match( + logText, + /\[app\]\[INFO\] Donut started version=\S+ os="[^"]+" arch=\S+ pid=\d+ /, + ); + assert.match( + logText, + /\[app\]\[INFO\] Donut exiting browsers=\[\] proxy_workers=\[\] vpn_workers=\[\] xray_workers=\[\]/, + ); + assert.doesNotMatch(logText, /donutbrowser_lib::/); } catch (error) { await app.capture("failure"); throw error; diff --git a/e2e/tests/ui.test.mjs b/e2e/tests/ui.test.mjs index 31c426ae..aa976536 100644 --- a/e2e/tests/ui.test.mjs +++ b/e2e/tests/ui.test.mjs @@ -60,6 +60,25 @@ async function tableRows(app, tableId) { ); } +/** Selection checkboxes, and the browser icons that stand in for them, that sit + * more than half a pixel off the center of their cell. */ +async function offCenterSelectionControls(app, tableSelector) { + return app.execute( + `return [...document.querySelectorAll(arguments[0] + ' :is(th, td) :is([role="checkbox"], [role="checkbox"] + [aria-hidden="true"] > svg)')] + .map((node) => { + const cell = node.closest("th, td").getBoundingClientRect(); + const rect = node.getBoundingClientRect(); + return { + control: node.getAttribute("aria-label") ?? "icon", + x: rect.left + rect.width / 2 - (cell.left + cell.width / 2), + y: rect.top + rect.height / 2 - (cell.top + cell.height / 2), + }; + }) + .filter(({ x, y }) => Math.abs(x) > 0.5 || Math.abs(y) > 0.5);`, + [tableSelector], + ); +} + async function tableShiftClick(app, selector) { // tauri-wd 0.2.1 omits modifiers from pointer events. Send the click with // Shift through the native WebView; the real checkbox handler selects rows. @@ -479,6 +498,10 @@ test("profile table filters, range selection, view settings, and keyboard edits ); assert.deepEqual(chrome.controls, ["0px", "0px", "0px"]); assert.equal(chrome.rowRules, 0, "rows are not divided by rules"); + assert.deepEqual( + await offCenterSelectionControls(app, '[data-table-id="profiles"]'), + [], + ); const row = (index) => `tr[data-table-row="${profiles[index].id}"]`; await app.clickSelector(`${row(0)} [role="checkbox"]`); await tableShiftClick(app, `${row(3)} [role="checkbox"]`); @@ -502,7 +525,9 @@ test("profile table filters, range selection, view settings, and keyboard edits /4/, ); const searchSelector = `input[placeholder="${en.header.searchPlaceholder}"]`; - await app.fillSelector(searchSelector, "Table 02"); + // Quoted: an unquoted "02" is its own term, which also prefix-matches + // any profile whose random id starts with 02. + await app.fillSelector(searchSelector, '"Table 02"'); await app.waitFor( async () => JSON.stringify(await tableRows(app, "profiles")) === @@ -746,6 +771,10 @@ test("management tables share search, filters, selection, and saved views", asyn async () => (await tableRows(app, "proxies")).length === 3, { description: "proxy table" }, ); + assert.deepEqual( + await offCenterSelectionControls(app, '[data-table-id="proxies"]'), + [], + ); const proxyRowHeight = () => app.execute( `return document.querySelector('[data-table-id="proxies"] tr[data-table-row]')?.getBoundingClientRect().height;`, @@ -2919,6 +2948,13 @@ test("the agent page guides setup, then shows agents, requests, notes, take-over const row = await waitPainted(`agent-profile-${profile.id}`); assert.match(row, /Agent UI Profile/); assert.match(row, /LOCATOR_NO_MATCH/); + assert.deepEqual( + await offCenterSelectionControls( + app, + '[data-testid="agent-profiles"]', + ), + [], + ); await app.clickSelector( `[data-testid="agent-profile-${profile.id}"] [data-testid="agent-take-over"]`, ); diff --git a/src-tauri/src/agent_console.rs b/src-tauri/src/agent_console.rs index ee3ef6ae..5659a139 100644 --- a/src-tauri/src/agent_console.rs +++ b/src-tauri/src/agent_console.rs @@ -864,7 +864,7 @@ fn profile_exists(profile_id: &str) -> Result<(), String> { let profiles = crate::profile::manager::ProfileManager::instance() .list_profiles() .map_err(|e| { - log::warn!("[agent-console] profiles could not be read: {e}"); + log::warn!("Agent console: profile list failed err=\"{e}\""); crate::backend_error("INTERNAL_ERROR") })?; if profiles.iter().any(|p| p.id.to_string() == profile_id) { diff --git a/src-tauri/src/api_client.rs b/src-tauri/src/api_client.rs index 91b9b62a..b16bbca1 100644 --- a/src-tauri/src/api_client.rs +++ b/src-tauri/src/api_client.rs @@ -4,6 +4,22 @@ use std::fs; use std::path::PathBuf; use std::time::{SystemTime, UNIX_EPOCH}; +use crate::log_streak::Streak; + +static WAYFERN_VERSION_FETCH: Streak = Streak::new(module_path!(), "Wayfern version fetch"); +static LAST_WAYFERN_VERSION: std::sync::Mutex> = std::sync::Mutex::new(None); + +fn wayfern_version_changed(version: &str) -> bool { + let mut last = LAST_WAYFERN_VERSION + .lock() + .unwrap_or_else(std::sync::PoisonError::into_inner); + if last.as_deref() == Some(version) { + return false; + } + *last = Some(version.to_string()); + true +} + #[derive(Debug, Clone, PartialEq, Eq)] pub struct VersionComponent { pub major: u32, @@ -156,12 +172,12 @@ impl ApiClient { let content = fs::read_to_string(&cache_file).ok()?; if let Ok(cached) = serde_json::from_str::(&content) { - log::info!("Using cached versions for {browser}"); + log::debug!("Browser versions from cache browser={browser}"); return Some(cached.releases); } if let Ok(legacy_versions) = serde_json::from_str::>(&content) { - log::info!("Using legacy cached versions for {browser}; upgrading in-memory"); + log::debug!("Browser versions from legacy cache browser={browser}"); let releases: Vec = legacy_versions .into_iter() .map(|version| BrowserRelease { @@ -214,7 +230,10 @@ impl ApiClient { let content = serde_json::to_string_pretty(&cached_data)?; fs::write(&cache_file, content)?; - log::info!("Cached {} versions for {}", releases.len(), browser); + log::debug!( + "Browser versions cached browser={browser} count={}", + releases.len() + ); Ok(()) } @@ -246,7 +265,7 @@ impl ApiClient { let content = serde_json::to_string_pretty(&cached_data)?; fs::write(&cache_file, content)?; - log::info!("Cached Wayfern version: {}", version_info.version); + log::debug!("Wayfern version cached version={}", version_info.version); Ok(()) } @@ -257,12 +276,14 @@ impl ApiClient { ) -> Result> { if !no_caching { if let Some(cached_version) = self.load_cached_wayfern_version() { - log::info!("Using cached Wayfern version: {}", cached_version.version); + log::debug!( + "Wayfern version from cache version={}", + cached_version.version + ); return Ok(cached_version); } } - log::info!("Fetching Wayfern version from https://donutbrowser.com/wayfern.json"); let url = "https://donutbrowser.com/wayfern.json"; let mut last_err = None; @@ -291,7 +312,7 @@ impl ApiClient { } } Err(e) => { - log::warn!("Wayfern fetch attempt {attempt}/3 failed: {e}"); + log::debug!("Wayfern version fetch attempt failed attempt={attempt} err=\"{e}\""); proxy_err = crate::system_proxy::explain(&e); last_err = Some(e.to_string()); } @@ -302,19 +323,31 @@ impl ApiClient { } } - let version_info = version_info.ok_or_else(|| { - proxy_err.unwrap_or_else(|| { - format!( - "Failed to fetch Wayfern version after 3 attempts: {}", - last_err.unwrap_or_default() - ) - }) - })?; - log::info!("Fetched Wayfern version: {}", version_info.version); + let version_info = match version_info { + Some(info) => { + WAYFERN_VERSION_FETCH.succeeded(); + info + } + None => { + let err = proxy_err.unwrap_or_else(|| { + format!( + "Failed to fetch Wayfern version after 3 attempts: {}", + last_err.unwrap_or_default() + ) + }); + WAYFERN_VERSION_FETCH.failed(&err); + return Err(err.into()); + } + }; + if wayfern_version_changed(&version_info.version) { + log::info!("Wayfern version fetched version={}", version_info.version); + } else { + log::debug!("Wayfern version fetched version={}", version_info.version); + } if !no_caching { if let Err(e) = self.save_cached_wayfern_version(&version_info) { - log::error!("Failed to cache Wayfern version: {e}"); + log::warn!("Wayfern version not cached err=\"{e}\""); } } @@ -368,10 +401,10 @@ impl ApiClient { let path = entry.path(); if path.is_file() { fs::remove_file(&path)?; - log::info!("Removed cache file: {path:?}"); + log::debug!("Version cache file removed path={path:?}"); } } - log::info!("All version cache cleared successfully"); + log::info!("Version cache cleared"); } Ok(()) diff --git a/src-tauri/src/api_server.rs b/src-tauri/src/api_server.rs index a7f2be3e..dbd864fe 100644 --- a/src-tauri/src/api_server.rs +++ b/src-tauri/src/api_server.rs @@ -24,6 +24,11 @@ use tower_http::cors::CorsLayer; use utoipa::{OpenApi, ToSchema}; use utoipa_axum::{router::OpenApiRouter, routes}; +/// Refused requests come in bursts from one client; one line per route and +/// status a minute is enough to see who is refused and how often. +static REFUSED_REQUESTS: crate::log_streak::Throttle = + crate::log_streak::Throttle::new(std::time::Duration::from_secs(60)); + // API Types #[derive(Debug, Serialize, Deserialize, Clone, ToSchema)] pub struct ApiProfile { @@ -887,9 +892,8 @@ impl ApiServer { "/v1/openapi.json", get(move || async move { Json(api_for_v1) }), ) - // Outermost layer: logs every request so customer reports show what - // their automation is actually calling, what the response status was, - // and how long it took. Never logs request bodies or auth headers. + // Outermost layer: logs failed requests with route, status and duration. + // Never logs request bodies, query strings or auth headers. .layer(middleware::from_fn(request_logging_middleware)) .layer(CorsLayer::permissive()) .with_state(state); @@ -1047,7 +1051,7 @@ async fn auth_middleware( let token = match auth_header { Some(token) => token, None => { - log::warn!("[api] Rejected {path}: missing Authorization header"); + log::debug!("API auth refused reason=missing_header path={path}"); return Err(StatusCode::UNAUTHORIZED); } }; @@ -1057,13 +1061,11 @@ async fn auth_middleware( let stored_token = match settings_manager.get_api_token(&state.app_handle).await { Ok(Some(stored_token)) => stored_token, Ok(None) => { - log::warn!( - "[api] Rejected {path}: API server has no stored token (was the API toggled off?)" - ); + log::debug!("API auth refused reason=no_stored_token path={path}"); return Err(StatusCode::UNAUTHORIZED); } Err(e) => { - log::error!("[api] Failed to read stored API token: {e}"); + log::error!("API token not readable err=\"{e}\""); return Err(StatusCode::INTERNAL_SERVER_ERROR); } }; @@ -1076,7 +1078,7 @@ async fn auth_middleware( let stored_bytes = stored_token.as_bytes(); let matches = token_bytes.len() == stored_bytes.len() && token_bytes.ct_eq(stored_bytes).into(); if !matches { - log::warn!("[api] Rejected {path}: token mismatch"); + log::debug!("API auth refused reason=token_mismatch path={path}"); return Err(StatusCode::UNAUTHORIZED); } @@ -1084,12 +1086,16 @@ async fn auth_middleware( Ok(next.run(request).await) } -/// Logs every request: method, path, query, response status, duration. +/// Logs a failed request with its route, status and duration; a successful +/// one at debug. 401 and 429 are logged by their own middleware. /// Skips Authorization header and request bodies entirely. async fn request_logging_middleware(request: axum::extract::Request, next: Next) -> Response { let method = request.method().clone(); - let path = request.uri().path().to_string(); - let query = request.uri().query().map(|q| q.to_string()); + let route = request + .extensions() + .get::() + .map(|matched| matched.as_str().to_string()) + .unwrap_or_else(|| request.uri().path().to_string()); let started = std::time::Instant::now(); let response = next.run(request).await; @@ -1097,20 +1103,25 @@ async fn request_logging_middleware(request: axum::extract::Request, next: Next) let status = response.status(); let elapsed_ms = started.elapsed().as_millis(); + if !(status.is_client_error() || status.is_server_error()) { + log::debug!( + "API request method={method} path={route} status={} elapsed_ms={elapsed_ms}", + status.as_u16() + ); + return response; + } let level = if status.is_server_error() { log::Level::Error - } else if status.is_client_error() { - log::Level::Warn } else { - log::Level::Info + log::Level::Warn }; - - match query { - Some(q) => log::log!( + if let Some(dropped) = REFUSED_REQUESTS.allow(&format!("{method} {route} {}", status.as_u16())) { + log::log!( level, - "[api] {method} {path}?{q} -> {status} ({elapsed_ms} ms)" - ), - None => log::log!(level, "[api] {method} {path} -> {status} ({elapsed_ms} ms)"), + "API request failed method={method} path={route} status={} elapsed_ms={elapsed_ms}{}", + status.as_u16(), + crate::log_streak::suppressed(dropped) + ); } response @@ -1192,10 +1203,9 @@ async fn rate_limit_middleware(request: axum::extract::Request, next: Next) -> R match crate::automation_rate_limiter::check_automation_rate_limit().await { crate::automation_rate_limiter::RateLimitOutcome::Limited { retry_after_secs } => { - log::warn!( - "[api] Rejected {}: automation rate limit exceeded; retry in {}s", - request.uri().path(), - retry_after_secs + log::debug!( + "API automation rate limited path={} retry_after_s={retry_after_secs}", + request.uri().path() ); ( StatusCode::TOO_MANY_REQUESTS, @@ -1618,8 +1628,9 @@ async fn create_profile( let _ = crate::events::emit_empty("profile-generation-limit-reached"); } log::warn!( - "[api] Could not create profile '{}': {body}", - Plain(&request.name) + "API profile create failed status={} err=\"{}\"", + status.as_u16(), + Plain(&body) ); Err((status, body)) } @@ -3506,7 +3517,7 @@ async fn pump_cdp(session_id: String, client: WebSocket, upstream: crate::cdp_ta () = to_client => {} } log::info!( - "CDP proxy for remote session {} closed", + "Remote session CDP proxy closed session={}", ShortId(&session_id) ); } diff --git a/src-tauri/src/app_auto_updater.rs b/src-tauri/src/app_auto_updater.rs index 96d2112a..578038c3 100644 --- a/src-tauri/src/app_auto_updater.rs +++ b/src-tauri/src/app_auto_updater.rs @@ -171,153 +171,175 @@ impl AppAutoUpdater { pub async fn check_for_updates( &self, ) -> Result, Box> { + self.check(false).await + } + + /// Runs one check and writes its one result line: at info when the outcome + /// differs from the previous check (or the person asked), else at debug. + async fn check( + &self, + manual: bool, + ) -> Result, Box> { + let started = std::time::Instant::now(); let current_version = Self::get_current_version(); + let channel = if Self::is_nightly_build() { + "nightly" + } else { + "stable" + }; + let releases = match self.fetch_app_releases().await { + Ok(releases) => { + APP_UPDATE_CHECK_STREAK.succeeded(); + releases + } + Err(e) => { + APP_UPDATE_CHECK_STREAK.failed(&e); + return Err(e); + } + }; + let (update, latest, result) = self.evaluate_releases(&releases, current_version.clone()); + + let outcome = format!("{latest} {result}"); + let changed = APP_UPDATE_LAST_OUTCOME + .lock() + .map(|mut last| last.replace(outcome.clone()) != Some(outcome)) + .unwrap_or(true); + let level = if changed || manual { + log::Level::Info + } else { + log::Level::Debug + }; + log::log!( + level, + "App update check current={current_version} latest={latest} channel={channel} result={result} manual={manual} elapsed_ms={}", + started.elapsed().as_millis() + ); + Ok(update) + } + + /// Picks the newest release of this build's channel and decides what the + /// check found. Returns the update, the latest tag (`-` when none) and a + /// `key=value` result fragment for the log line. + fn evaluate_releases( + &self, + releases: &[AppRelease], + current_version: String, + ) -> (Option, String, String) { let is_nightly = Self::is_nightly_build(); - - log::info!("=== App Update Check ==="); - log::info!("Current version: {current_version}"); - log::info!("Is nightly build: {is_nightly}"); - log::info!("STABLE_RELEASE env: {:?}", option_env!("STABLE_RELEASE")); - - let releases = self.fetch_app_releases().await?; - log::info!("Fetched {} releases from GitHub", releases.len()); - - // Filter releases based on build type let filtered_releases: Vec<&AppRelease> = if is_nightly { - // For nightly builds, look for nightly releases - let nightly_releases: Vec<&AppRelease> = releases + releases .iter() .filter(|release| release.tag_name.starts_with("nightly-")) - .collect(); - log::info!("Found {} nightly releases", nightly_releases.len()); - nightly_releases + .collect() } else { - // For stable builds, look for stable releases (semver format) - let stable_releases: Vec<&AppRelease> = releases + releases .iter() .filter(|release| release.tag_name.starts_with('v')) - .collect(); - log::info!("Found {} stable releases", stable_releases.len()); - stable_releases + .collect() }; - if filtered_releases.is_empty() { - log::info!("No releases found for build type (nightly: {is_nightly})"); - return Ok(None); + let Some(latest_release) = filtered_releases.first().copied() else { + return ( + None, + "-".to_string(), + format!("no_releases fetched={}", releases.len()), + ); + }; + let latest = latest_release.tag_name.clone(); + + if !self.should_update(¤t_version, &latest_release.tag_name, is_nightly) { + return (None, latest, "none".to_string()); } - // Get the latest release - let latest_release = filtered_releases[0]; - log::info!( - "Latest release: {} ({})", - latest_release.tag_name, - latest_release.name + let release_page_url = format!( + "https://github.com/zhom/donutbrowser/releases/tag/{}", + latest_release.tag_name ); - // Check if we need to update - if self.should_update(¤t_version, &latest_release.tag_name, is_nightly) { - log::info!("Update available!"); + let download_url = self.get_download_url_for_platform(&latest_release.assets); + let asset = download_url + .as_deref() + .and_then(|url| url.rsplit('/').next()) + .unwrap_or("-") + .to_string(); - // Build the release page URL - let release_page_url = format!( - "https://github.com/zhom/donutbrowser/releases/tag/{}", - latest_release.tag_name + // Locate the release's checksums file and the chosen asset's + // GitHub-computed digest for post-download verification. + let checksums_url = Self::find_checksums_url(&latest_release.assets); + let asset_digest = download_url.as_deref().and_then(|url| { + latest_release + .assets + .iter() + .find(|a| a.browser_download_url == url) + .and_then(|a| a.digest.clone()) + }); + + // Both release workflows upload SHA256SUMS.txt only after every platform + // build finishes, so a release without it is still being assembled (or + // its pipeline broke). Downloading now is guaranteed to fail closed, so + // treat the release as not ready and retry on a later check instead of + // surfacing an error for a healthy in-progress release. Applies only to + // the auto-download path — manual/repo notifications don't download. + let auto_download_possible = download_url.is_some(); + #[cfg(target_os = "linux")] + let auto_download_possible = auto_download_possible && !self.is_repo_configured(); + if auto_download_possible && checksums_url.is_none() { + return ( + None, + latest, + format!("not_ready missing={}", Self::CHECKSUMS_ASSET_NAME), ); - - // Find the appropriate asset for current platform - let download_url = self.get_download_url_for_platform(&latest_release.assets); - - // Locate the release's checksums file and the chosen asset's - // GitHub-computed digest for post-download verification. - let checksums_url = Self::find_checksums_url(&latest_release.assets); - let asset_digest = download_url.as_deref().and_then(|url| { - latest_release - .assets - .iter() - .find(|a| a.browser_download_url == url) - .and_then(|a| a.digest.clone()) - }); - - // Both release workflows upload SHA256SUMS.txt only after every platform - // build finishes, so a release without it is still being assembled (or - // its pipeline broke). Downloading now is guaranteed to fail closed, so - // treat the release as not ready and retry on a later check instead of - // surfacing an error for a healthy in-progress release. Applies only to - // the auto-download path — manual/repo notifications don't download. - let auto_download_possible = download_url.is_some(); - #[cfg(target_os = "linux")] - let auto_download_possible = auto_download_possible && !self.is_repo_configured(); - if auto_download_possible && checksums_url.is_none() { - log::info!( - "Release {} has no {} yet; treating as not ready for auto-update", - latest_release.tag_name, - Self::CHECKSUMS_ASSET_NAME - ); - return Ok(None); - } - - // On Linux, when a package repo is configured, notify users to update via - // their package manager instead of auto-downloading from GitHub. - #[cfg(target_os = "linux")] - { - let repo_update = self.is_repo_configured(); - let manual_update_required = download_url.is_none() || repo_update; - let update_info = AppUpdateInfo { - current_version, - new_version: latest_release.tag_name.clone(), - release_notes: latest_release.body.clone(), - download_url: download_url.unwrap_or_else(|| release_page_url.clone()), - is_nightly, - published_at: latest_release.published_at.clone(), - manual_update_required, - release_page_url: Some(release_page_url), - repo_update, - checksums_url, - asset_digest, - }; - - log::info!( - "Update info prepared: {} -> {} (manual_update_required: {}, repo_update: {})", - update_info.current_version, - update_info.new_version, - update_info.manual_update_required, - update_info.repo_update - ); - return Ok(Some(update_info)); - } - - #[cfg(not(target_os = "linux"))] - { - if let Some(url) = download_url { - let update_info = AppUpdateInfo { - current_version, - new_version: latest_release.tag_name.clone(), - release_notes: latest_release.body.clone(), - download_url: url, - is_nightly, - published_at: latest_release.published_at.clone(), - manual_update_required: false, - release_page_url: Some(release_page_url), - repo_update: false, - checksums_url, - asset_digest, - }; - - log::info!( - "Update info prepared: {} -> {}", - update_info.current_version, - update_info.new_version - ); - return Ok(Some(update_info)); - } else { - log::info!("No suitable download asset found for current platform"); - } - } - } else { - log::info!("No update needed"); } - Ok(None) + // On Linux, when a package repo is configured, notify users to update via + // their package manager instead of auto-downloading from GitHub. + #[cfg(target_os = "linux")] + { + let repo_update = self.is_repo_configured(); + let manual_update_required = download_url.is_none() || repo_update; + let update_info = AppUpdateInfo { + current_version, + new_version: latest_release.tag_name.clone(), + release_notes: latest_release.body.clone(), + download_url: download_url.unwrap_or_else(|| release_page_url.clone()), + is_nightly, + published_at: latest_release.published_at.clone(), + manual_update_required, + release_page_url: Some(release_page_url), + repo_update, + checksums_url, + asset_digest, + }; + let result = format!( + "available asset={asset} manual_update_required={manual_update_required} repo_update={repo_update}" + ); + (Some(update_info), latest, result) + } + + #[cfg(not(target_os = "linux"))] + { + let Some(url) = download_url else { + return (None, latest, "no_asset".to_string()); + }; + let update_info = AppUpdateInfo { + current_version, + new_version: latest_release.tag_name.clone(), + release_notes: latest_release.body.clone(), + download_url: url, + is_nightly, + published_at: latest_release.published_at.clone(), + manual_update_required: false, + release_page_url: Some(release_page_url), + repo_update: false, + checksums_url, + asset_digest, + }; + ( + Some(update_info), + latest, + format!("available asset={asset}"), + ) + } } /// Fetch app releases from GitHub @@ -346,10 +368,6 @@ impl AppAutoUpdater { return false; } - log::info!( - "Comparing versions: current={current_version}, new={new_version}, is_nightly={is_nightly}" - ); - if is_nightly { // For nightly builds, always update if there's a newer nightly if let (Some(current_hash), Some(new_hash)) = ( @@ -357,22 +375,17 @@ impl AppAutoUpdater { new_version.strip_prefix("nightly-"), ) { // Different commit hashes mean we should update - let should_update = new_hash != current_hash; - log::info!("Nightly comparison: current_hash={current_hash}, new_hash={new_hash}, should_update={should_update}"); - return should_update; + return new_hash != current_hash; } // If current version doesn't have nightly prefix but we're in nightly mode, // this could be a dev build or stable build upgrading to nightly if !current_version.starts_with("nightly-") { - log::info!("Upgrading from non-nightly to nightly: {new_version}"); return true; } } else { // For stable builds, use semantic versioning comparison - let should_update = self.is_version_newer(new_version, current_version); - log::info!("Stable comparison: {new_version} > {current_version} = {should_update}"); - return should_update; + return self.is_version_newer(new_version, current_version); } false @@ -439,7 +452,6 @@ impl AppAutoUpdater { }; let exe_path_str = exe_path.to_string_lossy(); - log::info!("Detecting installation method for: {exe_path_str}"); // Check if installed via package manager by querying package databases if let Some(exe_name) = exe_path.file_name().and_then(|n| n.to_str()) { @@ -450,7 +462,6 @@ impl AppAutoUpdater { if output.status.success() { let stdout = String::from_utf8_lossy(&output.stdout); if !stdout.trim().is_empty() && !stdout.contains("no path found") { - log::info!("Found DEB package owning the executable"); return LinuxInstallationMethod::Deb; } } @@ -461,7 +472,6 @@ impl AppAutoUpdater { if output.status.success() { let stdout = String::from_utf8_lossy(&output.stdout); if !stdout.trim().is_empty() && !stdout.contains("not owned") { - log::info!("Found RPM package owning the executable"); return LinuxInstallationMethod::Rpm; } } @@ -476,7 +486,6 @@ impl AppAutoUpdater { if output.status.success() { let stdout = String::from_utf8_lossy(&output.stdout); if !stdout.trim().is_empty() && stdout.contains(exe_name) { - log::info!("Found RPM package via {rpm_cmd}"); return LinuxInstallationMethod::Rpm; } } @@ -487,7 +496,6 @@ impl AppAutoUpdater { // Check installation location to infer method if exe_path_str.starts_with("/usr/bin/") || exe_path_str.starts_with("/usr/local/bin/") { // Likely installed via package manager or system-wide installation - log::info!("Executable in system directory, assuming package installation"); // Try to determine which package system is available if Command::new("dpkg").arg("--version").output().is_ok() { @@ -499,11 +507,9 @@ impl AppAutoUpdater { return LinuxInstallationMethod::Manual; } else if exe_path_str.contains("/.local/") || exe_path_str.starts_with("/home/") { // User-local installation - log::info!("Executable in user directory, assuming manual installation"); return LinuxInstallationMethod::Manual; } - log::info!("Could not determine installation method"); LinuxInstallationMethod::Unknown } @@ -547,13 +553,11 @@ impl AppAutoUpdater { "unknown" }; - log::info!("Looking for platform-specific asset for arch: {arch}"); - #[cfg(target_os = "linux")] { // If we're running from an AppImage, disable auto-updates for safety if self.is_running_from_appimage() { - log::info!("Running from AppImage - auto-updates disabled for safety"); + log::debug!("No auto-update asset: running from an AppImage"); return None; } } @@ -575,7 +579,6 @@ impl AppAutoUpdater { #[cfg(not(any(target_os = "macos", target_os = "windows", target_os = "linux")))] { - log::info!("Unsupported platform for auto-update"); None } } @@ -591,7 +594,10 @@ impl AppAutoUpdater { || asset.name.contains(&format!("-{arch}-")) || asset.name.contains(&format!("_{arch}-"))) { - log::info!("Found exact architecture match: {}", asset.name); + log::debug!( + "Asset picked asset={} rule=\"exact architecture match\"", + asset.name + ); return Some(asset.browser_download_url.clone()); } } @@ -602,7 +608,7 @@ impl AppAutoUpdater { if asset.name.contains(".dmg") && (asset.name.contains("x86_64") || asset.name.contains("x86-64")) { - log::info!("Found x86_64 variant: {}", asset.name); + log::debug!("Asset picked asset={} rule=\"x86_64 variant\"", asset.name); return Some(asset.browser_download_url.clone()); } } @@ -614,7 +620,7 @@ impl AppAutoUpdater { if asset.name.contains(".dmg") && (asset.name.contains("arm64") || asset.name.contains("aarch64")) { - log::info!("Found arm64 variant: {}", asset.name); + log::debug!("Asset picked asset={} rule=\"arm64 variant\"", asset.name); return Some(asset.browser_download_url.clone()); } } @@ -627,7 +633,7 @@ impl AppAutoUpdater { || asset.name.to_lowercase().contains("darwin") || !asset.name.contains(".app.tar.gz")) { - log::info!("Found fallback DMG: {}", asset.name); + log::debug!("Asset picked asset={} rule=\"fallback DMG\"", asset.name); return Some(asset.browser_download_url.clone()); } } @@ -650,7 +656,10 @@ impl AppAutoUpdater { || asset.name.contains(&format!("-{arch}-")) || asset.name.contains(&format!("_{arch}-"))) { - log::info!("Found Windows {ext} with exact arch match: {}", asset.name); + log::debug!( + "Asset picked asset={} rule=\"Windows {ext} with exact arch match\"", + asset.name + ); return Some(asset.browser_download_url.clone()); } } @@ -661,7 +670,10 @@ impl AppAutoUpdater { if asset.name.to_lowercase().ends_with(&format!(".{ext}")) && (asset.name.contains("x86_64") || asset.name.contains("x86-64")) { - log::info!("Found Windows {ext} with x86_64 variant: {}", asset.name); + log::debug!( + "Asset picked asset={} rule=\"Windows {ext} with x86_64 variant\"", + asset.name + ); return Some(asset.browser_download_url.clone()); } } @@ -674,7 +686,10 @@ impl AppAutoUpdater { || asset.name.to_lowercase().contains("win32") || asset.name.to_lowercase().contains("win64")) { - log::info!("Found Windows {ext} fallback: {}", asset.name); + log::debug!( + "Asset picked asset={} rule=\"Windows {ext} fallback\"", + asset.name + ); return Some(asset.browser_download_url.clone()); } } @@ -687,7 +702,7 @@ impl AppAutoUpdater { fn get_linux_download_url(&self, assets: &[AppReleaseAsset], arch: &str) -> Option { // Detect installation method to prioritize appropriate formats let installation_method = self.detect_linux_installation_method(); - log::info!("Detected Linux installation method: {installation_method:?}"); + log::debug!("Linux install detected method={installation_method:?}"); // Priority order based on installation method let extensions = match installation_method { @@ -695,7 +710,6 @@ impl AppAutoUpdater { LinuxInstallationMethod::Rpm => vec!["rpm", "tar.gz"], LinuxInstallationMethod::AppImage => { // AppImages should not auto-update for safety - log::info!("AppImage installation detected - auto-updates disabled"); return None; } LinuxInstallationMethod::Manual | LinuxInstallationMethod::Unknown => { @@ -714,7 +728,10 @@ impl AppAutoUpdater { || asset.name.contains(&format!("-{arch}-")) || asset.name.contains(&format!("_{arch}-"))) { - log::info!("Found Linux {ext} with exact arch match: {}", asset.name); + log::debug!( + "Asset picked asset={} rule=\"Linux {ext} with exact arch match\"", + asset.name + ); return Some(asset.browser_download_url.clone()); } } @@ -728,7 +745,10 @@ impl AppAutoUpdater { || asset.name.contains("x86-64") || asset.name.contains("amd64")) { - log::info!("Found Linux {ext} with x86_64 variant: {}", asset.name); + log::debug!( + "Asset picked asset={} rule=\"Linux {ext} with x86_64 variant\"", + asset.name + ); return Some(asset.browser_download_url.clone()); } } @@ -741,7 +761,10 @@ impl AppAutoUpdater { if asset_name_lower.ends_with(&format!(".{ext}")) && (asset.name.contains("arm64") || asset.name.contains("aarch64")) { - log::info!("Found Linux {ext} with arm64 variant: {}", asset.name); + log::debug!( + "Asset picked asset={} rule=\"Linux {ext} with arm64 variant\"", + asset.name + ); return Some(asset.browser_download_url.clone()); } } @@ -755,7 +778,10 @@ impl AppAutoUpdater { || asset_name_lower.contains("ubuntu") || asset_name_lower.contains("debian")) { - log::info!("Found Linux {ext} fallback: {}", asset.name); + log::debug!( + "Asset picked asset={} rule=\"Linux {ext} fallback\"", + asset.name + ); return Some(asset.browser_download_url.clone()); } } @@ -794,9 +820,9 @@ impl AppAutoUpdater { let Some(checksums_url) = update_info.checksums_url.as_deref() else { log::warn!( - "No {} asset on release {}", - Self::CHECKSUMS_ASSET_NAME, - update_info.new_version + "App update checksums missing version={} asset={}", + update_info.new_version, + Self::CHECKSUMS_ASSET_NAME ); return Err(unavailable()); }; @@ -810,11 +836,18 @@ impl AppAutoUpdater { { Ok(response) if response.status().is_success() => response, Ok(response) => { - log::warn!("Checksums file request failed: HTTP {}", response.status()); + log::warn!( + "App update checksums fetch failed version={} status={}", + update_info.new_version, + response.status().as_u16() + ); return Err(unavailable()); } Err(e) => { - log::warn!("Checksums file request failed: {e}"); + log::warn!( + "App update checksums fetch failed version={} err=\"{e}\"", + update_info.new_version + ); return Err(unavailable()); } }; @@ -822,14 +855,17 @@ impl AppAutoUpdater { let checksums_text = match response.text().await { Ok(text) => text, Err(e) => { - log::warn!("Failed to read checksums file: {e}"); + log::warn!( + "App update checksums read failed version={} err=\"{e}\"", + update_info.new_version + ); return Err(unavailable()); } }; let Some(expected) = crate::checksum::find_checksum_for_file(&checksums_text, filename) else { log::warn!( - "No checksum entry for {filename} in {}", + "App update checksum entry missing file={filename} in={}", Self::CHECKSUMS_ASSET_NAME ); return Err(unavailable()); @@ -860,8 +896,9 @@ impl AppAutoUpdater { } if mismatch { - log::error!( - "Checksum mismatch for {filename}: expected {expected}, got {actual} (asset digest: {asset_digest:?})" + log::warn!( + "App update checksum mismatch file={filename} expected={expected} actual={actual} asset_digest={}", + asset_digest.unwrap_or("-") ); let _ = fs::remove_file(file_path); return Err( @@ -874,7 +911,7 @@ impl AppAutoUpdater { ); } - log::info!("Checksum verified for {filename}: {actual}"); + log::debug!("App update checksum verified file={filename} sha256={actual}"); Ok(()) } @@ -898,8 +935,6 @@ impl AppAutoUpdater { return Err(format!("Download failed with status: {}", response.status()).into()); } - let total_size = response.content_length().unwrap_or(0); - log::info!("Silent download size: {} bytes", total_size); let raw_file = fs::File::create(&file_path)?; let mut file = std::io::BufWriter::with_capacity(8 * 1024 * 1024, raw_file); let mut stream = response.bytes_stream(); @@ -910,8 +945,6 @@ impl AppAutoUpdater { file.write_all(&chunk)?; } std::io::Write::flush(&mut file)?; - - log::info!("Silent download completed: {}", file_path.display()); Ok(file_path) } @@ -921,8 +954,37 @@ impl AppAutoUpdater { _app_handle: &tauri::AppHandle, update_info: &AppUpdateInfo, ) -> Result<(), Box> { - log::info!("Starting background update download and install"); + let started = std::time::Instant::now(); + let mut stage = "checksums"; + match self.download_and_prepare(update_info, &mut stage).await { + Ok((asset, bytes, result)) => { + log::info!( + "App update ready from={} to={} asset={asset} bytes={bytes} result={result} elapsed_ms={}", + update_info.current_version, + update_info.new_version, + started.elapsed().as_millis() + ); + let _ = events::emit("app-update-ready", update_info.new_version.clone()); + Ok(()) + } + Err(e) => { + log::error!( + "App update failed from={} to={} stage={stage} elapsed_ms={} err=\"{e}\"", + update_info.current_version, + update_info.new_version, + started.elapsed().as_millis() + ); + Err(e) + } + } + } + /// Returns the asset name, its size and what was done with it. + async fn download_and_prepare( + &self, + update_info: &AppUpdateInfo, + stage: &mut &'static str, + ) -> Result<(String, u64, &'static str), Box> { let temp_dir = std::env::temp_dir().join("donut_app_update"); fs::create_dir_all(&temp_dir)?; @@ -937,13 +999,13 @@ impl AppAutoUpdater { // rejected before the multi-hundred-MB download, not after. let expected_sha256 = self.fetch_expected_checksum(update_info, &filename).await?; - log::info!("Downloading update"); - + *stage = "download"; let download_path = self .download_update_silent(&update_info.download_url, &temp_dir, &filename) .await?; + let bytes = fs::metadata(&download_path).map(|m| m.len()).unwrap_or(0); - log::info!("Verifying update checksum..."); + *stage = "verify"; Self::verify_update_checksum( &download_path, &filename, @@ -951,7 +1013,7 @@ impl AppAutoUpdater { update_info.asset_digest.as_deref(), )?; - log::info!("Extracting update..."); + *stage = "extract"; let extracted_app_path = self.extract_update(&download_path, &temp_dir).await?; // On Windows, MSI/EXE installers close the running app, so running them now @@ -965,29 +1027,22 @@ impl AppAutoUpdater { .unwrap_or("") .to_lowercase(); if ext == "msi" || ext == "exe" { - log::info!("Deferring Windows installer execution until user-initiated restart"); *PENDING_INSTALLER_PATH.lock().unwrap() = Some(extracted_app_path); - } else { - log::info!("Installing update (overwriting binary)..."); - self.install_update(&extracted_app_path).await?; - log::info!("Cleaning up temporary files..."); - let _ = fs::remove_dir_all(&temp_dir); + return Ok((filename, bytes, "installer_deferred_to_restart")); } + *stage = "install"; + self.install_update(&extracted_app_path).await?; + let _ = fs::remove_dir_all(&temp_dir); + Ok((filename, bytes, "installed")) } #[cfg(not(target_os = "windows"))] { - log::info!("Installing update (overwriting binary)..."); + *stage = "install"; self.install_update(&extracted_app_path).await?; - log::info!("Cleaning up temporary files..."); let _ = fs::remove_dir_all(&temp_dir); + Ok((filename, bytes, "installed")) } - - log::info!("Update ready, emitting app-update-ready event"); - - let _ = events::emit("app-update-ready", update_info.new_version.clone()); - - Ok(()) } /// Extract the update using the extraction module @@ -1138,13 +1193,14 @@ impl AppAutoUpdater { } }; if needs_quarantine_removal { - let _ = Command::new("xattr") - .args([ + let _ = output_logged( + Command::new("xattr").args([ "-dr", "com.apple.quarantine", current_app_path.to_str().unwrap(), - ]) - .output(); + ]), + "clear quarantine on updated app", + ); } // Clean up backup after successful installation @@ -1154,14 +1210,15 @@ impl AppAutoUpdater { if let Some(parent_dir) = current_app_path.parent() { let old_app_path = parent_dir.join("Donut Browser.app"); if old_app_path.exists() && old_app_path != current_app_path { - log::info!( - "Removing old 'Donut Browser.app' from: {}", - old_app_path.display() - ); - if let Err(e) = fs::remove_dir_all(&old_app_path) { - log::warn!("Warning: Failed to remove old 'Donut Browser.app': {e}"); - } else { - log::info!("Successfully removed old 'Donut Browser.app'"); + match fs::remove_dir_all(&old_app_path) { + Ok(()) => log::info!( + "Removed pre-rename app bundle path=\"{}\"", + old_app_path.display() + ), + Err(e) => log::warn!( + "Pre-rename app bundle removal failed path=\"{}\" err=\"{e}\"", + old_app_path.display() + ), } } } @@ -1176,13 +1233,8 @@ impl AppAutoUpdater { .and_then(|ext| ext.to_str()) .unwrap_or(""); - log::info!("Installing Windows update with extension: {extension}"); - match extension { "msi" => { - // Install MSI silently with enhanced error handling - log::info!("Running MSI installer: {}", installer_path.display()); - let mut cmd = Command::new("msiexec"); cmd.args([ "/i", @@ -1198,43 +1250,30 @@ impl AppAutoUpdater { const CREATE_NO_WINDOW: u32 = 0x08000000; cmd.creation_flags(CREATE_NO_WINDOW); - let output = cmd.output()?; + let output = output_logged(&mut cmd, "msi update installer")?; if !output.status.success() { let error_msg = String::from_utf8_lossy(&output.stderr); let exit_code = output.status.code().unwrap_or(-1); - // Try to read the log file for more details let log_path = format!("{}.log", installer_path.to_str().unwrap()); let log_content = fs::read_to_string(&log_path).unwrap_or_default(); - - log::info!("MSI installation failed with exit code: {exit_code}"); - log::info!("Error output: {error_msg}"); - if !log_content.is_empty() { - log::info!( - "Log file content (last 500 chars): {}", - log_content - .chars() - .rev() - .take(500) - .collect::() - .chars() - .rev() - .collect::() - ); - } + let log_tail = log_content + .chars() + .rev() + .take(500) + .collect::() + .chars() + .rev() + .collect::(); + log::warn!("MSI install log tail code={exit_code} tail={log_tail:?}"); return Err( format!("MSI installation failed (exit code {exit_code}): {error_msg}").into(), ); } - - log::info!("MSI installation completed successfully"); } "exe" => { - // Run exe installer silently with multiple fallback options - log::info!("Running EXE installer: {}", installer_path.display()); - // Try NSIS silent flag first (most common for Tauri) let mut success = false; let mut last_error = String::new(); @@ -1248,15 +1287,11 @@ impl AppAutoUpdater { ]; for args in nsis_args { - log::info!("Trying installer with args: {:?}", args); - let output = Command::new(installer_path).args(&args).output(); + let purpose = format!("exe update installer args={}", args.join(" ")); + let output = output_logged(Command::new(installer_path).args(&args), &purpose); match output { Ok(output) if output.status.success() => { - log::info!( - "EXE installation completed successfully with args: {:?}", - args - ); success = true; break; } @@ -1267,15 +1302,9 @@ impl AppAutoUpdater { output.status.code().unwrap_or(-1), error_msg ); - log::info!("Installer failed with args {:?}: {}", args, last_error); } Err(e) => { last_error = format!("Failed to execute installer: {e}"); - log::info!( - "Failed to execute installer with args {:?}: {}", - args, - last_error - ); } } } @@ -1291,8 +1320,6 @@ impl AppAutoUpdater { } "zip" => { // Handle ZIP files by extracting and replacing the current executable - log::info!("Handling ZIP update: {}", installer_path.display()); - let temp_extract_dir = installer_path.parent().unwrap().join("extracted"); fs::create_dir_all(&temp_extract_dir)?; @@ -1337,8 +1364,6 @@ impl AppAutoUpdater { // Clean up let _ = fs::remove_dir_all(&temp_extract_dir); - - log::info!("ZIP update completed successfully"); } _ => { return Err(format!("Unsupported installer format: {extension}").into()); @@ -1355,8 +1380,6 @@ impl AppAutoUpdater { .and_then(|name| name.to_str()) .unwrap_or(""); - log::info!("Installing Linux update: {}", installer_path.display()); - // Handle compound extensions like .tar.gz if file_name.ends_with(".tar.gz") { return self.install_linux_tarball(installer_path).await; @@ -1387,7 +1410,6 @@ impl AppAutoUpdater { &self, deb_path: &Path, ) -> Result<(), Box> { - log::info!("Installing DEB package: {}", deb_path.display()); Self::install_linux_package_with_privileges(deb_path, "dpkg", "-i") } @@ -1397,7 +1419,6 @@ impl AppAutoUpdater { &self, rpm_path: &Path, ) -> Result<(), Box> { - log::info!("Installing RPM package: {}", rpm_path.display()); Self::install_linux_package_with_privileges(rpm_path, "rpm", "-Uvh") } @@ -1414,12 +1435,11 @@ impl AppAutoUpdater { let pkg = pkg_path.to_str().unwrap_or_default(); // 1. Try pkexec (graphical PolicyKit prompt) - if let Ok(status) = Command::new("pkexec") - .args([install_cmd, install_arg, pkg]) - .status() - { + if let Ok(status) = status_logged( + Command::new("pkexec").args([install_cmd, install_arg, pkg]), + &format!("{install_cmd} update package via pkexec"), + ) { if status.success() { - log::info!("Installed {pkg} with pkexec"); return Ok(()); } } @@ -1427,18 +1447,16 @@ impl AppAutoUpdater { // 2. Try graphical password dialog → sudo -S if let Some(password) = Self::get_password_graphically() { if Self::install_with_sudo_stdin(pkg_path, &password, install_cmd, install_arg) { - log::info!("Installed {pkg} with graphical sudo"); return Ok(()); } } // 3. Terminal sudo fallback - if let Ok(status) = Command::new("sudo") - .args([install_cmd, install_arg, pkg]) - .status() - { + if let Ok(status) = status_logged( + Command::new("sudo").args([install_cmd, install_arg, pkg]), + &format!("{install_cmd} update package via sudo"), + ) { if status.success() { - log::info!("Installed {pkg} with sudo"); return Ok(()); } } @@ -1506,10 +1524,19 @@ impl AppAutoUpdater { match child { Ok(mut child) => { + let pid = child.id(); + log::info!( + "Process spawned pid={pid} purpose=\"{install_cmd} update package via sudo -S\"" + ); if let Some(mut stdin) = child.stdin.take() { let _ = writeln!(stdin, "{password}"); } - child.wait().map(|s| s.success()).unwrap_or(false) + let status = child.wait(); + log::info!( + "Process exited pid={pid} purpose=\"{install_cmd} update package via sudo -S\" code={}", + status.as_ref().map_or("wait_failed".to_string(), exit_code) + ); + status.map(|s| s.success()).unwrap_or(false) } Err(_) => false, } @@ -1521,8 +1548,6 @@ impl AppAutoUpdater { &self, appimage_path: &Path, ) -> Result<(), Box> { - log::info!("Installing AppImage: {}", appimage_path.display()); - // This function should not be called for AppImages since we disable auto-updates for them // But if it somehow gets called, we'll handle it safely @@ -1548,14 +1573,13 @@ impl AppAutoUpdater { fs::copy(¤t_appimage, &backup_path)?; // Make new AppImage executable - let _ = Command::new("chmod") - .args(["+x", appimage_path.to_str().unwrap()]) - .output(); + let _ = output_logged( + Command::new("chmod").args(["+x", appimage_path.to_str().unwrap()]), + "chmod updated AppImage", + ); // Replace the AppImage fs::copy(appimage_path, ¤t_appimage)?; - - log::info!("AppImage replacement completed successfully"); Ok(()) } @@ -1565,8 +1589,6 @@ impl AppAutoUpdater { &self, tarball_path: &Path, ) -> Result<(), Box> { - log::info!("Installing tarball: {}", tarball_path.display()); - let current_exe = self.get_current_app_path()?; let temp_extract_dir = tarball_path.parent().unwrap().join("extracted"); fs::create_dir_all(&temp_extract_dir)?; @@ -1620,14 +1642,13 @@ impl AppAutoUpdater { fs::copy(&new_exe_path, ¤t_exe)?; // Make sure it's executable - let _ = Command::new("chmod") - .args(["+x", current_exe.to_str().unwrap()]) - .output(); + let _ = output_logged( + Command::new("chmod").args(["+x", current_exe.to_str().unwrap()]), + "chmod updated binary", + ); // Clean up let _ = fs::remove_dir_all(&temp_extract_dir); - - log::info!("Tarball installation completed successfully"); Ok(()) } @@ -1673,7 +1694,7 @@ impl AppAutoUpdater { let profiles = match crate::profile::ProfileManager::instance().list_profiles() { Ok(profiles) => profiles, Err(e) => { - log::error!("Failed to inspect running profiles before app update: {e}"); + log::error!("App update preparation failed step=list_profiles err=\"{e}\""); return Err( serde_json::json!({ "code": "UPDATE_PREPARATION_FAILED" @@ -1726,7 +1747,7 @@ impl AppAutoUpdater { for result in proxy_results.into_iter().chain(vpn_results) { if let Err(e) = result { - log::warn!("Failed to stop a network worker before app update: {e}"); + log::warn!("Worker stop before app update failed err=\"{e}\""); } } @@ -1744,10 +1765,7 @@ impl AppAutoUpdater { .into_iter() .filter(|pid| crate::proxy_storage::is_process_running(*pid)) .collect(); - log::error!( - "App update aborted because donut-proxy worker PIDs are still running: {:?}", - remaining - ); + log::error!("App update aborted: workers still running pids={remaining:?}"); Err( serde_json::json!({ "code": "UPDATE_PREPARATION_FAILED" @@ -1806,7 +1824,11 @@ rm "{}" use std::os::unix::process::CommandExt; cmd.process_group(0); - let _child = cmd.spawn()?; + let child = cmd.spawn()?; + log::info!( + "Process spawned pid={} purpose=\"relaunch after exit\" waits_for_pid={current_pid}", + child.id() + ); // Give the script a moment to start tokio::time::sleep(tokio::time::Duration::from_millis(500)).await; @@ -1872,12 +1894,6 @@ rm "{}" let file_w = encode_wide(&file); let params_w = encode_wide(¶meters); - log::info!( - "Running installer via ShellExecuteW: {:?} {:?}", - file, - parameters - ); - // Take the binding from the `windows` crate rather than writing the // declaration here. A hand-written one is what put the wrong width on // `SendMessageTimeoutA`'s out-parameter in `default_browser.rs`, and @@ -1907,6 +1923,11 @@ rm "{}" if code <= 32 { return Err(format!("ShellExecuteW failed with code {code}").into()); } + log::info!( + "Update installer launched via ShellExecuteW file={:?} params={:?}; exiting so it can replace the app", + file, + parameters + ); } else { // No pending installer — just restart the app. Use a minimal // detached process to relaunch after we exit. @@ -1928,10 +1949,14 @@ rm "{}" use std::os::windows::process::CommandExt; const CREATE_NO_WINDOW: u32 = 0x08000000; - let _child = Command::new("cmd") + let child = Command::new("cmd") .args(["/C", script_path.to_str().unwrap()]) .creation_flags(CREATE_NO_WINDOW) .spawn()?; + log::info!( + "Process spawned pid={} purpose=\"relaunch after exit\" waits_for_pid={current_pid}", + child.id() + ); } tokio::time::sleep(tokio::time::Duration::from_millis(500)).await; @@ -1985,7 +2010,11 @@ rm "{}" use std::os::unix::process::CommandExt; cmd.process_group(0); - let _child = cmd.spawn()?; + let child = cmd.spawn()?; + log::info!( + "Process spawned pid={} purpose=\"relaunch after exit\" waits_for_pid={current_pid}", + child.id() + ); // Give the script a moment to start tokio::time::sleep(tokio::time::Duration::from_millis(500)).await; @@ -2009,12 +2038,12 @@ pub async fn check_for_app_updates() -> Result, String> { if crate::e2e_automation_enabled() && std::env::var_os("DONUT_E2E_DISABLE_STARTUP_NETWORK").is_some() { - log::info!("E2E: skipping automatic app update check"); + log::debug!("App update check skipped reason=e2e"); return Ok(None); } if crate::app_dirs::is_portable() { - log::info!("App auto-updates disabled in portable mode"); + log::debug!("App update check skipped reason=portable"); return Ok(None); } // The disable_auto_updates setting controls app self-updates only @@ -2023,7 +2052,7 @@ pub async fn check_for_app_updates() -> Result, String> { .map(|s| s.disable_auto_updates) .unwrap_or(false); if disabled { - log::info!("App auto-updates disabled by user setting"); + log::debug!("App update check skipped reason=disabled_by_setting"); return Ok(None); } @@ -2070,14 +2099,13 @@ pub async fn check_for_app_updates_manual() -> Result, Str if crate::e2e_automation_enabled() && std::env::var_os("DONUT_E2E_DISABLE_STARTUP_NETWORK").is_some() { - log::info!("E2E: skipping manual app update check"); + log::debug!("App update check skipped reason=e2e manual=true"); return Ok(None); } - log::info!("Manual app update check triggered"); let updater = AppAutoUpdater::instance(); updater - .check_for_updates() + .check(true) .await .map_err(|e| format!("Failed to check for app updates: {e}")) } @@ -2085,6 +2113,51 @@ pub async fn check_for_app_updates_manual() -> Result, Str // Global singleton instance static APP_AUTO_UPDATER: std::sync::LazyLock = std::sync::LazyLock::new(AppAutoUpdater::new); +static APP_UPDATE_CHECK_STREAK: crate::log_streak::Streak = + crate::log_streak::Streak::new(module_path!(), "App update check"); +/// ` ` of the previous check, so an unchanged outcome logs at debug. +static APP_UPDATE_LAST_OUTCOME: std::sync::Mutex> = std::sync::Mutex::new(None); + +fn exit_code(status: &std::process::ExitStatus) -> String { + status + .code() + .map_or_else(|| "signal".to_string(), |code| code.to_string()) +} + +/// `Command::output`, with the spawn and the exit logged by pid. +fn output_logged(cmd: &mut Command, purpose: &str) -> std::io::Result { + let started = std::time::Instant::now(); + let child = cmd + .stdin(std::process::Stdio::null()) + .stdout(std::process::Stdio::piped()) + .stderr(std::process::Stdio::piped()) + .spawn()?; + let pid = child.id(); + log::info!("Process spawned pid={pid} purpose=\"{purpose}\""); + let output = child.wait_with_output()?; + log::info!( + "Process exited pid={pid} purpose=\"{purpose}\" code={} elapsed_ms={}", + exit_code(&output.status), + started.elapsed().as_millis() + ); + Ok(output) +} + +/// `Command::status`, with the spawn and the exit logged by pid. +#[cfg(target_os = "linux")] +fn status_logged(cmd: &mut Command, purpose: &str) -> std::io::Result { + let started = std::time::Instant::now(); + let mut child = cmd.spawn()?; + let pid = child.id(); + log::info!("Process spawned pid={pid} purpose=\"{purpose}\""); + let status = child.wait()?; + log::info!( + "Process exited pid={pid} purpose=\"{purpose}\" code={} elapsed_ms={}", + exit_code(&status), + started.elapsed().as_millis() + ); + Ok(status) +} /// The Windows installer that runs on the next user-initiated restart. #[cfg(target_os = "windows")] static PENDING_INSTALLER_PATH: std::sync::Mutex> = std::sync::Mutex::new(None); diff --git a/src-tauri/src/app_dirs.rs b/src-tauri/src/app_dirs.rs index 3b1008a2..9110b812 100644 --- a/src-tauri/src/app_dirs.rs +++ b/src-tauri/src/app_dirs.rs @@ -146,7 +146,7 @@ fn window_state_override_for(relocated: bool, data_dir: PathBuf) -> Option versions, Err(e) => { - log::warn!("Failed to fetch versions for {browser}: {e}, trying cache"); // Fall back to cache if network fails - if let Some(cached) = self + let cached = self .browser_version_manager - .get_cached_browser_versions_detailed(&browser) - { - cached - } else { - continue; + .get_cached_browser_versions_detailed(&browser); + let fallback = if cached.is_some() { "cache" } else { "none" }; + fetch_failures.push(format!("browser={browser} fallback={fallback} {e}")); + match cached { + Some(cached) => cached, + None => continue, } } }; @@ -110,116 +111,112 @@ impl AutoUpdater { } } + if fetch_failures.is_empty() { + VERSION_FETCH_STREAK.succeeded(); + } else { + VERSION_FETCH_STREAK.failed(fetch_failures.join("; ")); + } + Ok(notifications) } pub async fn check_for_updates_with_progress(&self, app_handle: &tauri::AppHandle) { - log::info!("Starting auto-update check with progress..."); - // Browser auto-updates are always enabled — the disable_auto_updates setting // only controls app self-updates, not browser version updates. // Check for browser updates and trigger auto-downloads + let started = std::time::Instant::now(); match self.check_for_updates().await { Ok(update_notifications) => { // Group by browser+version to avoid duplicate downloads let grouped = self.group_update_notifications(update_notifications); - if !grouped.is_empty() { - log::info!("Found {} browser updates", grouped.len()); + let summary = grouped + .iter() + .map(|n| { + format!( + "{}@{}(profiles={})", + n.browser, + n.new_version, + n.affected_profiles.len() + ) + }) + .collect::>() + .join(","); + let changed = BROWSER_UPDATE_LAST_SUMMARY + .lock() + .map(|mut last| last.replace(summary.clone()) != Some(summary.clone())) + .unwrap_or(true); + log::log!( + if changed { + log::Level::Info + } else { + log::Level::Debug + }, + "Browser update check updates=[{summary}] elapsed_ms={}", + started.elapsed().as_millis() + ); + for notification in grouped { + let browser = notification.browser.clone(); + let new_version = notification.new_version.clone(); + let app_handle_clone = app_handle.clone(); - for notification in grouped { - log::info!( - "Auto-updating {} to version {} ({} profiles)", - notification.browser, - notification.new_version, - notification.affected_profiles.len() - ); + // Spawn async task to handle the download and auto-update + tokio::spawn(async move { + let registry = + crate::downloaded_browsers_registry::DownloadedBrowsersRegistry::instance(); - let browser = notification.browser.clone(); - let new_version = notification.new_version.clone(); - let app_handle_clone = app_handle.clone(); + // Skip if this browser-version pair is already being downloaded + if crate::downloader::is_downloading(&browser, &new_version) { + log::debug!( + "Browser update download already running browser={browser} version={new_version}" + ); + return; + } - // Spawn async task to handle the download and auto-update - tokio::spawn(async move { - let registry = - crate::downloaded_browsers_registry::DownloadedBrowsersRegistry::instance(); - - // Skip if this browser-version pair is already being downloaded - if crate::downloader::is_downloading(&browser, &new_version) { - log::info!( - "Browser {browser} {new_version} is already being downloaded, skipping duplicate" - ); - return; - } - - if registry.is_browser_downloaded(&browser, &new_version) { - log::info!("Browser {browser} {new_version} already downloaded, proceeding to auto-update profiles"); - - // Browser already exists, go straight to profile update - match AutoUpdater::instance() - .auto_update_profile_versions(&app_handle_clone, &browser, &new_version) - .await - { - Ok(updated_profiles) => { - if !updated_profiles.is_empty() { - log::info!( - "Auto-updated {} profiles to {browser} {new_version}: {:?}", - updated_profiles.len(), - updated_profiles - ); - } - } - Err(e) => { - log::error!("Failed to auto-update profiles for {browser}: {e}"); - } - } - } else { - log::info!("Downloading browser {browser} version {new_version}..."); - - // Download directly from Rust — download_browser_full already - // auto-updates non-running profiles after successful download. - match crate::downloader::download_browser( - app_handle_clone, - browser.clone(), - new_version.clone(), - ) + if registry.is_browser_downloaded(&browser, &new_version) { + // Browser already exists, go straight to profile update + if let Err(e) = AutoUpdater::instance() + .auto_update_profile_versions(&app_handle_clone, &browser, &new_version) .await - { - Ok(actual_version) => { - log::info!("Auto-download completed for {browser} {actual_version}"); - } - Err(e) => { - log::error!("Failed to auto-download {browser} {new_version}: {e}"); - } - } + { + log::error!( + "Browser update apply failed browser={browser} version={new_version} err=\"{e}\"" + ); } - }); - } - } else { - log::info!("No browser updates needed"); + } else { + // Download directly from Rust — download_browser_full already + // auto-updates non-running profiles after successful download. + let download_started = std::time::Instant::now(); + // download_browser logs its own failure. + if let Ok(actual_version) = crate::downloader::download_browser( + app_handle_clone, + browser.clone(), + new_version.clone(), + ) + .await + { + log::info!( + "Browser update downloaded browser={browser} version={actual_version} elapsed_ms={}", + download_started.elapsed().as_millis() + ); + } + } + }); } } Err(e) => { - log::error!("Failed to check for browser updates: {e}"); + log::error!( + "Browser update check failed elapsed_ms={} err=\"{e}\"", + started.elapsed().as_millis() + ); } } // Also update any profiles that can be bumped to an already-installed newer version. // This handles cases where a version was downloaded but profiles weren't updated // (e.g., they were running at the time, or the update was missed). - match self.update_profiles_to_latest_installed(app_handle) { - Ok(updated) => { - if !updated.is_empty() { - log::info!( - "Updated {} profiles to latest installed versions: {:?}", - updated.len(), - updated - ); - } - } - Err(e) => { - log::error!("Failed to update profiles to latest installed versions: {e}"); - } + if let Err(e) = self.update_profiles_to_latest_installed(app_handle) { + log::error!("Moving profiles to the latest installed browser failed err=\"{e}\""); } } @@ -314,21 +311,14 @@ impl AutoUpdater { // moment it closes, and would pin that older binary against cleanup. if !self.is_version_newer(new_version, &profile.version) { log::debug!( - "Not queuing {} for running profile {}: not newer than {}", - new_version, - profile.name, + "Pending browser update skipped: not newer profile={} from={} to={new_version}", + profile.id, profile.version ); continue; } // Store as pending update so it gets applied when browser closes - log::info!( - "Profile {} is running, storing pending update {} -> {}", - profile.name, - profile.version, - new_version - ); let mut state = self.load_auto_update_state().unwrap_or_default(); let notification = UpdateNotification { id: format!("{}_{}_to_{}", browser, profile.version, new_version), @@ -349,6 +339,11 @@ impl AutoUpdater { { state.pending_updates.push(notification); let _ = self.save_auto_update_state(&state); + log::info!( + "Browser update queued until the profile closes profile={} browser={browser} from={} to={new_version}", + profile.id, + profile.version + ); } continue; } @@ -362,10 +357,18 @@ impl AutoUpdater { new_version, ) { Ok(_) => { + log::info!( + "Profile browser updated profile={} browser={browser} from={} to={new_version}", + profile.id, + profile.version + ); updated_profiles.push(profile.name); } Err(e) => { - log::error!("Failed to update profile {}: {}", profile.name, e); + log::error!( + "Profile browser update failed profile={} browser={browser} to={new_version} err=\"{e}\"", + profile.id + ); } } } @@ -513,18 +516,18 @@ impl AutoUpdater { { Ok(updated) => { log::info!( - "Updated profile {} from {} {} to latest installed version {}", - profile.name, + "Profile browser updated profile={} browser={} from={} to={latest}", + profile.id, profile.browser, - profile.version, - latest + profile.version ); Some(updated) } Err(e) => { log::error!( - "Failed to update profile {} to latest installed version: {e}", - profile.name + "Profile browser update failed profile={} browser={} to={latest} err=\"{e}\"", + profile.id, + profile.browser ); None } @@ -590,16 +593,17 @@ impl AutoUpdater { ) { Ok(_) => { log::info!( - "Updated profile {} from {} {} to latest installed version {}", - profile.name, - browser, - profile.version, - latest_version + "Profile browser updated profile={} browser={browser} from={} to={latest_version}", + profile.id, + profile.version ); all_updated.push(profile.name); } Err(e) => { - log::error!("Failed to update profile {}: {e}", profile.name); + log::error!( + "Profile browser update failed profile={} browser={browser} to={latest_version} err=\"{e}\"", + profile.id + ); } } } @@ -651,6 +655,10 @@ pub async fn check_for_updates_with_progress(app_handle: tauri::AppHandle) { // Global singleton instance static AUTO_UPDATER: std::sync::LazyLock = std::sync::LazyLock::new(AutoUpdater::new); +static VERSION_FETCH_STREAK: crate::log_streak::Streak = + crate::log_streak::Streak::new(module_path!(), "Browser version fetch"); +/// Updates found by the previous check, so an unchanged result logs at debug. +static BROWSER_UPDATE_LAST_SUMMARY: std::sync::Mutex> = std::sync::Mutex::new(None); #[cfg(test)] mod tests { diff --git a/src-tauri/src/bin/proxy_server.rs b/src-tauri/src/bin/proxy_server.rs index 8e8c76c3..1a84ba54 100644 --- a/src-tauri/src/bin/proxy_server.rs +++ b/src-tauri/src/bin/proxy_server.rs @@ -15,12 +15,12 @@ fn set_high_priority() { // This may fail without elevated privileges, which is fine let result = libc::setpriority(libc::PRIO_PROCESS, 0, -10); if result == 0 { - log::info!("Set process priority to -10 (high priority)"); + log::debug!("Process priority set nice=-10"); } else { // Try a less aggressive priority if -10 fails let result = libc::setpriority(libc::PRIO_PROCESS, 0, -5); if result == 0 { - log::info!("Set process priority to -5 (above normal)"); + log::debug!("Process priority set nice=-5"); } } } @@ -32,9 +32,9 @@ fn set_high_priority() { // Valid range is -1000 to 1000, lower = less likely to be killed // -500 is a reasonable value that makes us less likely to be killed if let Err(e) = std::fs::write("/proc/self/oom_score_adj", "-500") { - log::debug!("Could not set OOM score adjustment: {}", e); + log::debug!("OOM score adjustment failed err=\"{e}\""); } else { - log::info!("Set OOM score adjustment to -500"); + log::debug!("OOM score adjustment set oom_score_adj=-500"); } } @@ -47,9 +47,9 @@ fn set_high_priority() { unsafe { let process = GetCurrentProcess(); if SetPriorityClass(process, ABOVE_NORMAL_PRIORITY_CLASS).is_ok() { - log::info!("Set process priority to ABOVE_NORMAL_PRIORITY_CLASS"); + log::debug!("Process priority set class=ABOVE_NORMAL"); } else { - log::debug!("Could not set process priority class"); + log::debug!("Process priority class set failed"); } } } @@ -62,26 +62,43 @@ async fn main() { // Default filter is Info — Debug pulls in reqwest/hyper internals which // make the per-worker log unreadable on a busy browser session and obscure // the actual lines we care about (binds, accept errors, upstream failures). - // RUST_LOG=debug or RUST_LOG=donut_proxy=trace still works for deep dives. - env_logger::Builder::from_default_env() + // RUST_LOG is parsed after the default so it wins: `debug`, or + // `donutbrowser_lib::proxy_server=trace` for the tunnel code alone. + // Same line shape as the app log: `[ts][target][LEVEL] message`, with the + // crate prefix dropped from the target. + env_logger::Builder::new() .filter_level(log::LevelFilter::Info) - .format_timestamp_millis() + .parse_default_env() + .format(|buf, record| { + use std::io::Write; + let target = record.target(); + let target = target.strip_prefix("donutbrowser_lib::").unwrap_or(target); + writeln!( + buf, + "[{}][{}][{}] {}", + buf.timestamp_millis(), + target, + record.level(), + record.args() + ) + }) .init(); - // Set up panic handler to log panics before process exits std::panic::set_hook(Box::new(|panic_info| { - log::error!("PANIC in proxy worker: {:?}", panic_info); - if let Some(location) = panic_info.location() { - log::error!( - "Location: {}:{}:{}", - location.file(), - location.line(), - location.column() - ); - } - if let Some(s) = panic_info.payload().downcast_ref::<&str>() { - log::error!("Message: {}", s); - } + let location = panic_info + .location() + .map(|l| format!("{}:{}:{}", l.file(), l.line(), l.column())) + .unwrap_or_else(|| "-".to_string()); + let message = panic_info + .payload() + .downcast_ref::<&str>() + .map(|s| s.to_string()) + .or_else(|| panic_info.payload().downcast_ref::().cloned()) + .unwrap_or_default(); + log::error!( + "Worker panicked pid={} at={location} msg={message:?}", + std::process::id() + ); })); let matches = Command::new("donut-proxy") @@ -373,7 +390,7 @@ async fn main() { println!("{}", serde_json::to_string(&configs).unwrap()); process::exit(0); } else { - log::error!("Invalid action. Use 'start', 'stop', or 'list'"); + eprintln!("Invalid action. Use 'start', 'stop', or 'list'"); process::exit(1); } } else if let Some(xray_matches) = matches.subcommand_matches("xray") { @@ -459,7 +476,7 @@ async fn main() { } } } else { - log::error!("Invalid action. Use 'start', 'bind', or 'stop'"); + eprintln!("Invalid action. Use 'start', 'bind', or 'stop'"); process::exit(1); } } else if let Some(worker_matches) = matches.subcommand_matches("proxy-worker") { @@ -474,51 +491,42 @@ async fn main() { // Set high priority so this process is killed last under resource pressure set_high_priority(); - log::info!( - "Proxy worker starting (pid {}, config id {})", - std::process::id(), - id - ); - // Retry config loading to handle file system race condition on Windows // where the config file may not be immediately visible after being written let config = { let mut attempts = 0; loop { if let Some(config) = get_proxy_config(id) { - log::info!( - "Found config: id={}, port={:?}, upstream={}", - config.id, - config.local_port, - redacted_upstream(&config.upstream_url) - ); break config; } attempts += 1; if attempts >= 10 { log::error!( - "Proxy configuration {} not found after {} attempts", - id, - attempts + "Worker exiting kind=proxy id={id} pid={} reason=config_not_found attempts={attempts}", + process::id() ); process::exit(1); } - log::debug!("Config {} not found yet, retrying ({}/10)...", id, attempts); std::thread::sleep(std::time::Duration::from_millis(50)); } }; // Run the proxy server - this should never return (infinite loop) - log::info!("Starting proxy server for config id: {}", id); if let Err(e) = run_proxy_server(config).await { - log::error!("Proxy server failed: {} ({:?})", e, e); + log::error!( + "Worker exiting kind=proxy id={id} pid={} reason=error err=\"{e}\"", + process::id() + ); process::exit(1); } // This should never be reached - run_proxy_server has an infinite loop - log::error!("Proxy server returned unexpectedly (this should never happen)"); + log::error!( + "Worker exiting kind=proxy id={id} pid={} reason=accept_loop_returned", + process::id() + ); process::exit(1); } else { - log::error!("Invalid action for proxy-worker. Use 'start'"); + eprintln!("Invalid action for proxy-worker. Use 'start'"); process::exit(1); } } else if let Some(vpn_matches) = matches.subcommand_matches("vpn-worker") { @@ -533,67 +541,41 @@ async fn main() { if action == "start" { set_high_priority(); - - log::info!("VPN worker starting, config id: {}", id); - log::info!("Process PID: {}", std::process::id()); + let pid = process::id(); + let exit_with = |reason: &str, detail: String| -> ! { + log::error!("Worker exiting kind=vpn id={id} pid={pid} reason={reason} {detail}"); + process::exit(1); + }; let config = if let Some(path) = config_path { // Load config directly from the provided path - log::info!("Loading VPN worker config from: {}", path); match std::fs::read_to_string(path) { Ok(content) => match serde_json::from_str::< donutbrowser_lib::vpn_worker_storage::VpnWorkerConfig, >(&content) { - Ok(config) => { - log::info!( - "Found VPN worker config: id={}, vpn_type={}, vpn_id={}", - config.id, - config.vpn_type, - config.vpn_id - ); - config - } - Err(e) => { - log::error!("Failed to parse VPN worker config from {}: {}", path, e); - process::exit(1); - } + Ok(config) => config, + Err(e) => exit_with("config_unparsable", format!("path=\"{path}\" err=\"{e}\"")), }, - Err(e) => { - log::error!("Failed to read VPN worker config from {}: {}", path, e); - process::exit(1); - } + Err(e) => exit_with("config_unreadable", format!("path=\"{path}\" err=\"{e}\"")), } } else { // Fallback: discover config by ID with retries - let storage_dir = donutbrowser_lib::proxy_storage::get_storage_dir(); - log::info!("Looking for VPN worker config in: {:?}", storage_dir); let mut attempts = 0; loop { if let Some(config) = donutbrowser_lib::vpn_worker_storage::get_vpn_worker_config(id) { - log::info!( - "Found VPN worker config: id={}, vpn_type={}, vpn_id={}", - config.id, - config.vpn_type, - config.vpn_id - ); break config; } attempts += 1; if attempts >= 50 { - log::error!( - "VPN worker configuration {} not found after {} attempts in {:?}", - id, - attempts, - storage_dir + exit_with( + "config_not_found", + format!( + "attempts={attempts} dir=\"{}\"", + donutbrowser_lib::proxy_storage::get_storage_dir().display() + ), ); - process::exit(1); } - log::info!( - "VPN worker config {} not found yet, retrying ({}/50)...", - id, - attempts - ); std::thread::sleep(std::time::Duration::from_millis(100)); } }; @@ -601,24 +583,20 @@ async fn main() { // Read the decrypted VPN config from the temp file let vpn_config_data = match std::fs::read_to_string(&config.config_file_path) { Ok(data) => data, - Err(e) => { - log::error!( - "Failed to read VPN config file {}: {}", - config.config_file_path, - e - ); - process::exit(1); - } + Err(e) => exit_with( + "vpn_config_unreadable", + format!("vpn={} err=\"{e}\"", config.vpn_id), + ), }; match config.vpn_type.as_str() { "wireguard" => { let wg_config = match donutbrowser_lib::vpn::parse_wireguard_config(&vpn_config_data) { Ok(c) => c, - Err(e) => { - log::error!("Failed to parse WireGuard config: {}", e); - process::exit(1); - } + Err(e) => exit_with( + "wireguard_config_invalid", + format!("vpn={} err=\"{e}\"", config.vpn_id), + ), }; let server = @@ -627,17 +605,13 @@ async fn main() { .run(id.clone(), config_path.map(std::path::PathBuf::from)) .await { - log::error!("VPN worker failed: {}", e); - process::exit(1); + exit_with("error", format!("vpn={} err=\"{e}\"", config.vpn_id)); } } - other => { - log::error!("Unknown VPN type: {}", other); - process::exit(1); - } + other => exit_with("unknown_vpn_type", format!("vpn_type={other}")), } } else { - log::error!("Invalid action for vpn-worker. Use 'start'"); + eprintln!("Invalid action for vpn-worker. Use 'start'"); process::exit(1); } } else if let Some(xray_matches) = matches.subcommand_matches("xray-worker") { @@ -648,7 +622,7 @@ async fn main() { .get_one::("config-path") .expect("config-path is required"); if action != "start" { - log::error!("Invalid action for xray-worker. Use 'start'"); + eprintln!("Invalid action for xray-worker. Use 'start'"); process::exit(1); } @@ -656,11 +630,14 @@ async fn main() { if let Err(error) = donutbrowser_lib::xray_worker_runner::run_xray_worker(std::path::Path::new(config_path)).await { - log::error!("Xray worker failed: {error}"); + log::error!( + "Worker exiting kind=xray pid={} reason=error err=\"{error}\"", + process::id() + ); process::exit(1); } } else { - log::error!("No command specified"); + eprintln!("No command specified"); process::exit(1); } } diff --git a/src-tauri/src/browser.rs b/src-tauri/src/browser.rs index 81ca9614..161d0c15 100644 --- a/src-tauri/src/browser.rs +++ b/src-tauri/src/browser.rs @@ -158,7 +158,6 @@ mod linux { #[allow(dead_code)] pub fn prepare_executable(executable_path: &Path) -> Result<(), Box> { // On Linux, ensure the executable has proper permissions - log::info!("Setting execute permissions for: {:?}", executable_path); let metadata = std::fs::metadata(executable_path)?; let mut permissions = metadata.permissions(); @@ -169,10 +168,7 @@ mod linux { std::fs::set_permissions(executable_path, permissions)?; - log::info!( - "Execute permissions set successfully for: {:?}", - executable_path - ); + log::debug!("Execute permission set path={}", executable_path.display()); Ok(()) } } diff --git a/src-tauri/src/browser_runner.rs b/src-tauri/src/browser_runner.rs index 537e6d4a..8d90808d 100644 --- a/src-tauri/src/browser_runner.rs +++ b/src-tauri/src/browser_runner.rs @@ -53,6 +53,75 @@ fn emit_launch_stage(profile: &BrowserProfile, stage: &str, error: Option<&str>) ); } +/// An error for the log: the profile's name taken out (several launch errors +/// quote it), then URLs, credentials and addresses redacted. +fn log_err(err: &str, profile: &BrowserProfile) -> String { + let name = profile.name.trim(); + let without_name = if name.is_empty() { + err.to_string() + } else { + err.replace(name, "") + }; + crate::log_redaction::text(&without_name) +} + +/// Outcomes the person meets as a dialog or a notice, not a fault. +const LAUNCH_BLOCK_CODES: [&str; 10] = [ + "FINGERPRINT_EXIT_MISMATCH", + "LAUNCH_CONSENT_EXPIRED", + "PROFILE_RUNNING", + "PROFILE_RUNNING_REMOTELY", + "PROFILE_REMOTE_SYNC_PENDING", + "PROFILE_LOCKED_BY_MEMBER", + "PROFILE_LOCKED_ELSEWHERE", + "PROFILE_ROUTE_REQUIRED", + "PROFILE_ROUTE_UNAVAILABLE", + "WAYFERN_CROSS_OS_REQUIRES_PLAN", +]; + +/// One line per failed launch. A coded error logs its code and detail only: +/// the mismatch block carries the exit IP, timezone and language in its params. +fn log_launch_failure(profile: &BrowserProfile, err: &str, started: std::time::Instant) { + let elapsed_ms = started.elapsed().as_millis(); + let coded = serde_json::from_str::(err) + .ok() + .and_then(|value| { + let code = value.get("code")?.as_str()?.to_string(); + let params = value.get("params").cloned().unwrap_or_default(); + Some((code, params)) + }); + let Some((code, params)) = coded else { + log::error!( + "Browser launch failed profile={} elapsed_ms={elapsed_ms} err=\"{}\"", + profile.id, + log_err(err, profile) + ); + return; + }; + let detail = params + .get("detail") + .and_then(|d| d.as_str()) + .map(|d| format!(" detail=\"{}\"", log_err(d, profile))) + .unwrap_or_default(); + if LAUNCH_BLOCK_CODES.contains(&code.as_str()) { + let mismatches = params + .get("mismatches") + .and_then(|m| m.as_str()) + .filter(|m| !m.is_empty()) + .map(|m| format!(" mismatches={m}")) + .unwrap_or_default(); + log::info!( + "Browser launch blocked profile={} code={code}{mismatches}{detail} elapsed_ms={elapsed_ms}", + profile.id + ); + return; + } + log::error!( + "Browser launch failed profile={} code={code}{detail} elapsed_ms={elapsed_ms}", + profile.id + ); +} + pub struct BrowserRunner { pub profile_manager: &'static ProfileManager, pub downloaded_browsers_registry: &'static DownloadedBrowsersRegistry, @@ -116,7 +185,7 @@ impl BrowserRunner { }; if PROXY_MANAGER.is_cloud_or_derived(proxy_id) { - log::info!("Refreshing cloud proxy credentials before launch for proxy {proxy_id}"); + log::debug!("Refreshing cloud proxy credentials proxy={proxy_id}"); CLOUD_AUTH.sync_cloud_proxy().await; } // For cloud-derived proxies, inject profile-specific sid for sticky sessions @@ -154,8 +223,7 @@ impl BrowserRunner { Ok(u) => u, Err(e) => { log::warn!( - "Skipping launch hook for profile {} (ID: {}): invalid URL: {e}", - profile.name, + "Launch hook skipped, invalid URL profile={} err=\"{e}\"", profile.id ); return; @@ -164,17 +232,14 @@ impl BrowserRunner { if !matches!(parsed.scheme(), "http" | "https") { log::warn!( - "Skipping launch hook for profile {} (ID: {}): URL must be http or https", - profile.name, + "Launch hook skipped, URL is not http(s) profile={}", profile.id ); return; } let url = parsed.to_string(); - let url_label = crate::log_redaction::url_label(&url); - - log::info!("Firing launch hook GET {url_label}"); + let profile_id = profile.id; tokio::spawn(async move { let client = match reqwest::Client::builder() @@ -184,7 +249,7 @@ impl BrowserRunner { Ok(c) => c, Err(e) => { log::warn!( - "Launch hook client build failed: {}", + "Launch hook client build failed profile={profile_id} err=\"{}\"", crate::log_redaction::text(&e.to_string()) ); return; @@ -192,12 +257,21 @@ impl BrowserRunner { }; match client.get(&url).send().await { + Ok(resp) if resp.status().is_success() => { + log::debug!( + "Launch hook answered profile={profile_id} status={}", + resp.status().as_u16() + ); + } Ok(resp) => { - log::info!("Launch hook {url_label} returned status {}", resp.status()); + log::warn!( + "Launch hook answered with an error profile={profile_id} status={}", + resp.status().as_u16() + ); } Err(e) => { log::warn!( - "Launch hook {url_label} failed: {}", + "Launch hook failed profile={profile_id} err=\"{}\"", crate::log_redaction::text(&e.to_string()) ); } @@ -257,6 +331,7 @@ impl BrowserRunner { ) -> Result> { // Handle Wayfern profiles using WayfernManager if profile.browser == "wayfern" { + let launch_started = std::time::Instant::now(); let _launch_in_progress = crate::wayfern_identity_storage::yield_to_launch().await; let converted; let profile = if crate::wayfern_identity_storage::needs_conversion(profile) { @@ -269,10 +344,7 @@ impl BrowserRunner { }; // Get or create wayfern config let mut wayfern_config = profile.wayfern_config.clone().unwrap_or_else(|| { - log::info!( - "No wayfern config found for profile {}, using default", - profile.name - ); + log::debug!("No wayfern config, using default profile={}", profile.id); WayfernConfig::default() }); @@ -286,26 +358,20 @@ impl BrowserRunner { struct XrayLaunchGuard { worker_id: Option, - profile_name: String, } impl Drop for XrayLaunchGuard { fn drop(&mut self) { let Some(worker_id) = self.worker_id.take() else { return; }; - log::warn!( - "Launch failed after Xray-core start for profile {}; stopping worker", - self.profile_name - ); if let Err(error) = crate::xray_worker_runner::stop_xray_worker_now(&worker_id) { - log::warn!("Failed to stop Xray-core worker after failed launch: {error}"); + log::warn!( + "Xray worker stop after failed launch failed id={worker_id} err=\"{error}\"" + ); } } } - let mut xray_launch_guard = XrayLaunchGuard { - worker_id: None, - profile_name: profile.name.clone(), - }; + let mut xray_launch_guard = XrayLaunchGuard { worker_id: None }; if upstream_proxy .as_ref() @@ -321,10 +387,6 @@ impl BrowserRunner { .map_err(|error| -> Box { error.to_string().into() })?; - log::info!( - "Xray-core worker started for Wayfern profile on port {}", - worker.local_port - ); xray_launch_guard.worker_id = Some(worker.id.clone()); upstream_proxy = Some(worker.local_proxy_settings()); } @@ -340,7 +402,6 @@ impl BrowserRunner { worker_id: Option, vpn_id: String, created: bool, - profile_name: String, /// This launch's own hold on the worker, kept until the guard goes out /// of scope so a sibling launch cannot stop the worker while this one /// is still between adoption and publishing its browser PID. @@ -357,10 +418,6 @@ impl BrowserRunner { if !self.created { return; } - log::warn!( - "Launch failed after VPN worker start for profile {}; stopping worker", - self.profile_name - ); let vpn_id = self.vpn_id.clone(); tauri::async_runtime::spawn(async move { // Serialize against worker startup for the whole check-then-stop. @@ -368,27 +425,30 @@ impl BrowserRunner { // in-use check and the kill, and lose its tunnel a moment later. let _adopt_guard = crate::vpn_worker_runner::lock_vpn_starts().await; if crate::vpn_worker_runner::vpn_id_in_use_by_running_browser(&vpn_id) { - log::info!("VPN {vpn_id} is still in use by a running browser; leaving it up"); + log::debug!("VPN worker kept, another browser uses it vpn={vpn_id} id={worker_id}"); return; } if let Err(error) = crate::vpn_worker_runner::stop_vpn_worker(&worker_id).await { - log::warn!("Failed to stop VPN worker after failed launch: {error}"); + log::warn!( + "VPN worker stop after failed launch failed id={worker_id} err=\"{error}\"" + ); } }); } } let mut vpn_launch_guard: Option = None; + let mut vpn_worker_id: Option = None; // If profile has a VPN instead of proxy, start VPN worker and use it as upstream if upstream_proxy.is_none() { if let Some(ref vpn_id) = profile.vpn_id { match crate::vpn_worker_runner::start_vpn_worker_tracked(vpn_id).await { Ok(started) => { + vpn_worker_id = Some(started.config.id.clone()); vpn_launch_guard = Some(VpnLaunchGuard { worker_id: Some(started.config.id.clone()), vpn_id: vpn_id.clone(), created: started.created, - profile_name: profile.name.clone(), claim: Some(started.claim), }); if let Some(port) = started.config.local_port { @@ -400,7 +460,6 @@ impl BrowserRunner { password: None, vless_uri: None, }); - log::info!("VPN worker started for Wayfern profile on port {}", port); } } Err(e) => { @@ -439,15 +498,6 @@ impl BrowserRunner { // webhook exactly once. Self::fire_launch_hook(profile); - log::info!( - "Starting local proxy for Wayfern profile: {} (upstream: {})", - profile.name, - upstream_proxy - .as_ref() - .map(|p| format!("{}:{}", p.host, p.port)) - .unwrap_or_else(|| "DIRECT".to_string()) - ); - // Start the proxy and get local proxy settings // If proxy startup fails, DO NOT launch Wayfern - it requires local proxy let profile_id_str = profile.id.to_string(); @@ -472,11 +522,7 @@ impl BrowserRunner { "socks5", ) .await - .map_err(|e| { - let error_msg = crate::wrap_backend_error(e, "Failed to start local proxy for Wayfern"); - log::error!("{}", error_msg); - error_msg - })?; + .map_err(|e| crate::wrap_backend_error(e, "Failed to start local proxy for Wayfern"))?; // If any step below fails before the browser is up, the detached worker // must be stopped here: its config never gets a browser_pid, so neither @@ -485,21 +531,18 @@ impl BrowserRunner { struct ProxyLaunchGuard { app_handle: tauri::AppHandle, routing_pid: u32, - profile_name: String, armed: bool, } impl Drop for ProxyLaunchGuard { fn drop(&mut self) { if self.armed { - log::warn!( - "Launch failed after local proxy start for profile {}; stopping proxy worker", - self.profile_name - ); let app_handle = self.app_handle.clone(); let pid = self.routing_pid; tauri::async_runtime::spawn(async move { if let Err(e) = PROXY_MANAGER.stop_proxy(app_handle, pid).await { - log::warn!("Failed to stop proxy worker after failed launch: {e}"); + log::warn!( + "Proxy worker stop after failed launch failed browser_pid={pid} err=\"{e}\"" + ); } }); } @@ -508,7 +551,6 @@ impl BrowserRunner { let mut proxy_launch_guard = ProxyLaunchGuard { app_handle: app_handle.clone(), routing_pid: launch_placeholder_pid, - profile_name: profile.name.clone(), armed: true, }; @@ -519,28 +561,12 @@ impl BrowserRunner { // Set proxy in wayfern config wayfern_config.proxy = Some(proxy_url); - log::info!( - "Configured local proxy for Wayfern: {:?}", - wayfern_config.proxy - ); - let mut updated_profile = profile.clone(); let randomize_requested = wayfern_config.randomize_fingerprint_on_launch == Some(true); let needs_device = crate::wayfern_identity_storage::stored_shape(&wayfern_config) == crate::wayfern_identity_storage::StoredShape::Empty; - if randomize_requested || needs_device { - if needs_device && !randomize_requested { - log::info!( - "No stored device for Wayfern profile {}; generating one", - profile.name - ); - } else { - log::info!( - "Generating random fingerprint for Wayfern profile: {}", - profile.name - ); - } - + let fingerprint_generated = randomize_requested || needs_device; + if fingerprint_generated { // Create a config copy without the existing fingerprint to force generation of a new one let mut config_for_generation = wayfern_config.clone(); config_for_generation.fingerprint = None; @@ -569,12 +595,6 @@ impl BrowserRunner { let geolocation_applied = generated.geolocation_applied; - log::info!( - "New fingerprint generated, length: {} chars, identity: {:?}", - generated.fingerprint.len(), - generated.identity_id - ); - // Update the config with the new device for launching. An identity // stores the id and the location only; a legacy browser stores the // whole payload. @@ -618,13 +638,7 @@ impl BrowserRunner { } else { None }; - updated_profile.wayfern_config = Some(updated_wayfern_config.clone()); - - log::info!( - "Updated profile wayfern_config with new fingerprint for profile: {}, fingerprint length: {}", - profile.name, - updated_wayfern_config.fingerprint.as_ref().map(|f| f.len()).unwrap_or(0) - ); + updated_profile.wayfern_config = Some(updated_wayfern_config); } // A non-randomize profile keeps its configured fingerprint verbatim, even // when its proxy/VPN routing has changed since the fingerprint was built. @@ -644,9 +658,6 @@ impl BrowserRunner { .map_err(|e| -> Box { e.into() })?; } - // Launch Wayfern browser - log::info!("Launching Wayfern for profile: {}", profile.name); - // Get profile path for Wayfern let profiles_dir = self.profile_manager.get_profiles_dir(); let profile_data_path = @@ -660,13 +671,13 @@ impl BrowserRunner { // bookmarks, extensions and site data come back. match crate::profile_import::repair_legacy_layout(&profile_data_path) { Ok(true) => log::info!( - "Repaired legacy import layout for profile: {}", - updated_profile.name + "Repaired legacy import layout profile={}", + updated_profile.id ), Ok(false) => {} Err(e) => log::warn!( - "Could not repair legacy import layout for {}: {e}", - updated_profile.name + "Legacy import layout repair failed profile={} err=\"{e}\"", + updated_profile.id ), } @@ -679,17 +690,13 @@ impl BrowserRunner { let mgr = crate::extension_manager::EXTENSION_MANAGER.lock().unwrap(); match mgr.install_extensions_for_profile(&updated_profile, &profile_data_path) { Ok(paths) => { - if !paths.is_empty() { - log::info!( - "Prepared {} Chromium extensions for profile: {}", - paths.len(), - updated_profile.name - ); - } extension_paths = paths; } Err(e) => { - log::warn!("Failed to install extensions for Wayfern profile: {e}"); + log::warn!( + "Extension install failed, launching without them profile={} err=\"{e}\"", + updated_profile.id + ); } } } @@ -725,7 +732,10 @@ impl BrowserRunner { // Get the process ID from launch result let Some(process_id) = wayfern_result.processId.filter(|pid| *pid != 0) else { if let Err(error) = self.wayfern_manager.stop_wayfern(&wayfern_result.id).await { - log::warn!("Failed to stop Wayfern after it omitted its process ID: {error}"); + log::warn!( + "Browser stop after launch error failed profile={} step=no_pid err=\"{error}\"", + profile.id + ); } return Err( crate::backend_error_with_detail( @@ -735,28 +745,32 @@ impl BrowserRunner { .into(), ); }; - log::info!("Wayfern launched successfully with PID: {process_id}"); - if let Err(error) = PROXY_MANAGER.update_proxy_pid(launch_placeholder_pid, process_id) { if let Err(stop_error) = self.wayfern_manager.stop_wayfern(&wayfern_result.id).await { - log::warn!("Failed to stop Wayfern after proxy PID mapping failed: {stop_error}"); + log::warn!( + "Browser stop after launch error failed profile={} step=proxy_pid err=\"{stop_error}\"", + profile.id + ); } return Err(crate::backend_error_with_detail("INTERNAL_ERROR", error).into()); } proxy_launch_guard.routing_pid = process_id; - log::info!( - "Updated proxy PID mapping from launch placeholder {launch_placeholder_pid} to actual PID: {process_id}" - ); if !PROXY_MANAGER.set_browser_pid_for_profile(&updated_profile.id.to_string(), process_id) { if let Err(error) = self.wayfern_manager.stop_wayfern(&wayfern_result.id).await { - log::warn!("Failed to stop Wayfern after proxy worker reassignment failed: {error}"); + log::warn!( + "Browser stop after launch error failed profile={} step=proxy_owner err=\"{error}\"", + profile.id + ); } return Err(crate::backend_error("INTERNAL_ERROR").into()); } if let Some(worker_id) = xray_launch_guard.worker_id.as_deref() { if !crate::xray_worker_runner::set_browser_pid(worker_id, process_id) { if let Err(error) = self.wayfern_manager.stop_wayfern(&wayfern_result.id).await { - log::warn!("Failed to stop Wayfern after Xray worker reassignment failed: {error}"); + log::warn!( + "Browser stop after launch error failed profile={} step=xray_owner err=\"{error}\"", + profile.id + ); } return Err(crate::backend_error("XRAY_START_FAILED").into()); } @@ -766,48 +780,66 @@ impl BrowserRunner { // process identity, so later profile-persistence failures must not tear // down a live route. proxy_launch_guard.armed = false; - xray_launch_guard.worker_id = None; + let xray_worker_id = xray_launch_guard.worker_id.take(); if let Some(guard) = vpn_launch_guard.as_mut() { guard.worker_id = None; } + let mut launched = format!( + "Browser launched profile={} pid={process_id} browser=wayfern version={} proxy={} vpn={} proxy_worker={}", + updated_profile.id, + crate::log_redaction::Plain(&updated_profile.version), + profile.proxy_id.as_deref().unwrap_or("none"), + profile.vpn_id.as_deref().unwrap_or("none"), + PROXY_MANAGER + .resolve_proxy_id_for_profile(&profile_id_str) + .as_deref() + .unwrap_or("none"), + ); + if let Some(id) = vpn_worker_id.as_deref() { + launched.push_str(&format!(" vpn_worker={id}")); + } + if let Some(id) = xray_worker_id.as_deref() { + launched.push_str(&format!(" xray_worker={id}")); + } + if let Some(port) = wayfern_result.cdp_port { + launched.push_str(&format!(" cdp_port={port}")); + } + if headless { + launched.push_str(" headless=true"); + } + if kind == crate::wayfern_manager::LaunchKind::Automation { + launched.push_str(" kind=automation"); + } + if fingerprint_generated { + launched.push_str(" fingerprint=generated"); + } + if !extension_paths.is_empty() { + launched.push_str(&format!(" extensions={}", extension_paths.len())); + } + log::info!( + "{launched} elapsed_ms={}", + launch_started.elapsed().as_millis() + ); + // Update profile with the process info updated_profile.process_id = Some(process_id); updated_profile.last_launch = Some(SystemTime::now().duration_since(UNIX_EPOCH)?.as_secs()); // Save the updated profile - log::info!( - "Saving profile {} with wayfern_config fingerprint length: {}", - updated_profile.name, - updated_profile - .wayfern_config - .as_ref() - .and_then(|c| c.fingerprint.as_ref()) - .map(|f| f.len()) - .unwrap_or(0) - ); self.save_process_info(&updated_profile)?; let _ = crate::tag_manager::TAG_MANAGER.lock().map(|tm| { let _ = tm.rebuild_from_profiles(&self.profile_manager.list_profiles().unwrap_or_default()); }); - log::info!( - "Successfully saved profile with process info: {}", - updated_profile.name - ); // Emit profiles-changed to trigger frontend to reload profiles from disk if let Err(e) = events::emit_empty("profiles-changed") { - log::warn!("Warning: Failed to emit profiles-changed event: {e}"); + log::warn!("Event emit failed event=profiles-changed err=\"{e}\""); } - log::info!( - "Emitting profile events for successful Wayfern launch: {}", - updated_profile.name - ); - // Emit profile update event to frontend if let Err(e) = events::emit("profile-updated", &updated_profile) { - log::warn!("Warning: Failed to emit profile update event: {e}"); + log::warn!("Event emit failed event=profile-updated err=\"{e}\""); } // Emit minimal running changed event to frontend @@ -823,13 +855,7 @@ impl BrowserRunner { }; if let Err(e) = events::emit("profile-running-changed", &payload) { - log::warn!("Warning: Failed to emit profile running changed event: {e}"); - } else { - log::info!( - "Successfully emitted profile-running-changed event for Wayfern {}: running={}", - updated_profile.name, - payload.is_running - ); + log::warn!("Event emit failed event=profile-running-changed err=\"{e}\""); } return Ok(updated_profile); @@ -859,12 +885,6 @@ impl BrowserRunner { .await { Some(_wayfern_process) => { - log::info!( - "Opening URL in existing Wayfern process for profile: {} (ID: {})", - profile.name, - profile.id - ); - // Use CDP to open URL in a new tab self .wayfern_manager @@ -914,12 +934,6 @@ impl BrowserRunner { internal_proxy_settings: Option<&ProxySettings>, gate: &crate::launch_gate::FingerprintGate, ) -> Result> { - log::info!( - "launch_or_open_url called for profile: {} (ID: {})", - profile.name, - profile.id - ); - // Get the most up-to-date profile data let profiles = self .profile_manager @@ -930,12 +944,6 @@ impl BrowserRunner { .find(|p| p.id == profile.id) .unwrap_or_else(|| profile.clone()); - log::info!( - "Checking browser status for profile: {} (ID: {})", - updated_profile.name, - updated_profile.id - ); - // Check if browser is already running let is_running = self .check_browser_status(app_handle.clone(), &updated_profile) @@ -952,19 +960,8 @@ impl BrowserRunner { .find(|p| p.id == profile.id) .unwrap_or_else(|| updated_profile.clone()); - log::info!( - "Browser status check: running={is_running}, URL requested={}, PID present={}", - url.is_some(), - final_profile.process_id.is_some() - ); - if is_running { if let Some(url_ref) = url.as_ref() { - log::info!( - "Opening {} in existing browser", - crate::log_redaction::url_label(url_ref) - ); - match self .open_url_in_existing_browser( app_handle.clone(), @@ -975,23 +972,25 @@ impl BrowserRunner { .await { Ok(()) => { - log::info!("Successfully opened URL in existing browser"); + log::debug!( + "Opened URL in running browser profile={} pid={:?} url={}", + final_profile.id, + final_profile.process_id, + crate::log_redaction::url_label(url_ref) + ); Ok(final_profile) } - Err(e) => { - log::info!( - "Failed to open URL in existing browser: {}", - crate::log_redaction::text(&e.to_string()) - ); - Err(e) - } + // The caller logs the failure once, as a launch failure. + Err(e) => Err(e), } } else { - log::info!("Browser is already running and no URL was requested"); + log::debug!( + "Browser already running, nothing to open profile={}", + final_profile.id + ); Ok(final_profile) } } else { - log::info!("Launching new browser instance - browser not running"); self .launch_browser_internal( app_handle.clone(), @@ -1067,11 +1066,6 @@ impl BrowserRunner { return Ok(false); }; - log::info!( - "Stopping remote session {} for profile {} ({profile_id})", - ShortId(&session_id), - profile.name - ); crate::remote_session::end_remote_session(&session_id) .await .map_err(|e| -> Box { @@ -1079,11 +1073,15 @@ impl BrowserRunner { // STILL RUNNING; reporting success would tell the user their profile is // free when a remote host is still writing to it. log::warn!( - "Failed to stop remote session {}: {e}", + "Remote session stop failed profile={profile_id} session={} err=\"{e}\"", ShortId(&session_id) ); e.to_error_json().into() })?; + log::info!( + "Remote session stopped profile={profile_id} session={}", + ShortId(&session_id) + ); // The session is down and its work is in cloud storage. This is what puts // the profile into "pending sync" and starts the pull, so the user is not @@ -1107,30 +1105,18 @@ impl BrowserRunner { crate::ephemeral_dirs::get_effective_profile_path(profile, &profiles_dir); let profile_path_str = profile_data_path.to_string_lossy(); - log::info!( - "Attempting to kill Wayfern process for profile: {} (ID: {})", - profile.name, - profile.id - ); - // Stop the proxy associated with this profile first let profile_id_str = profile.id.to_string(); if let Err(e) = PROXY_MANAGER .stop_proxy_by_profile_id(app_handle.clone(), &profile_id_str) .await { - log::warn!( - "Warning: Failed to stop proxy for profile {}: {e}", - profile_id_str - ); + log::warn!("Proxy worker stop failed profile={profile_id_str} err=\"{e}\""); } if let Err(error) = crate::xray_worker_runner::stop_xray_worker_by_profile_id(&profile_id_str).await { - log::warn!( - "Warning: Failed to stop Xray-core worker for profile {}: {error}", - profile_id_str - ); + log::warn!("Xray worker stop failed profile={profile_id_str} err=\"{error}\""); } let mut process_actually_stopped = false; @@ -1140,12 +1126,6 @@ impl BrowserRunner { .await { Some(wayfern_process) => { - log::info!( - "Found Wayfern process: {} (PID: {:?})", - wayfern_process.id, - wayfern_process.processId - ); - match self.wayfern_manager.stop_wayfern(&wayfern_process.id).await { Ok(_) => { if let Some(pid) = wayfern_process.processId { @@ -1157,17 +1137,10 @@ impl BrowserRunner { let system = System::new_all(); process_actually_stopped = system.process(Pid::from(pid as usize)).is_none(); - if process_actually_stopped { - log::info!( - "Successfully stopped Wayfern process: {} (PID: {:?}) - verified process is dead", - wayfern_process.id, - pid - ); - } else { + if !process_actually_stopped { log::warn!( - "Wayfern stop command returned success but process {} (PID: {:?}) is still running - forcing kill", - wayfern_process.id, - pid + "Browser still running after stop, force killing profile={} pid={pid}", + profile.id ); // Force kill the process #[cfg(target_os = "macos")] @@ -1179,17 +1152,16 @@ impl BrowserRunner { ) .await { - log::error!("Failed to force kill Wayfern process {}: {}", pid, e); + log::error!( + "Browser force kill failed profile={} pid={pid} err=\"{e}\"", + profile.id + ); } else { sleep(Duration::from_millis(500)).await; let system = System::new_all(); process_actually_stopped = system.process(Pid::from(pid as usize)).is_none(); if process_actually_stopped { - log::info!( - "Successfully force killed Wayfern process {} (PID: {:?})", - wayfern_process.id, - pid - ); + log::info!("Browser force killed profile={} pid={pid}", profile.id); } } } @@ -1202,17 +1174,16 @@ impl BrowserRunner { ) .await { - log::error!("Failed to force kill Wayfern process {}: {}", pid, e); + log::error!( + "Browser force kill failed profile={} pid={pid} err=\"{e}\"", + profile.id + ); } else { sleep(Duration::from_millis(500)).await; let system = System::new_all(); process_actually_stopped = system.process(Pid::from(pid as usize)).is_none(); if process_actually_stopped { - log::info!( - "Successfully force killed Wayfern process {} (PID: {:?})", - wayfern_process.id, - pid - ); + log::info!("Browser force killed profile={} pid={pid}", profile.id); } } } @@ -1221,17 +1192,16 @@ impl BrowserRunner { use crate::platform_browser; if let Err(e) = platform_browser::windows::kill_browser_process_impl(pid).await { - log::error!("Failed to force kill Wayfern process {}: {}", pid, e); + log::error!( + "Browser force kill failed profile={} pid={pid} err=\"{e}\"", + profile.id + ); } else { sleep(Duration::from_millis(500)).await; let system = System::new_all(); process_actually_stopped = system.process(Pid::from(pid as usize)).is_none(); if process_actually_stopped { - log::info!( - "Successfully force killed Wayfern process {} (PID: {:?})", - wayfern_process.id, - pid - ); + log::info!("Browser force killed profile={} pid={pid}", profile.id); } } } @@ -1241,17 +1211,13 @@ impl BrowserRunner { } } Err(e) => { - log::error!( - "Error stopping Wayfern process {}: {}", - wayfern_process.id, - e + log::warn!( + "Browser stop failed, force killing profile={} pid={:?} err=\"{e}\"", + profile.id, + wayfern_process.processId ); // Try to force kill if we have a PID if let Some(pid) = wayfern_process.processId { - log::info!( - "Attempting force kill after stop_wayfern error for PID: {}", - pid - ); #[cfg(target_os = "macos")] { use crate::platform_browser; @@ -1259,7 +1225,10 @@ impl BrowserRunner { platform_browser::macos::kill_browser_process_impl(pid, Some(&profile_path_str)) .await { - log::error!("Failed to force kill Wayfern process {}: {}", pid, kill_err); + log::error!( + "Browser force kill failed profile={} pid={pid} err=\"{kill_err}\"", + profile.id + ); } else { use tokio::time::{sleep, Duration}; sleep(Duration::from_millis(500)).await; @@ -1275,7 +1244,10 @@ impl BrowserRunner { platform_browser::linux::kill_browser_process_impl(pid, Some(&profile_path_str)) .await { - log::error!("Failed to force kill Wayfern process {}: {}", pid, kill_err); + log::error!( + "Browser force kill failed profile={} pid={pid} err=\"{kill_err}\"", + profile.id + ); } else { use tokio::time::{sleep, Duration}; sleep(Duration::from_millis(500)).await; @@ -1290,7 +1262,10 @@ impl BrowserRunner { if let Err(kill_err) = platform_browser::windows::kill_browser_process_impl(pid).await { - log::error!("Failed to force kill Wayfern process {}: {}", pid, kill_err); + log::error!( + "Browser force kill failed profile={} pid={pid} err=\"{kill_err}\"", + profile.id + ); } else { use tokio::time::{sleep, Duration}; sleep(Duration::from_millis(500)).await; @@ -1304,21 +1279,17 @@ impl BrowserRunner { } } None => { - log::info!( - "No running Wayfern process found for profile: {} (ID: {})", - profile.name, - profile.id - ); + log::debug!("No running browser to stop profile={}", profile.id); process_actually_stopped = true; } } // If process wasn't confirmed stopped, return an error if !process_actually_stopped { - log::error!( - "Failed to stop Wayfern process for profile: {} (ID: {}) - process may still be running", - profile.name, - profile.id + log::warn!( + "Browser stop failed, process still alive profile={} pid={:?}", + profile.id, + profile.process_id ); return Err( format!( @@ -1343,13 +1314,6 @@ impl BrowserRunner { .auto_updater .get_pending_update(&profile.browser, &profile.version) { - log::info!( - "Found pending update for Wayfern profile {}: {} -> {}", - profile.name, - profile.version, - pending_update.new_version - ); - match self.profile_manager.update_profile_version( &app_handle, &profile.id.to_string(), @@ -1357,8 +1321,8 @@ impl BrowserRunner { ) { Ok(updated_profile_after_update) => { log::info!( - "Successfully updated Wayfern profile {} from version {} to {}", - profile.name, + "Pending browser update applied profile={} from={} to={}", + profile.id, profile.version, pending_update.new_version ); @@ -1368,14 +1332,14 @@ impl BrowserRunner { .auto_updater .dismiss_update_notification(&pending_update.id) { - log::warn!("Warning: Failed to dismiss pending update notification: {e}"); + log::warn!("Update notification dismiss failed err=\"{e}\""); } } Err(e) => { - log::error!( - "Failed to apply pending update for Wayfern profile {}: {}", - profile.name, - e + log::warn!( + "Pending browser update failed profile={} to={} err=\"{e}\"", + profile.id, + pending_update.new_version ); } } @@ -1392,14 +1356,9 @@ impl BrowserRunner { } crate::wayfern_identity_storage::request_conversion_pass(); - log::info!( - "Emitting profile events for successful Wayfern kill: {}", - updated_profile.name - ); - // Emit profile update event to frontend if let Err(e) = events::emit("profile-updated", &updated_profile) { - log::warn!("Warning: Failed to emit profile update event: {e}"); + log::warn!("Event emit failed event=profile-updated err=\"{e}\""); } // Emit minimal running changed event @@ -1414,13 +1373,7 @@ impl BrowserRunner { }; if let Err(e) = events::emit("profile-running-changed", &payload) { - log::warn!("Warning: Failed to emit profile running changed event: {e}"); - } else { - log::info!( - "Successfully emitted profile-running-changed event for Wayfern {}: running={}", - updated_profile.name, - payload.is_running - ); + log::warn!("Event emit failed event=profile-running-changed err=\"{e}\""); } if profile.password_protected { @@ -1456,32 +1409,18 @@ impl BrowserRunner { .profile_manager .delete_profile_permanently(&app_handle, &profile.id.to_string()) { - Ok(()) => log::info!( - "Deleted temporary profile {} now that its browser has stopped", - profile.name + Ok(()) => log::info!("Deleted temporary profile profile={}", profile.id), + Err(e) => log::warn!( + "Temporary profile delete failed profile={} err=\"{e}\"", + profile.id ), - Err(e) => log::warn!("Could not delete temporary profile {}: {e}", profile.name), } } - log::info!( - "Wayfern process cleanup completed for profile: {} (ID: {})", - profile.name, - profile.id - ); - // Consolidate browser versions after stopping a browser - if let Ok(consolidated) = self + let _ = self .downloaded_browsers_registry - .consolidate_browser_versions(&app_handle) - { - if !consolidated.is_empty() { - log::info!("Post-stop version consolidation results:"); - for action in &consolidated { - log::info!(" {action}"); - } - } - } + .consolidate_browser_versions(&app_handle); return Ok(()); } @@ -1525,11 +1464,19 @@ impl BrowserRunner { if profile.process_id.is_none() { if let Ok(target) = crate::cdp_target::resolve(&profile).await { if target.is_remote() { - log::info!("Opening URL through {}", target.describe()); + log::debug!( + "Opening URL through {} profile={}", + target.describe(), + profile.id + ); return crate::cdp_target::navigate(&target, &url, REMOTE_NAVIGATE_TIMEOUT_SECS) .await .map_err(|e| { - log::warn!("Failed to open a URL on the remote browser: {e}"); + log::warn!( + "Opening URL on remote browser failed profile={} err=\"{}\"", + profile.id, + crate::log_redaction::text(&e.to_string()) + ); format!("Failed to open URL with profile: {e}") }); } @@ -1551,18 +1498,14 @@ impl BrowserRunner { // to a local launch on a profile a host was writing to. crate::remote_handoff::ensure_local_launch_allowed(&profile.id.to_string())?; let acquired_team_lock = crate::team_lock::acquire_team_lock_if_needed(&profile).await?; - - log::info!("Opening URL with selected profile"); + let started = std::time::Instant::now(); // Use launch_or_open_url which handles both launching new instances and opening in existing ones if let Err(e) = self .launch_or_open_url(app_handle, &profile, Some(url.clone()), None, &gate) .await { - log::info!( - "Failed to open URL with selected profile: {}", - crate::log_redaction::text(&e.to_string()) - ); + log_launch_failure(&profile, &e.to_string(), started); // This path takes the team lock too, and a blocked launch never records a // process_id for the status sweep to release it from. unwind_launch(&profile, acquired_team_lock).await; @@ -1575,7 +1518,6 @@ impl BrowserRunner { )); } - log::info!("Successfully opened URL with selected profile"); Ok(()) } } @@ -1645,8 +1587,8 @@ impl LaunchOptions { async fn unwind_launch(profile: &BrowserProfile, acquired_team_lock: bool) { if browser_is_running_for(&profile.id.to_string()) { log::debug!( - "Not unwinding launch state for {}: a browser is still running for it", - profile.name + "Launch state kept, a browser is still running profile={}", + profile.id ); return; } @@ -1689,15 +1631,19 @@ pub async fn launch_browser_profile_impl( options: LaunchOptions, ) -> Result { let _profile_launch_guard = lock_profile_launch(&profile.id.to_string()).await; + let started = std::time::Instant::now(); emit_launch_stage(&profile, "queued", None); let result = launch_browser_profile_tracked(app_handle, profile.clone(), url, options).await; match &result { Ok(_) => emit_launch_stage(&profile, "running", None), - Err(error) => emit_launch_stage( - &profile, - "failed", - Some(&crate::wrap_backend_error(error, "Browser launch failed")), - ), + Err(error) => { + log_launch_failure(&profile, error, started); + emit_launch_stage( + &profile, + "failed", + Some(&crate::wrap_backend_error(error, "Browser launch failed")), + ) + } } result } @@ -1714,11 +1660,6 @@ async fn launch_browser_profile_tracked( force_new, gate, } = options; - log::info!( - "Launch request received for profile: {} (ID: {})", - profile.name, - profile.id - ); emit_launch_stage(&profile, "preparing", None); if profile.is_cross_os() { @@ -1765,18 +1706,6 @@ async fn launch_browser_profile_tracked( } }; - log::info!( - "Resolved profile for launch: {} (ID: {})", - profile_for_launch.name, - profile_for_launch.id - ); - - log::info!( - "Starting browser launch for profile: {} (ID: {})", - profile_for_launch.name, - profile_for_launch.id - ); - if force_new { let already_running = match browser_runner .check_browser_status(app_handle.clone(), &profile_for_launch) @@ -1823,12 +1752,6 @@ async fn launch_browser_profile_tracked( let updated_profile = match launch_result { Ok(updated) => updated, Err(e) => { - log::info!( - "Browser launch failed for profile: {}, error: {}", - profile_for_launch.name, - e - ); - // Emit a failure event to clear loading states in the frontend #[derive(serde::Serialize)] struct RunningChangedPayload { @@ -1841,7 +1764,7 @@ async fn launch_browser_profile_tracked( }; if let Err(e) = events::emit("profile-running-changed", &payload) { - log::warn!("Warning: Failed to emit profile running changed event: {e}"); + log::warn!("Event emit failed event=profile-running-changed err=\"{e}\""); } unwind_launch(&profile, acquired_team_lock).await; @@ -1861,12 +1784,6 @@ async fn launch_browser_profile_tracked( } }; - log::info!( - "Browser launch completed for profile: {} (ID: {})", - updated_profile.name, - updated_profile.id - ); - // The proxy PID mapping was already reconciled inside launch_browser_internal // (placeholder → real browser PID); nothing is ever keyed by a constant here. @@ -1887,11 +1804,6 @@ pub async fn kill_browser_profile( app_handle: tauri::AppHandle, profile: BrowserProfile, ) -> Result<(), String> { - log::info!( - "Kill request received for profile: {} (ID: {})", - profile.name, - profile.id - ); let browser_runner = BrowserRunner::instance(); match browser_runner @@ -1899,12 +1811,6 @@ pub async fn kill_browser_profile( .await { Ok(()) => { - log::info!( - "Successfully killed browser profile: {} (ID: {})", - profile.name, - profile.id - ); - // Release team lock if applicable crate::team_lock::release_team_lock_if_needed(&profile).await; @@ -1937,34 +1843,31 @@ pub async fn kill_browser_profile( Ok(updated) => { if !updated.is_empty() { log::info!( - "Auto-updated {} profiles after stop: {:?}", - updated.len(), - updated + "Profiles moved to latest browser after stop count={} browser={browser_for_update} version={latest_version}", + updated.len() ); } } Err(e) => { - log::error!("Failed to auto-update profile versions after stop: {e}"); + log::warn!("Profile browser update after stop failed err=\"{e}\""); } } } - match registry.cleanup_unused_binaries() { - Ok(cleaned) => { - if !cleaned.is_empty() { - log::info!("Cleaned up unused binaries after stop: {:?}", cleaned); - } - } - Err(e) => { - log::error!("Failed to cleanup unused binaries after stop: {e}"); - } + if let Err(e) = registry.cleanup_unused_binaries() { + log::warn!("Unused browser cleanup after stop failed err=\"{e}\""); } }); Ok(()) } Err(e) => { - log::info!("Failed to kill browser profile {}: {}", profile.name, e); + log::error!( + "Browser stop failed profile={} pid={:?} err=\"{}\"", + profile.id, + profile.process_id, + log_err(&e.to_string(), &profile) + ); // Emit a failure event to clear loading states in the frontend #[derive(serde::Serialize)] @@ -1979,7 +1882,7 @@ pub async fn kill_browser_profile( }; if let Err(e) = events::emit("profile-running-changed", &payload) { - log::warn!("Warning: Failed to emit profile running changed event: {e}"); + log::warn!("Event emit failed event=profile-running-changed err=\"{e}\""); } Err(format!("Failed to kill browser: {e}")) diff --git a/src-tauri/src/browser_version_manager.rs b/src-tauri/src/browser_version_manager.rs index 3cd21113..b0f2d986 100644 --- a/src-tauri/src/browser_version_manager.rs +++ b/src-tauri/src/browser_version_manager.rs @@ -204,7 +204,7 @@ impl BrowserVersionManager { .api_client .save_cached_versions(browser, &merged_releases) { - log::error!("Failed to save merged cache for {browser}: {e}"); + log::warn!("Browser version cache save failed browser={browser} err=\"{e}\""); } } @@ -282,7 +282,7 @@ impl BrowserVersionManager { }) .collect(); if let Err(e) = self.api_client.save_cached_versions(browser, &releases) { - log::error!("Failed to save updated cache for {browser}: {e}"); + log::warn!("Browser version cache save failed browser={browser} err=\"{e}\""); } Ok(new_versions_count) @@ -486,11 +486,15 @@ pub async fn fetch_browser_versions_cached_first( let service_clone = BrowserVersionManager::instance(); let browser_str_clone = browser_str.clone(); tokio::spawn(async move { - if let Err(e) = service_clone + match service_clone .fetch_browser_versions_detailed(&browser_str_clone, false) .await { - log::error!("Background version update failed for {browser_str_clone}: {e}"); + Ok(_) => BACKGROUND_UPDATE.succeeded(), + Err(e) => BACKGROUND_UPDATE.failed(format_args!( + "browser={browser_str_clone} {}", + crate::log_redaction::text(&e.to_string()) + )), } }); } @@ -518,11 +522,15 @@ pub async fn fetch_browser_versions_with_count_cached_first( let service_clone = BrowserVersionManager::instance(); let browser_str_clone = browser_str.clone(); tokio::spawn(async move { - if let Err(e) = service_clone + match service_clone .fetch_browser_versions_with_count(&browser_str_clone, false) .await { - log::error!("Background version update failed for {browser_str_clone}: {e}"); + Ok(_) => BACKGROUND_UPDATE.succeeded(), + Err(e) => BACKGROUND_UPDATE.failed(format_args!( + "browser={browser_str_clone} {}", + crate::log_redaction::text(&e.to_string()) + )), } }); } @@ -554,5 +562,8 @@ pub async fn fetch_browser_versions_with_count( } // Global singleton instance +static BACKGROUND_UPDATE: crate::log_streak::Streak = + crate::log_streak::Streak::new(module_path!(), "Background browser version update"); + static BROWSER_VERSION_SERVICE: std::sync::LazyLock = std::sync::LazyLock::new(BrowserVersionManager::new); diff --git a/src-tauri/src/cdp_target.rs b/src-tauri/src/cdp_target.rs index 347cbb2c..e4ca43c2 100644 --- a/src-tauri/src/cdp_target.rs +++ b/src-tauri/src/cdp_target.rs @@ -210,9 +210,9 @@ pub async fn resolve(profile: &BrowserProfile) -> Result Opti } if patience == Patience::WaitForLaunch { - log::warn!("Local CDP discovery on port {port} gave up: {last_err}"); + log::warn!("Local CDP discovery gave up cdp_port={port} err=\"{last_err}\""); } None } @@ -696,8 +696,8 @@ impl CdpTarget { return Err(error); } let delay = CONNECT_RETRY_BASE * 2u32.pow(attempt - 1); - log::warn!( - "CDP connect to {} failed ({error}); retrying in {}ms", + log::debug!( + "CDP connect failed target=\"{}\" attempt={attempt} retry_in_ms={} err=\"{error}\"", self.describe(), delay.as_millis() ); @@ -722,7 +722,7 @@ impl CdpTarget { let mut connection = dial_relay(ws_url, bearer).await?; if let Err(e) = connection.attach_to_page().await { log::warn!( - "Could not attach to a page in remote session {}: {e}", + "Remote session page attach failed session={} err=\"{e}\"", ShortId(session_id) ); return Err(e); @@ -763,7 +763,7 @@ pub async fn open_relay_socket(session_id: &str) -> Result return Err(e), }; - log::info!("The CDP relay refused the stored access token; refreshing and retrying once"); + log::debug!("CDP relay refused the access token, refreshing it once"); crate::cloud_auth::CLOUD_AUTH .refresh_access_token() .await @@ -824,7 +824,7 @@ async fn dial_relay(ws_url: &str, bearer: &str) -> Result return Err(e), }; - log::info!("The CDP relay refused the stored access token; refreshing and retrying once"); + log::debug!("CDP relay refused the access token, refreshing it once"); crate::cloud_auth::CLOUD_AUTH .refresh_access_token() .await diff --git a/src-tauri/src/cloud_auth.rs b/src-tauri/src/cloud_auth.rs index 3c789a92..afbacd1f 100644 --- a/src-tauri/src/cloud_auth.rs +++ b/src-tauri/src/cloud_auth.rs @@ -8,6 +8,7 @@ use std::time::{Duration, Instant}; use tokio::sync::Mutex; use crate::browser::ProxySettings; +use crate::log_streak::Streak; use crate::proxy_manager::PROXY_MANAGER; use crate::settings_manager::{SettingsManager, StoredMcpRemoteKey}; use crate::sync; @@ -24,6 +25,28 @@ const SYNC_TOKEN_REFRESH_MARGIN_SECS: i64 = 120; const DEFAULT_RETRY_AFTER: Duration = Duration::from_secs(60); const MAX_RETRY_AFTER: Duration = Duration::from_secs(60 * 60); +static ACCESS_TOKEN_REFRESH: Streak = Streak::new(module_path!(), "Access token refresh"); +static SYNC_TOKEN_FETCH: Streak = Streak::new(module_path!(), "Sync token fetch"); +static PROFILE_REFRESH: Streak = Streak::new(module_path!(), "Cloud profile refresh"); +static PROXY_CONFIG_FETCH: Streak = Streak::new(module_path!(), "Cloud proxy config fetch"); +static PROXY_USAGE_FETCH: Streak = Streak::new(module_path!(), "Cloud proxy usage fetch"); +static WAYFERN_TOKEN: Streak = Streak::new(module_path!(), "Wayfern token request"); + +/// What the last cloud proxy sync found, so an unchanged result is not +/// logged every ten minutes. +static CLOUD_PROXY_STATE: std::sync::Mutex> = std::sync::Mutex::new(None); + +fn cloud_proxy_state_changed(state: String) -> bool { + let mut last = CLOUD_PROXY_STATE + .lock() + .unwrap_or_else(std::sync::PoisonError::into_inner); + if last.as_deref() == Some(state.as_str()) { + return false; + } + *last = Some(state); + true +} + pub(crate) fn parse_retry_after(value: &str, now: chrono::DateTime) -> Option { let value = value.trim(); if let Ok(seconds) = value.parse::() { @@ -618,34 +641,24 @@ impl CloudAuthManager { .map_err(|e| format!("Failed to parse response: {e}"))?; // Store tokens - log::info!( - "Storing access token (len={}) and refresh token (len={})", - result.access_token.len(), - result.refresh_token.len() - ); Self::store_access_token(&result.access_token)?; Self::store_refresh_token(&result.refresh_token)?; // Verify tokens survived the encrypt/decrypt round-trip match Self::load_access_token() { - Ok(Some(loaded)) if loaded == result.access_token => { - log::info!( - "Access token verified after store/load (len={})", - loaded.len() - ); - } + Ok(Some(loaded)) if loaded == result.access_token => {} Ok(Some(loaded)) => { log::error!( - "Access token CORRUPTED during store/load: original_len={}, loaded_len={}", + "Access token corrupted by store and load stored_len={} loaded_len={}", result.access_token.len(), loaded.len() ); } Ok(None) => { - log::error!("Access token missing immediately after store"); + log::error!("Access token missing right after store"); } Err(e) => { - log::error!("Failed to load access token for verification: {e}"); + log::error!("Access token not readable after store err=\"{e}\""); } } @@ -657,7 +670,7 @@ impl CloudAuthManager { Self::store_auth_state(&auth_state)?; log::info!( - "Login successful: plan={}, subscription_status={}, proxy_bandwidth_limit={}MB", + "Signed in plan={} subscription_status={} proxy_bandwidth_limit_mb={}", auth_state.user.plan, auth_state.user.subscription_status, auth_state.user.proxy_bandwidth_limit_mb @@ -682,8 +695,6 @@ impl CloudAuthManager { wait.as_secs() )); } - log::info!("Refreshing access token (holding lock)..."); - let refresh_token = Self::load_refresh_token()?.ok_or_else(|| "No refresh token stored".to_string())?; @@ -698,7 +709,7 @@ impl CloudAuthManager { if !response.status().is_success() { let status = response.status(); - log::warn!("Token refresh failed ({status})"); + log::debug!("Access token refresh refused status={status}"); if status == reqwest::StatusCode::TOO_MANY_REQUESTS { self.defer_refresh(retry_after(response.headers())); } else if status == reqwest::StatusCode::UNAUTHORIZED { @@ -718,7 +729,7 @@ impl CloudAuthManager { Self::store_access_token(&result.access_token)?; Self::store_refresh_token(&result.refresh_token)?; - log::info!("Access token refreshed successfully"); + log::debug!("Access token refreshed"); Ok(()) } @@ -767,7 +778,7 @@ impl CloudAuthManager { Ok(fresh) => Ok(fresh), Err(e) if e.contains("(401") => Err(e), Err(e) => { - log::debug!("Early access token refresh did not complete: {e}"); + log::debug!("Early access token refresh not done err=\"{e}\""); Ok(token) } } @@ -777,7 +788,7 @@ impl CloudAuthManager { let _guard = self.refresh_lock.lock().await; if let Some(current) = Self::load_access_token()? { if current != rejected && !current.is_empty() { - log::info!("Token was already refreshed by another caller, retrying..."); + log::debug!("Access token already refreshed by another caller"); return Ok(current); } } @@ -822,7 +833,7 @@ impl CloudAuthManager { /// Only call this when the session is definitively dead (explicit logout /// or repeated background refresh failures). pub async fn invalidate_session(&self) { - log::warn!("Invalidating session — clearing all auth state"); + log::warn!("Session invalidated, auth state cleared"); PROXY_MANAGER.remove_cloud_proxy(); // Same reason `logout` does it: left running, the bridge reconnects with a // credential that no longer exists, fails, and backs off into an @@ -1001,18 +1012,16 @@ impl CloudAuthManager { Ok(Some(StoredMcpRemoteKey { id: Some(id), .. })) => { if let Err(e) = self.revoke_mcp_key(&id).await { log::warn!( - "Could not revoke the remote MCP credential on logout; revoke it from the account page: {e}" + "Remote MCP key not revoked on logout, revoke it on the account page err=\"{e}\"" ); } } Ok(Some(StoredMcpRemoteKey { id: None, .. })) => { - log::warn!( - "The remote MCP credential has no stored id, so it cannot be revoked from here; revoke it from the account page" - ); + log::warn!("Remote MCP key has no stored id, revoke it on the account page"); } Ok(None) => return, Err(e) => { - log::warn!("Could not read the remote MCP credential on logout: {e}"); + log::warn!("Remote MCP key not readable on logout err=\"{e}\""); } } Self::forget_mcp_key_locally("on logout"); @@ -1024,7 +1033,7 @@ impl CloudAuthManager { /// credential is leaving with the session either way. fn forget_mcp_key_locally(when: &str) { if let Err(e) = SettingsManager::instance().remove_mcp_remote_key() { - log::warn!("Could not forget the remote MCP credential {when}: {e}"); + log::warn!("Remote MCP key not removed locally when=\"{when}\" err=\"{e}\""); } } @@ -1078,7 +1087,7 @@ impl CloudAuthManager { } // Fetch new sync token - let sync_token = self + let fetched = self .api_call_with_retry(|access_token| { let url = format!("{CLOUD_API_URL}/api/auth/sync-token"); let client = self.client.clone(); @@ -1104,9 +1113,22 @@ impl CloudAuthManager { Ok(result.sync_token) } }) - .await?; + .await; + let sync_token = match fetched { + Ok(token) => { + SYNC_TOKEN_FETCH.succeeded(); + token + } + Err(e) => { + SYNC_TOKEN_FETCH.failed(&e); + return Err(e); + } + }; - Self::store_cloud_sync_token(&sync_token)?; + if let Err(e) = Self::store_cloud_sync_token(&sync_token) { + log::error!("Sync token store failed err=\"{e}\""); + return Err(e); + } Ok(Some(sync_token)) } @@ -1338,17 +1360,15 @@ impl CloudAuthManager { match make_request(access_token.clone()).await { Ok(result) => Ok(result), Err(e) if e.contains("(401") || e.contains("Unauthorized") => { - log::info!("Got 401/Unauthorized response, attempting token refresh..."); + log::debug!("Cloud API returned 401, refreshing the access token"); // Check if another caller already refreshed while we waited let current_token = Self::load_access_token()?.unwrap_or_default(); if current_token != access_token && !current_token.is_empty() { - log::info!("Token was already refreshed by another caller, retrying..."); return make_request(current_token).await; } let new_token = self.refresh_after_rejection(&access_token).await?; - log::info!("Token refreshed, retrying request..."); make_request(new_token).await } Err(e) => Err(e), @@ -1381,7 +1401,6 @@ impl CloudAuthManager { let status = response.status(); if status == reqwest::StatusCode::FORBIDDEN { - log::warn!("Proxy config returned 403"); return Err("__403__".to_string()); } @@ -1397,10 +1416,16 @@ impl CloudAuthManager { }) .await { - Ok(config) => Ok(Some(config)), - Err(e) if e.contains("__403__") => Ok(None), + Ok(config) => { + PROXY_CONFIG_FETCH.succeeded(); + Ok(Some(config)) + } + Err(e) if e.contains("__403__") => { + PROXY_CONFIG_FETCH.succeeded(); + Ok(None) + } Err(e) => { - log::warn!("Failed to fetch cloud proxy config: {e}"); + PROXY_CONFIG_FETCH.failed(e); Ok(None) } } @@ -1408,15 +1433,15 @@ impl CloudAuthManager { /// Sync the cloud-managed proxy: fetch config and upsert or remove pub async fn sync_cloud_proxy(&self) { - log::info!("Syncing cloud proxy configuration..."); match self.fetch_proxy_config().await { Ok(Some(config)) => { - log::info!( - "Cloud proxy config received: host={}, port={}, protocol={}", - config.host, - config.port, - config.protocol + let state = format!( + "host={} port={} protocol={}", + config.host, config.port, config.protocol ); + if cloud_proxy_state_changed(state.clone()) { + log::info!("Cloud proxy configured {state}"); + } let settings = ProxySettings { proxy_type: config.protocol, host: config.host, @@ -1427,19 +1452,20 @@ impl CloudAuthManager { }; match PROXY_MANAGER.upsert_cloud_proxy(settings) { Ok(_) => { - log::info!("Cloud proxy synced successfully"); // Propagate credential changes to derived location proxies PROXY_MANAGER.update_cloud_derived_proxies(); } - Err(e) => log::warn!("Failed to upsert cloud proxy: {e}"), + Err(e) => log::warn!("Cloud proxy not saved err=\"{e}\""), } } Ok(None) => { - log::info!("No cloud proxy config available (user may not have proxy bandwidth)"); + if cloud_proxy_state_changed("none".to_string()) { + log::info!("Cloud proxy removed: no config available"); + } PROXY_MANAGER.remove_cloud_proxy(); } Err(e) => { - log::error!("Failed to sync cloud proxy: {e}"); + log::error!("Cloud proxy sync failed err=\"{e}\""); } } } @@ -1511,7 +1537,7 @@ impl CloudAuthManager { if !self.is_entitled_to_wayfern_token().await { // Ok(()) here means callers log nothing, so a session that declined to // mint left no trace at all and looked identical to one that succeeded. - log::info!("Skipping wayfern token request: the cached plan is not active"); + log::info!("Wayfern token not requested: plan not active"); self.clear_wayfern_token().await; return Ok(()); } @@ -1561,10 +1587,10 @@ impl CloudAuthManager { // A 403 rejects the entitlement without invalidating the login session. // Clear the browser token and refresh account state before notifying UI. if e.contains("(403") || e.contains("Forbidden") { - log::warn!("Wayfern token blocked by backend (403): {e}"); + WAYFERN_TOKEN.failed(format!("refused: {}", refusal_message(&e))); self.clear_wayfern_token().await; if let Err(fetch_err) = self.fetch_profile().await { - log::warn!("Profile re-fetch after wayfern block failed: {fetch_err}"); + PROFILE_REFRESH.failed(fetch_err); } // Only the device rules produce a restriction the user can lift, and // the toast tells them to sign other devices out — so only those may @@ -1577,6 +1603,8 @@ impl CloudAuthManager { self.set_wayfern_device_refusal(Some(refusal_message(&e))); let _ = crate::events::emit_empty("wayfern-paid-blocked"); } + } else { + WAYFERN_TOKEN.failed(&e); } return Err(e); } @@ -1585,6 +1613,7 @@ impl CloudAuthManager { let mut wt = self.wayfern_token.lock().await; *wt = Some(token); self.set_wayfern_device_refusal(None); + WAYFERN_TOKEN.succeeded(); log::info!("Wayfern token acquired"); Ok(()) } @@ -1641,33 +1670,30 @@ impl CloudAuthManager { // This runs first so subsequent API calls use a fresh token. if let Ok(Some(token)) = Self::load_access_token() { if Self::access_token_needs_refresh(&token) { - if let Err(e) = CLOUD_AUTH.ensure_fresh_access_token().await { - log::warn!("Failed to refresh cloud access token: {e}"); - // If the refresh token itself was rejected, session is irrecoverable - if e.contains("(401") || e.contains("Unauthorized") { - continue; + match CLOUD_AUTH.ensure_fresh_access_token().await { + Ok(_) => ACCESS_TOKEN_REFRESH.succeeded(), + Err(e) => { + ACCESS_TOKEN_REFRESH.failed(&e); + // If the refresh token itself was rejected, session is irrecoverable + if e.contains("(401") || e.contains("Unauthorized") { + continue; + } } } } } - match CLOUD_AUTH.get_or_refresh_sync_token().await { - Ok(Some(_)) => { - log::debug!("Cloud sync token refreshed successfully"); - } - Ok(None) => {} - Err(e) => { - log::warn!("Failed to refresh cloud sync token: {e}"); - } - } + // Failures are logged inside. + let _ = CLOUD_AUTH.get_or_refresh_sync_token().await; let plan_before = CLOUD_AUTH.plan_marker().await; // Refresh profile data periodically. A failure here leaves the cached // plan stale, which silently gates paid features, so it belongs at warn // rather than debug where the shipped log level hides it. - if let Err(e) = CLOUD_AUTH.fetch_profile().await { - log::warn!("Failed to refresh cloud profile: {e}"); + match CLOUD_AUTH.fetch_profile().await { + Ok(_) => PROFILE_REFRESH.succeeded(), + Err(e) => PROFILE_REFRESH.failed(e), } if CLOUD_AUTH.plan_marker().await != plan_before { @@ -1705,9 +1731,7 @@ impl CloudAuthManager { && CLOUD_AUTH.get_wayfern_token().await.is_none(); if wayfern_refresh_counter >= 60 || missing_entitled_token { wayfern_refresh_counter = 0; - if let Err(e) = CLOUD_AUTH.request_wayfern_token().await { - log::warn!("Failed to refresh wayfern token: {e}"); - } + let _ = CLOUD_AUTH.request_wayfern_token().await; } let _ = &app_handle; // keep app_handle alive @@ -1794,12 +1818,12 @@ pub async fn cloud_exchange_device_code( // effort: a failure leaves the login response in place. match CLOUD_AUTH.fetch_profile().await { Ok(user) => state.user = user, - Err(e) => log::warn!("Post-login profile refresh failed: {e}"), + Err(e) => log::warn!("Post-login profile refresh failed err=\"{e}\""), } let has_subscription = CLOUD_AUTH.has_active_paid_subscription().await; log::info!( - "Post-login: plan={}, effective_plan={}, has_active_subscription={}", + "Post-login plan resolved plan={} effective_plan={} has_active_subscription={}", state.user.plan, state.user.effective_plan(), has_subscription @@ -1807,17 +1831,13 @@ pub async fn cloud_exchange_device_code( // Pre-fetch sync token so sync can start immediately if has_subscription { - log::info!("Pre-fetching sync token..."); - match CLOUD_AUTH.get_or_refresh_sync_token().await { - Ok(Some(_)) => log::info!("Sync token pre-fetched successfully"), - Ok(None) => log::warn!("Sync token not available despite active subscription"), - Err(e) => log::error!("Failed to pre-fetch sync token after login: {e}"), + // Failures of both are logged inside. + if let Ok(None) = CLOUD_AUTH.get_or_refresh_sync_token().await { + log::warn!("Sync token missing despite an active subscription"); } // Request wayfern token for paid users - if let Err(e) = CLOUD_AUTH.request_wayfern_token().await { - log::warn!("Failed to request wayfern token after login: {e}"); - } + let _ = CLOUD_AUTH.request_wayfern_token().await; } // Sync cloud proxy after login @@ -1873,9 +1893,7 @@ pub(crate) async fn ensure_remote_bridge(app_handle: &tauri::AppHandle) { .map(|settings| settings.mcp_remote_enabled) .unwrap_or(false); if enabled { - log::info!( - "[mcp-remote] Remote control is enabled and the account is signed in; opening the bridge" - ); + log::info!("Remote control bridge opening: enabled and signed in"); crate::mcp_remote::start(app_handle.clone()); } } @@ -1903,9 +1921,8 @@ pub async fn cloud_refresh_profile() -> Result { if CLOUD_AUTH.is_entitled_to_wayfern_token().await && CLOUD_AUTH.get_wayfern_token().await.is_none() { - if let Err(e) = CLOUD_AUTH.request_wayfern_token().await { - log::warn!("Refresh could not obtain a wayfern token: {e}"); - } + // Failures are logged inside. + let _ = CLOUD_AUTH.request_wayfern_token().await; } Ok(user) @@ -2070,13 +2087,16 @@ pub async fn cloud_get_proxy_usage() -> Result, String> }) .await { - Ok(usage) => Ok(Some(merge_proxy_usage( - &usage, - cached_recurring, - cached_extra, - ))), + Ok(usage) => { + PROXY_USAGE_FETCH.succeeded(); + Ok(Some(merge_proxy_usage( + &usage, + cached_recurring, + cached_extra, + ))) + } Err(e) => { - log::warn!("Failed to fetch live proxy usage, falling back to cached: {e}"); + PROXY_USAGE_FETCH.failed(format!("{e}; using cached usage")); // Fallback to cached values let state = CLOUD_AUTH.state.lock().await; match &*state { diff --git a/src-tauri/src/commercial_license.rs b/src-tauri/src/commercial_license.rs index 19a641b0..ba44d87b 100644 --- a/src-tauri/src/commercial_license.rs +++ b/src-tauri/src/commercial_license.rs @@ -78,11 +78,11 @@ impl CommercialLicenseManager { .save_settings(&settings) .map_err(|e| format!("Failed to save settings: {e}"))?; - log::info!("First launch timestamp recorded: {now}"); + log::info!("First launch recorded at={now}"); // Emit event to notify frontend if let Err(e) = events::emit("first-launch-recorded", now) { - log::warn!("Failed to emit first-launch-recorded event: {e}"); + log::warn!("Event not emitted event=first-launch-recorded err=\"{e}\""); } Ok(now) diff --git a/src-tauri/src/cookie_bot.rs b/src-tauri/src/cookie_bot.rs index 1e010cc1..9a2fc043 100644 --- a/src-tauri/src/cookie_bot.rs +++ b/src-tauri/src/cookie_bot.rs @@ -950,20 +950,23 @@ async fn send_profile_state(profile_id: String, state: ProfileState, identity: P if crate::cloud_auth::CLOUD_AUTH.is_logged_in().await { match update_profile_state(&profile_id, state, &identity).await { Ok(_) => { + STATE_REPORT.succeeded(&format!("profile={profile_id}")); record_enrolment(&mut enrolled_profiles(), &profile_id, true); - log::debug!("Re-declared cookie-bot profile state for {profile_id}"); + log::debug!("Cookie bot profile state re-declared profile={profile_id}"); } // Not enrolled is the common answer and not worth a log line at warn. Err(e) if e.code() == "COOKIE_BOT_NOT_ENROLLED" => { + STATE_REPORT.succeeded(&format!("profile={profile_id}")); record_enrolment(&mut enrolled_profiles(), &profile_id, false); } - Err(e) => { - log::warn!("Could not re-declare cookie-bot profile state for {profile_id}: {e}"); - } + Err(e) => STATE_REPORT.failed(&format!("profile={profile_id}"), e), } } } +static STATE_REPORT: crate::log_streak::KeyedStreak = + crate::log_streak::KeyedStreak::new(module_path!(), "Cookie bot profile state report"); + pub fn report_profiles_using_proxy(proxy_id: &str) { report_matching(|profile| profile.proxy_id.as_deref() == Some(proxy_id)); } @@ -989,7 +992,7 @@ pub async fn report_enrolled_profiles() { let list = match list_schedules(None).await { Ok(list) => list, Err(e) => { - log::debug!("Could not list cookie-bot schedules at startup: {e}"); + log::debug!("Cookie bot schedules not listed at startup err=\"{e}\""); return; } }; @@ -1361,7 +1364,7 @@ pub async fn delete_user_template(id: &str) -> Result { /// in a Japanese UI is the failure the `{"code":…}` convention exists to stop. fn command_error(context: &str, err: CookieBotError) -> String { log::warn!( - "Cookie bot {context} failed: {} (HTTP {})", + "Cookie bot request failed action=\"{context}\" code={} status={}", err.code(), err.status() ); diff --git a/src-tauri/src/default_browser.rs b/src-tauri/src/default_browser.rs index 2b140af2..d56307c1 100644 --- a/src-tauri/src/default_browser.rs +++ b/src-tauri/src/default_browser.rs @@ -301,9 +301,9 @@ mod windows { /// alone. fn remove_legacy_registration(root: &RegKey) { match root.delete_subkey_all(LEGACY_APP_KEY) { - Ok(()) => log::debug!("Removed the superseded default-browser registration key"), + Ok(()) => log::debug!("Superseded default-browser registry key removed"), Err(e) if e.kind() == std::io::ErrorKind::NotFound => {} - Err(e) => log::debug!("Could not remove the superseded registration key: {e}"), + Err(e) => log::debug!("Superseded default-browser registry key removal failed err=\"{e}\""), } for extension in [".htm", ".html"] { @@ -319,8 +319,10 @@ mod windows { if ours { match key.delete_value("") { - Ok(()) => log::debug!("Released the {extension} association taken by an older build"), - Err(e) => log::debug!("Could not release the {extension} association: {e}"), + Ok(()) => log::debug!("Older build's file association released extension={extension}"), + Err(e) => log::debug!( + "Older build's file association release failed extension={extension} err=\"{e}\"" + ), } } } diff --git a/src-tauri/src/dns_blocklist.rs b/src-tauri/src/dns_blocklist.rs index 5c954510..c8bd0ff8 100644 --- a/src-tauri/src/dns_blocklist.rs +++ b/src-tauri/src/dns_blocklist.rs @@ -346,16 +346,11 @@ impl BlocklistManager { // refused it: the outage this replaced was one CDN answering 403 for a // reason that had nothing to do with the user, and falling back would have // made it invisible. + let started = std::time::Instant::now(); let mut body: Option = None; let mut failures: Vec = Vec::new(); for url in &urls { - log::info!( - "[dns-blocklist] Fetching {} from {}", - level.display_name(), - url - ); - let response = match HTTP_CLIENT.get(url).send().await { Ok(response) => response, Err(e) => { @@ -371,18 +366,6 @@ impl BlocklistManager { match response.text().await { Ok(text) => { - if failures.is_empty() { - log::info!("[dns-blocklist] {} fetched", level.display_name()); - } else { - // Worth saying out loud: the primary source is down and somebody - // should know before the backup goes too. - log::warn!( - "[dns-blocklist] {} came from a fallback source after {} failure(s): {}", - level.display_name(), - failures.len(), - failures.join("; ") - ); - } body = Some(text); break; } @@ -407,10 +390,25 @@ impl BlocklistManager { .lines() .filter(|l| !l.starts_with('#') && !l.trim().is_empty()) .count(); - log::info!( - "[dns-blocklist] Cached {} ({} domains)", - level.display_name(), - entry_count + // A fallback is worth a warning: the primary source is down and somebody + // should know before the backup goes too. + let log_level = if failures.is_empty() { + log::Level::Info + } else { + log::Level::Warn + }; + log::log!( + log_level, + "Blocklist fetched level={} domains={entry_count} source={}/{} elapsed_ms={}{}", + level.as_str(), + failures.len() + 1, + urls.len(), + started.elapsed().as_millis(), + if failures.is_empty() { + String::new() + } else { + format!(" failed_sources=\"{}\"", failures.join("; ")) + } ); Ok(path) @@ -461,22 +459,25 @@ impl BlocklistManager { } else { // Fetch every source concurrently. Sequential awaits make this the sum of // all source latencies, and it runs on the blocking profile-launch path. + // Custom sources are the person's own URLs: the log names them by + // position and host only. let fetches = config.sources.iter().map(|source| async move { match HTTP_CLIENT.get(source).send().await { Ok(resp) if resp.status().is_success() => resp .text() .await - .map_err(|e| format!("custom source {source} body read failed: {e}")), - Ok(resp) => Err(format!( - "custom source {source} returned HTTP {}", - resp.status() - )), - Err(e) => Err(format!("custom source {source} failed: {e}")), + .map_err(|e| format!("body read failed: {}", e.without_url())), + Ok(resp) => Err(format!("status={}", resp.status().as_u16())), + Err(e) => Err(e.without_url().to_string()), } }); let mut source_failures = 0usize; - for result in futures_util::future::join_all(fetches).await { + for (index, result) in futures_util::future::join_all(fetches) + .await + .into_iter() + .enumerate() + { match result { Ok(body) => { for line in body.lines() { @@ -486,7 +487,13 @@ impl BlocklistManager { } } Err(e) => { - log::warn!("[dns-blocklist] {e}"); + let host = config + .sources + .get(index) + .and_then(|source| url::Url::parse(source).ok()) + .and_then(|url| url.host_str().map(str::to_string)) + .unwrap_or_else(|| "-".to_string()); + log::warn!("Custom blocklist source failed source={index} host={host} err=\"{e}\""); source_failures += 1; } } @@ -509,12 +516,12 @@ impl BlocklistManager { } } log::warn!( - "[dns-blocklist] {source_failures} custom source(s) failed; retained {} domain(s) from the cached list", + "Custom blocklist kept cached domains for failed sources failed={source_failures} retained={}", domains.len().saturating_sub(before) ); } Err(_) => log::warn!( - "[dns-blocklist] {source_failures} custom source(s) failed and no cached list exists; custom filtering is incomplete" + "Custom blocklist incomplete: sources failed and no cached list exists failed={source_failures}" ), } } @@ -546,20 +553,21 @@ impl BlocklistManager { .map_err(|e| format!("Failed to rename custom blocklist: {e}"))?; log::info!( - "[dns-blocklist] Compiled custom blocklist ({} domains)", - domains.len() + "Custom blocklist compiled domains={} sources={} allowlist_mode={}", + domains.len(), + config.sources.len(), + config.allowlist_mode ); Ok(path) } pub async fn refresh_all_stale(&self) { + let mut any_failed = false; for &level in BlocklistLevel::all_downloadable() { if !Self::is_cache_fresh(level) { if let Err(e) = Self::fetch_blocklist(level).await { - log::error!( - "[dns-blocklist] Failed to refresh {}: {e}", - level.display_name() - ); + any_failed = true; + REFRESH_STREAK.failed(format!("level={} {e}", level.as_str())); let _ = crate::events::emit( "dns-blocklist-refresh-failed", serde_json::json!({ @@ -570,11 +578,14 @@ impl BlocklistManager { } } } + if !any_failed { + REFRESH_STREAK.succeeded(); + } // Recompile the custom list too so its sources track upstream changes. let config = CustomDnsConfig::load(); if !config.sources.is_empty() || !config.block_domains.is_empty() { if let Err(e) = Self::compile_custom_blocklist().await { - log::error!("[dns-blocklist] Failed to recompile custom list: {e}"); + log::warn!("Custom blocklist recompile failed err=\"{e}\""); } } } @@ -629,6 +640,8 @@ impl BlocklistManager { } static BLOCKLIST_MANAGER: BlocklistManager = BlocklistManager; +static REFRESH_STREAK: crate::log_streak::Streak = + crate::log_streak::Streak::new(module_path!(), "Blocklist refresh"); // Tauri commands diff --git a/src-tauri/src/downloaded_browsers_registry.rs b/src-tauri/src/downloaded_browsers_registry.rs index 86b70972..6f47b1eb 100644 --- a/src-tauri/src/downloaded_browsers_registry.rs +++ b/src-tauri/src/downloaded_browsers_registry.rs @@ -49,6 +49,20 @@ fn is_download_artifact(file_name: &str) -> bool { .any(|suffix| lowered.ends_with(suffix)) } +/// Said once per browser type: every maintenance pass meets the same entries. +fn note_unsupported_browser(browser: &str) { + static SEEN: Mutex> = Mutex::new(Vec::new()); + let mut seen = SEEN.lock().unwrap_or_else(|e| e.into_inner()); + if seen.iter().any(|known| known == browser) { + return; + } + seen.push(browser.to_string()); + log::warn!( + "Unsupported browser type, entries ignored browser={}", + crate::log_redaction::Plain(browser) + ); +} + impl DownloadedBrowsersRegistry { fn new() -> Self { Self { @@ -135,7 +149,7 @@ impl DownloadedBrowsersRegistry { let browser_type = match BrowserType::from_str(browser) { Ok(bt) => bt, Err(_) => { - log::info!("Invalid browser type: {browser}"); + note_unsupported_browser(browser); return false; } }; @@ -147,7 +161,7 @@ impl DownloadedBrowsersRegistry { // If files don't exist but registry thinks they do, clean up the registry if !files_exist { - log::info!("Cleaning up stale registry entry for {browser} {version}"); + log::info!("Removed stale registry entry browser={browser} version={version}"); self.remove_browser(browser, version); let _ = self.save(); // Don't fail if save fails, just log } @@ -167,10 +181,8 @@ impl DownloadedBrowsersRegistry { pub fn mark_download_started(&self, browser: &str, version: &str, file_path: PathBuf) { // Only mark download started, don't add to registry yet // The browser will be added to registry only after verification succeeds - log::info!( - "Marking download started for {}:{} at {}", - browser, - version, + log::debug!( + "Download started browser={browser} version={version} path={}", file_path.display() ); } @@ -188,7 +200,7 @@ impl DownloadedBrowsersRegistry { file_path, }; self.add_browser(info); - log::info!("Browser {browser}:{version} successfully added to registry after verification"); + log::debug!("Registered browser={browser} version={version}"); Ok(()) } @@ -202,7 +214,7 @@ impl DownloadedBrowsersRegistry { // maintenance task land here, and a freshly downloaded version is referenced // by no persisted profile while profile creation is still in flight. if crate::downloader::is_downloading(browser, version) { - log::info!("Skipping cleanup of {browser} {version}: a download is in progress"); + log::debug!("Cleanup skipped, download in progress browser={browser} version={version}"); return Ok(()); } @@ -262,7 +274,7 @@ impl DownloadedBrowsersRegistry { let pending_updates = match self.auto_updater.get_pending_update_versions() { Ok(updates) => updates, Err(e) => { - log::warn!("Warning: Failed to get pending updates for cleanup: {e}"); + log::warn!("Pending update lookup failed, cleanup ignores pending updates err=\"{e}\""); std::collections::HashSet::new() } }; @@ -277,13 +289,13 @@ impl DownloadedBrowsersRegistry { // Don't remove if it's used by any active profile if active_set.contains(&browser_version) { - log::info!("Keeping: {browser} {version} (in use by profile)"); + log::debug!("Keeping browser={browser} version={version} reason=in_use"); continue; } // Don't remove if it's currently running (even if not in active profiles) if running_set.contains(&browser_version) { - log::info!("Keeping: {browser} {version} (currently running)"); + log::debug!("Keeping browser={browser} version={version} reason=running"); continue; } @@ -294,14 +306,14 @@ impl DownloadedBrowsersRegistry { let has_running_profile_for_browser = running_profiles.iter().any(|(b, _)| b == browser); if has_running_profile_for_browser { - log::info!("Keeping: {browser} {version} (pending update for running profile)"); + log::debug!("Keeping browser={browser} version={version} reason=pending_update"); continue; } } // Mark for removal to_remove.push(browser_version); - log::info!("Marking for removal: {browser} {version} (not used by any profile)"); + log::debug!("Unused browser={browser} version={version}"); } } } @@ -344,7 +356,7 @@ impl DownloadedBrowsersRegistry { .get(browser) .is_some_and(|keep| keep == version) { - log::info!("Keeping latest available version: {browser} {version}"); + log::debug!("Keeping browser={browser} version={version} reason=latest"); return false; } true @@ -354,21 +366,24 @@ impl DownloadedBrowsersRegistry { // Remove unused binaries and their version folders for (browser, version) in to_remove { if let Err(e) = self.cleanup_failed_download(&browser, &version) { - log::error!("Failed to cleanup unused binary {browser}:{version}: {e}"); + log::warn!("Unused browser removal failed browser={browser} version={version} err=\"{e}\""); } else { // After removing the binary, also remove the empty version folder if let Err(e) = self.remove_empty_version_folder(&browser, &version) { - log::error!("Failed to remove empty version folder for {browser}:{version}: {e}"); + log::warn!( + "Empty version folder removal failed browser={browser} version={version} err=\"{e}\"" + ); } cleaned_up.push(format!("{browser} {version}")); - log::info!("Successfully removed unused binary: {browser} {version}"); } } - if cleaned_up.is_empty() { - log::info!("No unused binaries found to clean up"); - } else { - log::info!("Cleaned up {} unused binaries", cleaned_up.len()); + if !cleaned_up.is_empty() { + log::info!( + "Removed unused browsers count={} versions=\"{}\"", + cleaned_up.len(), + cleaned_up.join(", ") + ); } Ok(cleaned_up) @@ -424,7 +439,7 @@ impl DownloadedBrowsersRegistry { // Files don't exist, remove from registry if let Some(_removed) = self.remove_browser(&browser_str, &version) { cleaned_up.push(format!("{browser_str} {version}")); - log::info!("Removed stale registry entry for {browser_str} {version}"); + log::info!("Removed stale registry entry browser={browser_str} version={version}"); } } } @@ -576,7 +591,7 @@ impl DownloadedBrowsersRegistry { if entries.next().is_none() { // Directory is empty, remove it fs::remove_dir(&version_dir)?; - log::info!("Removed empty version folder: {}", version_dir.display()); + log::debug!("Removed empty version folder browser={browser} version={version}"); // Also check if the browser folder is now empty and remove it too let browser_dir = binaries_dir.join(browser); @@ -584,7 +599,7 @@ impl DownloadedBrowsersRegistry { if let Ok(mut browser_entries) = fs::read_dir(&browser_dir) { if browser_entries.next().is_none() { fs::remove_dir(&browser_dir)?; - log::info!("Removed empty browser folder: {}", browser_dir.display()); + log::debug!("Removed empty browser folder browser={browser}"); } } } @@ -671,15 +686,13 @@ impl DownloadedBrowsersRegistry { // Remove empty version directories for (version_path, version_name) in empty_version_dirs { if let Err(e) = fs::remove_dir(&version_path) { - log::error!( - "Failed to remove empty version folder {}: {e}", - version_path.display() + log::warn!( + "Empty version folder removal failed browser={browser_name} version={version_name} err=\"{e}\"" ); } else { cleaned_up.push(format!( "Removed empty version folder: {browser_name}/{version_name}" )); - log::info!("Removed empty version folder: {}", version_path.display()); } } @@ -688,13 +701,9 @@ impl DownloadedBrowsersRegistry { if let Ok(mut entries) = fs::read_dir(&browser_path) { if entries.next().is_none() { if let Err(e) = fs::remove_dir(&browser_path) { - log::error!( - "Failed to remove empty browser folder {}: {e}", - browser_path.display() - ); + log::warn!("Empty browser folder removal failed browser={browser_name} err=\"{e}\""); } else { cleaned_up.push(format!("Removed empty browser folder: {browser_name}")); - log::info!("Removed empty browser folder: {}", browser_path.display()); } } } @@ -730,9 +739,9 @@ impl DownloadedBrowsersRegistry { profiles_to_update.push(*profile); older_versions_to_remove.insert(profile.version.clone()); } else { - log::info!( - "Skipping version update for running profile: {} ({})", - profile.name, + log::debug!( + "Version update deferred, browser running profile={} version={}", + profile.id, profile.version ); } @@ -744,26 +753,29 @@ impl DownloadedBrowsersRegistry { match update_profile(profile) { Ok(()) => { consolidated.push(format!( - "Updated profile '{}' from {} to {}", - profile.name, profile.version, latest_version + "profile {} {} -> {}", + profile.id, profile.version, latest_version )); } Err(e) => { - log::error!("Failed to update profile '{}': {}", profile.name, e); + log::warn!( + "Profile browser update failed profile={} to={latest_version} err=\"{e}\"", + profile.id + ); } } } // Remove older version binaries that are no longer needed for old_version in &older_versions_to_remove { - log::info!("Consolidating: removing old version {browser_name} {old_version}"); match remove_version(old_version.as_str()) { Ok(()) => { consolidated.push(format!("Removed old version: {browser_name} {old_version}")); - log::info!("Successfully removed old version: {browser_name} {old_version}"); } Err(e) => { - log::error!("Failed to cleanup old version {browser_name} {old_version}: {e}"); + log::warn!( + "Old browser removal failed browser={browser_name} version={old_version} err=\"{e}\"" + ); } } } @@ -776,8 +788,6 @@ impl DownloadedBrowsersRegistry { &self, app_handle: &tauri::AppHandle, ) -> Result, Box> { - log::info!("Starting browser version consolidation..."); - let profiles = self .profile_manager .list_profiles() @@ -811,16 +821,15 @@ impl DownloadedBrowsersRegistry { if browser.is_version_downloaded(&profile.version, &binaries_dir) { available_versions.push(profile.version.clone()); } else { - log::info!( - "Profile '{}' references version {} that doesn't exist on disk", - profile.name, + log::debug!( + "Profile browser not on disk profile={} browser={browser_name} version={}", + profile.id, profile.version ); } } if available_versions.is_empty() { - log::info!("No available versions found for {browser_name}, skipping consolidation"); continue; } @@ -831,7 +840,6 @@ impl DownloadedBrowsersRegistry { }); let latest_version = &available_versions[0]; - log::info!("Latest available version for {browser_name}: {latest_version}"); let mut consolidated_for_browser = Self::consolidate_profiles_for_browser( browser_name, @@ -858,10 +866,13 @@ impl DownloadedBrowsersRegistry { .save() .map_err(|e| format!("Failed to save registry after consolidation: {e}"))?; - log::info!( - "Browser version consolidation completed: {} actions taken", - consolidated.len() - ); + if !consolidated.is_empty() { + log::info!( + "Browser versions consolidated count={} actions=\"{}\"", + consolidated.len(), + consolidated.join("; ") + ); + } Ok(consolidated) } @@ -881,11 +892,7 @@ impl DownloadedBrowsersRegistry { let browser_type = match BrowserType::from_str(&profile.browser) { Ok(bt) => bt, Err(_) => { - log::info!( - "Warning: Invalid browser type '{}' for profile '{}'", - profile.browser, - profile.name - ); + note_unsupported_browser(&profile.browser); continue; } }; @@ -894,11 +901,6 @@ impl DownloadedBrowsersRegistry { let binaries_dir = crate::app_dirs::binaries_dir(); - log::info!( - "binaries_dir: {binaries_dir:?} for profile: {}", - profile.name - ); - // Check if the version is downloaded if !browser.is_version_downloaded(&profile.version, &binaries_dir) { missing_binaries.push((profile.name, profile.browser, profile.version)); @@ -914,77 +916,48 @@ impl DownloadedBrowsersRegistry { app_handle: &tauri::AppHandle, ) -> Result, Box> { // First, clean up any stale registry entries - if let Ok(cleaned_up) = self.verify_and_cleanup_stale_entries() { - if !cleaned_up.is_empty() { - log::info!( - "Cleaned up {} stale registry entries: {}", - cleaned_up.len(), - cleaned_up.join(", ") - ); - } - } + let _ = self.verify_and_cleanup_stale_entries(); // Consolidate browser versions - keep only latest version per browser - if let Ok(consolidated) = self.consolidate_browser_versions(app_handle) { - if !consolidated.is_empty() { - log::info!("Version consolidation results:"); - for action in &consolidated { - log::info!(" {action}"); - } - } - } + let _ = self.consolidate_browser_versions(app_handle); let missing_binaries = self.check_missing_binaries().await?; let mut downloaded = Vec::new(); for (profile_name, browser, version) in missing_binaries { - log::info!("Downloading missing binary for profile '{profile_name}': {browser} {version}"); - - match crate::downloader::download_browser( - app_handle.clone(), - browser.clone(), - version.clone(), - ) - .await + // A failed download logs itself. + if crate::downloader::download_browser(app_handle.clone(), browser.clone(), version.clone()) + .await + .is_ok() { - Ok(_) => { - downloaded.push(format!( - "{browser} {version} (for profile '{profile_name}')" - )); + downloaded.push(format!( + "{browser} {version} (for profile '{profile_name}')" + )); - // After successful download, update profiles that use this browser to the new version - match self - .update_profiles_to_version(app_handle, &browser, &version) - .await - { - Ok(updated_profiles) => { - if !updated_profiles.is_empty() { - log::info!( - "Successfully updated {} profiles to version {}:", - updated_profiles.len(), - version - ); - for update_msg in updated_profiles { - log::info!(" {update_msg}"); - } - } - } - Err(e) => { - log::error!("CRITICAL: Failed to update profiles to version {version}: {e}"); - log::error!("This may cause profile version inconsistencies and cleanup issues"); + // After successful download, update profiles that use this browser to the new version + match self + .update_profiles_to_version(app_handle, &browser, &version) + .await + { + Ok(updated_profiles) => { + if !updated_profiles.is_empty() { + log::info!( + "Profiles moved to downloaded browser count={} browser={browser} version={version}", + updated_profiles.len() + ); } } - } - Err(e) => { - log::error!("Failed to download {browser} {version} for profile '{profile_name}': {e}"); + Err(e) => { + log::error!( + "Moving profiles to downloaded browser failed browser={browser} version={version} err=\"{e}\"" + ); + } } } } // Check if GeoIP database is missing for Wayfern profiles if self.geoip_downloader.check_missing_geoip_database()? { - log::info!("GeoIP database is missing for Wayfern profiles, downloading..."); - match self .geoip_downloader .download_geoip_database(app_handle) @@ -992,10 +965,12 @@ impl DownloadedBrowsersRegistry { { Ok(_) => { downloaded.push("GeoIP database".to_string()); - log::info!("GeoIP database downloaded successfully"); } Err(e) => { - log::error!("Failed to download GeoIP database: {e}"); + log::error!( + "GeoIP database download failed err=\"{}\"", + crate::log_redaction::text(&e.to_string()) + ); // Don't fail the entire operation if GeoIP download fails } } @@ -1022,9 +997,9 @@ impl DownloadedBrowsersRegistry { if profile.browser == browser && profile.version != version { // Check if profile is currently running if profile.process_id.is_some() { - log::info!( - "Skipping version update for running profile: {} ({})", - profile.name, + log::debug!( + "Version update deferred, browser running profile={} version={}", + profile.id, profile.version ); continue; @@ -1038,22 +1013,20 @@ impl DownloadedBrowsersRegistry { ) { Ok(_) => { updated_profiles.push(format!( - "Updated profile '{}' from {} to {}", - profile.name, profile.version, version + "profile {} {} -> {}", + profile.id, profile.version, version )); - log::info!( - "Successfully updated profile '{}' to version {}", - profile.name, - version - ); // Save registry after each profile update to ensure consistency if let Err(e) = self.save() { - log::warn!("Warning: Failed to save registry after profile update: {e}"); + log::warn!("Registry save failed err=\"{e}\""); } } Err(e) => { - log::error!("Failed to update profile '{}': {}", profile.name, e); + log::warn!( + "Profile browser update failed profile={} to={version} err=\"{e}\"", + profile.id + ); } } } @@ -1095,7 +1068,7 @@ static DOWNLOADED_BROWSERS_REGISTRY: std::sync::LazyLock info.version, Err(e) => { - log::warn!("Failed to resolve current {browser} version: {e}"); + log::warn!( + "Browser version lookup failed browser={browser} err=\"{}\"", + crate::log_redaction::text(&e.to_string()) + ); // The first-run screen listens for this. Without it the screen // waits at 0% for a download that never starts (issue #625). let _ = crate::events::emit( @@ -1580,7 +1551,10 @@ pub async fn ensure_active_browsers_downloaded( let release_types = match version_manager.get_browser_release_types(browser).await { Ok(rt) => rt, Err(e) => { - log::warn!("Failed to get release types for {browser}: {e}"); + log::warn!( + "Browser release lookup failed browser={browser} err=\"{}\"", + crate::log_redaction::text(&e.to_string()) + ); continue; } }; @@ -1595,8 +1569,6 @@ pub async fn ensure_active_browsers_downloaded( } }; - log::info!("Auto-downloading {browser} {version} (no versions found locally)"); - // Retry transient failures a few times. Each attempt is wrapped in an overall // timeout so that a hang anywhere in the download pipeline (version resolution, // a stalled stream, extraction) cannot block the next browser forever. This is @@ -1618,14 +1590,10 @@ pub async fn ensure_active_browsers_downloaded( match result { Ok(Ok(_)) => { downloaded.push(format!("{browser} {version}")); - log::info!("Successfully auto-downloaded {browser} {version}"); succeeded = true; break; } Ok(Err(e)) => { - log::warn!( - "Failed to auto-download {browser} {version} (attempt {attempt}/{MAX_ATTEMPTS}): {e}" - ); // A proxy setting stays wrong until the user changes it. if crate::system_proxy::is_unreachable_error(&e.to_string()) { break; @@ -1637,7 +1605,7 @@ pub async fn ensure_active_browsers_downloaded( // (by browser prefix, as a catch-all for whatever key was in flight) and // emit a terminal error event so the UI stops spinning. log::warn!( - "Auto-download of {browser} {version} timed out after {}s (attempt {attempt}/{MAX_ATTEMPTS})", + "Browser auto-download timed out browser={browser} version={version} attempt={attempt}/{MAX_ATTEMPTS} timeout_s={}", ATTEMPT_TIMEOUT.as_secs() ); crate::downloader::clear_download_state_for_browser(browser); @@ -1656,7 +1624,9 @@ pub async fn ensure_active_browsers_downloaded( if !succeeded { // Do NOT abort the whole routine: continue with remaining browsers // still gets its chance even though this one failed/timed out. - log::warn!("Giving up on auto-download of {browser} {version} after {MAX_ATTEMPTS} attempts"); + log::error!( + "Browser auto-download gave up browser={browser} version={version} attempts={MAX_ATTEMPTS}" + ); } } @@ -1692,7 +1662,7 @@ pub async fn ensure_all_binaries_exist( if crate::e2e_automation_enabled() && std::env::var_os("DONUT_E2E_DISABLE_STARTUP_NETWORK").is_some() { - log::info!("E2E: skipping proactive binary and GeoIP downloads"); + log::debug!("E2E: skipping proactive binary and GeoIP downloads"); return Ok(Vec::new()); } diff --git a/src-tauri/src/downloader.rs b/src-tauri/src/downloader.rs index a6a29efb..0c2f5dbd 100644 --- a/src-tauri/src/downloader.rs +++ b/src-tauri/src/downloader.rs @@ -248,15 +248,9 @@ impl Downloader { let file_path = dest_path.join(&download_info.filename); // Resolve the actual download URL - log::info!( - "Resolving download URL for {} {}", - browser_type.as_str(), - version - ); let download_url = self .resolve_download_url(browser_type.clone(), version, download_info) .await?; - log::info!("Download URL resolved"); // Every browser asset is published with a `.sha256` sidecar. Fetch // it before the transfer starts: an asset nobody can verify costs one small @@ -331,13 +325,16 @@ impl Downloader { Ok(response) if response.status().is_success() => response, Ok(response) => { log::warn!( - "Checksum sidecar request failed for {browser} {version}: HTTP {}", - response.status() + "Checksum sidecar request failed browser={browser} version={version} status={}", + response.status().as_u16() ); return Err(unavailable()); } Err(e) => { - log::warn!("Checksum sidecar request failed for {browser} {version}: {e}"); + log::warn!( + "Checksum sidecar request failed browser={browser} version={version} err=\"{}\"", + crate::log_redaction::text(&e.to_string()) + ); return Err(crate::system_proxy::explain(&e).map_or_else(unavailable, Into::into)); } }; @@ -345,14 +342,17 @@ impl Downloader { let sidecar_text = match response.text().await { Ok(text) => text, Err(e) => { - log::warn!("Failed to read the checksum sidecar for {browser} {version}: {e}"); + log::warn!("Checksum sidecar read failed browser={browser} version={version} err=\"{e}\""); return Err(unavailable()); } }; let asset_name = asset_filename_from_url(download_url); let Some(expected) = crate::checksum::parse_sidecar_digest(&sidecar_text, asset_name) else { - log::warn!("No usable digest for {asset_name} in {sidecar_url}"); + log::warn!( + "Checksum sidecar has no digest for the asset browser={browser} version={version} asset={}", + Plain(asset_name) + ); return Err(unavailable()); }; Ok(expected) @@ -397,13 +397,13 @@ impl Downloader { request = request.header("Range", format!("bytes={existing_size}-")); } - log::info!("Sending download request (attempt {})...", attempt + 1); match request.send().await { Ok(resp) => { - log::info!( - "Download response received: status={}, content-length={:?}", - resp.status(), - resp.content_length() + log::debug!( + "Download response status={} content_length={:?} offset={existing_size} attempt={}", + resp.status().as_u16(), + resp.content_length(), + attempt + 1 ); if resp.status().as_u16() == 416 && existing_size > 0 { // The requested range is past the end of the object. Parse @@ -421,16 +421,12 @@ impl Downloader { None => true, }; if partial_is_complete { - log::info!( - "Archive {} already complete ({} bytes), skipping download", - file_path.display(), - existing_size - ); + log::debug!("Archive already complete bytes={existing_size}"); return Ok(file_path); } let _ = std::fs::remove_file(&file_path); existing_size = 0; - log::warn!("Download returned 416 with an incomplete partial, restarting from 0"); + log::debug!("Download range refused for an incomplete partial, restarting from 0"); continue; } response = Some(resp); @@ -442,18 +438,21 @@ impl Downloader { // bar at 0% for minutes before saying the same thing. if attempt > 0 { if let Some(proxy_error) = crate::system_proxy::explain(&e) { - log::warn!("Download request through the system proxy failed: {e}"); + log::warn!( + "Download request failed through the system proxy attempt={} err=\"{}\"", + attempt + 1, + crate::log_redaction::text(&e.to_string()) + ); return Err(proxy_error.into()); } } let is_retryable = e.is_connect() || e.is_timeout() || e.is_request(); if is_retryable && attempt < max_send_retries { let delay = 2u64.pow(attempt.min(4)); - log::warn!( - "Download attempt {} failed ({}), retrying in {}s...", + log::debug!( + "Download request failed attempt={} retry_in_s={delay} err=\"{}\"", attempt + 1, - e, - delay + crate::log_redaction::text(&e.to_string()) ); tokio::time::sleep(std::time::Duration::from_secs(delay)).await; } else { @@ -512,11 +511,7 @@ impl Downloader { if existing_size > 0 { if let Some(total) = total_size { if existing_size >= total { - log::info!( - "Archive {} already complete ({} bytes), skipping download", - file_path.display(), - existing_size - ); + log::debug!("Archive already complete bytes={existing_size}"); return Ok(file_path); } } @@ -654,13 +649,10 @@ impl Downloader { } stream_restarts += 1; let delay = 2u64.pow(stream_restarts.min(4)); - log::warn!( - "{} — resuming from {} bytes (restart {}/{}) in {}s", - err, + log::debug!( + "Download stream broke, resuming offset={} restart={stream_restarts}/{max_stream_restarts} retry_in_s={delay} err=\"{}\"", std::fs::metadata(&file_path).map(|m| m.len()).unwrap_or(0), - stream_restarts, - max_stream_restarts, - delay + crate::log_redaction::text(&err.to_string()) ); tokio::time::sleep(std::time::Duration::from_secs(delay)).await; } @@ -710,6 +702,7 @@ impl Downloader { } } + let started = std::time::Instant::now(); // Check if this browser-version pair is already being downloaded let download_key = format!("{browser_str}-{version}"); let cancel_token = { @@ -739,7 +732,7 @@ impl Downloader { } else { // Registry says it's downloaded but files don't exist - clean up registry log::info!( - "Registry indicates {} {} is downloaded, but files are missing. Cleaning up registry entry.", + "Removed stale registry entry browser={} version={}", Plain(&browser_str), Plain(&version) ); @@ -842,15 +835,8 @@ impl Downloader { // Do not remove the archive here. We keep it until verification succeeds. } Err(e) => { - log::error!( - "Extraction failed for {} {}: {e}", - Plain(&browser_str), - Plain(&version) - ); - // Delete the corrupt/invalid archive so a fresh download happens next time if download_path.exists() { - log::info!("Deleting corrupt archive: {}", download_path.display()); let _ = std::fs::remove_file(&download_path); } @@ -894,12 +880,6 @@ impl Downloader { let _ = events::emit("download-progress", &progress); // Verify the browser was downloaded correctly - log::info!( - "Verifying download for browser: {}, version: {}", - Plain(&browser_str), - Plain(&version) - ); - // Use the browser's own verification method if !browser.is_version_downloaded(&version, &binaries_dir) { // Provide detailed error information for debugging @@ -955,7 +935,7 @@ impl Downloader { .mark_download_completed(&browser_str, &version, browser_dir.clone()) { log::warn!( - "Warning: Could not mark {} {} as completed in registry: {e}", + "Registry update failed browser={} version={} err=\"{e}\"", Plain(&browser_str), Plain(&version) ); @@ -970,11 +950,18 @@ impl Downloader { let archive_path = browser_dir.join(&download_info.filename); if archive_path.exists() { if let Err(e) = std::fs::remove_file(&archive_path) { - log::warn!("Warning: Could not delete archive file after verification: {e}"); + log::warn!("Archive delete after install failed err=\"{e}\""); } } } + log::info!( + "Browser installed browser={} version={} elapsed_ms={}", + Plain(&browser_str), + Plain(&version), + started.elapsed().as_millis() + ); + // Emit completion let progress = DownloadProgress { browser: browser_str.clone(), @@ -1012,13 +999,18 @@ impl Downloader { Ok(updated) => { if !updated.is_empty() { log::info!( - "Applied {browser_for_update} {version_for_update} to profiles: {updated:?}" + "Profiles moved to installed browser count={} browser={} version={}", + updated.len(), + Plain(&browser_for_update), + Plain(&version_for_update) ); } } Err(e) => { - log::error!( - "Failed to apply {browser_for_update} {version_for_update} to profiles: {e}" + log::warn!( + "Moving profiles to installed browser failed browser={} version={} err=\"{e}\"", + Plain(&browser_for_update), + Plain(&version_for_update) ); } } @@ -1027,27 +1019,19 @@ impl Downloader { Ok(updated) => { if !updated.is_empty() { log::info!( - "Auto-updated {} profiles to latest installed versions: {:?}", - updated.len(), - updated + "Profiles moved to the latest installed browser count={}", + updated.len() ); } } Err(e) => { - log::error!("Failed to auto-update profile versions: {e}"); + log::warn!("Moving profiles to the latest installed browser failed err=\"{e}\""); } } let registry = crate::downloaded_browsers_registry::DownloadedBrowsersRegistry::instance(); - match registry.cleanup_unused_binaries() { - Ok(cleaned) => { - if !cleaned.is_empty() { - log::info!("Cleaned up unused binaries after download: {:?}", cleaned); - } - } - Err(e) => { - log::error!("Failed to cleanup unused binaries: {e}"); - } + if let Err(e) = registry.cleanup_unused_binaries() { + log::warn!("Unused browser cleanup after install failed err=\"{e}\""); } }); } @@ -1092,11 +1076,13 @@ async fn verify_archive_checksum( })??; if actual.eq_ignore_ascii_case(expected) { - log::info!("Checksum verified for {browser} {version}: {actual}"); + log::debug!("Checksum verified browser={browser} version={version} sha256={actual}"); return Ok(()); } - log::error!("Checksum mismatch for {browser} {version}: expected {expected}, got {actual}"); + log::warn!( + "Checksum mismatch, archive deleted browser={browser} version={version} expected={expected} actual={actual}" + ); let _ = std::fs::remove_file(file_path); Err( serde_json::json!({ @@ -1167,10 +1153,27 @@ pub async fn download_browser( version: String, ) -> Result { let downloader = Downloader::instance(); + let browser = Plain(&browser_str).to_string(); + let requested = Plain(&version).to_string(); downloader .download_browser_full(&app_handle, browser_str, version) .await - .map_err(|e| crate::wrap_backend_error(e, "Failed to download browser")) + .map_err(|e| { + let err = e.to_string(); + if err.contains("Download cancelled") { + log::info!("Browser download cancelled browser={browser} version={requested}"); + } else if err.contains("is already being downloaded") { + log::info!( + "Browser download skipped, already running browser={browser} version={requested}" + ); + } else { + log::error!( + "Browser download failed browser={browser} version={requested} err=\"{}\"", + crate::log_redaction::text(&err) + ); + } + crate::wrap_backend_error(e, "Failed to download browser") + }) } #[tauri::command] diff --git a/src-tauri/src/ephemeral_dirs.rs b/src-tauri/src/ephemeral_dirs.rs index f5b55c30..9c2bf8e1 100644 --- a/src-tauri/src/ephemeral_dirs.rs +++ b/src-tauri/src/ephemeral_dirs.rs @@ -52,6 +52,32 @@ fn ephemeral_base_override() -> Option { None } +#[cfg(target_os = "linux")] +const LINUX_EPHEMERAL_BASE: &str = "/dev/shm/donut-ephemeral"; +#[cfg(target_os = "macos")] +const MACOS_RAM_DISK: &str = "/Volumes/DonutEphemeral"; + +fn disk_fallback_base() -> PathBuf { + std::env::temp_dir().join("donut-ephemeral") +} + +/// Whether an earlier run left a base that may hold directories to recover. +/// Unlike `get_ephemeral_base_dir`, this never creates one. +fn earlier_base_exists() -> bool { + if let Some(base) = ephemeral_base_override() { + return base.exists(); + } + #[cfg(target_os = "linux")] + let ram = Path::new(LINUX_EPHEMERAL_BASE).exists(); + #[cfg(target_os = "macos")] + let ram = Path::new(MACOS_RAM_DISK).is_dir(); + #[cfg(target_os = "windows")] + let ram = existing_windows_ramdisk().is_some(); + #[cfg(not(any(target_os = "linux", target_os = "macos", target_os = "windows")))] + let ram = false; + ram || disk_fallback_base().exists() +} + /// Get or create the base directory for ephemeral profiles, and report whether /// it is actually RAM-backed. /// @@ -68,7 +94,7 @@ fn get_ephemeral_base_dir() -> Result<(PathBuf, EphemeralBacking), String> { #[cfg(target_os = "linux")] { - let base = PathBuf::from("/dev/shm/donut-ephemeral"); + let base = PathBuf::from(LINUX_EPHEMERAL_BASE); std::fs::create_dir_all(&base) .map_err(|e| format!("Failed to create ephemeral base in /dev/shm: {e}"))?; Ok((base, EphemeralBacking::Ram)) @@ -99,11 +125,11 @@ fn get_ephemeral_base_dir() -> Result<(PathBuf, EphemeralBacking), String> { // makes and the previous "may use disk" wording was logged unconditionally // right before disk was used, so it read as speculative when it was // certain. The cause used to be discarded entirely. - let base = std::env::temp_dir().join("donut-ephemeral"); + let base = disk_fallback_base(); std::fs::create_dir_all(&base) .map_err(|e| format!("Failed to create ephemeral base dir: {e}"))?; log::error!( - "No RAM disk available ({ramdisk_error}); ephemeral profiles are being written to disk at {} and will be securely erased on teardown instead", + "No RAM disk; ephemeral profiles go to disk and are erased on teardown path={} err=\"{ramdisk_error}\"", base.display() ); Ok((base, EphemeralBacking::Disk)) @@ -112,7 +138,7 @@ fn get_ephemeral_base_dir() -> Result<(PathBuf, EphemeralBacking), String> { #[cfg(target_os = "macos")] fn get_or_create_macos_ramdisk() -> Result { - let mount_point = PathBuf::from("/Volumes/DonutEphemeral"); + let mount_point = PathBuf::from(MACOS_RAM_DISK); // Reuse existing RAM disk from a previous session if mount_point.exists() && mount_point.is_dir() { @@ -150,18 +176,22 @@ fn get_or_create_macos_ramdisk() -> Result { )); } - log::info!("Created macOS RAM disk at {}", mount_point.display()); + log::info!("RAM disk mounted path={MACOS_RAM_DISK} device={dev} size_mb=256"); Ok(mount_point) } +#[cfg(target_os = "windows")] +fn existing_windows_ramdisk() -> Option { + ['R', 'Q', 'P', 'O'] + .into_iter() + .map(|letter| PathBuf::from(format!("{}:\\DonutEphemeral", letter))) + .find(|base| base.is_dir()) +} + #[cfg(target_os = "windows")] fn get_or_create_windows_ramdisk() -> Result { - // Check if a previous RAM disk with our directory already exists - for letter in ['R', 'Q', 'P', 'O'] { - let base = PathBuf::from(format!("{}:\\DonutEphemeral", letter)); - if base.exists() && base.is_dir() { - return Ok(base); - } + if let Some(base) = existing_windows_ramdisk() { + return Ok(base); } // Try to create a RAM disk using imdisk (open-source RAM disk driver) @@ -180,14 +210,13 @@ fn get_or_create_windows_ramdisk() -> Result { let base = PathBuf::from(format!("{}\\DonutEphemeral", drive)); std::fs::create_dir_all(&base) .map_err(|e| format!("Failed to create dir on RAM disk: {e}"))?; - log::info!("Created Windows RAM disk at {}", base.display()); + log::info!("RAM disk created path={} size_mb=256", base.display()); return Ok(base); } Ok(out) => { log::debug!( - "imdisk failed for drive {}: {}", - drive, - String::from_utf8_lossy(&out.stderr) + "imdisk failed drive={drive} err=\"{}\"", + String::from_utf8_lossy(&out.stderr).trim() ); } Err(e) => { @@ -220,13 +249,11 @@ pub fn create_ephemeral_dir(profile_id: &str) -> Result { // anything, so a log could not be used to tell a RAM-backed session from a // disk-backed one after the fact. log::info!( - "Created {} ephemeral dir for profile {}: {}", + "Ephemeral dir created profile={profile_id} backing={}", match backing { - EphemeralBacking::Ram => "RAM-backed", - EphemeralBacking::Disk => "DISK-backed (not in memory)", - }, - profile_id, - dir_path.display() + EphemeralBacking::Ram => "ram", + EphemeralBacking::Disk => "disk", + } ); Ok(dir_path) @@ -248,7 +275,7 @@ pub fn remove_ephemeral_dir(profile_id: &str) -> bool { let entry = match EPHEMERAL_DIRS.lock() { Ok(map) => map.get(profile_id).map(|e| (e.path.clone(), e.backing)), Err(e) => { - log::error!("Failed to lock ephemeral dirs while removing {profile_id}: {e}"); + log::error!("Ephemeral dir removal failed profile={profile_id} err=\"lock: {e}\""); return false; } }; @@ -272,16 +299,9 @@ pub fn remove_ephemeral_dir(profile_id: &str) -> bool { map.remove(profile_id); } log::info!( - "Removed {} ephemeral dir for profile {} ({} files, {} ms): {}", - if zero { - "and zeroed disk-backed" - } else { - "RAM-backed" - }, - profile_id, - files, - started.elapsed().as_millis(), - dir_path.display() + "Ephemeral dir removed profile={profile_id} backing={} files={files} elapsed_ms={}", + if zero { "disk_zeroed" } else { "ram" }, + started.elapsed().as_millis() ); true } @@ -290,7 +310,7 @@ pub fn remove_ephemeral_dir(profile_id: &str) -> bool { // knowingly still on the machine. The mapping is kept so a later sweep // can try again. log::error!( - "Failed to remove ephemeral dir {} for profile {profile_id}: {e}. Profile data is still on disk.", + "Ephemeral dir removal failed; data left behind profile={profile_id} path={} err=\"{e}\"", dir_path.display() ); false @@ -304,10 +324,17 @@ pub fn remove_ephemeral_dir(profile_id: &str) -> bool { pub fn recover_ephemeral_dirs() { cleanup_legacy_dirs(); + // Resolving the base creates it, and on macOS that mounts a RAM disk that + // stays until the Mac restarts. Most installs never use an ephemeral or + // password-protected profile, so there is usually nothing to look for. + if !earlier_base_exists() { + return; + } + let (base, backing) = match get_ephemeral_base_dir() { Ok(base) => base, Err(e) => { - log::warn!("Cannot recover ephemeral dirs: {e}"); + log::warn!("Ephemeral dir recovery failed err=\"{e}\""); return; } }; @@ -341,7 +368,7 @@ pub fn recover_ephemeral_dirs() { backing, }, ); - log::info!("Recovered ephemeral dir for profile {}", name); + log::info!("Ephemeral dir recovered profile={name}"); } } } @@ -352,24 +379,68 @@ pub fn recover_ephemeral_dirs() { /// fallback, unless that fallback is the base being used right now (in which /// case `recover_ephemeral_dirs` is about to adopt them instead). fn sweep_disk_fallback_residue(current_base: &Path) { - let fallback = std::env::temp_dir().join("donut-ephemeral"); + let fallback = disk_fallback_base(); if !fallback.exists() || fallback == current_base { return; } match crate::fs_secure::secure_remove_dir_all(&fallback, true) { Ok(files) if files > 0 => log::info!( - "Securely erased {files} file(s) of disk-backed ephemeral residue at {}", + "Erased disk-backed ephemeral residue files={files} path={}", fallback.display() ), Ok(_) => {} Err(e) => log::error!( - "Failed to erase disk-backed ephemeral residue at {}: {e}", + "Erasing disk-backed ephemeral residue failed path={} err=\"{e}\"", fallback.display() ), } } +/// Whether the macOS RAM disk is mounted. `None` on other systems. +pub fn ram_disk_mounted() -> Option { + #[cfg(target_os = "macos")] + return Some(Path::new(MACOS_RAM_DISK).is_dir()); + #[cfg(not(target_os = "macos"))] + None +} + +/// Detach the macOS RAM disk when no profile directory is on it. Nothing else +/// detaches it, so it would stay mounted until the Mac restarts. +pub fn detach_unused_ram_disk() { + #[cfg(target_os = "macos")] + { + // Every Donut build mounts the same volume, so what is on it decides, not + // only what this run created. + if ephemeral_base_override().is_some() || !holds_no_profile_dirs(Path::new(MACOS_RAM_DISK)) { + return; + } + match std::process::Command::new("hdiutil") + .args(["detach", "-force", MACOS_RAM_DISK]) + .output() + { + Ok(output) if output.status.success() => { + log::info!("RAM disk detached path={MACOS_RAM_DISK} reason=unused_at_exit"); + } + Ok(output) => log::warn!( + "RAM disk detach failed path={MACOS_RAM_DISK} err=\"{}\"", + String::from_utf8_lossy(&output.stderr).trim() + ), + Err(e) => log::warn!("RAM disk detach failed path={MACOS_RAM_DISK} err=\"{e}\""), + } + } +} + +/// False when `path` cannot be read, so a missing volume is never detached. +#[cfg_attr(not(target_os = "macos"), allow(dead_code))] +fn holds_no_profile_dirs(path: &Path) -> bool { + std::fs::read_dir(path).is_ok_and(|entries| { + entries + .flatten() + .all(|entry| uuid::Uuid::parse_str(&entry.file_name().to_string_lossy()).is_err()) + }) +} + /// Remove old-format ephemeral dirs from /tmp (pre-tmpfs migration). fn cleanup_legacy_dirs() { let temp_dir = std::env::temp_dir(); @@ -384,10 +455,10 @@ fn cleanup_legacy_dirs() { // always on real disk and always worth zeroing. if name.starts_with("donut-ephemeral-") && entry.path().is_dir() { if let Err(e) = crate::fs_secure::secure_remove_dir_all(&entry.path(), true) { - log::warn!("Failed to clean up legacy ephemeral dir: {e}"); + log::warn!("Legacy ephemeral dir cleanup failed err=\"{e}\""); } else { log::info!( - "Cleaned up legacy ephemeral dir: {}", + "Legacy ephemeral dir removed path={}", entry.path().display() ); } @@ -521,6 +592,30 @@ mod tests { remove_ephemeral_dir(&test_id); } + #[test] + #[serial_test::serial] + fn recovery_creates_no_base_when_no_earlier_run_left_one() { + let base = BaseGuard::new(); + let missing = base.path().join("never-created"); + std::env::set_var("DONUTBROWSER_EPHEMERAL_ROOT", &missing); + + recover_ephemeral_dirs(); + + assert!(!missing.exists()); + } + + #[test] + fn only_a_volume_without_profile_dirs_counts_as_unused() { + let volume = tempfile::tempdir().unwrap(); + assert!(!holds_no_profile_dirs(&volume.path().join("not-mounted"))); + + std::fs::create_dir(volume.path().join(".fseventsd")).unwrap(); + assert!(holds_no_profile_dirs(volume.path())); + + std::fs::create_dir(volume.path().join(uuid::Uuid::new_v4().to_string())).unwrap(); + assert!(!holds_no_profile_dirs(volume.path())); + } + #[test] #[serial_test::serial] fn disk_backed_dirs_are_zeroed_and_ram_backed_ones_are_not() { diff --git a/src-tauri/src/extension_fetch.rs b/src-tauri/src/extension_fetch.rs index 101364db..e03861bb 100644 --- a/src-tauri/src/extension_fetch.rs +++ b/src-tauri/src/extension_fetch.rs @@ -276,12 +276,15 @@ async fn download_archive(url: &str) -> Result, String> { .send() .await .map_err(|e| { - log::warn!("Extension download request failed: {e}"); + log::warn!("Extension download failed err=\"{}\"", e.without_url()); err("EXTENSION_DOWNLOAD_FAILED") })?; if !response.status().is_success() { - log::warn!("Extension download answered HTTP {}", response.status()); + log::warn!( + "Extension download failed status={}", + response.status().as_u16() + ); return Err(err("EXTENSION_DOWNLOAD_FAILED")); } // A redirect the policy stopped surfaces here as a 3xx, which @@ -301,7 +304,10 @@ async fn download_archive(url: &str) -> Result, String> { let mut stream = response.bytes_stream(); while let Some(chunk) = stream.next().await { let chunk = chunk.map_err(|e| { - log::warn!("Extension download stream failed: {e}"); + log::warn!( + "Extension download stream failed err=\"{}\"", + e.without_url() + ); err("EXTENSION_DOWNLOAD_FAILED") })?; // A server is free to lie about, or omit, Content-Length, so the ceiling diff --git a/src-tauri/src/extension_manager.rs b/src-tauri/src/extension_manager.rs index e4980ca3..87828b7e 100644 --- a/src-tauri/src/extension_manager.rs +++ b/src-tauri/src/extension_manager.rs @@ -756,7 +756,7 @@ impl ExtensionManager { fs::write(metadata_path, json)?; if let Err(e) = events::emit_empty("extensions-changed") { - log::error!("Failed to emit extensions-changed event: {e}"); + log::warn!("Event emit failed event=extensions-changed err=\"{e}\""); } if ext.sync_enabled { @@ -1041,7 +1041,7 @@ impl ExtensionManager { fs::write(metadata_path, json)?; if let Err(e) = events::emit_empty("extensions-changed") { - log::error!("Failed to emit extensions-changed event: {e}"); + log::warn!("Event emit failed event=extensions-changed err=\"{e}\""); } if ext.sync_enabled { @@ -1076,7 +1076,7 @@ impl ExtensionManager { self.save_groups_data(&groups_data)?; if let Err(e) = events::emit_empty("extensions-changed") { - log::error!("Failed to emit extensions-changed event: {e}"); + log::warn!("Event emit failed event=extensions-changed err=\"{e}\""); } if ext.sync_enabled { @@ -1086,11 +1086,13 @@ impl ExtensionManager { match crate::sync::SyncEngine::create_from_settings(&app_handle_clone).await { Ok(engine) => { if let Err(e) = engine.delete_extension(&ext_id).await { - log::warn!("Failed to delete extension {} from sync: {}", ext_id, e); + log::warn!("Remote extension delete failed extension={ext_id} err=\"{e}\""); } } Err(e) => { - log::debug!("Sync not configured, skipping remote deletion: {}", e); + log::debug!( + "Remote extension delete skipped: sync not configured extension={ext_id} err=\"{e}\"" + ); } } }); @@ -1151,7 +1153,7 @@ impl ExtensionManager { self.save_groups_data(&data)?; if let Err(e) = events::emit_empty("extensions-changed") { - log::error!("Failed to emit extensions-changed event: {e}"); + log::warn!("Event emit failed event=extensions-changed err=\"{e}\""); } if group.sync_enabled { @@ -1224,7 +1226,7 @@ impl ExtensionManager { self.save_groups_data(&data)?; if let Err(e) = events::emit_empty("extensions-changed") { - log::error!("Failed to emit extensions-changed event: {e}"); + log::warn!("Event emit failed event=extensions-changed err=\"{e}\""); } if updated.sync_enabled { @@ -1279,21 +1281,21 @@ impl ExtensionManager { Ok(engine) => { if let Err(e) = engine.delete_extension_group(&group_id_owned).await { log::warn!( - "Failed to delete extension group {} from sync: {}", - group_id_owned, - e + "Remote extension group delete failed extension_group={group_id_owned} err=\"{e}\"" ); } } Err(e) => { - log::debug!("Sync not configured, skipping remote deletion: {}", e); + log::debug!( + "Remote extension group delete skipped: sync not configured extension_group={group_id_owned} err=\"{e}\"" + ); } } }); } if let Err(e) = events::emit_empty("extensions-changed") { - log::error!("Failed to emit extensions-changed event: {e}"); + log::warn!("Event emit failed event=extensions-changed err=\"{e}\""); } Ok(()) @@ -1323,7 +1325,7 @@ impl ExtensionManager { self.save_groups_data(&data)?; if let Err(e) = events::emit_empty("extensions-changed") { - log::error!("Failed to emit extensions-changed event: {e}"); + log::warn!("Event emit failed event=extensions-changed err=\"{e}\""); } if updated.sync_enabled { @@ -1357,7 +1359,7 @@ impl ExtensionManager { self.save_groups_data(&data)?; if let Err(e) = events::emit_empty("extensions-changed") { - log::error!("Failed to emit extensions-changed event: {e}"); + log::warn!("Event emit failed event=extensions-changed err=\"{e}\""); } if updated.sync_enabled { @@ -1533,16 +1535,15 @@ impl ExtensionManager { let linked_path = PathBuf::from(linked); if !linked_path.join("manifest.json").exists() { log::warn!( - "Skipping linked extension '{}': {} is no longer an extension folder", - ext.name, - linked + "Linked extension skipped: folder has no manifest.json extension={} path=\"{linked}\"", + ext.id ); continue; } if !path_is_load_extension_safe(&linked_path) { log::warn!( - "Skipping linked extension '{}': path contains a comma, which --load-extension cannot express", - ext.name + "Linked extension skipped: path has a comma --load-extension cannot express extension={}", + ext.id ); continue; } @@ -1561,7 +1562,7 @@ impl ExtensionManager { extension_paths.push(unpack_dir.to_string_lossy().to_string()); } Err(e) => { - log::warn!("Failed to unpack extension '{}': {}", ext.name, e); + log::warn!("Extension unpack failed extension={} err=\"{e}\"", ext.id); } } } @@ -1582,7 +1583,7 @@ impl ExtensionManager { let dir = Self::unpacked_dir_for_profile(profile_id); if dir.exists() { if let Err(e) = fs::remove_dir_all(&dir) { - log::warn!("Failed to clean staged extensions for profile {profile_id}: {e}"); + log::warn!("Staged extension cleanup failed profile={profile_id} err=\"{e}\""); } } } diff --git a/src-tauri/src/extraction.rs b/src-tauri/src/extraction.rs index 07350d0c..f83598a6 100644 --- a/src-tauri/src/extraction.rs +++ b/src-tauri/src/extraction.rs @@ -215,8 +215,6 @@ impl Extractor { // If the executable is not in the expected subdirectory, create the structure if !exe_path.starts_with(&expected_subdir) { - log::info!("Reorganizing directory structure for {}", browser_type); - // Create the expected subdirectory std::fs::create_dir_all(&expected_subdir)?; @@ -238,19 +236,16 @@ impl Extractor { // Move the file/directory if let Err(e) = std::fs::rename(&path, &target_path) { - log::info!( - "Warning: Failed to move {} to {}: {}", + log::warn!( + "Browser layout move failed from={} to={} err=\"{e}\"", path.display(), - target_path.display(), - e + target_path.display() ); - } else { - log::info!("Moved {} to {}", path.display(), target_path.display()); } } } - log::info!("Directory structure reorganized for {}", browser_type); + log::debug!("Browser layout reorganized browser={browser_type}"); } Ok(()) @@ -283,13 +278,6 @@ impl Extractor { // report, and the frontend falls back to an indeterminate bar. let reporter = ExtractionReporter::new(browser_type.as_str().to_string(), version.to_string()); - log::info!( - "Starting extraction of {} for browser {} version {}", - archive_path.display(), - browser_type.as_str(), - version - ); - // Detect the actual file type by reading the file header let actual_format = self.detect_file_format(archive_path).map_err(|e| { format!( @@ -298,7 +286,10 @@ impl Extractor { e ) })?; - log::info!("Detected format: {actual_format}"); + log::debug!( + "Extracting browser={} version={version} format={actual_format}", + browser_type.as_str() + ); let extraction_result = match actual_format.as_str() { "dmg" => { @@ -396,23 +387,14 @@ impl Extractor { } } - log::info!( - "Successfully extracted {} {} to: {}", + log::debug!( + "Extracted browser={} version={version} executable={}", browser_type.as_str(), - version, path.display() ); Ok(path) } - Err(e) => { - log::error!( - "Extraction failed for {} {}: {}", - browser_type.as_str(), - version, - e - ); - Err(e) - } + Err(e) => Err(e), } } @@ -523,12 +505,6 @@ impl Extractor { dest_dir: &Path, progress: Option<&ExtractionReporter>, ) -> Result> { - log::info!( - "Extracting DMG: {} to {}", - dmg_path.display(), - dest_dir.display() - ); - // Create a temporary mount point let mount_point = std::env::temp_dir().join(format!( "donut_mount_{}", @@ -539,8 +515,6 @@ impl Extractor { )); create_dir_all(&mount_point)?; - log::info!("Created mount point: {}", mount_point.display()); - // Mount the DMG let output = Command::new("hdiutil") .args([ @@ -559,7 +533,7 @@ impl Extractor { if !output.status.success() { let stderr = String::from_utf8_lossy(&output.stderr); let stdout = String::from_utf8_lossy(&output.stdout); - log::error!("Failed to mount DMG. stdout: {stdout}, stderr: {stderr}"); + log::debug!("DMG mount failed stdout={stdout:?} stderr={stderr:?}"); // Clean up mount point before returning error let _ = fs::remove_dir_all(&mount_point); @@ -567,7 +541,7 @@ impl Extractor { return Err(format!("Failed to mount DMG: {stderr}").into()); } - log::info!("Successfully mounted DMG"); + log::debug!("DMG mounted mount={}", mount_point.display()); // Find the .app directory in the mount point let app_result = self.find_app_in_directory(&mount_point).await; @@ -575,7 +549,7 @@ impl Extractor { let app_entry = match app_result { Ok(app_path) => app_path, Err(e) => { - log::error!("Failed to find .app in mount point: {e}"); + log::debug!("No .app in mounted DMG err=\"{e}\""); // Try to unmount before returning error let _ = Command::new("hdiutil") @@ -588,13 +562,9 @@ impl Extractor { } }; - log::info!("Found .app bundle: {}", app_entry.display()); - // Copy the .app to the destination let app_path = dest_dir.join(app_entry.file_name().unwrap()); - log::info!("Copying .app to: {}", app_path.display()); - // The copy is the long pole of DMG extraction; size up the source once so // we can report real progress by polling the destination while cp runs. // report_bytes no-ops on a 0 total, so the None path skips both walks. @@ -634,7 +604,6 @@ impl Extractor { if !output.status.success() { let stderr = String::from_utf8_lossy(&output.stderr); - log::error!("Failed to copy app: {stderr}"); // Unmount before returning error let _ = Command::new("hdiutil") @@ -646,8 +615,6 @@ impl Extractor { return Err(format!("Failed to copy app: {stderr}").into()); } - log::info!("Successfully copied .app bundle"); - // Remove the macOS quarantine attribute so Gatekeeper doesn't block launch // — but only if it's actually present. A no-op `removexattr` syscall on a // signed .app bundle still trips macOS Sequoia's App Management privacy @@ -659,9 +626,7 @@ impl Extractor { .args(["-dr", "com.apple.quarantine", app_path.to_str().unwrap()]) .output() .await; - log::info!("Removed quarantine attributes"); - } else { - log::info!("No quarantine attribute on .app, skipping xattr removal"); + log::debug!("Removed quarantine attribute"); } // Unmount the DMG @@ -672,10 +637,12 @@ impl Extractor { if !output.status.success() { let stderr = String::from_utf8_lossy(&output.stderr); - log::warn!("Warning: Failed to unmount DMG: {stderr}"); + log::warn!( + "DMG unmount failed, image stays mounted mount={} stderr={:?}", + mount_point.display(), + stderr.trim() + ); // Don't fail if unmount fails - the extraction was successful - } else { - log::info!("Successfully unmounted DMG"); } // Clean up mount point directory @@ -713,7 +680,7 @@ impl Extractor { if path.is_dir() { if let Some(extension) = path.extension() { if extension == "app" { - log::info!("Found .app bundle at depth {}: {}", depth, path.display()); + log::debug!("Found .app bundle at depth {}: {}", depth, path.display()); return Ok(path); } } @@ -763,7 +730,7 @@ impl Extractor { dest_dir: &Path, progress: Option<&ExtractionReporter>, ) -> Result> { - log::info!("Extracting ZIP archive: {}", zip_path.display()); + log::debug!("Extracting ZIP archive: {}", zip_path.display()); std::fs::create_dir_all(dest_dir)?; let file = File::open(zip_path) @@ -772,7 +739,7 @@ impl Extractor { let mut archive = zip::ZipArchive::new(BufReader::new(file)) .map_err(|e| format!("Failed to read ZIP archive {}: {}", zip_path.display(), e))?; - log::info!("ZIP archive contains {} files", archive.len()); + log::debug!("ZIP archive contains {} files", archive.len()); // Total uncompressed size, known from the central directory without any // decompression. None for archives using data descriptors — those get no @@ -836,11 +803,10 @@ impl Extractor { } } - log::info!("ZIP extraction completed."); + log::debug!("ZIP extraction completed."); self.flatten_single_directory_archive(dest_dir)?; - log::info!("Searching for executable..."); self .find_extracted_executable(dest_dir) .await @@ -853,7 +819,7 @@ impl Extractor { dest_dir: &Path, progress: Option<&ExtractionReporter>, ) -> Result> { - log::info!("Extracting tar.gz archive: {}", tar_path.display()); + log::debug!("Extracting tar.gz archive: {}", tar_path.display()); std::fs::create_dir_all(dest_dir)?; let file = File::open(tar_path)?; @@ -866,9 +832,8 @@ impl Extractor { // Set executable permissions for extracted files self.set_executable_permissions_recursive(dest_dir).await?; - log::info!("tar.gz extraction completed."); + log::debug!("tar.gz extraction completed."); self.flatten_single_directory_archive(dest_dir)?; - log::info!("Searching for executable..."); self.find_extracted_executable(dest_dir).await } @@ -878,7 +843,7 @@ impl Extractor { dest_dir: &Path, progress: Option<&ExtractionReporter>, ) -> Result> { - log::info!("Extracting tar.bz2 archive: {}", tar_path.display()); + log::debug!("Extracting tar.bz2 archive: {}", tar_path.display()); std::fs::create_dir_all(dest_dir)?; let file = File::open(tar_path)?; @@ -891,9 +856,8 @@ impl Extractor { // Set executable permissions for extracted files self.set_executable_permissions_recursive(dest_dir).await?; - log::info!("tar.bz2 extraction completed."); + log::debug!("tar.bz2 extraction completed."); self.flatten_single_directory_archive(dest_dir)?; - log::info!("Searching for executable..."); self.find_extracted_executable(dest_dir).await } @@ -903,7 +867,7 @@ impl Extractor { dest_dir: &Path, progress: Option<&ExtractionReporter>, ) -> Result> { - log::info!("Extracting tar.xz archive: {}", tar_path.display()); + log::debug!("Extracting tar.xz archive: {}", tar_path.display()); std::fs::create_dir_all(dest_dir)?; let file = File::open(tar_path)?; @@ -946,9 +910,8 @@ impl Extractor { // Set executable permissions for extracted files self.set_executable_permissions_recursive(dest_dir).await?; - log::info!("tar.xz extraction completed."); + log::debug!("tar.xz extraction completed."); self.flatten_single_directory_archive(dest_dir)?; - log::info!("Searching for executable..."); self.find_extracted_executable(dest_dir).await } @@ -957,7 +920,7 @@ impl Extractor { msi_path: &Path, dest_dir: &Path, ) -> Result> { - log::info!("Extracting MSI archive: {}", msi_path.display()); + log::debug!("Extracting MSI archive: {}", msi_path.display()); std::fs::create_dir_all(dest_dir)?; // Extract MSI in a separate scope to avoid Send issues @@ -966,9 +929,8 @@ impl Extractor { extractor.to(dest_dir); } - log::info!("MSI extraction completed."); + log::debug!("MSI extraction completed."); self.flatten_single_directory_archive(dest_dir)?; - log::info!("Searching for executable..."); self.find_extracted_executable(dest_dir).await } @@ -1045,14 +1007,14 @@ impl Extractor { let single_dir = &dirs[0]; if single_dir.extension().is_some_and(|ext| ext == "app") { - log::info!( + log::debug!( "Skipping flatten: {} is a macOS app bundle", single_dir.display() ); return Ok(()); } - log::info!( + log::debug!( "Flattening single-directory archive: moving contents of {} to {}", single_dir.display(), dest_dir.display() @@ -1085,7 +1047,7 @@ impl Extractor { ) })?; - log::info!("Successfully flattened archive directory structure"); + log::debug!("Successfully flattened archive directory structure"); } Ok(()) @@ -1127,7 +1089,7 @@ impl Extractor { &self, dest_dir: &Path, ) -> Result> { - log::info!("Searching for .app bundle in: {}", dest_dir.display()); + log::debug!("Searching for .app bundle in: {}", dest_dir.display()); // Use the enhanced recursive search match self.find_app_in_directory(dest_dir).await { @@ -1135,7 +1097,7 @@ impl Extractor { // Check if the app is in a subdirectory and move it to the root if needed let app_parent = app_path.parent().unwrap(); if app_parent != dest_dir { - log::info!( + log::debug!( "Found .app in subdirectory, moving to root: {} -> {}", app_path.display(), dest_dir.display() @@ -1152,15 +1114,15 @@ impl Extractor { } } - log::info!("Successfully moved .app to: {}", target_path.display()); + log::debug!("Successfully moved .app to: {}", target_path.display()); Ok(target_path) } else { - log::info!("Found .app at root level: {}", app_path.display()); + log::debug!("Found .app at root level: {}", app_path.display()); Ok(app_path) } } Err(e) => { - log::info!("Failed to find .app bundle: {e}"); + log::debug!("Failed to find .app bundle: {e}"); Err("No .app found after extraction".into()) } } @@ -1171,7 +1133,7 @@ impl Extractor { &self, dest_dir: &Path, ) -> Result> { - log::info!( + log::debug!( "Searching for Windows executable in: {}", dest_dir.display() ); @@ -1184,7 +1146,7 @@ impl Extractor { for exe_name in &priority_exe_names { let exe_path = dest_dir.join(exe_name); if exe_path.exists() { - log::info!("Found priority executable: {}", exe_path.display()); + log::debug!("Found priority executable: {}", exe_path.display()); return Ok(exe_path); } } @@ -1192,7 +1154,7 @@ impl Extractor { // Recursively search for executables with depth limit match self.find_windows_executable_recursive(dest_dir, 0, 3).await { Ok(exe_path) => { - log::info!( + log::debug!( "Found executable via recursive search: {}", exe_path.display() ); @@ -1287,7 +1249,7 @@ impl Extractor { &self, dest_dir: &Path, ) -> Result> { - log::info!("Searching for Linux executable in: {}", dest_dir.display()); + log::debug!("Searching for Linux executable in: {}", dest_dir.display()); // Enhanced list of common browser executable names, Wayfern first since it // is the current name. Chrome/Chromium cover builds extracted before the @@ -1308,7 +1270,7 @@ impl Extractor { for exe_name in &exe_names { let exe_path = dest_dir.join(exe_name); if exe_path.exists() && self.is_executable(&exe_path) { - log::info!("Found executable at root level: {}", exe_path.display()); + log::debug!("Found executable at root level: {}", exe_path.display()); return Ok(exe_path); } } @@ -1343,7 +1305,7 @@ impl Extractor { for exe_name in &exe_names { let exe_path = subdir_path.join(exe_name); if exe_path.exists() && self.is_executable(&exe_path) { - log::info!("Found executable in subdirectory: {}", exe_path.display()); + log::debug!("Found executable in subdirectory: {}", exe_path.display()); return Ok(exe_path); } } @@ -1356,7 +1318,7 @@ impl Extractor { let path = entry.path(); if let Some(file_name) = path.file_name().and_then(|n| n.to_str()) { if file_name.ends_with(".AppImage") && self.is_executable(&path) { - log::info!("Found AppImage: {}", path.display()); + log::debug!("Found AppImage: {}", path.display()); return Ok(path); } } @@ -1364,15 +1326,15 @@ impl Extractor { } // Last resort: recursive search for any executable file - log::info!("Performing recursive search for executables..."); + log::debug!("Performing recursive search for executables..."); match self.find_any_executable_recursive(dest_dir, 0).await { Ok(path) => { - log::info!("Found executable via recursive search: {}", path.display()); + log::debug!("Found executable via recursive search: {}", path.display()); Ok(path) } Err(e) => { // List all files in the directory for debugging - log::info!("Failed to find executable. Directory contents:"); + let mut listed = Vec::new(); if let Ok(entries) = fs::read_dir(dest_dir) { for entry in entries.flatten() { let path = entry.path(); @@ -1381,9 +1343,18 @@ impl Extractor { } else { false }; - log::info!(" {} (executable: {})", path.display(), is_exec); + let name = path.file_name().unwrap_or_default().to_string_lossy(); + listed.push(if is_exec { + format!("{name}*") + } else { + name.to_string() + }); } } + log::warn!( + "No executable after extraction dir={} entries={listed:?}", + dest_dir.display() + ); Err( format!( "No executable found in {} after extraction. Original error: {}", @@ -1480,7 +1451,7 @@ impl Extractor { || name_lower.contains("wayfern") || file_name.ends_with(".AppImage") { - log::info!( + log::debug!( "Found priority executable at depth {}: {}", depth, path.display() @@ -1522,7 +1493,7 @@ impl Extractor { a_name.len().cmp(&b_name.len()) }); - log::info!( + log::debug!( "Found potential executable at depth {}: {}", depth, potential_executables[0].display() diff --git a/src-tauri/src/fingerprint_consistency.rs b/src-tauri/src/fingerprint_consistency.rs index 0d1343b6..8cedf8d9 100644 --- a/src-tauri/src/fingerprint_consistency.rs +++ b/src-tauri/src/fingerprint_consistency.rs @@ -429,7 +429,10 @@ pub async fn probe_and_check_consistency( // exit IP). Skip rather than warn on an unknown location — the same // database gates fingerprint geo, so there's nothing to disagree with. Err(e) => { - log::debug!("Consistency check: could not geolocate exit IP: {e}"); + log::debug!( + "Consistency check skipped, exit not geolocated err=\"{}\"", + crate::log_redaction::text(&e.to_string()) + ); Ok(ConsistencyResult::skip()) } } @@ -456,7 +459,10 @@ pub async fn probe_direct_and_check(profile: &BrowserProfile) -> Result { - log::debug!("Consistency check: could not geolocate direct exit IP: {e}"); + log::debug!( + "Consistency check skipped, direct exit not geolocated err=\"{}\"", + crate::log_redaction::text(&e.to_string()) + ); Ok(ConsistencyResult::skip()) } } diff --git a/src-tauri/src/fs_secure.rs b/src-tauri/src/fs_secure.rs index 58730489..fa36a912 100644 --- a/src-tauri/src/fs_secure.rs +++ b/src-tauri/src/fs_secure.rs @@ -97,7 +97,10 @@ fn remove_tree(dir: &Path, zero: bool, removed: &mut u64) { let entries = match fs::read_dir(dir) { Ok(entries) => entries, Err(e) => { - log::warn!("Secure erase could not read {}: {e}", dir.display()); + log::warn!( + "Secure erase could not read dir path=\"{}\" err=\"{e}\"", + dir.display() + ); return; } }; diff --git a/src-tauri/src/geoip_downloader.rs b/src-tauri/src/geoip_downloader.rs index 382e5270..48596f43 100644 --- a/src-tauri/src/geoip_downloader.rs +++ b/src-tauri/src/geoip_downloader.rs @@ -127,7 +127,7 @@ impl GeoIPDownloader { .compare_exchange(false, true, Ordering::SeqCst, Ordering::SeqCst) .is_err() { - log::info!("GeoIP database download already in progress, skipping"); + log::debug!("GeoIP download already running"); return Ok(()); } let result = self.download_geoip_database_inner(_app_handle).await; @@ -279,7 +279,10 @@ impl GeoIPDownloader { // the download that fingerprint geolocation actually depends on. if let Some(url) = asn_url { if let Err(e) = self.download_asn_database(&url).await { - log::warn!("Failed to download the GeoIP ASN database: {e}"); + log::warn!( + "GeoIP ASN database download failed err=\"{}\"", + crate::log_redaction::text(&e.to_string()) + ); } } diff --git a/src-tauri/src/geolocation.rs b/src-tauri/src/geolocation.rs index 8540423c..0f590404 100644 --- a/src-tauri/src/geolocation.rs +++ b/src-tauri/src/geolocation.rs @@ -56,7 +56,7 @@ pub fn locale_selector() -> Option<&'static LocaleSelector> { .get_or_init(|| match LocaleSelector::new() { Ok(s) => Some(s), Err(e) => { - log::warn!("Failed to build the CLDR locale selector: {e}"); + log::warn!("CLDR locale selector build failed err=\"{e}\""); None } }) @@ -163,7 +163,7 @@ impl LocaleSelector { } Ok(Event::Eof) => break, Err(e) => { - log::warn!("Error parsing territory XML: {}", e); + log::warn!("Territory XML parse failed err=\"{e}\""); break; } _ => {} diff --git a/src-tauri/src/group_bookmarks.rs b/src-tauri/src/group_bookmarks.rs index 2e9f6f8b..0beb6252 100644 --- a/src-tauri/src/group_bookmarks.rs +++ b/src-tauri/src/group_bookmarks.rs @@ -597,13 +597,13 @@ pub fn sync_profile(profile: &BrowserProfile) -> Result { /// browser process exists and while the profile is provably not running. pub fn sync_for_launch(profile: &BrowserProfile) { match sync_profile(profile) { - Ok(true) => log::info!("Wrote group bookmarks into profile {}", profile.name), + Ok(true) => log::info!("Group bookmarks written profile={}", profile.id), Ok(false) => {} // Never blocks a launch. The browser opening without today's shared // bookmarks is a smaller failure than the browser not opening. Err(e) => log::warn!( - "Could not write group bookmarks for profile {}: {e}", - profile.name + "Group bookmarks write failed profile={} err=\"{e}\"", + profile.id ), } } diff --git a/src-tauri/src/group_manager.rs b/src-tauri/src/group_manager.rs index e30daee0..8cc35d2f 100644 --- a/src-tauri/src/group_manager.rs +++ b/src-tauri/src/group_manager.rs @@ -122,7 +122,7 @@ impl GroupManager { // Emit event for reactive UI updates if let Err(e) = events::emit_empty("groups-changed") { - log::error!("Failed to emit groups-changed event: {e}"); + log::warn!("Event emit failed event=groups-changed err=\"{e}\""); } if group.sync_enabled { @@ -180,7 +180,7 @@ impl GroupManager { // Emit event for reactive UI updates if let Err(e) = events::emit_empty("groups-changed") { - log::error!("Failed to emit groups-changed event: {e}"); + log::warn!("Event emit failed event=groups-changed err=\"{e}\""); } if updated_group.sync_enabled { @@ -284,13 +284,15 @@ impl GroupManager { match crate::sync::SyncEngine::create_from_settings(&app_handle_clone).await { Ok(engine) => { if let Err(e) = engine.delete_group(&group_id_owned).await { - log::warn!("Failed to delete group {} from sync: {}", group_id_owned, e); + log::warn!("Remote group delete failed group={group_id_owned} err=\"{e}\""); } else { - log::info!("Group {} deleted from S3 sync storage", group_id_owned); + log::info!("Remote group deleted group={group_id_owned}"); } } Err(e) => { - log::debug!("Sync not configured, skipping remote deletion: {}", e); + log::debug!( + "Remote group delete skipped: sync not configured group={group_id_owned} err=\"{e}\"" + ); } } }); @@ -298,7 +300,7 @@ impl GroupManager { // Emit event for reactive UI updates if let Err(e) = events::emit_empty("groups-changed") { - log::error!("Failed to emit groups-changed event: {e}"); + log::warn!("Event emit failed event=groups-changed err=\"{e}\""); } Ok(()) @@ -330,7 +332,7 @@ impl GroupManager { self.save_groups_data(&groups_data)?; if let Err(e) = events::emit_empty("groups-changed") { - log::error!("Failed to emit groups-changed event: {e}"); + log::warn!("Event emit failed event=groups-changed err=\"{e}\""); } if updated_group.sync_enabled { diff --git a/src-tauri/src/launch_gate.rs b/src-tauri/src/launch_gate.rs index 4795ef41..e8e33f34 100644 --- a/src-tauri/src/launch_gate.rs +++ b/src-tauri/src/launch_gate.rs @@ -151,23 +151,19 @@ fn mismatch_error(result: &ConsistencyResult, token: &str) -> String { /// either, so the launch says what it could not check. fn report_consistency(profile: &BrowserProfile, result: &ConsistencyResult) { if result.is_verified() { - log::debug!( - "Fingerprint gate: {} agrees with its exit on every dimension", - profile.name - ); + log::debug!("Fingerprint gate passed profile={}", profile.id); return; } if result.unverified.is_empty() { return; } - log::warn!( - "Fingerprint gate: {} reached its exit but could not verify {}; \ - the fingerprint declares no value to compare against", - profile.name, - result.unverified.join(", ") + log::info!( + "Fingerprint gate could not verify, fingerprint declares no value profile={} unverified={}", + profile.id, + result.unverified.join(",") ); if let Err(e) = crate::events::emit("fingerprint-consistency-unverified", result) { - log::warn!("Failed to emit fingerprint consistency notice: {e}"); + log::warn!("Event emit failed event=fingerprint-consistency-unverified err=\"{e}\""); } } @@ -242,8 +238,9 @@ async fn enforce_direct_exit( Ok(result) => result, Err(e) => { log::warn!( - "Fingerprint gate: direct exit probe failed for profile {}, allowing launch: {e}", - profile.name + "Fingerprint gate direct exit probe failed, launch allowed profile={} err=\"{}\"", + profile.id, + crate::log_redaction::text(&e.to_string()) ); return Ok(()); } @@ -292,9 +289,10 @@ pub async fn enforce_fingerprint_gate( let key = fingerprint_consistency::exit_cache_key(profile); if key.is_none() || upstream.is_none() { log::warn!( - "Fingerprint gate: {} declares a proxy/VPN that yielded no usable upstream; \ - measuring the direct exit it will actually use", - profile.name + "Profile route gave no usable upstream, gate measures the direct exit profile={} proxy={} vpn={}", + profile.id, + profile.proxy_id.as_deref().unwrap_or("none"), + profile.vpn_id.as_deref().unwrap_or("none") ); return enforce_direct_exit(profile, gate).await; } @@ -320,8 +318,9 @@ pub async fn enforce_fingerprint_gate( Ok(result) => result, Err(e) => { log::warn!( - "Fingerprint gate: exit probe failed for profile {}, allowing launch: {e}", - profile.name + "Fingerprint gate exit probe failed, launch allowed profile={} err=\"{}\"", + profile.id, + crate::log_redaction::text(&e.to_string()) ); return Ok(()); } @@ -343,12 +342,12 @@ pub async fn enforce_fingerprint_gate( // `proxy` permission silently disarmed the gate for good. if matches!(gate, FingerprintGate::Advisory) { log::warn!( - "Fingerprint gate: {} launching with a known exit mismatch ({})", - profile.name, - result.mismatches.join(", ") + "Launching with a known fingerprint exit mismatch profile={} mismatches={}", + profile.id, + result.mismatches.join(",") ); if let Err(e) = crate::events::emit("fingerprint-consistency-warning", &result) { - log::warn!("Failed to emit fingerprint consistency warning: {e}"); + log::warn!("Event emit failed event=fingerprint-consistency-warning err=\"{e}\""); } return Ok(()); } diff --git a/src-tauri/src/launch_gate_prefs.rs b/src-tauri/src/launch_gate_prefs.rs index 551c4e25..b1058e6f 100644 --- a/src-tauri/src/launch_gate_prefs.rs +++ b/src-tauri/src/launch_gate_prefs.rs @@ -44,7 +44,7 @@ pub fn load() -> LaunchGatePrefs { return LaunchGatePrefs::default(); }; serde_json::from_str(&content).unwrap_or_else(|e| { - log::warn!("Failed to parse launch gate prefs, ignoring them: {e}"); + log::warn!("Launch gate prefs parse failed, ignoring them err=\"{e}\""); LaunchGatePrefs::default() }) } @@ -53,17 +53,17 @@ fn save(prefs: &LaunchGatePrefs) { let path = prefs_file(); if let Some(parent) = path.parent() { if let Err(e) = std::fs::create_dir_all(parent) { - log::warn!("Failed to create launch gate prefs dir: {e}"); + log::warn!("Launch gate prefs dir create failed err=\"{e}\""); return; } } match serde_json::to_string_pretty(prefs) { Ok(json) => { if let Err(e) = std::fs::write(&path, json) { - log::warn!("Failed to write launch gate prefs: {e}"); + log::warn!("Launch gate prefs write failed err=\"{e}\""); } } - Err(e) => log::warn!("Failed to serialize launch gate prefs: {e}"), + Err(e) => log::warn!("Launch gate prefs serialize failed err=\"{e}\""), } } diff --git a/src-tauri/src/legacy_autostart.rs b/src-tauri/src/legacy_autostart.rs new file mode 100644 index 00000000..3ca3b114 --- /dev/null +++ b/src-tauri/src/legacy_autostart.rs @@ -0,0 +1,131 @@ +//! The autostart entry that 0.14 to 0.17 installed for the old tray daemon. +//! +//! 0.18 to 0.24 removed it at launch. 0.25 deleted the daemon and that cleanup +//! with it, so a machine that went from 0.17 or earlier straight to 0.25 or +//! later still carries an entry that points at a binary no longer shipped. On +//! macOS that entry is a LaunchAgent, and Login Items lists Donut as running in +//! the background long after the app has quit. + +use std::io; +use std::path::Path; + +/// Remove the old daemon's autostart entry, if this machine still has one. +pub fn remove() { + #[cfg(any(target_os = "macos", target_os = "linux"))] + { + #[cfg(target_os = "macos")] + let entry = dirs::home_dir().map(|home| { + home + .join("Library/LaunchAgents") + .join(format!("{LAUNCH_AGENT_LABEL}.plist")) + }); + #[cfg(target_os = "linux")] + let entry = dirs::config_dir().map(|config| config.join("autostart/donut-daemon.desktop")); + + if let Some(path) = entry { + match remove_entry(&path, unload) { + Ok(true) => log::info!("Legacy daemon autostart removed path={}", path.display()), + Ok(false) => {} + Err(e) => log::warn!( + "Legacy daemon autostart removal failed path={} err=\"{e}\"", + path.display() + ), + } + } + } + + #[cfg(target_os = "windows")] + { + use winreg::enums::{HKEY_CURRENT_USER, KEY_QUERY_VALUE, KEY_SET_VALUE}; + use winreg::RegKey; + + let Ok(run) = RegKey::predef(HKEY_CURRENT_USER).open_subkey_with_flags( + r"Software\Microsoft\Windows\CurrentVersion\Run", + KEY_QUERY_VALUE | KEY_SET_VALUE, + ) else { + return; + }; + match run.delete_value("DonutBrowserDaemon") { + Ok(()) => log::info!("Legacy daemon autostart removed key=HKCU\\Run\\DonutBrowserDaemon"), + Err(e) if e.kind() == io::ErrorKind::NotFound => {} + Err(e) => log::warn!( + "Legacy daemon autostart removal failed key=HKCU\\Run\\DonutBrowserDaemon err=\"{e}\"" + ), + } + } +} + +#[cfg(target_os = "macos")] +const LAUNCH_AGENT_LABEL: &str = "com.donutbrowser.daemon"; + +/// Deleting the plist alone leaves the job loaded until the next login. +#[cfg(target_os = "macos")] +fn unload() { + let target = format!("gui/{}/{LAUNCH_AGENT_LABEL}", unsafe { libc::getuid() }); + match std::process::Command::new("launchctl") + .args(["bootout", &target]) + .output() + { + Ok(output) if output.status.success() => { + log::info!("Legacy daemon LaunchAgent unloaded target={target}"); + } + Ok(_) => {} + Err(e) => log::warn!("launchctl bootout failed target={target} err=\"{e}\""), + } +} + +#[cfg(target_os = "linux")] +fn unload() {} + +/// Delete the entry at `path`, calling `unload` first. `Ok(false)` when there +/// is no entry, in which case `unload` is not called. +#[cfg_attr(target_os = "windows", allow(dead_code))] +fn remove_entry(path: &Path, unload: impl FnOnce()) -> io::Result { + if path.symlink_metadata().is_err() { + return Ok(false); + } + unload(); + std::fs::remove_file(path)?; + Ok(true) +} + +#[cfg(test)] +mod tests { + use super::remove_entry; + use std::cell::Cell; + + #[test] + fn an_entry_is_unloaded_then_deleted() { + let dir = tempfile::tempdir().unwrap(); + let path = dir.path().join("com.donutbrowser.daemon.plist"); + std::fs::write(&path, "").unwrap(); + let unloaded = Cell::new(false); + + let removed = remove_entry(&path, || { + assert!(path.exists(), "unload runs while the entry still exists"); + unloaded.set(true); + }) + .unwrap(); + + assert!(removed); + assert!(unloaded.get()); + assert!(!path.exists()); + } + + #[test] + fn a_missing_entry_is_left_alone() { + let dir = tempfile::tempdir().unwrap(); + let unloaded = Cell::new(false); + + let removed = remove_entry(&dir.path().join("donut-daemon.desktop"), || { + unloaded.set(true) + }) + .unwrap(); + + assert!(!removed); + assert!( + !unloaded.get(), + "nothing is unloaded when there is no entry" + ); + } +} diff --git a/src-tauri/src/lib.rs b/src-tauri/src/lib.rs index a1903065..0d846950 100644 --- a/src-tauri/src/lib.rs +++ b/src-tauri/src/lib.rs @@ -34,6 +34,25 @@ pub(crate) fn vless_config_error(error: &crate::xray::XrayError) -> String { .to_string() } +/// `donutbrowser_lib::sync::scheduler` -> `sync::scheduler`, `lib.rs` itself +/// -> `app`, and `webview::