diff --git a/Cargo.lock b/Cargo.lock index bc982fc..ec6335a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3372,7 +3372,7 @@ checksum = "2ee67f1008b1ba2321834326597b8e186293b049a023cdef258527550b9935b4" [[package]] name = "pdfs-cli" -version = "1.11.0" +version = "1.11.1" dependencies = [ "anyhow", "clap", @@ -3387,7 +3387,7 @@ dependencies = [ [[package]] name = "pdfs-core" -version = "1.11.0" +version = "1.11.1" dependencies = [ "async-trait", "dbus-secret-service-keyring-store", @@ -3411,7 +3411,7 @@ dependencies = [ [[package]] name = "pdfs-fuse" -version = "1.11.0" +version = "1.11.1" dependencies = [ "base64 0.23.1", "fuser", @@ -3431,7 +3431,7 @@ dependencies = [ [[package]] name = "pdfs-gui" -version = "1.11.0" +version = "1.11.1" dependencies = [ "anyhow", "async-channel", diff --git a/Cargo.toml b/Cargo.toml index 63c95f4..67c5b15 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -3,7 +3,7 @@ resolver = "2" members = ["crates/pdfs-core", "crates/pdfs-fuse", "crates/pdfs-cli", "crates/pdfs-gui"] [workspace.package] -version = "1.11.0" +version = "1.11.1" edition = "2024" license = "MIT" authors = ["Nils Pukropp "] diff --git a/crates/pdfs-core/src/db/mod.rs b/crates/pdfs-core/src/db/mod.rs index 63e2da3..5f5559c 100644 --- a/crates/pdfs-core/src/db/mod.rs +++ b/crates/pdfs-core/src/db/mod.rs @@ -56,8 +56,8 @@ pub use local::LocalFileHit; pub use maintenance::{DbStats, VacuumOutcome}; pub use nodes::{PublishedSharedRoot, SearchHit, StoredNode}; pub use ops::{ - AttachedBlob, LOCAL_VOLUME, OP_CREATE, OP_MKDIR, OP_RENAME, OP_REVISION, OP_TRASH, PARK_UNTIL, - PendingCounts, PendingOp, RenameMeta, op_supersedes, + AttachedBlob, LOCAL_VOLUME, OP_CREATE, OP_MKDIR, OP_RENAME, OP_REVISION, OP_TRASH, + PARK_EXPIRY_MS, PARK_UNTIL, PendingCounts, PendingOp, RenameMeta, op_supersedes, }; pub use photos::{StoredPhoto, THUMB_HAVE, THUMB_NONE, THUMB_UNKNOWN, TimelineRow}; pub use pins::PinRow; diff --git a/crates/pdfs-core/src/db/ops.rs b/crates/pdfs-core/src/db/ops.rs index 89b5091..b21d87a 100644 --- a/crates/pdfs-core/src/db/ops.rs +++ b/crates/pdfs-core/src/db/ops.rs @@ -84,6 +84,25 @@ pub const LOCAL_VOLUME: &str = "local"; /// stall+resume, fork a `(sync-conflict)` copy (docs/BUGS.md B70). pub const PARK_UNTIL: i64 = 8_000_000_000_000; +/// How long a create may stay parked before the park is treated as permanent +/// and the bytes are let through anyway (ms). +/// +/// The park has exactly one exit: a rename from the transient name to the +/// finished one. Every writer that reaches that rename does so in seconds — an +/// atomic-write scratch file immediately, a download when it completes. A park +/// still standing an hour later belongs to a writer that will never perform +/// that rename: an editor that deletes its swap file instead, a download the +/// user abandoned, or a file that simply *is* named `report.tmp` and is never +/// going to be called anything else. +/// +/// Before this existed such a row sat at [`PARK_UNTIL`] for the life of the +/// database, holding the only copy of the file's bytes in `staging/` and +/// counting against the queue while promising progress that could not come. The +/// sweep un-parks it instead of dropping it: bytes the user can see in the mount +/// are bytes the user expects on Drive, and invariant 1 of the drain (a staged +/// blob is dropped only once its op has landed) admits no other answer. +pub const PARK_EXPIRY_MS: i64 = 60 * 60 * 1000; + /// A mutation that has been accepted locally but not yet performed against the /// API — the durable half of the write-back queue (offline.md Phase 3). /// @@ -661,6 +680,40 @@ impl Db { Ok(rows) } + /// Every parked create/mkdir, oldest first, for the park sweep. + /// + /// Parked rows are invisible to [`next_due_op`](Self::next_due_op) by + /// construction, so nothing else in the drain ever looks at them. This is + /// the one query that does. + pub fn parked_create_ops(&self) -> Result> { + let conn = self.read(); + let mut stmt = conn.prepare( + "SELECT id, kind, uid, parent_uid, name, blob_path, meta_json, created_at, + attempts, last_error, next_attempt_at + FROM pending_op + WHERE next_attempt_at >= ?1 AND kind IN (?2, ?3) + ORDER BY created_at", + )?; + let rows = stmt + .query_map(params![PARK_UNTIL, OP_CREATE, OP_MKDIR], |r| { + Ok(PendingOp { + id: r.get(0)?, + kind: r.get(1)?, + uid: r.get(2)?, + parent_uid: r.get(3)?, + name: r.get(4)?, + blob_path: r.get(5)?, + meta_json: r.get(6)?, + created_at: r.get(7)?, + attempts: r.get(8)?, + last_error: r.get(9)?, + next_attempt_at: r.get(10)?, + }) + })? + .collect::, _>>()?; + Ok(rows) + } + /// How many queued ops there are of each kind, for `Response::Status`. /// /// Split because "3 uploads queued" has to mean three files whose bytes are diff --git a/crates/pdfs-core/src/db/tests.rs b/crates/pdfs-core/src/db/tests.rs index f885e6c..7c10593 100644 --- a/crates/pdfs-core/src/db/tests.rs +++ b/crates/pdfs-core/src/db/tests.rs @@ -3049,6 +3049,57 @@ fn a_parked_transient_create_stays_off_the_drain_until_finalized() { assert_eq!(due.blob_path.as_deref(), Some("/staging/blob1")); } +/// The park sweep's query: parked creates are the rows nothing else in the drain +/// can see, so it has to find them by the sentinel and report how long each has +/// been parked. Ordinary queued work is not its business. +#[test] +fn parked_creates_are_listed_with_the_age_the_sweep_judges_them_by() { + let db = Db::open_in_memory().unwrap(); + let parent = uid("root").to_string(); + let parked = uid("swap").to_string(); + let due = uid("ordinary").to_string(); + for (node, name, next_attempt_at, created_at) in [ + (&parked, ".notes.txt.swp", PARK_UNTIL, 1_000), + (&due, "notes.txt", 0, 2_000), + ] { + db.enqueue_op(&PendingOp { + id: 0, + kind: OP_CREATE.to_string(), + uid: node.clone(), + parent_uid: Some(parent.clone()), + name: Some(name.to_string()), + blob_path: Some(format!("/staging/{name}")), + meta_json: None, + created_at, + attempts: 0, + last_error: None, + next_attempt_at, + }) + .unwrap(); + } + + let rows = db.parked_create_ops().unwrap(); + assert_eq!(rows.len(), 1, "only the parked create is swept"); + assert_eq!(rows[0].uid, parked); + assert_eq!(rows[0].created_at, 1_000, "the park's age is readable"); + assert_eq!( + rows[0].blob_path.as_deref(), + Some("/staging/.notes.txt.swp") + ); + + // What the sweep does with an expired park: un-park it, and it drains like + // any other create rather than waiting for a rename that is not coming. + assert!(db.set_create_hold(&parked, false).unwrap()); + assert!( + db.parked_create_ops().unwrap().is_empty(), + "an un-parked create is no longer the sweep's business" + ); + assert_eq!( + db.next_due_op(1_000 + PARK_EXPIRY_MS).unwrap().unwrap().uid, + parked + ); +} + /// Backoff still gates: nothing is returned before an op is due. #[test] fn next_due_op_respects_backoff() { diff --git a/crates/pdfs-core/src/syncignore.rs b/crates/pdfs-core/src/syncignore.rs index a91a534..6dd1b0b 100644 --- a/crates/pdfs-core/src/syncignore.rs +++ b/crates/pdfs-core/src/syncignore.rs @@ -45,18 +45,30 @@ pub const DEFAULT_IGNORE_PATTERNS: &[&str] = &[ "Thumbs.db", ]; -/// Suffixes of files that are, by convention, incomplete or throwaway while they -/// wear the name: a download in flight, an editor's swap or backup, an atomic -/// write's scratch copy. On an on-demand mount these should never seal a remote -/// revision — the app renames the finished file to its real name, and only that -/// belongs on Drive. See [`is_transient_name`] and docs/BUGS.md B70. +/// Suffixes that mean a file is incomplete *by construction*: only the program +/// writing it gives it this name, only while the write is in flight, and the +/// finished article always arrives under a different one. On an on-demand mount +/// these should never seal a remote revision — the app renames the finished file +/// to its real name, and only that belongs on Drive. See [`is_transient_name`] +/// and docs/BUGS.md B70. +/// +/// `.tmp`/`.temp` are deliberately **not** here, though they are in +/// [`DEFAULT_IGNORE_PATTERNS`]. The two lists answer different questions. Skipping +/// a `report.tmp` during a mirror reconcile costs nothing — the file stays on +/// disk, and a later pass picks it up if the rules change. Parking one on the +/// on-demand mount is irreversible in practice: the only exit is a rename to a +/// finished name, and a file that is simply *called* `index.tmp` — a static-site +/// template, a tool's output — never gets one. It then never reaches Drive at +/// all, silently, while its bytes pin `staging/`. That is what a real Takeout +/// tree of `index.tmp`/`preview.tmp` gallery templates did: 43 creates parked +/// forever. The generic-scratch case they were added for renames within +/// milliseconds, so it never needed the park; the download suffixes below, which +/// stay in flight for minutes, are what B70 was actually about. const TRANSIENT_SUFFIXES: &[&str] = &[ ".crdownload", // Chromium/Brave/Edge ".part", // Firefox, wget, aria2c ".partial", // some downloaders / older IE ".download", // Safari / macOS - ".tmp", // generic scratch - ".temp", // generic scratch ".swp", // vim swap ".swx", // vim swap (secondary) ]; @@ -319,8 +331,6 @@ mod tests { "movie.mkv.part", "big.iso.partial", "photo.jpg.download", - "export.xml.tmp", - "notes.TEMP", ".notes.txt.swp", "doc.txt~", ".~lock.report.odt#", @@ -340,6 +350,10 @@ mod tests { "archive.partly.zip", // ".partly" is not ".part" "template.dotx", "readme", + // A file that is *named* `.tmp` and never renamed: parking it would + // keep it off Drive for good. + "index.tmp", + "notes.TEMP", ] { assert!(!is_transient_name(name), "{name} should not be transient"); } diff --git a/crates/pdfs-fuse/src/control.rs b/crates/pdfs-fuse/src/control.rs index cd687f6..8aa28fd 100644 --- a/crates/pdfs-fuse/src/control.rs +++ b/crates/pdfs-fuse/src/control.rs @@ -22,7 +22,7 @@ use pdfs_core::control::{ }; use pdfs_core::{CoreError, CoreResult}; use proton_drive_rs::proton_sdk::ids::NodeUid; -use tracing::{info, warn}; +use tracing::{debug, info, warn}; use super::transfers::CountingReader; use super::{Core, count_noun, human_bytes, human_duration, parse_uid}; @@ -164,6 +164,50 @@ fn rel_to_mount(mountpoint: &Path, path: &str) -> CoreResult { /// Handle one control-socket connection: read a single JSON request line, /// dispatch it against `core`, and write back a JSON response line. +/// Refresh scopes being served right now, one entry per running refresh. +/// +/// A `Vec` because there are three scopes and at most `MAX_CONTROL_HANDLERS` +/// handlers, so a set would buy nothing. +static REFRESHING: std::sync::Mutex> = std::sync::Mutex::new(Vec::new()); + +/// What makes two refreshes the same work: the scope, and for a directory the +/// folder, since refreshing one folder says nothing about another. A full +/// photos refresh is not the same work as an ordinary one — it forgets what the +/// daemon knows first — so it keys apart. +fn scope_key(scope: &RefreshScope) -> String { + match scope { + RefreshScope::Dir { path } => format!("dir:{path}"), + RefreshScope::Trash => "trash".to_string(), + RefreshScope::Photos { full: true } => "photos:full".to_string(), + RefreshScope::Photos { full: false } => "photos".to_string(), + } +} + +/// Holds one refresh scope for as long as it is being served. `acquire` +/// returns `None` when that scope is already in flight. +struct RefreshGuard(String); + +impl RefreshGuard { + fn acquire(scope: &RefreshScope) -> Option { + let key = scope_key(scope); + let mut running = REFRESHING.lock().unwrap_or_else(|e| e.into_inner()); + if running.contains(&key) { + return None; + } + running.push(key.clone()); + Some(Self(key)) + } +} + +impl Drop for RefreshGuard { + fn drop(&mut self) { + let mut running = REFRESHING.lock().unwrap_or_else(|e| e.into_inner()); + if let Some(at) = running.iter().position(|key| *key == self.0) { + running.swap_remove(at); + } + } +} + fn handle_control_conn(core: &Core, username: &str, mountpoint: &Path, stream: UnixStream) { if let Err(e) = stream.set_read_timeout(Some(CONTROL_READ_TIMEOUT)) { warn!(error = %e, "control: could not set request timeout"); @@ -247,45 +291,69 @@ fn handle_control_conn(core: &Core, username: &str, mountpoint: &Path, stream: U }, Err(e) => CtlResponse::error(e), }, - Ok(CtlRequest::Refresh { scope }) => { - let result = match &scope { - RefreshScope::Dir { path } => route_to_mount(core, mountpoint, path) - .and_then(|(core, rel)| core.refresh_dir(&rel)), - RefreshScope::Trash => { - core.invalidate_trash(); - Ok(()) + Ok(CtlRequest::Refresh { scope }) => match RefreshGuard::acquire(&scope) { + // The same scope is already being refreshed by another handler. + // Running it again cannot make the answer newer, and the duplicate + // would spend its whole run contending for the state and database + // locks the first one holds — which is how five stacked photo + // refreshes sat in flight for twenty-three minutes at mount time. + None => { + debug!(scope = %scope_key(&scope), "a refresh of this scope is already running"); + CtlResponse::Ok { + message: "refreshing".to_string(), } - RefreshScope::Photos { full } => { - core.invalidate_photos(); - // A full refresh is "forget what you know", not a second code - // path: the ordinary refresh then finds every photo stale. - if let Some(Err(e)) = full.then(|| core.db.photos_mark_all_unresolved()) { - warn!(error = %e, "marking the whole timeline unresolved failed"); - } - // Whatever changed the timeline can just as easily have - // changed an album; one scope covers the whole photos view. - core.invalidate_albums(); - // The refresh is started here, not awaited. A library of - // twelve thousand photos is re-read in chunks of - // `TIMELINE_ENRICH_CHUNK` nodes, which takes minutes — - // longer than the client's read bound, so awaiting it - // returned `Resource temporarily unavailable` to a caller - // whose refresh was in fact running fine (B92). The front - // end follows it with `PhotosRefreshStatus`. - core.spawn_timeline_refresh(); - Ok(()) - } - }; - match result { - Ok(()) => CtlResponse::Ok { - message: match scope { - RefreshScope::Photos { .. } => "refreshing".to_string(), - _ => "refreshed".to_string(), - }, - }, - Err(e) => CtlResponse::error(e), } - } + Some(_refreshing) => { + let result = match &scope { + RefreshScope::Dir { path } => route_to_mount(core, mountpoint, path) + .and_then(|(core, rel)| core.refresh_dir(&rel)), + RefreshScope::Trash => { + core.invalidate_trash(); + Ok(()) + } + RefreshScope::Photos { full } if !full && core.timeline_refreshing() => { + // A refresh is already running and will publish exactly the + // timeline this request asks for. Doing the work again + // cannot make it newer, and the invalidation plus the + // album read contend with the running refresh for the + // database lock — which is how a handful of stacked photo + // refreshes at mount time left five control requests + // in flight for twenty-three minutes. + debug!("a photos refresh is already running; joining it"); + Ok(()) + } + RefreshScope::Photos { full } => { + core.invalidate_photos(); + // A full refresh is "forget what you know", not a second code + // path: the ordinary refresh then finds every photo stale. + if let Some(Err(e)) = full.then(|| core.db.photos_mark_all_unresolved()) { + warn!(error = %e, "marking the whole timeline unresolved failed"); + } + // Whatever changed the timeline can just as easily have + // changed an album; one scope covers the whole photos view. + core.invalidate_albums(); + // The refresh is started here, not awaited. A library of + // twelve thousand photos is re-read in chunks of + // `TIMELINE_ENRICH_CHUNK` nodes, which takes minutes — + // longer than the client's read bound, so awaiting it + // returned `Resource temporarily unavailable` to a caller + // whose refresh was in fact running fine (B92). The front + // end follows it with `PhotosRefreshStatus`. + core.spawn_timeline_refresh(); + Ok(()) + } + }; + match result { + Ok(()) => CtlResponse::Ok { + message: match scope { + RefreshScope::Photos { .. } => "refreshing".to_string(), + _ => "refreshed".to_string(), + }, + }, + Err(e) => CtlResponse::error(e), + } + } + }, Ok(CtlRequest::PhotosTimeline { offset, limit, @@ -1370,3 +1438,28 @@ mod request_limit_tests { assert!(rel_to_mount(mountpoint, "/mnt/elsewhere").is_err()); } } + +#[cfg(test)] +mod tests { + use super::*; + + /// Two refreshes of the same scope are one piece of work; two refreshes of + /// different scopes are not. + #[test] + fn a_scope_refreshes_once_at_a_time() { + let photos = RefreshScope::Photos { full: false }; + let held = RefreshGuard::acquire(&photos).expect("first refresh runs"); + assert!(RefreshGuard::acquire(&photos).is_none()); + // A full refresh forgets what the daemon knows, so it is other work. + assert!(RefreshGuard::acquire(&RefreshScope::Photos { full: true }).is_some()); + assert!( + RefreshGuard::acquire(&RefreshScope::Dir { + path: "a".to_string() + }) + .is_some() + ); + + drop(held); + assert!(RefreshGuard::acquire(&photos).is_some()); + } +} diff --git a/crates/pdfs-fuse/src/diagnostics.rs b/crates/pdfs-fuse/src/diagnostics.rs index fa9c6a2..5cde5df 100644 --- a/crates/pdfs-fuse/src/diagnostics.rs +++ b/crates/pdfs-fuse/src/diagnostics.rs @@ -73,7 +73,29 @@ pub(crate) fn request_kind(line: &str) -> String { line.strip_prefix('"') .and_then(|rest| rest.split('"').next()) }; - name.unwrap_or("unknown").to_string() + let name = name.unwrap_or("unknown"); + // A bare `Refresh` says nothing about which view wedged, and the three + // scopes cost wildly different amounts of work: a directory refresh is two + // cheap calls, a photos refresh can pull a whole library. The scope is one + // more peek into the same line. + if name == "Refresh" + && let Some(scope) = tagged_name_after(line, "\"scope\"") + { + return format!("Refresh({scope})"); + } + name.to_string() +} + +/// The variant name serde wrote for the value of `key`, whether that value is a +/// bare string (a unit variant) or an object whose single key is the name. +fn tagged_name_after(line: &str, key: &str) -> Option { + let rest = line.split_once(key)?.1.trim_start(); + let rest = rest.strip_prefix(':')?.trim_start(); + let rest = rest.strip_prefix('{').map_or(rest, str::trim_start); + rest.strip_prefix('"')? + .split('"') + .next() + .map(str::to_string) } /// Resident set size in bytes, or `0` when `/proc` did not answer. @@ -181,6 +203,26 @@ mod tests { assert_eq!(request_kind("garbage"), "unknown"); } + /// A stuck `Refresh` is only actionable if the report says which view it + /// was refreshing, so the scope rides along with the name. + #[test] + fn a_refresh_reports_its_scope() { + assert_eq!( + request_kind("{\"Refresh\":{\"scope\":{\"Photos\":{\"full\":true}}}}"), + "Refresh(Photos)" + ); + assert_eq!( + request_kind("{\"Refresh\":{\"scope\":{\"Dir\":{\"path\":\"a\"}}}}"), + "Refresh(Dir)" + ); + assert_eq!( + request_kind("{\"Refresh\":{\"scope\":\"Trash\"}}"), + "Refresh(Trash)" + ); + // A shape this does not recognise still names the request. + assert_eq!(request_kind("{\"Refresh\":{}}"), "Refresh"); + } + /// A guard registers for its lifetime and nothing longer: a handler that /// returns must not leave a permanent "in flight" entry behind. #[test] diff --git a/crates/pdfs-fuse/src/drain.rs b/crates/pdfs-fuse/src/drain.rs index 82f459f..62cebaf 100644 --- a/crates/pdfs-fuse/src/drain.rs +++ b/crates/pdfs-fuse/src/drain.rs @@ -33,7 +33,9 @@ use futures::StreamExt; use pdfs_core::batch; use pdfs_core::cache::{Baseline, StagedWrite}; use pdfs_core::control::{ActivityKind, TransferDirection}; -use pdfs_core::db::{OP_CREATE, OP_MKDIR, OP_RENAME, OP_REVISION, OP_TRASH, PendingOp, RenameMeta}; +use pdfs_core::db::{ + OP_CREATE, OP_MKDIR, OP_RENAME, OP_REVISION, OP_TRASH, PARK_EXPIRY_MS, PendingOp, RenameMeta, +}; use proton_drive_rs::proton_sdk::error::ProtonError; use proton_drive_rs::proton_sdk::ids::NodeUid; use proton_drive_rs::{Node, NodeMoveItem}; @@ -299,6 +301,10 @@ impl Core { // Cheap and a no-op when empty. self.cache.flush_touches(); self.recover_fsynced_writes(); + // Parked rows are invisible to `claim_next_due_op`, so + // an idle queue is exactly when a park that has outlived + // its writer has to be noticed. + self.sweep_parked_creates(); } // A debounced or backed-off op may be waiting: sleep only // until it becomes due rather than the full idle-poll. @@ -1201,6 +1207,101 @@ impl Core { Ok(()) } + /// Whether any mount still holds an open handle on `uid`. + /// + /// A transient file that is still open is still being written, however long + /// it has been parked, and the rename that finishes it has not happened yet. + fn uid_is_open(&self, uid: &NodeUid) -> bool { + let mut open = false; + self.for_each_state(|st| { + if open { + return; + } + open = st + .by_uid + .get(uid) + .and_then(|ino| st.entries.get(ino)) + .is_some_and(|entry| entry.open_count > 0); + }); + open + } + + /// Retire parks that are never going to end (docs/BUGS.md B70). + /// + /// A parked create waits for one event: the rename from the transient name + /// to the finished one. Nothing else ever un-parks it, and plenty of writers + /// never perform it — an editor unlinks its swap file, a download is + /// abandoned, or the file was always going to be called `index.tmp`. Such a + /// row stayed at [`PARK_UNTIL`] for the life of the database, pinning the + /// only copy of its bytes in `staging/` and counting against the queue. + /// + /// Two outcomes, and neither deletes bytes a user can still see: + /// + /// * The node is gone from the tree — the file was deleted while its create + /// was parked, so the create is no longer wanted. The op and its blob go, + /// which is what [`Core::discard_queued_ops`] would have done had the + /// delete path reached it. + /// * The node is still there and has been parked past + /// [`PARK_EXPIRY_MS`] with nothing holding it open — the park has outlived + /// the writer it was protecting. Un-park it, and the ordinary drain + /// uploads it like any other create. + /// + /// An open node is left alone whatever its age: it is still being written. + fn sweep_parked_creates(&self) { + let parked = match self.db.parked_create_ops() { + Ok(parked) if !parked.is_empty() => parked, + Ok(_) => return, + Err(error) => { + warn!(%error, "reading parked creates failed; skipping the park sweep"); + return; + } + }; + let now = now_millis(); + let (mut released, mut dropped) = (0usize, 0usize); + for op in &parked { + let Some(uid) = parse_node_uid(&op.uid) else { + continue; + }; + let name = op.name.as_deref().unwrap_or("?"); + let known = match self.db.node_by_uid(&op.uid) { + Ok(known) => known.is_some(), + // Never infer "deleted" from a failed read: that would discard + // the bytes over a transient database error. + Err(error) => { + debug!(%uid, %error, "cannot tell whether a parked node still exists"); + continue; + } + }; + if !known { + if let Err(error) = self.discard_queued_ops(&uid) { + warn!(%uid, name, ?error, "dropping a deleted transient's parked create failed"); + continue; + } + dropped += 1; + debug!(%uid, name, "dropped a parked create whose file was deleted"); + continue; + } + if park_verdict(op.created_at, now, self.uid_is_open(&uid)) != ParkVerdict::Release { + continue; + } + match self.db.set_create_hold(&op.uid, false) { + Ok(true) => { + released += 1; + info!(%uid, name, parked_ms = now - op.created_at, + "un-parked a transient create that was never renamed; uploading it"); + } + Ok(false) => {} + Err(error) => warn!(%uid, name, %error, "un-parking an expired park failed"), + } + } + if released > 0 || dropped > 0 { + info!(released, dropped, "swept parked creates"); + } + if released > 0 { + self.wake_drain(); + } + } + /// Drop `uid`'s pending entry, but only while it still names `blob`. /// /// A supersede can replace the entry while the op that owned it is in @@ -1573,6 +1674,24 @@ fn is_own_self_supersede(complete: bool, remote_rev: Option<&str>, own_rev: Opti complete && remote_rev.is_some() && remote_rev == own_rev } +/// What the park sweep does with one parked create whose node still exists. +#[derive(Debug, PartialEq, Eq)] +enum ParkVerdict { + /// Leave it parked: the rename it waits for can still come. + Keep, + /// Un-park it: nothing will rename it now, so the bytes go up as they are. + Release, +} + +/// Judge one parked create by age alone. An open node is kept whatever its age +/// — it is still being written, and the rename is the writer's last step. +fn park_verdict(created_at: i64, now: i64, open: bool) -> ParkVerdict { + if open || now - created_at < PARK_EXPIRY_MS { + return ParkVerdict::Keep; + } + ParkVerdict::Release +} + #[cfg(test)] mod tests { use super::*; @@ -1598,6 +1717,28 @@ mod tests { } } + /// The park's only ordinary exit is the transient-to-final rename. The + /// sweep is what happens when that rename never comes. + #[test] + fn a_park_expires_only_once_it_is_old_and_nobody_holds_the_file() { + let now = PARK_EXPIRY_MS * 10; + // Fresh: the writer may still rename it. + assert_eq!( + park_verdict(now - PARK_EXPIRY_MS + 1, now, false), + ParkVerdict::Keep + ); + // Old, but still open: a slow write is not an abandoned one. + assert_eq!( + park_verdict(now - PARK_EXPIRY_MS, now, true), + ParkVerdict::Keep + ); + // Old and closed: no rename is coming. + assert_eq!( + park_verdict(now - PARK_EXPIRY_MS, now, false), + ParkVerdict::Release + ); + } + #[test] fn drain_authorities_match_each_operation_kind() { for kind in [OP_REVISION, OP_TRASH] { diff --git a/crates/pdfs-fuse/src/lib.rs b/crates/pdfs-fuse/src/lib.rs index 7cd201a..dfaf9a8 100644 --- a/crates/pdfs-fuse/src/lib.rs +++ b/crates/pdfs-fuse/src/lib.rs @@ -197,6 +197,22 @@ const UPLOAD_TIME_MEMORY: usize = 512; /// for the SDK's own per-request concurrency. const DRAIN_WORKERS: usize = 3; +/// How long a staged blob that names no node is kept before it is retired. +/// +/// Staging is exempt from the cache budget because it holds the only copy of +/// writes that have not been uploaded, so nothing there is ever evicted to +/// reclaim space. That is right for a blob that still describes something. It is +/// wrong for one whose sidecar is missing or names a `local~` placeholder whose +/// create is gone: no future run can address it, no UI accounts for it, and it +/// occupies disk for the life of the machine. Real instance: 95 such blobs, +/// ~445 MiB, the oldest two months old, re-announced on every mount. +/// +/// A month is far longer than any transfer or any plausible "I will look at that +/// later", and the retirement is announced per blob with its size, so the one +/// case that matters — bytes a human still wants — has a month of warnings and a +/// path to go and fetch them from. +const STAGING_ORPHAN_RETAIN: Duration = Duration::from_secs(30 * 24 * 60 * 60); + const ONLINE_PROBE_MIN: Duration = Duration::from_secs(5); const ONLINE_PROBE_MAX: Duration = Duration::from_secs(300); /// How long the persisted photos timeline stays good before a page request @@ -1394,6 +1410,15 @@ fn release_must_retain_queued_trash(db: &Db, uid: &NodeUid) -> pdfs_core::Result db.has_pending_op(&uid.to_string(), OP_TRASH) } +/// The size of a staged blob that has outlived [`STAGING_ORPHAN_RETAIN`], or +/// `None` while it is younger than that — or while its age cannot be read at +/// all, which is never grounds for deleting bytes. +fn orphan_past_retention(blob: &Path) -> Option { + let meta = std::fs::metadata(blob).ok()?; + let age = meta.modified().ok()?.elapsed().ok()?; + (age >= STAGING_ORPHAN_RETAIN).then_some(meta.len()) +} + fn release_can_discard_unlinked(db: &Db, uid: &NodeUid) -> bool { match release_must_retain_queued_trash(db, uid) { Ok(retain) => !retain, @@ -1718,6 +1743,9 @@ impl Core { }; let mut queued = 0usize; let mut stranded = 0usize; + let mut retired = 0usize; + let mut retired_bytes = 0u64; + let mut example: Option = None; for (blob, meta) in staged { if claimed.contains(&blob.to_string_lossy().into_owned()) { continue; @@ -1725,9 +1753,17 @@ impl Core { let addressable = meta.as_ref().and_then(|m| parse_node_uid(&m.uid)); let Some((meta, uid)) = meta.zip(addressable).filter(|(_, uid)| !is_local_uid(uid)) else { + if let Some(bytes) = orphan_past_retention(&blob) { + retired += 1; + retired_bytes += bytes; + warn!(blob = %blob.display(), bytes, + age_days = STAGING_ORPHAN_RETAIN.as_secs() / 86_400, + "retiring staged bytes that name no node and have outlived retention"); + self.cache.discard_staged(&blob); + continue; + } stranded += 1; - warn!(blob = %blob.display(), - "staged bytes belong to no queued upload and name no node; kept for recovery"); + example.get_or_insert_with(|| blob.clone()); continue; }; if self.pending.lock().contains_key(&uid) { @@ -1773,8 +1809,21 @@ impl Core { } } } - if queued > 0 || stranded > 0 { - info!(queued, stranded, "reconciled orphaned staged writes"); + if stranded > 0 { + // One line, not one per blob. A tree of them says exactly as much as + // a single count and an example does, and said it on every mount: + // 86 identical warnings for the same 86 files, boot after boot. + warn!( + count = stranded, + example = %example.map(|b| b.display().to_string()).unwrap_or_default(), + "staged bytes belong to no queued upload and name no node; kept for recovery" + ); + } + if queued > 0 || stranded > 0 || retired > 0 { + info!( + queued, + stranded, retired, retired_bytes, "reconciled orphaned staged writes" + ); } } @@ -6124,14 +6173,64 @@ mod tests { Access, AccessFlags, Errno, HashMap, Intervals, PendingRevision, RootListingSnapshot, SELF_CHANGE_TTL_MS, ShareId, SharedWithMeItem, StateRegistry, VirtualRootPlan, accepted_share_provenance, conflict_name, copy_pending_for_truncate, expand_restore, - fuse_name, is_stale_mount, node_visible, note_self_change, parse_node_uid, - prepare_shared_roots, preserve_on_access_denied, publish_virtual_root_in_listing, - reconcile_virtual_root_in_listing, release_can_discard_unlinked, - release_must_retain_queued_trash, release_unlinked_entry, rename_needs_queue, - require_node_parent_access, require_rename_access, resolve_anywhere_with, - shared_with_me_uid, take_self_change, uid_write_authority, virtual_node, + fuse_name, is_stale_mount, node_visible, note_self_change, orphan_past_retention, + parse_node_uid, prepare_shared_roots, preserve_on_access_denied, + publish_virtual_root_in_listing, reconcile_virtual_root_in_listing, + release_can_discard_unlinked, release_must_retain_queued_trash, release_unlinked_entry, + rename_needs_queue, require_node_parent_access, require_rename_access, + resolve_anywhere_with, shared_with_me_uid, take_self_change, uid_write_authority, + virtual_node, }; use super::{Db, WriteAuthority}; + use std::time::Duration; + + /// Staged bytes that name no node are kept for a month, because the only + /// copy of a write must outlive the bug that stranded it. Past that, one + /// boot retires them instead of re-announcing them every boot forever. + #[test] + fn a_stranded_blob_is_retired_only_once_it_outlives_retention() { + let dir = std::env::temp_dir().join(format!("pdfs-orphan-{}", std::process::id())); + std::fs::create_dir_all(&dir).unwrap(); + let blob = dir.join("blob"); + std::fs::write(&blob, b"twelve bytes").unwrap(); + + // Written just now: still recoverable, still kept. + assert_eq!(orphan_past_retention(&blob), None); + + set_mtime_ago( + &blob, + super::STAGING_ORPHAN_RETAIN + Duration::from_secs(60), + ); + assert_eq!(orphan_past_retention(&blob), Some(12)); + + // A blob that is not there is not a blob to retire. + std::fs::remove_file(&blob).unwrap(); + assert_eq!(orphan_past_retention(&blob), None); + let _ = std::fs::remove_dir_all(&dir); + } + + /// Backdate a file's mtime, which is what the retention check reads. + fn set_mtime_ago(path: &std::path::Path, ago: Duration) { + let when = std::time::SystemTime::now() - ago; + let secs = when + .duration_since(std::time::UNIX_EPOCH) + .unwrap() + .as_secs() as libc::time_t; + let times = [ + libc::timeval { + tv_sec: secs, + tv_usec: 0, + }, + libc::timeval { + tv_sec: secs, + tv_usec: 0, + }, + ]; + let c_path = std::ffi::CString::new(path.as_os_str().as_encoded_bytes()).unwrap(); + // SAFETY: both pointers are valid for the call and nothing keeps them. + let rc = unsafe { libc::utimes(c_path.as_ptr(), times.as_ptr()) }; + assert_eq!(rc, 0, "utimes: {}", std::io::Error::last_os_error()); + } /// `(uid, parent)` pairs in the shape [`Db::trash_parents`] returns. fn relations(pairs: &[(&str, Option<&str>)]) -> Vec<(String, Option)> { diff --git a/crates/pdfs-fuse/src/photos.rs b/crates/pdfs-fuse/src/photos.rs index c5689f2..a43ef59 100644 --- a/crates/pdfs-fuse/src/photos.rs +++ b/crates/pdfs-fuse/src/photos.rs @@ -1450,7 +1450,18 @@ impl Core { // so the relation is recorded from whichever end resolves — the two ends // can land in different chunks, and one of them may not resolve at all. let mut main_of: HashMap = HashMap::new(); + let mut stopped = false; for chunk in uids.chunks(TIMELINE_ENRICH_CHUNK) { + // Teardown cancels the runtime under this loop, and every chunk + // still in flight then fails its decrypt task — a burst of + // "skipping undecryptable photo ... task was cancelled" warnings + // that read like corruption and are only a shutdown. Stop asking + // for chunks instead. What resolved so far is kept below; the rest + // stay unresolved and are read by the next refresh. + if self.shutdown.is_stopping() { + stopped = true; + break; + } match photos.enumerate_nodes(chunk).await { Ok(nodes) => { for node in nodes { @@ -1521,10 +1532,14 @@ impl Core { // like it never happened, and the chunk count is what it scales with. info!( photos = rows.len(), - resolved = uids.len(), + // `resolved` is what came back, which is short of `wanted` when + // shutdown cut the pass off or a chunk failed. + resolved = meta.len(), + wanted = uids.len(), skipped = rows.len().saturating_sub(uids.len()), chunks = uids.len().div_ceil(TIMELINE_ENRICH_CHUNK), elapsed_ms = started.elapsed().as_millis() as u64, + stopped, "photos timeline refreshed" ); Ok(true) diff --git a/docs/BUGS.md b/docs/BUGS.md index 1788e20..7c0520f 100644 --- a/docs/BUGS.md +++ b/docs/BUGS.md @@ -12,6 +12,115 @@ Conventions: --- +## B97 — Photo refreshes stack up on the control socket, and shutdown turns the resolve pass into a burst of "undecryptable photo" warnings + +**Status:** Fixed (unverified) — the daemon carrying the change has not been driven against a real +library yet. +**Found:** 2026-09-19, while reading the journal for issues that were still open. `pdfs diagnostics` +had reported a `Refresh` running for 23 minutes with `in_flight` at 5, and every mount that ended +in a `systemctl --user restart` was followed by ~95 `skipping undecryptable photo` warnings. + +**Where:** `crates/pdfs-fuse/src/control.rs` (`Refresh` handler), `crates/pdfs-fuse/src/photos.rs` +(`refresh_timeline`), `crates/pdfs-fuse/src/diagnostics.rs` (`request_kind`). + +**Cause.** Two unrelated faults with one symptom each. + +The stall: every `Refresh` arm is individually cheap — a directory refresh resolves and +invalidates one listing, a photos refresh clears one state key and spawns the real work — but +nothing stopped several of them running at once. A front end that asks again while the first +refresh is still going gets a second handler that does the whole thing again: `invalidate_photos`, +optionally `photos_mark_all_unresolved` over the entire timeline, `invalidate_albums`. Each of +those takes the database lock the already-running refresh holds for minutes at a time, so the +duplicates queue behind it, hold a control handler slot, and appear as a wedged `Refresh`. The +report could not even say which view was wedged: `request_kind` reads only serde's external tag, +so all three scopes logged as a bare `Refresh`. + +The warning burst: `refresh_timeline` resolves photo metadata in chunks and keeps going through +teardown. The runtime is cancelled under it, every decrypt task in flight fails with "task was +cancelled", and the SDK logs one `skipping undecryptable photo` per node. Nothing was corrupt — +the library was fine on the next mount, because `photos_replace` preserves prior metadata and +leaves `resolved_at` null so the next refresh re-reads exactly those photos. + +**What changed.** A refresh scope is now single-flight: `RefreshGuard` holds the scope key +(`dir:`, `trash`, `photos`, `photos:full`) for as long as one is being served, and a second +request for that same key is answered `refreshing` immediately instead of repeating the work. A +non-full photos refresh is additionally skipped while `timeline_refreshing()` is true, since that +work outlives the request that started it. `request_kind` now names the scope, so the diagnostics +report says `Refresh(Photos)` rather than `Refresh`. And the resolve loop stops asking for chunks +once `Shutdown::is_stopping()`, logging `stopped` and the resolved-versus-wanted counts on the way +out. + +--- + +## B96 — Staged bytes that name no node are never retired, and are re-announced on every boot + +**Status:** Fixed (unverified). +**Found:** 2026-09-19, in the journal: the same "staged bytes belong to no queued upload" warning +appeared once per blob per mount, forever. The staging directory held 138 blobs / 575 MiB, of +which 95 (~445 MiB) referenced no node at all; the oldest were two months old. + +**Where:** `crates/pdfs-fuse/src/lib.rs` (`reconcile_staging`). + +**Cause.** Startup reconciliation is deliberately conservative: staged bytes are the only copy of +an un-uploaded write, so a blob it cannot match to a queued op is kept rather than deleted. But +"kept" had no end. A blob whose node is gone from the database can never be matched by any future +boot, so the warning was both permanent and per-blob, and the bytes accumulated with no ceiling. + +**What changed.** A blob that names no node and whose mtime is older than `STAGING_ORPHAN_RETAIN` +(30 days) is retired, with its size logged. A month is long enough that a write stranded by a bug +can still be recovered by hand. Younger orphans are still kept, but they are now counted and +reported as one aggregated warning with one example path, not one line each. + +--- + +## B95 — A real `index.tmp` is treated as a browser tempfile and parked forever + +**Status:** Fixed (unverified). +**Found:** 2026-09-19, while working out why 43 uploads were parked. Most of them were +`index.tmp` and `preview.tmp` files from a Google Photos Takeout import — ordinary files whose +final name simply ends in `.tmp`. + +**Where:** `crates/pdfs-core/src/syncignore.rs` (`TRANSIENT_SUFFIXES`). + +**Cause.** One suffix list served two mechanisms with very different consequences. On a mirror +mount, calling a name transient means "do not reconcile it yet", which is reversible and costs +nothing if wrong. On an on-demand mount it means "park the create until the writer renames it" +(B70) — and a file whose real, final name ends in `.tmp` is never renamed, so the park stands +forever and the bytes never go up. + +**What changed.** `.tmp` and `.temp` are out of `TRANSIENT_SUFFIXES`. The remaining suffixes +(`.crdownload`, `.part`, `.partial`, `.download`, `.swp`, `.swx`) belong to writers that always +rename. A `.tmp` write from a program that does rename is still handled — by the rename itself, +which supersedes the create. + +--- + +## B94 — A parked create has no exit but the rename, so an abandoned one is stuck forever + +**Status:** Fixed (unverified). +**Found:** 2026-09-19, while reading the journal: 43 rows in `pending_op` carried the +`PARK_UNTIL` sentinel, some for weeks. `pdfs status` reported them as parked uploads that never +moved. + +**Where:** `crates/pdfs-core/src/db/ops.rs` (`parked_create_ops`, `PARK_EXPIRY_MS`), +`crates/pdfs-fuse/src/drain.rs` (`sweep_parked_creates`). + +**Cause.** B70 parks a transient create by writing `PARK_UNTIL` into `next_attempt_at`, and the +only thing that clears it is the transient-to-final rename (`Db::set_create_hold`). If the rename +never happens — the writer crashed, the user deleted the temp file, or the name was never +transient in the first place (B95) — the row is invisible to `claim_next_due_op` and stays in the +queue permanently, holding its staged blob. + +**What changed.** The primary drain worker sweeps parked creates when the queue is idle, which is +exactly when a park that has outlived its writer matters. A parked create whose node is gone from +the database has its queued ops discarded. One whose node still exists, that is older than +`PARK_EXPIRY_MS` (1 hour) and that nobody has open, is un-parked rather than dropped — drain +invariant 1 says staged bytes are only dropped once their op has landed, so the sweep lets the +bytes through under the transient name instead of destroying them. An open node is left parked +whatever its age: it is still being written. + +--- + ## B93 — A photo whose node would not resolve lost its name, and with it its tab and its group **Status:** Fixed (unverified) — found and fixed while making the timeline refresh incremental diff --git a/docs/CHANGELOG.md b/docs/CHANGELOG.md index d12c987..5586cd9 100644 --- a/docs/CHANGELOG.md +++ b/docs/CHANGELOG.md @@ -9,6 +9,33 @@ release ships. Migrations are forward-only — a database written by a newer cli refuse-to-open, not a downgrade, so rolling back a release means restoring the cache from scratch (user data in `staging/` and `recovery/` is never touched by this). +## [1.11.1] — 2026-09-19 + +Schema: **30** (unchanged). + +### Fixed +- **An upload parked behind a temp-file rename no longer stays parked forever.** A create for a + name that looks like a writer's temporary file waits for the rename to the final name. If that + rename never came — the writer crashed, the file was deleted, or the name was never temporary — + the upload sat in the queue permanently, holding its staged bytes. The queue now sweeps parked + creates while it is idle: one whose file is gone is dropped, and one that has been parked for + over an hour with nobody holding it open is uploaded under the name it has. An open file is + left alone however old it is (B94). +- **A file whose real name ends in `.tmp` uploads normally.** `.tmp` and `.temp` were treated as + writer temp-file suffixes, so ordinary files — a Google Photos Takeout `index.tmp`, for + instance — were parked waiting for a rename that was never going to happen (B95). +- **Staged bytes that belong to nothing are cleaned up.** A staged blob that matches no queued + upload and names no node used to be kept forever and warned about once per blob on every mount. + Blobs older than 30 days are now retired with their size logged; younger ones are kept, but + reported as a single line instead of one per blob (B96). +- **Refreshing the gallery repeatedly no longer wedges the control socket.** Each refresh scope + now runs one at a time; asking again while one is running is answered immediately rather than + repeating work that contends with it for the database. `pdfs diagnostics` also names the scope + of a running refresh (B97). +- **Shutting down during a photo refresh no longer logs a wall of "undecryptable photo" + warnings.** The metadata pass stops when teardown begins instead of running into the cancelled + runtime. Nothing was wrong with those photos; the next refresh reads them again (B97). + ## [1.11.0] — 2026-09-19 Schema: **30** (`photos.content_hash` / `main_uid` / `group_key`); SDK bumped to `proton-sdk` / diff --git a/packaging/PKGBUILD b/packaging/PKGBUILD index f07e770..dd608f6 100644 --- a/packaging/PKGBUILD +++ b/packaging/PKGBUILD @@ -9,7 +9,7 @@ # Build + install: cd packaging && makepkg -fi pkgname=proton-drive-linux -pkgver=1.11.0 +pkgver=1.11.1 pkgrel=1 pkgdesc="Unofficial Proton Drive client for Linux: files-on-demand FUSE mount, CLI, GTK4 app + tray" arch=('x86_64')