From 5616e3e5eb1c6320975ea9051f820d90554f80d7 Mon Sep 17 00:00:00 2001 From: Fabio Lussi <198260595+itrycodinganditsbad@users.noreply.github.com> Date: Mon, 19 Oct 2026 23:19:41 +0200 Subject: [PATCH 1/6] agent: retry an atomic replace that Windows refuses for a moment On Windows, renaming over a file fails with "Access is denied" while another program (a virus scanner, the search indexer) holds it open without delete sharing. The live store, status and account writes all went through that rename and failed outright; main's Windows CI hit it in the live speed test (a 2.5 s keystroke after "the live documents couldn't be written to disk"). The rename now retries for about 1.5 s on ERROR_ACCESS_DENIED and ERROR_SHARING_VIOLATION before giving up. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01RC1oqfy9kZznj94RjMojyz --- apps/craft-cloud-agent/src/account.rs | 57 ++++++++++++++++++++++++++- 1 file changed, 56 insertions(+), 1 deletion(-) diff --git a/apps/craft-cloud-agent/src/account.rs b/apps/craft-cloud-agent/src/account.rs index 8ef8e56..87c549c 100644 --- a/apps/craft-cloud-agent/src/account.rs +++ b/apps/craft-cloud-agent/src/account.rs @@ -579,7 +579,7 @@ pub(crate) fn write_atomic(path: &Path, bytes: &[u8], private: bool) -> io::Resu file.write_all(bytes)?; file.sync_all()?; drop(file); - fs::rename(&temp, path) + replace(&temp, path) })(); if result.is_err() { let _ = fs::remove_file(&temp); @@ -592,10 +592,65 @@ pub(crate) fn write_atomic(path: &Path, bytes: &[u8], private: bool) -> io::Resu Ok(()) } +/// Renames `temp` over `path`. On Windows the rename is refused while another program (a virus scanner, the search +/// indexer, a backup tool) holds `path` open without delete sharing, usually for milliseconds: try again for about a +/// second and a half before giving up. +fn replace(temp: &Path, path: &Path) -> io::Result<()> { + #[cfg(windows)] + { + // ERROR_ACCESS_DENIED and ERROR_SHARING_VIOLATION. + const BUSY: [i32; 2] = [5, 32]; + let mut wait = std::time::Duration::from_millis(5); + for _ in 0..12 { + match fs::rename(temp, path) { + Err(e) if e.raw_os_error().is_some_and(|code| BUSY.contains(&code)) => { + std::thread::sleep(wait); + wait = (wait * 2).min(std::time::Duration::from_millis(200)); + } + other => return other, + } + } + } + fs::rename(temp, path) +} + #[cfg(test)] mod tests { use super::*; + /// Another program holding the file for a moment (without delete sharing, as virus scanners do) delays the write; + /// it doesn't fail it. + #[cfg(windows)] + #[test] + fn a_file_held_open_for_a_moment_is_still_replaced() { + use std::os::windows::fs::OpenOptionsExt; + let dir = tempfile::tempdir().unwrap(); + let path = dir.path().join("status.json"); + fs::write(&path, b"old").unwrap(); + // FILE_SHARE_READ only: renaming over the file is refused while this handle is open. + let held = OpenOptions::new().read(true).share_mode(1).open(&path).unwrap(); + let release = std::thread::spawn(move || { + std::thread::sleep(std::time::Duration::from_millis(150)); + drop(held); + }); + write_atomic(&path, b"new", false).unwrap(); + release.join().unwrap(); + assert_eq!(fs::read(&path).unwrap(), b"new"); + } + + /// A file held open for good still fails the write, after the retries, and leaves no temporary file behind. + #[cfg(windows)] + #[test] + fn a_file_held_open_for_good_fails_the_write_cleanly() { + use std::os::windows::fs::OpenOptionsExt; + let dir = tempfile::tempdir().unwrap(); + let path = dir.path().join("status.json"); + fs::write(&path, b"old").unwrap(); + let _held = OpenOptions::new().read(true).share_mode(1).open(&path).unwrap(); + assert!(write_atomic(&path, b"new", false).is_err()); + assert_eq!(fs::read_dir(dir.path()).unwrap().count(), 1, "the temporary file is removed"); + } + fn account(folder: &Path) -> Account { Account { schema: ACCOUNT_SCHEMA, From 20e621757f7acb12ec69b8ba93b8010edce10fb4 Mon Sep 17 00:00:00 2001 From: Fabio Lussi <198260595+itrycodinganditsbad@users.noreply.github.com> Date: Tue, 20 Oct 2026 00:30:28 +0200 Subject: [PATCH 2/6] agent: keep a live document's journal in place instead of deleting it Writing a document whole emptied its journal by deleting the file, and the next change made it again. On Windows another program holding the journal without delete sharing (a scanner, the indexer, a backup tool) made the delete fail with ERROR_SHARING_VIOLATION, so the document's write failed. One holding it without write sharing failed the next append the same way. The journal now stays for the life of the document: emptied in place with set_len(0) and an fsync, like a cut. Its records are in the document's file before it is emptied, so a crash before the cut is durable still loads them and skips them by client_seq, as before. Opening the journal for an append, a cut or the emptying waits for a holder for up to about 1.5 s, like write_atomic's rename (the retry is now retry_busy, shared by both). Files that do go (a document or recents file that doesn't read, and state.json and account.json when the account is forgotten or replaced) are renamed to a temporary name of their own first and then deleted (retire), so their names are free at once for the file written next. A temporary file a crash leaves is removed by the existing clean-ups. The lead was a deleted file staying "delete pending" on Windows while a scanner holds it, so that making the journal again fails with ERROR_ACCESS_DENIED. On NTFS on current Windows (checked on Windows 11, build 26200) a delete frees the name at once (POSIX semantics), so that part doesn't happen there; the test for it passed before this change too. The two journal tests and the state.json test failed before it with os error 32. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01RC1oqfy9kZznj94RjMojyz --- apps/craft-cloud-agent/src/account.rs | 74 ++++++++-- apps/craft-cloud-agent/src/live/store.rs | 170 +++++++++++++++++++---- 2 files changed, 208 insertions(+), 36 deletions(-) diff --git a/apps/craft-cloud-agent/src/account.rs b/apps/craft-cloud-agent/src/account.rs index 87c549c..5a7a62e 100644 --- a/apps/craft-cloud-agent/src/account.rs +++ b/apps/craft-cloud-agent/src/account.rs @@ -489,7 +489,11 @@ impl DataDir { Err(e) => return Err(io_at(&path)(e)), } let approval = load::(&taken, APPROVAL_SCHEMA); - remove(&taken)?; + // (A name of its own already: deleted as it is.) + match fs::remove_file(&taken) { + Err(e) if e.kind() != io::ErrorKind::NotFound => return Err(io_at(&taken)(e)), + _ => {} + } approval } } @@ -514,11 +518,10 @@ fn save(path: &Path, value: &T) -> Result<(), AccountError> { write_atomic(path, &json, true).map_err(io_at(path)) } +/// Deletes a file of the data folder (absent is fine), freeing its name at once ([`retire`]): `state.json` is written +/// again soon after a sign-in removes it. fn remove(path: &Path) -> Result<(), AccountError> { - match fs::remove_file(path) { - Err(e) if e.kind() != io::ErrorKind::NotFound => Err(io_at(path)(e)), - _ => Ok(()), - } + retire(path).map(drop).map_err(io_at(path)) } /// The file a temporary name of [`write_atomic`] is for: `Some("state.json")` for exactly @@ -592,17 +595,24 @@ pub(crate) fn write_atomic(path: &Path, bytes: &[u8], private: bool) -> io::Resu Ok(()) } -/// Renames `temp` over `path`. On Windows the rename is refused while another program (a virus scanner, the search -/// indexer, a backup tool) holds `path` open without delete sharing, usually for milliseconds: try again for about a -/// second and a half before giving up. +/// Renames `temp` over `path` ([`retry_busy`]: on Windows the rename is refused while another program holds `path` +/// open without delete sharing). fn replace(temp: &Path, path: &Path) -> io::Result<()> { + retry_busy(|| fs::rename(temp, path)) +} + +/// Runs the file operation `op`. On Windows another program (a virus scanner, the search indexer, a backup tool) +/// holding the file open without sharing it for what `op` does makes it fail with ERROR_ACCESS_DENIED or +/// ERROR_SHARING_VIOLATION, usually for milliseconds: `op` is tried again for about a second and a half before +/// giving up. Elsewhere it runs once. +pub(crate) fn retry_busy(mut op: impl FnMut() -> io::Result) -> io::Result { #[cfg(windows)] { // ERROR_ACCESS_DENIED and ERROR_SHARING_VIOLATION. const BUSY: [i32; 2] = [5, 32]; let mut wait = std::time::Duration::from_millis(5); for _ in 0..12 { - match fs::rename(temp, path) { + match op() { Err(e) if e.raw_os_error().is_some_and(|code| BUSY.contains(&code)) => { std::thread::sleep(wait); wait = (wait * 2).min(std::time::Duration::from_millis(200)); @@ -611,7 +621,27 @@ fn replace(temp: &Path, path: &Path) -> io::Result<()> { } } } - fs::rename(temp, path) + op() +} + +/// Deletes the file at `path`; `Ok(false)` if there was none. It is first renamed to a temporary name of its own +/// beside it (the one [`write_atomic`] uses, so the clean-ups of interrupted writes remove one a crash leaves), then +/// that is deleted: its own name is free at once, so a file written there next never meets a deleted one that +/// another program still holds open (which Windows may keep, "delete pending", refusing a new file of that name +/// with ERROR_ACCESS_DENIED until the last handle closes). A holder that doesn't share the file for deletion is +/// waited for ([`retry_busy`]). The caller makes the change durable (the folder's fsync) if it must be. +pub(crate) fn retire(path: &Path) -> io::Result { + let dir = path.parent().ok_or_else(|| io::Error::other("no parent folder"))?; + let name = path.file_name().map(|n| n.to_string_lossy().into_owned()).unwrap_or_default(); + let gone = dir.join(format!(".{name}.{}.tmp", random_hex(8)?)); + match retry_busy(|| fs::rename(path, &gone)) { + Ok(()) => {} + Err(e) if e.kind() == io::ErrorKind::NotFound => return Ok(false), + Err(e) => return Err(e), + } + // The name is free now; a renamed file that can't be deleted yet is only a temporary file left behind. + let _ = retry_busy(|| fs::remove_file(&gone)); + Ok(true) } #[cfg(test)] @@ -651,6 +681,30 @@ mod tests { assert_eq!(fs::read_dir(dir.path()).unwrap().count(), 1, "the temporary file is removed"); } + /// Signing in again forgets the old sync state and writes a new one soon after: a scanner holding `state.json` for + /// a moment (without delete sharing) delays the removal, it doesn't fail the sign-in, and the name is free for the + /// new state at once. + #[cfg(windows)] + #[test] + fn a_state_held_for_a_moment_is_still_removed_and_written_again() { + use std::os::windows::fs::OpenOptionsExt; + let dir = tempfile::tempdir().unwrap(); + let data = DataDir::new(dir.path().join("data")); + data.save_state(&SavedState { schema: STATE_SCHEMA, ..SavedState::default() }).unwrap(); + let path = data.file(STATE_FILE); + // FILE_SHARE_READ | FILE_SHARE_WRITE: neither deleting nor renaming it works while this is open. + let held = OpenOptions::new().read(true).share_mode(1 | 2).open(&path).unwrap(); + let release = std::thread::spawn(move || { + std::thread::sleep(std::time::Duration::from_millis(150)); + drop(held); + }); + data.remove_state().unwrap(); + release.join().unwrap(); + assert!(!path.exists()); + data.save_state(&SavedState { schema: STATE_SCHEMA, ..SavedState::default() }).unwrap(); + assert!(path.exists()); + } + fn account(folder: &Path) -> Account { Account { schema: ACCOUNT_SCHEMA, diff --git a/apps/craft-cloud-agent/src/live/store.rs b/apps/craft-cloud-agent/src/live/store.rs index 56adc75..97c4d43 100644 --- a/apps/craft-cloud-agent/src/live/store.rs +++ b/apps/craft-cloud-agent/src/live/store.rs @@ -2,13 +2,21 @@ //! (temporary file, flush, rename), so a crash leaves the old file or the new one. A document's file holds its state, //! what the agent has of the server's log and its local updates not yet acked, so an add is on disk before the app //! is told it is kept. +//! +//! A document's journal is one file for as long as the document is here: appended to, cut back, and emptied in place +//! once its updates are in the document's file, never deleted and made again. (On Windows a virus scanner or the +//! search indexer opens files the agent just wrote; one that doesn't share the journal for deletion made the +//! deletion fail, and a deleted name another program still holds can stay "delete pending" and refuse a new file of +//! that name.) A holder that doesn't share the file for what the store does is waited for, about a second and a half +//! at most ([`crate::account::retry_busy`]). Files that do go (a document that doesn't read) are renamed to a name of +//! their own first, so their names are free at once ([`crate::account::retire`]). use std::collections::BTreeMap; use std::io; use std::path::{Path, PathBuf}; use std::sync::{Arc, Mutex, PoisonError}; -use crate::account::{remove_atomic_temps, write_atomic}; +use crate::account::{remove_atomic_temps, retire, retry_busy, write_atomic}; /// A place for the documents of one account. pub trait DocStore: Send { @@ -88,8 +96,12 @@ impl DiskStore { /// The store in `dir` (made owner-only if missing; interrupted writes cleaned up). pub fn open(dir: &Path) -> io::Result { make_private_dirs(dir)?; - // (Interrupted writes of documents and of set-aside copies.) - remove_atomic_temps(dir, |of| of.ends_with(SUFFIX) || of.ends_with(DOCUMENT_SUFFIX) || of.contains(ASIDE), std::time::Duration::ZERO)?; + // (Interrupted writes of documents and of set-aside copies, and removals a crash interrupted.) + remove_atomic_temps( + dir, + |of| of.ends_with(SUFFIX) || of.ends_with(DOCUMENT_SUFFIX) || of.ends_with(JOURNAL_SUFFIX) || of.contains(ASIDE), + std::time::Duration::ZERO, + )?; Ok(Self { dir: dir.to_owned() }) } @@ -163,10 +175,11 @@ impl DocStore for DiskStore { } fn remove(&mut self, name: &str) -> io::Result<()> { - std::fs::remove_file(self.dir.join(format!("{name}{SUFFIX}")))?; - #[cfg(unix)] - std::fs::File::open(&self.dir)?.sync_all()?; - Ok(()) + // (Written again soon: the document is filled from the server.) + if !retire(&self.dir.join(format!("{name}{SUFFIX}")))? { + return Err(io::Error::from(io::ErrorKind::NotFound)); + } + self.sync_dir() } fn document_names(&self) -> io::Result> { @@ -201,7 +214,7 @@ impl DocStore for DiskStore { use std::io::Write; let path = self.dir.join(format!("{name}{JOURNAL_SUFFIX}")); let new = !path.exists(); - let mut file = std::fs::OpenOptions::new().create(true).append(true).open(&path)?; + let mut file = retry_busy(|| std::fs::OpenOptions::new().create(true).append(true).open(&path))?; let before = file.metadata()?.len(); if let Err(e) = file.write_all(record).and_then(|()| file.sync_data()) { // Not kept: whatever part of it got there goes (a record cut off, or one whose flush failed, must not come @@ -217,17 +230,7 @@ impl DocStore for DiskStore { } fn truncate_journal(&mut self, name: &str, len: usize) -> io::Result<()> { - let path = self.dir.join(format!("{name}{JOURNAL_SUFFIX}")); - let file = match std::fs::OpenOptions::new().write(true).open(&path) { - Ok(file) => file, - Err(e) if e.kind() == io::ErrorKind::NotFound => return Ok(()), - Err(e) => return Err(e), - }; - if file.metadata()?.len() > len as u64 { - file.set_len(len as u64)?; - file.sync_data()?; - } - Ok(()) + cut(&self.dir.join(format!("{name}{JOURNAL_SUFFIX}")), len as u64) } fn load_journal(&self, name: &str) -> io::Result> { @@ -239,11 +242,9 @@ impl DocStore for DiskStore { } fn clear_journal(&mut self, name: &str) -> io::Result<()> { - match std::fs::remove_file(self.dir.join(format!("{name}{JOURNAL_SUFFIX}"))) { - Ok(()) => self.sync_dir(), - Err(e) if e.kind() == io::ErrorKind::NotFound => Ok(()), - Err(e) => Err(e), - } + // Emptied in place, not deleted: the next change's append finds the same file (see the module's doc). A crash + // before the cut is durable leaves the records, which the document's file has now, and a load skips them. + cut(&self.dir.join(format!("{name}{JOURNAL_SUFFIX}")), 0) } fn set_aside_document(&mut self, name: &str) -> io::Result { @@ -251,12 +252,30 @@ impl DocStore for DiskStore { } fn remove_document(&mut self, name: &str) -> io::Result<()> { - std::fs::remove_file(self.dir.join(format!("{name}{DOCUMENT_SUFFIX}")))?; - self.clear_journal(name)?; + // (Written again soon, with a new journal: the document is filled from the server.) + if !retire(&self.dir.join(format!("{name}{DOCUMENT_SUFFIX}")))? { + return Err(io::Error::from(io::ErrorKind::NotFound)); + } + retire(&self.dir.join(format!("{name}{JOURNAL_SUFFIX}")))?; self.sync_dir() } } +/// Cuts the file at `path` to its first `len` bytes if it is longer, durably (a missing file is empty already). A +/// holder that doesn't share it for writing is waited for. +fn cut(path: &Path, len: u64) -> io::Result<()> { + let file = match retry_busy(|| std::fs::OpenOptions::new().write(true).open(path)) { + Ok(file) => file, + Err(e) if e.kind() == io::ErrorKind::NotFound => return Ok(()), + Err(e) => return Err(e), + }; + if file.metadata()?.len() > len { + file.set_len(len)?; + file.sync_data()?; + } + Ok(()) +} + /// What a set-aside file's name has after the document's. const ASIDE: &str = ".unreadable-"; @@ -414,6 +433,105 @@ impl DocStore for MemStore { mod tests { use super::*; + /// Another program (a virus scanner, the search indexer, a backup tool) holding `path` open, sharing it as + /// `share` (`FILE_SHARE_READ` 1, `FILE_SHARE_WRITE` 2, `FILE_SHARE_DELETE` 4). + #[cfg(windows)] + fn hold(path: &Path, share: u32) -> std::fs::File { + use std::os::windows::fs::OpenOptionsExt; + std::fs::OpenOptions::new().read(true).share_mode(share).open(path).unwrap() + } + + /// A journal is emptied in place once its updates are in the document's file (the same file takes the next + /// change); removing a document leaves neither its file, nor its journal, nor a temporary name behind; and a + /// removal a crash cut short (the renamed file) is cleaned up at the next open. + #[test] + fn a_journal_is_emptied_in_place_and_a_removed_document_leaves_nothing() { + let dir = tempfile::tempdir().unwrap(); + let journal = dir.path().join(format!("doc{JOURNAL_SUFFIX}")); + let mut store = DiskStore::open(dir.path()).unwrap(); + store.save_document("doc", b"document").unwrap(); + store.append_journal("doc", b"first").unwrap(); + store.clear_journal("doc").unwrap(); + assert_eq!(std::fs::metadata(&journal).unwrap().len(), 0, "the journal stays, empty"); + assert!(store.load_journal("doc").unwrap().is_empty()); + store.append_journal("doc", b"second").unwrap(); + assert_eq!(store.load_journal("doc").unwrap(), b"second"); + store.clear_journal("never-journalled").unwrap(); + assert!(!dir.path().join(format!("never-journalled{JOURNAL_SUFFIX}")).exists()); + store.remove_document("doc").unwrap(); + let left: Vec<_> = std::fs::read_dir(dir.path()).unwrap().map(|e| e.unwrap().file_name()).collect(); + assert!(left.is_empty(), "{left:?}"); + assert!(store.remove_document("doc").is_err(), "a document that isn't there"); + let interrupted = dir.path().join(format!(".doc{JOURNAL_SUFFIX}.0011223344556677.tmp")); + std::fs::write(&interrupted, b"records").unwrap(); + DiskStore::open(dir.path()).unwrap(); + assert!(!interrupted.exists(), "the interrupted removal is left behind"); + } + + /// A scanner holding a document's journal without delete sharing doesn't fail the document's write (its journal + /// emptied once its updates are in its file) nor the next change's append. + #[cfg(windows)] + #[test] + fn a_journal_held_without_delete_sharing_is_still_emptied_and_appended_to() { + let dir = tempfile::tempdir().unwrap(); + let mut store = DiskStore::open(dir.path()).unwrap(); + store.save_document("doc", b"document").unwrap(); + store.append_journal("doc", b"first").unwrap(); + let _scanner = hold(&dir.path().join(format!("doc{JOURNAL_SUFFIX}")), 1 | 2); + store.save_document("doc", b"document, first in").unwrap(); + store.clear_journal("doc").unwrap(); + store.append_journal("doc", b"second").unwrap(); + assert_eq!(store.load_journal("doc").unwrap(), b"second"); + } + + /// A scanner holding the journal for a moment without sharing it for writing delays an append, a cut and an + /// emptying; it doesn't fail them. + #[cfg(windows)] + #[test] + fn a_journal_held_for_a_moment_delays_its_writes() { + let dir = tempfile::tempdir().unwrap(); + let journal = dir.path().join(format!("doc{JOURNAL_SUFFIX}")); + let mut store = DiskStore::open(dir.path()).unwrap(); + store.save_document("doc", b"document").unwrap(); + store.append_journal("doc", b"first").unwrap(); + let held_for_a_moment = |store: &mut DiskStore, what: &dyn Fn(&mut DiskStore) -> io::Result<()>| { + let scanner = hold(&journal, 1); + let release = std::thread::spawn(move || { + std::thread::sleep(std::time::Duration::from_millis(150)); + drop(scanner); + }); + let done = what(store); + release.join().unwrap(); + done + }; + held_for_a_moment(&mut store, &|s| s.append_journal("doc", b"second")).unwrap(); + assert_eq!(store.load_journal("doc").unwrap(), b"firstsecond"); + held_for_a_moment(&mut store, &|s| s.truncate_journal("doc", 5)).unwrap(); + assert_eq!(store.load_journal("doc").unwrap(), b"first"); + held_for_a_moment(&mut store, &|s| s.clear_journal("doc")).unwrap(); + assert!(store.load_journal("doc").unwrap().is_empty()); + } + + /// The lead this was found from: a file deleted while another program holds it (sharing it for deletion, as + /// scanners do) used to keep its name "delete pending" on Windows, and making a file of that name failed with + /// ERROR_ACCESS_DENIED until the last handle closed. A journal is never deleted and made again now; this checks + /// the store's own way of removing a document frees its names at once either way. + #[cfg(windows)] + #[test] + fn a_document_removed_while_held_can_be_written_again_at_once() { + let dir = tempfile::tempdir().unwrap(); + let mut store = DiskStore::open(dir.path()).unwrap(); + store.save_document("doc", b"damaged").unwrap(); + store.append_journal("doc", b"first").unwrap(); + let _scanners = + (hold(&dir.path().join(format!("doc{DOCUMENT_SUFFIX}")), 1 | 2 | 4), hold(&dir.path().join(format!("doc{JOURNAL_SUFFIX}")), 1 | 2 | 4)); + store.remove_document("doc").unwrap(); + store.save_document("doc", b"rebuilt").unwrap(); + store.append_journal("doc", b"again").unwrap(); + assert_eq!(store.load_document("doc").unwrap().as_deref(), Some(&b"rebuilt"[..])); + assert_eq!(store.load_journal("doc").unwrap(), b"again"); + } + /// Recents files and documents of files each keep their own few set-aside copies: many of one kind never push out /// the other's. #[test] From af4b9fd205252ba91dd1fc6745b80421f7eb9367 Mon Sep 17 00:00:00 2001 From: Fabio Lussi <198260595+itrycodinganditsbad@users.noreply.github.com> Date: Tue, 20 Oct 2026 00:30:28 +0200 Subject: [PATCH 3/6] tests: report each keystroke of the latency test, and bound its median and p95 The test sorted the keystroke times and failed on the single worst one, so a failure didn't say which keystroke was slow or what happened around it. It now prints every keystroke in order with when it was sent, how long it took, and anything else the two documents said meanwhile (going offline, for one). It asserts the median under 100 ms, the 95th percentile under 250 ms and the worst under 1 s. A delay on every keystroke, or on every tenth one, still fails. One keystroke held up once on a busy runner doesn't. A unit test checks the bounds against those cases. The test also waits for the pc's document to come online before typing, not only the laptop's. After an import the pc catches up on its own import from the server, and a keystroke sent before that ends waits in the journal, so it timed the rest of the catch-up instead of a keystroke. The agents stop before the assertions. Before this, a failed assertion deleted the agents' temporary folders while they were still running, which printed "the live documents couldn't be written to disk" (os error 2 on Linux and macOS, os error 5 on Windows). Those lines came from the failure, they didn't cause it. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01RC1oqfy9kZznj94RjMojyz --- apps/craft-cloud-agent/tests/live_speed.rs | 153 +++++++++++++++++---- 1 file changed, 128 insertions(+), 25 deletions(-) diff --git a/apps/craft-cloud-agent/tests/live_speed.rs b/apps/craft-cloud-agent/tests/live_speed.rs index fcb8167..2206535 100644 --- a/apps/craft-cloud-agent/tests/live_speed.rs +++ b/apps/craft-cloud-agent/tests/live_speed.rs @@ -1,6 +1,7 @@ //! How fast live documents are. **Latency**: a keystroke in an app on one machine is applied in the open document on //! another in under 250 ms, through the crate, two running agents and the server, on loopback with 2 ms of simulated -//! delay each way. **Size**: a 5 MB text document with 100,000 updates in its log opens on a machine that never had it +//! delay each way (95 keystrokes in 100, and the worst under a second: see [`P95_UNDER`]; each keystroke's time is +//! reported in order when it fails). **Size**: a 5 MB text document with 100,000 updates in its log opens on a machine that never had it //! in under a second, from the server's snapshot and the log above it. The size test runs only in a release build //! (`cargo test --release`), or with `LIVE_SIZE=1`, as the long simulations do. @@ -54,58 +55,160 @@ async fn a_keystroke_reaches_the_other_machine_in_under_250_ms() { let theirs = LoroDoc::new(); theirs.import(doc_laptop.state()).unwrap(); let (pc_side, laptop_side) = (Arc::new(Mutex::new((mine, doc_pc))), Arc::new(Mutex::new((theirs, doc_laptop)))); - // Both online (the laptop's document followed). - let l = laptop_side.clone(); - eventually("the laptop's document is online", move || { - let side = l.lock().unwrap(); - (side.1.opened_state().online || std::iter::from_fn(|| side.1.try_recv()).any(|e| matches!(e, Event::Status { online: true, .. }))) - .then_some(()) - }) - .await; + // Both online: the laptop's document followed, and the pc's caught up with its own import (the server sends it + // back once it is kept). Until then the pc's keystrokes wait in its journal, and the first ones would time the + // rest of that catch-up, not a keystroke. + for (who, side) in [("pc", pc_side.clone()), ("laptop", laptop_side.clone())] { + // As it was opened, then as each status since says. + let online = std::sync::atomic::AtomicBool::new(side.lock().unwrap().1.opened_state().online); + eventually(&format!("the {who}'s document is online"), move || { + let side = side.lock().unwrap(); + for event in std::iter::from_fn(|| side.1.try_recv()) { + if let Event::Status { online: now, .. } = event { + online.store(now, std::sync::atomic::Ordering::Relaxed); + } + } + online.load(std::sync::atomic::Ordering::Relaxed).then_some(()) + }) + .await; + } let (p, l) = (pc_side.clone(), laptop_side.clone()); - let times = off(move || { - let mut times = Vec::new(); - for i in 0..40 { - let typed = { + let typed = off(move || { + let mut typed = Vec::new(); + let start = Instant::now(); + for i in 0..KEYSTROKES { + let (at, mut events) = { let (mine, doc) = &*p.lock().unwrap(); let before = mine.oplog_vv(); let text = mine.get_text("text"); text.insert(text.len_unicode(), &format!("{}", i % 10)).unwrap(); mine.commit(); let update = mine.export(ExportMode::updates(&before)).unwrap(); + // What the pc's document said since the last keystroke (an offline spell, say). + let events: Vec = std::iter::from_fn(|| doc.try_recv()).filter(worth_saying).map(|e| format!("pc {e:?}")).collect(); let at = Instant::now(); doc.send(&update).unwrap(); - at + (at, events) }; let want = i + 1; let (theirs, doc) = &*l.lock().unwrap(); - loop { + let took = loop { match doc.recv_timeout(Duration::from_secs(5)) { Some(Event::Update(bytes)) => { theirs.import(&bytes).unwrap(); if theirs.get_text("text").len_unicode() >= want { - times.push(typed.elapsed()); - break; + break at.elapsed(); + } + } + Some(other) => { + if worth_saying(&other) { + events.push(format!("laptop {other:?}")); } } - Some(_) => {} None => panic!("keystroke {i} never arrived"), } - } + }; + typed.push(Keystroke { sent: at - start, took, events }); // A typist's pace: a keystroke batch every 30 ms. std::thread::sleep(Duration::from_millis(30)); } - times + typed }) .await; - let mut sorted = times.clone(); - sorted.sort(); - let (median, worst) = (sorted[sorted.len() / 2], sorted[sorted.len() - 1]); - eprintln!("keystroke to remote apply: median {median:?}, worst {worst:?} over {} keystrokes", sorted.len()); - assert!(worst < Duration::from_millis(250), "a keystroke took {worst:?}: {sorted:?}"); + // The agents stop before anything is asserted: a failure doesn't remove their folders under them (which only adds + // "couldn't be written to disk" lines to the output). drop((docs_pc, docs_laptop, pc_side, laptop_side)); run_pc.stop().await.0.unwrap(); run_laptop.stop().await.0.unwrap(); + let latency = Latency::of(&typed); + // (Shown with the failure, or with `--nocapture`.) + let in_order: String = typed.iter().enumerate().map(|(i, k)| format!("\n {i:2} {k}")).collect(); + eprintln!("keystroke to remote apply: {latency}; in order:{in_order}"); + assert!(latency.median < MEDIAN_UNDER, "the median keystroke took {:?}, over {MEDIAN_UNDER:?} (each keystroke above)", latency.median); + assert!(latency.p95 < P95_UNDER, "the 95th percentile took {:?}, over {P95_UNDER:?} (each keystroke above)", latency.p95); + assert!(latency.worst < WORST_UNDER, "keystroke {} took {:?}, over {WORST_UNDER:?} (each keystroke above)", latency.worst_at, latency.worst); +} + +/// Whether a document's event is worth reporting beside a keystroke's time: anything but acks and the count of +/// changes waiting going up and down while it is online. +fn worth_saying(event: &Event) -> bool { + !matches!(event, Event::Acked(_) | Event::Status { online: true, deleted: false, stopped: false, .. }) +} + +/// Keystrokes typed in the latency test. +const KEYSTROKES: usize = 40; +/// The latency test's bounds. A keystroke reaches the other machine in under 250 ms: 95 in 100 do, every time, and +/// the typical one well inside that. A debug build on a shared CI runner (two to four cores, with the rest of the +/// workspace's tests just run) can lose one or two keystrokes to the scheduler or the disk, so the worst one only has +/// to stay under a second; a delay many keystrokes share (on each keystroke, or on every few) still fails the median +/// or the 95th percentile. (Windows' timers tick every 15.6 ms, so each of the gate's 2 ms delays is one tick there: +/// its median is about 50 ms.) +const MEDIAN_UNDER: Duration = Duration::from_millis(100); +const P95_UNDER: Duration = Duration::from_millis(250); +const WORST_UNDER: Duration = Duration::from_secs(1); + +/// One keystroke of the latency test: when it was sent (from the first), how long it took to reach the laptop, and +/// what else the two documents said meanwhile. +struct Keystroke { + sent: Duration, + took: Duration, + events: Vec, +} + +impl std::fmt::Display for Keystroke { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!(f, "sent at {:>9.1?}, took {:>9.1?}", self.sent, self.took)?; + for event in &self.events { + write!(f, "; {event}")?; + } + Ok(()) + } +} + +/// The median, 95th percentile (nearest rank) and worst of the keystrokes' times, and which keystroke the worst was. +struct Latency { + median: Duration, + p95: Duration, + worst: Duration, + worst_at: usize, + count: usize, +} + +impl Latency { + fn of(typed: &[Keystroke]) -> Self { + let mut sorted: Vec = typed.iter().map(|k| k.took).collect(); + sorted.sort(); + let rank = |p: usize| sorted[(sorted.len() * p).div_ceil(100).saturating_sub(1)]; + let (worst_at, worst) = typed.iter().map(|k| k.took).enumerate().max_by_key(|(_, t)| *t).unwrap(); + Self { median: rank(50), p95: rank(95), worst, worst_at, count: typed.len() } + } +} + +impl std::fmt::Display for Latency { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + let Self { median, p95, worst, worst_at, count } = self; + write!(f, "median {median:?}, 95th percentile {p95:?}, worst {worst:?} (keystroke {worst_at}) over {count} keystrokes") + } +} + +/// The bounds fail what they are meant to fail: a 400 ms delay on every keystroke, or on every tenth, fails; one +/// keystroke held up once doesn't. +#[test] +fn the_latency_bounds_fail_a_shared_delay_but_not_one_hiccup() { + let fast = Duration::from_millis(10); + let slow = Duration::from_millis(400); + let run = |slow_at: &dyn Fn(usize) -> bool| -> Vec { + (0..KEYSTROKES) + .map(|i| Keystroke { sent: Duration::from_millis(40) * i as u32, took: if slow_at(i) { slow } else { fast }, events: Vec::new() }) + .collect() + }; + let passes = |l: &Latency| l.median < MEDIAN_UNDER && l.p95 < P95_UNDER && l.worst < WORST_UNDER; + assert!(passes(&Latency::of(&run(&|i| i == 17)))); + let hiccup = Latency::of(&run(&|i| i == 17)); + assert_eq!((hiccup.worst, hiccup.worst_at), (slow, 17)); + assert!(!passes(&Latency::of(&run(&|_| true)))); + assert!(!passes(&Latency::of(&run(&|i| i % 10 == 0)))); + assert!(!passes(&Latency::of(&run(&|i| i % 2 == 0)))); } /// A 5 MB text document with 100,000 updates in its log (compacted, with a tail above the snapshot) opens on a fresh From 6b955b5bf6cf1fd6fdf264590ac3375b62bfba4f Mon Sep 17 00:00:00 2001 From: Fabio Lussi <198260595+itrycodinganditsbad@users.noreply.github.com> Date: Tue, 20 Oct 2026 01:51:28 +0200 Subject: [PATCH 4/6] agent: don't hold a keystroke behind writes nothing is waiting for Right after a file is opened live, CI on Windows took 0.3 to 1.4 s per keystroke for about 4 s, and then settled. Two writes ran on threads that also relay every keystroke, and both waited for any other program holding the file they replace (retry_busy, up to about 1.5 s): - status.json, written on the run loop's runtime on every state change and heartbeat. That runtime also serves the local API, including the docs WebSocket that carries each keystroke from the app and to the other app. - a live document's whole file and the emptying of its journal, written on the hub's thread after a join and every 2 s while the document is dirty. That thread forwards every update to and from the server. Now status.json is written on a thread of its own (StatusWriter). Only the newest status waits there, a failed write is still tried again at the next write, and dropping the writer writes what still waits, so the loop's last status is on disk when it ends. The hub's writes that nothing waits for (flush and the 2 s flush_documents) don't wait for a holder of a document's files: the document stays dirty and is written at the next 2 s write. Its local updates are in its journal already. A journal that can't be emptied yet keeps records the file now has, and a load skips them by client_seq. Writes something does wait for still wait: an app's change written whole first, loads, recents adds, and the documents written when the agent stops. The new Windows test, a_keystroke_isnt_held_up_by_a_scanner_holding_the_ files_written_now_and_then, holds both agents' status.json and live document files open without delete sharing for 400 ms out of every 450 ms. On the previous commit it fails: median 33 ms, 95th percentile 2.0 s, keystrokes of 0.7 to 2.3 s. With this commit it passes at about 32 ms. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01RC1oqfy9kZznj94RjMojyz --- apps/craft-cloud-agent/src/account.rs | 25 +++- apps/craft-cloud-agent/src/daemon.rs | 140 +++++++++++++++++++-- apps/craft-cloud-agent/src/live/hub.rs | 2 +- apps/craft-cloud-agent/src/live/replica.rs | 65 ++++++++-- apps/craft-cloud-agent/src/live/store.rs | 27 +++- apps/craft-cloud-agent/tests/live_speed.rs | 55 +++++++- 6 files changed, 289 insertions(+), 25 deletions(-) diff --git a/apps/craft-cloud-agent/src/account.rs b/apps/craft-cloud-agent/src/account.rs index 5a7a62e..6c304f4 100644 --- a/apps/craft-cloud-agent/src/account.rs +++ b/apps/craft-cloud-agent/src/account.rs @@ -565,6 +565,16 @@ pub(crate) fn random_hex(n: usize) -> io::Result { /// Writes `bytes` to `path` atomically: a temporary file next to it, flushed, then renamed over it. `private` /// makes the file owner-only on Unix (mode 0600 from creation, so it is never readable by others). pub(crate) fn write_atomic(path: &Path, bytes: &[u8], private: bool) -> io::Result<()> { + write_atomic_as(path, bytes, private, true) +} + +/// [`write_atomic`], except that another program holding `path` refuses it at once ([`is_busy`]) rather than being +/// waited for: for a write that can as well be made later. +pub(crate) fn write_atomic_unless_busy(path: &Path, bytes: &[u8], private: bool) -> io::Result<()> { + write_atomic_as(path, bytes, private, false) +} + +fn write_atomic_as(path: &Path, bytes: &[u8], private: bool, wait: bool) -> io::Result<()> { let dir = path.parent().ok_or_else(|| io::Error::other("no parent folder"))?; let name = path.file_name().map(|n| n.to_string_lossy().into_owned()).unwrap_or_default(); let temp = dir.join(format!(".{name}.{}.tmp", random_hex(8)?)); @@ -582,7 +592,7 @@ pub(crate) fn write_atomic(path: &Path, bytes: &[u8], private: bool) -> io::Resu file.write_all(bytes)?; file.sync_all()?; drop(file); - replace(&temp, path) + if wait { replace(&temp, path) } else { fs::rename(&temp, path) } })(); if result.is_err() { let _ = fs::remove_file(&temp); @@ -601,6 +611,15 @@ fn replace(temp: &Path, path: &Path) -> io::Result<()> { retry_busy(|| fs::rename(temp, path)) } +/// Whether `e` is Windows refusing a file operation because another program holds the file (ERROR_ACCESS_DENIED or +/// ERROR_SHARING_VIOLATION; [`retry_busy`] waits those out). Never elsewhere. +pub(crate) fn is_busy(e: &io::Error) -> bool { + cfg!(windows) && e.raw_os_error().is_some_and(|code| BUSY.contains(&code)) +} + +/// ERROR_ACCESS_DENIED and ERROR_SHARING_VIOLATION. +const BUSY: [i32; 2] = [5, 32]; + /// Runs the file operation `op`. On Windows another program (a virus scanner, the search indexer, a backup tool) /// holding the file open without sharing it for what `op` does makes it fail with ERROR_ACCESS_DENIED or /// ERROR_SHARING_VIOLATION, usually for milliseconds: `op` is tried again for about a second and a half before @@ -608,12 +627,10 @@ fn replace(temp: &Path, path: &Path) -> io::Result<()> { pub(crate) fn retry_busy(mut op: impl FnMut() -> io::Result) -> io::Result { #[cfg(windows)] { - // ERROR_ACCESS_DENIED and ERROR_SHARING_VIOLATION. - const BUSY: [i32; 2] = [5, 32]; let mut wait = std::time::Duration::from_millis(5); for _ in 0..12 { match op() { - Err(e) if e.raw_os_error().is_some_and(|code| BUSY.contains(&code)) => { + Err(e) if is_busy(&e) => { std::thread::sleep(wait); wait = (wait * 2).min(std::time::Duration::from_millis(200)); } diff --git a/apps/craft-cloud-agent/src/daemon.rs b/apps/craft-cloud-agent/src/daemon.rs index 967f327..0bf8cd8 100644 --- a/apps/craft-cloud-agent/src/daemon.rs +++ b/apps/craft-cloud-agent/src/daemon.rs @@ -21,7 +21,9 @@ //! reach the server after resume). It is kept in `state.json`, so a paused agent starts paused. Resuming runs a full //! pass at once. **Quit** (the local API's `quit`) is a first stop request. //! - **Status**: `status.json` in the data folder ([`LoopStatus`]) is written on every change of state and as a -//! heartbeat, so `status` can tell whether the loop runs and what it is doing. +//! heartbeat, so `status` can tell whether the loop runs and what it is doing. It is written on a thread of its own +//! ([`StatusWriter`]): the loop's runtime also serves the local API, the apps' live documents among it, and a write +//! that waits for the disk or for a virus scanner holding the file must never hold up a keystroke on its way. //! - **Approval**: while deletions wait, the loop looks for `approval.json` (written by `sync --approve-deletes` //! from another terminal, for the set `status` showed) and releases exactly the deletions it names, if they are //! still the set that waits; any other approval is discarded with a message. Deletes held behind a link are a set @@ -416,8 +418,96 @@ fn run_state(state: &LoopState) -> RunState { /// The loop's clock and its status file. Its own clock is monotonic (scheduling only); every time it writes is the /// wall clock's. -struct Status { +/// Writes the loop's `status.json` off the loop's runtime: on a thread of its own, or (in a test of the file alone, or +/// when no thread can be started) in the caller's. Only the newest status waits: one handed over while another is +/// being written replaces any older one still waiting. Dropping it writes what still waits before it returns, so the +/// loop's last status (`Stopped`) is on disk when the loop ends. +struct StatusWriter { data: DataDir, + shared: std::sync::Arc<(std::sync::Mutex, std::sync::Condvar)>, + thread: Option>, +} + +/// What the loop hands the status thread. +#[derive(Default)] +struct Handover { + next: Option, + /// A write failed since the loop last asked ([`StatusWriter::take_failed`]). + failed: bool, + closed: bool, +} + +impl StatusWriter { + fn start(data: &DataDir) -> Self { + let mut writer = Self::inline(data); + let (shared, data) = (writer.shared.clone(), data.clone()); + // No thread: written in the loop, as before. + writer.thread = std::thread::Builder::new().name("craft-cloud-status".into()).spawn(move || write_statuses(&data, &shared)).ok(); + writer + } + + fn inline(data: &DataDir) -> Self { + Self { data: data.clone(), shared: std::sync::Arc::default(), thread: None } + } + + fn handover(&self) -> std::sync::MutexGuard<'_, Handover> { + self.shared.0.lock().unwrap_or_else(std::sync::PoisonError::into_inner) + } + + /// Has `status` written (soon, on the thread). + fn write(&self, status: LoopStatus) { + if self.thread.is_none() { + if let Err(e) = self.data.save_status(&status) { + crate::runlog::note(format_args!("can't write the status file: {e}")); + self.handover().failed = true; + } + return; + } + self.handover().next = Some(status); + self.shared.1.notify_one(); + } + + /// Whether a write failed since the last call. + fn take_failed(&self) -> bool { + std::mem::take(&mut self.handover().failed) + } +} + +impl Drop for StatusWriter { + fn drop(&mut self) { + self.handover().closed = true; + self.shared.1.notify_one(); + if let Some(thread) = self.thread.take() { + let _ = thread.join(); + } + } +} + +/// The status thread: writes each status handed over, the newest first, until the writer is dropped and nothing waits. +fn write_statuses(data: &DataDir, shared: &(std::sync::Mutex, std::sync::Condvar)) { + let lock = || shared.0.lock().unwrap_or_else(std::sync::PoisonError::into_inner); + loop { + let status = { + let mut handover = lock(); + loop { + if let Some(status) = handover.next.take() { + break status; + } + if handover.closed { + return; + } + handover = shared.1.wait(handover).unwrap_or_else(std::sync::PoisonError::into_inner); + } + }; + if let Err(e) = data.save_status(&status) { + crate::runlog::note(format_args!("can't write the status file: {e}")); + lock().failed = true; + } + } +} + +struct Status { + writer: StatusWriter, start: Instant, started_ms: i64, heartbeat: Duration, @@ -466,8 +556,12 @@ impl Status { /// converted from the loop's clock afresh at every call, so they jitter by a millisecond or so, and a new next try /// or next check only ever comes with a pass, whose `Syncing` is written in between. The loop wakes on every /// watcher event, so comparing them would write (and flush) the file on every other event while it retries. - /// A failed write is reported once per failure and tried again next time; it never stops the loop. + /// A failed write is reported once per failure and tried again next time; it never stops the loop. The write + /// itself happens on the status thread ([`StatusWriter`]). fn write(&mut self, state: LoopState, waiting_for_approval: bool, force: bool) { + if self.writer.take_failed() { + self.last_written = None; + } if let Some(pass) = &self.last_pass && !matches!(pass.outcome, Outcome::Failed(_)) { @@ -496,10 +590,8 @@ impl Status { } // Tried again at the next beat either way, never in a hot loop. self.next_beat = now.saturating_add(u64::try_from(self.heartbeat.as_millis()).unwrap_or(u64::MAX)); - match self.data.save_status(&status) { - Ok(()) => self.last_written = Some(status), - Err(e) => crate::runlog::note(format_args!("can't write the status file: {e}")), - } + self.writer.write(status.clone()); + self.last_written = Some(status); } } @@ -527,7 +619,7 @@ pub async fn run_loop(data: &DataDir, options: RunOptions, mut stop: mpsc::Unbou let api = LocalApi::start(data, control.clone()).await?; say(out, &format!("craft-cloud-agent: local API on 127.0.0.1:{} (for the Craft Cloud app and the other Craft apps)", api.port())); let mut status = Status { - data: data.clone(), + writer: StatusWriter::start(data), start: Instant::now(), started_ms: now_ms(), heartbeat: options.heartbeat, @@ -1251,7 +1343,7 @@ mod tests { let data = DataDir::new(dir.path()); let eight_hours = 8 * 3_600 * 1_000; let mut status = Status { - data: data.clone(), + writer: StatusWriter::inline(&data), start: Instant::now(), // Started 8 h (of wall-clock time) ago, but the monotonic clock only counted the time awake. started_ms: now_ms() - eight_hours, @@ -1282,7 +1374,7 @@ mod tests { let dir = tempfile::tempdir().unwrap(); let data = DataDir::new(dir.path()); let mut status = Status { - data: data.clone(), + writer: StatusWriter::inline(&data), start: Instant::now(), started_ms: now_ms(), heartbeat: Duration::from_secs(15), @@ -1325,6 +1417,34 @@ mod tests { assert!(file.exists(), "the heartbeat writes"); } + /// The status thread writes the newest status it was handed, and dropping the writer writes what still waits + /// before it returns (the loop's last status is on disk when the loop ends). + #[test] + fn the_status_thread_writes_the_newest_status_and_finishes_on_drop() { + let dir = tempfile::tempdir().unwrap(); + let data = DataDir::new(dir.path()); + let writer = StatusWriter::start(&data); + assert!(writer.thread.is_some()); + let status = |state: LoopState| LoopStatus { + schema: STATUS_SCHEMA, + pid: std::process::id(), + started_ms: now_ms(), + heartbeat_ms: now_ms(), + heartbeat_every_ms: 15_000, + state, + waiting_for_approval: false, + held: false, + last_pass: None, + not_watching: None, + }; + for _ in 0..50 { + writer.write(status(LoopState::Syncing)); + } + writer.write(status(LoopState::Stopped)); + drop(writer); + assert_eq!(data.load_status().unwrap().unwrap().state, LoopState::Stopped); + } + /// Finding 4 of the second review: every watcher start but the first is followed by a full pass, since events /// between the last pass and the start were lost. #[test] diff --git a/apps/craft-cloud-agent/src/live/hub.rs b/apps/craft-cloud-agent/src/live/hub.rs index 9c4be03..bb397f0 100644 --- a/apps/craft-cloud-agent/src/live/hub.rs +++ b/apps/craft-cloud-agent/src/live/hub.rs @@ -1062,7 +1062,7 @@ async fn run( state.send(frames).await; } _ = write_documents.tick() => { - if let Err(e) = state.replica.flush_documents() { + if let Err(e) = state.replica.flush_documents_now_and_then() { state.say(format!("the live documents couldn't be written to disk: {e}")); } } diff --git a/apps/craft-cloud-agent/src/live/replica.rs b/apps/craft-cloud-agent/src/live/replica.rs index 8d4d336..e703693 100644 --- a/apps/craft-cloud-agent/src/live/replica.rs +++ b/apps/craft-cloud-agent/src/live/replica.rs @@ -2741,19 +2741,30 @@ impl Replica { for (id, doc) in &mut self.docs { let now = !doc.kind.is_document() || doc.urgent || doc.journal > MAX_JOURNAL_BYTES; if doc.dirty && doc.joined && now { - save(&mut self.store, space, *id, doc)?; + // (A document of a file held by another program is written at a later flush: see `Patience`.) + save_as(&mut self.store, space, *id, doc, Patience::Later)?; } } Ok(()) } - /// Writes every document changed since it was last written, documents of files too (now and then, and when the - /// agent stops). + /// Writes every document changed since it was last written, documents of files too (when the agent stops: it + /// waits for another program holding a file). pub fn flush_documents(&mut self) -> std::io::Result<()> { + self.flush_documents_as(Patience::Wait) + } + + /// [`Replica::flush_documents`] now and then: a document of a file another program holds is left for the next + /// time rather than waited for. + pub fn flush_documents_now_and_then(&mut self) -> std::io::Result<()> { + self.flush_documents_as(Patience::Later) + } + + fn flush_documents_as(&mut self, patience: Patience) -> std::io::Result<()> { let space = self.space; for (id, doc) in &mut self.docs { if doc.dirty && doc.joined { - save(&mut self.store, space, *id, doc)?; + save_as(&mut self.store, space, *id, doc, patience)?; } } Ok(()) @@ -3005,7 +3016,24 @@ fn send_pending(id: DocId, doc: &mut Doc) -> Vec { frames } +/// Whether a write of a document of a file waits for another program holding its files. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +enum Patience { + /// It does (something waits for this write: an app's change, a load, the agent stopping). + Wait, + /// It doesn't: the document stays dirty and is written at the next flush. For the writes the hub makes now and + /// then, which nothing waits for (a document's local updates are in its journal already); the hub's thread also + /// relays every keystroke, and a write waiting for a virus scanner held them all up. + Later, +} + fn save(store: &mut S, space: SpaceId, id: DocId, doc: &mut Doc) -> std::io::Result<()> { + save_as(store, space, id, doc, Patience::Wait) +} + +/// [`save`], waiting for a holder of a document of a file's files or not (recents always wait: an add is answered +/// once it is on disk). +fn save_as(store: &mut S, space: SpaceId, id: DocId, doc: &mut Doc, patience: Patience) -> std::io::Result<()> { let snapshot = doc.body.copy().snapshot().map_err(std::io::Error::other)?; match &doc.kind { Kind::Recents(app) => { @@ -3052,10 +3080,33 @@ fn save(store: &mut S, space: SpaceId, id: DocId, doc: &mut Doc) -> }; let bytes = postcard::to_stdvec(&file).map_err(std::io::Error::other)?; let name = id.to_string(); - store.save_document(&name, &bytes)?; + match patience { + Patience::Wait => store.save_document(&name, &bytes)?, + Patience::Later => match store.save_document_unless_busy(&name, &bytes) { + Ok(()) => {} + // Still dirty: written at the next of the documents' writes, not tried again after every frame + // (its journal has its local updates meanwhile). + Err(e) if crate::account::is_busy(&e) => { + doc.urgent = false; + return Ok(()); + } + Err(e) => return Err(e), + }, + } // Its journal's updates are in the file now (a crash before this finds them there and skips them). - store.clear_journal(&name)?; - doc.journal = 0; + let cleared = match patience { + Patience::Wait => store.clear_journal(&name).map(|()| true), + // A journal held by another program stays as it is: its records are in the file now, and a load + // skips them (by their numbers); the next write empties it. + Patience::Later => match store.clear_journal_unless_busy(&name) { + Ok(()) => Ok(true), + Err(e) if crate::account::is_busy(&e) => Ok(false), + Err(e) => Err(e), + }, + }?; + if cleared { + doc.journal = 0; + } } } doc.dirty = false; diff --git a/apps/craft-cloud-agent/src/live/store.rs b/apps/craft-cloud-agent/src/live/store.rs index 97c4d43..2f880e9 100644 --- a/apps/craft-cloud-agent/src/live/store.rs +++ b/apps/craft-cloud-agent/src/live/store.rs @@ -16,7 +16,7 @@ use std::io; use std::path::{Path, PathBuf}; use std::sync::{Arc, Mutex, PoisonError}; -use crate::account::{remove_atomic_temps, retire, retry_busy, write_atomic}; +use crate::account::{remove_atomic_temps, retire, retry_busy, write_atomic, write_atomic_unless_busy}; /// A place for the documents of one account. pub trait DocStore: Send { @@ -48,6 +48,15 @@ pub trait DocStore: Send { fn save_document(&mut self, _name: &str, _bytes: &[u8]) -> io::Result<()> { Err(io::Error::from(io::ErrorKind::Unsupported)) } + /// [`DocStore::save_document`], refused at once (on Windows) while another program holds the file, for a write + /// that can as well be made later (see [`crate::account::is_busy`]). + fn save_document_unless_busy(&mut self, name: &str, bytes: &[u8]) -> io::Result<()> { + self.save_document(name, bytes) + } + /// [`DocStore::clear_journal`], refused at once (on Windows) while another program holds the journal. + fn clear_journal_unless_busy(&mut self, name: &str) -> io::Result<()> { + self.clear_journal(name) + } /// Appends `record` to the document's journal, durably, before this returns. On an error the journal is cut back /// to where it was, as far as the store can (the caller cuts it back too, and writes the document whole). fn append_journal(&mut self, _name: &str, _record: &[u8]) -> io::Result<()> { @@ -210,6 +219,14 @@ impl DocStore for DiskStore { write_atomic(&self.dir.join(format!("{name}{DOCUMENT_SUFFIX}")), bytes, true) } + fn save_document_unless_busy(&mut self, name: &str, bytes: &[u8]) -> io::Result<()> { + write_atomic_unless_busy(&self.dir.join(format!("{name}{DOCUMENT_SUFFIX}")), bytes, true) + } + + fn clear_journal_unless_busy(&mut self, name: &str) -> io::Result<()> { + cut_as(&self.dir.join(format!("{name}{JOURNAL_SUFFIX}")), 0, false) + } + fn append_journal(&mut self, name: &str, record: &[u8]) -> io::Result<()> { use std::io::Write; let path = self.dir.join(format!("{name}{JOURNAL_SUFFIX}")); @@ -264,7 +281,13 @@ impl DocStore for DiskStore { /// Cuts the file at `path` to its first `len` bytes if it is longer, durably (a missing file is empty already). A /// holder that doesn't share it for writing is waited for. fn cut(path: &Path, len: u64) -> io::Result<()> { - let file = match retry_busy(|| std::fs::OpenOptions::new().write(true).open(path)) { + cut_as(path, len, true) +} + +/// [`cut`]; without `wait`, a holder refuses it at once. +fn cut_as(path: &Path, len: u64, wait: bool) -> io::Result<()> { + let open = || std::fs::OpenOptions::new().write(true).open(path); + let file = match if wait { retry_busy(open) } else { open() } { Ok(file) => file, Err(e) if e.kind() == io::ErrorKind::NotFound => return Ok(()), Err(e) => return Err(e), diff --git a/apps/craft-cloud-agent/tests/live_speed.rs b/apps/craft-cloud-agent/tests/live_speed.rs index 2206535..7839719 100644 --- a/apps/craft-cloud-agent/tests/live_speed.rs +++ b/apps/craft-cloud-agent/tests/live_speed.rs @@ -24,6 +24,44 @@ async fn off(f: impl FnOnce() -> T + Send + 'static) -> T { #[tokio::test(flavor = "multi_thread", worker_threads = 4)] async fn a_keystroke_reaches_the_other_machine_in_under_250_ms() { + assert_fast(&time_keystrokes(false).await); +} + +/// The same while another program (a virus scanner, the search indexer, a backup tool) keeps opening the files the +/// agents write now and then, `status.json` and the live documents' files, without sharing them for deletion: the +/// agents' writes of them wait, or are left for later, and no keystroke waits for them. +#[cfg(windows)] +#[tokio::test(flavor = "multi_thread", worker_threads = 4)] +async fn a_keystroke_isnt_held_up_by_a_scanner_holding_the_files_written_now_and_then() { + assert_fast(&time_keystrokes(true).await); +} + +/// Holds each agent's `status.json` and live document files (`/live//*.doc` and `*.live`) open, sharing +/// them for reading only, for 400 ms of every 450 ms until `stop` is set. +#[cfg(windows)] +fn scanner(data: Vec, stop: Arc) -> std::thread::JoinHandle<()> { + use std::os::windows::fs::OpenOptionsExt; + std::thread::spawn(move || { + while !stop.load(std::sync::atomic::Ordering::Relaxed) { + let mut files: Vec = data.iter().map(|d| d.join("status.json")).collect(); + for space in data.iter().flat_map(|d| std::fs::read_dir(d.join("live")).into_iter().flatten().flatten()) { + for entry in std::fs::read_dir(space.path()).into_iter().flatten().flatten() { + if entry.path().extension().is_some_and(|x| x == "doc" || x == "live") { + files.push(entry.path()); + } + } + } + let held: Vec = files.iter().filter_map(|f| std::fs::OpenOptions::new().read(true).share_mode(1).open(f).ok()).collect(); + std::thread::sleep(Duration::from_millis(400)); + drop(held); + std::thread::sleep(Duration::from_millis(50)); + } + }) +} + +/// Two agents, a file opened live on both, and [`KEYSTROKES`] keystrokes typed on the pc and timed to the laptop's +/// app; with `scan`, a [`scanner`] holds the agents' files from just before the open on (Windows only). +async fn time_keystrokes(scan: bool) -> Vec { let server = Server::delayed(Duration::from_millis(2)).await; let (pc, laptop) = (Agent::signed_in(&server, "pc").await, Agent::signed_in(&server, "laptop").await); let (run_pc, run_laptop) = (pc.run(), laptop.run()); @@ -32,6 +70,11 @@ async fn a_keystroke_reaches_the_other_machine_in_under_250_ms() { std::fs::write(pc.folder.join("fast.txt"), "").unwrap(); let file = laptop.folder.join("fast.txt"); eventually("the file reached the laptop", move || file.exists().then_some(())).await; + let stop_scanning = Arc::new(std::sync::atomic::AtomicBool::new(false)); + #[cfg(windows)] + let scanning = scan.then(|| scanner(vec![pc.data.path().to_owned(), laptop.data.path().to_owned()], stop_scanning.clone())); + #[cfg(not(windows))] + let _ = scan; let c = on_pc.clone(); let (docs_pc, doc_pc) = off(move || { let docs = c.documents().unwrap(); @@ -115,12 +158,22 @@ async fn a_keystroke_reaches_the_other_machine_in_under_250_ms() { typed }) .await; + stop_scanning.store(true, std::sync::atomic::Ordering::Relaxed); + #[cfg(windows)] + if let Some(scanning) = scanning { + scanning.join().unwrap(); + } // The agents stop before anything is asserted: a failure doesn't remove their folders under them (which only adds // "couldn't be written to disk" lines to the output). drop((docs_pc, docs_laptop, pc_side, laptop_side)); run_pc.stop().await.0.unwrap(); run_laptop.stop().await.0.unwrap(); - let latency = Latency::of(&typed); + typed +} + +/// Holds the keystrokes' times to the bounds below, showing each keystroke in order. +fn assert_fast(typed: &[Keystroke]) { + let latency = Latency::of(typed); // (Shown with the failure, or with `--nocapture`.) let in_order: String = typed.iter().enumerate().map(|(i, k)| format!("\n {i:2} {k}")).collect(); eprintln!("keystroke to remote apply: {latency}; in order:{in_order}"); From ba6a69ea64d5ff08024be066fdd35437d94ca054 Mon Sep 17 00:00:00 2001 From: Fabio Lussi <198260595+itrycodinganditsbad@users.noreply.github.com> Date: Tue, 20 Oct 2026 03:17:59 +0200 Subject: [PATCH 5/6] tests: tell a late keystroke from a lost one, and run latency tests alone On 6b955b5, Windows CI failed both latency tests with "keystroke 5 never arrived": no update within the 5 s recv_timeout. The log can't say whether the update was lost or only late, because the test stopped at 5 s. The test now waits up to a minute for a keystroke that is over 5 s late. It records what each agent has in its live folder (documents and journals, with sizes) when the keystroke is 5 s late and again when it arrives. Only one that never comes panics, with that state. A late one fails the bounds with the in-order report. CRAFT_CLOUD_TEST_LOAD=n adds n busy threads while typing, as live_autosave does on app-kit. On this PC, 30 runs with the scanner and 32 to 96 busy threads, plus 20 traced runs, gave 10 keystrokes of 3.6 to 11 s. Every one arrived; none was lost. Tracing showed each gap inside one agent thread between two consecutive steps with no I/O in between (for example, the pc's hub between appending an update and queuing it for the server, 4.0 s). That is the thread not being run under full CPU, not something in our code holding it. The two latency tests now take turns (a shared lock). Since 6b955b5 they ran at once: four agents and two servers on a CI runner's few cores, each test timing the other. A unit test checks the paths 6b955b5 added for losing data. A document write refused because another program holds the document, or one whose journal is held, leaves the document dirty or the journal as it was. A crash then reads every acked change back, each once, and the next write catches up. It passes on 6b955b5 too: the skipped writes don't lose updates. MemStore can now simulate a held file (Held), and is_busy also accepts ErrorKind::ResourceBusy, the kind MemStore returns. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01RC1oqfy9kZznj94RjMojyz --- apps/craft-cloud-agent/src/account.rs | 4 +- apps/craft-cloud-agent/src/live/replica.rs | 52 +++++++++++++++++++ apps/craft-cloud-agent/src/live/store.rs | 40 +++++++++++++++ apps/craft-cloud-agent/tests/live_speed.rs | 58 +++++++++++++++++++++- 4 files changed, 151 insertions(+), 3 deletions(-) diff --git a/apps/craft-cloud-agent/src/account.rs b/apps/craft-cloud-agent/src/account.rs index 6c304f4..4a04ac3 100644 --- a/apps/craft-cloud-agent/src/account.rs +++ b/apps/craft-cloud-agent/src/account.rs @@ -612,9 +612,9 @@ fn replace(temp: &Path, path: &Path) -> io::Result<()> { } /// Whether `e` is Windows refusing a file operation because another program holds the file (ERROR_ACCESS_DENIED or -/// ERROR_SHARING_VIOLATION; [`retry_busy`] waits those out). Never elsewhere. +/// ERROR_SHARING_VIOLATION; [`retry_busy`] waits those out), or a store saying so (`ResourceBusy`). pub(crate) fn is_busy(e: &io::Error) -> bool { - cfg!(windows) && e.raw_os_error().is_some_and(|code| BUSY.contains(&code)) + (cfg!(windows) && e.raw_os_error().is_some_and(|code| BUSY.contains(&code))) || e.kind() == io::ErrorKind::ResourceBusy } /// ERROR_ACCESS_DENIED and ERROR_SHARING_VIOLATION. diff --git a/apps/craft-cloud-agent/src/live/replica.rs b/apps/craft-cloud-agent/src/live/replica.rs index e703693..af50c13 100644 --- a/apps/craft-cloud-agent/src/live/replica.rs +++ b/apps/craft-cloud-agent/src/live/replica.rs @@ -3759,6 +3759,58 @@ mod tests { assert!(matches!(typed.as_slice(), [ClientFrame::Update { .. }]), "{typed:?}"); } + /// A write now and then that another program refuses loses nothing. A document whose file is held stays dirty + /// and is written at the next write. One whose journal is held is written, with the journal kept as it was. Either + /// way, a crash then (or after more changes) reads every acked change back, each once. + #[test] + fn a_write_another_program_refuses_is_made_later_and_loses_nothing() { + use crate::live::store::Held; + for held in [Held::Documents, Held::Journals] { + let store = MemStore::default(); + let (space, node) = (SpaceId::generate(), NodeId::generate()); + let (mut r, id, import) = joined(&store, space, node); + let name = id.to_string(); + let edit = |peer: u64, s: &str| { + let d = text_doc(peer); + d.import(&import).unwrap(); + insert(&d, 0, s) + }; + r.local_update(id, &edit(50, "")).unwrap(); + let (file, journal) = (store.documents().get(&name).cloned(), store.journals().get(&name).cloned()); + store.hold(Some(held)); + r.flush_documents_now_and_then().unwrap(); + r.flush().unwrap(); + match held { + Held::Documents => { + assert_eq!(store.documents().get(&name), file.as_ref(), "the held file isn't written"); + assert_eq!(store.journals().get(&name), journal.as_ref(), "nor its journal emptied"); + } + Held::Journals => { + assert_ne!(store.documents().get(&name), file.as_ref(), "the file is written"); + assert_eq!(store.journals().get(&name), journal.as_ref(), "the held journal is kept as it was"); + } + } + r.local_update(id, &edit(51, "")).unwrap(); + // A crash with the files held. + drop(r); + let mut r = Replica::open(store.clone(), space, peers()).unwrap(); + r.open_document(node, &app()); + let text = text_of(&r, id); + assert!(text.contains("") && text.contains(""), "{held:?}: an acked change is lost: {text:?}"); + assert_eq!(r.document_status(id).map(|(_, waiting)| waiting), Some(2), "{held:?}: each change once"); + // Released: the next write now and then writes it and empties the journal. + store.hold(None); + r.local_update(id, &edit(52, "")).unwrap(); + r.flush_documents_now_and_then().unwrap(); + assert_eq!(store.journals().get(&name).map_or(0, Vec::len), 0, "{held:?}"); + drop(r); + let mut r = Replica::open(store.clone(), space, peers()).unwrap(); + r.open_document(node, &app()); + let text = text_of(&r, id); + assert!(["", "", ""].iter().all(|s| text.contains(s)), "{held:?}: {text:?}"); + } + } + /// A journal is written into its document's file at the next write once it holds over [`MAX_JOURNAL_BYTES`], not /// before (the file is written now and then besides). #[test] diff --git a/apps/craft-cloud-agent/src/live/store.rs b/apps/craft-cloud-agent/src/live/store.rs index 2f880e9..f326ccf 100644 --- a/apps/craft-cloud-agent/src/live/store.rs +++ b/apps/craft-cloud-agent/src/live/store.rs @@ -312,6 +312,18 @@ pub struct MemStore { journals: Arc>>>, /// How journal appends fail from now on ([`JournalFailure`] as a number; 0: they don't), for tests. failing: Arc, + /// Which files another program holds, for the writes that don't wait ([`Held`] as a number; 0: none), for tests. + held: Arc, +} + +/// Which of a [`MemStore`]'s files another program holds, for tests: the writes that don't wait for it are refused +/// as busy. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum Held { + /// Documents' files. + Documents, + /// Journals. + Journals, } /// How a [`MemStore`]'s journal appends fail, for tests. @@ -342,6 +354,24 @@ impl MemStore { self.failing.store(n, std::sync::atomic::Ordering::Relaxed); } + /// Has another program hold `held` (or nothing), for tests. + pub fn hold(&self, held: Option) { + let n = match held { + None => 0, + Some(Held::Documents) => 1, + Some(Held::Journals) => 2, + }; + self.held.store(n, std::sync::atomic::Ordering::Relaxed); + } + + fn holds(&self, held: Held) -> io::Result<()> { + let n = if held == Held::Documents { 1 } else { 2 }; + if self.held.load(std::sync::atomic::Ordering::Relaxed) == n { + return Err(io::Error::new(io::ErrorKind::ResourceBusy, "another program holds the file (test)")); + } + Ok(()) + } + /// The journals, by document (for tests that look inside). pub fn journals(&self) -> BTreeMap> { self.journals.lock().unwrap_or_else(PoisonError::into_inner).clone() @@ -400,6 +430,16 @@ impl DocStore for MemStore { Ok(()) } + fn save_document_unless_busy(&mut self, name: &str, bytes: &[u8]) -> io::Result<()> { + self.holds(Held::Documents)?; + self.save_document(name, bytes) + } + + fn clear_journal_unless_busy(&mut self, name: &str) -> io::Result<()> { + self.holds(Held::Journals)?; + self.clear_journal(name) + } + fn append_journal(&mut self, name: &str, record: &[u8]) -> io::Result<()> { let mut journals = self.journals.lock().unwrap_or_else(PoisonError::into_inner); match self.failing.load(std::sync::atomic::Ordering::Relaxed) { diff --git a/apps/craft-cloud-agent/tests/live_speed.rs b/apps/craft-cloud-agent/tests/live_speed.rs index 7839719..58fb88e 100644 --- a/apps/craft-cloud-agent/tests/live_speed.rs +++ b/apps/craft-cloud-agent/tests/live_speed.rs @@ -62,6 +62,9 @@ fn scanner(data: Vec, stop: Arc Vec { + // One latency test at a time: two at once (four agents, two servers) time each other on a CI runner's few cores. + static ONE_AT_A_TIME: tokio::sync::Mutex<()> = tokio::sync::Mutex::const_new(()); + let _one = ONE_AT_A_TIME.lock().await; let server = Server::delayed(Duration::from_millis(2)).await; let (pc, laptop) = (Agent::signed_in(&server, "pc").await, Agent::signed_in(&server, "laptop").await); let (run_pc, run_laptop) = (pc.run(), laptop.run()); @@ -116,6 +119,21 @@ async fn time_keystrokes(scan: bool) -> Vec { .await; } let (p, l) = (pc_side.clone(), laptop_side.clone()); + let data = [("pc", pc.data.path().to_owned()), ("laptop", laptop.data.path().to_owned())]; + // More load on demand: `CRAFT_CLOUD_TEST_LOAD=8` adds eight threads that keep the CPUs busy while typing. + let burners: usize = std::env::var("CRAFT_CLOUD_TEST_LOAD").ok().and_then(|n| n.parse().ok()).unwrap_or(0); + let burning: Vec<_> = (0..burners) + .map(|_| { + let stop = stop_scanning.clone(); + std::thread::spawn(move || { + let mut x = 0u64; + while !stop.load(std::sync::atomic::Ordering::Relaxed) { + x = x.wrapping_mul(6364136223846793005).wrapping_add(1); + std::hint::black_box(x); + } + }) + }) + .collect(); let typed = off(move || { let mut typed = Vec::new(); let start = Instant::now(); @@ -135,6 +153,9 @@ async fn time_keystrokes(scan: bool) -> Vec { }; let want = i + 1; let (theirs, doc) = &*l.lock().unwrap(); + // A keystroke that takes over 5 s is waited for up to a minute, and said: a late one fails the bounds with + // the report below, one that never comes is a lost update, reported with what each agent has on disk. + let mut late = false; let took = loop { match doc.recv_timeout(Duration::from_secs(5)) { Some(Event::Update(bytes)) => { @@ -148,9 +169,24 @@ async fn time_keystrokes(scan: bool) -> Vec { events.push(format!("laptop {other:?}")); } } - None => panic!("keystroke {i} never arrived"), + None if at.elapsed() < Duration::from_secs(60) => { + if !late { + late = true; + events.push(format!("not there after 5 s; on disk then: {}", on_disk(&data))); + } + let pc = p.lock().unwrap(); + events.extend(std::iter::from_fn(|| pc.1.try_recv()).filter(worth_saying).map(|e| format!("pc {e:?}"))); + } + None => panic!( + "keystroke {i} never arrived (a minute); the laptop has {:?}; on disk: {}; meanwhile: {events:?}", + theirs.get_text("text").to_string(), + on_disk(&data) + ), } }; + if late { + events.push(format!("arrived late; on disk now: {}", on_disk(&data))); + } typed.push(Keystroke { sent: at - start, took, events }); // A typist's pace: a keystroke batch every 30 ms. std::thread::sleep(Duration::from_millis(30)); @@ -159,6 +195,9 @@ async fn time_keystrokes(scan: bool) -> Vec { }) .await; stop_scanning.store(true, std::sync::atomic::Ordering::Relaxed); + for burner in burning { + burner.join().unwrap(); + } #[cfg(windows)] if let Some(scanning) = scanning { scanning.join().unwrap(); @@ -171,6 +210,23 @@ async fn time_keystrokes(scan: bool) -> Vec { typed } +/// Each agent's live document files (`/live//`) and their sizes, for a report. +fn on_disk(data: &[(&str, std::path::PathBuf)]) -> String { + let mut out = Vec::new(); + for (who, dir) in data { + let mut files: Vec = std::fs::read_dir(dir.join("live")) + .into_iter() + .flatten() + .flatten() + .flat_map(|space| std::fs::read_dir(space.path()).into_iter().flatten().flatten()) + .map(|e| format!("{} {}", e.file_name().to_string_lossy(), e.metadata().map_or(0, |m| m.len()))) + .collect(); + files.sort(); + out.push(format!("{who} [{}]", files.join(", "))); + } + out.join("; ") +} + /// Holds the keystrokes' times to the bounds below, showing each keystroke in order. fn assert_fast(typed: &[Keystroke]) { let latency = Latency::of(typed); From 72fd41cba633813c6cbdf007f9c799656f451628 Mon Sep 17 00:00:00 2001 From: Fabio Lussi <198260595+itrycodinganditsbad@users.noreply.github.com> Date: Tue, 20 Oct 2026 04:07:08 +0200 Subject: [PATCH 6/6] agent: write the first and last status in the loop, not on the status thread binary.rs's a_second_run_exits_0_with_a_note failed on Windows CI: `status`, run right after a second `run`, printed only "not signed in". It found no running loop in status.json. The test, the app and a second `run` all take "the local API is up" to mean "status.json says a loop runs". That held before 6b955b5 only by accident. The first status write ran on the loop's runtime, which also serves the local API, so the API couldn't answer until the write was done. With the write on the status thread, the API answered first. The loop now writes its first status itself, before it starts the local API: Idle when signed in, SignedOut when not, Paused when the account doesn't read. If the API can't start, it writes Stopped. At the end, the loop finishes the status thread (so Stopped is on disk) before it stops the API and lets go of the data folder. Before this, the last status could land after the lock was released, over the status of a `run` started next. Everything in between still goes through the status thread. once_the_local_api_is_up_status_json_says_the_loop_runs (Windows) holds an old status.json for 1 s as the loop starts and reads status.json as soon as local-api.json appears. On ba6a69e it fails (it reads the old file). With this commit it passes. live_documents.rs's an_app_that_misbehaves_is_refused_or_dropped_and_the_ rest_go_on failed once on macOS: the app that never reads wasn't dropped. The agent drops an app whose message it can't send within 10 s, and the 60 changes of 200 KB (12 MB) only hold a send up once the kernel's loopback buffers are full. macOS can let those grow to megabytes. That app now connects with a 64 KiB receive buffer, so the agent's send waits however large the system would let buffers grow. Nothing in this branch touches the drop: the docs socket, its 10 s limit and the hub's queue are as on main. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01RC1oqfy9kZznj94RjMojyz --- apps/craft-cloud-agent/src/daemon.rs | 56 ++++++++++++++++--- .../craft-cloud-agent/tests/live_documents.rs | 16 +++++- apps/craft-cloud-agent/tests/local_api.rs | 27 +++++++++ 3 files changed, 91 insertions(+), 8 deletions(-) diff --git a/apps/craft-cloud-agent/src/daemon.rs b/apps/craft-cloud-agent/src/daemon.rs index 0bf8cd8..ccc4315 100644 --- a/apps/craft-cloud-agent/src/daemon.rs +++ b/apps/craft-cloud-agent/src/daemon.rs @@ -457,16 +457,22 @@ impl StatusWriter { /// Has `status` written (soon, on the thread). fn write(&self, status: LoopStatus) { if self.thread.is_none() { - if let Err(e) = self.data.save_status(&status) { - crate::runlog::note(format_args!("can't write the status file: {e}")); - self.handover().failed = true; - } + self.write_now(&status); return; } self.handover().next = Some(status); self.shared.1.notify_one(); } + /// Writes `status` in the caller, before returning. Only while the thread has nothing to write (at the start), so + /// the two never race. + fn write_now(&self, status: &LoopStatus) { + if let Err(e) = self.data.save_status(status) { + crate::runlog::note(format_args!("can't write the status file: {e}")); + self.handover().failed = true; + } + } + /// Whether a write failed since the last call. fn take_failed(&self) -> bool { std::mem::take(&mut self.handover().failed) @@ -559,6 +565,22 @@ impl Status { /// A failed write is reported once per failure and tried again next time; it never stops the loop. The write /// itself happens on the status thread ([`StatusWriter`]). fn write(&mut self, state: LoopState, waiting_for_approval: bool, force: bool) { + self.write_as(state, waiting_for_approval, force, false); + } + + /// [`Status::write`], on disk before this returns: for the first status, written before the local API answers + /// anyone (who may run `status` next and must find the loop running). + fn write_now(&mut self, state: LoopState) { + self.write_as(state, false, true, true); + } + + /// Writes what still waits, and stops the status thread: the loop's last status is on disk before the loop lets + /// go of the data folder (a `run` started next must never have its status overwritten by this one's). + fn finish(self) { + drop(self); + } + + fn write_as(&mut self, state: LoopState, waiting_for_approval: bool, force: bool, now_on_disk: bool) { if self.writer.take_failed() { self.last_written = None; } @@ -590,7 +612,11 @@ impl Status { } // Tried again at the next beat either way, never in a hot loop. self.next_beat = now.saturating_add(u64::try_from(self.heartbeat.as_millis()).unwrap_or(u64::MAX)); - self.writer.write(status.clone()); + if now_on_disk { + self.writer.write_now(&status); + } else { + self.writer.write(status.clone()); + } self.last_written = Some(status); } } @@ -616,8 +642,6 @@ pub async fn run_loop(data: &DataDir, options: RunOptions, mut stop: mpsc::Unbou }); let control = Control::new(commands_tx).with_autostart(autostart_roots, data.path()); control.refresh_autostart().await; - let api = LocalApi::start(data, control.clone()).await?; - say(out, &format!("craft-cloud-agent: local API on 127.0.0.1:{} (for the Craft Cloud app and the other Craft apps)", api.port())); let mut status = Status { writer: StatusWriter::start(data), start: Instant::now(), @@ -631,6 +655,22 @@ pub async fn run_loop(data: &DataDir, options: RunOptions, mut stop: mpsc::Unbou last_synced_ms: None, control: Some(control.clone()), }; + // The first status is on disk before the local API answers: whoever finds the API up (the app, `status`, a second + // `run`) also finds the loop running. (The loop says what it does next as soon as it knows.) + status.write_now(match data.load_account() { + Ok(Some(_)) => LoopState::Idle, + Ok(None) => LoopState::SignedOut, + Err(e) => LoopState::Paused { reason: e.to_string(), next_check_ms: None }, + }); + let api = match LocalApi::start(data, control.clone()).await { + Ok(api) => api, + Err(e) => { + // No loop after all: `status` mustn't think one runs. + status.write_now(LoopState::Stopped); + return Err(e); + } + }; + say(out, &format!("craft-cloud-agent: local API on 127.0.0.1:{} (for the Craft Cloud app and the other Craft apps)", api.port())); let mut stops = 0; let mut stop_open = true; // A sign-out revoked the device but couldn't remove the account file: the dead account is never used again. @@ -1057,6 +1097,8 @@ pub async fn run_loop(data: &DataDir, options: RunOptions, mut stop: mpsc::Unbou } } }; + // Its last status (`Stopped`) on disk before the API goes and the data folder is let go of. + status.finish(); api.stop().await; drop(data_lock); say(out, "stopped"); diff --git a/apps/craft-cloud-agent/tests/live_documents.rs b/apps/craft-cloud-agent/tests/live_documents.rs index 0bc32af..dc752f1 100644 --- a/apps/craft-cloud-agent/tests/live_documents.rs +++ b/apps/craft-cloud-agent/tests/live_documents.rs @@ -365,6 +365,20 @@ mod raw { tokio_tungstenite::connect_async(request).await.unwrap().0 } + /// [`connect`], with a receive buffer of 64 KiB: an app that never reads then holds up the agent's sends once + /// the agent's own send buffer is full, whatever the system would let a receive buffer grow to (macOS lets + /// loopback buffers grow to megabytes). + pub async fn connect_with_a_small_receive_buffer(agent: &super::Agent) -> Ws { + let api: craft_cloud_proto::local::LocalApiFile = + serde_json::from_slice(&std::fs::read(agent.data.path().join(craft_cloud_proto::local::LOCAL_API_FILE)).unwrap()).unwrap(); + let mut request = format!("ws://127.0.0.1:{}/v1/docs", api.port).into_client_request().unwrap(); + request.headers_mut().insert("authorization", format!("Bearer {}", api.token).parse().unwrap()); + let socket = tokio::net::TcpSocket::new_v4().unwrap(); + socket.set_recv_buffer_size(64 * 1024).unwrap(); + let stream = socket.connect(std::net::SocketAddr::from(([127, 0, 0, 1], api.port))).await.unwrap(); + tokio_tungstenite::client_async(request, tokio_tungstenite::MaybeTlsStream::Plain(stream)).await.unwrap().0 + } + pub async fn send_text(ws: &mut Ws, json: serde_json::Value) { ws.send(Message::Text(json.to_string().into())).await.unwrap(); } @@ -472,7 +486,7 @@ async fn an_app_that_misbehaves_is_refused_or_dropped_and_the_rest_go_on() { .await; assert_eq!(other.1.text(), "other"); // An app that never reads while another floods its document with big changes: dropped (it can't hold the agent up). - let mut lazy = raw::connect(&pc).await; + let mut lazy = raw::connect_with_a_small_receive_buffer(&pc).await; raw::send_text(&mut lazy, serde_json::json!({ "type": "open", "id": 1, "path": "doc.txt", "app": "wordcraft" })).await; tokio::time::sleep(Duration::from_millis(500)).await; let good = Arc::new(Mutex::new(good)); diff --git a/apps/craft-cloud-agent/tests/local_api.rs b/apps/craft-cloud-agent/tests/local_api.rs index 33fcd6b..3da573e 100644 --- a/apps/craft-cloud-agent/tests/local_api.rs +++ b/apps/craft-cloud-agent/tests/local_api.rs @@ -407,6 +407,33 @@ async fn a_sign_out_that_cant_forget_the_account_stays_signed_out() { let _ = running.stop().await; } +/// Whoever finds the local API up finds `status.json` saying the loop runs (a second `run`, then `status`, relies on +/// it), even when another program holds the old `status.json` for a moment as the loop starts: the first status is +/// on disk before the API answers. +#[cfg(windows)] +#[tokio::test(flavor = "multi_thread", worker_threads = 4)] +async fn once_the_local_api_is_up_status_json_says_the_loop_runs() { + use std::os::windows::fs::OpenOptionsExt; + let dir = tempfile::tempdir().unwrap(); + let data = DataDir::new(dir.path().join("data")); + std::fs::create_dir_all(data.path()).unwrap(); + // A status an agent left long ago, held (for reading only, no delete sharing) for the first second. + let file = data.path().join("status.json"); + std::fs::write(&file, b"{}").unwrap(); + let held = std::fs::OpenOptions::new().read(true).share_mode(1).open(&file).unwrap(); + let release = std::thread::spawn(move || { + std::thread::sleep(Duration::from_secs(1)); + drop(held); + }); + let running = Running::start(&data); + api_file(data.path()).await; + let status = data.load_status(); + let now = std::time::SystemTime::now().duration_since(std::time::UNIX_EPOCH).unwrap().as_millis() as i64; + assert!(matches!(&status, Ok(Some(s)) if s.running(now)), "{status:?}"); + release.join().unwrap(); + let _ = running.stop().await; +} + #[tokio::test(flavor = "multi_thread", worker_threads = 4)] async fn run_starts_signed_out_and_signs_in_and_out_through_the_local_api() { let server = server().await;