diff --git a/crates/pdfs-fuse/src/drain.rs b/crates/pdfs-fuse/src/drain.rs index 71b18c0..037a488 100644 --- a/crates/pdfs-fuse/src/drain.rs +++ b/crates/pdfs-fuse/src/drain.rs @@ -766,17 +766,19 @@ impl Core { uid: uid.clone(), target_name: target_name.map(str::to_string), }; - self.rt.block_on(async { - let mut outcomes = - std::pin::pin!(self.client.move_nodes_streaming(vec![item], parent.clone())); - match outcomes.next().await { - Some(Ok((_, outcome))) => outcome, - Some(Err(e)) => Err(e), - None => Err(ProtonError::invalid_operation(format!( - "move of {uid} reported no outcome" - ))), - } - }) + self.rt + .block_on(async { + let mut outcomes = + std::pin::pin!(self.client.move_nodes_streaming(vec![item], parent.clone())); + match outcomes.next().await { + Some(Ok((_, outcome))) => outcome, + Some(Err(e)) => Err(e), + None => Err(ProtonError::invalid_operation(format!( + "move of {uid} reported no outcome" + ))), + } + }) + .inspect(|()| self.forget_sdk_node(uid)) } /// Apply a queued trash to the remote. diff --git a/crates/pdfs-fuse/src/filesystem.rs b/crates/pdfs-fuse/src/filesystem.rs index 86f7cbb..820e68d 100644 --- a/crates/pdfs-fuse/src/filesystem.rs +++ b/crates/pdfs-fuse/src/filesystem.rs @@ -2015,8 +2015,8 @@ impl ProtonFs { queue_it(reply); return; } - // Rename first if both halves change. Moving first makes the encrypted - // name requirements stale and repeatedly failed with InvalidRequirements. + // Rename first if both halves change; a move that then fails leaves the + // node renamed in its source folder, which the tree is told below. // A failure past this point has already trashed any node the rename was // replacing, so put it back rather than leaving the caller with neither // the source moved nor the destination intact. @@ -2042,48 +2042,28 @@ impl ProtonFs { reply.error(Errno::EIO); return; } - if newparent != parent { - let mut attempts = 0u32; - let moved = loop { - match self - .core - .block_on_bounded(self.core.client.move_node(&uid, &new_parent_uid)) - { - Ok(()) => break Ok(()), - Err(e) - if newname != name - && api_code(&e) == Some(ResponseCode::InvalidRequirements) - && attempts < 20 => - { - attempts += 1; - // Requirement propagation routinely takes longer than - // three seconds. Keep a bounded ten-second window; a - // successful POSIX reply must mean both remote halves - // landed, not merely that the second half was queued. - std::thread::sleep(Duration::from_millis(500)); - } - Err(e) => break Err(e), - } - }; - if let Err(e) = moved { - if self.core.lost_link(&e, "move") { - queue_it(reply); - return; - } - error!(%uid, attempts, error = %e, "move after rename failed"); - // The rename half landed in the source directory. - let mut state = self.core.state(); - let old_parent_uid = state - .entries - .get(&parent) - .map(|entry| entry.uid.clone()) - .unwrap_or_else(|| uid.clone()); - state.rename_in_place(ino, parent, &old_parent_uid, newname); - drop(state); - self.core.restore_replaced(victim.as_ref(), newname); - reply.error(Errno::EIO); + // A successful reply must mean both remote halves landed, not merely + // that the second half was queued. + if newparent != parent + && let Err(e) = self.core.move_remote(&uid, &new_parent_uid) + { + if self.core.lost_link(&e, "move") { + queue_it(reply); return; } + error!(%uid, error = %e, "move after rename failed"); + // The rename half landed in the source directory. + let mut state = self.core.state(); + let old_parent_uid = state + .entries + .get(&parent) + .map(|entry| entry.uid.clone()) + .unwrap_or_else(|| uid.clone()); + state.rename_in_place(ino, parent, &old_parent_uid, newname); + drop(state); + self.core.restore_replaced(victim.as_ref(), newname); + reply.error(Errno::EIO); + return; } self.core .state diff --git a/crates/pdfs-fuse/src/lib.rs b/crates/pdfs-fuse/src/lib.rs index 4f69435..ffe6621 100644 --- a/crates/pdfs-fuse/src/lib.rs +++ b/crates/pdfs-fuse/src/lib.rs @@ -1608,13 +1608,53 @@ fn prepare_shared_roots( } impl Core { - /// Rename `uid` on Drive, riding out a stale "out of date" answer that - /// follows an earlier rename of the same node. See [`retry_stale_rename`]. + /// Rename `uid` on Drive, riding out an "out of date" answer from a stale + /// name hash. See [`retry_out_of_date`]. pub(crate) fn rename_remote(&self, uid: &NodeUid, name: &str) -> Result<(), ProtonError> { - retry_stale_rename( - || self.block_on_bounded(self.client.rename_node(uid, name, None)), - || std::thread::sleep(RENAME_RETRY_DELAY), - ) + self.change_remote(uid, || { + self.block_on_bounded(self.client.rename_node(uid, name, None)) + }) + } + + /// Move `uid` into the folder `parent` on Drive, like [`Core::rename_remote`]. + pub(crate) fn move_remote(&self, uid: &NodeUid, parent: &NodeUid) -> Result<(), ProtonError> { + self.change_remote(uid, || { + self.block_on_bounded(self.client.move_node(uid, parent)) + }) + } + + /// Run a rename or move of `uid`, then drop the SDK's now stale copy of it. + fn change_remote( + &self, + uid: &NodeUid, + call: impl FnMut() -> Result<(), ProtonError>, + ) -> Result<(), ProtonError> { + retry_out_of_date(call, || { + self.forget_sdk_node(uid); + std::thread::sleep(OUT_OF_DATE_RETRY_DELAY); + }) + .inspect(|()| self.forget_sdk_node(uid)) + } + + /// Drop the SDK's cached copy of `uid` after this daemon renamed or moved it. + /// + /// The SDK sends a node's name hash from its entity cache, and nothing but + /// the event feed's echo of the change refreshes that entry. Until the next + /// poll, up to [`POLL_INTERVAL`] later, each rename or move of the node would + /// send the old hash and Drive would refuse it as out of date (docs/BUGS.md + /// B121). Feeding the SDK the echo now makes the next call read the link. + pub(crate) fn forget_sdk_node(&self, uid: &NodeUid) { + let changed = DriveEvent::NodeUpdated { + id: DriveEventId::from("pdfs-local-change"), + node_uid: uid.clone(), + parent_node_uid: None, + is_trashed: false, + is_shared: false, + }; + if let Err(error) = self.block_on_bounded(self.client.invalidate_caches_for_event(&changed)) + { + debug!(%uid, %error, "could not drop the SDK's cached node"); + } } /// Record that this daemon just changed `uid` on the remote, so the event @@ -4619,8 +4659,7 @@ impl Core { .get(&ino) .map(|entry| entry.node.name.clone()) .unwrap_or_default(); - self.rt - .block_on(self.client.move_node(&uid, &new_parent_uid)) + self.move_remote(&uid, &new_parent_uid) .map_err(|e| CoreError::from_api(&e, "move"))?; self.relocate_everywhere(&uid, &new_parent_uid, &name); self.invalidate_parent_listing(rel); @@ -5505,30 +5544,32 @@ fn api_code(e: &(dyn std::error::Error + 'static)) -> Option { } } -/// How often a rename that Drive calls out of date is retried, and how long -/// apart. Twenty half-second waits match the move retry in the FUSE `rename`. -const RENAME_RETRIES: u32 = 20; -const RENAME_RETRY_DELAY: Duration = Duration::from_millis(500); +/// How often a rename or move that Drive calls out of date is retried, and how +/// long apart. +const OUT_OF_DATE_RETRIES: u32 = 20; +const OUT_OF_DATE_RETRY_DELAY: Duration = Duration::from_millis(500); -/// Run a remote rename, retrying while Drive answers `InvalidRequirements`. +/// Run a remote rename or move, retrying while Drive answers +/// `InvalidRequirements`. /// -/// A rename sends the node's current name hash, read from the server just -/// before. Right after an earlier rename of the same node that read can still -/// return the old hash, and Drive rejects the request as "out of date" until -/// its reads catch up (docs/BUGS.md B111). Any other error returns at once. -fn retry_stale_rename( - mut rename: impl FnMut() -> Result<(), ProtonError>, +/// Both send the node's current name hash. The SDK takes it from its entity +/// cache, which still holds the old hash when the node changed since it was +/// cached, and Drive then rejects the request as "out of date" (docs/BUGS.md +/// B111, B121). `wait` drops that entry before the next attempt. Any other +/// error returns at once. +fn retry_out_of_date( + mut call: impl FnMut() -> Result<(), ProtonError>, mut wait: impl FnMut(), ) -> Result<(), ProtonError> { let mut attempts = 0u32; loop { - match rename() { + match call() { Err(e) if api_code(&e) == Some(ResponseCode::InvalidRequirements) - && attempts < RENAME_RETRIES => + && attempts < OUT_OF_DATE_RETRIES => { attempts += 1; - debug!(attempts, error = %e, "rename was out of date; retrying"); + debug!(attempts, error = %e, "Drive called the request out of date; retrying"); wait(); } result => return result, @@ -8350,7 +8391,7 @@ mod tests { ( "fn move_to(&self, rel: &Path", "require_rename_access", - ".move_node", + ".move_remote", "self.relocate_everywhere(&uid", ), ( @@ -8433,7 +8474,7 @@ mod tests { fn a_rename_called_out_of_date_is_retried_until_it_lands() { let mut calls = 0; let mut waits = 0; - let result = super::retry_stale_rename( + let result = super::retry_out_of_date( || { calls += 1; if calls < 3 { @@ -8451,7 +8492,7 @@ mod tests { #[test] fn a_rename_gives_up_on_other_errors_and_after_its_retries() { let mut calls = 0; - let taken = super::retry_stale_rename( + let taken = super::retry_out_of_date( || { calls += 1; Err(api_error(super::ResponseCode::AlreadyExists)) @@ -8462,7 +8503,7 @@ mod tests { assert_eq!(calls, 1, "a taken name is not a stale read"); let mut calls = 0; - let stale = super::retry_stale_rename( + let stale = super::retry_out_of_date( || { calls += 1; Err(api_error(super::ResponseCode::InvalidRequirements)) @@ -8470,24 +8511,44 @@ mod tests { || {}, ); assert!(stale.is_err()); - assert_eq!(calls, super::RENAME_RETRIES + 1); + assert_eq!(calls, super::OUT_OF_DATE_RETRIES + 1); } #[test] - fn every_remote_rename_rides_out_a_stale_read() { + fn every_remote_rename_and_move_rides_out_a_stale_hash() { for source in [ include_str!("lib.rs"), include_str!("filesystem.rs"), include_str!("drain.rs"), + include_str!("relocate.rs"), ] { assert_eq!( source.matches(concat!("client.rename_node", "(")).count(), usize::from(source.contains("fn rename_remote(")), "call Core::rename_remote instead of the SDK rename directly" ); + assert_eq!( + source.matches(concat!("client.move_node", "(")).count(), + usize::from(source.contains("fn move_remote(")), + "call Core::move_remote instead of the SDK move directly" + ); } } + #[test] + fn a_rename_or_move_drops_the_sdk_copy_of_the_node() { + // The SDK would send the old name hash with the node's next rename or + // move until the event poll caught up (B121). + let change = function_source(include_str!("lib.rs"), "fn change_remote("); + assert_eq!( + change.matches("self.forget_sdk_node(uid)").count(), + 2, + "forget the node before each retry and once the change landed" + ); + let drained = function_source(include_str!("drain.rs"), "fn move_renaming("); + assert!(drained.contains("self.forget_sdk_node(uid)")); + } + #[test] fn a_folder_lists_from_the_db_while_the_link_is_down() { // A listing dropped as stale mid-run, then a drop: every create in that diff --git a/crates/pdfs-fuse/src/relocate.rs b/crates/pdfs-fuse/src/relocate.rs index 289136f..bc24c27 100644 --- a/crates/pdfs-fuse/src/relocate.rs +++ b/crates/pdfs-fuse/src/relocate.rs @@ -254,7 +254,7 @@ impl Core { ))); } - if let Err(e) = self.rt.block_on(self.client.move_node(&src_uid, &dest_uid)) { + if let Err(e) = self.move_remote(&src_uid, &dest_uid) { if let Some((from, to)) = &renamed && let Err(back) = std::fs::rename(to, from) { diff --git a/docs/BUGS.md b/docs/BUGS.md index 5f41128..078df88 100644 --- a/docs/BUGS.md +++ b/docs/BUGS.md @@ -12,6 +12,38 @@ Conventions: --- +## B121 — A move right after a rename fails with `EIO`, and a rename across folders takes seconds + +**Status:** Fixed (unverified). +**Found:** 2026-10-03, in the journal of the account run on flaky Wi-Fi. Each change answered +correctly, but slowly. One rename and move through the mount collected 13 `operation failed … +method=PUT status=422` warnings over 8.2 seconds, and another collected 7 over 3.9 seconds. Each +one was a request that Drive refused as out of date and the daemon tried again half a second +later. + +**Where:** every remote rename and move: `serve_rename` in `crates/pdfs-fuse/src/filesystem.rs`, +the control `rename` and `move_to` in `crates/pdfs-fuse/src/lib.rs`, `move_between` in +`crates/pdfs-fuse/src/relocate.rs`, and the drain's renames and `move_renaming` in +`crates/pdfs-fuse/src/drain.rs`. + +**Cause.** A rename or move sends the node's current name hash as `OriginalHash`. The SDK takes +it from its entity cache before the hash in the link it has just fetched. Its own rename and move +do not update that cache entry. Only the event feed's echo of the change drops it, and the daemon +polls the feed every 10 seconds (`POLL_INTERVAL`). Until then, each rename or move of the same +node sent the old hash. A rename across folders, which is a rename and then a move, was refused +until the next poll, and the retries from B111 hid that as latency. A plain move was not retried +at all. When it came within the poll interval, `mv a b && mv b dir/` through the mount failed with +`EIO`, and `pdfs rename` followed by `pdfs move` failed with Drive's "out of date" error. + +**Fix.** `Core::forget_sdk_node` passes the SDK the event its own change will echo, which drops +the cached node. Every rename, and every move but the drain's, goes through `Core::rename_remote` +or `Core::move_remote`. Both drop the entry once the change has landed, and before each retry of a +request Drive called out of date. The drain's `move_renaming` drops it once its move lands. + +**Test:** the unit tests `a_rename_or_move_drops_the_sdk_copy_of_the_node` and +`every_remote_rename_and_move_rides_out_a_stale_hash`. On the account run, "regression B111" and +"regression B113" should show no `status=422` warnings. + ## B120 — A file queued in a folder that has just landed is put off by five seconds **Status:** Fixed (unverified). @@ -285,10 +317,10 @@ InvalidRequirements (http 422): This file or folder was out of date, rename fail `drain_rename_in_place` in `crates/pdfs-fuse/src/drain.rs`, and the control `rename` in `crates/pdfs-fuse/src/lib.rs`. -**Cause.** The SDK's `rename_node` reads the node's details from the server and sends its current -name hash as `OriginalHash`. Right after a rename of the same node, that read can still return the -old hash. Drive then refuses the request as out of date. The daemon reported this at once as -`EIO`, although the same request succeeds a moment later. +**Cause.** The SDK's `rename_node` sends the node's current name hash as `OriginalHash`. Right +after a rename of the same node, it still sent the old one. Drive then refuses the request as out +of date. The daemon reported this at once as `EIO`, although the same request succeeds a moment +later. The old hash comes from the SDK's entity cache, not from the server (see B121). **Fix.** All remote renames go through `Core::rename_remote`. It retries a rename that fails with `InvalidRequirements` up to 20 times, half a second apart, the same window the move after a diff --git a/docs/TESTING.md b/docs/TESTING.md index 46ee5a9..fda9315 100644 --- a/docs/TESTING.md +++ b/docs/TESTING.md @@ -241,6 +241,12 @@ eight times through the mount. On a mount it also does so three times with `pdfs rename`, after the queue is empty, so the renames race nothing but Drive. It runs against the reference too. +**B121** (a file renamed and moved at once lands) renames a file, moves it into +a subfolder and renames it back across folders through the mount, with no pause +between the steps. On a mount it then runs `pdfs rename` and `pdfs move` back to +back. The file must end up where it was sent, with its bytes, and the case +reports how long each half took. It runs against the reference too. + **B98** (an upload superseded by a write ends) writes 64 MiB and waits for its upload to show in `pdfs transfers`, then appends to the file. The queue must drain, the old upload must leave the transfer list, and the file must hold @@ -331,8 +337,8 @@ bug is open at the moment. B114 to B117 started as such cases. A full account run with `--journal-check` checks these `docs/BUGS.md` entries, many of them fixed but not yet verified: -- B48, B80, B94, B95, B98, B100, B101, B102, B111, B114, B115, B116, B117 and - B119, each with its own `regression B` case. +- B48, B80, B94, B95, B98, B100, B101, B102, B111, B114, B115, B116, B117, B119 + and B121, each with its own `regression B` case. - B118, with "application workloads" and "block boundaries", which failed on it. It needs Drive to be slow to list a new node, so a clean run is weak evidence. diff --git a/scripts/fuse-acceptance.py b/scripts/fuse-acceptance.py index 6e1306e..503c117 100755 --- a/scripts/fuse-acceptance.py +++ b/scripts/fuse-acceptance.py @@ -1810,9 +1810,9 @@ def test_regression_b95_tmp_name_uploads(ctx: Context) -> None: def test_regression_b111_rename_back_at_once(ctx: Context) -> None: """A file renamed and straight back keeps working, every time (B111). - Right after a rename, Drive can still hand out the old name hash, and a - rename sent with that hash was refused as out of date. The daemon answered - with `EIO`, about once a run. On a mount, `pdfs rename` is driven too. + Right after a rename, the SDK still sent the old name hash, and Drive + refused the next rename as out of date. The daemon answered with `EIO`, + about once a run. On a mount, `pdfs rename` is driven too. """ folder = ctx.root / "b111" folder.mkdir() @@ -1841,6 +1841,49 @@ def test_regression_b111_rename_back_at_once(ctx: Context) -> None: check_bytes(read(original), payload, "the file after pdfs rename there and back") +def test_regression_b121_move_right_after_rename(ctx: Context) -> None: + """A file renamed and moved at once lands where it was sent (B121). + + The SDK kept a node's old name hash until the next event poll, up to ten + seconds after the daemon's own rename. A move in that window was refused + as out of date: `EIO` through the mount, an error from `pdfs move`. A + rename across folders landed only after seconds of retries. On a mount, + `pdfs rename` and `pdfs move` are driven too. + """ + folder = ctx.root / "b121" + inner = folder / "inner" + inner.mkdir(parents=True) + path = folder / "b121 first.txt" + payload = b"b121 move right after rename\n" * 64 + write_durable(path, payload) + live = ctx.is_live and ctx.daemon is not None and is_fuse(ctx.root) + if live: + # The changes should race nothing but Drive. + ctx.daemon.wait_for_queue() + started = time.monotonic() + renamed = folder / "b121 renamed.txt" + os.rename(path, renamed) + os.rename(renamed, inner / renamed.name) + # A rename across folders is a rename and then a move of the same node. + back = folder / "b121 back.txt" + os.rename(inner / renamed.name, back) + ctx.info(f"renamed, moved and renamed back through the mount in {time.monotonic() - started:.1f}s") + names = sorted(os.listdir(folder)) + check(names == sorted([back.name, inner.name]), f"after the rename and moves: {names}") + check(not os.listdir(inner), f"inner still lists {sorted(os.listdir(inner))}") + check_bytes(read(back), payload, "the file after the rename and moves") + ctx.record("names", names) + if not live: + return + started = time.monotonic() + ctx.daemon.command("rename", str(back), path.name) + ctx.daemon.command("move", str(path), str(inner)) + ctx.info(f"pdfs rename and pdfs move took {time.monotonic() - started:.1f}s") + listed = sorted(entry["name"] for entry in ctx.daemon.listing(inner)) + check(listed == [path.name], f"pdfs ls lists {listed} in inner after pdfs rename and move") + check_bytes(read(inner / path.name), payload, "the file after pdfs rename and move") + + def _uploads_named(daemon: Daemon, name: str) -> list[dict]: transfers = json.loads(daemon.command("transfers", json_output=True)) return [ @@ -2612,6 +2655,7 @@ TESTS = [ Case("regression B94: a deleted .part file leaves nothing queued", test_regression_b94_deleted_transient_file_leaves_nothing_queued, (LIVE,)), Case("regression B95: a .tmp file uploads at once", test_regression_b95_tmp_name_uploads, (LIVE,)), Case("regression B111: renaming a file straight back works", test_regression_b111_rename_back_at_once), + Case("regression B121: a file renamed and moved at once lands", test_regression_b121_move_right_after_rename), Case("regression B98: an upload superseded by a write ends", test_regression_b98_superseded_upload_ends, (LIVE,), budget_scale=2), Case("regression B80: pdfs search finds a new file after a rewrite", test_regression_b80_new_file_is_searchable, (LIVE,)), Case("regression B48: an emptied folder can be removed at once", test_regression_b48_emptied_folder_removes_at_once),